Handle formatting markers in forwarded ETW timestamps

internal/vm/vmutils/gcs_logs.go

@@ -7,6 +7,7 @@ import (
 	"encoding/json"
 	"errors"
 	"io"
+	"strings"
 	"time"
 
 	hcs "github.com/Microsoft/hcsshim/internal/hcs/v2"
@@ -126,15 +127,38 @@ func (e *GCSLogEntry) UnmarshalJSON(b []byte) error {
 	// Default the log level to info.
 	e.Level = logrus.InfoLevel
 
-	// Unmarshal standard fields first
-	if err := json.Unmarshal(b, &e.GCSLogEntryStandard); err != nil {
+	// Identify ETW records before decoding their timestamps.
+	if err := json.Unmarshal(b, &e.Fields); err != nil {
 		return err
 	}
 
-	// Unmarshal all fields including custom ones
-	if err := json.Unmarshal(b, &e.Fields); err != nil {
+	entry := struct {
+		*GCSLogEntryStandard
+		Time json.RawMessage `json:"time"`
+	}{GCSLogEntryStandard: &e.GCSLogEntryStandard}
+	if err := json.Unmarshal(b, &entry); err != nil {
 		return err
 	}
+	if len(entry.Time) != 0 {
+		if e.Fields["Source"] == "ETW" {
+			var timestamp string
+			if err := json.Unmarshal(entry.Time, &timestamp); err != nil {
+				return err
+			}
+			// Log Forward Service can insert U+000E formatting markers when
+			// rendering ETW FILETIME fields. Do not alter other event data.
+			if strings.ContainsRune(timestamp, '\u000e') {
+				normalized, err := json.Marshal(strings.ReplaceAll(timestamp, "\u000e", ""))
+				if err != nil {
+					return err
+				}
+				entry.Time = normalized
+			}
+		}
+		if err := json.Unmarshal(entry.Time, &e.Time); err != nil {
+			return err
+		}
+	}
 
 	// Do not allow fatal or panic level errors to propagate.
 	if e.Level < logrus.ErrorLevel {

internal/vm/vmutils/gcs_logs_test.go

@@ -183,6 +183,48 @@ func TestGCSLogEntryStandard(t *testing.T) {
 	}
 }
 
+func TestGCSLogEntryForwardedETWTime(t *testing.T) {
+	const timestamp = "2026-11-05T14:32:55.464727700Z"
+	const marked = `"\u000e2026\u000e-\u000e11\u000e-\u000e05T14:32:55.464727700Z"`
+	want, err := time.Parse(time.RFC3339Nano, timestamp)
+	if err != nil {
+		t.Fatal(err)
+	}
+	for _, tc := range []struct {
+		name    string
+		input   string
+		wantErr bool
+	}{
+		{"ETW marked time", `{"Source":"ETW","Time":` + marked + `}`, false},
+		{"ETW uppercase escape", `{"Source":"ETW","Time":` + strings.ReplaceAll(marked, "000e", "000E") + `}`, false},
+		{"ETW lowercase time", `{"Source":"ETW","time":` + marked + `}`, false},
+		{"ETW valid time", `{"Source":"ETW","Time":"` + timestamp + `"}`, false},
+		{"ordinary valid time", `{"time":"` + timestamp + `"}`, false},
+		{"ordinary marked time", `{"time":` + marked + `}`, true},
+		{"other source marked time", `{"Source":"other","Time":` + marked + `}`, true},
+		{"ETW invalid time", `{"Source":"ETW","Time":"\u000enot-a-timestamp"}`, true},
+		{"ETW other control character", `{"Source":"ETW","Time":"\u000f2026-11-05T14:32:55.464727700Z"}`, true},
+		{"ETW numeric time", `{"Source":"ETW","Time":123}`, true},
+	} {
+		t.Run(tc.name, func(t *testing.T) {
+			var entry GCSLogEntry
+			err := json.Unmarshal([]byte(tc.input), &entry)
+			if tc.wantErr {
+				if err == nil {
+					t.Fatal("expected invalid timestamp to be rejected")
+				}
+				return
+			}
+			if err != nil {
+				t.Fatal(err)
+			}
+			if !entry.Time.Equal(want) {
+				t.Fatalf("time = %v, want %v", entry.Time, want)
+			}
+		})
+	}
+}
+
 func TestParseGCSLogrus(t *testing.T) {
 	// Create a hook to capture log entries
 	hook := &testLogHook{}
@@ -202,6 +244,28 @@ func TestParseGCSLogrus(t *testing.T) {
 		expectedCount int
 		validate      func(t *testing.T, entries []*logrus.Entry)
 	}{
+		{
+			name: "ETW FILETIME markers do not terminate stream",
+			vmID: "test-vm-etw",
+			input: `{"Source":"ETW","ProviderName":"Microsoft.Virtualization.GCSSidecar","Time":"\u000e2026\u000e-\u000e11\u000e-\u000e05T14:32:55.464727700Z","Level":"Info","Message":"Span\u000e","spanID":"707ab0753972cb10"}` +
+				`{"time":"2026-11-05T14:32:56Z","level":"info","msg":"following event"}`,
+			expectedCount: 2,
+			validate: func(t *testing.T, entries []*logrus.Entry) {
+				t.Helper()
+				first := entries[0]
+				if first.Message != "Span\u000e" || first.Data["spanID"] != "707ab0753972cb10" ||
+					first.Data["ProviderName"] != "Microsoft.Virtualization.GCSSidecar" || first.Data["uvm-id"] != "test-vm-etw" {
+					t.Fatalf("event metadata changed: %+v", first)
+				}
+				want := time.Date(2026, 11, 5, 14, 32, 55, 464727700, time.UTC)
+				if got, ok := first.Data["vm.time"].(time.Time); !ok || !got.Equal(want) {
+					t.Fatalf("vm.time = %v, want %v", first.Data["vm.time"], want)
+				}
+				if entries[1].Message != "following event" {
+					t.Fatalf("following event not decoded: %+v", entries[1])
+				}
+			},
+		},
 		{
 			name:          "single log entry",
 			vmID:          "test-vm-1",