diff --git a/binlog.cpp b/binlog.cpp index 59dd255..e33787a 100644 --- a/binlog.cpp +++ b/binlog.cpp @@ -37,22 +37,14 @@ BinlogWriter::~BinlogWriter() close(); } -bool BinlogWriter::open(uint32_t port2, unsigned session_n, const char *base_dir) +bool BinlogWriter::open(uint32_t port2, const char *base_dir) { if (fp != nullptr) { return true; } - time_t now = time(nullptr); - struct tm tm_now; - localtime_r(&now, &tm_now); - char dir[768]; - snprintf(dir, sizeof(dir), "%s/%u/%04d-%02d-%02d", - base_dir, port2, - tm_now.tm_year + 1900, - tm_now.tm_mon + 1, - tm_now.tm_mday); + snprintf(dir, sizeof(dir), "%s/%u/%s", base_dir, port2, datedir_.c_str()); if (mkpath_0700(dir) < 0) { ::printf("binlog: mkdir %s failed: %s\n", dir, strerror(errno)); @@ -60,14 +52,12 @@ bool BinlogWriter::open(uint32_t port2, unsigned session_n, const char *base_dir } char path[1024]; - snprintf(path, sizeof(path), "%s/session%u.bin", dir, session_n); - - // O_RDWR via "rb+"-then-"wb+" dance: blocks arrive out of order so - // we need to seek + write to arbitrary offsets. fopen "ab" forces - // every write to the end. Use "wb+" to truncate and create, or - // "rb+" to keep an existing file (rare — child crashed mid-session - // and a new fork is reusing the same N? next_session_n() rules - // that out, but defensively allow it). + snprintf(path, sizeof(path), "%s/%s.bin", dir, name_.c_str()); + + // O_RDWR via "wb+": blocks arrive out of order so we seek + write to + // arbitrary offsets ("ab" would force every write to the end). The + // basename is made unique before the session starts, so this creates + // a fresh file rather than truncating a live one. fp = fopen(path, "wb+"); if (fp == nullptr) { ::printf("binlog: fopen %s failed: %s\n", path, strerror(errno)); @@ -181,7 +171,7 @@ void BinlogWriter::mark_seqno_seen(uint32_t seqno) seen_bitmap[byte] |= uint8_t(1u << (seqno & 7)); } -void BinlogWriter::handle_block(uint32_t port2, unsigned session_n, +void BinlogWriter::handle_block(uint32_t port2, const mavlink_message_t &msg) { mavlink_remote_log_data_block_t blk {}; @@ -225,11 +215,9 @@ void BinlogWriter::handle_block(uint32_t port2, unsigned session_n, } return; } - unsigned n = (pending_session_n_ != 0) ? pending_session_n_ : session_n; - if (!open(port2, n)) { + if (!open(port2)) { return; } - pending_session_n_ = 0; gated_block_count_ = 0; } @@ -606,14 +594,20 @@ bool BinlogWriter::rotate_for_reboot() // pre-stream loop; the 5 s keep-alive (re-armed above) covers // reboot recovery. - // Pre-compute the next session N but do NOT open the file yet. - // The handle_block() strict-start gate (fp == nullptr + seqno!=0 - // is dropped) keeps the file unopened until a fresh seqno=0 from - // the rebooted vehicle, so any delayed pre-reboot blocks still - // in flight can't sparse-write into sessionN+1.bin. The open() - // happens lazily in handle_block using pending_session_n_. - pending_session_n_ = next_session_n(port2_, base_dir_.c_str()); - ::printf("binlog: rotation armed; next open will be session%u.bin " - "(awaiting fresh seqno=0)\n", pending_session_n_); + // Rebuild datedir_/name_ with a fresh reboot-time timestamp but do + // NOT open the file yet. The handle_block() strict-start gate + // (fp == nullptr + seqno!=0 dropped) keeps the file unopened until a + // fresh seqno=0 from the rebooted vehicle, so delayed pre-reboot + // blocks can't sparse-write into the new file. The open() happens + // lazily in handle_block using the new datedir_/name_. + char datedir[16], name[64]; + session_time_strings(time(nullptr), tz_use_offset_, tz_offset_hours_, + datedir, sizeof(datedir), name, sizeof(name)); + session_unique_basename(base_dir_.c_str(), port2_, datedir, + name, sizeof(name)); + datedir_ = datedir; + name_ = name; + ::printf("binlog: rotation armed; next open will be %s/%s.bin " + "(awaiting fresh seqno=0)\n", datedir_.c_str(), name_.c_str()); return true; } diff --git a/binlog.h b/binlog.h index 981b873..44b9404 100644 --- a/binlog.h +++ b/binlog.h @@ -39,14 +39,35 @@ class BinlogWriter { BinlogWriter &operator=(const BinlogWriter &) = delete; /* - open logs///sessionN.bin. Caller supplies - session_n via the shared next_session_n() helper so the .bin - and .tlog for one child fork share their N. + open logs///.bin. The timestamp datedir + + basename come from set_session_paths() (set once at fork so the + .bin and .tlog for one child share their name), or are recomputed + by rotate_for_reboot() for the post-reboot file. */ - bool open(uint32_t port2, unsigned session_n, - const char *base_dir = "logs"); + bool open(uint32_t port2, const char *base_dir = "logs"); bool is_open() const { return fp != nullptr; } + /* + Set the timestamp date subdir + basename for the (lazy) initial + open. Called once by the parent at fork with the shared session + name so .bin and .tlog pair up. rotate_for_reboot() overwrites + these with the reboot-time name for the next file. + */ + void set_session_paths(const char *datedir, const char *name) { + datedir_ = datedir; + name_ = name; + } + + /* + Log-naming timezone for the reboot-rotated file's name: whether to + apply the fixed GMT offset (KEY_FLAG_USE_TZ) and the offset itself. + Sourced from the KeyEntry at fork. + */ + void set_tz(bool use_offset, double offset_hours) { + tz_use_offset_ = use_offset; + tz_offset_hours_ = offset_hours; + } + /* Decode a REMOTE_LOG_DATA_BLOCK message and process it. @@ -66,12 +87,10 @@ class BinlogWriter { jump (seqno > highest_seen + 1) the gap is recorded for NACK in tick(). - port2 + session_n are used only on the (lazy) open. They're - passed every call rather than stored so BinlogWriter doesn't - need to copy strings. + port2 is used only on the (lazy) open; the datedir/name come from + set_session_paths(). */ - void handle_block(uint32_t port2, unsigned session_n, - const mavlink_message_t &msg); + void handle_block(uint32_t port2, const mavlink_message_t &msg); /* Observe an arbitrary user-side MAVLink message for FC-reboot @@ -247,12 +266,22 @@ class BinlogWriter { double last_stop_sent_s = 0.0; // Captured on the first successful open() so rotate_for_reboot() - // can re-scan the per-day dir for a fresh session N without - // dragging port2/base_dir through every observe() / handle_block() - // signature. + // can rebuild paths without dragging port2/base_dir through every + // observe() / handle_block() signature. uint32_t port2_ = 0; std::string base_dir_; + // Timestamp date subdir ("YYYY-MM-DD") and basename + // ("YYYY_MM_DD_HH:MM:SS") for the file. Set once at fork via + // set_session_paths() so .bin and .tlog pair up; rebuilt by + // rotate_for_reboot() for the post-reboot file. + std::string datedir_; + std::string name_; + // Log-naming timezone for rotate's new name: whether the fixed GMT + // offset is in use (KEY_FLAG_USE_TZ) and its value. + bool tz_use_offset_ = false; + double tz_offset_hours_ = 0.0; + // Current size of fp (= the largest seqno+1 we've written * 200). // Tracked locally rather than fstat'ing on every write. off_t current_file_size_ = 0; @@ -280,17 +309,12 @@ class BinlogWriter { // SYSTEM_TIME can't trigger a spurious reboot). uint32_t last_system_time_boot_ms_ = 0; - // Close + reset per-log state + arm pending_session_n_ for the - // NEXT open. Used when observe() decides the FC has rebooted. - // Does NOT re-open here — the new file is only opened when a - // fresh seqno=0 arrives, so the existing strict-start gate keeps - // protecting the rotated file from delayed pre-reboot blocks. - // Does NOT reset per-vehicle state (target_system/component, + // Close + reset per-log state + rebuild datedir_/name_ for the NEXT + // open (a fresh reboot-time timestamp). Used when observe() decides + // the FC has rebooted. Does NOT re-open here — the new file is only + // opened when a fresh seqno=0 arrives, so the existing strict-start + // gate keeps protecting the rotated file from delayed pre-reboot + // blocks. Does NOT reset per-vehicle state (target_system/component, // fc_sysid_filter_). bool rotate_for_reboot(); - - // Session N to use on the NEXT open(), set by rotate_for_reboot() - // and consumed on the gate-triggered open in handle_block. - // 0 = no pending rotation; use the caller's session_n argument. - unsigned pending_session_n_ = 0; }; diff --git a/keydb.h b/keydb.h index 283c666..e75ccd0 100644 --- a/keydb.h +++ b/keydb.h @@ -33,6 +33,7 @@ #define KEY_FLAG_BIDI_SIGN (1u << 1) // require signed MAVLink on the user side too #define KEY_FLAG_TLOG (1u << 2) // record per-connection MAVProxy-format tlogs #define KEY_FLAG_BINLOG (1u << 3) // record ArduPilot bin logs over MAVLink +#define KEY_FLAG_USE_TZ (1u << 4) // name logs with tz_offset_hours; else server local struct KeyEntry { uint64_t magic; @@ -46,7 +47,8 @@ struct KeyEntry { uint32_t flags; float log_retention_days; // tlog + bin; 0.0 = forever; fractional values allowed for tests uint32_t fc_sysid; // 0 = match any; otherwise only monitor packets from this MAVLink sysid (binlog reboot detection) - uint32_t reserved[15]; + float tz_offset_hours; // log naming: GMT offset in hours (fractional allowed), used only when KEY_FLAG_USE_TZ is set + uint32_t reserved[14]; }; /* diff --git a/keydb.py b/keydb.py index e8a2fa9..bb2c7f7 100755 --- a/keydb.py +++ b/keydb.py @@ -27,6 +27,7 @@ def main(): 'setflag', 'clearflag', 'flags', 'setretention', 'setsysid', + 'settz', 'stats'], help="action to perform") parser.add_argument("args", default=[], nargs=argparse.REMAINDER) @@ -135,6 +136,20 @@ def main(): else: print("Set fc_sysid=%u for %s" % (sysid, ke)) + elif args.action == "settz": + _expect(args.args, 2, + "keydb.py settz PORT2 HOURS " + "(GMT offset in hours, fractional ok; enables use_tz. " + "Clear the use_tz flag to revert to server-local naming.)") + try: + hours = float(args.args[1]) + except ValueError: + raise CLIError("HOURS must be a number, got %r" + % args.args[1]) + ke = keydb_lib.set_timezone(db, int(args.args[0]), hours) + print("Set log timezone=%s for %s" + % (keydb_lib.format_tz_offset(hours), ke)) + elif args.action == "stats": # Live-connection stats from connections.tdb (sibling of # keys.tdb), joined with each entry's name from this DB. diff --git a/keydb_lib.py b/keydb_lib.py index df5bc7a..e43ad82 100644 --- a/keydb_lib.py +++ b/keydb_lib.py @@ -12,6 +12,7 @@ import errno import hashlib import hmac +import math import os import struct import time @@ -24,14 +25,18 @@ # is acceptable (extra trailing bytes belong to a newer schema we ignore). # # The current C++ struct ends with `uint32_t flags`, `float log_retention_days`, -# `uint32_t fc_sysid`, and `uint32_t reserved[15]`. All are 4-byte aligned and -# slot in cleanly after the existing fields, so the struct is 168 bytes with -# no trailing pad. When a future field is added, claim another `reserved[]` -# slot (renumber: shrink reserved by 1, add a named field) so the on-disk byte -# layout stays compatible — the zero-init paths in db_load_key (C++) and -# unpack() (Python) handle older records transparently. +# `uint32_t fc_sysid`, `float tz_offset_hours`, and `uint32_t reserved[14]`. All +# are 4-byte aligned and slot in cleanly after the existing fields, so the +# struct is 168 bytes with no trailing pad. When a future field is added, claim +# another `reserved[]` slot (renumber: shrink reserved by 1, add a named field) +# so the on-disk byte layout stays compatible — the zero-init paths in +# db_load_key (C++) and unpack() (Python) handle older records transparently. +# tz_offset_hours took a slot that was previously a zeroed reserved word, so +# older records read back as 0.0 with the KEY_FLAG_USE_TZ bit clear — i.e. +# server-local naming (the flag, not the value, decides whether the offset +# is used), needing no conversion. KEYENTRY_MIN_SIZE = 96 -PACK_FORMAT = "= 0 else '-' + total_min = int(round(abs(hours) * 60.0)) + return 'GMT%s%02d:%02d' % (sign, total_min // 60, total_min % 60) class CLIError(Exception): @@ -68,6 +101,7 @@ def __init__(self, port2): self.flags = 0 self.log_retention_days = 0.0 self.fc_sysid = 0 + self.tz_offset_hours = 0.0 self.reserved = [0] * RESERVED_WORDS self.port2 = port2 # opaque trailing bytes from a record written by a future schema @@ -82,6 +116,7 @@ def pack(self): self.count2, name, self.flags, self.log_retention_days, self.fc_sysid, + self.tz_offset_hours, *reserved[:RESERVED_WORDS]) return body + self._tail @@ -99,8 +134,8 @@ def unpack(self, data): (self.magic, self.timestamp, secret_key, self.port1, self.connections, self.count1, self.count2, name, self.flags, self.log_retention_days, - self.fc_sysid) = unpacked[:11] - self.reserved = list(unpacked[11:11 + RESERVED_WORDS]) + self.fc_sysid, self.tz_offset_hours) = unpacked[:12] + self.reserved = list(unpacked[12:12 + RESERVED_WORDS]) self.secret_key = bytearray(secret_key) self.name = name.decode('utf-8', errors='ignore').rstrip('\0') @@ -156,10 +191,17 @@ def __str__(self): sysstr = '' if self.fc_sysid: sysstr = ' fc_sysid=%u' % self.fc_sysid - return ("%u/%u '%s' counts=%u/%u connections=%u ts=%u%s%s%s" + tzstr = '' + if self.flags & FLAG_USE_TZ: + tzstr = ' tz=%s' % format_tz_offset(self.tz_offset_hours) + elif self.tz_offset_hours: + # offset stored but not active — show it parenthesised so it + # is clear the server-local default is in effect + tzstr = ' tz=local(%s off)' % format_tz_offset(self.tz_offset_hours) + return ("%u/%u '%s' counts=%u/%u connections=%u ts=%u%s%s%s%s" % (self.port1, self.port2, self.name, self.count1, self.count2, self.connections, - self.timestamp, flagstr, retstr, sysstr)) + self.timestamp, flagstr, retstr, sysstr, tzstr)) def open_db(path='keys.tdb'): @@ -349,6 +391,26 @@ def set_log_retention(db, port2, days): return ke +def set_timezone(db, port2, hours): + """Set the per-entry log-naming GMT offset (hours, fractional) and + enable its use (KEY_FLAG_USE_TZ). Setting a timezone means you want + it applied; clear the 'use_tz' flag to revert to server-local naming + without discarding the stored offset.""" + ke = KeyEntry(port2) + if not ke.fetch(db): + raise CLIError("No entry for port2 %d" % port2) + if not math.isfinite(hours): + raise CLIError("timezone offset must be a finite number (got %r)" + % hours) + if hours < TZ_MIN_OFFSET or hours > TZ_MAX_OFFSET: + raise CLIError("timezone offset must be in %g..%g hours (got %r)" + % (TZ_MIN_OFFSET, TZ_MAX_OFFSET, hours)) + ke.tz_offset_hours = float(hours) + ke.flags |= FLAG_USE_TZ + ke.store(db) + return ke + + def set_fc_sysid(db, port2, sysid): """Set the MAVLink sysid filter for this entry. 0 = match any (default); non-zero restricts binlog reboot detection to packets from that sysid.""" diff --git a/session.cpp b/session.cpp index ac717f0..3bfaa90 100644 --- a/session.cpp +++ b/session.cpp @@ -1,15 +1,17 @@ /* - Shared sessionN + mkdir-p helpers for TlogWriter / BinlogWriter. + Shared timestamp-naming + mkdir-p helpers for TlogWriter / BinlogWriter. */ #include "session.h" #include #include +#include #include #include #include #include #include +#include int mkpath_0700(const char *path) { @@ -29,37 +31,97 @@ int mkpath_0700(const char *path) return 0; } -unsigned next_session_n(uint32_t port2, const char *base_dir) +void session_time_strings(time_t utc, bool use_offset, double tz_offset_hours, + char *datedir, size_t datedir_len, + char *name, size_t name_len) { - time_t now = time(nullptr); - struct tm tm_now; - localtime_r(&now, &tm_now); + struct tm tm {}; + struct tm *r; + if (use_offset && isfinite(tz_offset_hours)) { + // Explicit fixed GMT offset: apply it then format with gmtime so + // the machine's own timezone plays no part. No DST — a fixed + // offset by design. Clamp to the valid range before the + // arithmetic so a malformed stored value (e.g. use_tz set on a + // hand-edited record) can't overflow time_t in llround/add. + double off = tz_offset_hours; + if (off < -12.0) off = -12.0; + if (off > 14.0) off = 14.0; + time_t shifted = utc + (time_t)llround(off * 3600.0); + r = gmtime_r(&shifted, &tm); + } else { + // Default (KEY_FLAG_USE_TZ clear, or a non-finite offset): name + // in the server's local timezone, as configured on the host — + // the least-surprising default and what the pre-timestamp + // naming did. + r = localtime_r(&utc, &tm); + } + if (r == nullptr) { + // gmtime_r/localtime_r only fail on absurd inputs; format a + // zeroed tm rather than uninitialised stack. + memset(&tm, 0, sizeof(tm)); + } + + snprintf(datedir, datedir_len, "%04d-%02d-%02d", + tm.tm_year + 1900, tm.tm_mon + 1, tm.tm_mday); + snprintf(name, name_len, "%04d_%02d_%02d_%02d:%02d:%02d", + tm.tm_year + 1900, tm.tm_mon + 1, tm.tm_mday, + tm.tm_hour, tm.tm_min, tm.tm_sec); +} + +// True if neither /.tlog nor /.bin exists. +static bool basename_free(const char *dir, const char *candidate) +{ + char p_tlog[2048], p_bin[2048]; + snprintf(p_tlog, sizeof(p_tlog), "%s/%s.tlog", dir, candidate); + snprintf(p_bin, sizeof(p_bin), "%s/%s.bin", dir, candidate); + struct stat st; + return stat(p_tlog, &st) != 0 && stat(p_bin, &st) != 0; +} + +void session_unique_basename(const char *base_dir, uint32_t port2, + const char *datedir, + char *name, size_t name_len) +{ + char base[64]; + snprintf(base, sizeof(base), "%s", name); - char dir[768]; - snprintf(dir, sizeof(dir), "%s/%u/%04d-%02d-%02d", - base_dir, port2, - tm_now.tm_year + 1900, - tm_now.tm_mon + 1, - tm_now.tm_mday); + char dir[1024]; + snprintf(dir, sizeof(dir), "%s/%u/%s", base_dir, unsigned(port2), datedir); - DIR *d = opendir(dir); - if (d == nullptr) { - // No dir yet -> first session of the day. - return 1; + // Plain basename, then "-2", "-3", … — every candidate is checked + // for occupancy across BOTH extensions, so we never hand back a name + // that would truncate (.bin) or append into (.tlog) another session's + // log. A single "-N" suffix keeps the name browsable by the web UI. + // The cap is a safety bound; the first free slot is normally "-2". + for (int suffix = 1; suffix < 100000; suffix++) { + char candidate[96]; + if (suffix == 1) { + snprintf(candidate, sizeof(candidate), "%s", base); + } else { + snprintf(candidate, sizeof(candidate), "%s-%d", base, suffix); + } + if (basename_free(dir, candidate)) { + snprintf(name, name_len, "%s", candidate); + return; + } } - unsigned highest = 0; - struct dirent *ent; - while ((ent = readdir(d)) != nullptr) { - unsigned n = 0; - // Match either sessionN.tlog or sessionN.bin so paired N stays - // paired across both extensions. - if (sscanf(ent->d_name, "session%u.tlog", &n) == 1 - || sscanf(ent->d_name, "session%u.bin", &n) == 1) { - if (n > highest) { - highest = n; - } + // 100000 files in one second/dir cannot happen; as an absolute last + // resort append the pid+nanoseconds as ONE numeric suffix (still a + // single "-N" the web UI accepts) and still check occupancy, so we + // never return an occupied name. + for (int i = 0; i < 100; i++) { + struct timespec ts {}; + clock_gettime(CLOCK_REALTIME, &ts); + char candidate[96]; + snprintf(candidate, sizeof(candidate), "%s-%d%09ld", + base, int(getpid()), long(ts.tv_nsec)); + if (basename_free(dir, candidate)) { + snprintf(name, name_len, "%s", candidate); + return; } } - closedir(d); - return highest + 1; + // Unreachable: there is genuinely no free name. Leave `name` as the + // plain base (its value on entry) — no worse than the impossible + // exhaustion above. + snprintf(name, name_len, "%s", base); } diff --git a/session.h b/session.h index 6c9a6f4..a98fe36 100644 --- a/session.h +++ b/session.h @@ -1,14 +1,20 @@ /* Helpers shared by TlogWriter and BinlogWriter. - Both writers store files at logs///sessionN. - with paired N — when a child fork records both kinds of session - files, sessionN.tlog and sessionN.bin sit next to each other, which - makes the per-day file list in the web UI read naturally. + Both writers store files at logs///., + where is a timestamp "YYYY_MM_DD_HH:MM:SS" of the session + start. A child fork that records both kinds computes one and + passes it to both writers, so the .tlog and .bin sit next to each + other with matching names. The date subdir and the filename are both + formed in the entry's log-naming timezone: an explicit GMT offset in + hours, or — when the offset is 0/unset (the default) — the server's + own local timezone. */ #pragma once #include +#include +#include /* mkdir -p with mode 0700 for every component of `path` (logs may @@ -19,9 +25,26 @@ int mkpath_0700(const char *path); /* - Scan logs/// for sessionN.tlog and sessionN.bin, - return max(N) + 1 (so the first call against a fresh dir returns 1). - Considers BOTH extensions so a tlog-then-bin or bin-then-tlog open - ordering yields the same N for both writers in one child fork. + Format the date subdir ("YYYY-MM-DD") and the log basename + ("YYYY_MM_DD_HH:MM:SS") for the UTC time `utc`. `use_offset` mirrors + KEY_FLAG_USE_TZ: when true, the finite tz_offset_hours (fractional + allowed, clamped to [-12,+14]) is applied and formatted with gmtime — + a fixed GMT offset, no DST, so 0 is genuine GMT. When false (the + default, and every legacy entry), the time is formatted in the + server's own local timezone; tz_offset_hours is ignored. */ -unsigned next_session_n(uint32_t port2, const char *base_dir); +void session_time_strings(time_t utc, bool use_offset, double tz_offset_hours, + char *datedir, size_t datedir_len, + char *name, size_t name_len); + +/* + Make `name` (a basename from session_time_strings) unique within + logs/// across BOTH the .tlog and .bin extensions: if + a file with that base already exists (a same-second session start, or + a reboot rotation landing in the same second), append "-2", "-3", … + until free. Modifies `name` in place. Cheap — only touched once per + file open. + */ +void session_unique_basename(const char *base_dir, uint32_t port2, + const char *datedir, + char *name, size_t name_len); diff --git a/supportproxy.cpp b/supportproxy.cpp index 3df2170..c0eecab 100644 --- a/supportproxy.cpp +++ b/supportproxy.cpp @@ -82,6 +82,7 @@ struct listen_port { uint32_t flags; uint8_t fc_sysid; // 0 = match any; otherwise the FC's MAVLink // sysid for binlog reboot detection + float tz_offset_hours; // log-naming timezone (GMT offset in hours) bool seen; // set true by handle_record() during reload_ports() // for any entry that's still in the DB; entries left // unseen after a reload have been removed. @@ -134,7 +135,8 @@ static void close_sockets(struct listen_port *p); Used both at startup and on each reload; reload_ports() handles the flip side (entries that were in keys.tdb last time and aren't now). */ -static void upsert_port(int port1, int port2, uint32_t flags, uint8_t fc_sysid) +static void upsert_port(int port1, int port2, uint32_t flags, uint8_t fc_sysid, + float tz_offset_hours) { for (auto *p = ports; p; p=p->next) { if (p->port2 == port2) { @@ -146,6 +148,7 @@ static void upsert_port(int port1, int port2, uint32_t flags, uint8_t fc_sysid) p->port1 = port1; p->flags = flags; p->fc_sysid = fc_sysid; + p->tz_offset_hours = tz_offset_hours; if (p->pid == 0) { open_sockets(p); } @@ -161,12 +164,14 @@ static void upsert_port(int port1, int port2, uint32_t flags, uint8_t fc_sysid) p->port1 = port1; p->flags = flags; p->fc_sysid = fc_sysid; + p->tz_offset_hours = tz_offset_hours; if (p->pid == 0) { open_sockets(p); } } else { p->flags = flags; p->fc_sysid = fc_sysid; + p->tz_offset_hours = tz_offset_hours; } return; } @@ -182,6 +187,7 @@ static void upsert_port(int port1, int port2, uint32_t flags, uint8_t fc_sysid) p->pid = 0; p->flags = flags; p->fc_sysid = fc_sysid; + p->tz_offset_hours = tz_offset_hours; p->seen = true; p->removed = false; ports = p; @@ -204,7 +210,8 @@ static int handle_record(struct tdb_context *db, TDB_DATA key, TDB_DATA data, vo // KeyEntry.fc_sysid is uint32 for forward compat; the wire value is // a MAVLink sysid (0..255), so truncate to uint8 once it crosses the // C++/binlog boundary. The CLI / web UI already cap at 255. - upsert_port(k.port1, port2, k.flags, uint8_t(k.fc_sysid)); + upsert_port(k.port1, port2, k.flags, uint8_t(k.fc_sysid), + k.tz_offset_hours); return 0; } @@ -276,11 +283,21 @@ static void main_loop(struct listen_port *p) sigaction(SIGUSR1, &sa, nullptr); } - // session_n is computed once at fork start and shared between the - // tlog and (further down) the binlog writer so the paired files - // — sessionN.tlog + sessionN.bin — share their N regardless of - // which writer activates first or whether one of them never does. - const unsigned session_n = next_session_n(uint32_t(p->port2), "logs"); + // Log naming: one timestamp basename computed once at fork start + // (in the entry's log-naming timezone) and shared between the tlog + // and (further down) the binlog writer, so the paired files — + // .tlog + .bin — share their name and date subdir + // regardless of which writer activates first or whether one never + // does. Made unique up front so a same-second session start doesn't + // clobber an existing file. + const bool use_tz = (p->flags & KEY_FLAG_USE_TZ) != 0; + char log_datedir[16]; + char log_name[64]; + session_time_strings(time(nullptr), use_tz, p->tz_offset_hours, + log_datedir, sizeof(log_datedir), + log_name, sizeof(log_name)); + session_unique_basename("logs", uint32_t(p->port2), log_datedir, + log_name, sizeof(log_name)); // bidi: initialise the user-side validator once. Re-initialising // per unsigned datagram (as the pre-latch path originally did) @@ -299,7 +316,7 @@ static void main_loop(struct listen_port *p) const bool tlog_enabled = (p->flags & KEY_FLAG_TLOG) != 0; auto ensure_tlog_open = [&]() { if (tlog_enabled && !tlog.is_open()) { - tlog.open(uint32_t(p->port2), session_n); + tlog.open(uint32_t(p->port2), log_datedir, log_name); } }; auto tlog_ptr = [&]() -> TlogWriter * { @@ -318,6 +335,10 @@ static void main_loop(struct listen_port *p) // Per-entry sysid filter for SYSTEM_TIME-based reboot // detection. 0 (default) accepts any sysid. binlog.set_fc_sysid_filter(p->fc_sysid); + // Timezone (for the reboot-rotated file's timestamp name) and + // the shared session paths for the initial lazy open. + binlog.set_tz(use_tz, p->tz_offset_hours); + binlog.set_session_paths(log_datedir, log_name); } // Tap helper: returns true if the message was consumed by binlog // and the caller should NOT forward it to the engineer side. @@ -335,7 +356,7 @@ static void main_loop(struct listen_port *p) return false; } if (m.msgid == MAVLINK_MSG_ID_REMOTE_LOG_DATA_BLOCK) { - binlog.handle_block(uint32_t(p->port2), session_n, m); + binlog.handle_block(uint32_t(p->port2), m); } return true; // strip from user→engineer }; diff --git a/tests/test_binlog_capture.py b/tests/test_binlog_capture.py index 2713c61..a5ebede 100644 --- a/tests/test_binlog_capture.py +++ b/tests/test_binlog_capture.py @@ -21,6 +21,7 @@ import datetime import hashlib import os +import re import signal import socket import struct @@ -52,7 +53,10 @@ def _today_str(): - return datetime.datetime.now().strftime('%Y-%m-%d') + # The proxy names date dirs in the entry's log timezone; with none + # set that's the server's local timezone (the default), so use + # localtime here. + return time.strftime('%Y-%m-%d', time.localtime()) @pytest.fixture @@ -134,9 +138,49 @@ def _terminate(proc): time.sleep(0.3) +# Proxy-written session .bin names: YYYY_MM_DD_HH:MM:SS[-N].bin. Used to +# distinguish real session files from test-seeded fixtures like +# prefill.bin that share the .bin suffix. +_SESSION_BIN_RE = re.compile( + r'^\d{4}_\d{2}_\d{2}_\d{2}:\d{2}:\d{2}(-\d+)?\.bin$') + + +def _bins(workdir, port_eng): + """Proxy-written session .bin files under today's dir, oldest-first. + + Filters to the timestamp naming so test-seeded fixtures (prefill.bin) + are excluded, and sorts by mtime — the '-N' collision suffix makes + lexical order unreliable ('-' < '.').""" + d = workdir / 'logs' / str(port_eng) / _today_str() + if not d.is_dir(): + return [] + fs = [p for p in d.iterdir() if _SESSION_BIN_RE.match(p.name)] + fs.sort(key=lambda p: (p.stat().st_mtime, p.name)) + return fs + + def _bin_path(workdir, port_eng, n=1): + """The n-th (1-indexed, oldest-first) .bin file, or a placeholder + path that does not exist when fewer than n files are present (so + callers' .exists() polling works unchanged).""" + fs = _bins(workdir, port_eng) + if len(fs) >= n: + return fs[n - 1] return (workdir / 'logs' / str(port_eng) / _today_str() - / ('session%d.bin' % n)) + / ('__pending_%d.bin' % n)) + + +def _wait_bin(workdir, port_eng, n=1, min_size=1, timeout=5.0): + """Poll until the n-th session .bin exists with at least min_size + bytes; return its Path, or None on timeout. Re-resolves the glob each + poll because the timestamp name isn't known ahead of time.""" + deadline = time.time() + timeout + while time.time() < deadline: + p = _bin_path(workdir, port_eng, n) + if p.exists() and p.stat().st_size >= min_size: + return p + time.sleep(0.05) + return None def _wait_for(predicate, timeout=5.0): @@ -226,6 +270,112 @@ def _recv_block_statuses(sock, timeout=2.0): reason='supportproxy binary not built') class TestBinlogCapture: + def test_bin_named_by_timestamp_in_entry_timezone(self, proxy_workdir): + """The .bin file (and its date subdir) are named by the session + timestamp formed in the entry's log timezone. With a +10h offset + the name must be ~10h ahead of the UTC wall clock.""" + db_path = str(proxy_workdir / 'keys.tdb') + db = keydb_lib.init_db(db_path) + db.transaction_start() + keydb_lib.add_entry(db, PORT_USER, PORT_ENG, 'tzbin', 'bp') + keydb_lib.set_flag(db, PORT_ENG, 'binlog') + keydb_lib.set_timezone(db, PORT_ENG, 10.0) # GMT+10 + db.transaction_prepare_commit() + db.transaction_commit() + db.close() + + proc = _start_proxy(proxy_workdir, PORT_ENG) + try: + sock = socket.socket(socket.AF_INET, socket.SOCK_DGRAM) + sock.bind(('127.0.0.1', 0)) + dest = ('127.0.0.1', PORT_USER) + utc_before = time.time() + for seq in range(3): + _send_data_block(sock, dest, seq, b'\x77' * 50) + time.sleep(0.05) + + # The date dir + file are in GMT+10, so glob the whole tree. + root = proxy_workdir / 'logs' / str(PORT_ENG) + deadline = time.time() + 5 + found = [] + while time.time() < deadline and not found: + found = list(root.glob('*/*.bin')) + time.sleep(0.05) + assert found, 'no .bin written; proxy log:\n%s' % ''.join( + proc._lines[-10:]) + base = found[0].name[:-4] # strip .bin + m = re.match( + r'^(\d{4})_(\d{2})_(\d{2})_(\d{2}):(\d{2}):(\d{2})(-\d+)?$', + base) + assert m, 'bad timestamp basename: %r' % base + # Reconstruct the named epoch (interpreted as GMT+10) and check + # it matches now+10h within a small window. + import calendar + named = calendar.timegm((int(m[1]), int(m[2]), int(m[3]), + int(m[4]), int(m[5]), int(m[6]), 0, 0, 0)) + expected = utc_before + 10 * 3600 + assert abs(named - expected) < 5, \ + 'named %s (%d) not ~10h ahead of UTC %d' % ( + base, named, utc_before) + # date subdir agrees with the filename's date + assert found[0].parent.name == '%s-%s-%s' % (m[1], m[2], m[3]) + sock.close() + finally: + _terminate(proc) + + def test_out_of_range_offset_is_clamped(self, proxy_workdir): + """A hand-edited record with use_tz set and an absurd offset (past + the [-12,+14] range) must be clamped by the proxy, not overflow + time_t. The name should land at UTC+14, not UTC+1000.""" + db_path = str(proxy_workdir / 'keys.tdb') + db = keydb_lib.init_db(db_path) + db.transaction_start() + keydb_lib.add_entry(db, PORT_USER, PORT_ENG, 'tzclamp', 'bp') + keydb_lib.set_flag(db, PORT_ENG, 'binlog') + # Bypass set_timezone's validation to plant a garbage offset with + # the use_tz flag on, as a corrupted/hand-edited record would. + ke = keydb_lib.KeyEntry(PORT_ENG) + ke.fetch(db) + ke.tz_offset_hours = 1000.0 + ke.flags |= keydb_lib.FLAG_USE_TZ + ke.store(db) + db.transaction_prepare_commit() + db.transaction_commit() + db.close() + + proc = _start_proxy(proxy_workdir, PORT_ENG) + try: + sock = socket.socket(socket.AF_INET, socket.SOCK_DGRAM) + sock.bind(('127.0.0.1', 0)) + dest = ('127.0.0.1', PORT_USER) + utc_before = time.time() + for seq in range(3): + _send_data_block(sock, dest, seq, b'\x77' * 50) + time.sleep(0.05) + root = proxy_workdir / 'logs' / str(PORT_ENG) + deadline = time.time() + 5 + found = [] + while time.time() < deadline and not found: + found = list(root.glob('*/*.bin')) + time.sleep(0.05) + assert proc.poll() is None, 'proxy crashed on absurd offset' + assert found, 'no .bin written; proxy log:\n%s' % ''.join( + proc._lines[-10:]) + import calendar + m = re.match( + r'^(\d{4})_(\d{2})_(\d{2})_(\d{2}):(\d{2}):(\d{2})(-\d+)?$', + found[0].name[:-4]) + assert m, 'bad basename: %r' % found[0].name + named = calendar.timegm((int(m[1]), int(m[2]), int(m[3]), + int(m[4]), int(m[5]), int(m[6]), 0, 0, 0)) + # clamped to +14h, not +1000h + assert abs(named - (utc_before + 14 * 3600)) < 5, \ + 'offset not clamped to +14h: named epoch %d vs utc %d' % ( + named, utc_before) + sock.close() + finally: + _terminate(proc) + def test_data_blocks_land_in_bin_file(self, proxy_workdir): _setup_db(proxy_workdir, PORT_USER, PORT_ENG, 'bintest', 'bp', 'binlog') @@ -550,10 +700,10 @@ def test_bin_parses_with_dfreader(self, proxy_workdir): _terminate(proc) def test_paired_session_n_with_tlog(self, proxy_workdir): - """tlog + binlog flags both set on one entry should produce - sessionN.tlog and sessionN.bin sharing the same N. We drive - traffic from a single raw socket (sending DATA_BLOCKs) so the - proxy's connect() on first peer doesn't lock us out of + """tlog + binlog flags both set on one entry should produce a + .tlog and a .bin sharing the same timestamp basename. We + drive traffic from a single raw socket (sending DATA_BLOCKs) so + the proxy's connect() on first peer doesn't lock us out of subsequent sends. DATA_BLOCK frames are valid MAVLink, so they trip the tlog tap @@ -590,11 +740,14 @@ def test_paired_session_n_with_tlog(self, proxy_workdir): date_dir = (proxy_workdir / 'logs' / str(PORT_ENG_PAIR) / _today_str()) files = sorted(p.name for p in date_dir.iterdir()) - assert (date_dir / 'session1.tlog').exists(), \ - 'no session1.tlog; have %r' % files - assert (date_dir / 'session1.bin').exists(), \ - 'no session1.bin; have %r\nproxy log:\n%s' % ( + tlogs = [p.name[:-5] for p in date_dir.glob('*.tlog')] + bins = [p.name[:-4] for p in date_dir.glob('*.bin')] + assert len(tlogs) == 1 and len(bins) == 1, \ + 'expected one .tlog and one .bin; have %r\nproxy log:\n%s' % ( files, ''.join(getattr(proc, '_lines', []))) + # paired: the .tlog and .bin share the timestamp basename + assert tlogs[0] == bins[0], \ + 'paired basenames differ: %r vs %r' % (tlogs[0], bins[0]) finally: _terminate(proc) @@ -902,10 +1055,8 @@ def test_quota_breach_triggers_immediate_cleanup(self, proxy_workdir): # the write lands. _send_data_block(sock, dest, 0, b'\xaa' * 50) - bin_path = _bin_path(proxy_workdir, PORT_ENG) - assert _wait_for( - lambda: bin_path.exists() and bin_path.stat().st_size >= 200, - timeout=5.0), \ + assert _wait_bin(proxy_workdir, PORT_ENG, min_size=200) \ + is not None, \ 'write did not proceed after quota breach; proxy log:\n%s' \ % ''.join(proc._lines[-10:]) assert not prefilled.exists(), \ @@ -936,10 +1087,8 @@ def test_quota_boundary_prospective_breach_frees(self, proxy_workdir): dest = ('127.0.0.1', PORT_USER) _send_data_block(sock, dest, 0, b'\xaa' * 50) - bin_path = _bin_path(proxy_workdir, PORT_ENG) - assert _wait_for( - lambda: bin_path.exists() and bin_path.stat().st_size >= 200, - timeout=5.0), \ + assert _wait_bin(proxy_workdir, PORT_ENG, min_size=200) \ + is not None, \ 'boundary breach never freed; proxy log:\n%s' \ % ''.join(proc._lines[-10:]) assert not prefilled.exists(), \ @@ -972,11 +1121,8 @@ def test_sparse_forward_jump_not_charged_as_logical_size( _send_data_block(sock, dest, 0, b'\xaa' * 50) _send_data_block(sock, dest, 1600, b'\xbb' * 50) - bin_path = _bin_path(proxy_workdir, PORT_ENG) - assert _wait_for( - lambda: bin_path.exists() - and bin_path.stat().st_size == 1600 * 200 + 200, - timeout=5.0), \ + assert _wait_bin(proxy_workdir, PORT_ENG, + min_size=1600 * 200 + 200) is not None, \ 'sparse jump falsely tripped the quota; proxy log:\n%s' \ % ''.join(proc._lines[-10:]) @@ -1101,10 +1247,8 @@ def test_instream_seqno0_restart_rotates(self, proxy_workdir): _send_data_block(sock, dest, 0, b'\x33' * 50) _send_data_block(sock, dest, 1, b'\x33' * 50) - session2 = _bin_path(proxy_workdir, PORT_ENG, n=2) - assert _wait_for( - lambda: session2.exists() and session2.stat().st_size >= 400, - timeout=5.0), \ + assert _wait_bin(proxy_workdir, PORT_ENG, n=2, min_size=400) \ + is not None, \ 'no rotation on in-stream seqno=0; proxy log:\n%s' \ % ''.join(proc._lines[-10:]) @@ -1161,10 +1305,8 @@ def test_midstream_vehicle_gets_stop_nudge(self, proxy_workdir): # START restarts it from seqno 0 — data must now land. _send_data_block(sock, dest, 0, b'\x55' * 50) _send_data_block(sock, dest, 1, b'\x55' * 50) - bin_path = _bin_path(proxy_workdir, PORT_ENG) - assert _wait_for( - lambda: bin_path.exists() and bin_path.stat().st_size >= 400, - timeout=5.0), 'restart from seqno 0 did not open the file' + assert _wait_bin(proxy_workdir, PORT_ENG, min_size=400) \ + is not None, 'restart from seqno 0 did not open the file' sock.close() finally: @@ -1183,10 +1325,8 @@ def test_malformed_quota_env_ignored(self, proxy_workdir): dest = ('127.0.0.1', PORT_USER) _send_data_block(sock, dest, 0, b'\xaa' * 50) - bin_path = _bin_path(proxy_workdir, PORT_ENG) - assert _wait_for( - lambda: bin_path.exists() and bin_path.stat().st_size >= 200, - timeout=5.0), \ + assert _wait_bin(proxy_workdir, PORT_ENG, min_size=200) \ + is not None, \ "writes blocked - '1GB' was prefix-parsed; proxy log:\n%s" \ % ''.join(proc._lines[-10:]) sock.close() diff --git a/tests/test_keydb_log.py b/tests/test_keydb_log.py index 5ea315e..894db89 100644 --- a/tests/test_keydb_log.py +++ b/tests/test_keydb_log.py @@ -44,7 +44,8 @@ def test_pack_unpack_roundtrip(): assert e2.flags == keydb_lib.FLAG_TLOG | keydb_lib.FLAG_ADMIN # float32 quantisation: tolerate ~1e-7 relative error assert abs(e2.log_retention_days - 0.0001) < 1e-7 - assert e2.reserved == [0] * 15 + assert e2.tz_offset_hours == 0.0 + assert e2.reserved == [0] * 14 def test_legacy_104byte_record_zero_extends(): @@ -69,7 +70,8 @@ def test_legacy_104byte_record_zero_extends(): assert decoded.flags == keydb_lib.FLAG_ADMIN assert decoded.log_retention_days == 0.0 assert decoded.fc_sysid == 0 - assert decoded.reserved == [0] * 15 + assert decoded.tz_offset_hours == 0.0 + assert decoded.reserved == [0] * 14 # Re-pack: should emit the full 168-byte modern layout. re = decoded.pack() @@ -307,3 +309,70 @@ def test_legacy_104byte_record_decodes_fc_sysid_zero(tmp_path): decoded = keydb_lib.KeyEntry(0) decoded.unpack(legacy) assert decoded.fc_sysid == 0 + + +def test_tz_offset_round_trip(): + e = keydb_lib.KeyEntry(21002) + e.port1 = 21001 + e.tz_offset_hours = 5.5 + e2 = keydb_lib.KeyEntry(0) + e2.unpack(e.pack()) + assert abs(e2.tz_offset_hours - 5.5) < 1e-6 + assert e2.reserved == [0] * 14 + + +def test_format_tz_offset(): + assert keydb_lib.format_tz_offset(0) == 'GMT' + assert keydb_lib.format_tz_offset(5.5) == 'GMT+05:30' + assert keydb_lib.format_tz_offset(-3.75) == 'GMT-03:45' + assert keydb_lib.format_tz_offset(14) == 'GMT+14:00' + assert keydb_lib.format_tz_offset(float('nan')) == 'invalid' + + +def test_cli_settz_and_list(tmp_path): + p = str(tmp_path / 'keys.tdb') + assert _run_cli(p, 'initialise').returncode == 0 + assert _run_cli(p, 'add', '22001', '22002', 'CliTz', 'pw').returncode == 0 + r = _run_cli(p, 'settz', '22002', '5.5') + assert r.returncode == 0, r.stderr + assert 'GMT+05:30' in r.stdout + r = _run_cli(p, 'list') + # settz enables the use_tz flag and the fixed offset shows + assert 'tz=GMT+05:30' in r.stdout + assert 'use_tz' in r.stdout + # settz 0 with the flag on is a genuine GMT offset + r = _run_cli(p, 'settz', '22002', '0') + assert r.returncode == 0 + assert 'tz=GMT' in _run_cli(p, 'list').stdout + # clearing the flag reverts to server-local naming (no fixed tz shown) + assert _run_cli(p, 'clearflag', '22002', 'use_tz').returncode == 0 + out = _run_cli(p, 'list').stdout + assert 'tz=GMT' not in out and 'use_tz' not in out + + +def test_cli_settz_rejects_out_of_range(tmp_path): + p = str(tmp_path / 'keys.tdb') + _run_cli(p, 'initialise') + _run_cli(p, 'add', '23001', '23002', 'CliTzBad', 'pw') + r = _run_cli(p, 'settz', '23002', '20') + assert r.returncode == 1 + assert 'must be in' in r.stdout + + +def test_set_timezone_rejects_nan(tmp_path): + import math + p = str(tmp_path / 'keys.tdb') + db = keydb_lib.init_db(p) + db.transaction_start() + keydb_lib.add_entry(db, 24001, 24002, 'nan', 'pw') + try: + keydb_lib.set_timezone(db, 24002, float('nan')) + assert False, 'NaN offset should be rejected' + except keydb_lib.CLIError: + pass + # stored value stays finite (unchanged default 0.0) + ke = keydb_lib.KeyEntry(24002) + ke.fetch(db) + assert math.isfinite(ke.tz_offset_hours) and ke.tz_offset_hours == 0.0 + db.transaction_cancel() + db.close() diff --git a/tests/test_tlog_capture.py b/tests/test_tlog_capture.py index d1763d4..f0c1880 100644 --- a/tests/test_tlog_capture.py +++ b/tests/test_tlog_capture.py @@ -4,10 +4,10 @@ starts supportproxy there, drives a few HEARTBEATs in each direction, kills the proxy, and asserts: - * logs///session1.tlog exists, is non-empty, and parses + * logs///.tlog exists, is non-empty, and parses with pymavlink.mavutil.mavlink_connection - * a second connection (after the first child idles out) produces - session2.tlog + * a second connection (after the first child idles out) produces a + second .tlog * timestamps in the tlog are monotonic * messages from BOTH directions appear (at minimum, both sides' HEARTBEATs are seen) @@ -43,8 +43,29 @@ def _today_str(): - """Match the proxy's localtime-based directory naming.""" - return datetime.datetime.now().strftime('%Y-%m-%d') + """Match the proxy's date-dir naming. With no per-entry timezone set + the proxy names in the server's local timezone (the default), so use + localtime here.""" + return time.strftime('%Y-%m-%d', time.localtime()) + + +def _tlogs(workdir, port_eng): + """All .tlog files under today's dir for port_eng, oldest-first.""" + d = workdir / 'logs' / str(port_eng) / _today_str() + if not d.is_dir(): + return [] + fs = [p for p in d.iterdir() if p.suffix == '.tlog'] + fs.sort(key=lambda p: (p.stat().st_mtime, p.name)) + return fs + + +def _only_tlog(workdir, port_eng): + """The single .tlog for this session, or a placeholder path that + doesn't exist yet.""" + fs = _tlogs(workdir, port_eng) + if fs: + return fs[0] + return workdir / 'logs' / str(port_eng) / _today_str() / '__pending.tlog' @pytest.fixture @@ -224,10 +245,9 @@ def test_session1_created_with_bidirectional_traffic(self, proxy_workdir): finally: _terminate(proc) - tlog = (proxy_workdir / 'logs' / str(PORT_ENG) - / _today_str() / 'session1.tlog') - assert tlog.exists(), 'expected %s to exist; proxy stdout: %s' % ( - tlog, ''.join(getattr(proc, '_lines', []))) + tlog = _only_tlog(proxy_workdir, PORT_ENG) + assert tlog.exists(), 'expected a .tlog to exist; proxy stdout: %s' % ( + ''.join(getattr(proc, '_lines', []))) assert tlog.stat().st_size > 0 # Validate every record has a sane framed packet behind its 8-byte ts. @@ -263,8 +283,7 @@ def test_pymavlink_can_read_tlog(self, proxy_workdir): finally: _terminate(proc) - tlog = (proxy_workdir / 'logs' / str(PORT_ENG) - / _today_str() / 'session1.tlog') + tlog = _only_tlog(proxy_workdir, PORT_ENG) assert tlog.exists() msgs = _parse_tlog_with_pymavlink(str(tlog)) # We sent at minimum a few HEARTBEATs each way; pymavlink should @@ -302,11 +321,10 @@ def test_user_only_traffic_records_to_tlog(self, proxy_workdir): finally: _terminate(proc) - tlog = (proxy_workdir / 'logs' / str(PORT_ENG) - / _today_str() / 'session1.tlog') + tlog = _only_tlog(proxy_workdir, PORT_ENG) proxy_log = ''.join(getattr(proc, '_lines', [])) assert tlog.exists(), \ - ('session1.tlog missing — user-only traffic was discarded.\n' + ('.tlog missing — user-only traffic was discarded.\n' 'sent %d heartbeats. proxy log:\n%s' % (n_sent, proxy_log)) assert tlog.stat().st_size > 0, \ 'tlog is empty; parse loop did not write the user frames' @@ -342,8 +360,8 @@ def test_second_connection_creates_session2(self, proxy_workdir): date_dir = proxy_workdir / 'logs' / str(PORT_ENG) / _today_str() proxy_log = ''.join(getattr(proc, '_lines', [])) - assert (date_dir / 'session1.tlog').exists(), proxy_log - assert (date_dir / 'session2.tlog').exists(), ( - 'expected session2.tlog after second connection; have %r\n' + tlogs = _tlogs(proxy_workdir, PORT_ENG) + assert len(tlogs) == 2, ( + 'expected two .tlog files after a second connection; have %r\n' 'proxy log:\n%s' % ( sorted(p.name for p in date_dir.iterdir()), proxy_log)) diff --git a/tests/webadmin/test_log_routes.py b/tests/webadmin/test_log_routes.py index a629a1b..bf3f072 100644 --- a/tests/webadmin/test_log_routes.py +++ b/tests/webadmin/test_log_routes.py @@ -192,6 +192,45 @@ def test_admin_can_set_fractional(self, client, keydb_path): ke = fetch_entry(keydb_path, ALICE_PORT2) assert ke.log_retention_days == 0.5 + def test_owner_can_enable_fixed_timezone(self, client, keydb_path): + import keydb_lib + login_as(client, ALICE_PORT1, ALICE_PASS) + client.post('/me/', data={ + 'name': 'alice', + 'use_tz': 'y', + 'tz_offset_hours': '5.5', + 'submit': 'Save', + }) + ke = fetch_entry(keydb_path, ALICE_PORT2) + assert abs(ke.tz_offset_hours - 5.5) < 1e-6 + assert ke.flags & keydb_lib.FLAG_USE_TZ + + def test_owner_unticking_use_tz_reverts_to_local(self, client, keydb_path): + import keydb_lib + login_as(client, ALICE_PORT1, ALICE_PASS) + # enable, then submit again without the box -> flag cleared, + # offset retained. + client.post('/me/', data={ + 'name': 'alice', 'use_tz': 'y', 'tz_offset_hours': '5.5', + 'submit': 'Save'}) + client.post('/me/', data={ + 'name': 'alice', 'tz_offset_hours': '5.5', 'submit': 'Save'}) + ke = fetch_entry(keydb_path, ALICE_PORT2) + assert not (ke.flags & keydb_lib.FLAG_USE_TZ) + assert abs(ke.tz_offset_hours - 5.5) < 1e-6 + + def test_owner_timezone_out_of_range_rejected(self, client, keydb_path): + login_as(client, ALICE_PORT1, ALICE_PASS) + r = client.post('/me/', data={ + 'name': 'alice', + 'use_tz': 'y', + 'tz_offset_hours': '20', + 'submit': 'Save', + }) + # form validation fails -> re-render, value not stored + ke = fetch_entry(keydb_path, ALICE_PORT2) + assert ke.tz_offset_hours == 0.0 + # --------------------------------------------------------------------------- # listing & download @@ -302,6 +341,72 @@ def test_bogus_extension_still_404s(self, client, logs_dir): assert r.status_code == 404 +class TestTimestampNames: + """Session files are named by YYYY_MM_DD_HH:MM:SS timestamp now. + The listing regex must accept them (with the ':' in the name) and + downloads must work despite the colons in the URL path.""" + + TS = '2026_07_19_09:37:10' + + def test_timestamp_names_listed(self, client, keydb_path, logs_dir): + seed_session(logs_dir, ALICE_PORT2, '2026-07-19', + self.TS + '.tlog', content=b'TLOG') + seed_session(logs_dir, ALICE_PORT2, '2026-07-19', + self.TS + '.bin', content=b'BIN') + login_as(client, ALICE_PORT1, ALICE_PASS) + r = client.get('/me/logs/2026-07-19/') + assert r.status_code == 200 + assert (self.TS + '.tlog').encode() in r.data + assert (self.TS + '.bin').encode() in r.data + + def test_timestamp_name_downloads(self, client, keydb_path, logs_dir): + seed_session(logs_dir, ALICE_PORT2, '2026-07-19', + self.TS + '.bin', content=b'\x00ARDUPILOT') + login_as(client, ALICE_PORT1, ALICE_PASS) + r = client.get('/me/logs/2026-07-19/' + self.TS + '.bin') + assert r.status_code == 200 + assert r.data.endswith(b'ARDUPILOT') + + def test_collision_suffix_name_ok(self, client, keydb_path, logs_dir): + seed_session(logs_dir, ALICE_PORT2, '2026-07-19', + self.TS + '-2.tlog', content=b'X') + login_as(client, ALICE_PORT1, ALICE_PASS) + r = client.get('/me/logs/2026-07-19/') + assert (self.TS + '-2.tlog').encode() in r.data + r = client.get('/me/logs/2026-07-19/' + self.TS + '-2.tlog') + assert r.status_code == 200 + + def test_pid_ns_fallback_name_browsable(self, client, keydb_path, + logs_dir): + # The exhaustion fallback is a single big numeric "-N" suffix + # (pid+nanoseconds concatenated); it must list and download like + # any other session file. + fb = self.TS + '-149785439335901.bin' + seed_session(logs_dir, ALICE_PORT2, '2026-07-19', fb, content=b'F') + login_as(client, ALICE_PORT1, ALICE_PASS) + r = client.get('/me/logs/2026-07-19/') + assert fb.encode() in r.data + r = client.get('/me/logs/2026-07-19/' + fb) + assert r.status_code == 200 + + def test_collision_suffix_chronological_order(self, client, keydb_path, + logs_dir): + # The unsuffixed original is the first session that second and + # must list BEFORE its -2 / -10 collision siblings, even though + # lexically '-' < '.'. + for suffix in ('-10', '', '-2'): + seed_session(logs_dir, ALICE_PORT2, '2026-07-19', + self.TS + suffix + '.bin', content=b'X') + login_as(client, ALICE_PORT1, ALICE_PASS) + body = client.get('/me/logs/2026-07-19/').data.decode() + i_base = body.index(self.TS + '.bin') + i_2 = body.index(self.TS + '-2.bin') + i_10 = body.index(self.TS + '-10.bin') + assert i_base < i_2 < i_10, \ + 'collision suffixes out of order: base=%d -2=%d -10=%d' % ( + i_base, i_2, i_10) + + class TestTlogDownloadCacheHeaders: """Tlog payloads contain raw vehicle telemetry. They must not be cached by browsers or intermediaries — even though the rest of diff --git a/tlog.cpp b/tlog.cpp index c563828..e14a8e6 100644 --- a/tlog.cpp +++ b/tlog.cpp @@ -19,22 +19,15 @@ TlogWriter::~TlogWriter() close(); } -bool TlogWriter::open(uint32_t port2, unsigned session_n, const char *base_dir) +bool TlogWriter::open(uint32_t port2, const char *datedir, const char *name, + const char *base_dir) { if (fp != nullptr) { return true; } - time_t now = time(nullptr); - struct tm tm_now; - localtime_r(&now, &tm_now); - char dir[768]; - snprintf(dir, sizeof(dir), "%s/%u/%04d-%02d-%02d", - base_dir, port2, - tm_now.tm_year + 1900, - tm_now.tm_mon + 1, - tm_now.tm_mday); + snprintf(dir, sizeof(dir), "%s/%u/%s", base_dir, port2, datedir); if (mkpath_0700(dir) < 0) { ::printf("tlog: mkdir %s failed: %s\n", dir, strerror(errno)); @@ -42,7 +35,7 @@ bool TlogWriter::open(uint32_t port2, unsigned session_n, const char *base_dir) } char path[1024]; - snprintf(path, sizeof(path), "%s/session%u.tlog", dir, session_n); + snprintf(path, sizeof(path), "%s/%s.tlog", dir, name); fp = fopen(path, "ab"); if (fp == nullptr) { diff --git a/tlog.h b/tlog.h index 218393e..6b3bd4a 100644 --- a/tlog.h +++ b/tlog.h @@ -20,12 +20,13 @@ class TlogWriter { TlogWriter &operator=(const TlogWriter &) = delete; /* - open logs///sessionN.tlog. The caller supplies - session_n via the shared next_session_n() helper so the paired - .tlog / .bin files for one child fork share their N. Creates parent - dirs as needed. Returns true on success. + open logs///.tlog. The caller supplies the + timestamp datedir + basename (from session_time_strings / + session_unique_basename) so the paired .tlog / .bin files for one + child fork share their name. Creates parent dirs as needed. + Returns true on success. */ - bool open(uint32_t port2, unsigned session_n, + bool open(uint32_t port2, const char *datedir, const char *name, const char *base_dir = "logs"); /* diff --git a/webadmin/forms.py b/webadmin/forms.py index 8c132ce..8efab84 100644 --- a/webadmin/forms.py +++ b/webadmin/forms.py @@ -59,6 +59,13 @@ class OwnerEditForm(FlaskForm): 'Flight-controller MAVLink sysid (0 = any) — restricts binlog ' 'reboot detection to packets from this sysid', validators=[Optional(), NumberRange(min=0, max=255)]) + use_tz = BooleanField( + 'Name logs in a fixed timezone (below) instead of the server\'s ' + 'local time') + tz_offset_hours = FloatField( + 'Log timezone (GMT offset in hours, fractional ok; 0 = GMT) — ' + 'used only when the box above is ticked', + validators=[Optional(), NumberRange(min=-12.0, max=14.0)]) reset_timestamp = BooleanField('Reset signing timestamp (recover from clock skew)') submit = SubmitField('Save') @@ -94,6 +101,13 @@ class AdminEditForm(FlaskForm): 'Flight-controller MAVLink sysid (0 = any) — restricts binlog ' 'reboot detection to packets from this sysid', validators=[Optional(), NumberRange(min=0, max=255)]) + use_tz = BooleanField( + 'Name logs in a fixed timezone (below) instead of the server\'s ' + 'local time') + tz_offset_hours = FloatField( + 'Log timezone (GMT offset in hours, fractional ok; 0 = GMT) — ' + 'used only when the box above is ticked', + validators=[Optional(), NumberRange(min=-12.0, max=14.0)]) reset_timestamp = BooleanField('Reset signing timestamp (recover from clock skew)') submit = SubmitField('Save') diff --git a/webadmin/logs.py b/webadmin/logs.py index 4ed8eb3..2e3da2a 100644 --- a/webadmin/logs.py +++ b/webadmin/logs.py @@ -2,8 +2,12 @@ Covers both file types written under logs///: - * sessionN.tlog — raw MAVLink frame captures (KEY_FLAG_TLOG) - * sessionN.bin — ArduPilot dataflash logs over MAVLink (KEY_FLAG_BINLOG) + * .tlog — raw MAVLink frame captures (KEY_FLAG_TLOG) + * .bin — ArduPilot dataflash logs over MAVLink (KEY_FLAG_BINLOG) + +where is a YYYY_MM_DD_HH:MM:SS session-start timestamp (with an +optional "-N" collision suffix). Legacy sessionN.* names are still +accepted so older logs remain browsable. Two parallel views, sharing the listing/download helpers below: @@ -29,8 +33,10 @@ # Cover both .tlog (raw MAVLink frames) and .bin (ArduPilot dataflash # logs over MAVLink). Listing + download flow through this regex, so # broadening it surfaces .bin files alongside .tlog without further -# changes. -SESSION_RE = re.compile(r'^session\d+\.(tlog|bin)$') +# changes. Accept the current YYYY_MM_DD_HH:MM:SS[-N] timestamp names +# and the legacy sessionN names so old logs stay browsable. +SESSION_RE = re.compile( + r'^(session\d+|\d{4}_\d{2}_\d{2}_\d{2}:\d{2}:\d{2}(-\d+)?)\.(tlog|bin)$') # Natural-sort key: treat embedded digit runs as numbers so that # session10.tlog sorts AFTER session2.tlog (not between session1 and @@ -39,8 +45,19 @@ # digit chunks. _NATKEY_RE = re.compile(r'(\d+)') +# A timestamp session name, with an optional "-N" collision suffix. An +# unsuffixed file is the original for that second and must sort BEFORE +# its "-N" siblings — but lexically "-" < ".", so "-2.bin" would +# otherwise beat ".bin". Normalise the unsuffixed name to "-1" for +# the sort key so the numeric suffix orders it correctly. +_TS_NAME_RE = re.compile( + r'^(\d{4}_\d{2}_\d{2}_\d{2}:\d{2}:\d{2})(-\d+)?(\.\w+)$') + def _natural_key(name): + m = _TS_NAME_RE.match(name) + if m and not m.group(2): + name = m.group(1) + '-1' + m.group(3) return [int(tok) if tok.isdigit() else tok.lower() for tok in _NATKEY_RE.split(name)] diff --git a/webadmin/routes_admin.py b/webadmin/routes_admin.py index 1e3b239..97463b4 100644 --- a/webadmin/routes_admin.py +++ b/webadmin/routes_admin.py @@ -205,6 +205,12 @@ def edit(port2): ke.log_retention_days = keydb_lib.DEFAULT_LOG_RETENTION_DAYS if form.fc_sysid.data is not None: ke.fc_sysid = int(form.fc_sysid.data) + if form.tz_offset_hours.data is not None: + ke.tz_offset_hours = float(form.tz_offset_hours.data) + if form.use_tz.data: + ke.flags |= keydb_lib.FLAG_USE_TZ + else: + ke.flags &= ~keydb_lib.FLAG_USE_TZ if form.reset_timestamp.data: ke.timestamp = 0 ke.store(db) @@ -227,6 +233,8 @@ def edit(port2): form.binlog_enabled.data = bool(ke.flags & keydb_lib.FLAG_BINLOG) form.log_retention_days.data = ke.log_retention_days form.fc_sysid.data = ke.fc_sysid + form.tz_offset_hours.data = ke.tz_offset_hours + form.use_tz.data = bool(ke.flags & keydb_lib.FLAG_USE_TZ) return render_template('admin_edit.html', form=form, entry=ke, delete_form=delete_form) diff --git a/webadmin/routes_owner.py b/webadmin/routes_owner.py index d31217e..028b3db 100644 --- a/webadmin/routes_owner.py +++ b/webadmin/routes_owner.py @@ -81,6 +81,12 @@ def me(): ke.log_retention_days = keydb_lib.DEFAULT_LOG_RETENTION_DAYS if form.fc_sysid.data is not None: ke.fc_sysid = int(form.fc_sysid.data) + if form.tz_offset_hours.data is not None: + ke.tz_offset_hours = float(form.tz_offset_hours.data) + if form.use_tz.data: + ke.flags |= keydb_lib.FLAG_USE_TZ + else: + ke.flags &= ~keydb_lib.FLAG_USE_TZ if form.reset_timestamp.data: ke.timestamp = 0 ke.store(db) @@ -101,6 +107,8 @@ def me(): form.binlog_enabled.data = bool(ke.flags & keydb_lib.FLAG_BINLOG) form.log_retention_days.data = ke.log_retention_days form.fc_sysid.data = ke.fc_sysid + form.tz_offset_hours.data = ke.tz_offset_hours + form.use_tz.data = bool(ke.flags & keydb_lib.FLAG_USE_TZ) active = conn_db.list_for_port2(port2) return render_template('owner.html', form=form, entry=ke, active=active, kill_form=KillForm()) diff --git a/webadmin/templates/admin_edit.html b/webadmin/templates/admin_edit.html index f4a7c2c..0870eb6 100644 --- a/webadmin/templates/admin_edit.html +++ b/webadmin/templates/admin_edit.html @@ -20,6 +20,8 @@

Edit entry {{ entry.port1 }}/{{ entry.port2 }}

{{ form.binlog_enabled() }} {{ form.binlog_enabled.label }}
{{ form.log_retention_days.label }}: {{ form.log_retention_days() }}
{{ form.fc_sysid.label }}: {{ form.fc_sysid() }}
+
{{ form.use_tz() }} {{ form.use_tz.label }}
+
{{ form.tz_offset_hours.label }}: {{ form.tz_offset_hours() }}
browse logs →
{{ form.reset_timestamp() }} {{ form.reset_timestamp.label }}
{{ form.submit() }}
diff --git a/webadmin/templates/owner.html b/webadmin/templates/owner.html index afb932a..4df4093 100644 --- a/webadmin/templates/owner.html +++ b/webadmin/templates/owner.html @@ -55,6 +55,8 @@

My entry

{{ form.binlog_enabled() }} {{ form.binlog_enabled.label }}
{{ form.log_retention_days.label }}: {{ form.log_retention_days() }}
{{ form.fc_sysid.label }}: {{ form.fc_sysid() }}
+
{{ form.use_tz() }} {{ form.use_tz.label }}
+
{{ form.tz_offset_hours.label }}: {{ form.tz_offset_hours() }}
browse logs →
{{ form.reset_timestamp() }} {{ form.reset_timestamp.label }}
{{ form.submit() }}