amari.kpi: Teach LogMeasure to handle stats messages with multiple cells

Starting from 71087f67 (amari.kpi: New package with driver for Amarisoft
LTE stack to retrieve KPI-related measurements from logs) a limitation
was hardcoded that only 1-cell configurations are supported. However we
do use multicell eNB configurations and computing E-RAB Accessibility
KPI was failing on them as e.g.:

    xlte.amari.kpi.LogError: t1731059787.321: stats describes 2 cells;  but only single-cell configurations are supported

-> Remove that limitation and handle stats covering multiple cells.

amari/kpi.py

 # -*- coding: utf-8 -*-
-# Copyright (C) 2022-2023  Nexedi SA and Contributors.
+# Copyright (C) 2022-2024  Nexedi SA and Contributors.
 #                          Kirill Smelkov <kirr@nexedi.com>
 #
 # This program is free software: you can Use, Study, Modify and Redistribute
@@ -225,11 +225,12 @@ def _handle_stats(logm, stats: xlog.Message, m_prev: kpi.Measurement):
     #   preserve statistical properties, but not more. See m_initfini below for
     #   details.
     #
-    # - it is possible to handle eNB with single cell only. This limitation
+    # - it is not easy to produce per-cell measurements. 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.
+    #   It is thus hard to see how much S1 connection establishments are associated
+    #   with one particular cell if there are several of them. One S1 connection could
+    #   be even related to multiple cells simultaneously when carriers are aggregated.
     #
     # TODO also parse enb.log to fix those issues.
 
@@ -259,7 +260,7 @@ def _handle_stats(logm, stats: xlog.Message, m_prev: kpi.Measurement):
     # do init/fini correction if there was also third preceding stats message.
     m = logm._m.copy() # [stats_prev, stats)
 
-    # δcc(counter) tells how specified cumulative counter changed since last stats result.
+    # δcc(counter) tells how specified global cumulative counter changed since last stats result.
     def δcc(counter):
         old = _stats_cc(stats_prev, counter)
         new = _stats_cc(stats,      counter)
@@ -267,6 +268,14 @@ def _handle_stats(logm, stats: xlog.Message, m_prev: kpi.Measurement):
             raise LogError(stats.timestamp, "cc %s↓  (%s → %s)" % (counter, old, new))
         return new - old
 
+    # δcell_cc(counter) tells how specified per-cell cumulative counter changed since last stats result.
+    def δcell_cc(cell, counter):
+        old = _stats_cell_cc(stats_prev, cell, counter)
+        new = _stats_cell_cc(stats,      cell, counter)
+        if new < old:
+            raise LogError(stats.timestamp, "cc C%s.%s↓  (%s → %s)" % (cell, counter, old, new))
+        return new - old
+
     # m_initfini populates m[init] and m[fini] from vinit and vfini values.
     # copy of previous ._m[fini] is correspondingly adjusted for init/fini correction.
     p = None
@@ -297,9 +306,24 @@ def _handle_stats(logm, stats: xlog.Message, m_prev: kpi.Measurement):
     # any logic error in data will be reported via LogError.
     try:
         # RRC: connection establishment
+        #
+        # Aggregate statistics for all cells because in E-RAB Accessibility we need
+        # aggregated RRC.ConnEstab* for whole eNB. It would be more logical to emit
+        # per-cell RRC statistics here and aggregate the result in KPI computation
+        # routine, but for now we are not delving to rework kpi.Measurement to
+        # contain per-cell values. For E-RAB Accessibility the end result is the
+        # same whether we do aggregation here or in kpi.Calc.erab_accessibility().
+        #
+        # TODO rework to emit per-cell measurements when/if we need per-cell KPIs
+        cells = set(stats['cells'].keys())  # NOTE cells are taken only from stats, not from stat_prev
+        δΣcell_rrc_connection_request = 0   # (if a cell disappears its counters stop to be accounted)
+        δΣcell_rrc_connection_setup_complete = 0
+        for cell in cells:
+            δΣcell_rrc_connection_request         += δcell_cc(cell, 'rrc_connection_request')
+            δΣcell_rrc_connection_setup_complete  += δcell_cc(cell, 'rrc_connection_setup_complete')
         m_initfini(
-            'RRC.ConnEstabAtt.sum',         δcc('rrc_connection_request'),
-            'RRC.ConnEstabSucc.sum',        δcc('rrc_connection_setup_complete'))
+            'RRC.ConnEstabAtt.sum',         δΣcell_rrc_connection_request,
+            'RRC.ConnEstabSucc.sum',        δΣcell_rrc_connection_setup_complete)
 
         # S1: connection establishment
         m_initfini(
@@ -334,37 +358,28 @@ def _handle_stats(logm, stats: xlog.Message, m_prev: kpi.Measurement):
 
 
 # _stats_check verifies stats message to have required structure.
-#
-# only configurations with one single cell are supported.
-# ( because else it would not be clear to which cell to associate e.g. global
-#   counters for S1 messages )
 def _stats_check(stats: xlog.Message):
-    cells = stats['cells']
-    if len(cells) != 1:
-        raise LogError(stats.timestamp, "stats describes %d cells;  but only single-cell configurations are supported" % len(cells))
-    cellname = list(cells.keys())[0]
-
     try:
         stats.get1("counters", dict).get1("messages", dict)
-        stats.get1("cells", dict).get1(cellname, dict).get1("counters", dict).get1("messages", dict)
+        cells = stats.get1("cells", dict)
+        for cell in cells:
+            cells.get1(cell, dict).get1("counters", dict).get1("messages", dict)
     except Exception as e:
         raise LogError(stats.timestamp, "stats: %s" % e)  from None
     return
 
-# _stats_cc returns specified cumulative counter from stats result.
+# _stats_cc returns specified global cumulative counter from stats result.
 #
-# counter may be both "global" or "per-cell".
 # stats is assumed to be already verified by _stats_check.
 def _stats_cc(stats: xlog.Message, counter: str):
-    cells = stats['cells']
-    cell = list(cells.values())[0]
-
-    if counter.startswith("rrc_"):
-        cc_dict = cell ['counters']
-    else:
-        cc_dict = stats['counters']
-
-    return cc_dict['messages'].get(counter, 0)
+    return stats['counters']['messages'].get(counter, 0)
+
+# _stats_cell_cc is like _stats_cc but returns specified per-cell cumulative counter from stats result.
+def _stats_cell_cc(stats: xlog.Message, cell: str, counter: str):
+    _ = stats['cells'].get(cell)
+    if _ is None:
+        return 0    # cell is absent in this stats
+    return _['counters']['messages'].get(counter, 0)
 
 
 # _handle_drb_stats handles next x.drb_stats xlog entry upon _read request.

amari/kpi_test.py

 # -*- coding: utf-8 -*-
-# Copyright (C) 2022-2023  Nexedi SA and Contributors.
+# Copyright (C) 2022-2024  Nexedi SA and Contributors.
 #                          Kirill Smelkov <kirr@nexedi.com>
 #
 # This program is free software: you can Use, Study, Modify and Redistribute
@@ -244,28 +244,28 @@ def test_LogMeasure():
     # init           0     3     2     5     0
     # fini    ø ←─── 2     1←─── 2←─── 4←─── 1
     # fini'          0     3 ²   2 ²   3 ¹   0
-    tstats({'rrc_connection_request':           0,
-            'rrc_connection_setup_complete':    2}) # completions for previous uncovered period
+    tstats({'C1.rrc_connection_request':        0,
+            'C1.rrc_connection_setup_complete': 2}) # completions for previous uncovered period
     _('RRC.ConnEstabAtt.sum',       0)
     _('RRC.ConnEstabSucc.sum',      0)  # not 2
     # p2
-    tstats({'rrc_connection_request':           0 +3,  # 3 new initiations
-            'rrc_connection_setup_complete':    2 +1}) # 1 new completion
+    tstats({'C1.rrc_connection_request':        0 +3,  # 3 new initiations
+            'C1.rrc_connection_setup_complete': 2 +1}) # 1 new completion
     _('RRC.ConnEstabAtt.sum',       3)
     _('RRC.ConnEstabSucc.sum',      3)  # not 1
     # p3
-    tstats({'rrc_connection_request':           0+3 +2,  # 2 new initiations
-            'rrc_connection_setup_complete':    2+1 +2}) # 2 completions for p2
+    tstats({'C1.rrc_connection_request':        0+3 +2,  # 2 new initiations
+            'C1.rrc_connection_setup_complete': 2+1 +2}) # 2 completions for p2
     _('RRC.ConnEstabAtt.sum',       2)
     _('RRC.ConnEstabSucc.sum',      2)  # 2, but it is 2 - 2(for_p2) + 2(from_p4)
     # p4
-    tstats({'rrc_connection_request':           0+3+2 +5,  # 5 new initiations
-            'rrc_connection_setup_complete':    2+1+2 +4}) # 2 completions for p3 + 2 new
+    tstats({'C1.rrc_connection_request':        0+3+2 +5,  # 5 new initiations
+            'C1.rrc_connection_setup_complete': 2+1+2 +4}) # 2 completions for p3 + 2 new
     _('RRC.ConnEstabAtt.sum',       5)
     _('RRC.ConnEstabSucc.sum',      3)
     # p5
-    tstats({'rrc_connection_request':           0+3+2+5 +0,  # no new initiations
-            'rrc_connection_setup_complete':    2+1+2+4 +1}) # 1 completion for p4
+    tstats({'C1.rrc_connection_request':        0+3+2+5 +0,  # no new initiations
+            'C1.rrc_connection_setup_complete': 2+1+2+4 +1}) # 1 completion for p4
     _('RRC.ConnEstabAtt.sum',       0)
     _('RRC.ConnEstabSucc.sum',      0)
 
@@ -364,8 +364,8 @@ def test_LogMeasure():
 
     # service detach/attach, connect failure, xlog failure
     tδstats({}) # untie from previous history
-    i, f = 'rrc_connection_request', 'rrc_connection_setup_complete'
-    I, F = 'RRC.ConnEstabAtt.sum',   'RRC.ConnEstabSucc.sum'
+    i, f = 'C1.rrc_connection_request', 'C1.rrc_connection_setup_complete'
+    I, F = 'RRC.ConnEstabAtt.sum',      'RRC.ConnEstabSucc.sum'
 
     tδstats({i:2, f:1})
     _(I, 2)
@@ -412,25 +412,54 @@ def test_LogMeasure():
     t.expect_nodata()
 
 
-# verify that only stats with single cell and expected structure are accepted.
+    # multiple cells
+    # TODO emit per-cell measurements instead of accumulating all cells
+    tstats({})
+    t.expect_nodata()
+    tstats({})
+    _('RRC.ConnEstabAtt.sum',       0)
+    _('RRC.ConnEstabSucc.sum',      0)
+    #  C1 appears
+    tstats({'C1.rrc_connection_request':    12,     'C1.rrc_connection_setup_complete': 11})
+    _('RRC.ConnEstabAtt.sum',       12)
+    _('RRC.ConnEstabSucc.sum',      11+1)
+    #  C2 appears
+    tstats({'C1.rrc_connection_request':    12+3,   'C1.rrc_connection_setup_complete': 11+3,
+            'C2.rrc_connection_request':    22,     'C2.rrc_connection_setup_complete': 21})
+    _('RRC.ConnEstabAtt.sum',       3+22)
+    _('RRC.ConnEstabSucc.sum',      -1+3+21+2)
+    #  C1 and C2 stays
+    tstats({'C1.rrc_connection_request':    12+3+3, 'C1.rrc_connection_setup_complete': 11+3+3,
+            'C2.rrc_connection_request':    22+4,   'C2.rrc_connection_setup_complete': 21+4})
+    _('RRC.ConnEstabAtt.sum',       3+4)
+    _('RRC.ConnEstabSucc.sum',      -2+3+4+2)
+    #  C1 disappears
+    tstats({'C2.rrc_connection_request':    22+4+4, 'C2.rrc_connection_setup_complete': 21+4+4})
+    _('RRC.ConnEstabAtt.sum',       4)
+    _('RRC.ConnEstabSucc.sum',      4-2)
+    #  C2 disappears
+    tstats({})
+    _('RRC.ConnEstabAtt.sum',       0)
+    _('RRC.ConnEstabSucc.sum',      0)
+
+    tevent("service detach")
+    t.expect_nodata()
+
+
+# verify that only stats with expected structure are accepted.
 @func
 def test_LogMeasure_badinput():
     t = tLogMeasure()
     defer(t.close)
     _ = t.expect1
 
-    cc = 'rrc_connection_request'
+    cc = 'C1.rrc_connection_request'
     CC = 'RRC.ConnEstabAtt.sum'
 
     # initial ok entries
     t.xlog( jstats(1, {}) )
     t.xlog( jstats(2, {cc: 2}) )
     t.xlog( jstats(3, {cc: 2+3}) )
-    # bad: not single cell
-    t.xlog('{"message":"stats", "utc":11, "cells": {}}')
-    t.xlog('{"message":"stats", "utc":12, "cells": {}}')
-    t.xlog('{"message":"stats", "utc":13, "cells": {"a": {}, "b": {}}}')
-    t.xlog('{"message":"stats", "utc":14, "cells": {"a": {}, "b": {}, "c": {}}}')
     # bad: no counters
     t.xlog('{"message":"stats", "utc":21, "counters": {"messages": {}}, "cells": {"1": {}}}')
     t.xlog('{"message":"stats", "utc":22, "counters": {"messages": {}}, "cells": {"1": {"counters": {}}}}')
@@ -466,31 +495,18 @@ def test_LogMeasure_badinput():
     read_nodata(0.02, 0.98) # attach-1
     readok(1, 2)            # 1-2
     readok(2, 3)            # 2-3
-    read_nodata(3, 8)       # 3-11
-
-    def tbadcell(τ, ncell):
-        with raises(LogError, match="t%s: stats describes %d cells;" % (τ, ncell) +
-                    "  but only single-cell configurations are supported"):
-            t.read()
-    tbadcell(11, 0)
-    read_nodata(11, 1)
-    tbadcell(12, 0)
-    read_nodata(12, 1)
-    tbadcell(13, 2)
-    read_nodata(13, 1)
-    tbadcell(14, 3)
+    read_nodata(3, 18)      # 3-21
 
     def tbadstats(τ, error):
         with raises(LogError, match="t%s: stats: %s" % (τ, error)):
             t.read()
-    read_nodata(14, 7)
-    tbadstats(21, ":10/cells/1 no `counters`")
+    tbadstats(21, ":6/cells/1 no `counters`")
     read_nodata(21, 1)
-    tbadstats(22, ":11/cells/1/counters no `messages`")
+    tbadstats(22, ":7/cells/1/counters no `messages`")
     read_nodata(22, 1)
-    tbadstats(23, ":12/ no `counters`")
+    tbadstats(23, ":8/ no `counters`")
     read_nodata(23, 1)
-    tbadstats(24, ":13/counters no `messages`")
+    tbadstats(24, ":9/counters no `messages`")
     read_nodata(24, 7)
 
     readok(31, 5)           # 31-32
@@ -511,7 +527,7 @@ def test_LogMeasure_cc_wraparound():
     defer(t.close)
     _ = t.expect1
 
-    cc = 'rrc_connection_request'
+    cc = 'C1.rrc_connection_request'
     CC = 'RRC.ConnEstabAtt.sum'
 
     t.xlog( jstats(1, {}) )
@@ -545,7 +561,7 @@ def test_LogMeasure_sync():
     defer(t.close)
     _ = t.expect1
 
-    cc = 'rrc_connection_request'
+    cc = 'C1.rrc_connection_request'
     CC = 'RRC.ConnEstabAtt.sum'
 
     t.xlog( jstats(1, {}) )
@@ -568,31 +584,47 @@ def test_LogMeasure_sync():
 
 
 # jstats returns json-encoded stats message corresponding to counters dict.
+#
+# if a counter goes as "Cxxx.yyy" it is emitted as counter yyy of cell xxx in the output.
 # τ goes directly to stats['utc'] as is.
 def jstats(τ, counters):  # -> str
-    g_cc    = {}  # global
-    cell_cc = {}  # per-cell
+    g_cc    = {}  # global cumulative counters
+    cells   = {}  # .cells
 
     for cc, value in counters.items():
-        if cc.startswith("rrc_"):
-            cell_cc[cc] = value
+        _ = re.match(r"^C([^.]+)\.(.+)$", cc)
+        if _ is not None:
+            cell = _.group(1)
+            cc   = _.group(2)
+            cells.setdefault(cell, {})          \
+                 .setdefault("counters", {})    \
+                 .setdefault("messages", {})    \
+                 [cc] = value
         else:
             g_cc[cc] = value
 
     s = {
         "message":  "stats",
         "utc":      τ,
-        "cells":    {"1": {"counters": {"messages": cell_cc}}},
+        "cells":    cells,
         "counters": {"messages": g_cc},
     }
 
     return json.dumps(s)
 
 def test_jstats():
-    assert jstats(0, {}) == '{"message": "stats", "utc": 0, "cells": {"1": {"counters": {"messages": {}}}}, "counters": {"messages": {}}}'
-    assert jstats(123.4, {"rrc_x": 1, "s1_y": 2, "rrc_z": 3, "x2_zz": 4}) == \
+    assert jstats(0, {}) == '{"message": "stats", "utc": 0, "cells": {}, "counters": {"messages": {}}}'
+    assert jstats(123.4, {"C1.rrc_x": 1, "s1_y": 2, "C1.rrc_z": 3, "x2_zz": 4}) == \
             '{"message": "stats", "utc": 123.4, "cells": {"1": {"counters": {"messages": {"rrc_x": 1, "rrc_z": 3}}}}, "counters": {"messages": {"s1_y": 2, "x2_zz": 4}}}'
 
+    # multiple cells
+    assert jstats(432.1, {"C1.rrc_x": 11, "C2.rrc_y": 22, "C3.xyz": 33, "C1.abc": 111, "xyz": 44}) == \
+            '{"message": "stats", "utc": 432.1, "cells": {'                 + \
+            '"1": {"counters": {"messages": {"rrc_x": 11, "abc": 111}}}, '  + \
+            '"2": {"counters": {"messages": {"rrc_y": 22}}}, '              + \
+            '"3": {"counters": {"messages": {"xyz": 33}}}}, '               + \
+            '"counters": {"messages": {"xyz": 44}}}'
+
 
 # jdrb_stats, similarly to jstats, returns json-encoded x.drb_stats message
 # corresponding to per-QCI dl/ul tx_time/tx_bytes.