WIP: adding features 1) distinct logging for RCP and Posix processes; 2) log style output of otbr.sh; 3) param if to set bb interface per OTBR; 4) fast fail handling when OTBR process exits - without 5 sec wait.

Author: EskoDijk

GUIDE.md

@@ -292,12 +292,15 @@ myusername ALL=(ALL) NOPASSWD: /usr/local/bin/ot-ctl
 
 Check that the binaries are installed in the given locations: if not, adjust the paths accordingly. If both binaries are available in the user's PATH, OTNS will find them automatically.
 
-Below is an example how OTNS should be run to add an OTBR to the simulation. Once OTNS is running, the CLI command to add an OTBR is `add otbr`.
+Below are examples how OTNS should be run to enable OTBRs in the simulation.
 
 ```bash
-otns -realtime -otbr-backbone-if eth0
+otns -realtime -otbr-if eth0
+otns -realtime
 ```
 
 The flag `-realtime` specifies that OTNS runs in real-time mode, required to support OTBR and other RCP/Posix based nodes.
 
-The parameter `-otbr-backbone-if` specifies the network interface (AIL) that the OTBR should use to connect to the real network. It can be your local Ethernet or Wi-Fi interface, or a virtual network interface set up with Linux network namespaces. If the parameter is omitted, the OTBR will connect to the loopback interface (`lo`) by default. In this case, no external communication is possible.
+The parameter `-otbr-if` specifies the network interface (AIL) that the OTBR should use to connect to the real network. It can be your local Ethernet or Wi-Fi interface, or a virtual network interface set up with Linux network namespaces. If the parameter is omitted, the OTBR will connect to the loopback interface (`lo`) by default. In this case, no external IP communication is possible even though an OTBR can be started.
+
+Once OTNS is running, the CLI command to add an OTBR is `add otbr` to use the default backbone interface as specified above. To use a different interface, use `add otbr if "wifi1"` for example to pick the 'wifi1' interface. This is useful when adding multiple OTBRs in a simulation.

cli/CmdRunner.go

@@ -455,6 +455,9 @@ func (rt *CmdRunner) executeAddNode(cc *CommandContext, cmd *AddCmd) {
 	if cmd.Raw != nil {
 		cfg.IsRaw = true
 	}
+	if cmd.BackboneIf != nil {
+		cfg.NetIfName = cmd.BackboneIf.Name
+	}
 
 	rt.postAsyncWait(cc, func(sim *simulation.Simulation) {
 		sim.NodeConfigFinalize(&cfg)

cli/ast.go

@@ -307,7 +307,8 @@ type AddCmd struct {
 	Restore    *RestoreFlag    `| @@`                 //nolint
 	Version    *ThreadVersion  `| @@`                 //nolint
 	Raw        *RawFlag        `| @@`                 //nolint
-	Executable *ExecutableFlag `| @@ )*`              //nolint
+	Executable *ExecutableFlag `| @@`                 //nolint
+	BackboneIf *BackboneIfFlag `| @@ )*`              //nolint
 }
 
 // noinspection GoVetStructTag
@@ -346,6 +347,12 @@ type RawFlag struct {
 	Dummy struct{} `"raw"` //nolint
 }
 
+// noinspection GoVetStructTag
+type BackboneIfFlag struct {
+	Dummy struct{} `"if"`   //nolint
+	Name  string   `@String` //nolint
+}
+
 // noinspection GoVetStructTag
 type MaxSpeedFlag struct {
 	Dummy struct{} `( "max" | "inf")` //nolint

cli/cli_test.go

@@ -61,6 +61,10 @@ func TestParseBytes(t *testing.T) {
 	assert.True(t, cmd.Add.RadioRange.Val == 1234)
 	assert.Nil(t, parseBytes([]byte("add router x 1 y 2 id 3 rr 1234"), &cmd))
 	assert.Nil(t, parseBytes([]byte("add router rr 1234 id 3 y 2 x 1"), &cmd))
+	assert.Nil(t, parseBytes([]byte(`add otbr if "eth0"`), &cmd))
+	assert.True(t, cmd.Add.BackboneIf != nil && cmd.Add.BackboneIf.Name == "eth0")
+	assert.Nil(t, parseBytes([]byte("add otbr"), &cmd))
+	assert.True(t, cmd.Add.BackboneIf == nil)
 
 	assert.Nil(t, parseBytes([]byte("autogo"), &cmd))
 	assert.NotNil(t, cmd.AutoGo)

dispatcher/FailureCtrl_test.go

@@ -44,7 +44,10 @@ type mockDispatcherCallback struct {
 func (m mockDispatcherCallback) OnUartWrite(nodeid NodeId, data []byte) {
 }
 
-func (m mockDispatcherCallback) OnLogWrite(nodeid NodeId, data []byte) {
+func (m mockDispatcherCallback) OnUartDisconnected(nodeid NodeId) {
+}
+
+func (m mockDispatcherCallback) OnLogWrite(nodeid NodeId, data []byte, isFromHost bool) {
 }
 
 func (m mockDispatcherCallback) OnNextEventTime(nextTimeUs uint64) {

dispatcher/dispatcher.go

@@ -61,7 +61,7 @@ type CallbackHandler interface {
 	OnUartWrite(nodeid NodeId, data []byte)
 
 	// OnLogWrite Notifies that a log item was written to the node's log.
-	OnLogWrite(nodeid NodeId, data []byte)
+	OnLogWrite(nodeid NodeId, data []byte, isFromHost bool)
 
 	// OnNextEventTime Notifies that the Dispatcher simulated-time will move to the next event time.
 	OnNextEventTime(nextTimeUs uint64)
@@ -78,7 +78,11 @@ type CallbackHandler interface {
 	// started nodes currently (and then the connection to it will be closed by Dispatcher).
 	OnNewNodeDetected(nodeid NodeId) bool
 
-	// OnNodeDisconnected Notifies that the Dispatcher detected disconnection of a node process.
+	// OnUartDisconnected Notifies that the node's UART stream has ended (node process exited).
+	// Called after stdout/stderr pipes for the node have been closed.
+	OnUartDisconnected(nodeid NodeId)
+
+	// OnNodeDisconnected Notifies that the Dispatcher detected disconnection of a node process from the Unix socket.
 	OnNodeDisconnected(nodeid NodeId)
 }
 
@@ -479,7 +483,9 @@ func (d *Dispatcher) HandleEvent(evt *Event) {
 		if d.isDeleted(nodeid) {
 			switch evt.Type {
 			case EventTypeUartWrite,
-				EventTypeLogWrite:
+				EventTypeUartDisconnected,
+				EventTypeLogWrite,
+				EventTypeLogWriteHost:
 				node = d.deletedNodes[nodeid]
 			default:
 				return
@@ -536,16 +542,20 @@ func (d *Dispatcher) HandleEvent(evt *Event) {
 		d.Counters.UartWriteEvents += 1
 		d.cbHandler.OnUartWrite(node.Id, evt.Data)
 	case EventTypeUartDisconnected:
-		d.Counters.OtherEvents += 1
-		d.setSleeping(node.Id)
-		d.alarmMgr.SetTimestamp(node.Id, Ever)
+		d.Counters.UartWriteEvents += 1
+		// if the process exited, we trigger the node's/socket's disconnection.
+		d.setDisconnected(node.Id)
+		d.cbHandler.OnUartDisconnected(node.Id)
 	case EventTypeLogWrite:
 		d.Counters.LogWriteEvents += 1
-		d.cbHandler.OnLogWrite(node.Id, evt.Data)
+		d.cbHandler.OnLogWrite(node.Id, evt.Data, false)
+	case EventTypeLogWriteHost:
+		d.Counters.LogWriteEvents += 1
+		d.cbHandler.OnLogWrite(node.Id, evt.Data, true)
 	case EventTypeExtAddr:
 		d.Counters.OtherEvents += 1
-		var extaddr = binary.BigEndian.Uint64(evt.Data[0:8])
-		node.onStatusPushExtAddr(extaddr)
+		extAddr := binary.BigEndian.Uint64(evt.Data[0:8])
+		node.onStatusPushExtAddr(extAddr)
 	case EventTypeNodeInfo:
 		d.Counters.OtherEvents += 1
 		// No further handling is needed; the node info was already used at this point.
@@ -1085,13 +1095,17 @@ func (d *Dispatcher) setSleeping(nodeid NodeId) {
 
 func (d *Dispatcher) setDisconnected(nodeid NodeId) {
 	node := d.nodes[nodeid]
-	logger.AssertNotNil(node)
-	logger.AssertFalse(d.isDeleted(nodeid))
-
+	if node == nil {
+		node = d.deletedNodes[nodeid]
+		if node == nil {
+			return // if node was already deleted
+		}
+	} else {
+		d.alarmMgr.SetTimestamp(nodeid, Ever)
+		d.setSleeping(nodeid)
+	}
 	logger.Debugf("Node %d is set to disconnected and sleeping state.", nodeid)
-	d.alarmMgr.SetTimestamp(nodeid, Ever)
-	d.setSleeping(nodeid)
-	node.hasDisconnected.Store(true)
+	node.DisconnectSocket()
 }
 
 // syncAliveNodes advances the node's time of alive nodes only to current dispatcher time.

event/event.go

@@ -1,4 +1,4 @@
-// Copyright (c) 2020-2024, The OTNS Authors.
+// Copyright (c) 2020-2026, The OTNS Authors.
 // All rights reserved.
 //
 // Redistribution and use in source and binary forms, with or without
@@ -65,6 +65,7 @@ const (
 	EventTypeIp6ToHost          EventType = 21
 	EventTypeUdpFromHost        EventType = 22
 	EventTypeIp6FromHost        EventType = 23
+	EventTypeLogWriteHost       EventType = 24
 )
 
 const (
@@ -94,8 +95,7 @@ type Event struct {
 	MsgToHostData  MsgToHostEventData
 }
 
-// All ...EventData formats below only used by OT nodes supporting advanced
-// RF simulation.
+// All ...EventData formats below define the type-specific event payloads.
 const radioCommEventDataHeaderLen = 11 // from OT-RFSIM platform, event-sim.h struct
 type RadioCommEventData struct {
 	Channel  uint8

logger/nodelogger.go

@@ -159,13 +159,14 @@ func (nl *NodeLogger) IsLevelVisible(level Level) bool {
 
 // LogOt logs a complete OT format log string, which includes timestamp, log level character, and
 // the log message. The right level to log is automatically determined.
-func (nl *NodeLogger) LogOt(levelAndMsg string) {
-	isOtLogLine, level := ParseOtLogLine(levelAndMsg)
+// If alternateMarker is non-empty, it will replace the standard ": " marker of the log message.
+func (nl *NodeLogger) LogOt(levelAndMsg string, alternateMarker string) {
+	isOtLogLine, level, adaptedMsg := ParseOtLogLineAndAdaptMarker(levelAndMsg, alternateMarker)
 	levelAndMsg = strings.TrimSpace(levelAndMsg)
 	if isOtLogLine {
-		NodeLogf(nl.Id, level, levelAndMsg)
+		NodeLogf(nl.Id, level, adaptedMsg)
 	} else {
-		NodeLogf(nl.Id, InfoLevel, levelAndMsg)
+		NodeLogf(nl.Id, InfoLevel, adaptedMsg)
 	}
 }
 

logger/parse.go

@@ -29,12 +29,14 @@ package logger
 import (
 	"fmt"
 	"regexp"
+	"strings"
 )
 
 const (
 	OffLevelString     = "off"
 	NoneLevelString    = "none"
 	DefaultLevelString = "default"
+	AltOtLogMarker     = "| "
 )
 
 // Example Posix ot-cli OTNS status push: 00:00:02.233 [-] Otns----------: transmit=11,d841,121,ffff
@@ -108,6 +110,33 @@ func ParseOtnsStatusPush(line string) (bool, string) {
 	return true, match[1]
 }
 
+// ParseOtLogLineAndAdaptMarker checks like ParseOtLogLine and if it is a log line, and if so, it replaces
+// the ': ' string that marks the start of the log message (after the log module name) with the provided
+// marker string, unless the marker is empty "".
+func ParseOtLogLineAndAdaptMarker(line string, marker string) (bool, Level, string) {
+	logIdx := logPattern.FindStringSubmatchIndex(line)
+	if logIdx == nil {
+		return false, OffLevel, line
+	}
+
+	// Find the module/message separator colon (first ': ' after the level marker).
+	level := parseOtLevelChar(line[logIdx[2]])
+	if len(marker) > 0 {
+		n := logIdx[1] + 1
+		linePart := line[n:]
+		moduleColonOffset := strings.Index(linePart, ": ")
+		if moduleColonOffset >= 8 && moduleColonOffset <= 28 {
+			// verify that no space exists between module name and colon
+			firstSpaceOffset := strings.Index(linePart, " ")
+			if firstSpaceOffset > moduleColonOffset {
+				msgStart := n + moduleColonOffset + 2
+				line = line[:msgStart-2] + marker + line[msgStart:]
+			}
+		}
+	}
+	return true, level, line
+}
+
 func GetLevelString(level Level) string {
 	switch level {
 	case MicroLevel:

ot-rfsim/ot-versions/ot-br.sh

@@ -29,13 +29,17 @@
 
 # ot-br.sh - script to start an OTBR node from an OTNS simulation.
 
+DEBG="[DEBG]-OTBR.SH-:"
+CRIT="[CRIT]-OTBR.SH-:"
+INFO="[INFO]-OTBR.SH-:"
+
 # When a running script receives SIGTERM
 cleanup()
 {
-    echo "[DEBG] ot-br.sh: caught signal, cleaning up child processes"
+    echo "${DEBG} ot-br.sh: caught signal, cleaning up child processes"
     jobs -p | xargs -r kill
     wait
-    echo "[DEBG] ot-br.sh: script exit"
+    echo "${DEBG} ot-br.sh: script exit"
     exit 0
 }
 
@@ -45,16 +49,16 @@ sudo_command_failed()
 {
     local cmd="$1"
     local cmd_path
-    echo "[CRIT] passwordless sudo failed for '${cmd}'"
-    echo "[CRIT] add below lines to /etc/sudoers (run: sudo visudo):"
+    echo "${CRIT} passwordless sudo failed for '${cmd}'"
+    echo "${CRIT} add below lines to /etc/sudoers (run: sudo visudo):"
 
     cmd="otbr-agent"
     cmd_path=$(command -v "$cmd" 2>/dev/null)
-    echo "[CRIT]   ${USER} ALL=(ALL) NOPASSWD: SETENV: ${cmd_path:-/usr/local/sbin/${cmd}}"
+    echo "[CRIT]           ${USER} ALL=(ALL) NOPASSWD: SETENV: ${cmd_path:-/usr/local/sbin/${cmd}}"
 
     cmd="ot-ctl"
     cmd_path=$(command -v "$cmd" 2>/dev/null)
-    echo "[CRIT]   ${USER} ALL=(ALL) NOPASSWD: ${cmd_path:-/usr/local/bin/${cmd}}"
+    echo "[CRIT]           ${USER} ALL=(ALL) NOPASSWD: ${cmd_path:-/usr/local/bin/${cmd}}"
     exit 1
 }
 
@@ -69,49 +73,50 @@ socket_in_use()
     fi
 }
 
-echo "[DEBG] ot-br.sh started"
+echo "${DEBG} ot-br.sh started"
 
 NODE_ID=$1
 BACKBONE_IF_NAME=$2
 AGENT_PARAM=$3
 RADIO_URL=$4
-# TODO: 'wpan1' for node 1 etc doesn't work - needs to be wpan0. Check later if there's a way to use others.
-THREAD_IF_NAME="wpan0"
+THREAD_IF_NAME="wpan${PORT_OFFSET}_${NODE_ID}"
+REST_PORT=$((8080 + NODE_ID))
 EXTRA_DELAY=0
 MAX_WAIT_SEC=5
 SOCKET_PATH="/run/openthread-${THREAD_IF_NAME}.sock"
 DATA_PATH="/var/lib/thread"
 
-echo "[DEBG]  PORT_OFFSET     =${PORT_OFFSET}"
-echo "[DEBG]  NODE_ID         =${NODE_ID}"
-echo "[DEBG]  BACKBONE_IF_NAME=${BACKBONE_IF_NAME}"
-echo "[DEBG]  THREAD_IF_NAME  =${THREAD_IF_NAME}"
-echo "[DEBG]  RADIO_URL       =${RADIO_URL}"
-echo "[DEBG]  SOCKET_PATH     =${SOCKET_PATH}"
-echo "[DEBG]  DATA_PATH       =${DATA_PATH}"
-echo "[DEBG]  AGENT_PARAM     =${AGENT_PARAM}"
+echo "${DEBG}   PORT_OFFSET     =${PORT_OFFSET}"
+echo "${DEBG}   NODE_ID         =${NODE_ID}"
+echo "${DEBG}   BACKBONE_IF_NAME=${BACKBONE_IF_NAME}"
+echo "${DEBG}   THREAD_IF_NAME  =${THREAD_IF_NAME}"
+echo "${DEBG}   REST_PORT       =${REST_PORT}"
+echo "${DEBG}   RADIO_URL       =${RADIO_URL}"
+echo "${DEBG}   SOCKET_PATH     =${SOCKET_PATH}"
+echo "${DEBG}   DATA_PATH       =${DATA_PATH}"
+echo "${DEBG}   AGENT_PARAM     =${AGENT_PARAM}"
 
 # check for passwordless sudo access to commands
 sudo -n otbr-agent -V >/dev/null 2>&1 || sudo_command_failed otbr-agent
 sudo -n ot-ctl -h >/dev/null 2>&1 || sudo_command_failed ot-ctl
 
-# check for existing socket usage
+# check for existing socket usage`
 if [ -S "${SOCKET_PATH}" ]; then
     if socket_in_use "${SOCKET_PATH}"; then
-        echo "[CRIT] socket ${SOCKET_PATH} is already in use - is otbr-agent already running on ${THREAD_IF_NAME}?"
+        echo "${CRIT} socket ${SOCKET_PATH} is already in use - is otbr-agent already running on ${THREAD_IF_NAME}?"
         exit 1
     fi
-    echo "[DEBG] existing (unused?) file ${SOCKET_PATH} detected - start with extra delay"
+    echo "${DEBG} existing (unused?) file ${SOCKET_PATH} detected - start with extra delay"
     EXTRA_DELAY=3
 fi
 
-echo "[DEBG] starting otbr-agent"
+echo "${INFO} starting otbr-agent"
 # All otbr-agent output redirected to stderr, so that ot-ctl CLI interactions are not garbled.
 sudo -n PORT_OFFSET="${PORT_OFFSET}" otbr-agent --data-path "${DATA_PATH}" -s -d 7 -I ${THREAD_IF_NAME} -B "${BACKBONE_IF_NAME}" \
-    "${AGENT_PARAM}" "${RADIO_URL}" 1>&2 &
+    --rest-listen-port "${REST_PORT}" "${AGENT_PARAM}" "${RADIO_URL}" 1>&2 &
 SUDO_OTBR_PID=$!
 
-echo "[DEBG] otbr-agent started in background (parent PID=${SUDO_OTBR_PID}) - waiting until ready"
+echo "${DEBG} otbr-agent started in background (parent PID=${SUDO_OTBR_PID}) - waiting until ready"
 
 # wait for otbr-agent to create its Unix socket
 elapsed=0
@@ -127,11 +132,12 @@ while [ ! -S "${SOCKET_PATH}" ]; do
     sleep 0.1
     elapsed=$((elapsed + 1))
 done
-echo "[DEBG] otbr-agent socket ready after $((elapsed / 10)).$((elapsed % 10))s, starting ot-ctl CLI"
+echo "${DEBG} otbr-agent socket ready after $((elapsed / 10)).$((elapsed % 10))s, adding ${EXTRA_DELAY} s delay"
 sleep ${EXTRA_DELAY}
-sudo -n ot-ctl
+echo "${INFO} starting ot-ctl CLI"
+sudo -n ot-ctl -I "${THREAD_IF_NAME}"
 
-echo "[DEBG] ot-br.sh: ot-ctl CLI exited, cleaning up child processes"
+echo "${DEBG} ot-br.sh: ot-ctl CLI exited, cleaning up child processes"
 jobs -p | xargs -r kill
 wait
-echo "[DEBG] ot-br.sh: script exit"
+echo "${DEBG} ot-br.sh: script exit"