mirror of
https://github.com/openziti/ziti.git
synced 2026-09-10 00:35:41 +00:00
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
This commit is contained in:
Paul Lorenz
+70
-4
@@ -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 <name> <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
|
||||
<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
|
||||
|
||||
|
||||
|
||||
@@ -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
|
||||
}
|
||||
}
|
||||
|
||||
@@ -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 }
|
||||
@@ -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")
|
||||
}
|
||||
@@ -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.
|
||||
|
||||
@@ -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
|
||||
|
||||
@@ -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
|
||||
}
|
||||
@@ -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)
|
||||
}
|
||||
}
|
||||
|
||||
@@ -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")
|
||||
}
|
||||
|
||||
@@ -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
|
||||
}
|
||||
@@ -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")
|
||||
}
|
||||
@@ -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
|
||||
|
||||
@@ -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
|
||||
|
||||
|
||||
@@ -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.<area>")`
|
||||
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.<verb>`, `cli.fabric.<verb>`, 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)
|
||||
+171
@@ -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.
|
||||
@@ -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)
|
||||
}
|
||||
|
||||
+48
-13
@@ -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",
|
||||
|
||||
+33
-14
@@ -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()))...)
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
@@ -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
|
||||
|
||||
+14
-11
@@ -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()
|
||||
}
|
||||
|
||||
|
||||
Reference in New Issue
Block a user