feat: support PRINTK_CALLER kmsg logs

happy-dude · smira · commit 47655eefbc8d · 2024-05-08T20:55:06.000+04:00
Closes #10 Add support for caller information in kmsg log entries. More examples available at #10 (comment) Also adds tests for a log entry with a Thread caller and a Cpu caller. Further references: * https://elixir.bootlin.com/linux/v6.6.22/source/kernel/printk/printk_ringbuffer.h#L15 * https://elixir.bootlin.com/linux/v6.6.22/source/kernel/printk/printk.c#L629 Signed-off-by: Stanley Chan <pocketgamer5000@gmail.com> Signed-off-by: Andrey Smirnov <andrey.smirnov@siderolabs.com>
diff --git a/message.go b/message.go
@@ -40,6 +40,23 @@ const (
 	Local7
 )
 
+// CallerType is a single char byte caller type in kmsg logs with PRINTK_CALLER support.
+type CallerType byte
+
+// Types of callers a kmsg can originate from.
+//
+// ref: https://elixir.bootlin.com/linux/v6.6.22/source/kernel/printk/printk.c#L629
+const (
+	CPUCaller    = 'C'
+	ThreadCaller = 'T'
+)
+
+// Caller struct containing the type and ID from kmsg logs with PRINTK_CALLER support.
+type Caller struct {
+	Type CallerType
+	ID   uint32
+}
+
 func (f Facility) String() string {
 	return [...]string{
 		"kern", "user", "mail", "daemon",
@@ -77,6 +94,7 @@ type Message struct {
 	Priority       Priority
 	SequenceNumber int64
 	Clock          int64
+	Caller         Caller
 }
 
 // ParseMessage parses internal kernel log format.
@@ -108,12 +126,38 @@ func ParseMessage(input []byte, bootTime time.Time) (Message, error) {
 		return Message{}, fmt.Errorf("errors parsing clock from boot: %w", err)
 	}
 
+	caller := Caller{}
+
+	if len(metadata) == 5 {
+		// CONFIG_PRINTK_CALLER is enabled and kmsg has CPU or Thread caller info
+		callParts := strings.Split(metadata[4], "=")
+
+		callStr := callParts[1]
+
+		switch callStr[0] {
+		case ThreadCaller:
+			caller.Type = ThreadCaller
+		case CPUCaller:
+			caller.Type = CPUCaller
+		default:
+			return Message{}, fmt.Errorf("errors parsing caller id type")
+		}
+
+		id, err := strconv.ParseUint(callStr[1:], 10, 32)
+		if err != nil {
+			return Message{}, fmt.Errorf("errors parsing caller id value: %w", err)
+		}
+
+		caller.ID = uint32(id)
+	}
+
 	return Message{
 		Priority:       Priority(syslogPrefix & 7),
 		Facility:       Facility(syslogPrefix >> 3),
 		SequenceNumber: sequence,
 		Clock:          clock,
 		Timestamp:      bootTime.Add(time.Duration(clock) * time.Microsecond),
+		Caller:         caller,
 		Message:        unescape(message),
 	}, nil
 }
diff --git a/message_test.go b/message_test.go
@@ -63,6 +63,36 @@ func TestParseMessage(t *testing.T) {
 				Message:        "NET: Registered protocol family \\10\\ in µs",
 			},
 		},
+		{
+			input: `6,378,5140900,-,caller=T148;ata1: SATA max UDMA/133 abar m8192@0xf0820000 port 0xf0820100 irq 21`,
+			expected: kmsg.Message{
+				Facility:       kmsg.Kern,
+				Priority:       kmsg.Info,
+				SequenceNumber: 378,
+				Clock:          5140900,
+				Timestamp:      mustParse("0001-01-01 00:00:05.1409 +0000 UTC"),
+				Caller: kmsg.Caller{
+					Type: kmsg.ThreadCaller,
+					ID:   148,
+				},
+				Message: "ata1: SATA max UDMA/133 abar m8192@0xf0820000 port 0xf0820100 irq 21",
+			},
+		},
+		{
+			input: `0,380,5140900,-,caller=C10;watchdog: BUG: soft lockup - CPU#10 stuck for 216s! [softlockup_thre:529]`,
+			expected: kmsg.Message{
+				Facility:       kmsg.Kern,
+				Priority:       kmsg.Emerg,
+				SequenceNumber: 380,
+				Clock:          5140900,
+				Timestamp:      mustParse("0001-01-01 00:00:05.1409 +0000 UTC"),
+				Caller: kmsg.Caller{
+					Type: kmsg.CPUCaller,
+					ID:   10,
+				},
+				Message: "watchdog: BUG: soft lockup - CPU#10 stuck for 216s! [softlockup_thre:529]",
+			},
+		},
 	} {
 		message, err := kmsg.ParseMessage([]byte(testCase.input), time.Time{})
 		require.NoError(t, err)
