From 0aefe599c90507fe87793bb88d19bb83bfafe934 Mon Sep 17 00:00:00 2001 From: Paul Lorenz Date: Mon, 1 Jun 2026 10:10:18 -0400 Subject: [PATCH] Install slog and route agent log-level callbacks through common/logging. Fixes #3910 - adds BuildPrettyHandler and BuildHandlerForFormat in common/logging: pretty output wraps the hand-rolled logging.PrettyHandler (a direct port of pfxlog's; df/dl was dropped after review found level-label gaps, so there is no github.com/michaelquigley/df dependency) in the AsyncHandler chain; the format-aware builder picks pretty / json / text by --log-formatter so default look matches pre-slog - adds BuildTextHandler so --log-formatter=text emits logrus-TextFormatter- style key=value output (level=info msg=...) via a slog TextHandler rather than the colored pretty handler, restoring the pre-slog meaning of text - adds logging.Fatal: a slog-world fatal (slog provides none) that emits at LevelFatal durably via SyncEmit, then exits, so hard-exit paths do not lose the record to the async queue; converts the controller and router startup hard-exit sites from Error+os.Exit / Error+panic to it, dropping the router's startup panic - rewires agentlog.DefaultLogLevelCallbacks onto common/logging: SetLogLevel drives logging.SetGlobalLevel (lockstep slog + logrus), SetChannelLogLevel and ClearChannelLogLevel drive SetNamedLevel / ClearNamedLevel; per-channel overrides become slog-only per design - adds agentToSlog mapping across the seven canonical levels with an Info fallback for forward-compat - ziti/run Options.PreRun and ziti/tunnel rootPreRun build the slog handler chain via logging.BuildHandlerForFormat and call Install; --verbose seeds the initial level instead of mutating logrus directly; AsyncOptions flags exposed via logging.AddFlags on each persistent flag set - hardens the run command's logging flags: PreRun reads --verbose / --log-formatter across the command chain so they are honored at either the alias-parent (ziti controller run) or child position, and the ziti controller / ziti router alias parents skip their legacy pfxlog/logrus PersistentPreRun setup for the run subcommand (which installs the slog chain itself), keeping it for sibling subcommands - adds Phase 7 acceptance tests in common/agentlog: TestInstallInvariant covers Out=io.Discard, noop formatter, ReportCaller, and the lockstep level mirror after Install; TestEndToEnd_AgentSetLogLevel walks the agent set-log-level path end to end across bridged-logrus and direct-slog routes; TestPerChannelOverride_AppliesToSlogOnly_NotPfxlog confirms the design's slog-only channel semantics - adds Fatal/Panic durability subprocess tests in common/logging that fork the test binary, Install the production handler chain, then call logrus.Fatal / logrus.Panic and assert the records reach stderr before exit/panic; proves the bridge's SyncEmit path flushes before os.Exit - adds doc/logging.md developer note covering how to write a slog line, channel-naming convention, the no-Warn/Error-in-hot-paths rule, the operator surface, the migration checklist, AsyncOptions tunables, and what's deliberately deferred - adds doc/design/slog-conversion-plan.md with the code-grounded per-package channel inventory, the sdk-golang embedder-injection pattern, conversion order with deep analysis for the first four chunks, and cross-repo coordination notes --- CHANGELOG.md | 74 +++- common/agentlog/callbacks.go | 52 ++- common/agentlog/callbacks_test.go | 124 +++++++ common/agentlog/e2e_test.go | 185 ++++++++++ common/logging/bridge.go | 25 ++ common/logging/bridge_test.go | 39 +++ common/logging/fatal_panic_test.go | 178 ++++++++++ common/logging/format.go | 62 ++++ common/logging/format_test.go | 94 ++++++ common/logging/pretty.go | 302 +++++++++++++++++ common/logging/pretty_test.go | 238 +++++++++++++ doc/design/logging-refactor-progress.md | 9 + doc/design/logging-refactor.md | 75 ++--- doc/design/slog-conversion-plan.md | 430 ++++++++++++++++++++++++ doc/logging.md | 171 ++++++++++ ziti/cmd/cmd.go | 16 + ziti/run/root.go | 61 +++- ziti/run/run_controller.go | 47 ++- ziti/run/run_router.go | 8 +- ziti/tunnel/root.go | 25 +- 20 files changed, 2115 insertions(+), 100 deletions(-) create mode 100644 common/agentlog/callbacks_test.go create mode 100644 common/agentlog/e2e_test.go create mode 100644 common/logging/fatal_panic_test.go create mode 100644 common/logging/pretty.go create mode 100644 common/logging/pretty_test.go create mode 100644 doc/design/slog-conversion-plan.md create mode 100644 doc/logging.md diff --git a/CHANGELOG.md b/CHANGELOG.md index 460f650c3..6c7e557df 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -9,6 +9,7 @@ * [Router Configs](#router-configs) - Allow routers to have a list of associated configs * [Multiple LAN Interfaces for tproxy](#multiple-lan-interfaces-for-tproxy) - `lanIf` now accepts a single interface or a list of interfaces * [Multiple Resolver Addresses for tproxy](#multiple-resolver-addresses-for-tproxy) - `resolver` now accepts a single address or a list of addresses +* [Logging Now Uses slog with an Async Handler](#logging-now-uses-slog-with-an-async-handler) - Logging moves to Go's `log/slog` behind an asynchronous sink; output is unchanged by default, with new flags to tune buffering ## Cluster Quorum Recovery @@ -196,10 +197,65 @@ across interfaces. Existing single-address configs are unchanged. - udp://192.168.10.1:53 ``` +## Logging Now Uses slog with an Async Handler + +The controller, router, and `ziti tunnel` now log through Go's standard +`log/slog` library behind a single asynchronous sink. By default the output is +unchanged - the same human-readable format as before - so no configuration +change is required. Existing `pfxlog`/`logrus` log statements continue to work; +they are bridged into the new sink rather than rewritten, so the migration to +slog is gradual and nothing is lost in the meantime. + +The motivation is performance under load. Previously every log call contended on +a single process-wide formatter-plus-writer mutex, which could block many +goroutines at once. Writing is now handed to a background goroutine, off the hot +path of the code doing the logging. + +### Asynchronous writes and dropped records + +Because writes are buffered through a bounded queue, behavior under saturation +is the one change worth knowing about: + +* Records at or above a configurable block threshold (default `warn`) block the + caller until there is room, so warnings, errors, and fatal messages are never + silently dropped. +* Lower-priority records (`info`, `debug`, `trace`) are dropped when the queue is + full instead of blocking. Whenever drops occur, a summary line is emitted + periodically reporting how many records were dropped per level, so the loss is + always visible in the logs. + +Under normal load nothing is dropped; this only engages when log volume outruns +the writer. + +### New CLI flags + +`ziti controller run`, `ziti router run`, and `ziti tunnel` gain three optional +flags to tune the async sink. All have sensible defaults, so leaving them unset +preserves current behavior: + +* `--log-queue-size` (default `4096`) - capacity of the async log queue. +* `--log-block-threshold` (default `warn`) - lowest level that blocks rather than + dropping under saturation (`panic|fatal|error|warn|info|debug|trace`). +* `--log-summary-interval` (default `5s`) - how often the dropped-record summary + line is emitted. + +The existing `--log-formatter` flag is unchanged: `pfxlog` (default), `json` +(unchanged JSON shape), and `text` (logrus-style `key=value`). + +### Per-channel log levels are slog-only + +`ziti agent set-channel-log-level ` now adjusts only code that has +been migrated to the new slog loggers. Call sites still using `pfxlog.Logger()` +or `pfxlog.ChannelLogger(...)` continue to follow the global level, so because +most call sites are not yet migrated, per-channel overrides have limited reach +today and expand as packages are converted. The global `ziti agent set-log-level +` still affects everything. + ## Component Updates and Bug Fixes -* github.com/openziti/foundation/v2: [v2.0.91 -> v2.0.92](https://github.com/openziti/foundation/compare/v2.0.91...v2.0.92) -* github.com/openziti/identity: [v1.0.129 -> v1.0.130](https://github.com/openziti/identity/compare/v1.0.129...v1.0.130) +* github.com/openziti/edge-api: [v0.31.0 -> v0.31.1](https://github.com/openziti/edge-api/compare/v0.31.0...v0.31.1) +* github.com/openziti/foundation/v2: [v2.0.91 -> v2.0.95](https://github.com/openziti/foundation/compare/v2.0.91...v2.0.95) +* github.com/openziti/identity: [v1.0.129 -> v1.0.133](https://github.com/openziti/identity/compare/v1.0.129...v1.0.133) * github.com/openziti/sdk-golang: [v1.7.0 -> v1.8.0](https://github.com/openziti/sdk-golang/compare/v1.7.0...v1.8.0) * [Issue #927](https://github.com/openziti/sdk-golang/issues/927) - Apply exponential backoff to auth retry attempts * [Issue #926](https://github.com/openziti/sdk-golang/issues/926) - Refresh OIDC token using a window to avoid race conditions and herding @@ -207,13 +263,25 @@ across interfaces. Existing single-address configs are unchanged. * [Issue #924](https://github.com/openziti/sdk-golang/issues/924) - Make controller http timeout configurable, with a default of 30s * [Issue #932](https://github.com/openziti/sdk-golang/issues/932) - API Session Certificate chain is not preserved +* github.com/openziti/secretstream: [v0.1.49 -> v0.1.51](https://github.com/openziti/secretstream/compare/v0.1.49...v0.1.51) +* github.com/openziti/transport/v2: [v2.0.215 -> v2.0.216](https://github.com/openziti/transport/compare/v2.0.215...v2.0.216) * github.com/openziti/ziti/v2: [v2.0.0 -> v2.1.0](https://github.com/openziti/ziti/compare/v2.0.0...v2.1.0) + * [Issue #3910](https://github.com/openziti/ziti/issues/3910) - Install slog and route agent log-level callbacks through common/logging + * [Issue #3927](https://github.com/openziti/ziti/issues/3927) - Router does not enforce api-session or identity revocations on live connections; revoked OIDC sessions keep dialing/hosting until access-token expiry + * [Issue #3906](https://github.com/openziti/ziti/issues/3906) - Add named-logger registry, logrus bridge, and pfxlog-shape JSON + * [Issue #3904](https://github.com/openziti/ziti/issues/3904) - Add slog AsyncHandler in preparation for moving to slog for logging + * [Issue #3902](https://github.com/openziti/ziti/issues/3902) - Add agent IPC capability discovery and channel-based log-level commands + * [Issue #3894](https://github.com/openziti/ziti/issues/3894) - Consolidate duplicated agent channel-upgrade code into common/agent + * [Issue #3893](https://github.com/openziti/ziti/issues/3893) - Import openziti/agent library into common/agent + * [Issue #3952](https://github.com/openziti/ziti/issues/3952) - externalIdClaim on CA returns HTTP 500 with empty body for most matcher/parser combinations + * [Issue #3780](https://github.com/openziti/ziti/issues/3780) - Add configs field to routers * [Issue #1593](https://github.com/openziti/ziti/issues/1593) - Expanded attribute query support in management API; add policy attribute support and usage count * [Issue #3867](https://github.com/openziti/ziti/issues/3867) - Tunneler skips iptables rules for services sharing an intercept hostname * [Issue #3949](https://github.com/openziti/ziti/issues/3949) - DeleteById swallows errors when firing change events * [Issue #3945](https://github.com/openziti/ziti/issues/3945) - Increase certificate serial number namespace to 159 bits * [Issue #3942](https://github.com/openziti/ziti/issues/3942) - Prep for channel v5: bind handler invocation, send priorities * [Issue #3938](https://github.com/openziti/ziti/issues/3938) - Carry the link id in a link header instead of only in the channel identity token + * [Issue #3908](https://github.com/openziti/ziti/issues/3908) - Router posture-data updates don't revoke SDK-hosted xgress circuits or hosted terminators * [Issue #3914](https://github.com/openziti/ziti/issues/3914) - ziti login fails with oidc + wildcard certs * [Issue #3891](https://github.com/openziti/ziti/issues/3891) - oidc auth fails with wildcard server-cert SANs * [Issue #3744](https://github.com/openziti/ziti/issues/3744) - Add a target field to config type @@ -221,5 +289,3 @@ across interfaces. Existing single-address configs are unchanged. * [Issue #3849](https://github.com/openziti/ziti/issues/3849) - Add a recover mechanism for when a controller cluster can't form a quorum * [Issue #3972](https://github.com/openziti/ziti/issues/3972) - Support multiple LAN interfaces for tproxy mode * [Issue #3988](https://github.com/openziti/ziti/issues/3988) - Support multiple resolver addresses for tproxy mode - - diff --git a/common/agentlog/callbacks.go b/common/agentlog/callbacks.go index f9d3411a6..8b6c02991 100644 --- a/common/agentlog/callbacks.go +++ b/common/agentlog/callbacks.go @@ -20,31 +20,55 @@ package agentlog import ( - "github.com/michaelquigley/pfxlog" + "log/slog" + "github.com/openziti/ziti/v2/common/agent" - "github.com/sirupsen/logrus" + "github.com/openziti/ziti/v2/common/logging" ) // DefaultLogLevelCallbacks returns the agent log-level callbacks that drive -// logrus (global level) and pfxlog (per-channel overrides), matching the -// behavior of the legacy framed log-level handlers. The agent LogLevel enum is -// ordered to match logrus.Level, so the conversion is a direct cast. +// the common/logging registry. The global-level callback goes through +// logging.SetGlobalLevel, which moves slog and logrus.StandardLogger in +// lockstep; the channel callbacks drive logging.SetNamedLevel / +// logging.ClearNamedLevel, which apply slog-side only. Call sites that +// haven't migrated to logging.For(name) stay at the global level, which +// matches the design's migration carrot ("convert your package to slog to +// gain per-channel debug overrides"). func DefaultLogLevelCallbacks() agent.LogLevelCallbacks { return agent.LogLevelCallbacks{ SetLogLevel: func(level agent.LogLevel) { - logrus.SetLevel(logrus.Level(level)) + logging.SetGlobalLevel(agentToSlog(level)) }, SetChannelLogLevel: func(channel string, level agent.LogLevel) { - pfxlog.GlobalConfig(func(options *pfxlog.Options) *pfxlog.Options { - options.SetChannelLogLevel(channel, logrus.Level(level)) - return options - }) + logging.SetNamedLevel(channel, agentToSlog(level)) }, ClearChannelLogLevel: func(channel string) { - pfxlog.GlobalConfig(func(options *pfxlog.Options) *pfxlog.Options { - options.ClearChannelLogLevel(channel) - return options - }) + logging.ClearNamedLevel(channel) }, } } + +// agentToSlog converts the agent's transport-neutral LogLevel into the +// equivalent slog.Level. The agent enum is finite and process-stable; an +// unrecognised value falls back to slog.LevelInfo so a future enum addition +// can't accidentally silence logging entirely. +func agentToSlog(level agent.LogLevel) slog.Level { + switch level { + case agent.PanicLevel: + return logging.LevelPanic + case agent.FatalLevel: + return logging.LevelFatal + case agent.ErrorLevel: + return slog.LevelError + case agent.WarnLevel: + return slog.LevelWarn + case agent.InfoLevel: + return slog.LevelInfo + case agent.DebugLevel: + return slog.LevelDebug + case agent.TraceLevel: + return logging.LevelTrace + default: + return slog.LevelInfo + } +} diff --git a/common/agentlog/callbacks_test.go b/common/agentlog/callbacks_test.go new file mode 100644 index 000000000..7cc235f57 --- /dev/null +++ b/common/agentlog/callbacks_test.go @@ -0,0 +1,124 @@ +/* + Copyright NetFoundry Inc. + + Licensed under the Apache License, Version 2.0 (the "License"); + you may not use this file except in compliance with the License. + You may obtain a copy of the License at + + https://www.apache.org/licenses/LICENSE-2.0 + + Unless required by applicable law or agreed to in writing, software + distributed under the License is distributed on an "AS IS" BASIS, + WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + See the License for the specific language governing permissions and + limitations under the License. +*/ + +package agentlog + +import ( + "context" + "log/slog" + "testing" + + "github.com/openziti/ziti/v2/common/agent" + "github.com/openziti/ziti/v2/common/logging" + "github.com/sirupsen/logrus" + "github.com/stretchr/testify/require" +) + +// TestAgentToSlogMapping covers the seven canonical levels by name so a +// future renumbering of either enum is caught here, not silently downstream. +func TestAgentToSlogMapping(t *testing.T) { + cases := []struct { + agentLvl agent.LogLevel + slogLvl slog.Level + }{ + {agent.PanicLevel, logging.LevelPanic}, + {agent.FatalLevel, logging.LevelFatal}, + {agent.ErrorLevel, slog.LevelError}, + {agent.WarnLevel, slog.LevelWarn}, + {agent.InfoLevel, slog.LevelInfo}, + {agent.DebugLevel, slog.LevelDebug}, + {agent.TraceLevel, logging.LevelTrace}, + } + for _, c := range cases { + t.Run(c.agentLvl.String(), func(t *testing.T) { + require.Equal(t, c.slogLvl, agentToSlog(c.agentLvl)) + }) + } +} + +// TestAgentToSlogUnknownFallsBackToInfo proves an out-of-range LogLevel does +// not silence logging; it falls back to Info so log output is preserved. +func TestAgentToSlogUnknownFallsBackToInfo(t *testing.T) { + require.Equal(t, slog.LevelInfo, agentToSlog(agent.LogLevel(99))) +} + +// TestDefaultCallbacks_SetLogLevel proves SetLogLevel drives the slog global +// AND logrus.SetLevel via the package-level lockstep helper. This is the path +// `ziti agent set-log-level info` takes. +func TestDefaultCallbacks_SetLogLevel(t *testing.T) { + prevLogrus := logrus.StandardLogger().Level + t.Cleanup(func() { logrus.StandardLogger().SetLevel(prevLogrus) }) + + configureForTest(t) + cbs := DefaultLogLevelCallbacks() + + cbs.SetLogLevel(agent.DebugLevel) + require.Equal(t, slog.LevelDebug, logging.GlobalLevel()) + require.Equal(t, logrus.DebugLevel, logrus.StandardLogger().Level) + + cbs.SetLogLevel(agent.WarnLevel) + require.Equal(t, slog.LevelWarn, logging.GlobalLevel()) + require.Equal(t, logrus.WarnLevel, logrus.StandardLogger().Level) +} + +// TestDefaultCallbacks_SetChannelLogLevel proves the channel callback drives +// the named-logger override; the slog Logger returned by logging.For honors +// the override on its next Enabled check. +func TestDefaultCallbacks_SetChannelLogLevel(t *testing.T) { + configureForTest(t) + cbs := DefaultLogLevelCallbacks() + + // Global Warn; channel "router.link" overridden to Debug. + cbs.SetLogLevel(agent.WarnLevel) + cbs.SetChannelLogLevel("router.link", agent.DebugLevel) + + logger := logging.For("router.link") + require.True(t, logger.Enabled(context.Background(), slog.LevelDebug), "override must lift the channel above the global level") + + // Another channel without an override stays at global Warn. + other := logging.For("router.xgress") + require.False(t, other.Enabled(context.Background(), slog.LevelDebug), "non-overridden channels must follow the global level") +} + +// TestDefaultCallbacks_ClearChannelLogLevel proves Clear restores the channel +// to the global level live; the channel logger's next Enabled check uses the +// global, even if it was below the previously-overridden level. +func TestDefaultCallbacks_ClearChannelLogLevel(t *testing.T) { + configureForTest(t) + cbs := DefaultLogLevelCallbacks() + + cbs.SetLogLevel(agent.WarnLevel) + cbs.SetChannelLogLevel("router.link", agent.DebugLevel) + cbs.ClearChannelLogLevel("router.link") + + logger := logging.For("router.link") + require.False(t, logger.Enabled(context.Background(), slog.LevelDebug), "Clear must drop the channel back to the global level") +} + +// configureForTest wires a no-op default Registry so the package-level +// logging functions don't panic. The Registry's root is a discard handler +// because tests here only assert level state, not record dispatch. +func configureForTest(t *testing.T) { + t.Helper() + logging.Configure(discardHandler{}) +} + +type discardHandler struct{} + +func (discardHandler) Enabled(context.Context, slog.Level) bool { return true } +func (discardHandler) Handle(context.Context, slog.Record) error { return nil } +func (h discardHandler) WithAttrs([]slog.Attr) slog.Handler { return h } +func (h discardHandler) WithGroup(string) slog.Handler { return h } diff --git a/common/agentlog/e2e_test.go b/common/agentlog/e2e_test.go new file mode 100644 index 000000000..fc67e48c9 --- /dev/null +++ b/common/agentlog/e2e_test.go @@ -0,0 +1,185 @@ +/* + Copyright NetFoundry Inc. + + Licensed under the Apache License, Version 2.0 (the "License"); + you may not use this file except in compliance with the License. + You may obtain a copy of the License at + + https://www.apache.org/licenses/LICENSE-2.0 + + Unless required by applicable law or agreed to in writing, software + distributed under the License is distributed on an "AS IS" BASIS, + WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + See the License for the specific language governing permissions and + limitations under the License. +*/ + +package agentlog + +import ( + "context" + "io" + "log/slog" + "sync" + "testing" + + "github.com/michaelquigley/pfxlog" + "github.com/openziti/ziti/v2/common/agent" + "github.com/openziti/ziti/v2/common/logging" + "github.com/sirupsen/logrus" + "github.com/stretchr/testify/require" +) + +// recordingHandler captures every record that reaches it. The tests in this +// file install a sync recording handler (rather than the production +// AsyncHandler) so they don't depend on a queue drain to flush before +// assertions; this isolates the level-filtering behavior under test from the +// AsyncHandler's lifecycle. +type recordingHandler struct { + mu sync.Mutex + records []slog.Record +} + +func (h *recordingHandler) Enabled(context.Context, slog.Level) bool { return true } + +func (h *recordingHandler) Handle(_ context.Context, r slog.Record) error { + h.mu.Lock() + defer h.mu.Unlock() + h.records = append(h.records, r.Clone()) + return nil +} + +func (h *recordingHandler) WithAttrs([]slog.Attr) slog.Handler { return h } +func (h *recordingHandler) WithGroup(string) slog.Handler { return h } + +func (h *recordingHandler) messages() []string { + h.mu.Lock() + defer h.mu.Unlock() + out := make([]string, len(h.records)) + for i, r := range h.records { + out[i] = r.Message + } + return out +} + +// installForTest installs the sync recording handler onto logrus.StandardLogger +// (pfxlog v0.6.10 dispatches there, so the bridge must be wired to the +// standard logger for pfxlog calls to reach slog) and registers a cleanup +// that restores logrus's previous Out / Formatter / Level / ReportCaller and +// clears all hooks. Tests in this file mutate global logrus state by design. +func installForTest(t *testing.T, level slog.Level) *recordingHandler { + t.Helper() + rec := &recordingHandler{} + + std := logrus.StandardLogger() + prevOut := std.Out + prevFmt := std.Formatter + prevLevel := std.Level + prevReport := std.ReportCaller + prevHooks := std.Hooks + t.Cleanup(func() { + std.SetOutput(prevOut) + std.SetFormatter(prevFmt) + std.SetLevel(prevLevel) + std.SetReportCaller(prevReport) + std.ReplaceHooks(prevHooks) + }) + + logging.Install(rec, level) + return rec +} + +// TestInstallInvariant proves logrus.StandardLogger is fully captured by the +// bridge after Install: output is io.Discard, formatter is the noop, the +// caller's level is mirrored to logrus, ReportCaller is on so the bridge has +// a PC to forward, and subsequent SetGlobalLevel updates keep the two worlds +// in lockstep. This is the invariant the Phase 6 design hangs on. +func TestInstallInvariant(t *testing.T) { + installForTest(t, slog.LevelInfo) + + std := logrus.StandardLogger() + require.Equal(t, io.Discard, std.Out, "output must be io.Discard") + require.True(t, std.ReportCaller, "ReportCaller must be enabled") + require.Equal(t, logrus.InfoLevel, std.Level, "logrus level must mirror the slog initial level") + require.Equal(t, slog.LevelInfo, logging.GlobalLevel()) + + // noopFormatter is unexported in common/logging; assert by behavior: the + // formatter returns an empty byte slice for any entry, which is the + // contract that makes the io.Discard sink benign. + out, err := std.Formatter.Format(&logrus.Entry{Message: "x"}) + require.NoError(t, err) + require.Empty(t, out) + + // Subsequent SetGlobalLevel must keep logrus pre-filter in lockstep. + logging.SetGlobalLevel(logging.LevelTrace) + require.Equal(t, logrus.TraceLevel, std.Level) + logging.SetGlobalLevel(slog.LevelWarn) + require.Equal(t, logrus.WarnLevel, std.Level) +} + +// TestEndToEnd_AgentSetLogLevel proves the agent callback chain drives both +// sides of the bridge. After cb.SetLogLevel(InfoLevel), logrus's pre-filter +// drops Debug records (so they never reach the bridge) and the slog Registry +// reports the matching global; Info records flow through both the bridged +// logrus path (via pfxlog.Logger()) and the direct slog path (via +// logging.For()). This is the path `ziti agent set-log-level info` takes. +func TestEndToEnd_AgentSetLogLevel(t *testing.T) { + rec := installForTest(t, slog.LevelWarn) + cb := DefaultLogLevelCallbacks() + + // Initial level Warn: Info from either side is filtered. + pfxlog.Logger().Info("pre-info-pfxlog") + logging.For("zone.x").Info("pre-info-slog") + require.Empty(t, rec.messages(), "pre-SetLogLevel Info records must be filtered") + + // Operator runs `ziti agent set-log-level info`; lockstep moves both sides. + cb.SetLogLevel(agent.InfoLevel) + require.Equal(t, slog.LevelInfo, logging.GlobalLevel()) + require.Equal(t, logrus.InfoLevel, logrus.StandardLogger().Level) + + // Below threshold remains filtered. + pfxlog.Logger().Debug("post-debug-pfxlog") + logging.For("zone.x").Debug("post-debug-slog") + // At threshold: both paths emit. + pfxlog.Logger().Info("post-info-pfxlog") + logging.For("zone.x").Info("post-info-slog") + + got := rec.messages() + require.Contains(t, got, "post-info-pfxlog", "bridged logrus Info must reach slog after SetLogLevel(Info)") + require.Contains(t, got, "post-info-slog", "direct slog Info must reach the handler after SetLogLevel(Info)") + require.NotContains(t, got, "post-debug-pfxlog", "logrus Debug must be filtered by the pre-filter after SetLogLevel(Info)") + require.NotContains(t, got, "post-debug-slog", "slog Debug must be filtered by the global Registry level") +} + +// TestPerChannelOverride_AppliesToSlogOnly_NotPfxlog proves Phase 7's slog-only +// channel-override semantics: when the global level is Info, an override +// lifting "test.gossip" to Debug enables slog Debug for that channel but does +// not affect pfxlog's channel-level mechanism. pfxlog.Logger() / ChannelLogger +// still observe the global logrus level (Info), so a pfxlog Debug call on the +// same channel name stays filtered. Clearing the override drops the channel +// back to the global level. +func TestPerChannelOverride_AppliesToSlogOnly_NotPfxlog(t *testing.T) { + rec := installForTest(t, slog.LevelInfo) + cb := DefaultLogLevelCallbacks() + + cb.SetChannelLogLevel("test.gossip", agent.DebugLevel) + + // slog override: Debug on the named channel is allowed through. + logging.For("test.gossip").Debug("slog-debug-allowed") + // pfxlog at Debug stays filtered because the global logrus level is Info + // and the per-channel override does not touch pfxlog's overrides map. + pfxlog.Logger().Debug("pfxlog-debug-filtered") + pfxlog.ChannelLogger("test.gossip").Debug("pfxlog-channel-debug-filtered") + // pfxlog at Info still gets through, confirming the bridge is wired. + pfxlog.Logger().Info("pfxlog-info-allowed") + + got := rec.messages() + require.Contains(t, got, "slog-debug-allowed", "slog channel override must enable Debug for that channel") + require.Contains(t, got, "pfxlog-info-allowed", "bridge must continue to deliver pfxlog Info records") + require.NotContains(t, got, "pfxlog-debug-filtered", "pfxlog Debug must stay filtered by the global logrus level") + require.NotContains(t, got, "pfxlog-channel-debug-filtered", "pfxlog channel logger must not see the slog-only override") + + cb.ClearChannelLogLevel("test.gossip") + logging.For("test.gossip").Debug("post-clear-debug-filtered") + require.NotContains(t, rec.messages(), "post-clear-debug-filtered", "Clear must drop the channel back to the global Info level") +} diff --git a/common/logging/bridge.go b/common/logging/bridge.go index fa4d2e72e..d4cac6afc 100644 --- a/common/logging/bridge.go +++ b/common/logging/bridge.go @@ -21,6 +21,9 @@ import ( "fmt" "io" "log/slog" + "os" + "runtime" + "time" "github.com/sirupsen/logrus" ) @@ -143,6 +146,28 @@ func SyncEmit(ctx context.Context, r slog.Record) error { return root.Handle(ctx, r) } +// osExit is os.Exit, indirected so tests can exercise Fatal without +// terminating the test process. +var osExit = os.Exit + +// Fatal writes msg at LevelFatal and then exits the process with status 1. It +// is the slog-world equivalent of logrus.Fatal, which slog does not provide +// (slog has only Debug/Info/Warn/Error and never exits the process itself). +// +// The record is emitted durably through SyncEmit, so it flushes any queued +// records and writes synchronously before the exit, and it bypasses level +// gating so a fatal is never filtered out. Hard-exit paths call this instead +// of logging an Error and then calling os.Exit or panic: those drop the record +// because the async queue never drains before the process is gone. +func Fatal(ctx context.Context, msg string, attrs ...slog.Attr) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) // skip runtime.Callers + this frame + r := slog.NewRecord(time.Now(), LevelFatal, msg, pcs[0]) + r.AddAttrs(attrs...) + _ = SyncEmit(ctx, r) + osExit(1) +} + // logrusToSlog maps a logrus.Level to its canonical slog.Level. logrus // levels are densely packed (0..6, panic..trace); the seven canonical slog // levels we use here map one-to-one. diff --git a/common/logging/bridge_test.go b/common/logging/bridge_test.go index 718daea32..7107d0fce 100644 --- a/common/logging/bridge_test.go +++ b/common/logging/bridge_test.go @@ -304,6 +304,45 @@ func TestBridgeEndToEndResolvesRealCaller(t *testing.T) { require.NotContains(t, fn, "sirupsen/logrus", "caller must not resolve to a logrus frame") } +// TestFatalEmitsDurablyAndExits proves Fatal writes its record synchronously +// (present before any Close, so it survives a process exit), carries the +// attrs, and calls osExit(1). The global level is set above Fatal to also +// prove Fatal bypasses level gating, matching logrus.Fatal. +func TestFatalEmitsDurablyAndExits(t *testing.T) { + resetDefaultForTest() + rec := &recordingHandler{} + async, err := NewAsyncHandler(rec, DefaultOptions()) + require.NoError(t, err) + Configure(async) + SetGlobalLevel(LevelPanic) // above Fatal: a gated path would drop it + + var gotCode int + var exited bool + prev := osExit + osExit = func(code int) { gotCode = code; exited = true } + defer func() { osExit = prev }() + + Fatal(context.Background(), "boom", slog.String("k", "v")) + + require.True(t, exited, "Fatal must call osExit") + require.Equal(t, 1, gotCode) + require.Equal(t, 1, rec.count(), "record must be written synchronously, not left in the queue") + + got := rec.snapshot()[0] + require.Equal(t, LevelFatal, got.Level) + require.Equal(t, "boom", got.Message) + require.NotZero(t, got.PC, "Fatal should capture the caller PC") + attrs := map[string]string{} + got.Attrs(func(a slog.Attr) bool { + attrs[a.Key] = a.Value.String() + return true + }) + require.Equal(t, "v", attrs["k"]) + + require.NoError(t, async.Close()) + <-async.drainDone +} + // TestInstallToIsIdempotent proves repeated InstallTo on the same logger // doesn't stack multiple slogBridge hooks. The quickstart hits this path by // running the controller and router from a single process, each calling diff --git a/common/logging/fatal_panic_test.go b/common/logging/fatal_panic_test.go new file mode 100644 index 000000000..4604dab6a --- /dev/null +++ b/common/logging/fatal_panic_test.go @@ -0,0 +1,178 @@ +/* + Copyright NetFoundry Inc. + + Licensed under the Apache License, Version 2.0 (the "License"); + you may not use this file except in compliance with the License. + You may obtain a copy of the License at + + https://www.apache.org/licenses/LICENSE-2.0 + + Unless required by applicable law or agreed to in writing, software + distributed under the License is distributed on an "AS IS" BASIS, + WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + See the License for the specific language governing permissions and + limitations under the License. +*/ + +package logging + +import ( + "bytes" + "encoding/json" + "log/slog" + "os" + "os/exec" + "strings" + "testing" + + "github.com/sirupsen/logrus" + "github.com/stretchr/testify/require" +) + +// subprocessEnv selects the child-mode behavior; an empty value means the +// process is the parent test driver. Held under one env var so both +// subprocess tests share the same dispatch. +const subprocessEnv = "ZITI_LOGGING_FATAL_PANIC_CHILD" + +const ( + subprocessFatalMsg = "durable-fatal-marker" + subprocessPanicMsg = "durable-panic-marker" +) + +// TestFatalReachesStderrBeforeExit forks the test binary, has the child +// configure the production handler chain via BuildHandler over os.Stderr, +// then call logrus.Fatal. The parent asserts the child exited non-zero AND +// that the fatal marker appears in the child's stderr; together these prove +// the bridge's SyncEmit path flushed the record to the leaf handler before +// logrus called os.Exit. +func TestFatalReachesStderrBeforeExit(t *testing.T) { + if os.Getenv(subprocessEnv) == "fatal" { + runFatalChild() + return // unreachable when logrus.Fatal works + } + stderr, exitCode := runChild(t, "fatal") + require.NotEqual(t, 0, exitCode, "logrus.Fatal must produce a non-zero exit; child stderr was: %q", stderr) + require.True(t, stderrContainsRecord(stderr, subprocessFatalMsg, "fatal"), + "fatal record must reach stderr before os.Exit; child stderr was: %q", stderr) +} + +// TestPanicReachesStderrBeforeExit mirrors the Fatal test for Panic. logrus +// fires hooks before issuing its panic; the bridge routes Panic-level records +// through SyncEmit so the leaf handler writes to stderr synchronously. The +// runtime's panic stack trace also goes to stderr; the assertion only cares +// that our JSON record arrived in the same stream. +func TestPanicReachesStderrBeforeExit(t *testing.T) { + if os.Getenv(subprocessEnv) == "panic" { + runPanicChild() + return + } + stderr, exitCode := runChild(t, "panic") + require.NotEqual(t, 0, exitCode, "logrus.Panic must produce a non-zero exit; child stderr was: %q", stderr) + require.True(t, stderrContainsRecord(stderr, subprocessPanicMsg, "panic"), + "panic record must reach stderr before the runtime panic; child stderr was: %q", stderr) +} + +// TestFatalLabeledInPrettyOutput mirrors the Fatal durability test through +// the pretty handler chain: a post-Install logrus.Fatal must render the +// "FATAL" label in human-readable output, not a blank level column. +func TestFatalLabeledInPrettyOutput(t *testing.T) { + if os.Getenv(subprocessEnv) == "fatal-pretty" { + runPrettyChild(logrus.Fatal, subprocessFatalMsg) + return + } + stderr, exitCode := runChild(t, "fatal-pretty") + require.NotEqual(t, 0, exitCode, "logrus.Fatal must produce a non-zero exit; child stderr was: %q", stderr) + require.True(t, prettyStderrContainsRecord(stderr, subprocessFatalMsg, "FATAL"), + "pretty output must carry the FATAL label; child stderr was: %q", stderr) +} + +// TestPanicLabeledInPrettyOutput mirrors TestFatalLabeledInPrettyOutput for +// Panic. +func TestPanicLabeledInPrettyOutput(t *testing.T) { + if os.Getenv(subprocessEnv) == "panic-pretty" { + runPrettyChild(logrus.Panic, subprocessPanicMsg) + return + } + stderr, exitCode := runChild(t, "panic-pretty") + require.NotEqual(t, 0, exitCode, "logrus.Panic must produce a non-zero exit; child stderr was: %q", stderr) + require.True(t, prettyStderrContainsRecord(stderr, subprocessPanicMsg, "PANIC"), + "pretty output must carry the PANIC label; child stderr was: %q", stderr) +} + +// runChild forks the current test binary, asking it to run only the calling +// test with the subprocess env set to mode. It returns the child's stderr +// (captured) and exit code. +func runChild(t *testing.T, mode string) (string, int) { + t.Helper() + cmd := exec.Command(os.Args[0], "-test.run=^"+t.Name()+"$", "-test.v") + cmd.Env = append(os.Environ(), subprocessEnv+"="+mode) + var stderr bytes.Buffer + cmd.Stderr = &stderr + err := cmd.Run() + if exitErr, ok := err.(*exec.ExitError); ok { + return stderr.String(), exitErr.ExitCode() + } + if err == nil { + return stderr.String(), 0 + } + t.Fatalf("subprocess failed to launch: %v", err) + return stderr.String(), -1 +} + +func runFatalChild() { + h, err := BuildHandler(os.Stderr, DefaultOptions()) + if err != nil { + panic(err) + } + Install(h, slog.LevelInfo) + logrus.Fatal(subprocessFatalMsg) +} + +func runPanicChild() { + h, err := BuildHandler(os.Stderr, DefaultOptions()) + if err != nil { + panic(err) + } + Install(h, slog.LevelInfo) + logrus.Panic(subprocessPanicMsg) +} + +// runPrettyChild configures the default pretty handler chain (the controller, +// router, and tunnel operator default) over stderr and fires the given +// logrus call. +func runPrettyChild(logFn func(args ...any), msg string) { + h, err := BuildHandlerForFormat(os.Stderr, DefaultOptions(), FormatPretty) + if err != nil { + panic(err) + } + Install(h, slog.LevelInfo) + logFn(msg) +} + +// prettyStderrContainsRecord scans the child's stderr for a pretty-format +// line that carries both the expected message and the expected level label. +func prettyStderrContainsRecord(stderr, msg, label string) bool { + for _, line := range strings.Split(strings.TrimSpace(stderr), "\n") { + if strings.Contains(line, msg) && strings.Contains(line, label) { + return true + } + } + return false +} + +// stderrContainsRecord scans the child's stderr for a JSON line that carries +// both the expected message and the expected level. The runtime panic trace +// and the testing harness's own output share the stream; non-JSON lines are +// ignored. +func stderrContainsRecord(stderr, msg, level string) bool { + for _, line := range strings.Split(strings.TrimSpace(stderr), "\n") { + var rec map[string]any + if err := json.Unmarshal([]byte(line), &rec); err != nil { + continue + } + if rec["msg"] == msg && rec["level"] == level { + return true + } + } + return false +} diff --git a/common/logging/format.go b/common/logging/format.go index ce3281b84..52aa891e5 100644 --- a/common/logging/format.go +++ b/common/logging/format.go @@ -114,3 +114,65 @@ func BuildHandler(out io.Writer, opts AsyncOptions) (*AsyncHandler, error) { flat := &sourceFlattener{parent: json} return NewAsyncHandler(flat, opts) } + +// BuildTextHandler constructs the async chain for plain key=value text output: +// a slog TextHandler over out (lowercased canonical level names via +// ReplaceAttr, flat file/func via sourceFlattener), wrapped in an AsyncHandler. +// This is what --log-formatter=text selects, matching the pre-slog +// logrus.TextFormatter shape (level=info msg=...) rather than the colored, +// positional pretty output. +// +// out defaults to os.Stderr when nil. +func BuildTextHandler(out io.Writer, opts AsyncOptions) (*AsyncHandler, error) { + if out == nil { + out = os.Stderr + } + text := slog.NewTextHandler(out, &slog.HandlerOptions{ + AddSource: false, + Level: LevelTrace, + ReplaceAttr: ReplaceAttr, + }) + flat := &sourceFlattener{parent: text} + return NewAsyncHandler(flat, opts) +} + +// BuildPrettyHandler builds the async chain for ziti's pretty (pfxlog-shape) +// output: a PrettyHandler over out, wrapped in an AsyncHandler. The +// PrettyHandler resolves the caller frame from slog.Record.PC, so the bridge +// must have ReportCaller enabled (which Install does) for legacy logrus call +// sites to render their original file/func. +// +// prettyOpts defaults to DefaultPrettyOptions(): pfxlog-compatible labels, +// "github.com/openziti/" trimmed from function names, relative time since the +// start of today, and color off unless PFXLOG_USE_COLOR opts in. out defaults +// to os.Stderr. +func BuildPrettyHandler(out io.Writer, opts AsyncOptions, prettyOpts *PrettyOptions) (*AsyncHandler, error) { + if out == nil { + out = os.Stderr + } + return NewAsyncHandler(NewPrettyHandler(out, prettyOpts), opts) +} + +// Recognised values for the --log-formatter flag. "" is treated as +// FormatPretty so unconfigured binaries match the pre-slog default look. +const ( + FormatPretty = "pfxlog" + FormatJSON = "json" + FormatText = "text" +) + +// BuildHandlerForFormat picks the production handler chain by name. Unknown +// or empty formats fall back to FormatPretty so ziti's default look-and-feel +// matches the pre-slog binaries. +func BuildHandlerForFormat(out io.Writer, opts AsyncOptions, format string) (*AsyncHandler, error) { + switch format { + case FormatJSON: + return BuildHandler(out, opts) + case FormatText: + return BuildTextHandler(out, opts) + case "", FormatPretty: + return BuildPrettyHandler(out, opts, nil) + default: + return nil, fmt.Errorf("logging: unknown formatter %q (want %q, %q, or %q)", format, FormatPretty, FormatJSON, FormatText) + } +} diff --git a/common/logging/format_test.go b/common/logging/format_test.go index 21bf637f8..54e257df2 100644 --- a/common/logging/format_test.go +++ b/common/logging/format_test.go @@ -152,3 +152,97 @@ func TestBuildHandlerEmitsCustomLevels(t *testing.T) { } require.Equal(t, []string{"trace", "fatal", "panic"}, levels) } + +// TestBuildPrettyHandlerEmitsTextWithoutColor proves the pretty handler +// produces text output (not JSON) and writes to the supplied io.Writer when +// color is disabled. +func TestBuildPrettyHandlerEmitsTextWithoutColor(t *testing.T) { + buf := &bytes.Buffer{} + opts := DefaultOptions() + opts.SummaryInterval = time.Hour + prettyOpts := DefaultPrettyOptions() + prettyOpts.UseColor = false + h, err := BuildPrettyHandler(buf, opts, prettyOpts) + require.NoError(t, err) + + slog.New(h).Info("hello", "k", "v") + require.NoError(t, h.Close()) + <-h.drainDone + + line := strings.TrimSpace(buf.String()) + require.NotEmpty(t, line) + require.Contains(t, line, "INFO") + require.Contains(t, line, "hello") + require.Contains(t, line, "k=[v]") + require.False(t, json.Valid([]byte(line)), "pretty output must not be JSON") +} + +// TestBuildHandlerForFormatSelectsLeaf covers the format-string switch and +// asserts each format's distinct output shape, not just JSON-vs-not: pfxlog and +// "" produce the positional pretty output (uppercase level label, no key=value +// level); text produces logrus-style key=value (level=info msg=...); json +// produces JSON. Distinguishing text from pretty is the point - both are +// non-JSON, so a not-JSON check alone would miss a text/pretty regression. +func TestBuildHandlerForFormatSelectsLeaf(t *testing.T) { + cases := []struct { + name string + format string + mustContain []string + mustNotHave []string + }{ + {"empty-defaults-to-pretty", "", []string{"INFO", "hello"}, []string{"level=info", `"msg"`}}, + {"pfxlog-explicit", FormatPretty, []string{"INFO", "hello"}, []string{"level=info", `"msg"`}}, + {"text", FormatText, []string{"level=info", "msg=hello"}, []string{"INFO", `"msg"`}}, + {"json", FormatJSON, []string{`"level":"info"`, `"msg":"hello"`}, []string{"level=info"}}, + } + for _, c := range cases { + t.Run(c.name, func(t *testing.T) { + buf := &bytes.Buffer{} + opts := DefaultOptions() + opts.SummaryInterval = time.Hour + h, err := BuildHandlerForFormat(buf, opts, c.format) + require.NoError(t, err) + slog.New(h).Info("hello") + require.NoError(t, h.Close()) + <-h.drainDone + line := strings.TrimSpace(buf.String()) + require.NotEmpty(t, line) + for _, s := range c.mustContain { + require.Contains(t, line, s, "format %q output %q", c.format, line) + } + for _, s := range c.mustNotHave { + require.NotContains(t, line, s, "format %q output %q", c.format, line) + } + }) + } +} + +// TestBuildTextHandlerEmitsKeyValue proves --log-formatter=text produces plain +// logrus-style key=value output (level=info msg=...), not the pretty handler's +// positional/uppercase shape. This is the compatibility guard for the text +// format, which previously mapped to logrus.TextFormatter. +func TestBuildTextHandlerEmitsKeyValue(t *testing.T) { + buf := &bytes.Buffer{} + opts := DefaultOptions() + opts.SummaryInterval = time.Hour + h, err := BuildTextHandler(buf, opts) + require.NoError(t, err) + + slog.New(h).Info("hello", "k", "v") + require.NoError(t, h.Close()) + <-h.drainDone + + line := strings.TrimSpace(buf.String()) + require.NotEmpty(t, line) + require.Contains(t, line, "level=info", "level must be the lowercased canonical name") + require.Contains(t, line, "msg=hello") + require.Contains(t, line, "k=v") + require.NotContains(t, line, "INFO", "text output must not use the pretty handler's uppercase label") + require.False(t, json.Valid([]byte(line)), "text output must not be JSON") +} + +func TestBuildHandlerForFormatRejectsUnknown(t *testing.T) { + _, err := BuildHandlerForFormat(nil, DefaultOptions(), "logfmt") + require.Error(t, err) + require.Contains(t, err.Error(), "logfmt") +} diff --git a/common/logging/pretty.go b/common/logging/pretty.go new file mode 100644 index 000000000..861c8f49d --- /dev/null +++ b/common/logging/pretty.go @@ -0,0 +1,302 @@ +/* + Copyright NetFoundry Inc. + + Licensed under the Apache License, Version 2.0 (the "License"); + you may not use this file except in compliance with the License. + You may obtain a copy of the License at + + https://www.apache.org/licenses/LICENSE-2.0 + + Unless required by applicable law or agreed to in writing, software + distributed under the License is distributed on an "AS IS" BASIS, + WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + See the License for the specific language governing permissions and + limitations under the License. +*/ + +package logging + +import ( + "context" + "fmt" + "io" + "log/slog" + "os" + "runtime" + "sort" + "strconv" + "strings" + "sync" + "time" +) + +// ANSI color sequences matching the mgutz/ansi values the old pfxlog +// formatter used, so colored output looks the same as the pre-slog binaries. +const ( + ansiRed = "\033[31m" + ansiYellow = "\033[33m" + ansiWhite = "\033[37m" + ansiBlue = "\033[34m" + ansiLightBlack = "\033[90m" + ansiCyan = "\033[36m" + ansiLightCyan = "\033[96m" + ansiDefaultFg = "\033[39m" +) + +// Special attr keys carried over from pfxlog: ChannelsKey holds a []string of +// channel names rendered as |a, b| after the function, ContextKey holds a +// string rendered as [ctx]. Both are excluded from the fields block. +const ( + ChannelsKey = "_channels" + ContextKey = "_context" +) + +// PrettyOptions configures PrettyHandler's human-readable output. +type PrettyOptions struct { + // AbsoluteTime renders the record's time as a wall-clock timestamp using + // TimestampFormat instead of seconds since StartTimestamp. + AbsoluteTime bool + + // StartTimestamp is the baseline for the relative [seconds] time column. + // DefaultPrettyOptions sets it to the start of today in local time, + // matching pfxlog's StartingToday behavior. + StartTimestamp time.Time + + // TimestampFormat is the time layout used when AbsoluteTime is set. + TimestampFormat string + + // TrimPrefix is removed from the front of function names before they are + // rendered. DefaultPrettyOptions sets "github.com/openziti/". + TrimPrefix string + + // UseColor enables ANSI coloring of every colored segment (level label, + // timestamp, function, fields). When false the output contains no escape + // sequences at all. + UseColor bool +} + +// DefaultPrettyOptions returns PrettyOptions matching the pre-slog pfxlog +// defaults: relative time since the start of today, "github.com/openziti/" +// trimmed from function names, and color off unless PFXLOG_USE_COLOR opts in. +func DefaultPrettyOptions() *PrettyOptions { + now := time.Now() + return &PrettyOptions{ + StartTimestamp: time.Date(now.Year(), now.Month(), now.Day(), 0, 0, 0, 0, now.Location()), + TimestampFormat: "2006-01-02 15:04:05.000", + TrimPrefix: "github.com/openziti/", + UseColor: useColor(), + } +} + +// useColor decides the default color setting. ziti has always run its pretty +// logs without color (cmd/main sets pfxlog's NoColor), so color is off unless a +// caller opts in via PFXLOG_USE_COLOR. TTY detection is deliberately not used: +// it would turn color on in interactive terminals where the pre-slog binaries +// showed none. +func useColor() bool { + if env := os.Getenv("PFXLOG_USE_COLOR"); env != "" { + if v, err := strconv.ParseBool(env); err == nil { + return v + } + } + return false +} + +// PrettyHandler is a slog.Handler that renders records in the pfxlog pretty +// format the pre-slog ziti binaries produced: +// +// [ 12.345] ERROR ziti/controller/server.Run: {k=[v]} something failed +// +// All seven canonical levels (trace through panic) render with their pfxlog +// labels; non-canonical levels fall back to slog's offset form. The handler +// does no level gating; that lives upstream in the registry chain. +type PrettyHandler struct { + opts PrettyOptions + out io.Writer + lock *sync.Mutex + attrs []slog.Attr +} + +// NewPrettyHandler builds a PrettyHandler writing to out. A nil opts uses +// DefaultPrettyOptions(); out defaults to os.Stderr when nil. +func NewPrettyHandler(out io.Writer, opts *PrettyOptions) *PrettyHandler { + if out == nil { + out = os.Stderr + } + if opts == nil { + opts = DefaultPrettyOptions() + } + return &PrettyHandler{ + opts: *opts, + out: out, + lock: &sync.Mutex{}, + } +} + +func (h *PrettyHandler) Enabled(context.Context, slog.Level) bool { + return true +} + +func (h *PrettyHandler) Handle(_ context.Context, r slog.Record) error { + var out strings.Builder + + recordTime := r.Time + if recordTime.IsZero() { + recordTime = time.Now() + } + var timeLabel string + if h.opts.AbsoluteTime { + timeLabel = "[" + recordTime.Format(h.opts.TimestampFormat) + "]" + } else { + timeLabel = fmt.Sprintf("[%8.3f]", recordTime.Sub(h.opts.StartTimestamp).Seconds()) + } + out.WriteString(h.colored(ansiBlue, timeLabel)) + + out.WriteString(" " + h.levelLabel(r.Level)) + + function := h.functionFor(r) + + // collect handler attrs then record attrs; later keys overwrite earlier + // ones in the fields map, matching logrus WithField semantics + fields := map[string]any{} + addAttr := func(a slog.Attr) { + fields[a.Key] = a.Value.Any() + } + for _, a := range h.attrs { + addAttr(a) + } + r.Attrs(func(a slog.Attr) bool { + addAttr(a) + return true + }) + + // func/file attrs only stand in for the caller frame when there's no PC + // (bridged records keep them in Entry.Data); with a PC they'd be + // redundant with the resolved frame + if function == "" { + if fn, ok := fields["func"].(string); ok { + function = fn + delete(fields, "func") + delete(fields, "file") + } + } + function = strings.TrimPrefix(function, h.opts.TrimPrefix) + + if channels, ok := fields[ChannelsKey].([]string); ok && len(channels) > 0 { + function += " |" + strings.Join(channels, ", ") + "|" + } + delete(fields, ChannelsKey) + if logCtx, ok := fields[ContextKey].(string); ok { + function += " [" + logCtx + "]" + } + delete(fields, ContextKey) + + out.WriteString(" " + h.colored(ansiCyan, function) + ":") + + if len(fields) > 0 { + keys := make([]string, 0, len(fields)) + for k := range fields { + keys = append(keys, k) + } + sort.Strings(keys) + var fieldsStr strings.Builder + fieldsStr.WriteString("{") + for i, k := range keys { + if i > 0 { + fieldsStr.WriteString(" ") + } + fmt.Fprintf(&fieldsStr, "%s=[%v]", k, fields[k]) + } + fieldsStr.WriteString("}") + out.WriteString(" " + h.colored(ansiLightCyan, fieldsStr.String())) + } + + out.WriteString(" " + r.Message) + + h.lock.Lock() + defer h.lock.Unlock() + _, err := fmt.Fprintln(h.out, out.String()) + return err +} + +// WithAttrs returns a handler whose output includes attrs in the fields +// block of every record, appended after any attrs already held. +func (h *PrettyHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + if len(attrs) == 0 { + return h + } + merged := make([]slog.Attr, 0, len(h.attrs)+len(attrs)) + merged = append(merged, h.attrs...) + merged = append(merged, attrs...) + return &PrettyHandler{opts: h.opts, out: h.out, lock: h.lock, attrs: merged} +} + +// WithGroup returns the handler unchanged: the pfxlog pretty format has no +// group concept, so group qualification is intentionally dropped, as it was +// in the pfxlog and df handlers this replaces. +func (h *PrettyHandler) WithGroup(string) slog.Handler { + return h +} + +// functionFor resolves the record's caller function from its PC, or returns +// "" when there is no PC (bridged records carry func/file as attrs instead). +func (h *PrettyHandler) functionFor(r slog.Record) string { + if r.PC == 0 { + return "" + } + frames := runtime.CallersFrames([]uintptr{r.PC}) + frame, _ := frames.Next() + return frame.Function +} + +// levelLabel returns the 7-character pfxlog label for the level, colored when +// UseColor is set. Non-canonical levels render slog's offset form (for +// example "DEBUG+1") right-aligned to the same width. +func (h *PrettyHandler) levelLabel(l slog.Level) string { + var label string + switch l { + case LevelPanic: + label = " PANIC" + case LevelFatal: + label = " FATAL" + case slog.LevelError: + label = " ERROR" + case slog.LevelWarn: + label = "WARNING" + case slog.LevelInfo: + label = " INFO" + case slog.LevelDebug: + label = " DEBUG" + case LevelTrace: + label = " TRACE" + default: + label = fmt.Sprintf("%7s", l.String()) + } + return h.colored(levelColor(l), label) +} + +// levelColor buckets a level into the color of the canonical level at or +// below it, so non-canonical levels color like their nearest neighbor. +func levelColor(l slog.Level) string { + switch { + case l >= slog.LevelError: + return ansiRed + case l >= slog.LevelWarn: + return ansiYellow + case l >= slog.LevelInfo: + return ansiWhite + case l >= slog.LevelDebug: + return ansiBlue + default: + return ansiLightBlack + } +} + +// colored wraps s in the given color and a foreground reset when UseColor is +// set, and returns s unchanged otherwise. +func (h *PrettyHandler) colored(color, s string) string { + if !h.opts.UseColor { + return s + } + return color + s + ansiDefaultFg +} diff --git a/common/logging/pretty_test.go b/common/logging/pretty_test.go new file mode 100644 index 000000000..604e139f0 --- /dev/null +++ b/common/logging/pretty_test.go @@ -0,0 +1,238 @@ +/* + Copyright NetFoundry Inc. + + Licensed under the Apache License, Version 2.0 (the "License"); + you may not use this file except in compliance with the License. + You may obtain a copy of the License at + + https://www.apache.org/licenses/LICENSE-2.0 + + Unless required by applicable law or agreed to in writing, software + distributed under the License is distributed on an "AS IS" BASIS, + WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + See the License for the specific language governing permissions and + limitations under the License. +*/ + +package logging + +import ( + "bytes" + "context" + "log/slog" + "strings" + "testing" + "time" + + "github.com/sirupsen/logrus" + "github.com/stretchr/testify/require" +) + +func plainPrettyOptions() *PrettyOptions { + return &PrettyOptions{ + StartTimestamp: time.Date(2026, 1, 1, 0, 0, 0, 0, time.UTC), + TimestampFormat: "2006-01-02 15:04:05.000", + UseColor: false, + } +} + +// TestPrettyHandlerLabelsAllSevenLevels is the regression test for the +// blank-label bug: every canonical level, including the custom Fatal, Panic, +// and Trace values the logrus bridge produces, must render its pfxlog label. +func TestPrettyHandlerLabelsAllSevenLevels(t *testing.T) { + cases := []struct { + lvl slog.Level + want string + }{ + {LevelTrace, " TRACE"}, + {slog.LevelDebug, " DEBUG"}, + {slog.LevelInfo, " INFO"}, + {slog.LevelWarn, "WARNING"}, + {slog.LevelError, " ERROR"}, + {LevelFatal, " FATAL"}, + {LevelPanic, " PANIC"}, + } + for _, c := range cases { + buf := &bytes.Buffer{} + h := NewPrettyHandler(buf, plainPrettyOptions()) + r := slog.NewRecord(time.Now(), c.lvl, "msg", 0) + require.NoError(t, h.Handle(context.Background(), r)) + require.Contains(t, buf.String(), c.want, "level %v", c.lvl) + } +} + +// TestPrettyHandlerNonCanonicalLevelFallsBack proves levels between the +// canonical seven still render a label rather than an empty column. +func TestPrettyHandlerNonCanonicalLevelFallsBack(t *testing.T) { + buf := &bytes.Buffer{} + h := NewPrettyHandler(buf, plainPrettyOptions()) + r := slog.NewRecord(time.Now(), slog.LevelDebug+1, "msg", 0) + require.NoError(t, h.Handle(context.Background(), r)) + require.Contains(t, buf.String(), "DEBUG+1") +} + +func TestPrettyHandlerRelativeTimeUsesRecordTime(t *testing.T) { + buf := &bytes.Buffer{} + opts := plainPrettyOptions() + h := NewPrettyHandler(buf, opts) + r := slog.NewRecord(opts.StartTimestamp.Add(12345*time.Millisecond), slog.LevelInfo, "msg", 0) + require.NoError(t, h.Handle(context.Background(), r)) + require.Contains(t, buf.String(), "[ 12.345]") +} + +func TestPrettyHandlerAbsoluteTime(t *testing.T) { + buf := &bytes.Buffer{} + opts := plainPrettyOptions() + opts.AbsoluteTime = true + h := NewPrettyHandler(buf, opts) + at := time.Date(2026, 6, 9, 10, 11, 12, int(13*time.Millisecond), time.UTC) + r := slog.NewRecord(at, slog.LevelInfo, "msg", 0) + require.NoError(t, h.Handle(context.Background(), r)) + require.Contains(t, buf.String(), "[2026-06-09 10:11:12.013]") +} + +// TestPrettyHandlerTrimsFunctionPrefix proves the configured TrimPrefix is +// removed from the rendered caller, restoring the pre-slog controller/router +// behavior of SetTrimPrefix("github.com/openziti/"). +func TestPrettyHandlerTrimsFunctionPrefix(t *testing.T) { + buf := &bytes.Buffer{} + opts := plainPrettyOptions() + opts.TrimPrefix = "github.com/openziti/" + h := NewPrettyHandler(buf, opts) + + slog.New(h).Info("hello") + + line := buf.String() + require.NotContains(t, line, "github.com/openziti/") + require.Contains(t, line, "ziti/v2/common/logging", "trimmed function path must remain") +} + +// TestPrettyHandlerColorGating proves UseColor=false produces zero escape +// sequences and UseColor=true produces them, independent of how the options +// were constructed. +func TestPrettyHandlerColorGating(t *testing.T) { + for _, useColor := range []bool{false, true} { + buf := &bytes.Buffer{} + opts := plainPrettyOptions() + opts.UseColor = useColor + h := NewPrettyHandler(buf, opts) + r := slog.NewRecord(time.Now(), slog.LevelError, "msg", 0) + r.AddAttrs(slog.String("k", "v")) + require.NoError(t, h.Handle(context.Background(), r)) + if useColor { + require.Contains(t, buf.String(), "\033[", "color enabled must emit ANSI") + } else { + require.NotContains(t, buf.String(), "\033[", "color disabled must emit no ANSI") + } + } +} + +// TestPrettyHandlerFieldsSortedAndFormatted checks the pfxlog fields block: +// sorted keys, k=[v] entries, placed before the message. +func TestPrettyHandlerFieldsSortedAndFormatted(t *testing.T) { + buf := &bytes.Buffer{} + h := NewPrettyHandler(buf, plainPrettyOptions()) + r := slog.NewRecord(time.Now(), slog.LevelInfo, "msg", 0) + r.AddAttrs(slog.String("b", "2"), slog.String("a", "1")) + require.NoError(t, h.Handle(context.Background(), r)) + + line := buf.String() + require.Contains(t, line, "{a=[1] b=[2]}") + require.Less(t, strings.Index(line, "{a=[1]"), strings.Index(line, "msg"), "fields render before the message") +} + +// TestPrettyHandlerChannelsAndContext covers the pfxlog _channels/_context +// conventions: rendered after the function as |a, b| and [ctx], excluded +// from the fields block. +func TestPrettyHandlerChannelsAndContext(t *testing.T) { + buf := &bytes.Buffer{} + h := NewPrettyHandler(buf, plainPrettyOptions()) + r := slog.NewRecord(time.Now(), slog.LevelInfo, "msg", 0) + r.AddAttrs( + slog.Any(ChannelsKey, []string{"policyEval", "serviceEval"}), + slog.String(ContextKey, "ch{edge}"), + slog.String("k", "v"), + ) + require.NoError(t, h.Handle(context.Background(), r)) + + line := buf.String() + require.Contains(t, line, "|policyEval, serviceEval|") + require.Contains(t, line, "[ch{edge}]") + require.NotContains(t, line, ChannelsKey) + require.NotContains(t, line, ContextKey) + require.Contains(t, line, "{k=[v]}") +} + +// TestPrettyHandlerFuncAttrFallback proves records without a PC (the bridged +// shape, where the bridge resolves func/file from logrus's Entry.Caller and +// attaches them as attrs) render the func attr as the caller and suppress the +// func/file keys from the fields block. +func TestPrettyHandlerFuncAttrFallback(t *testing.T) { + buf := &bytes.Buffer{} + opts := plainPrettyOptions() + opts.TrimPrefix = "github.com/openziti/" + h := NewPrettyHandler(buf, opts) + r := slog.NewRecord(time.Now(), slog.LevelInfo, "msg", 0) + r.AddAttrs( + slog.String("func", "github.com/openziti/ziti/controller.Run"), + slog.String("file", "controller.go:42"), + ) + require.NoError(t, h.Handle(context.Background(), r)) + + line := buf.String() + require.Contains(t, line, " ziti/controller.Run:") + require.NotContains(t, line, "func=[") + require.NotContains(t, line, "file=[") +} + +// TestPrettyHandlerWithAttrsAccumulates proves chained WithAttrs calls append +// rather than replace, and that record attrs override handler attrs with the +// same key. +func TestPrettyHandlerWithAttrsAccumulates(t *testing.T) { + buf := &bytes.Buffer{} + base := NewPrettyHandler(buf, plainPrettyOptions()) + h := base.WithAttrs([]slog.Attr{slog.String("a", "1")}). + WithAttrs([]slog.Attr{slog.String("b", "2")}) + + r := slog.NewRecord(time.Now(), slog.LevelInfo, "msg", 0) + r.AddAttrs(slog.String("b", "3")) + require.NoError(t, h.Handle(context.Background(), r)) + + line := buf.String() + require.Contains(t, line, "a=[1]", "first WithAttrs batch must survive the second") + require.Contains(t, line, "b=[3]", "record attr must override handler attr") + require.NotContains(t, line, "b=[2]") +} + +// TestPrettyHandlerEndToEndResolvesRealCaller drives a real logrus log call +// through getCaller, the bridge, and the PrettyHandler, asserting the rendered +// caller label is the actual call site rather than a logrus or bridge frame. +// This is the pretty-output analog of the JSON end-to-end guard for the PC +// re-decode bug: forwarding entry.Caller.PC and re-decoding it in functionFor +// resolved to logrus.NewEntry. +// +// NOTE: this depends on the bridge fix from #3906 (slog-named-loggers). On +// slog-ziti-integration it stays red until this branch is rebased onto the +// fixed slog-named-loggers, which brings the corrected bridge into history. +func TestPrettyHandlerEndToEndResolvesRealCaller(t *testing.T) { + resetDefaultForTest() + var buf bytes.Buffer + popts := DefaultPrettyOptions() + popts.UseColor = false + h, err := BuildPrettyHandler(&buf, DefaultOptions(), popts) + require.NoError(t, err) + + target := logrus.New() + InstallTo(target, h, slog.LevelInfo) + + // A real log call so logrus's getCaller walks the live stack. + logrus.NewEntry(target).Info("hello from pretty test") + + require.NoError(t, h.Close()) + <-h.drainDone + + line := buf.String() + require.Contains(t, line, "TestPrettyHandlerEndToEndResolvesRealCaller", + "rendered caller must be the real call site") + require.NotContains(t, line, "logrus.NewEntry", "caller must not render a logrus frame") +} diff --git a/doc/design/logging-refactor-progress.md b/doc/design/logging-refactor-progress.md index f23fa68d5..d0270fa92 100644 --- a/doc/design/logging-refactor-progress.md +++ b/doc/design/logging-refactor-progress.md @@ -25,6 +25,15 @@ gates each phase before the next can start. ### Phase 1 — Mirror df under openziti (insurance only) +> **Superseded.** PR review of the foundation found behavior gaps in +> dl's PrettyHandler that its options cannot reach (blank labels for +> Fatal/Panic/Trace, color not actually gateable, color keyed on +> stdout while we log to stderr). We replaced it with a hand-rolled +> `logging.PrettyHandler` and removed the df dependency entirely; see +> "Why we hand-roll the pretty handler" in +> [logging-refactor.md](logging-refactor.md). The mirror can stay or +> be archived; nothing depends on it. + **Scope.** Create `github.com/openziti/df` as a pristine mirror of `github.com/michaelquigley/df`, including the `v1.0.0` tag and full history. ziti depends on **upstream df directly**; the mirror exists diff --git a/doc/design/logging-refactor.md b/doc/design/logging-refactor.md index 0463af6b7..57b49b1e1 100644 --- a/doc/design/logging-refactor.md +++ b/doc/design/logging-refactor.md @@ -80,7 +80,7 @@ For this branch specifically: ▼ ┌─ JSONHandler + ReplaceAttr → stderr (prod) │ - └─ dl.PrettyHandler → stderr (dev/console) + └─ logging.PrettyHandler → stderr (dev/console) ``` - **API contract:** vanilla slog at every call site (including code @@ -126,53 +126,44 @@ call site and across our package boundary. Reasons: ecosystem shift. If slog is the long-term winner (it appears so), call sites do not need to migrate again. -We write most handler pieces ourselves (async wrapper, JSON-shape -coercion, named-logger registry, override map). The one component we -borrow is `dl.NewPrettyHandler` for dev/console output — see the next -section for why. +We write all handler pieces ourselves: async wrapper, JSON-shape +coercion, named-logger registry, override map, and the pretty +console handler. -### What we adopt from df/dl, and what we do not +### Why we hand-roll the pretty handler (and don't use df/dl) `df/dl` is a slog-based logging package by the same author as -pfxlog (upstream: `github.com/michaelquigley/df`). We depend on -upstream `github.com/michaelquigley/df` directly and keep an -`openziti/df` mirror purely as insurance (see stability story -below). Reading the source carefully, dl breaks down into three -things, with very different value to us: +pfxlog (upstream: `github.com/michaelquigley/df`), and its +`PrettyHandler` is a direct port of pfxlog's pretty formatter. An +earlier revision of this branch used it for console output, with an +`openziti/df` mirror as a stability fallback. We dropped it after +review found behavior gaps that `dl.Options` cannot reach: -- **PrettyHandler** (dev/console output). A direct port of pfxlog's - pretty handler. Color-aware, timestamp-formatting, channel-aware. - This is the only piece of dl we adopt — it gives us the dev-time - console experience pfxlog users already know, without us - re-implementing it. +- The level switch in dl's `Handle` covers only the four standard + slog levels; our custom Fatal, Panic, and Trace levels render a + blank label. A post-Install `logrus.Fatal` losing its FATAL marker + in operator logs was the blocking finding. +- Color sequences for the timestamp/function/fields segments are + written unconditionally; `UseColor=false` only suppresses the + resets, and `DefaultOptions()` bakes color into the level labels + at construction time. The "text" (no color) format is therefore + unachievable through options. +- Terminal detection stats `os.Stdout` while ziti logs to stderr, + and df's defaults differ from pfxlog's (`StartTimestamp` is + process start rather than start-of-day, no `TrimPrefix`). - Stability story: df is now tagged 1.0, so SemVer applies. Any - incompatible API change requires a `/v2` module path bump and we - pull it in at our leisure (i.e., never inadvertently). On top of - that, we keep an `openziti/df` mirror as a fallback: a pristine, - byte-identical copy of upstream that keeps the same module path - (`github.com/michaelquigley/df`). We use upstream directly day to - day. If upstream ever breaks backwards compatibility or - disappears, we pin the mirror with a one-line - `replace github.com/michaelquigley/df => github.com/openziti/df` - in go.mod, with no source or import-path changes. The - PrettyHandler surface is also small enough that we could replace - it with a hand-rolled pretty handler in an afternoon if all of - these safety nets ever fail. -- **JSON handler**. Worth knowing: dl's JSON path is *just* - `slog.NewJSONHandler` with no `ReplaceAttr`. It produces stdlib - slog JSON shape (uppercase level, nested `source` object), not - pfxlog-compatible JSON. So dl gives us nothing here; we write our - own JSON shape coercion either way (see "Format compatibility"). -- **Channel registry, `dl.Info`/`dl.ChannelLog()` top-level helpers**. - Useful surface for callers that want dl's specific API. We do not - adopt this. Call sites use vanilla slog (`slog.Info`, - `logger.With(...)`, `logging.For(name)`) so the API contract at the - call-site is the standard library. Future replacement of dl with - hand-rolled handlers does not touch any call site. +`logging.PrettyHandler` (`common/logging/pretty.go`) replaces it: +the same pfxlog output shape, all seven level labels, color fully +gated and keyed on the actual output writer (with `PFXLOG_USE_COLOR` +still honored), `_channels`/`_context` rendering, record-time +timestamps, and a correct `WithAttrs`. It is ~150 lines, the size +the design always assumed a hand-rolled replacement would be. -The net: dl is an implementation detail of one of our handlers, not -the foundation. Call sites do not know dl exists. +Worth knowing about dl for context: its JSON path is *just* +`slog.NewJSONHandler` with no `ReplaceAttr` (stdlib shape, not +pfxlog-compatible), and its channel registry / `dl.Info` helpers +are a non-standard API surface we never wanted at call sites. So +nothing else in dl was load-bearing for us. ## Coexistence with pfxlog/logrus diff --git a/doc/design/slog-conversion-plan.md b/doc/design/slog-conversion-plan.md new file mode 100644 index 000000000..4cac43e2b --- /dev/null +++ b/doc/design/slog-conversion-plan.md @@ -0,0 +1,430 @@ +# Slog conversion plan + +Companion to [logging-refactor.md](logging-refactor.md) and +[logging-refactor-progress.md](logging-refactor-progress.md). Where +the progress doc gives a coarse chunking order, this plan is the +code-grounded version: which packages convert in which order, what +channel names they take, and how the special cases (sdk-golang +embedders, cross-repo deps) get handled. + +## Goals + +1. Operators get per-channel debug control over every subsystem + that has a stated triage value. +2. The conversion produces small, reviewable PRs. One chunk = one + PR is the target. +3. Cross-repo deps (channel, transport, sdk-golang) convert in an + order that lets ziti rebase cleanly when each lands. +4. SDK embedders can inject their own logger without + `logging.Install`-ing global state. + +Working assumptions (callable out if they need revising): + +- **Default channel granularity is one channel per Go package.** + Sub-channels appear only when there's a specific operational + reason (high volume, separable failure modes inside the package). +- **The first three to four chunks get deep analysis here.** Later + chunks get a sketch plus a "revisit after the first pass" note, + since the early conversions teach us things we can apply later. + +## Scope inventory + +### ziti repo + +Counts are `pfxlog.` call sites, approximate, gathered with +`grep -rh 'pfxlog\.' --include='*.go'`. The "channel" column is +the proposed name; multiple lines under one package mean splitting +into sub-channels. + +| Package | Files | Sites | Proposed channel(s) | +|---|---:|---:|---| +| `controller/model` | ~30 | ~85 | `controller.model` (likely splits later by area: `.identity`, `.policy`, `.posture`) | +| `controller/internal/routes` | 22 | ~60 | `controller.edge.api` | +| `controller/handler_ctrl` | 24 | ~55 | `controller.ctrl` | +| `controller/handler_edge_ctrl` | 21 | ~50 | `controller.edge.ctrl` | +| `controller/db` | 15 | ~30 | `controller.db` | +| `controller/handler_mgmt` | 12 | ~25 | `controller.mgmt` | +| `controller/storage` | 11 | ~25 | `controller.storage` | +| `controller/network` | 9 | ~20 | `controller.network` | +| `controller/raft` | 7 | ~15 | `controller.raft` | +| `controller/oidc_auth` | 5 | ~10 | `controller.oidc` | +| `controller/handler_peer_ctrl` | 6 | ~10 | `controller.peer` | +| `controller/events` | 4 | ~10 | `controller.events` | +| `controller/sync_strats` | 3 | ~5 | `controller.sync` | +| `controller/env` | 4 | ~10 | `controller.env` | +| `router/xgress_edge` | 8 | 95 | `router.xgress.edge` | +| `router/state` | 14 | 58 | `router.state` | +| `router/env` | 3 | 35 | `router.env` | +| `router/xgress_edge_tunnel` | 5 | 25 | `router.xgress.edge_tunnel` | +| `router/handler_ctrl` | 11 | 21 | `router.ctrl` | +| `router/link` | 3 | 20 | `router.link` | +| `router/xlink_transport` | 5 | 13 | `router.link.transport` | +| `router/forwarder` | 3 | 11 | `router.forwarder` | +| `router/handler_link` | 6 | 9 | `router.link.handler` | +| `router/xgress_transport_udp` | 2 | 8 | `router.xgress.transport_udp` | +| `router/posture` | 3 | 7 | `router.posture` | +| `router/xgress_geneve` | 2 | 6 | `router.xgress.geneve` | +| `router/xgress_sdk` | 1 | 4 | `router.xgress.sdk` | +| Other `router/xgress_*` | — | ≤3 each | `router.xgress.*` (fold into one chunk) | +| `common/pb` | — | 22 | (generated code; do last, low value) | +| `common/agent` | — | 16 | `common.agent` (already touched by Phase 2) | +| `common/agentlog` | — | 8 | already migrated | +| `common/profiler` | — | 7 | `common.profiler` | +| `common/alert` | — | 5 | `common.alert` | +| `tunnel/*` | — | ~17 | `tunnel.*` (per package) | +| `ziti/cmd` | — | 74 | `cli.*` (per subcommand; low value, do as touched) | +| `ziti/run` | — | 10 | already migrated to `Install` | +| `ziti/enroll` | — | 6 | `cli.enroll` | +| `zititest/*` | — | ~60 | test code; convert only as test infra is touched | + +**Total ziti-repo call sites: ~1500** (estimate; includes line +counts not unique-call-site counts). + +### Other openziti repos + +Counts here are from a `pfxlog org:openziti` search slice +(per_page=100, total=583). These are partial — the absolute counts +matter less than the relative ordering and which repos are +dependencies of ziti. + +| Repo | Search hits (slice) | Position in dep graph | Notes | +|---|---:|---|---| +| `openziti/sdk-golang` | 28 | ziti depends on it | Embedder-injected logger required; see SDK pattern below | +| `openziti/channel` | 15 | ziti depends on it | Core message bus; converts cleanly with one channel per logical area | +| `openziti/transport` | 7 | ziti depends on it | TLS / TCP / quic; relatively small surface | +| `openziti/identity` | 3 | ziti depends on it | Identity, certs, configs; small | +| `openziti/xweb` | 4 | ziti depends on it | HTTP server framework | +| `openziti/metrics` | 2 | ziti depends on it | Metrics pipeline; small | +| `openziti/fablab` | 11 | test-only | Lab automation; convert as it's touched | +| `openziti/zrok` | 7 | independent product | Tracks ziti's conversion; not in scope here | +| `openziti/agora` | 2 | independent | Not in scope | +| `openziti/llm-gateway`, `openziti/mcp-gateway` | 2 each | new products | Not in scope | +| `openziti/ziti-doc` | 3 | docs/tutorials | Cosmetic; convert with code samples as they change | +| `openziti/dilithium`, `openziti/ziti-ops` | 1 each | rarely touched | Convert opportunistically | +| `openziti/agent` | 2 | archived (folded into ziti's common/agent) | No conversion needed | + +For ziti's correctness, **only the four deps that ziti pulls into +its binaries matter**: `sdk-golang`, `channel`, `transport`, +`identity` (+ `xweb`, `metrics` to a lesser extent). Those are +the cross-repo critical path. + +## SDK injection pattern + +`sdk-golang` is consumed as a library by ziti embedders (zrok, +ziti-tunnel-sdk-c, third-party apps). Those embedders want control +over their own logging output: they don't want the SDK calling +`logrus.SetOutput(io.Discard)` or installing a global bridge under +their feet. + +The SDK conversion follows a different pattern from the binaries. + +### What the SDK exports + +```go +// Package logging in sdk-golang. Mirrors the surface of +// common/logging but does NOT install anything globally. + +package logging + +// SetLogger installs the *slog.Logger the SDK uses for all of its +// own log lines. Default is slog.Default(), which inherits the +// embedder's existing setup. Calling this is optional; embedders +// who haven't migrated to slog can leave it alone. +func SetLogger(logger *slog.Logger) + +// For returns a channel-scoped logger derived from the configured +// root. The "channel" attr is set to name. Operators of an +// embedding application can adjust per-channel levels via whatever +// surface that application exposes; the SDK does not provide one. +func For(name string) *slog.Logger +``` + +Inside the SDK, every package does `var log = logging.For("ziti.sdk.")` +just like the ziti binary packages do, but the `logging` package +here is `sdk-golang/internal/logging`, not `ziti/v2/common/logging`. + +### What the SDK does NOT do + +- No `Install` function. SDK never touches the embedder's logrus + state. +- No AsyncHandler by default. The SDK uses whatever handler the + embedder's `*slog.Logger` already has. Embedders who want async + buffering bring their own. +- No agent integration. The agent surface is application-level; an + embedder that wants per-channel control over the SDK plumbs that + via its own code. + +### Migration step for sdk-golang + +The conversion is a sequence: + +1. Add `sdk-golang/internal/logging` with `SetLogger` + `For`. + Default root is `slog.Default()`. +2. Add a logrus-to-slog bridge inside the SDK, **scoped to the SDK's + own logrus calls only**. The SDK's `pfxlog.Logger()` calls flow + through the SDK's bridge to the SDK's configured `*slog.Logger`. + This is so the SDK can convert package-by-package without + forcing embedders to migrate all at once. +3. Convert SDK packages to `logging.For(...)`. One package per PR. +4. Once all SDK packages are converted, remove the SDK-internal + bridge. + +The SDK's internal bridge differs from ziti's bridge in scope: it +hooks only the SDK's logrus instance (or none if the SDK isolates +itself to its own logger), not `logrus.StandardLogger`. Open +question for the first SDK PR: does the SDK already use a +non-standard logrus logger, or does it use `pfxlog.Logger()` which +goes through the standard one? + +## Channel taxonomy + +The naming convention is `subsystem.area[.sub-area]`, lowercase, +dot-separated. Proposed full set (grouped to make the operator's +view of available toggles legible): + +**controller.\*** — controller subsystems: +- `controller.ctrl` — control-channel handlers +- `controller.edge.api` — edge REST endpoints (routes) +- `controller.edge.ctrl` — edge control-channel handlers +- `controller.mgmt` — management channel +- `controller.network` — network model +- `controller.model` — entity model (may split further on first pass) +- `controller.db` — boltdb / persistence +- `controller.storage` — controller storage layer +- `controller.raft` — raft / clustering +- `controller.oidc` — OIDC auth +- `controller.peer` — peer-controller links +- `controller.events` — event bus / dispatch +- `controller.sync` — sync strategies +- `controller.env` — controller env / boot + +**router.\*** — router subsystems: +- `router.ctrl` — control-channel client side +- `router.link` — link state + dial/accept +- `router.link.transport` — xlink_transport implementation +- `router.link.handler` — control-channel link handlers +- `router.forwarder` — circuit forwarder +- `router.state` — router state mgmt +- `router.env` — router env / boot +- `router.xgress.edge` — edge-side xgress +- `router.xgress.edge_tunnel` — embedded tunneler xgress +- `router.xgress.transport_udp` — UDP xgress +- `router.xgress.geneve` — geneve xgress +- `router.xgress.sdk` — sdk-backed xgress +- `router.xgress.*` (others) — small variants +- `router.posture` — posture checks +- `router.metrics` — metrics +- `router.inspect` — inspect handlers + +**fabric.\*** — fabric core (cross-repo for now; lives in sdk-golang/xgress): +- `fabric.xgress` — the xgress data path itself + +**tunnel.\*** — embedded tunneler in `ziti tunnel` and in router's +embedded mode: +- `tunnel.intercept`, `tunnel.dns`, `tunnel.host`, etc. + +**common.\*** — shared infrastructure: +- `common.agent` — agent listener + dispatch +- `common.profiler`, `common.alert`, `common.metrics` + +**cli.\*** — ziti CLI subcommands: +- `cli.enroll`, `cli.edge.`, `cli.fabric.`, etc. + Most of these are one-shot and don't benefit much from per-channel + control, but the naming is consistent. + +**ziti.sdk.\*** — SDK call sites (live in sdk-golang): +- `ziti.sdk.identity`, `ziti.sdk.controller`, `ziti.sdk.edge.api`, + `ziti.sdk.xgress`, `ziti.sdk.tunnel`, etc. + +**channel.\*** — channel/v4 internals (cross-repo): +- `channel.framing`, `channel.binding`, `channel.dispatcher`, etc. + +**transport.\*** — transport/v2 internals (cross-repo): +- `transport.tls`, `transport.tcp`, `transport.quic`, etc. + +## Conversion order + +Roughly highest-value-first, where value = operational triage +benefit + bridge fast-path benefit + how often this code shows up +in chaos traces. + +### Chunk 1: `router.link` + `router.link.transport` + `router.link.handler` + +**Files**: `router/link/`, `router/xlink_transport/`, +`router/handler_link/` — ~14 files, ~42 sites. + +**Why first**: The progress doc calls out `linkState.updateStatus` +as the proof-of-pattern conversion bootstrap. Link state, dial, +and accept paths are also where the gossip-links work happens, so +converting this first means gossip-links lands on slog directly. + +**Channels**: +- `router.link` — overarching link state, link map management. +- `router.link.transport` — xlink_transport-specific (dial, accept, + TLS handshake). +- `router.link.handler` — control-channel handlers that mutate link + state. + +**Hot-path watch**: link state churn under chaos. Any new +Warn/Error in this conversion gets bounced; resilience messaging +("link X dropped, retrying") at Info is fine because it's rate- +limited by the underlying event. + +**Tests**: the existing link tests (`tests/link_test.go`, +`testutil/linkschecker.go`) stay on logrus assertions; we update +them to slog assertions in the same PR. + +### Chunk 2: `router.xgress.*` + +**Files**: `router/xgress_edge/` (95 sites — heaviest), +`router/xgress_edge_tunnel/`, `router/xgress_transport_udp/`, +`router/xgress_geneve/`, `router/xgress_sdk/`, smaller variants. + +**Why second**: per-payload paths in xgress. The progress doc +notes "Fabric Debug volume often originates here". Converting lets +operators surgically enable Debug for one xgress flow without +flooding everything. + +**Channels**: one per package, prefixed `router.xgress.`. The +implementations are independent enough that single-channel-for-all +loses the operational benefit. + +**Hot-path watch**: this is the highest-volume conversion in the +plan. Carefully audit each new log line; nothing new at Warn/Error +per packet. Existing Debug lines stay Debug. + +**Note**: core xgress data path lives in `openziti/sdk-golang/xgress`, +not in ziti. That part converts under Chunk 6 (SDK). + +### Chunk 3: `controller.ctrl` + `controller.edge.ctrl` + `controller.peer` + +**Files**: `controller/handler_ctrl/` (~55 sites), +`controller/handler_edge_ctrl/` (~50 sites), +`controller/handler_peer_ctrl/` (~10 sites). + +**Why third**: Control channels are visible in chaos traces and +have a clean subsystem boundary. Three packages, three channels; +all three convert together because they share helpers. + +**Channels**: +- `controller.ctrl` — fabric-side control handlers +- `controller.edge.ctrl` — edge control handlers +- `controller.peer` — peer-controller (HA / clustering) + +**Tests**: handler test files in each package convert in the same +PR. + +### Chunk 4: `controller.network` + `router.forwarder` + `controller.events` + +**Files**: `controller/network/`, `router/forwarder/`, +`controller/events/`. + +**Why fourth**: the digest / forwarding / event paths the design +doc highlighted from chaos traces. Smaller per-package than the +edge handlers but operationally important. + +**Channels**: `controller.network`, `router.forwarder`, +`controller.events`. + +### Chunks 5+: sketch only + +The rest, in rough order. Each gets its own PR; the channel name +is the row in the inventory above. + +5. **`controller.raft` + `controller.storage` + `controller.db`** — + persistence layer. Convert together because they're tightly + coupled and the operational use case is "show me what raft is + doing" which spans all three. +6. **sdk-golang** — see SDK section. Larger surface; do as its own + stream of PRs in the SDK repo. +7. **`controller.model` + `controller.internal.routes` + + `controller.handler_mgmt`** — edge model + REST. Largest by + call-site count, but mostly Info-level boilerplate. Less hot-path + than the others; do once the bridge has been measured. +8. **`router.state` + `router.env` + `controller.env`** — boot / + state mgmt; mostly Info-level startup messages. +9. **transport/v2** — cross-repo. TLS handshake-EOF site lives here; + conversion lets operators enable Debug for the TLS subsystem + specifically during DoS triage. +10. **channel/v4** — cross-repo. Smaller surface but foundational. +11. **`common.*` packages** — agent, profiler, alert, etc. + Convert each as its own small PR. +12. **`tunnel.*`** — embedded tunneler. +13. **`ziti/cmd`** — CLI subcommands. Per-channel control is + low-value here (one-shot commands), but the naming consistency + is worth doing as commands get touched for other reasons. +14. **Generated code (`common/pb`)** — convert last; mechanical and + low-value. +15. **`zititest/*`** — test infrastructure. Convert as test infra + gets touched for other reasons. + +## Cross-repo coordination + +The dep order matters because each downstream rebases on its +upstreams. Two paths: + +**Path A — bridge holds, ziti converts first.** ziti's +`common/logging` foundation is already merged. ziti can convert +its own packages (chunks 1–5, 7, 8) without touching the deps, +because un-migrated dep call sites flow through the bridge at the +global level. Then sdk-golang, transport, channel convert at their +own pace and ziti rebases. + +This is the default path and the one the conversion order above +assumes. + +**Path B — bridge holds, deps convert first.** Possible if a +specific dep change is needed earlier (e.g. transport.tls debug +to triage a production issue). Each dep PR stands alone and ziti +picks them up on its next dep bump. + +The plan does not commit to a specific ordering between the two +paths; they can interleave. + +## Per-conversion PR checklist + +Reproduces the checklist in [logging.md](../logging.md) so it +shows up in this plan too: + +- [ ] All `pfxlog.Logger()` / `pfxlog.ContextLogger(...)` calls in + the package replaced by a package-scoped + `var log = logging.For("subsystem.area")` or by a context- + derived child (`log.With("circuit", c.Id)`). +- [ ] Channel name documented at the top of the package (godoc + comment). +- [ ] No level changes. Lines stay at the level they had. +- [ ] No new Warn/Error at per-event hot-path rate. +- [ ] Tests updated to use slog assertions (`slog.Record` / + `slog.Logger.Enabled` / a recording handler) instead of + logrus-based ones. +- [ ] Where the package's bridged behavior was operator-visible + (per-channel pfxlog overrides), the conversion PR mentions + that operators wanting that surface back must use the agent's + slog channel name. + +## Open questions to resolve as we go + +- **Sub-channel granularity inside `controller.model`.** ~85 sites + in one package is too coarse to be useful. First PR proposes a + split (likely `.identity`, `.policy`, `.posture`, `.config`, + `.service`), reviewed against actual sites. +- **SDK logrus instance.** Does sdk-golang already use a non- + standard logrus logger, or does it call `pfxlog.Logger()` which + goes through `logrus.StandardLogger`? Answer affects how the + SDK's bridge isolation works. Investigate at the start of the + SDK conversion. +- **fablab call sites.** The 11 hits in `openziti/fablab` are + test-infrastructure-only; do we convert them as a single PR or + per-test-area? Decide after the ziti chunks settle. +- **Whether to file a tracking issue per chunk.** The progress doc + raised this question without answering it. Default: yes, one + tracking issue per chunk, opened when the chunk is next in the + queue. Avoids 15+ open issues sitting cold. + +## Out of scope (deferred per the foundation design) + +- PC-based method/file level overrides +- OTel adapter +- Persistent yaml-driven level overrides +- pfxlog removal (the package stays on the dep graph; the bridge + handles its remaining calls indefinitely) diff --git a/doc/logging.md b/doc/logging.md new file mode 100644 index 000000000..f46c4d6f9 --- /dev/null +++ b/doc/logging.md @@ -0,0 +1,171 @@ +# Logging in ziti + +ziti's logging foundation is `log/slog` under the hood, with a `logrus` +bridge so legacy call sites keep working unchanged. Output looks the +same as it did before (pretty by default, JSON with +`--log-formatter=json`). The reason for the change is operator +control: with slog, the agent can set the global level and lift any +*named channel* above the global without restarting the process, and +the bridge keeps logrus's mutex out of the per-record hot path for +call sites that have migrated. + +This note covers what you need to know to write new code, migrate +existing code, and avoid the rough edges. + +## How to write a new log line + +In new code, pick a channel name for your package or subsystem and +hold a logger at package scope: + +```go +package link + +import "github.com/openziti/ziti/v2/common/logging" + +// channelName is the agent-facing name for this package's log records. +// Operators can set its level at runtime with +// ziti agent set-channel-log-level router.link debug +var log = logging.For("router.link") + +func dial(ctx context.Context, remote *Identity) error { + log.Info("dialing", "remote", remote.Id, "underlay", remote.Underlay) + if err := remote.Connect(ctx); err != nil { + log.Warn("dial failed", "remote", remote.Id, "error", err) + return err + } + log.Debug("dialed", "remote", remote.Id, "elapsed", time.Since(start)) + return nil +} +``` + +`logging.For(name)` returns a `*slog.Logger` whose handler binds +`channel: name` as the first attr, so every record carries the +channel it came from. Loggers are cached per name, so subsequent +calls return the same pointer. + +If you have nothing meaningful to channel-name (e.g. one-off CLI +glue), use `slog.Default()`. Anything that participates in the +operator's per-channel control surface should go through `logging.For`. + +## Channel naming + +Use `subsystem.area` form, lowercased, dot-separated. Examples that +match the structure of the codebase: + +- `router.link`, `router.xgress`, `router.forwarder` +- `controller.gossip`, `controller.fabric` +- `fabric.ctrl`, `fabric.router` +- `edge.api`, `edge.identity` +- `transport.tls` + +Pick the name at a *subsystem boundary*, not per-method. Method-level +channels make sense only when you've already discovered that the +subsystem channel is too coarse for triage; the default is one +channel per package or per logical area. + +## The hot-path rule + +Do **not** introduce Warn/Error log lines at per-event rate. A line +that fires once per packet, per circuit message, per gossip tick, or +per connection is a hot path. At those rates, every log call goes +through the leaf handler's write lock, and Warn/Error in particular +defeat the bridge's drop-summary path because they sit above the +default block threshold. + +If you need to see hot-path detail, write it at Debug or Trace and +let the operator enable the channel on demand: + +```go +log.Debug("payload received", "circuit", c.Id, "len", len(p.Data)) +``` + +Reviewers will bounce conversion PRs that introduce new Warn/Error at +hot-path rates. + +## Operator surface + +Once a package uses `logging.For(name)`, operators can drive that +channel via the agent: + +``` +ziti agent set-log-level info # global level, both slog and logrus +ziti agent set-log-level debug # raise everything +ziti agent set-channel-log-level router.link debug # lift one channel +ziti agent clear-channel-log-level router.link # drop back to global +``` + +`set-log-level` moves both worlds in lockstep (the slog Registry's +global AND `logrus.SetLevel`), so legacy pfxlog call sites observe the +same global threshold as slog ones. `set-channel-log-level` is +slog-only by design: it lifts records emitted through +`logging.For(name)` above the global, but `pfxlog.Logger()` / +`pfxlog.ChannelLogger(name)` calls keep observing the global level +until the call site migrates. This is the migration carrot, not an +oversight. + +## Migrating an existing package + +Conversion is mechanical: + +1. Add a package-scoped logger: `var log = logging.For("subsystem.area")`. +2. Document the channel name at the top of the package (godoc + comment). +3. Replace `pfxlog.Logger()` and `pfxlog.ContextLogger(...)` call + sites with `log` (or a context-derived child, e.g. + `log.With("circuit", c.Id)`). +4. Keep every line at the level it had before. Conversion is *not* a + level audit. +5. Don't introduce new Warn/Error at per-event rate. +6. Update tests as needed. slog uses positional `key, value` pairs + rather than `pfxlog.WithField(...)`. + +Until a package is migrated, its `pfxlog.Logger()` calls still work +(via the bridge) but the package has no per-channel agent control. + +## Tunables + +`AsyncOptions` controls the bridge's queue. The defaults are fine for +production; the flags exist so operators can adjust under +investigation: + +| Flag | Default | What it controls | +|---|---|---| +| `--log-queue-size` | 4096 | Bounded capacity of the async log queue | +| `--log-block-threshold` | `warn` | Lowest level that blocks under queue saturation (records below this drop and bump a summary counter) | +| `--log-summary-interval` | 5s | Cadence of the drop-summary record when records have been dropped | + +If you see the bridge dropping records (the periodic summary line +mentions it), the question is usually "what's emitting so much?", +not "is the queue too small?" — but the knob is there. + +## Architecture, briefly + +- [`common/logging`](../common/logging) is the slog foundation: + `AsyncHandler`, the named-logger Registry, the logrus bridge, level + helpers, and the format handlers (pfxlog-shape JSON via + `BuildHandler`, pfxlog-shape pretty via `BuildPrettyHandler`). +- [`common/agentlog`](../common/agentlog) wires the agent's + transport-neutral log-level commands onto + `logging.SetGlobalLevel` / `SetNamedLevel` / `ClearNamedLevel`. The + controller, router, and tunnel binaries each register this from + their `PreRun`. +- Design docs: + [logging-refactor.md](design/logging-refactor.md) and + [logging-refactor-progress.md](design/logging-refactor-progress.md). + +## Deferred, not missing + +The current implementation deliberately does not include: + +- PC-based method/file level overrides. The agent commands operate at + the channel level only. +- An OTel adapter. Records still flow through the local handler + chain; export to OTel is a future addition. +- Persistent yaml-driven level overrides. Level changes via the agent + are in-memory and reset on restart. +- pfxlog removal. Legacy `pfxlog.Logger()` calls keep working through + the bridge; the conversion to `logging.For` is incremental and per + package. + +These are tracked in the design doc and are explicitly out of scope +for the current foundation work. diff --git a/ziti/cmd/cmd.go b/ziti/cmd/cmd.go index 855de488b..9b04128a5 100644 --- a/ziti/cmd/cmd.go +++ b/ziti/cmd/cmd.go @@ -611,6 +611,14 @@ func NewControllerCmd() *cobra.Command { Use: "controller", Short: "Ziti Controller", PersistentPreRun: func(cmd *cobra.Command, args []string) { + // The run subcommand installs the slog logging chain in its own + // PreRun (ziti/run), which supersedes this legacy pfxlog/logrus + // setup and would overwrite it. Skip the block for run so it isn't + // dead, conflicting work; sibling subcommands still rely on it. + if cmd.Name() == "run" { + return + } + if verbose { logrus.SetLevel(logrus.DebugLevel) } @@ -660,6 +668,14 @@ func NewRouterCmd() *cobra.Command { Use: "router", Short: "Ziti Router", PersistentPreRun: func(cmd *cobra.Command, args []string) { + // The run subcommand installs the slog logging chain in its own + // PreRun (ziti/run), which supersedes this legacy pfxlog/logrus + // setup and would overwrite it. Skip the block for run so it isn't + // dead, conflicting work; sibling subcommands still rely on it. + if cmd.Name() == "run" { + return + } + if verbose { logrus.SetLevel(logrus.DebugLevel) } diff --git a/ziti/run/root.go b/ziti/run/root.go index 8918353dc..25997e546 100644 --- a/ziti/run/root.go +++ b/ziti/run/root.go @@ -19,8 +19,10 @@ package run import ( "context" "io" + "log/slog" + "os" - "github.com/michaelquigley/pfxlog" + "github.com/openziti/ziti/v2/common/logging" "github.com/openziti/ziti/v2/ziti/tunnel" "github.com/openziti/ziti/v2/ziti/util" "github.com/sirupsen/logrus" @@ -43,27 +45,60 @@ func (self *Options) BindFlags(cmd *cobra.Command) { cmd.PersistentFlags().BoolVarP(&self.CliAgentEnabled, "cliagent", "a", true, "Enable/disabled CLI Agent (enabled by default)") cmd.PersistentFlags().StringVar(&self.CliAgentAddr, "cli-agent-addr", "", "Specify where CLI Agent should listen (ex: unix:/tmp/myfile.sock or tcp:127.0.0.1:10001)") cmd.PersistentFlags().StringVar(&self.CliAgentAlias, "cli-agent-alias", "", "Alias which can be used by ziti agent commands to find this instance") + logging.AddFlags(cmd.PersistentFlags()) } -func (self *Options) PreRun(_ *cobra.Command, _ []string) { - if self.Verbose { - logrus.SetLevel(logrus.DebugLevel) +func (self *Options) PreRun(cmd *cobra.Command, _ []string) { + // Install the slog handler chain before anything else can log: this wires + // logrus into the bridge and seeds the default Registry so the agent + // callbacks (registered later in Run) have a Registry to drive. + // + // --verbose and --log-formatter are defined both here and on the alias + // parent (ziti controller / ziti router), so read them across the whole + // command chain rather than from self.* alone. That honors the flag + // wherever it appears - "ziti controller --verbose run ..." as well as + // "ziti controller run --verbose ..." - independent of cobra's rules for + // which scope a duplicated flag binds to. + verbose := self.Verbose + if v, ok := changedFlagValue(cmd, "verbose"); ok { + verbose = v == "true" + } + logFormatter := self.LogFormatter + if v, ok := changedFlagValue(cmd, "log-formatter"); ok { + logFormatter = v } - switch self.LogFormatter { - case "pfxlog": - pfxlog.SetFormatter(pfxlog.NewFormatter(pfxlog.DefaultOptions().SetTrimPrefix("github.com/openziti/").StartingToday())) - case "json": - pfxlog.SetFormatter(&logrus.JSONFormatter{TimestampFormat: "2006-01-02T15:04:05.000Z"}) - case "text": - pfxlog.SetFormatter(&logrus.TextFormatter{}) - default: - // let logrus do its own thing + asyncOpts, err := logging.OptionsFromFlags(cmd.Flags()) + if err != nil { + logrus.WithError(err).Fatal("invalid --log-* flags") } + handler, err := logging.BuildHandlerForFormat(os.Stderr, asyncOpts, logFormatter) + if err != nil { + logrus.WithError(err).Fatal("unable to build log handler") + } + initialLevel := slog.LevelInfo + if verbose { + initialLevel = slog.LevelDebug + } + logging.Install(handler, initialLevel) util.LogReleaseVersionCheck() } +// changedFlagValue walks cmd and its ancestors for a persistent flag named +// `name`, returning the value of the first one that was explicitly set. The run +// command and its alias parent both define --verbose / --log-formatter; which +// one a given occurrence binds to depends on its position and cobra internals, +// so reading across the chain lets PreRun honor the flag wherever it appears. +func changedFlagValue(cmd *cobra.Command, name string) (string, bool) { + for c := cmd; c != nil; c = c.Parent() { + if f := c.PersistentFlags().Lookup(name); f != nil && f.Changed { + return f.Value.String(), true + } + } + return "", false +} + func NewRunCmd(out, err io.Writer) *cobra.Command { cmd := &cobra.Command{ Use: "run", diff --git a/ziti/run/run_controller.go b/ziti/run/run_controller.go index cf0644f87..74a65a4b8 100644 --- a/ziti/run/run_controller.go +++ b/ziti/run/run_controller.go @@ -20,6 +20,7 @@ import ( "context" "errors" "fmt" + "log/slog" "net" "os" "os/signal" @@ -33,6 +34,7 @@ import ( "github.com/openziti/foundation/v2/errorz" "github.com/openziti/ziti/v2/common/agent" "github.com/openziti/ziti/v2/common/agentlog" + "github.com/openziti/ziti/v2/common/logging" "github.com/openziti/ziti/v2/common/version" "github.com/openziti/ziti/v2/controller" "github.com/openziti/ziti/v2/controller/server" @@ -70,6 +72,20 @@ func formatRootCause(err error) string { return fmt.Sprintf("%v (root cause: %v)", err, root) } +// versionAttrs returns the build/version fields the controller and router +// startup loggers carry, as slog attrs for the logging.Fatal hard-exit paths. +// A fresh slice is returned on each call so callers can append safely. +func versionAttrs() []slog.Attr { + return []slog.Attr{ + slog.String("version", version.GetVersion()), + slog.String("go-version", version.GetGoVersion()), + slog.String("os", version.GetOS()), + slog.String("arch", version.GetArchitecture()), + slog.String("build-date", version.GetBuildDate()), + slog.String("revision", version.GetRevision()), + } +} + func NewRunControllerCmd() *cobra.Command { action := &ControllerAction{} @@ -115,8 +131,8 @@ func (self *ControllerAction) Run(cmd *cobra.Command, args []string) { ctrlConfig, err := config.LoadConfig(args[0]) if err != nil { - startLogger.WithError(err).Error("error starting ziti-controller") - os.Exit(1) + logging.Fatal(cmd.Context(), "error starting ziti-controller", + append(versionAttrs(), slog.String("error", err.Error()))...) } startLogger = startLogger.WithField("nodeId", ctrlConfig.Id.Token) @@ -124,19 +140,21 @@ func (self *ControllerAction) Run(cmd *cobra.Command, args []string) { if self.fabricController, err = controller.NewController(ctrlConfig, version.GetCmdBuildInfo()); err != nil { cause := formatRootCause(err) - startLogger.WithError(err). - WithField("cause", cause). - Errorf("unable to create fabric controller (cause: %s)", cause) - os.Exit(1) + logging.Fatal(cmd.Context(), "unable to create fabric controller", + append(versionAttrs(), + slog.String("nodeId", ctrlConfig.Id.Token), + slog.String("cause", cause), + slog.String("error", err.Error()))...) } self.edgeController, err = server.NewController(self.fabricController) if err != nil { cause := formatRootCause(err) - startLogger.WithError(err). - WithField("cause", cause). - Errorf("unable to create edge controller (cause: %s)", cause) - os.Exit(1) + logging.Fatal(cmd.Context(), "unable to create edge controller", + append(versionAttrs(), + slog.String("nodeId", ctrlConfig.Id.Token), + slog.String("cause", cause), + slog.String("error", err.Error()))...) } self.edgeController.Initialize() @@ -165,10 +183,11 @@ func (self *ControllerAction) Run(cmd *cobra.Command, args []string) { self.edgeController.Run() if err := self.fabricController.Run(); err != nil { cause := formatRootCause(err) - startLogger.WithError(err). - WithField("cause", cause). - Errorf("fabric controller exited with error (cause: %s)", cause) - os.Exit(1) + logging.Fatal(cmd.Context(), "fabric controller exited with error", + append(versionAttrs(), + slog.String("nodeId", ctrlConfig.Id.Token), + slog.String("cause", cause), + slog.String("error", err.Error()))...) } } diff --git a/ziti/run/run_router.go b/ziti/run/run_router.go index 8c040c1fb..baf3d7919 100644 --- a/ziti/run/run_router.go +++ b/ziti/run/run_router.go @@ -18,9 +18,11 @@ package run import ( "fmt" + "log/slog" "github.com/openziti/xweb/v3" "github.com/openziti/ziti/v2/common/bindpoints" + "github.com/openziti/ziti/v2/common/logging" "github.com/openziti/ziti/v2/common/version" "github.com/openziti/ziti/v2/router" "github.com/openziti/ziti/v2/router/env" @@ -69,8 +71,10 @@ func (self *RouterAction) Run(cmd *cobra.Command, args []string) { config, err := env.LoadConfig(args[0]) if err != nil { - startLogger.WithError(err).Error("error loading ziti router config") - panic(err) + logging.Fatal(cmd.Context(), "error loading ziti router config", + append(versionAttrs(), + slog.String("configFile", args[0]), + slog.String("error", err.Error()))...) } config.Edge.ForceExtendEnrollment = self.ForceCertificateExtension diff --git a/ziti/tunnel/root.go b/ziti/tunnel/root.go index 8f5a3609b..05ca97a39 100644 --- a/ziti/tunnel/root.go +++ b/ziti/tunnel/root.go @@ -17,6 +17,7 @@ package tunnel import ( + "log/slog" "net" "os" "path/filepath" @@ -24,6 +25,7 @@ import ( "time" "github.com/openziti/sdk-golang/ziti/sdkinfo" + "github.com/openziti/ziti/v2/common/logging" "github.com/openziti/ziti/v2/ziti/cmd/common" "github.com/openziti/ziti/v2/ziti/util" @@ -73,6 +75,7 @@ func NewTunnelCmd(legacy bool) *cobra.Command { root.PersistentFlags().BoolVar(&sdkFlowControl, "sdk-flow-control", true, "enables sdk flow control") root.PersistentFlags().Uint8Var(&maxDefaultConnections, "default-connections", 2, "sets the desired number of default connections") root.PersistentFlags().Uint8Var(&maxControlConnections, "control-connections", 1, "sets the desired number of control connections") + logging.AddFlags(root.PersistentFlags()) root.AddCommand(NewHostCmd()) root.AddCommand(NewProxyCmd()) for _, cmdF := range hostSpecificCmds { @@ -104,20 +107,20 @@ func rootPreRun(cmd *cobra.Command, _ []string) { if err != nil { println("err") } + asyncOpts, err := logging.OptionsFromFlags(cmd.Flags()) + if err != nil { + logrus.WithError(err).Fatal("invalid --log-* flags") + } + handler, err := logging.BuildHandlerForFormat(os.Stderr, asyncOpts, logFormatter) + if err != nil { + logrus.WithError(err).Fatal("unable to build log handler") + } + initialLevel := slog.LevelInfo if verbose { - logrus.SetLevel(logrus.DebugLevel) + initialLevel = slog.LevelDebug } + logging.Install(handler, initialLevel) - switch logFormatter { - case "pfxlog": - logrus.SetFormatter(pfxlog.NewFormatter(pfxlog.DefaultOptions().StartingToday())) - case "json": - logrus.SetFormatter(&logrus.JSONFormatter{TimestampFormat: "2006-01-02T15:04:05.000Z"}) - case "text": - logrus.SetFormatter(&logrus.TextFormatter{}) - default: - // let logrus do its own thing - } util.LogReleaseVersionCheck() }