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

Fix `amari.Conn._send_msg` to include the arguments in the message sent.
Without it, logspec options such as `stats[samples,rf]/60s` are ignored.

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

Add JupyterLab notebook that shows how to build KPI-computing pipeline
and to compute the KPIs. The notebook comes with extensive comments
describing every step. Please see those comments for details.

Add demo program that shows how to build KPI-computing pipeline and to
compute the KPIs. It can be used e.g. as follows:

    $ ./demo/kpidemo.py 60 https://lab.nexedi.com/kirr/misc/raw/162307b9/lte/20221211-overload.xlog

The program comes with extensive comments describing every step.
Please see those comments for details.

The next patch will also add analogous JupyterLab notebook.

kpi.Calc is calculator to compute KPIs. It can be instantiated on
MeasurementLog and time interval over which to perform computations.
It currently implements calculations for only one "E-RAB Accessibility KPI".

Please see added docstrings and tests for details.

The next patch will also add demo program that uses all kpi.Calc and
other parts of KPI-computation pipeline to build and visualize E-RAB
Accessibility from real data.

amari.kpi: New package with driver for Amarisoft LTE stack to retrieve KPI-related measurements from logs

amari.kpi provides LogMeasure that takes enb.xlog (TODO and enb.log) as
input, and produces kpi.Measurements on output.

    enb.xlog     ─────────
    ─────────>  │   Log   │
                │         │ ────> []kpi.Measurement
    ─────────>  │ Measure │
    enb.log      ─────────

We read log data organizing periods around stats queries, and for now we
build Measurement from stats' counters. To do so we take δ(stats_prev, stat)
and process it mapping Amarisoft counters to 3GPP ones specified by
kpi.Measurement.

We emit measurement X after reading stats X+2 - i.e. we emit measurement
for a period after reading data covering _next_ period. It is organized
this way to account for init/fini correction:

             fini adjust
            -------------
           '             '
     Sx    v     Sx+1    '   Sx+2
  ────|───────────|───────────|────
       Measurement Measurement
            X          X+1

This approach has following limitations:

- for most of the counters there is no direct mapping in between
  Amarisoft and 3GPP. For example we currently use s1_erab_setup_request for
  ERAB.EstabAddAtt.sum, but this mapping is not strictly correct and will
  break if corresponding S1 E-RAB SETUP REQUEST message contains multiple
  ERABs. The code has corresponding FIXME marks where such approximations
  are used.

- it is not possible to implement init/fini correction precisely. From
  aggregated statistics we only get total amount for a fini value for a
  period - without knowing which part of it corresponds to init events
  from previous period, and which part to init events from current one.
  With that it is only possible to make a reasonable guess and try to
  preserve statistical properties, but not more. See m_initfini in the
  code for details.

- it is possible to handle eNB with single cell only. This limitation
  comes from the fact that in Amarisoft LTE stack S1-related counters
  come as "globals" ones, while e.g. RRC-related counters are "per-cell".
  It is thus not possible to see how much S1 connection establishments
  are associated with one particular cell if there are several of them.

TODO also parse enb.log to fix those issues.

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.

Start the package to process measurements and compute KPIs from them.

In this patch we add kpi.Measurement - a central part to represent
measurement results in intermediate generic form. kpi.Measurement will
be used by both KPI calculator, and by drivers for particular LTE stacks
to provide their KPI-related data in this uniform common format.

kpi.Measurement also establishes semantic for such measurement results
to be followed by drivers. The semantic is stated in kpi.Measurement
docstring and in comment for every field. Also in particular, according
to TS 32.401 and common sense, measurement data are required to be
correctly accounted for initiation/termination events to avoid
discrepancies. Quoting kpi.Measurement documentation:

    Important note (init/fini correction):

      Termination events should be counted in the same granularity period, where
      corresponding initiation event occurred, even if termination event happens
      _after_ granularity period covering the initiation event. For example in the
      following illustration "ConnEstab Success" event should be counted in the
      same granularity period 1 as "ConnEstab Initiate" event:

                     -----------------------
                    '                       '
            | p e r ' i o d 1       | p e r ' i o d 2    |
            |       '               |       v            |
        ────'───────x───────────────'───────x────────────'────────────>
                ConnEstab               ConnEstab                time
                Initiate                 Success

      This preserves invariant that N(initiations) is always ≥ N(results) and
      goes in line with what TS 32.401 4.3.2 "Perceived accuracy -> Same period
      for the same two events" requires.

kpi.Measurement comes accompanied by kpi.MeasurementLog which in essence
is array of kpi.Measurements.

We will use kpi.Measurement and kpi.MeasurementLog in later patches to
both provide Amarisoft-specific data in this common format, and to
compute KPIs from it.

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.

Conn multiplexes many requests/responses over single WebSocket
connection. To do so it organizes dedicated receive thread that
continuously receives messages from underlying websocket connection and
dispatches received replies back to threads that issued corresponding requests.

An rx timeout in that receive thread is thus not something unexpected -
it can happen e.g. if there is simply no requests sent. But I missed
that in 61ad9032 (amari: Add functionality to interoperate with an
Amarisoft LTE service via WebSocket) and implicitly did not ignored such
global rx timeout. As the result `amari xlog` does not work properly if
period of requests is greater than timeout value, for example:

        $ xamari xlog ws://localhost:9001 ue_get/30s
        {"meta": {"event": "start", "time": 1670588996.0623107, "generator": "xlog ws://localhost:9001 ue_get[]/30.0s"}}
        {"meta": {"event": "service attach", "time": 1670588996.1852894, "srv_name": "ENB", "srv_type": "ENB", "srv_version": "2022-12-01"}}
        {"message":"config_get", ...}
  note  {"message":"ue_get","ue_list":[],"message_id":2,"time":3045.323,"utc":1670588996.423}
  ----> {"meta": {"event": "service detach", "time": 1670589026.3569217, "srv_name": "ENB", "srv_type": "ENB", "srv_version": "2022-12-01", "reason": "timed out"}}
        {"meta": {"event": "service attach", "time": 1670589029.485363, "srv_name": "ENB", "srv_type": "ENB", "srv_version": "2022-12-01"}}
        {"message":"config_get", ...}
        {"message":"ue_get","ue_list":[],"message_id":2,"time":3078.606,"utc":1670589029.706}
        ...

-> Fix it by ignoring global rx timeout.

NOTE: we must also add manual handling of per-request timeout when
waiting for corresponding reply. If we don't do that a situation where
particular reply does not come back, but replies for other requests are
coming back ok, will never be detected.

Here is how fixed version works now:

        $ xamari xlog ws://localhost:9001 ue_get/30s
        {"meta": {"event": "start", "time": 1670589223.0339117, "generator": "xlog ws://localhost:9001 ue_get[]/30.0s"}}
        {"meta": {"event": "service attach", "time": 1670589223.1970558, "srv_name": "ENB", "srv_type": "ENB", "srv_version": "2022-12-01"}}
        {"message":"config_get", ...}
        {"message":"ue_get","ue_list":[],"message_id":2,"time":3272.292,"utc":1670589223.391}
        {"message":"ue_get","ue_list":[],"message_id":3,"time":3302.274,"utc":1670589253.373}
        {"message":"ue_get","ue_list":[],"message_id":4,"time":3332.266,"utc":1670589283.365}
        ...

Note that ue_get messages are coming sequentially and there is no
"service detach" event, that was artificially popping up due to wrong
timeout handling.

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

- amari.connect() connects to a service and returns Conn.
- Conn can be used to issue requests, receive replies and (TODO) event
  notifications. Several requests could be issued simultaneously and
  handled in parallel.

Only main driver framework here without actual subcommands.

Based on similar main driver from Zodbtools:

https://lab.nexedi.com/nexedi/zodbtools/blob/master/zodbtools/zodb.py

So that import xlte.abc resolves to xlte/abc.py

Based on similar top-level import redirector from wendelin.core
See nexedi/wendelin.core@e870781d for
context and links in added code for further details.

Stub setup.py, README/CHANGELOG, .gitignore.

Follow standard GPL3 + wide exception for Free and Open-source software.
See https://www.nexedi.com/licensing for details.

The project to implement assorted functionality related to LTE.

In particular I intend for it to be the place where KPI-related
functionality will live.