Changeset 11187 in ntrip


Ignore:
Timestamp:
Nov 9, 2026, 5:37:55 PM (less than one hour ago)
Author:
stuerze
Message:

Structured logging improved

Location:
trunk/BNC
Files:
15 edited

Legend:

Unmodified
Added
Removed

  • trunk/BNC/CHANGELOG.md

    r11185 r11187  
    11# Changelog
    22## 2.13.8 (2026-11-04)
    3 - ADDED: **Structured logfile** (General options 'Structured logfile', 'Format' and 'Min. level', keys logFileStructured, logFormatStructured and logLevelStructured): in addition to the unchanged logfile, the same records as JSON Lines ('json', default) or key=value pairs ('logfmt'), daily file '_YYMMDD' like the logfile; each record has time in UTC ('time') and GPS Time ('gpst'), level, component, event, stream, the event's fields, the logfile text ('msg') and a version ('v'). Events with fields: ppp_position, ppp_epoch_failed, stream_format, stream_content (RTCM scan, with message_type and size of the received message types), stream_timeout, stream_outage_begin/end, stream_corrupted_begin/end, stream_latency; all other messages as event 'message' with the component of their origin (stream, ntrip, bce, ssr, ppp, cmb, upload, ssrqc, bnc) and a level (error: a function does not work; warning: data or configuration problem, BNC continues; info: status); messages of the BNC_DEBUG_BCE/OBS/CMB defines with level 'debug' and component bce/obs/cmb. Test case log_structured and check tests/tools/logcheck.py
     3- ADDED: **Structured logfile** (General options 'Structured logfile', 'Format' and 'Min. level', keys logFileStructured, logFormatStructured and logLevelStructured): in addition to the unchanged logfile, the same records as JSON Lines ('json', default) or key=value pairs ('logfmt'), one appended file without date for rotation by logrotate & co (reopened if moved or removed); each record has the time in UTC ('time'), for records of a data epoch its GPS Time ('epoch'), level, component, event, mountpoint ('mp'), the event's fields, the logfile text ('msg') and a version ('v'). Events with fields: ppp_position, ppp_epoch_failed, stream_format, stream_content (RTCM scan, with message_type and size of the received message types and short msg 'Received message'), stream_timeout, stream_outage_begin/end, stream_corrupted_begin/end, stream_latency; all other messages as event 'message' with the component of their origin (stream, ntrip, bce, ssr, ppp, cmb, upload, ssrqc, bnc) and a level (error: a function does not work; warning: data or configuration problem, BNC continues; info: status); messages of the BNC_DEBUG_BCE/OBS/CMB defines with level 'debug' and component bce/obs/cmb. Test case log_structured and check tests/tools/logcheck.py
    44- FIXED: Build with BNC_DEBUG_BCE: undeclared message number in the debug messages of the Galileo ephemeris decoder
    55- ADDED: **epoch/velocity fields to PPP coordinates file to allow BNC to propagate the reference coordinates** related to a dedicated reference epoch to the current processing epoch internally; coordinates can also be given as latitude/longitude/height

  • trunk/BNC/src/bnccore.cpp

    r11185 r11187  
    4343#include <QMessageBox>
    4444#include <cmath>
     45#ifndef Q_OS_WIN
     46#include <sys/stat.h>
     47#endif
    4548
    4649#include "bnccore.h"
    … …  
    7275  _logStream   = 0;
    7376  _logFileStructured  = 0;
     77  _logStructuredInit  = false;
    7478  _logFormatStructured = t_logRecord::json;
    7579  _logLevelStructured  = t_logRecord::debug;
    … …  
    195199    delete _logStream; _logStream = 0;
    196200    delete _logFile;   _logFile   = 0;
    197     delete _logFileStructured; _logFileStructured = 0;
    198201    _logFileFlag = 1;
    199202    _fileDate = currDate;
    … …  
    214217      _logStream->setDevice(_logFile);
    215218    }
    216     QString structName = settings.value("logFileStructured").toString();
    217     if ( !structName.isEmpty() ) {
    218       expandEnvVar(structName);
     219  }
     220
     221  // Structured logfile: one endless file (rotation by external tools)
     222  // ---------------------------------------------------------------
     223  if (!_logStructuredInit) {
     224    _logStructuredInit = true;
     225    bncSettings settings;
     226    _logFileStructuredName = settings.value("logFileStructured").toString();
     227    if (!_logFileStructuredName.isEmpty()) {
     228      expandEnvVar(_logFileStructuredName);
    219229      _logFormatStructured = t_logRecord::formatFromString(
    220230                               settings.value("logFormatStructured").toString());
    221231      _logLevelStructured  = t_logRecord::levelFromString(
    222232                               settings.value("logLevelStructured").toString());
    223       _logFileStructured = new QFile(structName + "_" + currDate.toString("yyMMdd"));
    224       if (!_logFileStructured->open(append ? (QIODevice::WriteOnly | QIODevice::Append)
    225                                            : QIODevice::WriteOnly)) {
    226         delete _logFileStructured; _logFileStructured = 0;
    227       }
    228     }
     233      openLogFileStructured();
     234    }
     235  }
     236  else if (!_logFileStructuredName.isEmpty() && _logStructuredCheck.hasExpired(1000)) {
     237    openLogFileStructured();   // reopens only if the file was moved or removed
    229238  }
    230239
    … …  
    244253    _logFileStructured->write(rec.encode(_logFormatStructured, currDateTime) + "\n");
    245254    _logFileStructured->flush();
     255  }
     256}
     257
     258// Open the structured logfile, or reopen it after an external rotation
     259// (logrotate without copytruncate moves the file and the old one must be
     260// released); always appending, also after copytruncate
     261////////////////////////////////////////////////////////////////////////////
     262void t_bncCore::openLogFileStructured() {
     263  _logStructuredCheck.start();
     264  if (_logFileStructured) {
     265    bool same = _logFileStructured->exists();
     266#ifndef Q_OS_WIN
     267    if (same) {
     268      struct stat stPath, stOpen;
     269      same = (stat(QFile::encodeName(_logFileStructuredName).constData(), &stPath) == 0 &&
     270              fstat(_logFileStructured->handle(), &stOpen) == 0 &&
     271              stPath.st_dev == stOpen.st_dev && stPath.st_ino == stOpen.st_ino);
     272    }
     273#endif
     274    if (same) {
     275      return;
     276    }
     277    delete _logFileStructured; _logFileStructured = 0;
     278  }
     279  _logFileStructured = new QFile(_logFileStructuredName);
     280  if (!_logFileStructured->open(QIODevice::WriteOnly | QIODevice::Append)) {
     281    delete _logFileStructured; _logFileStructured = 0;
    246282  }
    247283}

  • trunk/BNC/src/bnccore.h

    r11185 r11187  
    2525#ifndef BNCAPP_H
    2626#define BNCAPP_H
     27
     28#include <QElapsedTimer>
    2729
    2830#include "bnctime.h"
    … …  
    183185                       const QString& strV4);
    184186  void  messagePrivate(const t_logRecord& rec);
     187  void  openLogFileStructured();
    185188
    186189  QSettings::SettingsMap _settings;
    … …  
    189192  int                    _logFileFlag;
    190193  QFile*                 _logFileStructured;
     194  QString                _logFileStructuredName;
     195  bool                   _logStructuredInit;
     196  QElapsedTimer          _logStructuredCheck;
    191197  t_logRecord::e_format  _logFormatStructured;
    192198  t_logRecord::e_level   _logLevelStructured;

  • trunk/BNC/src/bncgetthread.cpp

    r11185 r11187  
    840840        t_logRecord rec(t_logRecord::info, "stream", "stream_content", _staID,
    841841                        _staID + ": Received message type " + type.toLatin1() +  size.toLatin1());
     842        rec.setStructuredMsg("Received message");
    842843        rec.add("message_type", int(decoder()->_typeList[ii]._type));
    843844        if (decoder()->_typeList[ii]._size) {

  • trunk/BNC/src/bnchelp.html

    r11185 r11187  
    27872787    For log processing tools (e.g. Grafana Loki, Elasticsearch, Vector, jq), BNC can write the same records in
    27882788    addition into a structured logfile: specify its path in the 'Structured logfile' field and select the format,
    2789     'json' for one JSON object per line (JSON Lines) or 'logfmt' for key=value pairs separated by blanks. As for the
    2790     logfile, the name is extended by '_YYMMDD'. The logfile itself remains unchanged, so existing scripts reading it
    2791     keep working. Default is an empty option field, meaning that no structured logfile is written. 'Min. level'
     2789    'json' for one JSON object per line (JSON Lines) or 'logfmt' for key=value pairs separated by blanks. Unlike the
     2790    logfile, the structured logfile is one file without date in its name, always appended (also without 'Append
     2791    files'), meant to be rotated by an external tool such as logrotate: if the file is moved or removed, BNC
     2792    continues with a new file of the same name within one second; 'copytruncate' works as well. The logfile itself
     2793    remains unchanged, so existing scripts reading it keep working. Default is an empty option field, meaning that no structured logfile is written. 'Min. level'
    27922794    restricts the structured logfile to records of at least the selected level: 'debug' (default) writes all records,
    27932795    'info' leaves out the debug records, 'warning' writes warnings and errors, 'error' errors only.
    … …  
    27982800  <ul>
    27992801    <li>'time': time of the record in UTC, ISO 8601 with 'Z', e.g. '2025-11-17T13:49:40.000Z',</li>
    2800     <li>'gpst': the same time in GPS Time (as the time stamps of the logfile), e.g. '2025-11-17T13:49:58.000',</li>
     2802    <li>'epoch': GPS Time of the data epoch the record refers to, ISO 8601 without 'Z', e.g. '2025-11-17T13:49:10.000';
     2803        only in records of an epoch ('ppp_position', 'ppp_epoch_failed'),</li>
    28012804    <li>'level': 'debug', 'info', 'warning' or 'error'; debug records exist only in BNC versions built with the
    28022805        defines BNC_DEBUG_BCE, BNC_DEBUG_OBS or BNC_DEBUG_CMB (src/src.pri),</li>
    … …  
    28062809        (SSR QC), or 'bnc' for general messages,</li>
    28072810    <li>'event': the kind of record, see below, or 'message' for general messages,</li>
    2808     <li>'stream': the stream (mountpoint) or the PPP station, if known,</li>
     2811    <li>'mp': the mountpoint of the stream or the PPP station, if known,</li>
    28092812    <li>the fields of the event,</li>
    2810     <li>'msg': the text of the record in the logfile,</li>
     2813    <li>'msg': the text of the record in the logfile (shortened where the fields carry the details),</li>
    28112814    <li>'v': the version of the record layout, currently 1.</li>
    28122815  </ul>
    … …  
    28152818  </p>
    28162819  <ul>
    2817     <li>'ppp_position': 'epoch' (GPS Time), 'x', 'y', 'z', 'dn', 'de', 'du', 'trp0', 'trp', 'trp_stdev', 'num_sat',
     2820    <li>'ppp_position': 'x', 'y', 'z', 'dn', 'de', 'du', 'trp0', 'trp', 'trp_stdev', 'num_sat',
    28182821        'hdop', 'fixed' (true/false), 'fix_percent'; 'ppp_epoch_failed' (warning) if no solution was computed,</li>
    28192822    <li>'stream_format': 'decoder' (RTCM2, RTCM3, ZERO, ZERO2FILE, RTNET) and 'format' (format entry of the stream),</li>
    … …  
    28212824    <li>'stream_content': content of the stream found by the RTCM scan (see section <a href=#miscscan>2.12.3</a>), e.g. observation
    28222825        types, antenna and receiver descriptors, antenna coordinates, GLONASS slots, CRS and Helmert parameters; for the
    2823         received message types with the fields 'message_type' and, if known, 'size' (bytes),</li>
     2826        received message types with the fields 'message_type' and, if known, 'size' (bytes) and the short 'msg'
     2827        'Received message' (logfile: 'Received message type 1127 (size 618)'),</li>
    28242828    <li>'stream_outage_begin' (warning), 'stream_corrupted_begin' (warning): 'since' (UTC);
    28252829        'stream_outage_end', 'stream_corrupted_end': 'ended' and 'since' (UTC),</li>
    … …  
    28392843  </p>
    28402844  <pre><p style="font-family:Monospace">
    2841 {"time":"2025-11-17T13:48:51.000Z","gpst":"2025-11-17T13:49:09.000","level":"info","component":"stream","event":"stream_format","stream":"BCEP00BKG0","decoder":"RTCM3","format":"RTCM_3.3","msg":"BCEP00BKG0: Get data in RTCM 3.x format","v":1}
    2842 {"time":"2025-11-17T13:49:40.000Z","gpst":"2025-11-17T13:49:58.000","level":"info","component":"ppp","event":"ppp_position","stream":"WTZR00DEU0","epoch":"2025-11-17T13:49:10.000","x":4075580.2172,"y":931854.1555,"z":4801568.3403,"dn":0.0000,"de":0.0000,"du":0.0001,"trp0":2.1833,"trp":0.0019,"trp_stdev":0.0993,"num_sat":17,"hdop":0.59,"fixed":false,"fix_percent":0,"msg":"2025-11-17_13:49:10.000 WTZR00DEU0 X = 4075580.2172 ...","v":1}
     2845{"time":"2025-11-17T13:48:51.000Z","level":"info","component":"stream","event":"stream_format","mp":"BCEP00BKG0","decoder":"RTCM3","format":"RTCM_3.3","msg":"BCEP00BKG0: Get data in RTCM 3.x format","v":1}
     2846{"time":"2025-11-17T13:49:40.000Z","epoch":"2025-11-17T13:49:10.000","level":"info","component":"ppp","event":"ppp_position","mp":"WTZR00DEU0","x":4075580.2172,"y":931854.1555,"z":4801568.3403,"dn":0.0000,"de":0.0000,"du":0.0001,"trp0":2.1833,"trp":0.0019,"trp_stdev":0.0993,"num_sat":17,"hdop":0.59,"fixed":false,"fix_percent":0,"msg":"2025-11-17_13:49:10.000 WTZR00DEU0 X = 4075580.2172 ...","v":1}
    28432847</pre>
    28442848  </p>
    … …  
    28472851  </p>
    28482852  <pre><p style="font-family:Monospace">
    2849 time=2025-11-17T13:48:51.000Z gpst=2025-11-17T13:49:09.000 level=info component=stream event=stream_format stream=BCEP00BKG0 decoder=RTCM3 format=RTCM_3.3 msg="BCEP00BKG0: Get data in RTCM 3.x format" v=1
    2850 time=2025-11-17T13:49:40.000Z gpst=2025-11-17T13:49:58.000 level=info component=ppp event=ppp_position stream=WTZR00DEU0 epoch=2025-11-17T13:49:10.000 x=4075580.2172 y=931854.1555 z=4801568.3403 dn=0.0000 de=0.0000 du=0.0001 trp0=2.1833 trp=0.0019 trp_stdev=0.0993 num_sat=17 hdop=0.59 fixed=false fix_percent=0 msg="2025-11-17_13:49:10.000 WTZR00DEU0 X = 4075580.2172 ..." v=1
     2853time=2025-11-17T13:48:51.000Z level=info component=stream event=stream_format mp=BCEP00BKG0 decoder=RTCM3 format=RTCM_3.3 msg="BCEP00BKG0: Get data in RTCM 3.x format" v=1
     2854time=2025-11-17T13:49:40.000Z epoch=2025-11-17T13:49:10.000 level=info component=ppp event=ppp_position mp=WTZR00DEU0 x=4075580.2172 y=931854.1555 z=4801568.3403 dn=0.0000 de=0.0000 du=0.0001 trp0=2.1833 trp=0.0019 trp_stdev=0.0993 num_sat=17 hdop=0.59 fixed=false fix_percent=0 msg="2025-11-17_13:49:10.000 WTZR00DEU0 X = 4075580.2172 ..." v=1
    28512855</pre>
    28522856  </p>

  • trunk/BNC/src/bnclog.cpp

    r11185 r11187  
    2121#include "bnclog.h"
    2222#include "bncutils.h"
     23#include "bnctime.h"
    2324
    2425namespace {
    … …  
    211212//
    212213////////////////////////////////////////////////////////////////////////////
     214t_logRecord& t_logRecord::setEpoch(const bncTime& epoch) {
     215  if (epoch.valid()) {
     216    _epoch = QByteArray((epoch.datestr() + 'T' + epoch.timestr(3)).c_str());
     217  }
     218  else {
     219    _epoch.clear();
     220  }
     221  return *this;
     222}
     223
     224//
     225////////////////////////////////////////////////////////////////////////////
    213226const char* t_logRecord::levelString(e_level level) {
    214227  switch (level) {
    … …  
    254267  QDateTime utc = gpst.addSecs(-gnumleap(dd.year(), dd.month(), dd.day()));
    255268
    256   QByteArray msg = _msg;
     269  QByteArray msg = _msgStructured.isEmpty() ? _msg : _msgStructured;
    257270  while (msg.startsWith('\n')) {
    258271    msg.remove(0, 1);
    … …  
    266279  };
    267280  put("time",      utc.toString("yyyy-MM-ddThh:mm:ss.zzz").toLatin1() + "Z", true);
    268   put("gpst",      gpst.toString("yyyy-MM-ddThh:mm:ss.zzz").toLatin1(), true);
     281  if (!_epoch.isEmpty()) {
     282    put("epoch",   _epoch, true);
     283  }
    269284  put("level",     levelString(_level), true);
    270285  put("component", _component, true);
    271286  put("event",     _event, true);
    272287  if (!_stream.isEmpty()) {
    273     put("stream", _stream, true);
     288    put("mp", _stream, true);
    274289  }
    275290  all += _fields;

  • trunk/BNC/src/bnclog.h

    r11185 r11187  
    3131#include <QVector>
    3232
     33class bncTime;
     34
    3335// One record of the structured logfile (option logFileStructured).
    3436//
    … …  
    3638// logfile gets one line per record, JSON (JSON Lines) or logfmt:
    3739//
    38 //   time gpst level component event [stream] [fields ...] msg v
     40//   time [epoch] level component event [mp] [fields ...] msg v
     41//
     42// mp: mountpoint of the stream or PPP station (member _stream)
     43//
     44// time: time of the record in UTC; epoch: GPS Time of the data epoch the
     45// record refers to (e.g. PPP position), only if set (setEpoch())
    3946//
    4047// Messages that are still emitted as plain text (newMessage(QByteArray,bool))
    … …  
    7582  t_logRecord& addTime(const char* key, const QDateTime& utc);   // ISO 8601, "Z"
    7683
    77   // one line without line end; gpst: time of the record in GPS time
     84  // shorter text for the structured logfile only, e.g. if the fields carry
     85  // the details; the classic logfile keeps _msg
     86  t_logRecord& setStructuredMsg(const QByteArray& msg) { _msgStructured = msg; return *this; }
     87
     88  // data epoch of the record (GPS Time, ISO 8601 without "Z"), key "epoch"
     89  t_logRecord& setEpoch(const bncTime& epoch);
     90
     91  // one line without line end; gpst: time of the record in GPS Time,
     92  // written as UTC (key "time")
    7893  QByteArray encode(e_format format, const QDateTime& gpst) const;
    7994
    … …  
    89104  QByteArray _component;
    90105  QByteArray _event;
     106  QByteArray _epoch;
    91107  QByteArray _stream;
    92108  QByteArray _msg;
     109  QByteArray _msgStructured;
    93110
    94111 private:

  • trunk/BNC/src/bncwindow.cpp

    r11185 r11187  
    15891589  // ------------------
    15901590  _logFileLineEdit->setWhatsThis(tr("<p>Records of BNC's activities are shown in the 'Log' tab on the bottom of this window. They can be saved into a file when a valid path for that is specified in the 'Logfile (full path)' field.</p><p>The logfile name will automatically be extended by a string '_YYMMDD' carrying the current date. <i>[key: logFile]</i></p>"));
    1591   _logFileStructuredLineEdit->setWhatsThis(tr("<p>In addition to the logfile, BNC can write the same records as a structured logfile for log processing tools: one record per line, either JSON (JSON Lines) or logfmt (key=value pairs separated by blanks). Each record carries the time in UTC ('time', ISO 8601 with 'Z') and in GPS time ('gpst'), a level (debug, info, warning, error), the component (e.g. stream, ppp, cmb), the event (e.g. ppp_position, stream_outage_begin), the stream (mountpoint) or PPP station if known, the event's fields, the text of the classic logfile ('msg') and the record version ('v').</p><p>Messages without own event are written with event 'message' and the component of their origin; their level is error (a function does not work), warning (data or configuration problem, BNC continues) or info (status). The logfile itself remains unchanged.</p><p>The file name will automatically be extended by a string '_YYMMDD' carrying the current date. Default is an empty option field, meaning that no structured logfile is written. <i>[key: logFileStructured]</i></p>"));
     1591  _logFileStructuredLineEdit->setWhatsThis(tr("<p>In addition to the logfile, BNC can write the same records as a structured logfile for log processing tools: one record per line, either JSON (JSON Lines) or logfmt (key=value pairs separated by blanks). Each record carries the time in UTC ('time', ISO 8601 with 'Z'), for records of a data epoch its GPS Time ('epoch'), a level (debug, info, warning, error), the component (e.g. stream, ppp, cmb), the event (e.g. ppp_position, stream_outage_begin), the mountpoint ('mp') of the stream or the PPP station if known, the event's fields, the text of the classic logfile ('msg') and the record version ('v').</p><p>Messages without own event are written with event 'message' and the component of their origin; their level is error (a function does not work), warning (data or configuration problem, BNC continues) or info (status). The logfile itself remains unchanged.</p><p>The structured logfile is one file without date in its name, always appended, to be rotated by an external tool like logrotate (BNC continues with a new file if it is moved or removed). Default is an empty option field, meaning that no structured logfile is written. <i>[key: logFileStructured]</i></p>"));
    15921592  _logFormatStructuredComboBox->setWhatsThis(tr("<p>Select the format of the structured logfile: 'json' for one JSON object per line (JSON Lines), 'logfmt' for key=value pairs. Default is 'json'. <i>[key: logFormatStructured]</i></p>"));
    15931593  _logLevelStructuredComboBox->setWhatsThis(tr("<p>Select the minimum level of the records written into the structured logfile: 'debug' writes all records (debug records exist only in BNC versions built with the BNC_DEBUG_* defines), 'info' leaves out the debug records, 'warning' writes warnings and errors only, 'error' errors only. The logfile is not affected. Default is 'debug'. <i>[key: logLevelStructured]</i></p>"));

  • trunk/BNC/src/pppRun.cpp

    r11185 r11187  
    465465      }
    466466      if (output._error) {
    467         emit newLogRecord(t_logRecord(t_logRecord::warning, "ppp", "ppp_epoch_failed",
    468                                       staID, QByteArray(log.str().c_str())), true);
     467        t_logRecord rec(t_logRecord::warning, "ppp", "ppp_epoch_failed", staID,
     468                        QByteArray(log.str().c_str()));
     469        rec.setEpoch(output._epoTime);
     470        emit newLogRecord(rec, true);
    469471      }
    470472      else {
    471473        t_logRecord rec(t_logRecord::info, "ppp", "ppp_position", staID,
    472474                        QByteArray(log.str().c_str()));
    473         rec.add("epoch", QByteArray((output._epoTime.datestr() + 'T' +
    474                                      output._epoTime.timestr(3)).c_str()))
     475        rec.setEpoch(output._epoTime)
    475476           .add("x", output._xyzRover[0], 4)
    476477           .add("y", output._xyzRover[1], 4)

  • trunk/BNC/tests/README.md

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

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

    r11185 r11187  
    2424                     "-key", "logFormatStructured", "logfmt"]},
    2525           {"dir": "chk", "tool": ["logcheck.py", "Output/PPPQuickStart.log_251117",
    26                                    "Output/PPPQuickStart.jsonl_251117",
    27                                    "lf/Output/PPPQuickStart.logfmt_251117"]}],
     26                                   "Output/PPPQuickStart.jsonl",
     27                                   "lf/Output/PPPQuickStart.logfmt"]}],
    2828  "outputs": [
    29     {"glob": "Output/PPPQuickStart.jsonl_251117", "name": "PPPQuickStart.jsonl"},
    30     {"glob": "lf/Output/PPPQuickStart.logfmt_251117", "name": "PPPQuickStart.logfmt"},
     29    {"glob": "Output/PPPQuickStart.jsonl", "name": "PPPQuickStart.jsonl"},
     30    {"glob": "lf/Output/PPPQuickStart.logfmt", "name": "PPPQuickStart.logfmt"},
    3131    {"glob": "chk/stdout.txt", "name": "logcheck.txt"}
    3232  ]

  • trunk/BNC/tests/tools/logcheck.py

    r11179 r11187  
    66Checks that every line of the JSON file is a JSON object and every line of the
    77logfmt file a sequence of key=value pairs, that both carry the same records,
    8 that the records have the mandatory keys in the documented order, that 'time'
    9 (UTC) is 'gpst' minus the GPS-UTC leap seconds and that the 'msg' of the
    10 records equals the text of the classic logfile line by line (classic lines
    11 without their "yy-mm-dd hh:mm:ss " prefix; the start line is skipped, it goes
    12 to the file of the current date). Prints a summary of the records per level,
     8that the records have the mandatory keys in the documented order (optional
     9'epoch' after 'time', GPS Time without 'Z'), that the 'msg' of the records
     10(for RTCM scan message types: 'mp', 'message_type', 'size') equals the text of
     11the classic logfile line by line (classic lines without
     12their "yy-mm-dd hh:mm:ss " prefix; the start line is skipped, it goes to the
     13file of the current date) and that 'time' (UTC) is the GPS Time stamp of the
     14classic line minus the GPS-UTC leap seconds. Prints a summary of the records per level,
    1315component and event; exit code 1 on any error.
    1416"""
    … …  
    2022import sys
    2123
    22 HEAD = ["time", "gpst", "level", "component", "event"]
     24HEAD = ["time", "level", "component", "event"]
    2325LEVELS = {"info", "warning", "error"}
    2426LEAP_GPS_UTC = 18          # valid since 2017-01-01
    … …  
    6870
    6971
     72def classic_text(r):
     73    """Text of the classic logfile line of a record: 'msg', except for the
     74    message types of the RTCM scan, which carry the short text 'Received message'
     75    and the details in their fields."""
     76    if r.get("event") == "stream_content" and "message_type" in r:
     77        if r["msg"] != "Received message":
     78            return "unexpected msg %r" % r["msg"]
     79        size = " (size %d)" % r["size"] if "size" in r else " "
     80        return "%s: Received message type %d%s" % (r["mp"], r["message_type"], size)
     81    return r.get("msg")
     82
     83
    7084def main():
    7185    errors = []
    72     classic = []
     86    classic, stamps = [], []
    7387    for line in open(sys.argv[1], encoding="latin-1", newline="").read().split("\r\n"):
    7488        if not line or "========== Start BNC" in line:
    7589            continue
    76         classic.append(line[18:] if re.match(r"\d\d-\d\d-\d\d \d\d:\d\d:\d\d ", line) else line)
     90        if re.match(r"\d\d-\d\d-\d\d \d\d:\d\d:\d\d ", line):
     91            classic.append(line[18:])
     92            stamps.append(datetime.datetime.strptime(line[:17], "%y-%m-%d %H:%M:%S"))
     93        else:
     94            classic.append(line)
     95            stamps.append(None)
    7796
    7897    recs = []
    … …  
    92111            errors.append("json %d records, logfmt %d" % (len(recs), len(lf)))
    93112        for k, (a, b) in enumerate(zip(recs, lf), 1):
    94             if list(a.keys()) != list(b.keys()) or any(a[x] != b[x] for x in a):
     113            # the start line carries the wall clock time of each run
     114            start = "========== Start BNC" in a.get("msg", "")
     115            if list(a.keys()) != list(b.keys()) or any(a[x] != b[x] for x in a
     116                                                        if not (start and x == "time")):
    95117                errors.append("record %d differs between json and logfmt" % k)
    96118
    … …  
    98120    for k, r in enumerate(recs, 1):
    99121        keys = list(r.keys())
    100         if keys[:5] != HEAD or keys[-2:] != ["msg", "v"]:
     122        if keys[1:2] == ["epoch"]:
     123            try:
     124                datetime.datetime.strptime(r["epoch"], "%Y-%m-%dT%H:%M:%S.%f")
     125            except ValueError:
     126                errors.append("record %d: epoch %s" % (k, r["epoch"]))
     127            keys = keys[:1] + keys[2:]
     128        if keys[:4] != HEAD or keys[-2:] != ["msg", "v"]:
    101129            errors.append("record %d: keys %s" % (k, keys))
    102130            continue
    103131        if r["level"] not in LEVELS:
    104132            errors.append("record %d: level %s" % (k, r["level"]))
    105         utc = datetime.datetime.strptime(r["time"], "%Y-%m-%dT%H:%M:%S.%fZ")
    106         gps = datetime.datetime.strptime(r["gpst"], "%Y-%m-%dT%H:%M:%S.%f")
    107         if (gps - utc).total_seconds() != LEAP_GPS_UTC:
    108             errors.append("record %d: time %s gpst %s" % (k, r["time"], r["gpst"]))
    109133        count[(r["level"], r["component"], r["event"])] += 1
    110134
    111     msgs = [r.get("msg") for r in recs if "========== Start BNC" not in r.get("msg", "")]
     135    body = [r for r in recs if "========== Start BNC" not in r.get("msg", "")]
     136    msgs = [classic_text(r) for r in body]
     137    for k, (r, st) in enumerate(zip(body, stamps), 1):
     138        utc = datetime.datetime.strptime(r["time"], "%Y-%m-%dT%H:%M:%S.%fZ")
     139        if st is not None and (st - utc.replace(microsecond=0)).total_seconds() != LEAP_GPS_UTC:
     140            errors.append("record %d: time %s, classic %s" % (k, r["time"], st))
    112141    if msgs != classic:
    113142        for k, (a, b) in enumerate(zip(msgs, classic), 1):
Note: See TracChangeset for help on using the changeset viewer.