|
| 1 | +/* |
| 2 | + Copyright The containerd Authors. |
| 3 | +
|
| 4 | + Licensed under the Apache License, Version 2.0 (the "License"); |
| 5 | + you may not use this file except in compliance with the License. |
| 6 | + You may obtain a copy of the License at |
| 7 | +
|
| 8 | + http://www.apache.org/licenses/LICENSE-2.0 |
| 9 | +
|
| 10 | + Unless required by applicable law or agreed to in writing, software |
| 11 | + distributed under the License is distributed on an "AS IS" BASIS, |
| 12 | + WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. |
| 13 | + See the License for the specific language governing permissions and |
| 14 | + limitations under the License. |
| 15 | +*/ |
| 16 | + |
| 17 | +// Package logging provides unified structured logging utilities for the |
| 18 | +// shim and vminitd components. |
| 19 | +package logging |
| 20 | + |
| 21 | +import ( |
| 22 | + "bufio" |
| 23 | + "context" |
| 24 | + "encoding/json" |
| 25 | + "io" |
| 26 | + "log/slog" |
| 27 | + "os" |
| 28 | + "strings" |
| 29 | + "time" |
| 30 | + |
| 31 | + "github.com/containerd/log" |
| 32 | +) |
| 33 | + |
| 34 | +// SetupShimLog configures slog-based logging for the shim process. |
| 35 | +// It opens the platform-specific log output (FIFO on Unix, named pipe |
| 36 | +// on Windows), then creates a slog TextHandler and sets it as the |
| 37 | +// default logger with a "component=shim" attribute. |
| 38 | +// |
| 39 | +// The base handler (without component) is stored for use by |
| 40 | +// [ForwardConsoleLogs] so that forwarded records carry their own |
| 41 | +// component rather than inheriting "shim". |
| 42 | +// |
| 43 | +// For the short-lived start and delete actions, only [log.UseSlog] is |
| 44 | +// called to route logrus through slog; the log output is not opened. |
| 45 | +func SetupShimLog() { |
| 46 | + log.UseSlog() |
| 47 | + |
| 48 | + var ( |
| 49 | + debug bool |
| 50 | + ns string |
| 51 | + id string |
| 52 | + attrs []slog.Attr |
| 53 | + ) |
| 54 | + args := os.Args[1:] |
| 55 | + for i := 0; i < len(args); i++ { |
| 56 | + switch args[i] { |
| 57 | + case "start", "delete": |
| 58 | + return |
| 59 | + case "-debug": |
| 60 | + debug = true |
| 61 | + case "-namespace": |
| 62 | + if i+1 < len(args) { |
| 63 | + i++ |
| 64 | + ns = args[i] |
| 65 | + attrs = append(attrs, slog.String("ns", ns)) |
| 66 | + } |
| 67 | + case "-id": |
| 68 | + if i+1 < len(args) { |
| 69 | + i++ |
| 70 | + id = args[i] |
| 71 | + attrs = append(attrs, slog.String("id", id)) |
| 72 | + } |
| 73 | + } |
| 74 | + } |
| 75 | + |
| 76 | + w := openShimLog(ns, id) |
| 77 | + |
| 78 | + var level slog.LevelVar |
| 79 | + if debug { |
| 80 | + level.Set(slog.LevelDebug) |
| 81 | + log.SetLevel("debug") //nolint:errcheck |
| 82 | + } |
| 83 | + |
| 84 | + handler := slog.NewTextHandler(w, &slog.HandlerOptions{Level: &level}).WithAttrs(attrs) |
| 85 | + SetBaseHandler(handler) |
| 86 | + slog.SetDefault(slog.New(handler).With("component", "shim")) |
| 87 | +} |
| 88 | + |
| 89 | +// baseHandler is the slog handler used by ForwardConsoleLogs to emit |
| 90 | +// records without the caller's pre-applied attributes (e.g. component=shim). |
| 91 | +var baseHandler slog.Handler |
| 92 | + |
| 93 | +// SetBaseHandler stores the base handler for use by ForwardConsoleLogs. |
| 94 | +// This should be called before any console forwarding starts, typically |
| 95 | +// during init with the handler before any .With() attributes are applied. |
| 96 | +func SetBaseHandler(h slog.Handler) { |
| 97 | + baseHandler = h |
| 98 | +} |
| 99 | + |
| 100 | +// consoleHandler returns the handler that ForwardConsoleLogs should use. |
| 101 | +// It prefers the base handler set via SetBaseHandler, falling back to |
| 102 | +// the default slog handler. |
| 103 | +func consoleHandler() slog.Handler { |
| 104 | + if baseHandler != nil { |
| 105 | + return baseHandler |
| 106 | + } |
| 107 | + return slog.Default().Handler() |
| 108 | +} |
| 109 | + |
| 110 | +// ForwardConsoleLogs reads lines from r and re-emits them as structured |
| 111 | +// log entries through the base [slog.Handler] set via [SetBaseHandler]. |
| 112 | +// |
| 113 | +// Lines that are valid JSON objects (emitted by vminitd's JSON slog handler) |
| 114 | +// are parsed and re-emitted preserving the original level, message, |
| 115 | +// and attributes. All other lines are treated as kernel messages and emitted |
| 116 | +// at INFO level with component=kmsg. |
| 117 | +// |
| 118 | +// The base handler is used directly (rather than the default logger) so that |
| 119 | +// pre-applied attributes such as component=shim are not added to forwarded |
| 120 | +// records, which carry their own component. |
| 121 | +// |
| 122 | +// If raw is non-nil, every line is also written there verbatim (useful for |
| 123 | +// tests that need the unprocessed console output). |
| 124 | +func ForwardConsoleLogs(r io.Reader, raw io.Writer) { |
| 125 | + scanner := bufio.NewScanner(r) |
| 126 | + for scanner.Scan() { |
| 127 | + line := scanner.Text() |
| 128 | + |
| 129 | + if raw != nil { |
| 130 | + raw.Write([]byte(line)) |
| 131 | + raw.Write([]byte("\n")) |
| 132 | + } |
| 133 | + |
| 134 | + if line == "" { |
| 135 | + continue |
| 136 | + } |
| 137 | + |
| 138 | + if strings.HasPrefix(line, "{") { |
| 139 | + if forwardJSONLog(line) { |
| 140 | + continue |
| 141 | + } |
| 142 | + } |
| 143 | + |
| 144 | + // Kernel message — parse optional "[ 1.234567] " timestamp prefix. |
| 145 | + msg := line |
| 146 | + attrs := []slog.Attr{slog.String("component", "kmsg")} |
| 147 | + if after, ktime, ok := parseKernelTimestamp(line); ok { |
| 148 | + msg = after |
| 149 | + attrs = append(attrs, slog.String("ktime", ktime)) |
| 150 | + } |
| 151 | + record := slog.NewRecord(time.Now(), slog.LevelInfo, msg, 0) |
| 152 | + record.AddAttrs(attrs...) |
| 153 | + handler := consoleHandler() |
| 154 | + if handler.Enabled(context.Background(), slog.LevelInfo) { |
| 155 | + handler.Handle(context.Background(), record) //nolint:errcheck |
| 156 | + } |
| 157 | + } |
| 158 | + if err := scanner.Err(); err != nil { |
| 159 | + record := slog.NewRecord(time.Now(), slog.LevelWarn, "console log reader stopped", 0) |
| 160 | + record.AddAttrs(slog.String("component", "kmsg"), slog.Any("error", err)) |
| 161 | + handler := consoleHandler() |
| 162 | + if handler.Enabled(context.Background(), slog.LevelWarn) { |
| 163 | + handler.Handle(context.Background(), record) //nolint:errcheck |
| 164 | + } |
| 165 | + } |
| 166 | +} |
| 167 | + |
| 168 | +// forwardJSONLog attempts to parse line as a JSON slog record and emit it |
| 169 | +// through the console handler. Returns true if the line was handled. |
| 170 | +func forwardJSONLog(line string) bool { |
| 171 | + var fields map[string]json.RawMessage |
| 172 | + if err := json.Unmarshal([]byte(line), &fields); err != nil { |
| 173 | + return false |
| 174 | + } |
| 175 | + |
| 176 | + // A valid vminitd log must at least have "msg". |
| 177 | + rawMsg, ok := fields["msg"] |
| 178 | + if !ok { |
| 179 | + return false |
| 180 | + } |
| 181 | + |
| 182 | + var msg string |
| 183 | + if err := json.Unmarshal(rawMsg, &msg); err != nil { |
| 184 | + return false |
| 185 | + } |
| 186 | + delete(fields, "msg") |
| 187 | + |
| 188 | + var level slog.Level |
| 189 | + if raw, ok := fields["level"]; ok { |
| 190 | + var s string |
| 191 | + if err := json.Unmarshal(raw, &s); err == nil { |
| 192 | + level.UnmarshalText([]byte(s)) //nolint:errcheck |
| 193 | + } |
| 194 | + delete(fields, "level") |
| 195 | + } |
| 196 | + |
| 197 | + // Discard the VM-side timestamp — the guest clock is not |
| 198 | + // synchronised and typically reads as epoch. |
| 199 | + delete(fields, "time") |
| 200 | + t := time.Now() |
| 201 | + |
| 202 | + handler := consoleHandler() |
| 203 | + if !handler.Enabled(context.Background(), level) { |
| 204 | + return true |
| 205 | + } |
| 206 | + |
| 207 | + record := slog.NewRecord(t, level, msg, 0) |
| 208 | + for k, v := range fields { |
| 209 | + var val any |
| 210 | + if err := json.Unmarshal(v, &val); err == nil { |
| 211 | + record.AddAttrs(slog.Any(k, val)) |
| 212 | + } |
| 213 | + } |
| 214 | + |
| 215 | + handler.Handle(context.Background(), record) //nolint:errcheck |
| 216 | + return true |
| 217 | +} |
| 218 | + |
| 219 | +// parseKernelTimestamp extracts the "[ seconds.usecs] " prefix from a |
| 220 | +// kernel log line. Returns the message after the prefix, the timestamp |
| 221 | +// string, and whether a timestamp was found. |
| 222 | +func parseKernelTimestamp(line string) (msg, ktime string, ok bool) { |
| 223 | + if len(line) < 3 || line[0] != '[' { |
| 224 | + return "", "", false |
| 225 | + } |
| 226 | + end := strings.IndexByte(line, ']') |
| 227 | + if end < 0 { |
| 228 | + return "", "", false |
| 229 | + } |
| 230 | + ktime = strings.TrimSpace(line[1:end]) |
| 231 | + msg = line[end+1:] |
| 232 | + if len(msg) > 0 && msg[0] == ' ' { |
| 233 | + msg = msg[1:] |
| 234 | + } |
| 235 | + return msg, ktime, true |
| 236 | +} |
0 commit comments