Add --log-interval flag and timestamp capture logs

Follow-ups from the capture-reliability review:
- All server-side capture log lines are now prefixed with a local
  timestamp (YYYY-MM-DD HH:MM:SS) for easier correlation.
- New --log-interval SECONDS CLI flag (default 60) tunes the
  "Capture alive" heartbeat interval; passed through to CaptureManager.

Stays on 1.22.0 (backend-only). 369 tests pass.

README.md

@@ -113,12 +113,14 @@ simtrace2-pysniff-server --capture direct
 simtrace2-pysniff-server --capture disabled
 ```
 
-The server logs its capture liveness to stderr: `Capture started` on
+The server logs its capture liveness to stderr (each line timestamped
-begin, a periodic `Capture alive: session=N messages=M bytes=B dropped=D`
+with the local time): `Capture started` on begin, a periodic
-heartbeat, and `Capture stopped` (or `ERROR: capture thread stopped on
+`Capture alive: session=N messages=M bytes=B dropped=D` heartbeat, and
-error …` if the capture thread died unexpectedly). A mis-framed or
+`Capture stopped` (or `ERROR: capture thread stopped on error …` if the
-non-SIM GSMTAP datagram is dropped and counted (`dropped`) rather than
+capture thread died unexpectedly). A mis-framed or non-SIM GSMTAP
-silently killing the capture.
+datagram is dropped and counted (`dropped`) rather than silently
+killing the capture. The heartbeat interval defaults to 60 s and is
+tunable via `--log-interval SECONDS`.
 
 The GSMTAP listener also accepts the **sigrok-iso7816-stream** decoder
 (https://github.com/anttro/sigrok_iso7816_stream) — an FX2-logic-analyzer

simtrace2_pysniff/server/__main__.py

@@ -35,7 +35,10 @@ def main():
     p.add_argument('--capture', choices=['gsmtap', 'direct', 'disabled'], default='gsmtap',
                    help='Capture mode: gsmtap (listen UDP 4729), direct (SIMtrace2 USB), or disabled (no capture)')
     p.add_argument('--gsmtap-port', type=int, default=4729,
-                   help='UDP port for GSMTAP listener (default: 4729)')
+                    help='UDP port for GSMTAP listener (default: 4729)')
+    p.add_argument('--log-interval', type=float, default=60.0,
+                    help='Seconds between capture liveness heartbeat logs '
+                         '(default: 60.0)')
     p.add_argument('--web-dir', default=_default_web_dir(), metavar='PATH',
                    help='Directory with the simtrace-analyser PWA static files to serve (default: <repo>/frontend)')
     args = p.parse_args()
@@ -45,10 +48,10 @@ def main():
     capture = None
     if args.capture == 'gsmtap':
         backend = GsmtapListener(bind_port=args.gsmtap_port)
-        capture = CaptureManager(backend, db)
+        capture = CaptureManager(backend, db, log_interval=args.log_interval)
     elif args.capture == 'direct':
         backend = DirectSniffer()
-        capture = CaptureManager(backend, db)
+        capture = CaptureManager(backend, db, log_interval=args.log_interval)
 
     RequestHandler.db = db
     RequestHandler.capture = capture

simtrace2_pysniff/server/capture.py

@@ -10,6 +10,15 @@ from ..gsmtap import (GsmtapReceiver, GSMTAP_SIM_ATR,
                       GSMTAP_SIM_RST_EVENT, GSMTAP_SIM_VCC_EVENT)
 
 
+def _ts():
+    """Local-time stamp for server-side capture log lines."""
+    return time.strftime('%Y-%m-%d %H:%M:%S')
+
+
+def _log(msg):
+    print(f'[{_ts()}] {msg}', file=sys.stderr)
+
+
 def gsmtap_msg_type(sub_type):
     """Map a GSMTAP-SIM sub_type to a stored message type.
 
@@ -51,8 +60,7 @@ class GsmtapListener:
                 # the whole capture — drop it and keep listening.
                 self._dropped += 1
                 if self._dropped <= 1 or self._dropped % 100 == 0:
-                    print(f'GSMTAP: dropped packet ({self._dropped}): {e}',
+                    _log(f'GSMTAP: dropped packet ({self._dropped}): {e}')
-                          file=sys.stderr)
                 continue
             if sub_type is None:
                 continue
@@ -147,8 +155,7 @@ class CaptureManager:
         self._thread.start()
 
         self._stop_event.clear()
-        print(f'Capture started (mode={mode}, session={self._session_id})',
+        _log(f'Capture started (mode={mode}, session={self._session_id})')
-              file=sys.stderr)
         self._log_thread = threading.Thread(target=self._log_loop, daemon=True)
         self._log_thread.start()
 
@@ -169,12 +176,11 @@ class CaptureManager:
         empty = self._db.count_messages(sid) == 0
         if empty:
             self._db.delete_session(sid)
-            print(f'Capture stopped: empty session discarded (session={sid})',
+            _log(f'Capture stopped: empty session discarded (session={sid})')
-                  file=sys.stderr)
             return None
         self._db.close_session(sid)
-        print(f'Capture stopped: session={sid} messages={self._msg_count} '
+        _log(f'Capture stopped: session={sid} messages={self._msg_count} '
-              f'bytes={self._byte_count}', file=sys.stderr)
+             f'bytes={self._byte_count}')
         return sid
 
     def _capture_loop(self):
@@ -190,14 +196,12 @@ class CaptureManager:
                     self._byte_count += len(data)
                     self._latest_msg_id = mid
                 except Exception as e:
-                    print(f'Capture: insert error, dropping msg: {e}',
+                    _log(f'Capture: insert error, dropping msg: {e}')
-                          file=sys.stderr)
                     continue
         except Exception:
             # The capture thread died unexpectedly (not a user stop).
             sid = self._session_id
-            print(f'ERROR: capture thread stopped on error (session={sid}):',
+            _log(f'ERROR: capture thread stopped on error (session={sid}):')
-                  file=sys.stderr)
             traceback.print_exc()
             self._stop_event.set()
             if sid is not None:
@@ -213,6 +217,6 @@ class CaptureManager:
             if self._session_id is None:
                 break
             dropped = getattr(self._backend, 'dropped', 0)
-            print(f'Capture alive: session={self._session_id} '
+            _log(f'Capture alive: session={self._session_id} '
-                  f'messages={self._msg_count} bytes={self._byte_count} '
+                 f'messages={self._msg_count} bytes={self._byte_count} '
-                  f'dropped={dropped}', file=sys.stderr)
+                 f'dropped={dropped}')