Implemented full e2e testing

2026-07-02 10:10:57 +02:00
parent f8c79131c9
commit f2042d624b
35 changed files with 2419 additions and 78 deletions
@@ -28,6 +28,8 @@
 #let ok_color = rgb("#1a7f37")
 #let bad_color = rgb("#cf222e")
 #let neutral = rgb("#57606a")
+#let fail_bg = rgb("#ffebe9")  // light-red row background for FAIL rows in scenario tables
+#let fail_row_fill(is_fail) = (x, y) => if y > 0 and is_fail(y - 1) { fail_bg } else { none }

 #let warn_color = rgb("#9a6700")   // XFAIL — expected/known failure
 #let xpass_color = rgb("#8250df")  // XPASS — stale marker, needs attention
@@ -204,6 +206,7 @@ MARTe2 processes, plus sustained client throughput (recorded samples ÷ duration
  align: (left, right, right, right, right, right),
  stroke: 0.4pt + rgb("#d0d7de"),
  inset: 5pt,
+  fill: fail_row_fill(i => e2e.scenarios.at(i).status == "FAIL"),
  table.header([*Scenario*], [*Hub CPU (s)*], [*Hub RSS (MB)*],
               [*MARTe CPU (s)*], [*MARTe RSS (MB)*], [*Throughput (sp/s)*]),
  ..e2e.scenarios.map(sc => {
@@ -247,6 +250,7 @@ MARTe2 processes, plus sustained client throughput (recorded samples ÷ duration
    align: (left, center, left, left, right, right, right, center, center),
    stroke: 0.4pt + rgb("#d0d7de"),
    inset: 4pt,
+    fill: fail_row_fill(i => sc.signals.at(i).pass == false),
    table.header([*Signal*], [*Pass*], [*Type*], [*Quant*], [*Max abs err*],
                 [*Corr*], [*nRMSE*], [*Fidelity*], [*Shape*]),
    ..sc.signals.map(g => (
@@ -341,6 +345,7 @@ MARTe2 processes, plus sustained client throughput (recorded samples ÷ duration
      align: (left, center, left),
      stroke: 0.4pt + rgb("#d0d7de"),
      inset: 5pt,
+      fill: fail_row_fill(i => block.scenarios.at(i).status == "FAIL"),
      table.header([*Scenario*], [*Status*], [*Known issue*]),
      ..block.scenarios.map(s => (
        [#s.id],
@@ -357,6 +362,7 @@ MARTe2 processes, plus sustained client throughput (recorded samples ÷ duration
 #kind_table("Recorder (BinaryRecorder disk output)", data.recorder)
 #kind_table("Debug Service E2E", data.debug)
 #kind_table("TCPLogger E2E", data.tcplogger)
+#kind_table("Debug Service PAUSE/RESUME E2E", data.debug_pause_resume)

 // ── stress tests ─────────────────────────────────────────────────────────────
 = Stress Tests
@@ -28,7 +28,7 @@ func main() {
 	logPort := flag.Int("logport", 9090, "TCPLogger TCP port")
 	scenario := flag.String("scenario", "", "scenario id (for output naming)")
 	outDir := flag.String("out", "/tmp/debug_e2e", "output directory")
-	mode := flag.String("mode", "debug", "debug|tcplogger")
+	mode := flag.String("mode", "debug", "debug|tcplogger|debug_pause_resume")
 	dur := flag.Duration("dur", 4*time.Second, "how long to run the script/collection")
 	flag.Parse()

@@ -72,6 +72,8 @@ func main() {
 		ok, msg = runDebugScript(mc, &events, &mu)
 	case "tcplogger":
 		ok, msg = runTcpLoggerScript(mc, *dur, &events, &mu, baseline)
+	case "debug_pause_resume":
+		ok, msg = runPauseResumeScript(mc, &events, &mu)
 	default:
 		fmt.Fprintf(os.Stderr, "unknown -mode %q\n", *mode)
 		os.Exit(2)
@@ -252,3 +254,150 @@ func runTcpLoggerScript(mc *debugger.MarteController, dur time.Duration, events
 	}
 	return false, "no matching log event received within duration"
 }
+
+// readValueResponse sends "VALUE <name>" and waits for the matching
+// {"Name":...,"Value":"...",...} JSON reply (DebugServiceBase::GetSignalValue,
+// dispatched via HandleCommand's "VALUE" token, terminated by a bare
+// "OK VALUE" sentinel line). MarteController's readLoop recognises the
+// leading '{' and accumulates until the sentinel, then delivers the clean
+// JSON text as a map[string]any{"type":"response","tag":"VALUE","data":...}
+// event. Unlike TRACE, VALUE reads the signal's live memory address directly
+// regardless of whether tracing is enabled, so it works as a completely
+// independent observation channel for the PAUSE/RESUME test below.
+func readValueResponse(events *[]event, mu *sync.Mutex, start int, timeout time.Duration) (uint32, bool) {
+	deadline := time.Now().Add(timeout)
+	for time.Now().Before(deadline) {
+		mu.Lock()
+		for _, e := range (*events)[start:] {
+			m, ok := e.data.(map[string]any)
+			if !ok || m["type"] != "response" || m["tag"] != "VALUE" {
+				continue
+			}
+			data, _ := m["data"].(string)
+			var v struct {
+				Value string `json:"Value"`
+			}
+			if json.Unmarshal([]byte(data), &v) == nil {
+				var n uint32
+				if _, err := fmt.Sscanf(v.Value, "%d", &n); err == nil {
+					mu.Unlock()
+					return n, true
+				}
+			}
+		}
+		mu.Unlock()
+		time.Sleep(20 * time.Millisecond)
+	}
+	return 0, false
+}
+
+// waitForBareOK waits for a text_line event whose data is exactly "OK" — the
+// literal reply DebugServiceBase::HandleCommand sends for PAUSE/RESUME
+// ("out += \"OK\\n\";", no per-signal count unlike FORCE/TRACE/BREAK's
+// "OK <TOKEN> <count>\n"), so it cannot be confused with those other acks.
+func waitForBareOK(events *[]event, mu *sync.Mutex, start int, timeout time.Duration) bool {
+	deadline := time.Now().Add(timeout)
+	for time.Now().Before(deadline) {
+		mu.Lock()
+		for _, e := range (*events)[start:] {
+			m, ok := e.data.(map[string]any)
+			if ok && m["type"] == "text_line" && m["data"] == "OK" {
+				mu.Unlock()
+				return true
+			}
+		}
+		mu.Unlock()
+		time.Sleep(20 * time.Millisecond)
+	}
+	return false
+}
+
+// runPauseResumeScript exercises PAUSE/RESUME over the TCP 8080 command
+// protocol. This complements runDebugScript (FORCE/TRACE/BREAK/UNFORCE):
+// those only confirm DebugService *acknowledges* a command; this confirms
+// PAUSE actually halts the RT GAM loop rather than merely replying "OK".
+// DebugBrokerWrapper's pause spin (DebugBrokerWrapper.h) only runs in the
+// OUTPUT broker's Execute(), AFTER it has already committed the GAM's
+// result for the current cycle — input brokers deliberately never spin
+// (would risk stalling cross-thread EventSem posts). So the *input*-side
+// registration for a signal (e.g. "App.Data.Timer.Counter", the raw
+// LinuxTimer memory feeding TimerGAM) keeps advancing even while paused;
+// only the *output*-side registration ("App.Data.DDB1.Counter", TimerGAM's
+// copy into DDB1 after IOGAM's pass-through) actually freezes. Confirmed
+// empirically: manual PAUSE/RESUME polling showed Timer.Counter advancing
+// continuously through the pause window while DDB1.Counter held constant.
+func runPauseResumeScript(mc *debugger.MarteController, events *[]event, mu *sync.Mutex) (bool, string) {
+	const target = "App.Data.DDB1.Counter"
+	const ackTimeout = 2 * time.Second
+
+	sample := func() (uint32, bool) {
+		mu.Lock()
+		start := len(*events)
+		mu.Unlock()
+		mc.SendCommand("VALUE " + target)
+		return readValueResponse(events, mu, start, ackTimeout)
+	}
+
+	v1, ok := sample()
+	if !ok {
+		return false, "no VALUE response received while running"
+	}
+	time.Sleep(200 * time.Millisecond)
+	v2, ok := sample()
+	if !ok {
+		return false, "no VALUE response received on second running sample"
+	}
+	if v2 <= v1 {
+		return false, fmt.Sprintf("Counter did not advance while running (%d -> %d)", v1, v2)
+	}
+
+	mu.Lock()
+	start := len(*events)
+	mu.Unlock()
+	mc.SendCommand("PAUSE")
+	if !waitForBareOK(events, mu, start, ackTimeout) {
+		return false, "no bare \"OK\" ack received for PAUSE"
+	}
+
+	time.Sleep(100 * time.Millisecond) // let any already-in-flight cycle settle
+	vPause1, ok := sample()
+	if !ok {
+		return false, "no VALUE response received while paused"
+	}
+	time.Sleep(500 * time.Millisecond)
+	vPause2, ok := sample()
+	if !ok {
+		return false, "no VALUE response received on second paused sample"
+	}
+	if vPause2 > vPause1+1 { // tolerate at most one straggling in-flight cycle
+		return false, fmt.Sprintf("Counter kept advancing while paused (%d -> %d)", vPause1, vPause2)
+	}
+
+	mu.Lock()
+	start = len(*events)
+	mu.Unlock()
+	mc.SendCommand("RESUME")
+	if !waitForBareOK(events, mu, start, ackTimeout) {
+		return false, "no bare \"OK\" ack received for RESUME"
+	}
+
+	time.Sleep(200 * time.Millisecond)
+	v3, ok := sample()
+	if !ok {
+		return false, "no VALUE response received after resume"
+	}
+	time.Sleep(200 * time.Millisecond)
+	v4, ok := sample()
+	if !ok {
+		return false, "no VALUE response received on second post-resume sample"
+	}
+	if v4 <= v3 {
+		return false, fmt.Sprintf("Counter did not resume advancing after RESUME (%d -> %d)", v3, v4)
+	}
+
+	if !mc.IsConnected() {
+		return false, "lost connection to DebugService during pause/resume script"
+	}
+	return true, fmt.Sprintf("PAUSE halted Counter (%d -> %d) and RESUME restored advancement (%d -> %d)",
+		vPause1, vPause2, v3, v4)
+}
@@ -273,6 +273,7 @@ _DIRECTION.update({
    "recorder_pass": True, "recorder_fail": False,
    "debug_pass": True, "debug_fail": False,
    "tcplogger_pass": True, "tcplogger_fail": False,
+    "debug_pause_resume_pass": True, "debug_pause_resume_fail": False,
 })
 _DIRECTION.update(_STRESS_DIRECTION)
 _LABELS.update({
@@ -280,6 +281,8 @@ _LABELS.update({
    "recorder_pass": "Recorder scenarios passed", "recorder_fail": "Recorder scenarios failed",
    "debug_pass": "Debug scenarios passed", "debug_fail": "Debug scenarios failed",
    "tcplogger_pass": "TCPLogger scenarios passed", "tcplogger_fail": "TCPLogger scenarios failed",
+    "debug_pause_resume_pass": "Debug pause/resume scenarios passed",
+    "debug_pause_resume_fail": "Debug pause/resume scenarios failed",
 })
 _LABELS.update(_STRESS_LABELS)

@@ -378,6 +381,7 @@ def main():
    recorder = build_by_kind(results, "recorder")
    debug = build_by_kind(results, "debug")
    tcplogger = build_by_kind(results, "tcplogger")
+    debug_pause_resume = build_by_kind(results, "debug_pause_resume")

    stress = None
    stress_plot_paths = []
@@ -398,6 +402,8 @@ def main():
        "recorder_pass": recorder["n_pass"], "recorder_fail": recorder["n_fail"],
        "debug_pass": debug["n_pass"], "debug_fail": debug["n_fail"],
        "tcplogger_pass": tcplogger["n_pass"], "tcplogger_fail": tcplogger["n_fail"],
+        "debug_pause_resume_pass": debug_pause_resume["n_pass"],
+        "debug_pause_resume_fail": debug_pause_resume["n_fail"],
    })
    if stress:
        hl.update(stress_headline(stress))
@@ -430,6 +436,7 @@ def main():
    doc = {
        "meta": meta, "e2e": e2e, "unit_tests": ut, "coverage": cov,
        "direct": direct, "recorder": recorder, "debug": debug, "tcplogger": tcplogger,
+        "debug_pause_resume": debug_pause_resume,
        "stress": stress, "stress_plots": [os.path.basename(p) for p in stress_plot_paths],
        "regression": reg, "headline": hl, "trend_plots": plots,
        "history_len": len(history), "is_first_run": prev is None,
@@ -111,11 +111,11 @@ fi
 # chain:            kind|id|ws_port|udp_port0|network|oracle|trig|checks
 # direct:           kind|id|cfg|-|-|-|-|-
 # recorder:         kind|id|marte_cfg|hub_cfg|-|-|-|-
-# debug/tcplogger:  kind|id|cfg|cmd_port|udp_port|log_port|-|-
+# debug/tcplogger/debug_pause_resume: kind|id|cfg|cmd_port|udp_port|log_port|-|-
 SKIP_KINDS=""
 [ "${SKIP_DATASOURCES}" -eq 1 ] && SKIP_KINDS="${SKIP_KINDS}direct,"
 [ "${SKIP_RECORDER}" -eq 1 ] && SKIP_KINDS="${SKIP_KINDS}recorder,"
-[ "${SKIP_DEBUG}" -eq 1 ] && SKIP_KINDS="${SKIP_KINDS}debug,"
+[ "${SKIP_DEBUG}" -eq 1 ] && SKIP_KINDS="${SKIP_KINDS}debug,debug_pause_resume,"
 [ "${SKIP_TCPLOGGER}" -eq 1 ] && SKIP_KINDS="${SKIP_KINDS}tcplogger,"
 LIST="$(${PY} - "${ONLY}" "${SKIP_KINDS}" <<'PY'
 import sys, os
@@ -145,6 +145,8 @@ for s in S.SCENARIOS:
        print("|".join([kind, s["id"], s["cfg"], str(s["cmd_port"]), str(s["udp_port"]), str(s["log_port"]), "", ""]))
    elif kind == "tcplogger":
        print("|".join([kind, s["id"], s["cfg"], str(s["cmd_port"]), str(s["udp_port"]), str(s["log_port"]), "", ""]))
+    elif kind == "debug_pause_resume":
+        print("|".join([kind, s["id"], s["cfg"], str(s["cmd_port"]), str(s["udp_port"]), str(s["log_port"]), "", ""]))
 PY
 )"

@@ -329,7 +331,7 @@ sys.exit(0 if ok else 1)
    fi
    ;;

-    debug|tcplogger)
+    debug|tcplogger|debug_pause_resume)
    CFG="${F2}"; CMDPORT="${F3}"; UDPPORT2="${F4}"; LOGPORT="${F5}"
    echo ""
    echo "══ scenario ${ID}  (kind=${KIND} cfg=${CFG}) ══"
@@ -144,7 +144,7 @@ def validate_scenario(s):
        if "hub_cfg" not in s or "marte_cfg" not in s:
            errs.append(f"recorder scenario {s.get('id')} missing hub_cfg/marte_cfg")
        return errs
-    if kind in ("debug", "tcplogger"):
+    if kind in ("debug", "tcplogger", "debug_pause_resume"):
        if not all(k in s for k in ("cfg", "cmd_port", "udp_port", "log_port")):
            errs.append(f"{kind} scenario {s.get('id')} missing cfg/cmd_port/udp_port/log_port")
        return errs
@@ -644,7 +644,20 @@ _TCPLOGGER = [
    },
 ]

-SCENARIOS = SCENARIOS + _DIRECT + _RECORDER + _DEBUG + _TCPLOGGER
+_DEBUG_PAUSE_RESUME = [
+    {
+        "id": "s57_debug_pause_resume",
+        "desc": "DebugService PAUSE/RESUME halts and resumes the RT loop, "
+                "verified via live VALUE polling (not just command acks)",
+        "kind": "debug_pause_resume",
+        "cfg": "Test/E2E/suite/debug_e2e.cfg",
+        "cmd_port": 8080, "udp_port": 8081, "log_port": 9090,
+        "client_checks": [],
+        "known_issue": None,
+    },
+]
+
+SCENARIOS = SCENARIOS + _DIRECT + _RECORDER + _DEBUG + _TCPLOGGER + _DEBUG_PAUSE_RESUME


 if __name__ == "__main__":
@@ -61,7 +61,7 @@ class TestScenarios(unittest.TestCase):
    def test_all_scenarios_have_kind(self):
        for s in S.SCENARIOS:
            self.assertIn("kind", s, f"{s['id']} missing kind")
-            self.assertIn(s["kind"], ("chain", "direct", "recorder", "debug", "tcplogger"))
+            self.assertIn(s["kind"], ("chain", "direct", "recorder", "debug", "tcplogger", "debug_pause_resume"))

    def test_direct_and_recorder_scenarios_present(self):
        kinds = {s["kind"] for s in S.SCENARIOS}
@@ -166,6 +166,28 @@ def sine_shape(t, v, freq):
    return corr, nrmse, amp


+def best_sine_shape(t, v, freq_nominal, band=0.05, n=41):
+    """Refine ``freq_nominal`` within +/-``band`` (fractional) before fitting.
+
+    The gross-sanity gate assumes the nominal configured frequency, but
+    MARTe2's LinuxTimer RT loop runs at a small, systematic offset from true
+    wall-clock time (a few percent at most), which accumulates into visible
+    phase drift over a multi-second capture even though every sample value is
+    bit-correct. A coarse search for the actual best-fit frequency near the
+    nominal value absorbs that clock-rate skew while still rejecting a
+    genuinely wrong-frequency or corrupted signal, which collapses correlation
+    regardless of the search window. Returns (corr, nrmse, amp, freq_used).
+    """
+    candidates = np.linspace(freq_nominal * (1.0 - band),
+                              freq_nominal * (1.0 + band), n)
+    best = None
+    for f in candidates:
+        corr, nrmse, amp = sine_shape(t, v, f)
+        if best is None or corr > best[0]:
+            best = (corr, nrmse, amp, float(f))
+    return best
+
+
 def compare_signal(gt, t_recv, v_recv, tap_v=None):
    tol, step = _tol(gt)
    truth_v = gt["v"].astype(np.float64)
@@ -193,7 +215,15 @@ def compare_signal(gt, t_recv, v_recv, tap_v=None):

    shape_ok = True
    if gt["formula"] == "sine" and v_recv.size >= 8 and gt["freq"]:
-        corr, nrmse, amp = sine_shape(t_recv, v_recv, gt["freq"])
+        # Refine the fit frequency within +/-5% of nominal before scoring:
+        # MARTe2's LinuxTimer RT loop runs at a small, systematic offset from
+        # true wall-clock time (a few percent), which accumulates into
+        # visible phase drift over a multi-second capture even though every
+        # sample value is bit-correct (see best_sine_shape docstring). This
+        # keeps the gate a *gross frequency-sanity* check — a wrong-frequency
+        # or corrupted signal still collapses corr regardless of the search
+        # window — while absorbing legitimate clock-rate skew.
+        corr, nrmse, amp, freq_fit = best_sine_shape(t_recv, v_recv, gt["freq"])
        # Shape is a *gross frequency-sanity gate* plus a *tracked quality
        # metric*, not a tight correctness gate. Signal values are bit-faithful
        # (the fidelity oracle proves that); the gap from a perfect fit is
@@ -208,7 +238,7 @@ def compare_signal(gt, t_recv, v_recv, tap_v=None):
        nrmse_tol = 0.30 + (step / (gt["range_max"] - gt["range_min"])
                            if gt["quant"] != "none" else 0.0)
        shape_ok = corr >= 0.5 and nrmse <= nrmse_tol
-        m.update(corr=corr, nrmse=nrmse, amp_fit=amp,
+        m.update(corr=corr, nrmse=nrmse, amp_fit=amp, freq_fit=freq_fit,
                 nrmse_tol=nrmse_tol, shape_ok=bool(shape_ok),
                 shape_gate="gross")