Changeset 11189 in ntrip for trunk/BNC


Ignore:
Timestamp:
Nov 10, 2026, 8:45:57 AM (8 hours ago)
Author:
stuerze
Message:

Structured logging improved

Location:
trunk/BNC
Files:
9 edited

Legend:

Unmodified
Added
Removed

  • trunk/BNC/CHANGELOG.md

    r11187 r11189  
    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'), 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
     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', without the leading mountpoint and shortened where the fields carry the details, e.g. 'PPP position') 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
    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/bnchelp.html

    r11187 r11189  
    27622762  </p>
    27632763  <pre><p style="font-family:Monospace">
    2764 22-10-04 19:53:57 ========== Start BNC v2.13 (LINUX) ==========
    2765 22-10-04 19:53:57 Panel 'PPP' active
    2766 22-10-04 19:53:57 WTZR00DEU0: Get data in RTCM 3.x format
    2767 22-10-04 19:53:57 BCEP00BKG0: Get data in RTCM 3.x format
    2768 22-10-04 19:53:58 SSRA00BKG1: Get data in RTCM 3.x format
    2769 22-10-04 19:53:58 Configuration read: 08_PPP.bnc, 3 stream(s)
    2770 22-10-04 19:53:58 BCEP00BKG0: UNHEALTHY EPH G28 LNAV: 2022 10 04 20 00 00
    2771 22-10-04 19:54:13 2022-10-04_19:53:59.000 WTZR00DEU0 X = 4075580.5340 Y = 931854.3984 Z = 4801568.4250 NEU:  -0.1623  +0.2450  +0.2991 TRP:  +2.1833  +0.0002
    2772 22-10-04 19:54:13 2022-10-04_19:54:00.000 WTZR00DEU0 X = 4075580.5393 Y = 931854.4017 Z = 4801568.4126 NEU:  -0.1748  +0.2471  +0.2936 TRP:  +2.1833  +0.0002
    2773 22-10-04 19:54:14 2022-10-04_19:54:01.000 WTZR00DEU0 X = 4075580.4979 Y = 931854.4015 Z = 4801568.3441 NEU:  -0.1891  +0.2560  +0.2153 TRP:  +2.1833  +0.0004
    2774 22-10-04 19:54:14 2022-10-04_19:54:02.000 WTZR00DEU0 X = 4075580.4871 Y = 931854.4003 Z = 4801568.3157 NEU:  -0.1995  +0.2573  +0.1868 TRP:  +2.1833  +0.0007
    2775 22-10-04 19:54:14 2022-10-04_19:54:03.000 WTZR00DEU0 X = 4075580.4698 Y = 931854.3966 Z = 4801568.3005 NEU:  -0.1961  +0.2575  +0.1637 TRP:  +2.1833  +0.0009
    2776 22-10-04 19:54:14 2022-10-04_19:54:04.000 WTZR00DEU0 X = 4075580.4598 Y = 931854.3940 Z = 4801568.2881 NEU:  -0.1964  +0.2573  +0.1476 TRP:  +2.1833  +0.0010
    2777 22-10-04 19:54:18 2022-10-04_19:54:05.000 WTZR00DEU0 X = 4075580.4625 Y = 931854.3971 Z = 4801568.2917 NEU:  -0.1966  +0.2597  +0.1525 TRP:  +2.1833  +0.0012
    2778 22-10-04 19:54:18 2022-10-04_19:54:06.000 WTZR00DEU0 X = 4075580.4587 Y = 931854.3966 Z = 4801568.2912 NEU:  -0.1940  +0.2600  +0.1496 TRP:  +2.1833  +0.0014
    2779 22-10-04 19:54:18 2022-10-04_19:54:07.000 WTZR00DEU0 X = 4075580.4539 Y = 931854.3931 Z = 4801568.2818 NEU:  -0.1960  +0.2577  +0.1389 TRP:  +2.1833  +0.0018
    2780 22-10-04 19:54:18 2022-10-04_19:54:08.000 WTZR00DEU0 X = 4075580.4502 Y = 931854.3946 Z = 4801568.2757 NEU:  -0.1975  +0.2599  +0.1321 TRP:  +2.1833  +0.0021
    2781 22-10-04 19:54:18 2022-10-04_19:54:09.000 WTZR00DEU0 X = 4075580.4478 Y = 931854.3958 Z = 4801568.2737 NEU:  -0.1973  +0.2617  +0.1293 TRP:  +2.1833  +0.0023
     276426-11-09 16:42:47 ========== Start BNC v2.13.8 (LINUX) ==========
     276526-11-09 16:42:47 Panel 'PPP' active
     276626-11-09 16:42:47 WTZR00DEU0: Get data in RTCM 3.x format
     276726-11-09 16:42:47 BCEP00BKG0: Get data in RTCM 3.x format
     276826-11-09 16:42:47 SSRA00CNE1: Get data in RTCM 3.x format
     276926-11-09 16:42:47 Configuration read: 10_PPPQuickStart.bnc, 3 stream(s)
     277026-11-09 16:42:49 WTZR00DEU0: PPP uses the ephemerides of BCEP00BKG0 only
     277126-11-09 16:43:05 2026-11-09_16:42:50.000 WTZR00DEU0 X = 4075580.2017 Y = 931854.1723 Z = 4801568.3503 NEU:  -0.0000  -0.0000  +0.0001 TRP:  +2.1833  +0.0015 flt
     277226-11-09 16:43:05 2026-11-09_16:42:51.000 WTZR00DEU0 X = 4075580.2018 Y = 931854.1723 Z = 4801568.3504 NEU:  -0.0000  -0.0001  +0.0003 TRP:  +2.1833  +0.0030 flt
     277326-11-09 16:43:05 2026-11-09_16:42:52.000 WTZR00DEU0 X = 4075580.2019 Y = 931854.1723 Z = 4801568.3505 NEU:  -0.0000  -0.0001  +0.0004 TRP:  +2.1833  +0.0046 flt
     277426-11-09 16:43:05 2026-11-09_16:42:53.000 WTZR00DEU0 X = 4075580.2020 Y = 931854.1722 Z = 4801568.3506 NEU:  -0.0000  -0.0002  +0.0006 TRP:  +2.1833  +0.0059 flt
     277526-11-09 16:43:05 2026-11-09_16:42:54.000 WTZR00DEU0 X = 4075580.2021 Y = 931854.1722 Z = 4801568.3507 NEU:  -0.0000  -0.0002  +0.0007 TRP:  +2.1833  +0.0076 flt
     277626-11-09 16:43:09 2026-11-09_16:42:55.000 WTZR00DEU0 X = 4075580.2022 Y = 931854.1722 Z = 4801568.3508 NEU:  -0.0001  -0.0002  +0.0008 TRP:  +2.1833  +0.0086 flt
     277726-11-09 16:43:09 2026-11-09_16:42:56.000 WTZR00DEU0 X = 4075580.2023 Y = 931854.1722 Z = 4801568.3509 NEU:  -0.0001  -0.0003  +0.0010 TRP:  +2.1833  +0.0097 flt
     277826-11-09 16:43:09 2026-11-09_16:42:57.000 WTZR00DEU0 X = 4075580.2024 Y = 931854.1722 Z = 4801568.3510 NEU:  -0.0001  -0.0003  +0.0011 TRP:  +2.1833  +0.0098 flt
     277926-11-09 16:43:09 2026-11-09_16:42:58.000 WTZR00DEU0 X = 4075580.2025 Y = 931854.1721 Z = 4801568.3511 NEU:  -0.0001  -0.0004  +0.0012 TRP:  +2.1833  +0.0124 flt
     278026-11-09 16:43:09 2026-11-09_16:42:59.000 WTZR00DEU0 X = 4075580.2025 Y = 931854.1721 Z = 4801568.3512 NEU:  -0.0001  -0.0004  +0.0013 TRP:  +2.1833  +0.0138 flt
     278126-11-09 16:43:14 2026-11-09_16:43:00.000 WTZR00DEU0 X = 4075580.2014 Y = 931854.1735 Z = 4801568.3512 NEU:  +0.0005  +0.0012  +0.0008 TRP:  +2.1833  +0.0544 flt
     278226-11-09 16:43:14 2026-11-09_16:43:01.000 WTZR00DEU0 X = 4075580.2014 Y = 931854.1723 Z = 4801568.3527 NEU:  +0.0018  +0.0001  +0.0018 TRP:  +2.1833  +0.0927 flt
     278326-11-09 16:43:14 2026-11-09_16:43:02.000 WTZR00DEU0 X = 4075580.2014 Y = 931854.1740 Z = 4801568.3565 NEU:  +0.0039  +0.0017  +0.0049 TRP:  +2.1833  +0.1211 flt
     278426-11-09 16:43:14 2026-11-09_16:43:03.000 WTZR00DEU0 X = 4075580.2022 Y = 931854.1742 Z = 4801568.3554 NEU:  +0.0026  +0.0017  +0.0046 TRP:  +2.1833  +0.1440 flt
     278526-11-09 16:43:14 2026-11-09_16:43:04.000 WTZR00DEU0 X = 4075580.2043 Y = 931854.1761 Z = 4801568.3567 NEU:  +0.0016  +0.0031  +0.0071 TRP:  +2.1833  +0.1639 flt
     278626-11-09 16:43:18 2026-11-09_16:43:05.000 WTZR00DEU0 X = 4075580.2024 Y = 931854.1741 Z = 4801568.3547 NEU:  +0.0020  +0.0016  +0.0041 TRP:  +2.1833  +0.1855 flt
     278726-11-09 16:43:18 2026-11-09_16:43:06.000 WTZR00DEU0 X = 4075580.2044 Y = 931854.1755 Z = 4801568.3566 NEU:  +0.0015  +0.0024  +0.0071 TRP:  +2.1833  +0.2028 flt
     278826-11-09 16:43:18 2026-11-09_16:43:07.000 WTZR00DEU0 X = 4075580.2040 Y = 931854.1748 Z = 4801568.3541 NEU:  +0.0003  +0.0019  +0.0049 TRP:  +2.1833  +0.2195 flt
    27822789...
    27832790</pre>
    … …  
    28112818    <li>'mp': the mountpoint of the stream or the PPP station, if known,</li>
    28122819    <li>the fields of the event,</li>
    2813     <li>'msg': the text of the record in the logfile (shortened where the fields carry the details),</li>
     2820    <li>'msg': the text of the record in the logfile, without the leading mountpoint ('&lt;mp&gt;: ') and shortened
     2821        for events whose fields carry the details: 'PPP position' (ppp_position), 'Received message' (message types
     2822        of the RTCM scan), 'Mean latency' (stream_latency), 'Failure threshold exceeded, outage' / 'corrupted' and
     2823        'Recovery threshold exceeded, outage ended' / 'corruption ended' (stream_outage_*, stream_corrupted_*),</li>
    28142824    <li>'v': the version of the record layout, currently 1.</li>
    28152825  </ul>
    … …  
    28242834    <li>'stream_content': content of the stream found by the RTCM scan (see section <a href=#miscscan>2.12.3</a>), e.g. observation
    28252835        types, antenna and receiver descriptors, antenna coordinates, GLONASS slots, CRS and Helmert parameters; for the
    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>
     2836        received message types with the fields 'message_type' and, if known, 'size' (bytes),</li>
    28282837    <li>'stream_outage_begin' (warning), 'stream_corrupted_begin' (warning): 'since' (UTC);
    28292838        'stream_outage_end', 'stream_corrupted_end': 'ended' and 'since' (UTC),</li>
    … …  
    28432852  </p>
    28442853  <pre><p style="font-family:Monospace">
    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}
     2854{"time":"2025-11-17T13:48:51.000Z","level":"info","component":"stream","event":"stream_format","mp":"BCEP00BKG0","decoder":"RTCM3","format":"RTCM_3.3","msg":"Get data in RTCM 3.x format","v":1}
     2855{"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":"PPP position","v":1}
    28472856</pre>
    28482857  </p>
    … …  
    28512860  </p>
    28522861  <pre><p style="font-family:Monospace">
    2853 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
    2854 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
     2862time=2025-11-17T13:48:51.000Z level=info component=stream event=stream_format mp=BCEP00BKG0 decoder=RTCM3 format=RTCM_3.3 msg="Get data in RTCM 3.x format" v=1
     2863time=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="PPP position" v=1
    28552864</pre>
    28562865  </p>

  • trunk/BNC/src/bnclog.cpp

    r11187 r11189  
    271271    msg.remove(0, 1);
    272272  }
     273  // the mountpoint is a key of its own
     274  if (!_stream.isEmpty() && msg.startsWith(_stream + ": ")) {
     275    msg.remove(0, _stream.size() + 2);
     276  }
    273277
    274278  QVector<t_field> all;

  • trunk/BNC/src/bncwindow.cpp

    r11187 r11189  
    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'), 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>"));
     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', shortened where the fields carry the details) 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/latencychecker.cpp

    r11185 r11189  
    181181                      (_staID + ": Failure threshold exceeded, outage since "
    182182                       + _begDateOut + " " + _begTimeOut + " UTC").toLatin1());
     183      rec.setStructuredMsg("Failure threshold exceeded, outage");
    183184      rec.addTime("since", _outageSince);
    184185      emit newLogRecord(rec, true);
    … …  
    264265                          (_staID + ": Failure threshold exceeded, corrupted since "
    265266                           + _begDateCorr + " " + _begTimeCorr + " UTC").toLatin1());
     267          rec.setStructuredMsg("Failure threshold exceeded, corrupted");
    266268          rec.addTime("since", _corruptSince);
    267269          emit newLogRecord(rec, true);
    … …  
    287289                            (_staID + ": Recovery threshold exceeded, corruption ended "
    288290                             + _endDateCorr + " " + _endTimeCorr + " UTC").toLatin1());
     291            rec.setStructuredMsg("Recovery threshold exceeded, corruption ended");
    289292            rec.addTime("ended", _begDateTimeCorr);
    290293            if (_corruptSince.isValid()) {
    … …  
    321324                      (_staID + ": Recovery threshold exceeded, outage ended "
    322325                       + _endDateOut + " " + _endTimeOut + " UTC").toLatin1());
     326      rec.setStructuredMsg("Recovery threshold exceeded, outage ended");
    323327      rec.addTime("ended", _begDateTimeOut);
    324328      if (_outageSince.isValid()) {
    … …  
    563567  }
    564568  t_logRecord rec(t_logRecord::info, "stream", "stream_latency", _staID, text.toLatin1());
     569  rec.setStructuredMsg("Mean latency");
    565570  rec.add("type", l._type)
    566571     .add("mean", mean, 2)

  • trunk/BNC/src/pppRun.cpp

    r11187 r11189  
    473473        t_logRecord rec(t_logRecord::info, "ppp", "ppp_position", staID,
    474474                        QByteArray(log.str().c_str()));
     475        rec.setStructuredMsg("PPP position");
    475476        rec.setEpoch(output._epoTime)
    476477           .add("x", output._xyzRover[0], 4)

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

    r11187 r11189  
    77logfmt file a sequence of key=value pairs, that both carry the same records,
    88that 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
    11 the classic logfile line by line (classic lines without
    12 their "yy-mm-dd hh:mm:ss " prefix; the start line is skipped, it goes to the
    13 file of the current date) and that 'time' (UTC) is the GPS Time stamp of the
    14 classic line minus the GPS-UTC leap seconds. Prints a summary of the records per level,
    15 component and event; exit code 1 on any error.
     9'epoch' after 'time', GPS Time without 'Z'), that the records belong line by
     10line to the classic logfile ('msg' is the classic text without the "<mp>: "
     11prefix, shortened for events whose fields carry the details, see matches();
     12classic lines without their "yy-mm-dd hh:mm:ss " prefix; the start line is
     13skipped, it goes to the file of the current date) and that 'time' (UTC) is the
     14GPS Time stamp of the classic line minus the GPS-UTC leap seconds. Prints a
     15summary of the records per level, component and event; exit code 1 on any
     16error.
    1617"""
    1718
    … …  
    7071
    7172
    72 def 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"]
     73# events with a short structured 'msg': prefix the classic line must start with
     74SHORT = {
     75    "ppp_position": lambda r: "%s %s X = " % (r["epoch"].replace("T", "_"), r["mp"]),
     76    "stream_latency": lambda r: "%s %s: Mean latency " % (r["mp"], r["type"]),
     77}
     78
     79
     80def matches(r, line):
     81    """Does the record belong to the classic logfile line? The structured 'msg'
     82    is the classic text without the "<mp>: " prefix, shortened where the
     83    fields carry the details."""
     84    mp, msg, ev = r.get("mp"), r.get("msg"), r.get("event")
     85    if ev in SHORT:
     86        return line.startswith(SHORT[ev](r))
     87    if ev == "stream_content" and "message_type" in r:
    7988        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")
     89        return msg == "Received message" and \
     90            line == "%s: Received message type %d%s" % (mp, r["message_type"], size)
     91    if mp and line.startswith(mp + ": "):
     92        line = line[len(mp) + 2:]
     93    if ev.startswith("stream_outage_") or ev.startswith("stream_corrupted_"):
     94        return line.startswith(msg + " ")
     95    return msg == line
    8296
    8397
    … …  
    134148
    135149    body = [r for r in recs if "========== Start BNC" not in r.get("msg", "")]
    136     msgs = [classic_text(r) for r in body]
    137150    for k, (r, st) in enumerate(zip(body, stamps), 1):
    138151        utc = datetime.datetime.strptime(r["time"], "%Y-%m-%dT%H:%M:%S.%fZ")
    139152        if st is not None and (st - utc.replace(microsecond=0)).total_seconds() != LEAP_GPS_UTC:
    140153            errors.append("record %d: time %s, classic %s" % (k, r["time"], st))
    141     if msgs != classic:
    142         for k, (a, b) in enumerate(zip(msgs, classic), 1):
    143             if a != b:
    144                 errors.append("record %d: msg %r, classic %r" % (k, a, b))
    145                 break
    146         else:
    147             errors.append("%d records, %d classic lines" % (len(msgs), len(classic)))
     154    for k, (r, line) in enumerate(zip(body, classic), 1):
     155        if not matches(r, line):
     156            errors.append("record %d: msg %r, classic %r" % (k, r.get("msg"), line))
     157            break
     158    if len(body) != len(classic):
     159        errors.append("%d records, %d classic lines" % (len(body), len(classic)))
    148160
    149161    print("%d records" % len(recs))
Note: See TracChangeset for help on using the changeset viewer.