1. 12 Dec, 2022 8 commits
    • Kirill Smelkov's avatar
      amari.xlog += Reader · 0633d26f
      Kirill Smelkov authored
      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.
      0633d26f
    • Kirill Smelkov's avatar
      kpi: Start of the package · dc1d5481
      Kirill Smelkov authored
      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.
      dc1d5481
    • Kirill Smelkov's avatar
      amari.xlog: Mention it in readme · 949cc753
      Kirill Smelkov authored
      949cc753
    • Kirill Smelkov's avatar
      amari.xlog: Clarify why we will need to implement log rotation ourselves · d20f64be
      Kirill Smelkov authored
      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.
      d20f64be
    • Kirill Smelkov's avatar
      amari.xlog: Document xlog protocol · 22292b62
      Kirill Smelkov authored
      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.
      22292b62
    • Kirill Smelkov's avatar
      amari.xlog: Switch time emitted in events to be seconds/epoch instead of RFC822 · 3175e9c6
      Kirill Smelkov authored
      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.
      3175e9c6
    • Kirill Smelkov's avatar
      amari.xlog: Flush each emitted line · 9c8da27f
      Kirill Smelkov authored
      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.
      9c8da27f
    • Kirill Smelkov's avatar
      amari: Fix Conn rx timeout handling · 8f94b47d
      Kirill Smelkov authored
      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.
      8f94b47d
  2. 02 Nov, 2022 1 commit
    • Kirill Smelkov's avatar
      amari.xlog: Begin emitting queries right after startup · 134f3a1e
      Kirill Smelkov authored
      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.
      134f3a1e
  3. 19 Oct, 2022 7 commits
    • Kirill Smelkov's avatar
      amari.xlog: Initial draft · e0cc8a38
      Kirill Smelkov authored
      `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
      e0cc8a38
    • Kirill Smelkov's avatar
      amari: Add functionality to interoperate with an Amarisoft LTE service via WebSocket. · 61ad9032
      Kirill Smelkov authored
      - 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.
      61ad9032
    • Kirill Smelkov's avatar
      xamari: New supplementary tool for managing Amarisoft LTE services. · 95cd8912
      Kirill Smelkov authored
      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
      95cd8912
    • Kirill Smelkov's avatar
      Top-level in-tree import redirector · 3c971d64
      Kirill Smelkov authored
      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.
      3c971d64
    • Kirill Smelkov's avatar
      Initial Administrivia · 3de908b0
      Kirill Smelkov authored
      Stub setup.py, README/CHANGELOG, .gitignore.
      3de908b0
    • Kirill Smelkov's avatar
      Licensing · ede5d48e
      Kirill Smelkov authored
      Follow standard GPL3 + wide exception for Free and Open-source software.
      See https://www.nexedi.com/licensing for details.
      ede5d48e
    • Kirill Smelkov's avatar
      Start of xlte.git · 12c09480
      Kirill Smelkov authored
      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.
      12c09480