Changeset 11187 in ntrip for trunk/BNC/tests

Timestamp:

Nov 9, 2026, 5:37:55 PM (37 hours ago)

Author:

stuerze

Message:

Structured logging improved

Location:

trunk/BNC/tests

Files:

• README.md (modified) (1 diff)
• cases/log_structured/case.json (modified) (1 diff)
• cases/log_structured/expected/PPPQuickStart.jsonl.gz (modified) ( previous)
• cases/log_structured/expected/PPPQuickStart.logfmt.gz (modified) ( previous)
• cases/log_structured/expected/logcheck.txt.gz (modified) ( previous)
• tools/logcheck.py (modified) (5 diffs)

trunk/BNC/tests/README.md

@@ -33 +33 @@
 | `tools/net_check.py` | UDP/RTP sender filter and upload status checks on loopback (not part of `run_tests.py`) |
 | `tools/cred_check.py` | credentials files (`~/.netrc`, BNC format) for download and upload (not part of `run_tests.py`) |
-| `tools/logcheck.py` | structured logfile: JSON/logfmt syntax, both formats equal, `time` = `gpst` - leap seconds, `msg` = classic logfile |
+| `tools/logcheck.py` | structured logfile: JSON/logfmt syntax, both formats equal, `time` = classic GPS time stamp - leap seconds, optional `epoch`, `msg` = classic logfile |
 | `work/` | scratch output, not versioned |
 

trunk/BNC/tests/cases/log_structured/case.json

@@ -24 +24 @@
                      "-key", "logFormatStructured", "logfmt"]},
            {"dir": "chk", "tool": ["logcheck.py", "Output/PPPQuickStart.log_251117",
-                                   "Output/PPPQuickStart.jsonl_251117",
-                                   "lf/Output/PPPQuickStart.logfmt_251117"]}],
+                                   "Output/PPPQuickStart.jsonl",
+                                   "lf/Output/PPPQuickStart.logfmt"]}],
   "outputs": [
-    {"glob": "Output/PPPQuickStart.jsonl_251117", "name": "PPPQuickStart.jsonl"},
-    {"glob": "lf/Output/PPPQuickStart.logfmt_251117", "name": "PPPQuickStart.logfmt"},
+    {"glob": "Output/PPPQuickStart.jsonl", "name": "PPPQuickStart.jsonl"},
+    {"glob": "lf/Output/PPPQuickStart.logfmt", "name": "PPPQuickStart.logfmt"},
     {"glob": "chk/stdout.txt", "name": "logcheck.txt"}
   ]

trunk/BNC/tests/tools/logcheck.py

@@ -6 +6 @@
 Checks that every line of the JSON file is a JSON object and every line of the
 logfmt file a sequence of key=value pairs, that both carry the same records,
-that the records have the mandatory keys in the documented order, that 'time'
-(UTC) is 'gpst' minus the GPS-UTC leap seconds and that the 'msg' of the
-records equals the text of the classic logfile line by line (classic lines
-without their "yy-mm-dd hh:mm:ss " prefix; the start line is skipped, it goes
-to the file of the current date). Prints a summary of the records per level,
+that the records have the mandatory keys in the documented order (optional
+'epoch' after 'time', GPS Time without 'Z'), that the 'msg' of the records
+(for RTCM scan message types: 'mp', 'message_type', 'size') equals the text of
+the classic logfile line by line (classic lines without
+their "yy-mm-dd hh:mm:ss " prefix; the start line is skipped, it goes to the
+file of the current date) and that 'time' (UTC) is the GPS Time stamp of the
+classic line minus the GPS-UTC leap seconds. Prints a summary of the records per level,
 component and event; exit code 1 on any error.
 """
@@ -20 +22 @@
 import sys
 
-HEAD = ["time", "gpst", "level", "component", "event"]
+HEAD = ["time", "level", "component", "event"]
 LEVELS = {"info", "warning", "error"}
 LEAP_GPS_UTC = 18          # valid since 2017-01-01
@@ -68 +70 @@
 
 
+def classic_text(r):
+    """Text of the classic logfile line of a record: 'msg', except for the
+    message types of the RTCM scan, which carry the short text 'Received message'
+    and the details in their fields."""
+    if r.get("event") == "stream_content" and "message_type" in r:
+        if r["msg"] != "Received message":
+            return "unexpected msg %r" % r["msg"]
+        size = " (size %d)" % r["size"] if "size" in r else " "
+        return "%s: Received message type %d%s" % (r["mp"], r["message_type"], size)
+    return r.get("msg")
+
+
 def main():
     errors = []
-    classic = []
+    classic, stamps = [], []
     for line in open(sys.argv[1], encoding="latin-1", newline="").read().split("\r\n"):
         if not line or "========== Start BNC" in line:
             continue
-        classic.append(line[18:] if re.match(r"\d\d-\d\d-\d\d \d\d:\d\d:\d\d ", line) else line)
+        if re.match(r"\d\d-\d\d-\d\d \d\d:\d\d:\d\d ", line):
+            classic.append(line[18:])
+            stamps.append(datetime.datetime.strptime(line[:17], "%y-%m-%d %H:%M:%S"))
+        else:
+            classic.append(line)
+            stamps.append(None)
 
     recs = []
@@ -92 +111 @@
             errors.append("json %d records, logfmt %d" % (len(recs), len(lf)))
         for k, (a, b) in enumerate(zip(recs, lf), 1):
-            if list(a.keys()) != list(b.keys()) or any(a[x] != b[x] for x in a):
+            # the start line carries the wall clock time of each run
+            start = "========== Start BNC" in a.get("msg", "")
+            if list(a.keys()) != list(b.keys()) or any(a[x] != b[x] for x in a
+                                                        if not (start and x == "time")):
                 errors.append("record %d differs between json and logfmt" % k)
 
@@ -98 +120 @@
     for k, r in enumerate(recs, 1):
         keys = list(r.keys())
-        if keys[:5] != HEAD or keys[-2:] != ["msg", "v"]:
+        if keys[1:2] == ["epoch"]:
+            try:
+                datetime.datetime.strptime(r["epoch"], "%Y-%m-%dT%H:%M:%S.%f")
+            except ValueError:
+                errors.append("record %d: epoch %s" % (k, r["epoch"]))
+            keys = keys[:1] + keys[2:]
+        if keys[:4] != HEAD or keys[-2:] != ["msg", "v"]:
             errors.append("record %d: keys %s" % (k, keys))
             continue
         if r["level"] not in LEVELS:
             errors.append("record %d: level %s" % (k, r["level"]))
-        utc = datetime.datetime.strptime(r["time"], "%Y-%m-%dT%H:%M:%S.%fZ")
-        gps = datetime.datetime.strptime(r["gpst"], "%Y-%m-%dT%H:%M:%S.%f")
-        if (gps - utc).total_seconds() != LEAP_GPS_UTC:
-            errors.append("record %d: time %s gpst %s" % (k, r["time"], r["gpst"]))
         count[(r["level"], r["component"], r["event"])] += 1
 
-    msgs = [r.get("msg") for r in recs if "========== Start BNC" not in r.get("msg", "")]
+    body = [r for r in recs if "========== Start BNC" not in r.get("msg", "")]
+    msgs = [classic_text(r) for r in body]
+    for k, (r, st) in enumerate(zip(body, stamps), 1):
+        utc = datetime.datetime.strptime(r["time"], "%Y-%m-%dT%H:%M:%S.%fZ")
+        if st is not None and (st - utc.replace(microsecond=0)).total_seconds() != LEAP_GPS_UTC:
+            errors.append("record %d: time %s, classic %s" % (k, r["time"], st))
     if msgs != classic:
         for k, (a, b) in enumerate(zip(msgs, classic), 1):