1// Package telemetry records what 012 spends its time on, as structured2// events written with log/slog. It is off unless a destination is given:3// a JSON log file (012 --log path, or O12_LOG), one line per event that4// DuckDB or an OpenTelemetry Collector's filelog receiver can read,5// and/or an OTLP/HTTP endpoint (012 --otlp URL, or6// OTEL_EXPORTER_OTLP_ENDPOINT) that gets the events as logs, spans as7// traces and frame summaries as metrics. Stdout belongs to the terminal8// UI. See docs/contributing/observability.md.9//10// Events carry sizes, counts and durations only: never cell contents,11// file contents or secrets.12//13// The API is small on purpose, so call sites stay few and backends can14// change behind it without touching them.15package telemetry1617import (18 "context"19 "io"20 "log/slog"21 "os"22 "runtime"23 "sync"24 "sync/atomic"25 "time"26)2728// on is read by every call site, so being off costs one atomic load.29var on atomic.Bool3031var (32 mu sync.Mutex33 logger = slog.New(slog.DiscardHandler)34 closer io.Closer35 exp *exporter // nil unless OTLP is on36)3738// Config says where events go.39type Config struct {40 // LogPath is the JSON log file, appended to. Empty (and no OTLP)41 // turns telemetry off.42 LogPath string43 // Level is the least severe level logged; Info by default. Debug adds44 // an event for every frame and every command.45 Level slog.Level46 // Version is 012's version or commit, added to the start event and47 // sent as the OTLP service.version.48 Version string49 // OTLP sends events to an OpenTelemetry endpoint too, or instead.50 OTLP OTLPConfig51}5253// ConfigFromEnv reads O12_LOG, O12_LOG_LEVEL (debug, info, warn) and the54// standard OTEL_* variables described at OTLPConfig.55func ConfigFromEnv() Config {56 c := Config{LogPath: os.Getenv("O12_LOG"), OTLP: otlpFromEnv()}57 c.Level.UnmarshalText([]byte(os.Getenv("O12_LOG_LEVEL")))58 return c59}6061// Setup starts recording as c says. The returned function flushes and62// closes the log and sends what OTLP has queued; call it on exit.63func Setup(c Config) (func() error, error) {64 u := c.OTLP.urls()65 if c.LogPath == "" && !u.any() {66 return func() error { return nil }, nil67 }68 var w io.Writer69 if c.LogPath != "" {70 f, err := os.OpenFile(c.LogPath, os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0o600)71 if err != nil {72 return nil, err73 }74 w = f75 }76 var e *exporter77 if u.any() {78 e = newExporter(c.OTLP, c.Version)79 }80 start(w, e, c)81 Logger().Info("start", "event", "start", "version", c.Version, "go", runtime.Version(), "os", runtime.GOOS, "arch", runtime.GOARCH,82 "cpus", runtime.NumCPU(), "pid", os.Getpid(), "file", w != nil, "otlp", e != nil)83 return Close, nil84}8586// start sends events to w and e, either of which may be nil; tests use87// it with a buffer.88func start(w io.Writer, e *exporter, c Config) {89 mu.Lock()90 defer mu.Unlock()91 var hs []slog.Handler92 if w != nil {93 // OTLP carries the service in its resource instead.94 hs = append(hs, slog.NewJSONHandler(w, &slog.HandlerOptions{Level: c.Level}).95 WithAttrs([]slog.Attr{slog.String("service", "012")}))96 }97 if e != nil && e.urls.logs != "" {98 hs = append(hs, &otlpHandler{e: e, level: c.Level})99 }100 switch len(hs) {101 case 0:102 logger = slog.New(slog.DiscardHandler)103 case 1:104 logger = slog.New(hs[0])105 default:106 logger = slog.New(slog.NewMultiHandler(hs...))107 }108 slog.SetDefault(logger)109 closer = nil110 if cl, ok := w.(io.Closer); ok {111 closer = cl112 }113 exp = e114 frames.reset(time.Now())115 on.Store(true)116}117118// Close stops recording, sends what OTLP has queued (waiting at most119// about one request timeout) and closes the log file.120func Close() error {121 mu.Lock()122 if !on.Load() {123 mu.Unlock()124 return nil125 }126 e, l, cl := exp, logger, closer127 if e != nil {128 // How OTLP fared so far, for the file log (and the collector).129 sent, dropped, failed := e.counts()130 attrs := []slog.Attr{slog.String("event", "otlp")}131 for i, name := range signalNames {132 attrs = append(attrs, slog.Group(name, "sent", sent[i], "dropped", dropped[i], "failed", failed[i]))133 }134 l.LogAttrs(context.Background(), slog.LevelInfo, "otlp", attrs...)135 }136 on.Store(false)137 logger = slog.New(slog.DiscardHandler)138 slog.SetDefault(logger)139 exp, closer = nil, nil140 mu.Unlock()141 if e != nil {142 e.shutdown()143 }144 if cl != nil {145 return cl.Close()146 }147 return nil148}149150// Enabled reports whether events are being recorded.151func Enabled() bool { return on.Load() }152153// Logger is the event logger; it discards everything while off.154func Logger() *slog.Logger {155 mu.Lock()156 defer mu.Unlock()157 return logger158}159160// Debug logs a finished operation at Debug level, for events too161// frequent to keep by default (and to send as spans).162func Debug(name string, d time.Duration, attrs ...slog.Attr) {163 if !on.Load() {164 return165 }166 emit(slog.LevelDebug, name, d, attrs, spanIDs{})167}168169// current is the logger and the OTLP exporter (nil unless OTLP is on).170func current() (*slog.Logger, *exporter) {171 mu.Lock()172 defer mu.Unlock()173 return logger, exp174}175176// emit logs an event that took d and ended now. With ids set it is a177// span: its log record carries the ids, and with OTLP on it is also sent178// as a span and a sample of the operation histogram. attrs is not kept.179func emit(level slog.Level, name string, d time.Duration, attrs []slog.Attr, ids spanIDs) {180 l, e := current()181 span := !ids.span.IsZero()182 if span && e != nil {183 end := time.Now()184 e.span(name, end.Add(-d), end, level >= slog.LevelWarn, attrs, ids)185 }186 ctx := context.Background()187 if !l.Enabled(ctx, level) {188 return189 }190 all := make([]slog.Attr, 0, len(attrs)+5)191 all = append(all, slog.String("event", name), slog.Float64("dur_ms", ms(d)))192 if span {193 all = idAttrs(all, ids)194 if e != nil && e.urls.logs != "" { // the OTLP log handler's195 ctx = context.WithValue(ctx, spanKey{}, ids)196 }197 }198 l.LogAttrs(ctx, level, name, append(all, attrs...)...)199}200201func ms(d time.Duration) float64 { return float64(d.Microseconds()) / 1000 }