- 12 Dec, 2022 4 commits
-
-
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.
-
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.
-
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.
-
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.
-
- 02 Nov, 2022 1 commit
-
-
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.
-
- 19 Oct, 2022 7 commits
-
-
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
-
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.
-
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
-
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.
-
Kirill Smelkov authored
Stub setup.py, README/CHANGELOG, .gitignore.
-
Kirill Smelkov authored
Follow standard GPL3 + wide exception for Free and Open-source software. See https://www.nexedi.com/licensing for details.
-
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.
-