Update: added separate 'log write' event type for OT nodes (#162)

* [all] added separate 'log write' event type for OT nodes. This simplifies the parsing at OTNS side: not intertwined anymore with UART output. The otoutfilter package is removed (if in future needed for parsing UART-based OT logs, then it can always be added back in again)

dispatcher/FailureCtrl_test.go

@@ -44,6 +44,9 @@ type mockDispatcherCallback struct {
 func (m mockDispatcherCallback) OnUartWrite(nodeid NodeId, data []byte) {
 }
 
+func (m mockDispatcherCallback) OnLogWrite(nodeid NodeId, data []byte) {
+}
+
 func (m mockDispatcherCallback) OnNextEventTime(nextTimeUs uint64) {
 }
 

dispatcher/dispatcher.go

@@ -57,6 +57,9 @@ type CallbackHandler interface {
 	// OnUartWrite Notifies that the node's UART was written with data.
 	OnUartWrite(nodeid NodeId, data []byte)
 
+	// OnLogWrite Notifies that a log item wsa written to the node's log.
+	OnLogWrite(nodeid NodeId, data []byte)
+
 	// OnNextEventTime Notifies that the Dispatcher simulation will move shortly to the next event time.
 	OnNextEventTime(nextTimeUs uint64)
 
@@ -80,6 +83,7 @@ type Dispatcher struct {
 		RadioEvents      uint64
 		StatusPushEvents uint64
 		UartWriteEvents  uint64
+		LogWriteEvents   uint64
 		OtherEvents      uint64
 		// Packet-related event dispatching counters
 		DispatchByExtAddrSucc   uint64
@@ -407,6 +411,9 @@ func (d *Dispatcher) handleRecvEvent(evt *Event) {
 	case EventTypeUartWrite:
 		d.Counters.UartWriteEvents += 1
 		d.cbHandler.OnUartWrite(node.Id, evt.Data)
+	case EventTypeLogWrite:
+		d.Counters.LogWriteEvents += 1
+		d.cbHandler.OnLogWrite(node.Id, evt.Data)
 	case EventTypeExtAddr:
 		d.Counters.OtherEvents += 1
 		var extaddr = binary.BigEndian.Uint64(evt.Data[0:8])

event/event.go

@@ -1,4 +1,4 @@
-// Copyright (c) 2020-2023, The OTNS Authors.
+// Copyright (c) 2020-2024, The OTNS Authors.
 // All rights reserved.
 //
 // Redistribution and use in source and binary forms, with or without
@@ -60,6 +60,7 @@ const (
 	EventTypeRadioRfSimParamGet EventType = 16
 	EventTypeRadioRfSimParamSet EventType = 17
 	EventTypeRadioRfSimParamRsp EventType = 18
+	EventTypeLogWrite           EventType = 19
 )
 
 const (

logger/logger.go

@@ -1,4 +1,4 @@
-// Copyright (c) 2023, The OTNS Authors.
+// Copyright (c) 2023-2024, The OTNS Authors.
 // All rights reserved.
 //
 // Redistribution and use in source and binary forms, with or without

logger/nodelogger.go

@@ -29,6 +29,7 @@ package logger
 import (
 	"fmt"
 	"os"
+	"strings"
 	"sync"
 	"time"
 
@@ -156,6 +157,18 @@ func (nl *NodeLogger) IsLevelVisible(level Level) bool {
 	return nl.displayLevel >= level
 }
 
+// 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)
+	levelAndMsg = strings.TrimSpace(levelAndMsg)
+	if isOtLogLine {
+		NodeLogf(nl.Id, level, levelAndMsg)
+	} else {
+		NodeLogf(nl.Id, InfoLevel, levelAndMsg)
+	}
+}
+
 func (nl *NodeLogger) Log(level Level, msg string) {
 	NodeLogf(nl.Id, level, msg)
 }

logger/parse.go

@@ -26,14 +26,21 @@
 
 package logger
 
-import "fmt"
+import (
+	"fmt"
+	"regexp"
+)
 
 const (
 	OffLevelString     = "off"
 	NoneLevelString    = "none"
 	DefaultLevelString = "default"
 )
 
+var (
+	logPattern = regexp.MustCompile(`\[(-|C|W|N|I|D|CRIT|WARN|NOTE|INFO|DEBG)]`)
+)
+
 func ParseLevelString(level string) (Level, error) {
 	switch level {
 	case "micro":
@@ -59,7 +66,7 @@ func ParseLevelString(level string) (Level, error) {
 	}
 }
 
-func ParseOtLevelChar(level byte) Level {
+func parseOtLevelChar(level byte) Level {
 	switch level {
 	case 'T':
 		return TraceLevel
@@ -78,6 +85,16 @@ func ParseOtLevelChar(level byte) Level {
 	}
 }
 
+// ParseOtLogLine attempts to parse line as an OT generated log line with timestamp/level/message.
+// Returns true if successful and also returns the determined log level of the log line.
+func ParseOtLogLine(line string) (bool, Level) {
+	logIdx := logPattern.FindStringSubmatchIndex(line)
+	if logIdx == nil {
+		return false, 0
+	}
+	return true, parseOtLevelChar(line[logIdx[2]])
+}
+
 func GetLevelString(level Level) string {
 	switch level {
 	case MicroLevel:

ot-rfsim/src/event-sim.c

@@ -112,6 +112,18 @@ void otSimSendUartWriteEvent(const uint8_t *aData, uint16_t aLength) {
     otSimSendEvent(&event);
 }
 
+void otSimSendLogWriteEvent(const uint8_t *aData, uint16_t aLength) {
+    OT_ASSERT(aLength <= OT_EVENT_DATA_MAX_SIZE);
+
+    struct Event event;
+    event.mEvent      = OT_SIM_EVENT_LOG_WRITE;
+    event.mDelay      = 0;
+    event.mDataLength = aLength;
+    memcpy(event.mData, aData, aLength);
+
+    otSimSendEvent(&event);
+}
+
 void otSimSendOtnsStatusPushEvent(const char *aStatus, uint16_t aLength) {
     OT_ASSERT(aLength <= OT_EVENT_DATA_MAX_SIZE);
 

ot-rfsim/src/event-sim.h

@@ -64,6 +64,7 @@ enum
     OT_SIM_EVENT_RFSIM_PARAM_GET     = 16,
     OT_SIM_EVENT_RFSIM_PARAM_SET     = 17,
     OT_SIM_EVENT_RFSIM_PARAM_RSP     = 18,
+    OT_SIM_EVENT_LOG_WRITE           = 19,
 };
 
 #define OT_EVENT_DATA_MAX_SIZE 1024
@@ -171,6 +172,14 @@ void otSimSendRadioChanSampleEvent(struct RadioCommEventData *aChanData);
  */
 void otSimSendUartWriteEvent(const uint8_t *aData, uint16_t aLength);
 
+/**
+ * Send an OT log-write event to the simulator, containing a single log item.
+ *
+ * @param[in]   aData       A pointer to the UART data.
+ * @param[in]   aLength     Length of UART data.
+ */
+void otSimSendLogWriteEvent(const uint8_t *aData, uint16_t aLength);
+
 /**
  * Send status push data event to the OT-NS simulator.
  *

ot-rfsim/src/logging.c

@@ -74,7 +74,7 @@ OT_TOOL_WEAK void otPlatLog(otLogLevel aLogLevel, otLogRegion aLogRegion, const
     if (!gTerminate) {
         logString[strLen] = '\n';
         logString[strLen + 1] = '\0';
-        otSimSendUartWriteEvent((const uint8_t *) &logString[0], strLen + 1);
+        otSimSendLogWriteEvent((const uint8_t *) &logString[0], strLen + 1);
     }
 }