MARTe-Integrated-Components/Test/E2E/suite/debugclient/main.go

// Command debugclient drives a running MARTeApp.ex DebugService+TCPLogger
// instance over TCP/UDP for the Test/E2E/suite "debug" and "tcplogger"
// scenario kinds. It scripts a fixed command sequence, captures responses
// and log/trace output, and reports PASS/FAIL as JSON to -out.
package main

import (
	"encoding/json"
	"flag"
	"fmt"
	"os"
	"strings"
	"sync"
	"time"

	debugger "marte2debugger/controller" // see go.mod replace directive; marte2debugger is Client/debugger's module name
)

type event struct {
	kind string
	data any
}

func main() {
	host := flag.String("host", "127.0.0.1", "MARTeApp host")
	cmdPort := flag.Int("cmdport", 8080, "DebugService TCP command port")
	udpPort := flag.Int("udpport", 8081, "DebugService UDP trace port")
	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|debug_pause_resume")
	dur := flag.Duration("dur", 4*time.Second, "how long to run the script/collection")
	flag.Parse()

	if *scenario == "" {
		fmt.Fprintln(os.Stderr, "missing -scenario")
		os.Exit(2)
	}
	os.MkdirAll(*outDir, 0o755)

	var mu sync.Mutex
	var events []event
	sink := func(v any) {
		mu.Lock()
		defer mu.Unlock()
		// runLog (and every other MarteController event site) passes a
		// map[string]any literal to sink; store it as-is, no
		// unmarshal/remarshal needed.
		events = append(events, event{kind: fmt.Sprintf("%T", v), data: v})
	}

	mc := debugger.NewHeadlessMarteController(sink)
	mc.Connect(*host, *cmdPort, *udpPort, *logPort)
	defer mc.Disconnect()

	time.Sleep(500 * time.Millisecond) // allow TCP/UDP/log connects to establish

	// Snapshot the event count *after* the connect-settle sleep so
	// runTcpLoggerScript only scans events recorded from here on. Without this,
	// the "log" event that Connect() itself emits synchronously (a "Connecting
	// to ..." INFO message, well before any TCPLogger TCP traffic happens)
	// would satisfy the check instantly regardless of whether the real
	// TCPLogger (port 9090) ever delivers anything for the triggered event.
	mu.Lock()
	baseline := len(events)
	mu.Unlock()

	var ok bool
	var msg string
	switch *mode {
	case "debug":
		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)
	}

	time.Sleep(300 * time.Millisecond) // drain final events

	result := map[string]any{
		"id":     *scenario,
		"pass":   ok,
		"detail": msg,
	}
	f, _ := os.Create(fmt.Sprintf("%s/result_%s.json", *outDir, *scenario))
	json.NewEncoder(f).Encode(result)
	f.Close()

	status := "FAIL"
	if ok {
		status = "PASS"
	}
	fmt.Printf("%s: %s - %s\n", *scenario, status, msg)
	os.WriteFile(fmt.Sprintf("%s/status_%s.txt", *outDir, *scenario), []byte(status), 0o644)

	if !ok {
		os.Exit(1)
	}
}

// waitForAck polls events (from index start onward) for a MarteController
// "text_line" event exactly matching DebugServiceBase::HandleCommand's
// "OK <token> <count>\n" reply grammar, requiring count > 0. HandleCommand
// prints this reply for every one of FORCE/UNFORCE/TRACE/BREAK regardless of
// enable/disable direction, and count is always "number of signals the
// command actually matched" (DebugServiceBase.cpp:1468-1525) — so count==0
// means the target signal path was never resolved (e.g. a wire-format/name-
// translation bug), which a bare "did the socket stay open" check like the
// old runDebugScript could never catch.
func waitForAck(events *[]event, mu *sync.Mutex, start int, token string, timeout time.Duration) (string, bool) {
	prefix := "OK " + token + " "
	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" {
				continue
			}
			line, _ := m["data"].(string)
			if !strings.HasPrefix(line, prefix) {
				continue
			}
			var count uint32
			if _, err := fmt.Sscanf(line, prefix+"%d", &count); err == nil && count > 0 {
				mu.Unlock()
				return line, true
			}
		}
		mu.Unlock()
		time.Sleep(50 * time.Millisecond)
	}
	return "", false
}

// runDebugScript exercises FORCE/TRACE/BREAK over the TCP 8080 command
// protocol (grammar confirmed against Source/Components/Interfaces/
// DebugService/DebugServiceBase.cpp's HandleCommand: "FORCE <name> <val>",
// "TRACE <name> <0|1> [decim]", "BREAK <name> <op|OFF> <threshold>",
// each replying "OK <TOKEN> <count>\n"). Each step waits for the real
// "OK <TOKEN> <count>" acknowledgement with count > 0 via waitForAck,
// confirming DebugService actually resolved and applied the command against
// the named signal — not merely that the TCP connection stayed alive (which
// would pass even if DebugService silently no-op'd every command, e.g. due
// to a signal-name/wire-format bug).
func runDebugScript(mc *debugger.MarteController, events *[]event, mu *sync.Mutex) (bool, string) {
	const ackTimeout = 2 * time.Second

	mu.Lock()
	start := len(*events)
	mu.Unlock()
	mc.SendCommand("FORCE App.Data.Timer.Counter 42")
	if _, ok := waitForAck(events, mu, start, "FORCE", ackTimeout); !ok {
		return false, "no \"OK FORCE <count>\" ack with count>0 received (signal not resolved)"
	}

	mu.Lock()
	start = len(*events)
	mu.Unlock()
	mc.SendCommand("TRACE App.Data.Timer.Counter 1 1")
	if _, ok := waitForAck(events, mu, start, "TRACE", ackTimeout); !ok {
		return false, "no \"OK TRACE <count>\" ack with count>0 received (signal not resolved)"
	}

	mu.Lock()
	start = len(*events)
	mu.Unlock()
	mc.SendCommand("BREAK App.Data.Timer.Counter > 1000")
	if _, ok := waitForAck(events, mu, start, "BREAK", ackTimeout); !ok {
		return false, "no \"OK BREAK <count>\" ack with count>0 received for SetBreak (signal not resolved)"
	}

	mu.Lock()
	start = len(*events)
	mu.Unlock()
	mc.SendCommand("BREAK App.Data.Timer.Counter OFF")
	if _, ok := waitForAck(events, mu, start, "BREAK", ackTimeout); !ok {
		return false, "no \"OK BREAK <count>\" ack with count>0 received for ClearBreak (signal not resolved)"
	}

	mu.Lock()
	start = len(*events)
	mu.Unlock()
	mc.SendCommand("UNFORCE App.Data.Timer.Counter")
	if _, ok := waitForAck(events, mu, start, "UNFORCE", ackTimeout); !ok {
		return false, "no \"OK UNFORCE <count>\" ack with count>0 received (signal not resolved)"
	}

	if !mc.IsConnected() {
		return false, "lost connection to DebugService during script"
	}
	return true, "FORCE/TRACE/BREAK/UNFORCE all acknowledged with count>0 (real signal resolution confirmed)"
}

// runTcpLoggerScript triggers a log-worthy event and waits for a matching
// "log" event to arrive over the real TCPLogger TCP connection (port 9090)
// within dur.
//
// NOTE: an invalid "FORCE <nonexistent signal> <val>" is *not* usable here —
// DebugServiceBase::ForceSignal() silently no-ops (count stays 0, no
// REPORT_ERROR call) when no signal matches, so it never reaches the logger
// at all. Instead we send "MSG <nonexistent destination> <fn> 0", which
// DebugServiceBase::HandleCommand's MSG handler always resolves via
// ObjectRegistryDatabase::Find() and, on failure, does call
// REPORT_ERROR_STATIC(Warning, "MSG: destination '%s' not found in ORD.")
// (Source/Components/Interfaces/DebugService/DebugServiceBase.cpp) — a real,
// synchronous, deterministic log emission that the framework's LoggerService
// broadcasts to the auto-injected TcpLogger, which then writes
// "LOG <level> <description>\n" to every connected TCP client (see
// Source/Components/Interfaces/TCPLogger/TcpLogger.cpp ConsumeLogMessage /
// Execute). MarteController's runLog reads that line from the real TCP 9090
// socket and forwards it through sink as map[string]any{"type": "log",
// "time": ..., "level": ..., "message": ...}.
//
// baseline is the length of *events captured right after the initial
// connect-settle sleep, before this function sends the MSG command: only
// events recorded from index baseline onward are eligible, so the "log"
// event that MarteController.Connect() itself emits synchronously (a
// "Connecting to ..." INFO message, emitted before any TCP/UDP/log socket
// activity) can never satisfy this check.
func runTcpLoggerScript(mc *debugger.MarteController, dur time.Duration, events *[]event, mu *sync.Mutex, baseline int) (bool, string) {
	const missingDest = "DebugClientNoSuchDestination"
	mc.SendCommand(fmt.Sprintf("MSG %s SomeFunction 0", missingDest))
	deadline := time.Now().Add(dur)
	for time.Now().Before(deadline) {
		mu.Lock()
		for _, e := range (*events)[baseline:] {
			if m, ok := e.data.(map[string]any); ok && m["type"] == "log" {
				msg, _ := m["message"].(string)
				// MarteController.writeCmd() also emits a client-side "CMD"
				// level log echoing every outgoing command as "→ <cmd>"
				// (see martecontrol.go) — since our own MSG command text
				// contains missingDest, that local echo would otherwise
				// satisfy a naive substring check instantly, before the real
				// TCPLogger round-trip ever happens. Require the actual
				// REPORT_ERROR text the DebugService MSG handler produces
				// ("not found in ORD"), which can only arrive via runLog's
				// real TCP 9090 read, never via the local echo.
				if strings.Contains(msg, missingDest) && strings.Contains(msg, "not found in ORD") {
					mu.Unlock()
					return true, fmt.Sprintf("received real TCPLogger log event: %v", m)
				}
			}
		}
		mu.Unlock()
		time.Sleep(100 * time.Millisecond)
	}
	if !mc.IsConnected() {
		return false, "lost connection during tcplogger wait and no matching log event received"
	}
	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)
}