GitLab

Python2 does not support type annotations.

Python2 does not support unicode characters in identifiers.

This will make diff in between master and py2 backport a bit smaller.

We currently emit information about local time in events, and
information about on-service time in messages. Events don't have
information about on-service time and messages don't carry information
about local time. That is mostly ok, since primary xlog setup is to run
on the same machine, where eNB runs because on-service .utc correlates
with .time in events.

However for eNB < 2022-12-01 on-service time includes only .time field
without .utc field with .time representing "time passed since when eNB
was started". This way for enb.xlog streams generated on older systems
it is not possible for xlog.Reader to know the absolute timestamps of
read messages.

To fix this we amend "attach" and "sync" events to carry both local and
on-service times. This way xlog.Reader, after seeing e.g. "sync" with
.time and only .srv_time without .srv_utc, should be able to
correlate local and on-service clocks and to approximate srv_utc as

	srv_utc' = srv_time' + (time - srv_time)

where time and srv_time correspond to last synchronization, and
srv_time' is what xlog.Reader retrieves for a further-read message in
question.

See kirr/xlte!3 for related discussion.

This functionality is useful to look at tail of a log without reading it
in full from the start.

This way xlog.Reader can be sure that if it looked around in such a
window and did not find a sync, then something is not good with the
stream and it does not need to go beyond that limit looking around.

This is a change of the protocol. But it is early days and existing logs
- that we use in the demo, are all below 1000 lines limit, so they will
continue to be loaded ok.

No direct test for actual Loss Of Sync detection - this functionality is
draft for now and should be improved later. However for no-LOS cases
xlog.Reader is already covered with tests.

Let's use "sync(reason=start)" instead of dedicated "start" event for
uniformity. Periodic syncs are now "sync(reason=periodic)" and after
logrotation support there will be also "pre-logrotate" and
"post-logrotate" reasons. Emit "sync(reason=stop)" at xlog shutdown for
uniformity and to make it more clear from looking at just enb.xlog about
what is xlog state at the end.

Stop requiring "start" to be present in the header - we will soon rework
xlog reader to look around for nearby sync automatically so that reading
could be started from any position in the stream.

We emit config_get after every attach from the beginning of xlog in
e0cc8a38 (amari.xlog: Initial draft). The reasoning here is that it is
useful by default to know configuration of a service.

In the previous patch we added sync events so that xlog stream becomes
self-synchronizing. To continue that line it is now useful to have that
config_get emitted after every such synchronization point instead of
only after attaching to the service. That's what hereby patch does.

As a bonus the code is reworked in a way that config_get setup is not
hardcoded anymore and config_get periodicity now can be controlled by
users via explicitly specifying config_get in the logspec.

So that xlog stream becomes self-synchronized and could be used even if
we start reading it from some intermediate point instead of only from
the beginning.

We will need this in general - to be able to start reading long log not
only from its beginning, and also in particular for Wendelin systems
where logs are uploaded by Fluentd in chunks and some chunks could be
potentially lost.

Sync events are emitted always unconditionally with default sync
interval being 10x the longest specified period. We also provide users a
way to control sync periodicity via explicitly specifying
"meta.sync/period" query in the logspec.

See kirr/xlte!3 (comment 175796) and
further for related discussion.

This is change of xlog protocol. But it is early days and the only
direct consumer of xlog is amari.kpi which we adjust accordingly. So it
should be ok.

We will soon need to construct logspecs not only by way of parsing.

In 79d10eb9 that patch wired ctx through xlog callchains and added
corresponding handling of cancellation. But I overlooked one place where
plain sleep was used.

-> Fix it.

Noticed while developing support for E-UTRAN IP Throughtput.

This patch provides next building block for E-UTRAN IP Throughput KPI
and continues d102ffaa (drb: Start of the package). Quoting that patch

    The scheme to compute E-UTRAN IP Throughput is thus as follows: poll eNB at
    100Hz frequency for `ue_get[stats]` and retrieve information about per-UE/QCI
    streams and the number of transport blocks dl/ul-ed to the UE in question
    during that 10ms frame. Estimate `tx_time` taking into account
    the number of transmitted transport blocks. And estimate whether eNB is congested or
    not based on `dl_use_avg`/`ul_use_avg` taken from `stats`. For the latter we
    also need to poll for `stats` at 100Hz frequency and synchronize
    `ue_get[stats]` and `stats` requests in time so that they both cover the same
    time interval of particular frame.

    Then organize the polling process to provide aggregated statistics in the form of	<-- NOTE
    new `x.drb_stats` message, and teach `xamari xlog` to save that messages to		<-- NOTE
    `enb.xlog` together with `stats`.							<-- NOTE

    Then further adjust `amari.kpi.LogMeasure` and generic
    `kpi.Measurement` and `kpi.Calc` to handle DRB-related data.

So here we implement the noted step:

- add drv._x_stats_srv server that polls eNB at 100Hz rate, uses Sampler
  to extract bursts and aggregates information about those bursts.

- teach xlog to organize servers for synthetic messages and communicate
  with them, and register drv._x_stats_srv as such server to handle
  generation of x.drb_stats message.

We will soon need to run 2 threads:

- one with the main logger, and
- another one to serve requests for synthetic x.drb_stats queries

Both main and the second thread will be run via sync.WorkGroup to cancel
each other in case of failure somewhere. So since WorkGroup.wait(),
similarly to all pygolang operations, is not interrupted by signals(*),
we need to wire ctx to be passed through all operations and manage to
cancel that context on SIGINT/SIGTERM.

This patch:

1. adjusts xlog to wire ctx through all call chains and moves ._xlog1()
   to be run in the thread.
2. adjusts amari.Conn to take ctx as argument on all operations and
   react reasonably on that ctx cancel. We need to do it here because
   xlog uses Conn internally.
3. adjusts xamari main driver to setup root context that is canceled on
   SIGINT/SIGTERM similarly e.g. to how nxdtest does it in
   nexedi/nxdtest@b0cf277d .

(*) see nexedi/pygolang@e18adbab for details.

We will soon add more levels of trying to this part of the code and
linear defers are easier to follow compared to many levels of try/except
nesting.

Fix off-by-one error in `amari.xlog.LogSpec.parse` which truncated the last
character of options, e.g. `stats[rf]/60s` would parse option `r` instead of `rf`.

/reviewed-by @kirr
/reviewed-on kirr/xlte!1

xlog.Reader could be used to parse and read back data previously saved
by xlog. In the next patch we will use it in Amarisoft driver for KPI
measurements.

Upon rotation we want to emit trailing part to the old file, and emit
new header into new log file. All this is custom and cannot be handled
reliably when rotation is done by external tool.

Document kind of messages and events that could be emitted by xlog.

The messages come from Amarisoft software directly, but events are
xlog-specific and without proper documentation it is easy to miss what
they are and which information and semantic they carry.

The time emitted in messages by Amarisoft is in seconds. It also makes
sense to emit meta/event times in seconds as well for uniformity.

This is backward-incompatible change, but it should be ok at this early time.

xlog logging is kind of slow - usually it comes once per several seconds
or once per minute. And without flushing many entries can remain sitting
up in the file buffer in userspace without being conveyed to OS kernel.
Which is not very convenient because in such situation we cannot make good
use of tools like `tail -f`.

Since flushing is relatively cheap operation - it is just one write
syscall - let's do it after every emitted line. The write syscall does
not force data to be synced to disk, so it should not slow things down,
but make it convenient to have latest logs right away in the filesystem
view.

For example with `stats/100s` stats query is emitted every 100 seconds,
but currently it will be first emitted only after waiting for 100
seconds after `xamari xlog` startup, or after reconnection to eNB if eNB
itself was restarted. And this way it will be hard to interpret obtained
numbers in relation to last 100s time interval.

-> Start emitting queries right after reconnection / xlog start, so that
we see the values as observed at the beginning, and can compare result
of further queries to them.

`xamari xlog` can be used to maintin extra log for an Amarisoft LTE
service: in addition to native logs, xlog contains results of periodic
queries done via WebSocket. For example with the following aguments

	xamari xlog <wsuri>  stats/10s ue_get/3s erab_get/3s

xlog will emit results of stats query - every 10 seconds, results from
ue_get query - every 3 seconds, and similarly for erab_get query.

The results are saved into xlog in JSON Lines format for easy future
processing. For the reference below is a copy of corresponding help
entries:

    xlte$ xamari help xlog
    Usage: xamari xlog [OPTIONS] <wsuri> <logspec>+
    Maintain extra log for a service.

    The service is queried periodically according to logspec and results are saved
    in JSON format to a file (see 'xamari help jsonlog').

    <wsuri> is URI (see 'xamari help websock') of an Amarisoft-service.
    <logspec> is specification of what to log. It has the following parts:

        <query>[<options>]/<period>

    The query specifies a message, that should be used to query service. For
    example "stats", "ue_get", "erab_get", ... Query part is mandatory.

    Options specifies additional flags for the query. Options part can be omitted.

    Period specifies periodicity of how often the service should be queried.
    Period is optional and defaults to 60 seconds.

    Example for <logspec>+:

        stats[samples,rf]/30s  ue_get[stats]  erab_get/10s  qos_flow_get

    Options:

        -h  --help            show this help

    xlte$ xamari help jsonlog
    Some commands produce logs with JSON entries. Such logs are organized with JSON
    Lines format(*) with each entry occupying one line.

    Logs in JSON Lines format are handy to exchange in between programs, and with
    corresponding tools, e.g. jq(+), they can be also displayed in human-readable
    form and inspected quickly.

    (*) https://jsonlines.org/
    (+) https://stedolan.github.io/jq/

Example output:

(xlte3.venv) kirr@deca:~/src/wendelin/xlte$ xamari xlog ws://localhost:9001 ue_get/3s erab_get/3s
{"meta": {"event": "start", "time": "Wed, 19 Oct 2022 15:05:50 -0000", "generator": "xlog ws://localhost:9001 ue_get[]/3.0s erab_get[]/3.0s"}}
{"meta": {"event": "service attach", "time": "Wed, 19 Oct 2022 15:05:51 -0000", "srv_name": "ENB", "srv_type": "ENB", "srv_version": "2022-09-16"}}
{"message":"config_get","version":"2022-09-16","type":"ENB","name":"ENB","license_id":"d9a961c166d2d4b15249fc559cdec925efbbe942d73b143aff","license_user":"rapid.space","logs":{"layers":{"PHY":{"level":"error","max_size":0,"key":false,"crypto":false,"payload":false},"MAC":{"level":"error","max_size":0,"key":false,"crypto":false,"payload":false},"RLC":{"level":"error","max_size":0,"key":false,"crypto":false,"payload":false},"PDCP":{"level":"error","max_size":0,"key":false,"crypto":false,"payload":false},"RRC":{"level":"debug","max_size":1,"key":false,"crypto":false,"payload":false},"NAS":{"level":"debug","max_size":1,"key":false,"crypto":false,"payload":false},"S1AP":{"level":"debug","max_size":1,"key":false,"crypto":false,"payload":false},"NGAP":{"level":"error","max_size":0,"key":false,"crypto":false,"payload":false},"GTPU":{"level":"error","max_size":0,"key":false,"crypto":false,"payload":false},"X2AP":{"level":"debug","max_size":1,"key":false,"crypto":false,"payload":false},"XnAP":{"level":"error","max_size":0,"key":false,"crypto":false,"payload":false},"M2AP":{"level":"error","max_size":0,"key":false,"crypto":false,"payload":false},"LPPa":{"level":"error","max_size":0,"key":false,"crypto":false,"payload":false},"NRPPa":{"level":"error","max_size":0,"key":false,"crypto":false,"payload":false},"TRX":{"level":"error","max_size":0,"key":false,"crypto":false,"payload":false}},"bcch":false,"mib":false,"signal":false,"cch":false,"rep":false,"dci_size":false,"csi":false,"cell_meas":false,"count":8192,"rotate":250000000,"path":"/var/log/lte"},"tai":9610.092,"global_enb_id":{"plmn":"00101","enb_id_type":"macro","enb_id":107216,"enb_name":"enb1a2d0"},"cells":{"1":{"n_antenna_dl":2,"n_antenna_ul":2,"n_layer_dl":2,"n_layer_ul":1,"gain":0,"ul_disabled":false,"rf_port":0,"dl_qam":256,"ul_qam":64,"ecgi":{"plmn":"00101","eci":27447297},"n_id_cell":1,"n_rb_dl":100,"n_rb_ul":100,"dl_earfcn":38350,"ul_earfcn":38350,"band":39,"dl_freq":1890000000,"ul_freq":1890000000,"mode":"TDD","uldl_config":2,"sp_config":7,"prach_sequence_index":204,"dl_cyclic_prefix":"normal","ul_cyclic_prefix":"normal","prach_config_index":4,"prach_freq_offset":11,"delta_pucch_shift":2,"n_rb_cqi":1,"n_cs_an":0,"pucch_allocation":[{"type":"2/2a/2b","rbs":1,"n":6}],"pucch_ack_nack_start":11,"pucch_reserved_rbs":[0,0,22,0,0,0,0,22,0,0],"sr_resource_count":44,"cqi_resource_count":48,"srs_resources":{"offsets":16,"freqs":20,"total":640},"gbr":{"dl_limit":7123840,"ul_limit":1797120},"tac":1,"plmn_list":[{"plmn":"00101","reserved":false}]}},"rx_channels":[{"gain":9,"freq":1890,"port":0},{"gain":9,"freq":1890,"port":0}],"tx_channels":[{"gain":60,"freq":1890,"port":0},{"gain":60,"freq":1890,"port":0}],"rf_ports":[{"sample_rate":30720000}],"message_id":1,"time":9610.087}
{"message":"ue_get","ue_list":[],"message_id":2,"time":9613.347}
{"message":"erab_get","erab_list":[],"timestamp":9613704,"message_id":3,"time":9613.704}
{"message":"ue_get","ue_list":[],"message_id":4,"time":9616.355}
{"message":"erab_get","erab_list":[],"timestamp":9616618,"message_id":5,"time":9616.618}
{"message":"ue_get","ue_list":[],"message_id":6,"time":9619.272}
{"message":"erab_get","erab_list":[],"timestamp":9619547,"message_id":7,"time":9619.547}
{"message":"ue_get","ue_list":[],"message_id":8,"time":9622.319}
{"message":"erab_get","erab_list":[],"timestamp":9622588,"message_id":9,"time":9622.588}
{"message":"ue_get","ue_list":[],"message_id":10,"time":9625.263}
{"message":"erab_get","erab_list":[],"timestamp":9625663,"message_id":11,"time":9625.663}
{"message":"ue_get","ue_list":[],"message_id":12,"time":9628.403}
{"message":"erab_get","erab_list":[],"timestamp":9628725,"message_id":13,"time":9628.725}
{"message":"ue_get","ue_list":[],"message_id":14,"time":9631.381}
{"message":"erab_get","erab_list":[],"timestamp":9631798,"message_id":15,"time":9631.798}
{"message":"ue_get","ue_list":[],"message_id":16,"time":9634.303}
{"message":"erab_get","erab_list":[],"timestamp":9634596,"message_id":17,"time":9634.596}
{"message":"ue_get","ue_list":[],"message_id":18,"time":9637.268}
{"message":"erab_get","erab_list":[],"timestamp":9637568,"message_id":19,"time":9637.568}

    (below an UE registers with eNB)

{"message":"ue_get","ue_list":[{"enb_ue_id":8,"mme_ue_id":107,"rnti":68,"cells":[{"cell_id":1}]}],"message_id":20,"time":9640.296}
{"message":"erab_get","erab_list":[{"erab_id":5,"qci":9,"dl_total_bytes":0,"ul_total_bytes":0,"enb_ue_id":8}],"timestamp":9640831,"message_id":21,"time":9640.831}
{"message":"ue_get","ue_list":[{"enb_ue_id":8,"mme_ue_id":107,"rnti":68,"cells":[{"cell_id":1}]}],"message_id":22,"time":9643.268}
{"message":"erab_get","erab_list":[{"erab_id":5,"qci":9,"dl_total_bytes":0,"ul_total_bytes":0,"enb_ue_id":8}],"timestamp":9643555,"message_id":23,"time":9643.555}
{"message":"ue_get","ue_list":[{"enb_ue_id":8,"mme_ue_id":107,"rnti":68,"cells":[{"cell_id":1}]}],"message_id":24,"time":9646.326}
{"message":"erab_get","erab_list":[{"erab_id":5,"qci":9,"dl_total_bytes":0,"ul_total_bytes":0,"enb_ue_id":8}],"timestamp":9646850,"message_id":25,"time":9646.85}
{"message":"ue_get","ue_list":[],"message_id":26,"time":9649.287}
{"message":"erab_get","erab_list":[],"timestamp":9649646,"message_id":27,"time":9649.646}
^CTraceback (most recent call last):
  File "/home/kirr/src/wendelin/venv/xlte3.venv/bin/xamari", line 33, in <module>
    sys.exit(load_entry_point('xlte', 'console_scripts', 'xamari')())
  File "/home/kirr/src/wendelin/xlte/amari/xamari.py", line 130, in main
    return command_module.main(argv)
  File "/home/kirr/src/wendelin/xlte/amari/xlog.py", line 275, in main
    xlog(wsuri, logspecv)
  File "/home/kirr/src/wendelin/xlte/amari/xlog.py", line 108, in xlog
    xl.xlog1()
  File "/home/kirr/src/wendelin/venv/xlte3.venv/lib/python3.9/site-packages/decorator.py", line 232, in fun
    return caller(func, *(extras + args), **kw)
  File "/home/kirr/src/wendelin/venv/xlte3.venv/lib/python3.9/site-packages/golang/__init__.py", line 103, in _
    return f(*argv, **kw)
  File "/home/kirr/src/wendelin/xlte/amari/xlog.py", line 157, in xlog1
    xl._xlog1(conn)
  File "/home/kirr/src/wendelin/xlte/amari/xlog.py", line 208, in _xlog1
    time.sleep(δtsleep)
KeyboardInterrupt