diff --git a/cmd/ateom-gvisor/logger.go b/cmd/ateom-gvisor/logger.go index 01972d2..8789814 100644 --- a/cmd/ateom-gvisor/logger.go +++ b/cmd/ateom-gvisor/logger.go @@ -16,41 +16,58 @@ package main import ( "bufio" - "context" + "bytes" "encoding/json" "io" - "log/slog" "os" - "strings" + "sync" + "time" ) +type syncedWriter struct { + mu sync.Mutex + w io.Writer +} + +func (sw *syncedWriter) Write(p []byte) (n int, err error) { + sw.mu.Lock() + defer sw.mu.Unlock() + return sw.w.Write(p) +} + // ActorLogger handles structured logging for actor sandboxes and lifecycle events. type ActorLogger struct { + writer io.Writer labelsKey string - logger *slog.Logger } // NewActorLogger creates a new ActorLogger wrapping the provided destination writer. -func NewActorLogger(logger *slog.Logger, isOnGCE bool) *ActorLogger { +func NewActorLogger(w io.Writer, isOnGCE bool) *ActorLogger { labelsKey := "labels" if isOnGCE { labelsKey = "logging.googleapis.com/labels" } return &ActorLogger{ + writer: w, labelsKey: labelsKey, - logger: logger, } } // EmitLifecycleLog logs a synthetic actor lifecycle event. func (al *ActorLogger) EmitLifecycleLog(msg, actorID, actorTemplate, actorNamespace string) { - slog.LogAttrs(context.Background(), slog.LevelInfo, msg, - slog.Group(al.labelsKey, - slog.String("ate.dev/actor_id", actorID), - slog.String("ate.dev/actor_template", actorTemplate), - slog.String("ate.dev/actor_namespace", actorNamespace), - ), - ) + envelope := map[string]any{ + "time": time.Now().Format(time.RFC3339Nano), + "message": msg, + al.labelsKey: map[string]string{ + "ate.dev/actor_id": actorID, + "ate.dev/actor_template": actorTemplate, + "ate.dev/actor_namespace": actorNamespace, + }, + } + if envBytes, err := json.Marshal(envelope); err == nil { + envBytes = append(envBytes, '\n') + _, _ = al.writer.Write(envBytes) + } } // StartJSONLogPipe intercepts container raw stdout/stderr streams and pipes them through the logger. @@ -68,7 +85,6 @@ func (al *ActorLogger) StartJSONLogPipe(actorID, actorTemplate, actorNamespace s // WrapContainerLogs reads log lines from r, parses them, and logs them in a unified structured format. func (al *ActorLogger) WrapContainerLogs(r io.Reader, actorID, actorTemplate, actorNamespace string) { - ctx := context.Background() rdr := bufio.NewReader(r) for { lineBytes, err := rdr.ReadBytes('\n') @@ -80,16 +96,36 @@ func (al *ActorLogger) WrapContainerLogs(r io.Reader, actorID, actorTemplate, ac if len(lineBytes) > 0 { var m map[string]any - if unmarshalErr := json.Unmarshal(lineBytes, &m); unmarshalErr != nil { - al.logger.LogAttrs(ctx, slog.LevelInfo, string(lineBytes), - slog.Group(al.labelsKey, - slog.String("ate.dev/actor_id", actorID), - slog.String("ate.dev/actor_template", actorTemplate), - slog.String("ate.dev/actor_namespace", actorNamespace), - ), - ) + var envelope map[string]any + + dec := json.NewDecoder(bytes.NewReader(lineBytes)) + dec.UseNumber() + + if unmarshalErr := dec.Decode(&m); unmarshalErr != nil { + envelope = map[string]any{ + "time": time.Now().Format(time.RFC3339Nano), + "message": string(lineBytes), + al.labelsKey: map[string]string{ + "ate.dev/actor_id": actorID, + "ate.dev/actor_template": actorTemplate, + "ate.dev/actor_namespace": actorNamespace, + }, + } } else { - al.parseAndLogContainerJSONLine(ctx, m, actorID, actorTemplate, actorNamespace) + if _, ok := m["time"]; !ok { + m["time"] = time.Now().Format(time.RFC3339Nano) + } + m[al.labelsKey] = map[string]string{ + "ate.dev/actor_id": actorID, + "ate.dev/actor_template": actorTemplate, + "ate.dev/actor_namespace": actorNamespace, + } + envelope = m + } + + if envBytes, err := json.Marshal(envelope); err == nil { + envBytes = append(envBytes, '\n') + _, _ = al.writer.Write(envBytes) } } @@ -98,42 +134,3 @@ func (al *ActorLogger) WrapContainerLogs(r io.Reader, actorID, actorTemplate, ac } } } - -func (al *ActorLogger) parseAndLogContainerJSONLine(ctx context.Context, m map[string]any, actorID, actorTemplate, actorNamespace string) { - msg := "" - if mMsg, ok := m["msg"].(string); ok { - msg = mMsg - } else if mMessage, ok := m["message"].(string); ok { - msg = mMessage - } - - level := slog.LevelInfo - if mLevel, ok := m["level"].(string); ok { - switch strings.ToLower(mLevel) { - case "debug": - level = slog.LevelDebug - case "info": - level = slog.LevelInfo - case "warn", "warning": - level = slog.LevelWarn - case "error": - level = slog.LevelError - } - } - - var attrs []slog.Attr - for k, v := range m { - if k == "msg" || k == "message" || k == "level" || k == "time" { - continue - } - attrs = append(attrs, slog.Any(k, v)) - } - - attrs = append(attrs, slog.Group(al.labelsKey, - slog.String("ate.dev/actor_id", actorID), - slog.String("ate.dev/actor_template", actorTemplate), - slog.String("ate.dev/actor_namespace", actorNamespace), - )) - - al.logger.LogAttrs(ctx, level, msg, attrs...) -} diff --git a/cmd/ateom-gvisor/logger_test.go b/cmd/ateom-gvisor/logger_test.go index 8a50083..36f6573 100644 --- a/cmd/ateom-gvisor/logger_test.go +++ b/cmd/ateom-gvisor/logger_test.go @@ -17,11 +17,9 @@ package main import ( "bytes" "encoding/json" - "log/slog" "strings" + "sync" "testing" - - "github.com/agent-substrate/substrate/internal/contextlogging" ) func TestWrapContainerLogs(t *testing.T) { @@ -29,9 +27,7 @@ func TestWrapContainerLogs(t *testing.T) { rdr := strings.NewReader(input) var buf bytes.Buffer - logger := slog.New(contextlogging.NewHandler(slog.NewJSONHandler(&buf, nil))) - - al := NewActorLogger(logger, false) + al := NewActorLogger(&buf, false) al.WrapContainerLogs(rdr, "act-1", "tmpl-1", "default") var m map[string]any @@ -39,11 +35,14 @@ func TestWrapContainerLogs(t *testing.T) { t.Fatalf("failed to parse JSON output: %v", err) } - if m["msg"] != "Test application log output" { - t.Errorf("got msg = %v, want 'Test application log output'", m["msg"]) + if m["message"] != "Test application log output" { + t.Errorf("got message = %v, want 'Test application log output'", m["message"]) } - if m["level"] != "INFO" { - t.Errorf("got level = %v, want 'INFO'", m["level"]) + if _, ok := m["level"]; ok { + t.Errorf("level should be absent for plain text logs (no guessing)") + } + if _, ok := m["actor_log"]; ok { + t.Errorf("actor_log should be absent for text logs") } labelsAny, ok := m[al.labelsKey] @@ -67,29 +66,39 @@ func TestWrapContainerLogs(t *testing.T) { } func TestWrapContainerLogs_JSONInput(t *testing.T) { - input := `{"level":"info","msg":"Started container","custom_attr":"value"}` + "\n" + // Include large 64-bit integer and pre-existing time field + input := `{"level":"info","msg":"Started container","custom_attr":"value","trace_id":1234567890123456789,"time":"2026-05-16T01:03:37Z"}` + "\n" rdr := strings.NewReader(input) var buf bytes.Buffer - logger := slog.New(contextlogging.NewHandler(slog.NewJSONHandler(&buf, nil))) - - al := NewActorLogger(logger, false) + al := NewActorLogger(&buf, false) al.WrapContainerLogs(rdr, "act-1", "tmpl-1", "default") + dec := json.NewDecoder(&buf) + dec.UseNumber() var m map[string]any - if err := json.Unmarshal(buf.Bytes(), &m); err != nil { + if err := dec.Decode(&m); err != nil { t.Fatalf("failed to parse JSON output: %v", err) } if m["msg"] != "Started container" { t.Errorf("got msg = %v, want 'Started container'", m["msg"]) } - if m["level"] != "INFO" { - t.Errorf("got level = %v, want 'INFO'", m["level"]) + if m["level"] != "info" { + t.Errorf("got level = %v, want 'info'", m["level"]) } if m["custom_attr"] != "value" { t.Errorf("got custom_attr = %v, want 'value'", m["custom_attr"]) } + if m["time"] != "2026-05-16T01:03:37Z" { + t.Errorf("got time = %v, want '2026-05-16T01:03:37Z' (pre-existing time should be preserved)", m["time"]) + } + if m["trace_id"] != json.Number("1234567890123456789") { + t.Errorf("got trace_id = %v, want json.Number('1234567890123456789') (large integer should be preserved exactly)", m["trace_id"]) + } + if _, ok := m["actor_log"]; ok { + t.Errorf("actor_log should be absent for flat JSON logs") + } labelsAny, ok := m[al.labelsKey] if !ok { @@ -104,3 +113,44 @@ func TestWrapContainerLogs_JSONInput(t *testing.T) { t.Errorf("got actor_id = %v, want 'act-1'", labels["ate.dev/actor_id"]) } } + +func TestSyncedWriter_Concurrency(t *testing.T) { + var buf bytes.Buffer + sw := &syncedWriter{w: &buf} + + const numWorkers = 10 + const writesPerWorker = 100 + var wg sync.WaitGroup + + wg.Add(numWorkers) + for i := 0; i < numWorkers; i++ { + go func(workerID int) { + defer wg.Done() + for j := 0; j < writesPerWorker; j++ { + line := []byte(strings.Repeat("a", 10) + "\n") + _, err := sw.Write(line) + if err != nil { + t.Errorf("write failed: %v", err) + } + } + }(i) + } + + wg.Wait() + + lines := strings.Split(buf.String(), "\n") + if len(lines) != numWorkers*writesPerWorker+1 { + t.Errorf("got %d lines, want %d", len(lines)-1, numWorkers*writesPerWorker) + } + for i, line := range lines { + if i == len(lines)-1 { + if line != "" { + t.Errorf("last line should be empty") + } + continue + } + if len(line) != 10 { + t.Errorf("line %d has length %d, want 10 (interleaved write detected?): %q", i, len(line), line) + } + } +} diff --git a/cmd/ateom-gvisor/main.go b/cmd/ateom-gvisor/main.go index cbc1fe9..91b5063 100644 --- a/cmd/ateom-gvisor/main.go +++ b/cmd/ateom-gvisor/main.go @@ -64,7 +64,8 @@ func do(ctx context.Context) error { ctx, cancel := context.WithCancel(ctx) defer cancel() - logger := slog.New(contextlogging.NewHandler(slog.NewJSONHandler(os.Stdout, nil))) + syncedWriter := &syncedWriter{w: os.Stdout} + logger := slog.New(contextlogging.NewHandler(slog.NewJSONHandler(syncedWriter, nil))) slog.SetDefault(logger) slog.InfoContext(ctx, "ateom booting") @@ -128,7 +129,7 @@ func do(ctx context.Context) error { return fmt.Errorf("while creating ateom-interior netns: %w", err) } - actorLogger := NewActorLogger(logger, metadata.OnGCE()) + actorLogger := NewActorLogger(syncedWriter, metadata.OnGCE()) ateomService := NewService(interiorNetNS, eth0LinkInfo, actorLogger) svr := grpc.NewServer( diff --git a/cmd/kubectl-ate/internal/cmd/logs_actors.go b/cmd/kubectl-ate/internal/cmd/logs_actors.go index d0f4aad..fad1ada 100644 --- a/cmd/kubectl-ate/internal/cmd/logs_actors.go +++ b/cmd/kubectl-ate/internal/cmd/logs_actors.go @@ -16,13 +16,13 @@ package cmd import ( "bufio" + "bytes" "context" "encoding/json" "errors" "fmt" "io" "os" - "sort" "strings" "sync" "time" @@ -39,7 +39,6 @@ import ( ) var followLogs bool -var rawOutput bool var logsActorsCmd = &cobra.Command{ Use: "actors ", @@ -51,7 +50,6 @@ var logsActorsCmd = &cobra.Command{ func init() { logsActorsCmd.Flags().BoolVarP(&followLogs, "follow", "f", false, "Specify if the logs should be streamed.") - logsActorsCmd.Flags().BoolVar(&rawOutput, "raw", false, "Output raw JSON log lines instead of pretty-printed format") logsCmd.AddCommand(logsActorsCmd) } @@ -82,7 +80,6 @@ type LogsActorRunner struct { stdout io.Writer stderr io.Writer follow bool - raw bool pollInterval time.Duration reconnectInterval time.Duration tickerInterval time.Duration @@ -136,7 +133,7 @@ func (r *LogsActorRunner) runOneShot(ctx context.Context, actorID string) error scanner.Buffer(buf, 1024*1024) // Support up to 1MB lines for scanner.Scan() { line := scanner.Text() - filterAndDisplayLogLine(line, actorID, r.stdout, r.raw) + filterAndDisplayLogLine(line, actorID, r.stdout) } if err := scanner.Err(); err != nil { return fmt.Errorf("error reading log stream: %w", err) @@ -214,7 +211,7 @@ func (r *LogsActorRunner) runFollow(ctx context.Context, actorID string) error { scanner.Buffer(buf, 1024*1024) // Support up to 1MB lines for scanner.Scan() { line := scanner.Text() - logTime, _ := filterAndDisplayLogLine(line, actorID, r.stdout, r.raw) + logTime, _ := filterAndDisplayLogLine(line, actorID, r.stdout) if !logTime.IsZero() { lastSeenTime = logTime } @@ -298,7 +295,6 @@ func runLogsActor(cmd *cobra.Command, args []string) error { stdout: os.Stdout, stderr: os.Stderr, follow: followLogs, - raw: rawOutput, pollInterval: 2 * time.Second, reconnectInterval: 1 * time.Second, tickerInterval: 2 * time.Second, @@ -307,9 +303,11 @@ func runLogsActor(cmd *cobra.Command, args []string) error { return runner.Run(ctx, actorID) } -func filterAndDisplayLogLine(line, targetActorID string, w io.Writer, raw bool) (time.Time, bool) { +func filterAndDisplayLogLine(line, targetActorID string, w io.Writer) (time.Time, bool) { var m map[string]any - if err := json.Unmarshal([]byte(line), &m); err != nil { + dec := json.NewDecoder(strings.NewReader(line)) + dec.UseNumber() + if err := dec.Decode(&m); err != nil { return time.Time{}, false } @@ -339,60 +337,34 @@ func filterAndDisplayLogLine(line, targetActorID string, w io.Writer, raw bool) return logTime, false } - if raw { - fmt.Fprintln(w, line) - return logTime, true - } - - timeStr := "" - if !logTime.IsZero() { - timeStr = logTime.Format("2006-01-02 15:04:05") - } else if tVal, ok := m["time"].(string); ok { - timeStr = tVal - } + delete(m, "logging.googleapis.com/labels") + delete(m, "labels") - levelStr := "INFO" - if lVal, ok := m["level"].(string); ok { - levelStr = strings.ToUpper(lVal) + timeVal, hasTime := m["time"] + if hasTime { + delete(m, "time") } - msgStr := "" - if mVal, ok := m["msg"].(string); ok { - msgStr = mVal - } else if mVal, ok := m["message"].(string); ok { - msgStr = mVal + var buf bytes.Buffer + enc := json.NewEncoder(&buf) + enc.SetEscapeHTML(false) + if err := enc.Encode(m); err != nil { + return logTime, false } - var extraParts []string - var extraKeys []string - for k := range m { - if k == "time" || k == "level" || k == "msg" || k == "message" || k == "logging.googleapis.com/labels" || k == "labels" { - continue - } - extraKeys = append(extraKeys, k) - } - sort.Strings(extraKeys) - for _, k := range extraKeys { - v := m[k] - if sVal, ok := v.(string); ok { - extraParts = append(extraParts, fmt.Sprintf("%s=%q", k, sVal)) + encodedStr := strings.TrimSpace(buf.String()) + if hasTime { + timeJSON, _ := json.Marshal(timeVal) + if encodedStr == "{}" { + fmt.Fprintf(w, `{"time":%s}`+"\n", string(timeJSON)) + } else if strings.HasPrefix(encodedStr, "{") { + fmt.Fprintf(w, `{"time":%s,%s`+"\n", string(timeJSON), encodedStr[1:]) } else { - if b, err := json.Marshal(v); err == nil { - extraParts = append(extraParts, fmt.Sprintf("%s=%s", k, string(b))) - } else { - extraParts = append(extraParts, fmt.Sprintf("%s=%v", k, v)) - } + fmt.Fprintln(w, encodedStr) } + } else { + fmt.Fprintln(w, encodedStr) } - extraStr := "" - if len(extraParts) > 0 { - extraStr = " [" + strings.Join(extraParts, " ") + "]" - } - - if timeStr != "" { - fmt.Fprintf(w, "[%s] ", timeStr) - } - fmt.Fprintf(w, "[%s] %s%s\n", levelStr, msgStr, extraStr) return logTime, true } diff --git a/cmd/kubectl-ate/internal/cmd/logs_actors_test.go b/cmd/kubectl-ate/internal/cmd/logs_actors_test.go index 00bcba0..afa2b18 100644 --- a/cmd/kubectl-ate/internal/cmd/logs_actors_test.go +++ b/cmd/kubectl-ate/internal/cmd/logs_actors_test.go @@ -36,61 +36,46 @@ func TestFilterAndDisplayLogLine(t *testing.T) { name string line string targetActorID string - raw bool wantMatched bool wantTime string wantOutput string }{ { - name: "matching actor, pretty printed with RFC3339Nano", + name: "matching actor, JSON log with RFC3339Nano", line: `{"time":"2026-05-16T01:03:38.602878302Z","level":"info","msg":"Count","logging.googleapis.com/labels":{"ate.dev/actor_id":"act-1"}}`, targetActorID: "act-1", - raw: false, wantMatched: true, wantTime: "2026-05-16T01:03:38.602878302Z", - wantOutput: `[2026-05-16 01:03:38] [INFO] Count`, + wantOutput: `{"time":"2026-05-16T01:03:38.602878302Z","level":"info","msg":"Count"}`, }, { - name: "matching actor, pretty printed with message key", - line: `{"time":"2026-05-16T01:03:38Z","level":"warn","message":"Hello","logging.googleapis.com/labels":{"ate.dev/actor_id":"act-1"}}`, + name: "matching actor, plain text log", + line: `{"time":"2026-05-16T01:03:38Z","message":"Hello","logging.googleapis.com/labels":{"ate.dev/actor_id":"act-1"}}`, targetActorID: "act-1", - raw: false, wantMatched: true, wantTime: "2026-05-16T01:03:38Z", - wantOutput: `[2026-05-16 01:03:38] [WARN] Hello`, + wantOutput: `{"time":"2026-05-16T01:03:38Z","message":"Hello"}`, }, { - name: "matching actor, pretty printed with no timestamp fallback", + name: "matching actor, JSON log with no timestamp fallback", line: `{"level":"error","msg":"Failed","logging.googleapis.com/labels":{"ate.dev/actor_id":"act-1"}}`, targetActorID: "act-1", - raw: false, wantMatched: true, wantTime: "", - wantOutput: `[ERROR] Failed`, - }, - { - name: "matching actor, raw output requested", - line: `{"time":"2026-05-16T01:03:38.602878302Z","level":"info","msg":"Count","logging.googleapis.com/labels":{"ate.dev/actor_id":"act-1"}}`, - targetActorID: "act-1", - raw: true, - wantMatched: true, - wantTime: "2026-05-16T01:03:38.602878302Z", - wantOutput: `{"time":"2026-05-16T01:03:38.602878302Z","level":"info","msg":"Count","logging.googleapis.com/labels":{"ate.dev/actor_id":"act-1"}}`, + wantOutput: `{"level":"error","msg":"Failed"}`, }, { name: "matching actor, fallback to standard labels key", line: `{"time":"2026-05-16T01:03:38.602878302Z","level":"info","msg":"Count","labels":{"ate.dev/actor_id":"act-1"}}`, targetActorID: "act-1", - raw: false, wantMatched: true, wantTime: "2026-05-16T01:03:38.602878302Z", - wantOutput: `[2026-05-16 01:03:38] [INFO] Count`, + wantOutput: `{"time":"2026-05-16T01:03:38.602878302Z","level":"info","msg":"Count"}`, }, { name: "non-matching actor", line: `{"time":"2026-05-16T01:03:38Z","message":"Hello world","logging.googleapis.com/labels":{"ate.dev/actor_id":"act-2"}}`, targetActorID: "act-1", - raw: false, wantMatched: false, wantTime: "2026-05-16T01:03:38Z", wantOutput: "", @@ -99,26 +84,40 @@ func TestFilterAndDisplayLogLine(t *testing.T) { name: "invalid json line", line: "not a json line", targetActorID: "act-1", - raw: false, wantMatched: false, wantTime: "", wantOutput: "", }, { - name: "matching actor, pretty printed with non-standard JSON fields sorted and appended", + name: "matching actor, flat JSON log", line: `{"time":"2026-05-16T01:03:38Z","level":"info","msg":"Hello","traceID":"abc-123","err":"timeout","logging.googleapis.com/labels":{"ate.dev/actor_id":"act-1"}}`, targetActorID: "act-1", - raw: false, wantMatched: true, wantTime: "2026-05-16T01:03:38Z", - wantOutput: `[2026-05-16 01:03:38] [INFO] Hello [err="timeout" traceID="abc-123"]`, + wantOutput: `{"time":"2026-05-16T01:03:38Z","err":"timeout","level":"info","msg":"Hello","traceID":"abc-123"}`, + }, + { + name: "matching actor, severity and message keys", + line: `{"time":"2026-05-16T01:03:38Z","severity":"error","message":"Disk full","custom_tag":"alert","logging.googleapis.com/labels":{"ate.dev/actor_id":"act-1"}}`, + targetActorID: "act-1", + wantMatched: true, + wantTime: "2026-05-16T01:03:38Z", + wantOutput: `{"time":"2026-05-16T01:03:38Z","custom_tag":"alert","message":"Disk full","severity":"error"}`, + }, + { + name: "matching actor, 2-field structured log without time", + line: `{"message":"login failed","code":401,"logging.googleapis.com/labels":{"ate.dev/actor_id":"act-1"}}`, + targetActorID: "act-1", + wantMatched: true, + wantTime: "", + wantOutput: `{"code":401,"message":"login failed"}`, }, } for _, tc := range tests { t.Run(tc.name, func(t *testing.T) { var buf bytes.Buffer - logTime, matched := filterAndDisplayLogLine(tc.line, tc.targetActorID, &buf, tc.raw) + logTime, matched := filterAndDisplayLogLine(tc.line, tc.targetActorID, &buf) if matched != tc.wantMatched { t.Errorf("got matched = %v, want %v", matched, tc.wantMatched) @@ -214,7 +213,6 @@ func TestLogsActorRunner_Run_OneShotSuccess(t *testing.T) { stdout: &stdout, stderr: &stderr, follow: false, - raw: false, } err := runner.Run(context.Background(), actorID) @@ -227,7 +225,7 @@ func TestLogsActorRunner_Run_OneShotSuccess(t *testing.T) { } gotOutput := strings.TrimSpace(stdout.String()) - wantOutput := `[2026-05-16 01:03:38] [INFO] Hello world` + wantOutput := `{"time":"2026-05-16T01:03:38Z","level":"info","msg":"Hello world"}` if gotOutput != wantOutput { t.Errorf("got stdout %q, want %q", gotOutput, wantOutput) } @@ -348,7 +346,6 @@ func TestLogsActorRunner_Run_Follow_SuspendedToRunning(t *testing.T) { stdout: &stdout, stderr: &stderr, follow: true, - raw: false, pollInterval: 1 * time.Millisecond, reconnectInterval: 1 * time.Millisecond, tickerInterval: 1 * time.Millisecond, @@ -370,7 +367,7 @@ func TestLogsActorRunner_Run_Follow_SuspendedToRunning(t *testing.T) { } gotStdout := strings.TrimSpace(stdout.String()) - wantStdout := `[2026-05-16 01:03:38] [INFO] Follow hello` + wantStdout := `{"time":"2026-05-16T01:03:38Z","level":"info","msg":"Follow hello"}` if gotStdout != wantStdout { t.Errorf("got stdout %q, want %q", gotStdout, wantStdout) } diff --git a/docs/observability.md b/docs/observability.md index 6725951..bc307d7 100644 --- a/docs/observability.md +++ b/docs/observability.md @@ -36,36 +36,27 @@ $ kubectl ate logs test Error: actor test is not currently running on any worker pod ``` -#### Example 2: Default Pretty-Printed Output -When an active actor is assigned to a worker pod, the CLI formats the log stream for easy reading: +#### Example 2: Default Clean JSON Lines Output +When an active actor is assigned to a worker pod, the CLI outputs clean, uniform JSON lines stripped of Substrate metadata, perfectly matching standard `kubectl logs` behavior: ```bash $ kubectl ate logs test -[INFO] Actor started -[2026-05-19 18:39:24] [INFO] Starting server on port 80 -[2026-05-19 18:39:24] [INFO] Count -[2026-05-19 18:39:34] [INFO] Count -[2026-05-19 18:39:44] [INFO] Count +{"time":"2026-05-22T21:49:15.23700774Z","message":"Actor started"} +{"time":"2026-05-22T21:49:15.23700774Z","level":"INFO","msg":"Starting server on port 80"} +{"time":"2026-05-22T21:49:15.255765354Z","count":0,"fshash":"mCY7G4S318ztOUojPTF2NA/W+ZSmWyr+T5K3udFuP50","level":"INFO","msg":"Count"} +{"time":"2026-05-22T21:49:25.263744806Z","count":1,"fshash":"mCY7G4S318ztOUojPTF2NA/W+ZSmWyr+T5K3udFuP50","level":"INFO","msg":"Count"} ``` -#### Example 3: Raw JSON Output (`--raw`) -To inspect the underlying structured JSON log entries, use the `--raw` flag. Note that during logging pipeline ingestion, the `ate.dev/` prefix is typically stripped from the label keys for cleaner indexing: - -```bash -$ kubectl ate logs test --raw -{"count":9,"fshash":"JiOzRUA5Ab+aro4YnhADSSMq8gUXhh/DMNSFzl75Q7c","level":"INFO","logging.googleapis.com/labels":{"actor_id":"test","actor_namespace":"ate-demo-counter","actor_template":"counter"},"msg":"Count","time":"2026-05-19T18:40:54.957798659Z"} -``` - -#### Example 4: Streaming/Live Logs (`--follow` or `-f`) +#### Example 3: Streaming/Live Logs (`--follow` or `-f`) To stream actor logs in real-time, append the `--follow` (or `-f`) flag. The CLI is fully actor-aware, automatically resuming the stream if the actor is suspended or migrates to a different worker pod: ```bash $ kubectl ate logs test -f Actor is currently running on pod ate-demo-counter/counter-deployment-d8f99-m7d96 -[2026-05-19 18:39:24] [INFO] Count -[2026-05-19 18:39:34] [INFO] Count +{"time":"2026-05-22T21:49:15.255765354Z","count":0,"fshash":"mCY7...","level":"INFO","msg":"Count"} +{"time":"2026-05-22T21:49:25.263744806Z","count":1,"fshash":"mCY7...","level":"INFO","msg":"Count"} Actor is currently running on pod ate-demo-counter/counter-deployment-ab123-x4y5z -[2026-05-19 18:40:02] [INFO] Count +{"time":"2026-05-22T21:50:02.123456789Z","count":2,"fshash":"mCY7...","level":"INFO","msg":"Count"} ```