From e5c73e5a9f6547523689ffacf092458143f9c8a6 Mon Sep 17 00:00:00 2001 From: lemo-o <21benjaminhall@gmail.com> Date: Tue, 20 Oct 2026 09:35:28 -0600 Subject: [PATCH] logging --- cmd/iontk/flagdoc.go | 4 + cmd/iontk/main.go | 4 + cmd/iontk/root.go | 31 ++- cmd/iontk/search.go | 4 + internal/app/auth.go | 7 + internal/app/cli.go | 46 +++++ internal/app/client.go | 17 +- internal/app/flags.go | 4 + internal/app/logging_test.go | 99 +++++++++ internal/app/signin.go | 3 + internal/app/tenant.go | 3 + internal/config/config.go | 4 + internal/config/reset.go | 3 +- internal/config/reset_test.go | 7 + internal/logging/logging.go | 309 +++++++++++++++++++++++++++++ internal/logging/logging_test.go | 194 ++++++++++++++++++ internal/logging/recent_test.go | 28 +++ internal/logging/redact.go | 153 ++++++++++++++ internal/logging/redact_test.go | 148 ++++++++++++++ internal/saseauth/browser.go | 26 ++- internal/saseauth/identity_test.go | 4 +- internal/saseauth/logging_test.go | 97 +++++++++ internal/saseauth/oauth.go | 4 + internal/saseauth/seed.go | 22 +- internal/saseauth/seed_test.go | 16 +- internal/saseauth/source.go | 37 +++- internal/saseauth/source_test.go | 4 +- internal/tui/ha.go | 5 + internal/tui/multitenant.go | 4 + internal/tui/settings.go | 23 +++ internal/tui/settings_test.go | 56 ++++++ internal/tui/tui.go | 3 + internal/tui/tuimenu.go | 2 + 33 files changed, 1347 insertions(+), 24 deletions(-) create mode 100644 internal/app/logging_test.go create mode 100644 internal/logging/logging.go create mode 100644 internal/logging/logging_test.go create mode 100644 internal/logging/recent_test.go create mode 100644 internal/logging/redact.go create mode 100644 internal/logging/redact_test.go create mode 100644 internal/saseauth/logging_test.go diff --git a/cmd/iontk/flagdoc.go b/cmd/iontk/flagdoc.go index 0299ba8..6b7e0ea 100644 --- a/cmd/iontk/flagdoc.go +++ b/cmd/iontk/flagdoc.go @@ -68,6 +68,9 @@ var flagGroups = []struct { {"Rich data", "The TUI's third element mode reads the portal instead of opening a session. Its panes are defined in YAML: `--views` points at a file instead of `views.yaml` in the config directory, which is also how a `--fixtures` run gets views of its own.", []string{ "views", }}, + {"Logging", "Every run writes a JSON log to `logs/` in the config directory, keeping the last ten. Secrets never reach it: tokens and passwords are logged as a fingerprint — the last four characters and a length. With an explicit level, a headless run gets the same records on stderr as text.", []string{ + "log", "log-level", + }}, {"Appearance", "Color schemes are YAML too: `--themes` points at a file whose schemes are added to the built-in ones, or replace one of the same name, instead of `themes.yaml` in the config directory. The same escape hatch as `--views`, for the same reason.", []string{ "themes", }}, @@ -116,6 +119,7 @@ func writeFlagDocs(w io.Writer, root *cobra.Command) error { {"SCM_TOKEN", "bearer token, overriding the service account entirely"}, {"ION_USER", "device CLI login, required with `--cmd`"}, {"ION_PASS", "device CLI password, required with `--cmd`"}, + {"ION_LOG_LEVEL", "log level; `--log-level` wins"}, } { fmt.Fprintf(&b, "| `%s` | %s |\n", e[0], e[1]) } diff --git a/cmd/iontk/main.go b/cmd/iontk/main.go index 612dbcd..3a70e0a 100644 --- a/cmd/iontk/main.go +++ b/cmd/iontk/main.go @@ -7,12 +7,16 @@ import ( "fmt" "os" "os/signal" + + "tyrtop.com/iontk/internal/logging" ) func main() { ctx, cancel := signal.NotifyContext(context.Background(), os.Interrupt) defer cancel() + defer logging.Close() + if err := rootCmd.ExecuteContext(ctx); err != nil { fmt.Fprintln(os.Stderr, err) os.Exit(1) diff --git a/cmd/iontk/root.go b/cmd/iontk/root.go index c1c3313..58c8222 100644 --- a/cmd/iontk/root.go +++ b/cmd/iontk/root.go @@ -2,10 +2,14 @@ package main import ( "fmt" + "io" + "os" + "strings" "github.com/joho/godotenv" "github.com/spf13/cobra" "tyrtop.com/iontk/internal/app" + "tyrtop.com/iontk/internal/logging" "tyrtop.com/iontk/internal/tui" ) @@ -27,6 +31,13 @@ var ( flagThemes string ) +func wantsTheTerminal(cmd *cobra.Command) bool { + if cmd.Parent() != nil { + return cmd.Name() == "shell" + } + return len(flagCommands) == 0 && flagSearch == "" +} + var rootCmd = &cobra.Command{ Use: "iontk [flags]", Short: "API-driven ION CLI management for Prisma SD-WAN", @@ -64,7 +75,23 @@ login from the keyring, so --cmd needs none of these once one is signed in.`, PersistentPreRunE: func(cmd *cobra.Command, args []string) error { _ = godotenv.Load() app.ThemesFile = flagThemes - return loadFixtures(cmd.ErrOrStderr()) + if err := loadFixtures(cmd.ErrOrStderr()); err != nil { + return err + } + + var toStderr io.Writer + if app.LogLevelAsked() != "" && !wantsTheTerminal(cmd) { + toStderr = cmd.ErrOrStderr() + } + if err := app.StartLogging(app.OpenStore(), toStderr); err != nil { + if app.LogLevel != "" { + return err + } + fmt.Fprintln(cmd.ErrOrStderr(), err) + } + logging.L().Info("iontk starting", "version", buildVersion(), + "command", cmd.CommandPath(), "args", strings.Join(os.Args[1:], " ")) + return nil }, RunE: func(cmd *cobra.Command, args []string) error { @@ -124,6 +151,8 @@ func init() { pf.StringVar(&flagFixtures, "fixtures", "", "YAML file of fake tenants, elements and CLI responses to run against instead of real hardware") pf.StringVar(&flagViews, "views", "", "YAML file of rich-data views to use instead of views.yaml in the config directory") pf.StringVar(&flagThemes, "themes", "", "YAML file of color schemes to add to the built-in ones, instead of themes.yaml in the config directory") + pf.StringVar(&app.LogFile, "log", "", "write this run's log here instead of a stamped file under logs/ in the config directory") + pf.StringVar(&app.LogLevel, "log-level", "", "how much to log: "+strings.Join(logging.LevelNames(), ", ")+" (default info, or ION_LOG_LEVEL)") pf.StringVar(&app.Defaults.TSGID, "tsg", "", "tenant service group ID (overrides SCM_TSG_ID)") pf.StringVar(&flagFormat, "format", "", `batch output format: "json", "jsonl", "text", "table" or "csv" (default from settings, else json)`) pf.StringVar(&flagOrient, "orientation", "", `row order for "table" and "csv": "ion" groups each element's commands, "command" puts one command across the fleet together (default from settings, else ion)`) diff --git a/cmd/iontk/search.go b/cmd/iontk/search.go index 10c41d5..6085a15 100644 --- a/cmd/iontk/search.go +++ b/cmd/iontk/search.go @@ -17,6 +17,7 @@ import ( "golang.org/x/term" "tyrtop.com/iontk/internal/app" "tyrtop.com/iontk/internal/config" + "tyrtop.com/iontk/internal/logging" "tyrtop.com/iontk/internal/output" "tyrtop.com/iontk/internal/sase" "tyrtop.com/iontk/internal/sase/api" @@ -344,11 +345,14 @@ func (fl *fleet) fetch(ctx context.Context, t config.Tenant, cached *config.Elem els, err := c.ListElements(ctx) if err != nil { + logging.L().Warn("element list failed", "tsg", t.TSGID, "tenant", t.Name, "err", err) return nil, nil, err } sites := search.SiteMap{} ss, siteErr := c.ListSites(ctx) + logging.L().Info("elements loaded", "tsg", t.TSGID, "tenant", t.Name, + "elements", len(els), "sites", len(ss), "site_err", siteErr) for _, s := range ss { sites[t.TSGID+"/"+s.ID] = s.Name } diff --git a/internal/app/auth.go b/internal/app/auth.go index 0b29c56..63197c4 100644 --- a/internal/app/auth.go +++ b/internal/app/auth.go @@ -10,6 +10,7 @@ import ( "tyrtop.com/iontk/internal/config" "tyrtop.com/iontk/internal/fixture" + "tyrtop.com/iontk/internal/logging" "tyrtop.com/iontk/internal/sase/api" "tyrtop.com/iontk/internal/saseauth" ) @@ -111,6 +112,12 @@ func ShortAuthError(err error) string { if err == nil { return "" } + short := shortAuthError(err) + logging.L().Info("auth error shortened", "short", short, "err", err) + return short +} + +func shortAuthError(err error) string { text := err.Error() switch { case strings.Contains(text, "did not complete within"): diff --git a/internal/app/cli.go b/internal/app/cli.go index 543bc84..d19ee3a 100644 --- a/internal/app/cli.go +++ b/internal/app/cli.go @@ -3,12 +3,15 @@ package app import ( "errors" "fmt" + "io" + "log/slog" "os" "path/filepath" "strings" "tyrtop.com/iontk/internal/clock" "tyrtop.com/iontk/internal/config" + "tyrtop.com/iontk/internal/logging" "tyrtop.com/iontk/internal/ui" ) @@ -150,3 +153,46 @@ func TenantChoices(cfg *config.Config) string { } return "saved tenants: " + strings.Join(names, ", ") } + +var ( + LogFile string + LogLevel string +) + +func LogsPath(st *config.Store) string { + if LogFile != "" { + return LogFile + } + if st == nil { + return "" + } + return st.LogsDir() +} + +func LogLevelAsked() string { + if LogLevel != "" { + return LogLevel + } + return os.Getenv("ION_LOG_LEVEL") +} + +func StartLogging(st *config.Store, stderr io.Writer) error { + level, lvlErr := logging.ParseLevel(LogLevelAsked()) + if lvlErr != nil { + if LogLevel != "" { + return lvlErr + } + level = slog.LevelInfo + } + + opt := logging.Options{Level: level, Stderr: stderr} + if LogFile != "" { + opt.File = LogFile + } else if st != nil { + opt.Dir = st.LogsDir() + } + if _, err := logging.Start(opt); err != nil { + return fmt.Errorf("logging: %w", err) + } + return lvlErr +} diff --git a/internal/app/client.go b/internal/app/client.go index 09c5993..5ff457e 100644 --- a/internal/app/client.go +++ b/internal/app/client.go @@ -8,10 +8,17 @@ import ( "time" "tyrtop.com/iontk/internal/config" + "tyrtop.com/iontk/internal/logging" "tyrtop.com/iontk/internal/sase/api" ) func NewClient(ctx context.Context, st *config.Store, f Flags, logw io.Writer) (*api.Client, error) { + log := logging.L().With("tsg", f.TSGID) + chose := func(what string) { + fmt.Fprintln(logw, what) + log.Info("credential path", "path", what) + } + wsClient := &http.Client{Transport: &http.Transport{ MaxConnsPerHost: f.Concurrency, MaxIdleConnsPerHost: 50, @@ -28,28 +35,30 @@ func NewClient(ctx context.Context, st *config.Store, f Flags, logw io.Writer) ( } if Fixture != nil { - fmt.Fprintln(logw, "using fixtures") + chose("using fixtures") fake := &http.Client{Transport: Fixture.Transport(f.TSGID)} const fixtureRPS = 1000 return setup(api.NewClient(fake, fake, "fixture", f.Verbose, fixtureRPS, fixtureRPS)), nil } if f.Token != "" { - fmt.Fprintln(logw, "using SCM_TOKEN") + chose("using SCM_TOKEN") return setup(api.NewClient(httpClient, wsClient, f.Token, f.Verbose, f.RPS, f.Burst)), nil } if f.BrowserAuth { - fmt.Fprintln(logw, "using the browser sign-in for this tenant") + chose("using the browser sign-in for this tenant") src := BrowserSource(f, httpClient, st) c, err := api.NewTokenSourceClient(ctx, httpClient, wsClient, src, f.RefreshMargin, f.Verbose, f.RPS, f.Burst) if err != nil { + log.Warn("the browser credential did not produce a token", "err", err) return nil, err } return setup(c), nil } - fmt.Fprintln(logw, "minting from service account") + chose("minting from service account") c, err := api.NewServiceAccountClient(ctx, httpClient, wsClient, f.ClientID, f.ClientSecret, f.TSGID, f.RefreshMargin, f.Verbose, f.RPS, f.Burst) if err != nil { + log.Warn("the service account did not mint a token", "err", err, "client_id", f.ClientID) return nil, err } return setup(c), nil diff --git a/internal/app/flags.go b/internal/app/flags.go index daad44e..4a099c2 100644 --- a/internal/app/flags.go +++ b/internal/app/flags.go @@ -5,6 +5,7 @@ import ( "os" "time" + "tyrtop.com/iontk/internal/logging" "tyrtop.com/iontk/internal/sase" "tyrtop.com/iontk/internal/sase/ioncli" ) @@ -90,6 +91,9 @@ func BaseFlags() Flags { if Defaults.TSGID != "" { f.TSGID = Defaults.TSGID } + logging.Mask(f.Token) + logging.Mask(f.ClientSecret) + logging.Mask(f.IONPassword) return f } diff --git a/internal/app/logging_test.go b/internal/app/logging_test.go new file mode 100644 index 0000000..686e43a --- /dev/null +++ b/internal/app/logging_test.go @@ -0,0 +1,99 @@ +package app + +import ( + "context" + "io" + "os" + "path/filepath" + "strings" + "testing" + + "tyrtop.com/iontk/internal/logging" +) + +func logTo(t *testing.T, file, level string) { + t.Helper() + LogFile, LogLevel = file, level + t.Cleanup(func() { + LogFile, LogLevel = "", "" + logging.Close() + }) +} + +func TestStartLoggingWritesWhereTheFlagSays(t *testing.T) { + where := filepath.Join(t.TempDir(), "runs", "this-one.log") + logTo(t, where, "") + + if err := StartLogging(nil, nil); err != nil { + t.Fatalf("StartLogging() error = %v", err) + } + if got := logging.Path(); got != where { + t.Errorf("Path() = %q, want %q", got, where) + } + logging.L().Info("hello") + if _, err := os.Stat(where); err != nil { + t.Errorf("stat %s: %v", where, err) + } +} + +func TestStartLoggingRefusesALevelTheFlagGotWrong(t *testing.T) { + logTo(t, filepath.Join(t.TempDir(), "a.log"), "chatty") + + if err := StartLogging(nil, nil); err == nil { + t.Fatal("StartLogging() error = nil, want the bad --log-level reported") + } +} + +func TestABadLevelInTheEnvironmentStillLeavesALog(t *testing.T) { + t.Setenv("ION_LOG_LEVEL", "chatty") + logTo(t, filepath.Join(t.TempDir(), "a.log"), "") + + err := StartLogging(nil, nil) + if err == nil { + t.Error("StartLogging() error = nil, want the bad ION_LOG_LEVEL reported") + } + if !logging.On() { + t.Error("nothing is being logged; a bad environment variable must not cost the run its log") + } +} + +func TestLoggingOffWritesNothing(t *testing.T) { + dir := t.TempDir() + logTo(t, filepath.Join(dir, "a.log"), "off") + + if err := StartLogging(nil, nil); err != nil { + t.Fatalf("StartLogging() error = %v", err) + } + logging.L().Error("not this either") + if entries, _ := os.ReadDir(dir); len(entries) != 0 { + t.Errorf("%q holds %d files, want none", dir, len(entries)) + } +} + +func TestTheCredentialPathReachesTheLog(t *testing.T) { + where := filepath.Join(t.TempDir(), "a.log") + logTo(t, where, "") + if err := StartLogging(nil, nil); err != nil { + t.Fatalf("StartLogging() error = %v", err) + } + + f := BaseFlags() + f.Token, f.TSGID = "scm-token-value-0001", "1436146912" + if _, err := NewClient(context.Background(), nil, f, io.Discard); err != nil { + t.Fatalf("NewClient() error = %v", err) + } + + b, err := os.ReadFile(where) + if err != nil { + t.Fatal(err) + } + body := string(b) + for _, want := range []string{"credential path", "using SCM_TOKEN", "1436146912"} { + if !strings.Contains(body, want) { + t.Errorf("the log never says %q, which is the one line the TUI used to throw away:\n%s", want, body) + } + } + if strings.Contains(body, f.Token) { + t.Errorf("the bearer token reached the log:\n%s", body) + } +} diff --git a/internal/app/signin.go b/internal/app/signin.go index fe7b215..17567a4 100644 --- a/internal/app/signin.go +++ b/internal/app/signin.go @@ -8,6 +8,7 @@ import ( "time" "tyrtop.com/iontk/internal/config" + "tyrtop.com/iontk/internal/logging" "tyrtop.com/iontk/internal/saseauth" ) @@ -45,12 +46,14 @@ type TenantWarm struct { func WarmEach(ctx context.Context, st *config.Store, tenants []config.Tenant) []TenantWarm { httpClient := &http.Client{Timeout: Defaults.HTTPTimeout} out := make([]TenantWarm, 0, len(tenants)) + logging.L().Info("warming every tenant", "tenants", len(tenants)) for _, t := range tenants { if !t.UsesBrowser() { out = append(out, TenantWarm{Tenant: t, Skipped: true}) continue } _, _, err := tenantSource(st, httpClient, t.TSGID).Token(ctx) + logging.L().Info("tenant warmed", "tsg", t.TSGID, "tenant", t.Name, "err", err) out = append(out, TenantWarm{Tenant: t, Err: err}) if ctx.Err() != nil { return out diff --git a/internal/app/tenant.go b/internal/app/tenant.go index 4437f6a..f43866a 100644 --- a/internal/app/tenant.go +++ b/internal/app/tenant.go @@ -4,6 +4,7 @@ import ( "os" "tyrtop.com/iontk/internal/config" + "tyrtop.com/iontk/internal/logging" ) func tenantFromEnv() (config.Tenant, bool) { @@ -59,6 +60,8 @@ func TenantFlags(st *config.Store, t config.Tenant, ionUser string) Flags { } } } + logging.Mask(f.ClientSecret) + logging.Mask(f.IONPassword) return f } diff --git a/internal/config/config.go b/internal/config/config.go index 62270e0..25218c2 100644 --- a/internal/config/config.go +++ b/internal/config/config.go @@ -7,6 +7,8 @@ import ( "path/filepath" "strings" "sync" + + "tyrtop.com/iontk/internal/logging" ) type IONUser struct { @@ -139,6 +141,8 @@ func (s *Store) configPath() string { return filepath.Join(s.Root, "config.json" func (s *Store) BrowserDir() string { return filepath.Join(s.Root, "browser") } +func (s *Store) LogsDir() string { return filepath.Join(s.Root, logging.DirName) } + func (s *Store) Config() (*Config, error) { b, err := os.ReadFile(s.configPath()) if os.IsNotExist(err) { diff --git a/internal/config/reset.go b/internal/config/reset.go index ea8e893..aa42c1f 100644 --- a/internal/config/reset.go +++ b/internal/config/reset.go @@ -33,7 +33,8 @@ func (s *Store) Reset() error { errs = append(errs, removePath(p.Path())) } - errs = append(errs, removePath(s.BrowserDir()), removePath(s.configPath())) + errs = append(errs, removePath(s.BrowserDir()), removePath(s.LogsDir()), + removePath(s.configPath())) return errors.Join(errs...) } diff --git a/internal/config/reset_test.go b/internal/config/reset_test.go index 4035177..3f0ef42 100644 --- a/internal/config/reset_test.go +++ b/internal/config/reset_test.go @@ -52,6 +52,12 @@ func savedStore(t *testing.T) (*Store, *Config) { if err := os.WriteFile(filepath.Join(st.BrowserDir(), "Default", "Cookies"), []byte("session"), 0o600); err != nil { t.Fatal(err) } + if err := os.MkdirAll(st.LogsDir(), 0o700); err != nil { + t.Fatal(err) + } + if err := os.WriteFile(filepath.Join(st.LogsDir(), "iontk-20261020-091403.log"), []byte("{}\n"), 0o600); err != nil { + t.Fatal(err) + } return st, cfg } @@ -85,6 +91,7 @@ func TestResetLeavesNothingBehind(t *testing.T) { st.cacheDir(), st.commandsPath(), st.BrowserDir(), + st.LogsDir(), filepath.Join(st.Root, "secrets.json"), } { if _, err := os.Stat(path); !os.IsNotExist(err) { diff --git a/internal/logging/logging.go b/internal/logging/logging.go new file mode 100644 index 0000000..7246fe0 --- /dev/null +++ b/internal/logging/logging.go @@ -0,0 +1,309 @@ +package logging + +import ( + "context" + "crypto/rand" + "encoding/hex" + "encoding/json" + "fmt" + "io" + "log/slog" + "os" + "path/filepath" + "sort" + "strings" + "sync" + "time" + + "tyrtop.com/iontk/internal/clock" +) + +const ( + DirName = "logs" + DefaultKeep = 10 + + levelOff = slog.Level(32) +) + +type Options struct { + Dir string + File string + Level slog.Level + Keep int + Stderr io.Writer + Now time.Time + RunID string +} + +var ( + mu sync.Mutex + current = slog.New(slog.DiscardHandler) + file *os.File + path string + level = slog.LevelInfo + runID string + problem error +) + +func L() *slog.Logger { + mu.Lock() + defer mu.Unlock() + return current +} + +func Path() string { + mu.Lock() + defer mu.Unlock() + return path +} + +func Level() slog.Level { + mu.Lock() + defer mu.Unlock() + return level +} + +func LevelName() string { return levelName(Level()) } + +func RunID() string { + mu.Lock() + defer mu.Unlock() + return runID +} + +func Problem() error { + mu.Lock() + defer mu.Unlock() + return problem +} + +func On() bool { return Path() != "" } + +func Start(opt Options) (*slog.Logger, error) { + if opt.Now.IsZero() { + opt.Now = time.Now() + } + if opt.Keep <= 0 { + opt.Keep = DefaultKeep + } + if opt.RunID == "" { + opt.RunID = newRunID() + } + + if opt.Level == levelOff { + set(slog.New(slog.DiscardHandler), nil, "", opt, nil) + return L(), nil + } + + f, where, err := openFile(opt) + if err != nil { + set(slog.New(slog.DiscardHandler), nil, "", opt, err) + return L(), err + } + + hs := []slog.Handler{redact(slog.NewJSONHandler(f, &slog.HandlerOptions{Level: opt.Level}))} + if opt.Stderr != nil { + hs = append(hs, redact(slog.NewTextHandler(opt.Stderr, &slog.HandlerOptions{Level: opt.Level}))) + } + + log := slog.New(fanout(hs)).With("run", opt.RunID) + set(log, f, where, opt, nil) + return log, nil +} + +func set(log *slog.Logger, f *os.File, where string, opt Options, err error) { + mu.Lock() + defer mu.Unlock() + if file != nil { + file.Close() + } + current, file, path, level, runID, problem = log, f, where, opt.Level, opt.RunID, err + slog.SetDefault(log) +} + +func openFile(opt Options) (*os.File, string, error) { + where := opt.File + if where == "" { + if opt.Dir == "" { + return nil, "", fmt.Errorf("no directory to log to") + } + where = filepath.Join(opt.Dir, "iontk-"+opt.Now.Format("20060102-150405")+".log") + } + dir := filepath.Dir(where) + if err := os.MkdirAll(dir, 0o700); err != nil { + return nil, "", fmt.Errorf("create %s: %w", dir, err) + } + prune(dir, opt.Keep-1) + + f, err := os.OpenFile(where, os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0o600) + if err != nil { + return nil, "", fmt.Errorf("open %s: %w", where, err) + } + return f, where, nil +} + +func prune(dir string, keep int) { + entries, err := os.ReadDir(dir) + if err != nil { + return + } + var names []string + for _, e := range entries { + if !e.IsDir() && strings.HasPrefix(e.Name(), "iontk-") && strings.HasSuffix(e.Name(), ".log") { + names = append(names, e.Name()) + } + } + sort.Strings(names) + if keep < 0 { + keep = 0 + } + for i := 0; i < len(names)-keep; i++ { + os.Remove(filepath.Join(dir, names[i])) + } +} + +func Close() error { + mu.Lock() + defer mu.Unlock() + err := error(nil) + if file != nil { + err = file.Close() + } + current, file, path, problem = slog.New(slog.DiscardHandler), nil, "", nil + level, runID = slog.LevelInfo, "" + slog.SetDefault(current) + return err +} + +const tailWindow = 64 << 10 + +func Tail(n int) []string { + where := Path() + if where == "" || n <= 0 { + return nil + } + f, err := os.Open(where) + if err != nil { + return nil + } + defer f.Close() + + fi, err := f.Stat() + if err != nil { + return nil + } + at := int64(0) + if fi.Size() > tailWindow { + at = fi.Size() - tailWindow + } + b, err := io.ReadAll(io.NewSectionReader(f, at, fi.Size()-at)) + if err != nil { + return nil + } + + var out []string + for _, line := range strings.Split(strings.TrimSpace(string(b)), "\n") { + if strings.TrimSpace(line) != "" { + out = append(out, line) + } + } + if len(out) > n { + out = out[len(out)-n:] + } + return out +} + +func ParseLevel(s string) (slog.Level, error) { + switch strings.ToLower(strings.TrimSpace(s)) { + case "", "info": + return slog.LevelInfo, nil + case "debug": + return slog.LevelDebug, nil + case "warn", "warning": + return slog.LevelWarn, nil + case "error", "err": + return slog.LevelError, nil + case "off", "none": + return levelOff, nil + } + return 0, fmt.Errorf("unknown log level %q: want one of %s", s, strings.Join(LevelNames(), ", ")) +} + +func LevelNames() []string { return []string{"debug", "info", "warn", "error", "off"} } + +func levelName(l slog.Level) string { + if l == levelOff { + return "off" + } + return strings.ToLower(l.String()) +} + +func newRunID() string { + var b [4]byte + if _, err := rand.Read(b[:]); err != nil { + return fmt.Sprintf("%08x", time.Now().UnixNano()) + } + return hex.EncodeToString(b[:]) +} + +type fanout []slog.Handler + +func (f fanout) Enabled(ctx context.Context, l slog.Level) bool { + for _, h := range f { + if h.Enabled(ctx, l) { + return true + } + } + return false +} + +func (f fanout) Handle(ctx context.Context, rec slog.Record) error { + var err error + for _, h := range f { + if !h.Enabled(ctx, rec.Level) { + continue + } + if e := h.Handle(ctx, rec.Clone()); e != nil && err == nil { + err = e + } + } + return err +} + +func (f fanout) WithAttrs(attrs []slog.Attr) slog.Handler { + out := make(fanout, len(f)) + for i, h := range f { + out[i] = h.WithAttrs(attrs) + } + return out +} + +func (f fanout) WithGroup(name string) slog.Handler { + out := make(fanout, len(f)) + for i, h := range f { + out[i] = h.WithGroup(name) + } + return out +} + +func Recent(n int) []string { + lines := Tail(n) + out := make([]string, 0, len(lines)) + for _, line := range lines { + out = append(out, summarize(line)) + } + return out +} + +func summarize(line string) string { + var rec struct { + Time time.Time `json:"time"` + Level string `json:"level"` + Msg string `json:"msg"` + } + if err := json.Unmarshal([]byte(line), &rec); err != nil || rec.Msg == "" { + return line + } + return rec.Time.In(clock.Zone()).Format("15:04:05 MST") + " " + + strings.ToLower(rec.Level) + " " + rec.Msg +} diff --git a/internal/logging/logging_test.go b/internal/logging/logging_test.go new file mode 100644 index 0000000..45e0579 --- /dev/null +++ b/internal/logging/logging_test.go @@ -0,0 +1,194 @@ +package logging + +import ( + "encoding/json" + "log/slog" + "os" + "path/filepath" + "strings" + "testing" + "time" +) + +func start(t *testing.T, opt Options) string { + t.Helper() + if opt.Dir == "" && opt.File == "" { + opt.Dir = t.TempDir() + } + log, err := Start(opt) + if err != nil { + t.Fatalf("Start() error = %v", err) + } + if log == nil { + t.Fatal("Start() returned no logger") + } + t.Cleanup(func() { Close() }) + return Path() +} + +func lines(t *testing.T, path string) []string { + t.Helper() + b, err := os.ReadFile(path) + if err != nil { + t.Fatalf("read %s: %v", path, err) + } + return strings.Split(strings.TrimSpace(string(b)), "\n") +} + +func TestStartWritesOneFilePerRun(t *testing.T) { + dir := t.TempDir() + path := start(t, Options{Dir: dir, Now: time.Date(2026, 10, 20, 9, 14, 3, 0, time.UTC)}) + + if want := filepath.Join(dir, "iontk-20261020-091403.log"); path != want { + t.Errorf("Path() = %q, want %q", path, want) + } + L().Info("hello", "tsg", "1436146912") + if got := lines(t, path); len(got) != 1 || !strings.Contains(got[0], `"msg":"hello"`) { + t.Errorf("log holds %q, want one record saying hello", got) + } +} + +func TestEveryRecordCarriesTheRunID(t *testing.T) { + path := start(t, Options{}) + L().Info("first") + L().With("tsg", "123").Info("second") + + for _, line := range lines(t, path) { + var rec map[string]any + if err := json.Unmarshal([]byte(line), &rec); err != nil { + t.Fatalf("line %q is not JSON: %v", line, err) + } + if got, _ := rec["run"].(string); got != RunID() { + t.Errorf("run = %q, want %q; interleaved tenants need it to sort by", got, RunID()) + } + } +} + +func TestTheLevelGatesTheFile(t *testing.T) { + path := start(t, Options{Level: slog.LevelWarn}) + L().Info("quiet") + L().Warn("loud") + + got := lines(t, path) + if len(got) != 1 || !strings.Contains(got[0], "loud") { + t.Errorf("log holds %q, want the warning alone", got) + } +} + +func TestStartKeepsTheLastFewFilesAndDropsTheRest(t *testing.T) { + dir := t.TempDir() + for _, name := range []string{ + "iontk-20261001-100000.log", "iontk-20261002-100000.log", + "iontk-20261003-100000.log", "iontk-20261004-100000.log", + } { + if err := os.WriteFile(filepath.Join(dir, name), []byte("{}\n"), 0o600); err != nil { + t.Fatal(err) + } + } + if err := os.WriteFile(filepath.Join(dir, "notes.txt"), []byte("keep me"), 0o600); err != nil { + t.Fatal(err) + } + + start(t, Options{Dir: dir, Keep: 3, Now: time.Date(2026, 10, 5, 10, 0, 0, 0, time.UTC)}) + + var logs []string + entries, _ := os.ReadDir(dir) + for _, e := range entries { + if strings.HasSuffix(e.Name(), ".log") { + logs = append(logs, e.Name()) + } + } + want := []string{"iontk-20261003-100000.log", "iontk-20261004-100000.log", "iontk-20261005-100000.log"} + if strings.Join(logs, ",") != strings.Join(want, ",") { + t.Errorf("logs = %v, want %v", logs, want) + } + if _, err := os.Stat(filepath.Join(dir, "notes.txt")); err != nil { + t.Errorf("a file that is not a log was removed: %v", err) + } +} + +func TestADirectoryThatCannotBeMadeDoesNotStopTheRun(t *testing.T) { + blocked := filepath.Join(t.TempDir(), "file") + if err := os.WriteFile(blocked, nil, 0o600); err != nil { + t.Fatal(err) + } + + if _, err := Start(Options{Dir: filepath.Join(blocked, "logs")}); err == nil { + t.Fatal("Start() error = nil, want the directory failure reported") + } + t.Cleanup(func() { Close() }) + + if Problem() == nil { + t.Error("Problem() = nil, want the reason kept for the Debug page") + } + if Path() != "" { + t.Errorf("Path() = %q, want empty", Path()) + } + L().Info("this must not panic") +} + +func TestTailReturnsTheLastLines(t *testing.T) { + start(t, Options{}) + for _, msg := range []string{"one", "two", "three"} { + L().Info(msg) + } + + got := Tail(2) + if len(got) != 2 || !strings.Contains(got[0], "two") || !strings.Contains(got[1], "three") { + t.Errorf("Tail(2) = %q, want the last two records", got) + } +} + +func TestParseLevel(t *testing.T) { + tests := []struct { + in string + want slog.Level + wantErr bool + }{ + {"", slog.LevelInfo, false}, + {"debug", slog.LevelDebug, false}, + {"INFO", slog.LevelInfo, false}, + {" warn ", slog.LevelWarn, false}, + {"warning", slog.LevelWarn, false}, + {"error", slog.LevelError, false}, + {"off", levelOff, false}, + {"chatty", 0, true}, + } + for _, tt := range tests { + got, err := ParseLevel(tt.in) + if (err != nil) != tt.wantErr { + t.Errorf("ParseLevel(%q) error = %v, wantErr %v", tt.in, err, tt.wantErr) + continue + } + if err == nil && got != tt.want { + t.Errorf("ParseLevel(%q) = %v, want %v", tt.in, got, tt.want) + } + } +} + +func TestOffWritesNoFileAtAll(t *testing.T) { + dir := t.TempDir() + if _, err := Start(Options{Dir: dir, Level: levelOff}); err != nil { + t.Fatalf("Start() error = %v", err) + } + t.Cleanup(func() { Close() }) + + L().Error("not even this") + entries, _ := os.ReadDir(dir) + if len(entries) != 0 { + t.Errorf("%q holds %d files, want none when logging is off", dir, len(entries)) + } +} + +func TestStderrGetsTextWhileTheFileGetsJSON(t *testing.T) { + var buf strings.Builder + path := start(t, Options{Stderr: &buf}) + L().Info("dialed", "element", "store-0003-rtr-01") + + if got := buf.String(); !strings.Contains(got, "element=store-0003-rtr-01") { + t.Errorf("stderr = %q, want a text record", got) + } + if got := lines(t, path); !strings.Contains(got[0], `"element":"store-0003-rtr-01"`) { + t.Errorf("file = %q, want a JSON record", got) + } +} diff --git a/internal/logging/recent_test.go b/internal/logging/recent_test.go new file mode 100644 index 0000000..e18f3f4 --- /dev/null +++ b/internal/logging/recent_test.go @@ -0,0 +1,28 @@ +package logging + +import ( + "strings" + "testing" +) + +func TestRecentReadsAsALineOfText(t *testing.T) { + start(t, Options{}) + L().Info("stored refresh token accepted", "tsg", "1436146912", "rotated", true) + + got := Recent(1) + if len(got) != 1 { + t.Fatalf("Recent(1) = %q, want one line", got) + } + if !strings.Contains(got[0], "info stored refresh token accepted") { + t.Errorf("Recent(1)[0] = %q, want the level and the message", got[0]) + } + if strings.Contains(got[0], `"msg"`) { + t.Errorf("Recent(1)[0] = %q, want the JSON unwrapped for the Debug page", got[0]) + } +} + +func TestRecentPassesThroughWhatItCannotParse(t *testing.T) { + if got := summarize("not json at all"); got != "not json at all" { + t.Errorf("summarize() = %q, want the line as it stands", got) + } +} diff --git a/internal/logging/redact.go b/internal/logging/redact.go new file mode 100644 index 0000000..6a0d897 --- /dev/null +++ b/internal/logging/redact.go @@ -0,0 +1,153 @@ +package logging + +import ( + "context" + "fmt" + "log/slog" + "regexp" + "sort" + "strings" + "sync" +) + +var secretKeys = map[string]bool{ + "token": true, + "access_token": true, + "refresh_token": true, + "id_token": true, + "refresh": true, + "secret": true, + "client_secret": true, + "password": true, + "pass": true, + "code": true, + "code_verifier": true, + "verifier": true, + "authorization": true, + "cookie": true, + "seed": true, + "api_key": true, +} + +var secretNamed = regexp.MustCompile( + `(?i)\b(access_token|refresh_token|id_token|client_secret|code_verifier|verifier|password)\b["']?\s*[:=]\s*["']?([A-Za-z0-9._~+/=-]{4,})`) + +var secretParam = regexp.MustCompile( + `(?i)\b(token|secret|pass|code)=["']?([A-Za-z0-9._~+/=-]{4,})`) + +func Fingerprint(secret string) string { + switch n := len(secret); { + case n == 0: + return "(empty)" + case n < 8: + return fmt.Sprintf("(%d chars)", n) + default: + return fmt.Sprintf("…%s (%d chars)", secret[n-4:], n) + } +} + +const maskMin = 8 + +var ( + maskMu sync.RWMutex + masked = map[string]bool{} + replacer *strings.Replacer +) + +func Mask(secret string) { + if len(secret) < maskMin { + return + } + maskMu.Lock() + defer maskMu.Unlock() + if masked[secret] { + return + } + masked[secret] = true + + keys := make([]string, 0, len(masked)) + for k := range masked { + keys = append(keys, k) + } + sort.Slice(keys, func(i, j int) bool { return len(keys[i]) > len(keys[j]) }) + + pairs := make([]string, 0, 2*len(keys)) + for _, k := range keys { + pairs = append(pairs, k, Fingerprint(k)) + } + replacer = strings.NewReplacer(pairs...) +} + +func masker() *strings.Replacer { + maskMu.RLock() + defer maskMu.RUnlock() + return replacer +} + +func scrubText(s string) string { + if s == "" { + return s + } + if r := masker(); r != nil { + s = r.Replace(s) + } + for _, re := range []*regexp.Regexp{secretNamed, secretParam} { + s = re.ReplaceAllStringFunc(s, func(m string) string { + g := re.FindStringSubmatch(m) + return strings.TrimSuffix(m, g[2]) + Fingerprint(g[2]) + }) + } + return s +} + +func scrubAttr(a slog.Attr) slog.Attr { + if a.Value.Kind() == slog.KindGroup { + in := a.Value.Group() + out := make([]slog.Attr, len(in)) + for i, g := range in { + out[i] = scrubAttr(g) + } + return slog.Attr{Key: a.Key, Value: slog.GroupValue(out...)} + } + if secretKeys[strings.ToLower(a.Key)] { + return slog.String(a.Key, Fingerprint(fmt.Sprint(a.Value.Any()))) + } + if a.Value.Kind() == slog.KindString { + return slog.String(a.Key, scrubText(a.Value.String())) + } + if a.Value.Kind() == slog.KindAny { + if err, ok := a.Value.Any().(error); ok && err != nil { + return slog.String(a.Key, scrubText(err.Error())) + } + } + return a +} + +func scrubAll(attrs []slog.Attr) []slog.Attr { + out := make([]slog.Attr, len(attrs)) + for i, a := range attrs { + out[i] = scrubAttr(a) + } + return out +} + +type redactor struct{ slog.Handler } + +func redact(h slog.Handler) slog.Handler { return redactor{h} } + +func (r redactor) Handle(ctx context.Context, rec slog.Record) error { + safe := slog.NewRecord(rec.Time, rec.Level, scrubText(rec.Message), rec.PC) + rec.Attrs(func(a slog.Attr) bool { + safe.AddAttrs(scrubAttr(a)) + return true + }) + return r.Handler.Handle(ctx, safe) +} + +func (r redactor) WithAttrs(attrs []slog.Attr) slog.Handler { + return redactor{r.Handler.WithAttrs(scrubAll(attrs))} +} + +func (r redactor) WithGroup(name string) slog.Handler { + return redactor{r.Handler.WithGroup(name)} +} diff --git a/internal/logging/redact_test.go b/internal/logging/redact_test.go new file mode 100644 index 0000000..a1bc731 --- /dev/null +++ b/internal/logging/redact_test.go @@ -0,0 +1,148 @@ +package logging + +import ( + "bytes" + "context" + "encoding/json" + "log/slog" + "strings" + "testing" +) + +func record(t *testing.T, log func(*slog.Logger)) (string, map[string]any) { + t.Helper() + var buf bytes.Buffer + log(slog.New(redact(slog.NewJSONHandler(&buf, nil)))) + + line := strings.TrimSpace(buf.String()) + if line == "" { + t.Fatal("nothing was logged") + } + var out map[string]any + if err := json.Unmarshal([]byte(line), &out); err != nil { + t.Fatalf("log line %q is not JSON: %v", line, err) + } + return line, out +} + +func TestSecretAttributesBecomeFingerprints(t *testing.T) { + const secret = "eyJhbGciOiJSUzI1NiJ9.verylongtokenbody.signature" + + tests := []string{ + "token", "access_token", "refresh_token", "id_token", "client_secret", + "password", "code", "code_verifier", "authorization", "seed", + } + for _, key := range tests { + t.Run(key, func(t *testing.T) { + line, out := record(t, func(l *slog.Logger) { + l.Info("auth", key, secret) + }) + if strings.Contains(line, secret) { + t.Fatalf("%s reached the log: %s", key, line) + } + got, _ := out[key].(string) + if want := Fingerprint(secret); got != want { + t.Errorf("%s = %q, want %q", key, got, want) + } + }) + } +} + +func TestSecretsInsideGroupsAndWithAttrsAreScrubbed(t *testing.T) { + const secret = "rt-abcdefghijklmnop" + + line, _ := record(t, func(l *slog.Logger) { + l.With("refresh_token", secret).WithGroup("seed").Info("redeem", "token", secret) + }) + if strings.Contains(line, secret) { + t.Fatalf("a secret survived a group or With: %s", line) + } +} + +func TestSecretsInMessagesAndErrorsAreScrubbed(t *testing.T) { + const secret = "4/0AY0e-g7xlongauthcode" + + tests := []struct { + name string + log func(*slog.Logger) + }{ + {"message", func(l *slog.Logger) { + l.Info(`token: status 400 Bad Request: {"refresh_token":"` + secret + `"}`) + }}, + {"error attribute", func(l *slog.Logger) { + l.Info("refresh failed", "err", `token: status 400: {"access_token": "`+secret+`"}`) + }}, + {"form body", func(l *slog.Logger) { + l.Info("exchange", "body", "grant_type=refresh_token&refresh_token="+secret) + }}, + {"device password", func(l *slog.Logger) { + l.Info("login", "err", "password="+secret+" rejected") + }}, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + line, _ := record(t, tt.log) + if strings.Contains(line, secret) { + t.Fatalf("a secret survived in free text: %s", line) + } + if !strings.Contains(line, Fingerprint(secret)) { + t.Errorf("line %q names no fingerprint, so the length is lost", line) + } + }) + } +} + +func TestCallbackURLKeepsEverythingButTheCode(t *testing.T) { + const code = "pLkFQ3-authorizationcode-9ZxY" + + line, out := record(t, func(l *slog.Logger) { + l.Info("callback", "url", + "https://example.test/authentication/callback?code="+code+"&state=abc123") + }) + if strings.Contains(line, code) { + t.Fatalf("the callback code reached the log: %s", line) + } + got, _ := out["url"].(string) + if !strings.Contains(got, "state=abc123") { + t.Errorf("url = %q, want the state kept for matching up a leg", got) + } +} + +func TestANonSecretAttributeIsLeftAlone(t *testing.T) { + _, out := record(t, func(l *slog.Logger) { + l.Info("elements", "tsg", "1436146912", "count", 5613) + }) + if got, _ := out["tsg"].(string); got != "1436146912" { + t.Errorf("tsg = %q, want it untouched", got) + } + if got, _ := out["count"].(float64); got != 5613 { + t.Errorf("count = %v, want 5613", got) + } +} + +func TestFingerprintKeepsTheLastFourAndTheLength(t *testing.T) { + tests := []struct { + name, in, want string + }{ + {"long token", strings.Repeat("x", 1440) + "9f3a", "…9f3a (1444 chars)"}, + {"short enough to guess", "secret", "(6 chars)"}, + {"empty", "", "(empty)"}, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + if got := Fingerprint(tt.in); got != tt.want { + t.Errorf("Fingerprint() = %q, want %q", got, tt.want) + } + }) + } +} + +func TestTheHandlerStillReportsWhatItWraps(t *testing.T) { + h := redact(slog.NewJSONHandler(&bytes.Buffer{}, &slog.HandlerOptions{Level: slog.LevelWarn})) + if h.Enabled(context.Background(), slog.LevelInfo) { + t.Error("Enabled(info) = true on a warn handler") + } + if !h.Enabled(context.Background(), slog.LevelError) { + t.Error("Enabled(error) = false on a warn handler") + } +} diff --git a/internal/saseauth/browser.go b/internal/saseauth/browser.go index 1000ead..e838926 100644 --- a/internal/saseauth/browser.go +++ b/internal/saseauth/browser.go @@ -4,6 +4,7 @@ import ( "context" "errors" "fmt" + "log/slog" "net/http" "os" "strings" @@ -12,6 +13,7 @@ import ( "github.com/chromedp/cdproto/network" "github.com/chromedp/chromedp" + "tyrtop.com/iontk/internal/logging" ) var ErrNoSession = errors.New("no existing browser session") @@ -27,10 +29,18 @@ type Options struct { AuthorizeURL string TokenURL string Client *http.Client + Logger *slog.Logger Seed *Seed } +func (o Options) log() *slog.Logger { + if o.Logger != nil { + return o.Logger + } + return logging.L() +} + func (o Options) authorize() string { if o.AuthorizeURL != "" { return o.AuthorizeURL @@ -95,11 +105,13 @@ func LoginSilent(ctx context.Context, tsg string, opt Options) (*Token, error) { } key := refusalKey(opt.DataDir, tsg) if _, refused := silentRefused.Load(key); refused { + opt.log().Info("silent sign-in skipped", "tsg", tsg, "reason", "already refused for this profile") return nil, fmt.Errorf("%w: a silent sign-in was already refused for this profile", ErrNoSession) } tok, err := login(ctx, tsg, opt, true) if err != nil && ctx.Err() == nil { silentRefused.Store(key, struct{}{}) + opt.log().Info("silent sign-in refused", "tsg", tsg, "err", err) return nil, fmt.Errorf("%w: %v", ErrNoSession, err) } return tok, err @@ -115,15 +127,26 @@ func login(ctx context.Context, tsg string, opt Options, silent bool) (*Token, e } func loginToken(ctx context.Context, tsg string, opt Options, silent bool) (*Token, error) { + log := opt.log().With("tsg", tsg, "silent", silent) + p, err := newPKCE() if err != nil { return nil, err } + log.Info("launching chrome", "data_dir", opt.DataDir, "chrome", opt.Chrome) code, err := codeFromBrowser(ctx, p.authorizeURL(opt.authorize(), tsg, silent), p.state, opt, silent) if err != nil { + log.Warn("browser leg failed", "err", err) return nil, err } - return ExchangeCode(ctx, opt.httpClient(), opt.token(), code, p.verifier) + + log.Info("authorization code received") + tok, err := ExchangeCode(ctx, opt.httpClient(), opt.token(), code, p.verifier) + if err != nil { + log.Warn("code exchange failed", "err", err) + return nil, err + } + return tok, nil } var cleanUpGrace = 5 * time.Second @@ -205,6 +228,7 @@ func codeFromBrowser(ctx context.Context, authorizeURL, state string, opt Option if ev.Request == nil || !strings.HasPrefix(ev.Request.URL, RedirectURI) { continue } + opt.log().Debug("callback reached", "url", ev.Request.URL) return CodeFromCallback(ev.Request.URL, state) } diff --git a/internal/saseauth/identity_test.go b/internal/saseauth/identity_test.go index 4810b68..716877c 100644 --- a/internal/saseauth/identity_test.go +++ b/internal/saseauth/identity_test.go @@ -5,6 +5,8 @@ import ( "encoding/json" "testing" "time" + + "tyrtop.com/iontk/internal/logging" ) func jwt(t *testing.T, claims map[string]any) string { @@ -132,7 +134,7 @@ func TestSourceExposesIdentityAndTTL(t *testing.T) { AccessToken: jwt(t, map[string]any{"tsg_id": "123"}), ExpiresIn: 899 * time.Second, } - if _, _, err := src.accept(tok); err != nil { + if _, _, err := src.accept(tok, logging.L()); err != nil { t.Fatalf("accept() error = %v", err) } if got := src.Identity().Name; got != "Ben" { diff --git a/internal/saseauth/logging_test.go b/internal/saseauth/logging_test.go new file mode 100644 index 0000000..47e7608 --- /dev/null +++ b/internal/saseauth/logging_test.go @@ -0,0 +1,97 @@ +package saseauth + +import ( + "context" + "net/http" + "net/http/httptest" + "os" + "strings" + "testing" + + "tyrtop.com/iontk/internal/logging" +) + +func TestNoSecretReachesTheLogFile(t *testing.T) { + const ( + stored = "rt1-c3VwZXItc2VjcmV0LXN0b3JlZC1yZWZyZXNoLXRva2Vu" + seed = "seed-YWNjb3VudC1zZWVkLXJlZnJlc2gtdG9rZW4tdmFsdWU" + access = "at-ZXlKaGJHY2lPaUpTVXpJMU5pSjkuYWNjZXNz" + rotate = "rt2-cm90YXRlZC1yZWZyZXNoLXRva2VuLXZhbHVl" + ) + + tests := []struct { + name string + stored string + status int + wantSay []string + }{ + {"stored token works", stored, http.StatusOK, []string{ + "trying the stored refresh token", + "stored refresh token accepted", + "refresh token saved for this tenant", + }}, + {"stored token refused, the account credential narrows", stored, http.StatusBadRequest, []string{ + "stored refresh token rejected", + "redeeming the account credential", + }}, + {"no stored token at all", "", http.StatusBadRequest, []string{ + "no stored refresh token for this tenant", + "redeeming the account credential", + }}, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + r.ParseForm() + if r.PostForm.Get("refresh_token") == stored && tt.status != http.StatusOK { + w.WriteHeader(tt.status) + w.Write([]byte(`{"error":"invalid_grant","error_description":"token ` + stored + ` is dead"}`)) + return + } + w.Write([]byte(`{"access_token":"` + access + `","refresh_token":"` + rotate + `","expires_in":899}`)) + })) + defer srv.Close() + + if _, err := logging.Start(logging.Options{Dir: t.TempDir()}); err != nil { + t.Fatalf("logging.Start() error = %v", err) + } + defer logging.Close() + + var saved string + src := NewSource("1436146912", tt.stored, + Options{TokenURL: srv.URL, Client: srv.Client(), Seed: NewSeed(seed)}, + func(rt string) error { saved = rt; return nil }) + + if _, _, err := src.Token(context.Background()); err != nil { + t.Fatalf("Token() error = %v", err) + } + if saved != rotate { + t.Fatalf("saved refresh token = %q, want the rotated one", saved) + } + + b, err := os.ReadFile(logging.Path()) + if err != nil { + t.Fatalf("read the log: %v", err) + } + body := string(b) + + for _, secret := range []string{stored, seed, access, rotate} { + if tt.stored == "" && secret == stored { + continue + } + if strings.Contains(body, secret) { + t.Errorf("the log carries a secret ending %q:\n%s", logging.Fingerprint(secret), body) + } + } + for _, say := range tt.wantSay { + if !strings.Contains(body, say) { + t.Errorf("the log never says %q, so the path it took is still unrecoverable:\n%s", say, body) + } + } + if !strings.Contains(body, logging.Fingerprint(rotate)) { + t.Errorf("the log names no fingerprint for the saved token, so it cannot be told apart:\n%s", body) + } + }) + } +} diff --git a/internal/saseauth/oauth.go b/internal/saseauth/oauth.go index d1529e2..d0db12e 100644 --- a/internal/saseauth/oauth.go +++ b/internal/saseauth/oauth.go @@ -12,6 +12,8 @@ import ( "net/url" "strings" "time" + + "tyrtop.com/iontk/internal/logging" ) const ( @@ -155,6 +157,8 @@ func exchange(ctx context.Context, client *http.Client, tokenURL string, form ur } func ExchangeCode(ctx context.Context, client *http.Client, tokenURL, code, verifier string) (*Token, error) { + logging.Mask(code) + logging.Mask(verifier) return exchange(ctx, client, tokenURL, url.Values{ "grant_type": {"authorization_code"}, "code": {code}, diff --git a/internal/saseauth/seed.go b/internal/saseauth/seed.go index 49f82f0..19a1c2d 100644 --- a/internal/saseauth/seed.go +++ b/internal/saseauth/seed.go @@ -2,9 +2,12 @@ package saseauth import ( "context" + "log/slog" "net/http" "strings" "sync" + + "tyrtop.com/iontk/internal/logging" ) type Seed struct { @@ -13,27 +16,42 @@ type Seed struct { spent bool } -func NewSeed(token string) *Seed { return &Seed{token: token} } +func NewSeed(token string) *Seed { + logging.Mask(token) + return &Seed{token: token} +} -func (s *Seed) redeem(ctx context.Context, client *http.Client, tokenURL, tsg string) (tok *Token, tried bool, err error) { +func (s *Seed) redeem(ctx context.Context, client *http.Client, tokenURL, tsg string, log *slog.Logger) (tok *Token, tried bool, err error) { if s == nil { + log.Info("no account credential to narrow") return nil, false, nil } s.mu.Lock() defer s.mu.Unlock() if s.spent || s.token == "" { + log.Info("account credential skipped", "reason", reason(s.spent)) return nil, false, nil } + log.Info("redeeming the account credential", "seed", s.token) tok, err = Refresh(ctx, client, tokenURL, s.token, tsg) if err != nil { if strings.Contains(err.Error(), "invalid_grant") { s.spent = true } + log.Warn("account credential refused", "err", err, "spent", s.spent) return nil, true, err } if tok.RefreshToken != s.token { s.spent = true } + log.Info("account credential redeemed", "narrowed_to_this_tenant", s.spent) return tok, true, nil } + +func reason(spent bool) string { + if spent { + return "already spent by another tenant" + } + return "none is held" +} diff --git a/internal/saseauth/seed_test.go b/internal/saseauth/seed_test.go index f849e08..3825053 100644 --- a/internal/saseauth/seed_test.go +++ b/internal/saseauth/seed_test.go @@ -10,6 +10,8 @@ import ( "sync" "sync/atomic" "testing" + + "tyrtop.com/iontk/internal/logging" ) func seedServer(t *testing.T, rotate bool) (*httptest.Server, *[]url.Values, *atomic.Int32) { @@ -50,7 +52,7 @@ func TestSeedRedeemedByOneTenantAtATime(t *testing.T) { wg.Add(1) go func() { defer wg.Done() - seed.redeem(context.Background(), srv.Client(), srv.URL, tsg) + seed.redeem(context.Background(), srv.Client(), srv.URL, tsg, logging.L()) }() } wg.Wait() @@ -64,7 +66,7 @@ func TestSeedRetiredOnceRotated(t *testing.T) { srv, seen, _ := seedServer(t, true) seed := NewSeed("account-rt") - tok, tried, err := seed.redeem(context.Background(), srv.Client(), srv.URL, "1") + tok, tried, err := seed.redeem(context.Background(), srv.Client(), srv.URL, "1", logging.L()) if err != nil || !tried { t.Fatalf("redeem() = tried %v, error %v, want a successful first redemption", tried, err) } @@ -72,7 +74,7 @@ func TestSeedRetiredOnceRotated(t *testing.T) { t.Fatal("the test server did not rotate, so this proves nothing") } - if _, tried, _ := seed.redeem(context.Background(), srv.Client(), srv.URL, "2"); tried { + if _, tried, _ := seed.redeem(context.Background(), srv.Client(), srv.URL, "2", logging.L()); tried { t.Error("redeem() tried = true after a rotation, want the spent seed to be skipped") } if len(*seen) != 1 { @@ -85,7 +87,7 @@ func TestSeedSurvivesAServerThatDoesNotRotate(t *testing.T) { seed := NewSeed("account-rt") for _, tsg := range []string{"1", "2", "3"} { - tok, tried, err := seed.redeem(context.Background(), srv.Client(), srv.URL, tsg) + tok, tried, err := seed.redeem(context.Background(), srv.Client(), srv.URL, tsg, logging.L()) if err != nil || !tried { t.Fatalf("tenant %s: redeem() = tried %v, error %v, want it to succeed", tsg, tried, err) } @@ -121,10 +123,10 @@ func TestSeedRetiredOnlyWhenTheTokenItselfIsRefused(t *testing.T) { defer srv.Close() seed := NewSeed("account-rt") - if _, tried, err := seed.redeem(context.Background(), srv.Client(), srv.URL, "1"); !tried || err == nil { + if _, tried, err := seed.redeem(context.Background(), srv.Client(), srv.URL, "1", logging.L()); !tried || err == nil { t.Fatalf("redeem() = tried %v, error %v, want a reported failure", tried, err) } - _, tried, _ := seed.redeem(context.Background(), srv.Client(), srv.URL, "2") + _, tried, _ := seed.redeem(context.Background(), srv.Client(), srv.URL, "2", logging.L()) if tried == tt.wantSpent { t.Errorf("second redeem tried = %v, want the seed spent = %v", tried, tt.wantSpent) } @@ -134,7 +136,7 @@ func TestSeedRetiredOnlyWhenTheTokenItselfIsRefused(t *testing.T) { func TestNilSeedIsNotTried(t *testing.T) { var seed *Seed - tok, tried, err := seed.redeem(context.Background(), http.DefaultClient, "http://unused", "1") + tok, tried, err := seed.redeem(context.Background(), http.DefaultClient, "http://unused", "1", logging.L()) if tried || tok != nil || err != nil { t.Errorf("redeem() on a nil seed = (%v, %v, %v), want it to be a no-op", tok, tried, err) } diff --git a/internal/saseauth/source.go b/internal/saseauth/source.go index 43f989b..da5c0d3 100644 --- a/internal/saseauth/source.go +++ b/internal/saseauth/source.go @@ -4,8 +4,11 @@ import ( "context" "errors" "fmt" + "log/slog" "sync" "time" + + "tyrtop.com/iontk/internal/logging" ) var ErrInteractiveRequired = errors.New("interactive sign-in required") @@ -24,6 +27,7 @@ type Source struct { } func NewSource(tsg, refreshToken string, opt Options, save func(string) error) *Source { + logging.Mask(refreshToken) return &Source{tsg: tsg, opt: opt, save: save, refresh: refreshToken} } @@ -45,7 +49,11 @@ func (s *Source) Identity() Identity { return s.identity } -func (s *Source) accept(tok *Token) (string, time.Duration, error) { +func (s *Source) accept(tok *Token, log *slog.Logger) (string, time.Duration, error) { + logging.Mask(tok.AccessToken) + logging.Mask(tok.RefreshToken) + logging.Mask(tok.IDToken) + s.mu.Lock() s.refresh = tok.RefreshToken s.lastTTL = tok.ExpiresIn @@ -57,29 +65,38 @@ func (s *Source) accept(tok *Token) (string, time.Duration, error) { if save != nil && tok.RefreshToken != "" { if err := save(tok.RefreshToken); err != nil { + log.Error("could not save the refresh token", "err", err) return tok.AccessToken, tok.ExpiresIn, fmt.Errorf("save refresh token: %w", err) } + log.Info("refresh token saved for this tenant", "refresh_token", tok.RefreshToken) } + log.Info("access token accepted", "ttl", tok.ExpiresIn.String(), "scope", tok.Scope) return tok.AccessToken, tok.ExpiresIn, nil } func (s *Source) Token(ctx context.Context) (string, time.Duration, error) { + log := s.log() var stored, account error if rt := s.RefreshToken(); rt != "" { + log.Info("trying the stored refresh token", "refresh_token", rt) tok, err := Refresh(ctx, s.opt.httpClient(), s.opt.token(), rt, s.tsg) if err == nil { - return s.accept(tok) + log.Info("stored refresh token accepted", "rotated", tok.RefreshToken != rt) + return s.accept(tok, log) } if ctx.Err() != nil { return "", 0, err } + log.Warn("stored refresh token rejected", "err", err) stored = fmt.Errorf("stored refresh token rejected: %w", err) + } else { + log.Info("no stored refresh token for this tenant") } - if tok, tried, err := s.opt.Seed.redeem(ctx, s.opt.httpClient(), s.opt.token(), s.tsg); tried { + if tok, tried, err := s.opt.Seed.redeem(ctx, s.opt.httpClient(), s.opt.token(), s.tsg, log); tried { if err == nil { - return s.accept(tok) + return s.accept(tok, log) } if ctx.Err() != nil { return "", 0, err @@ -89,11 +106,13 @@ func (s *Source) Token(ctx context.Context) (string, time.Duration, error) { tok, err := LoginSilent(ctx, s.tsg, s.opt) if err == nil { - return s.accept(tok) + log.Info("silent browser sign-in worked") + return s.accept(tok, log) } if ctx.Err() != nil { return "", 0, err } + log.Warn("no credential worked; an interactive sign-in is needed", "silent", err) if stored != nil { return "", 0, permanentError{fmt.Errorf("%w: %v; %w", ErrInteractiveRequired, stored, err)} } @@ -111,12 +130,18 @@ func (e permanentError) Unwrap() error { return e.err } func (e permanentError) Temporary() bool { return false } func (s *Source) SignIn(ctx context.Context) error { + log := s.log() + log.Info("interactive sign-in asked for") + tok, err := Login(ctx, s.tsg, s.opt) if err != nil { + log.Warn("interactive sign-in failed", "err", err) return err } - _, _, err = s.accept(tok) + _, _, err = s.accept(tok, log) return err } +func (s *Source) log() *slog.Logger { return s.opt.log().With("tsg", s.tsg) } + func (s *Source) Seed() *Seed { return s.opt.Seed } diff --git a/internal/saseauth/source_test.go b/internal/saseauth/source_test.go index 66f59a0..a1b5514 100644 --- a/internal/saseauth/source_test.go +++ b/internal/saseauth/source_test.go @@ -12,6 +12,8 @@ import ( "sync/atomic" "testing" "time" + + "tyrtop.com/iontk/internal/logging" ) func TestSourceTokenUsesStoredRefreshToken(t *testing.T) { @@ -170,7 +172,7 @@ func TestSourcePrefersItsOwnTokenOverTheSeed(t *testing.T) { if got := form.Get("refresh_token"); got != "tenant-rt" { t.Errorf("sent refresh_token = %q, want the tenant's own %q", got, "tenant-rt") } - if _, tried, _ := seed.redeem(context.Background(), srv.Client(), srv.URL, "9"); !tried { + if _, tried, _ := seed.redeem(context.Background(), srv.Client(), srv.URL, "9", logging.L()); !tried { t.Error("the shared seed was spent by a tenant that did not need it") } } diff --git a/internal/tui/ha.go b/internal/tui/ha.go index a8a66d5..99d26fc 100644 --- a/internal/tui/ha.go +++ b/internal/tui/ha.go @@ -11,6 +11,7 @@ import ( tea "charm.land/bubbletea/v2" "tyrtop.com/iontk/internal/app" "tyrtop.com/iontk/internal/config" + "tyrtop.com/iontk/internal/logging" "tyrtop.com/iontk/internal/sase/api" "tyrtop.com/iontk/internal/ui" ) @@ -97,6 +98,8 @@ func loadHAChunk(ctx context.Context, c *api.Client, tsg string, w haWork, ids [ return func() tea.Msg { sts, err := c.SpokeClusterStatuses(ctx, ask) if err != nil { + logging.L().Warn("ha falling back to the per-cluster sweep", "tsg", tsg, + "asked", len(ask), "clusters", len(w.pairs), "err", err) msg := haStatesMsg{tsg: tsg, bulk: shortTenantErr(err), rest: w.pairs} if len(w.noSite) > 0 { msg.failed = map[string]string{} @@ -117,6 +120,8 @@ func loadHAChunk(ctx context.Context, c *api.Client, tsg string, w haWork, ids [ answered = append(answered, st.ClusterID) } } + logging.L().Info("ha read in bulk", "tsg", tsg, "asked", len(ask), + "rows", len(sts), "clusters", len(answered), "queued", len(rest)) return haStatesMsg{ tsg: tsg, states: states, answered: answered, bulk: "used", restElements: rest, diff --git a/internal/tui/multitenant.go b/internal/tui/multitenant.go index 25d1c77..68dee5c 100644 --- a/internal/tui/multitenant.go +++ b/internal/tui/multitenant.go @@ -15,6 +15,7 @@ import ( "tyrtop.com/iontk/internal/app" "tyrtop.com/iontk/internal/config" "tyrtop.com/iontk/internal/ionterm" + "tyrtop.com/iontk/internal/logging" "tyrtop.com/iontk/internal/sase" "tyrtop.com/iontk/internal/sase/api" "tyrtop.com/iontk/internal/ui" @@ -113,11 +114,14 @@ func loadTenant(ctx context.Context, f app.Flags, t config.Tenant, pool *clientP els, err := c.ListElements(ctx) if err != nil { + logging.L().Warn("element list failed", "tsg", t.TSGID, "tenant", t.Name, "err", err) return fail(err) } sites := map[string]string{} ss, siteErr := c.ListSites(ctx) + logging.L().Info("elements loaded", "tsg", t.TSGID, "tenant", t.Name, + "elements", len(els), "sites", len(ss), "site_err", siteErr) for _, s := range ss { sites[t.TSGID+"/"+s.ID] = s.Name } diff --git a/internal/tui/settings.go b/internal/tui/settings.go index 3508165..398626b 100644 --- a/internal/tui/settings.go +++ b/internal/tui/settings.go @@ -12,6 +12,7 @@ import ( "tyrtop.com/iontk/internal/clock" "tyrtop.com/iontk/internal/config" "tyrtop.com/iontk/internal/ioncmd" + "tyrtop.com/iontk/internal/logging" "tyrtop.com/iontk/internal/output" "tyrtop.com/iontk/internal/sase/api" "tyrtop.com/iontk/internal/saseauth" @@ -522,6 +523,7 @@ func (m tuiModel) sectionContent() []string { ui.Label("Colors")+ui.StyleDim.Render(ui.CurrentTheme().Name+" "+profileLabel()), ui.Label("Terminal")+ui.StyleDim.Render(termColorLine()), ui.Label("Times")+ui.StyleDim.Render(clock.Name()), + ui.Label("Log")+logLine(), "", ui.Label("Tenant")+ui.StyleDim.Render(m.tenant.Name+" tsg "+m.tenant.TSGID), ui.Label("ION User")+ui.StyleDim.Render(m.ionUser), @@ -536,10 +538,28 @@ func (m tuiModel) sectionContent() []string { if app.Debug { out = append(out, "", ui.StyleWarn.Render("--debug: throwaway config, no saved tenants, secrets held only in memory")) } + if tail := logging.Recent(logTailLines); len(tail) > 0 { + out = append(out, "") + for _, line := range tail { + out = append(out, ui.StyleDim.Render(" "+ui.Truncate(line, max(20, m.width-4)))) + } + } } return out } +const logTailLines = 5 + +func logLine() string { + if err := logging.Problem(); err != nil { + return ui.StyleWarn.Render("nothing written: " + err.Error()) + } + if !logging.On() { + return ui.StyleDim.Render("off") + } + return ui.StyleDim.Render(logging.Path() + " " + logging.LevelName() + ", run " + logging.RunID()) +} + func (m tuiModel) sectionHint() string { if m.setSection == secDebug { return "read only · ↑↓ section · esc back" @@ -607,6 +627,9 @@ func (m tuiModel) viewSettings() string { } rows := m.sectionContent() + if len(rows) > bodyHeight { + rows = rows[:bodyHeight] + } var content strings.Builder for i, r := range rows { cursor := " " diff --git a/internal/tui/settings_test.go b/internal/tui/settings_test.go index 45cf402..769ef0b 100644 --- a/internal/tui/settings_test.go +++ b/internal/tui/settings_test.go @@ -8,6 +8,7 @@ import ( tea "charm.land/bubbletea/v2" "tyrtop.com/iontk/internal/config" + "tyrtop.com/iontk/internal/logging" "tyrtop.com/iontk/internal/ui" ) @@ -717,3 +718,58 @@ func TestTheResetSectionsTwoRowsArmSeparately(t *testing.T) { t.Error("a cancelled reset still wiped the tenants") } } + +func TestDebugSectionNamesTheLogAndItsLastLines(t *testing.T) { + if _, err := logging.Start(logging.Options{Dir: t.TempDir()}); err != nil { + t.Fatalf("logging.Start() error = %v", err) + } + defer logging.Close() + logging.L().Info("stored refresh token accepted", "tsg", "1436146912") + + m := settingsModel(t) + m.setSection = secDebug + m.width = 120 + + got := plain(m.viewSettings()) + if !strings.Contains(got, logging.Path()) { + t.Errorf("Debug never names the log file %q:\n%s", logging.Path(), got) + } + if !strings.Contains(got, "stored refresh token accepted") { + t.Errorf("Debug shows no tail, so the file has to be found by hand:\n%s", got) + } +} + +func TestDebugSectionSaysWhenNothingIsBeingLogged(t *testing.T) { + logging.Close() + + m := settingsModel(t) + m.setSection = secDebug + m.width = 120 + + if got := plain(m.viewSettings()); !strings.Contains(got, "Log") || !strings.Contains(got, "off") { + t.Errorf("Debug should say the log is off:\n%s", got) + } +} + +func TestTheDebugPageKeepsTheFrameHeight(t *testing.T) { + if _, err := logging.Start(logging.Options{Dir: t.TempDir()}); err != nil { + t.Fatalf("logging.Start() error = %v", err) + } + defer logging.Close() + for i := 0; i < logTailLines*2; i++ { + logging.L().Info("a line that pads the tail out") + } + + m := settingsModel(t) + m.setSection = secDebug + m.width, m.height = 100, 24 + + general := m + general.setSection = secGeneral + + got := len(strings.Split(m.viewSettings(), "\n")) + if want := len(strings.Split(general.viewSettings(), "\n")); got != want { + t.Errorf("the Debug page is %d lines where General is %d on a %d-row terminal; the tail must be clipped, not grow the frame", + got, want, m.height) + } +} diff --git a/internal/tui/tui.go b/internal/tui/tui.go index b7ec755..1616f24 100644 --- a/internal/tui/tui.go +++ b/internal/tui/tui.go @@ -23,6 +23,7 @@ import ( "tyrtop.com/iontk/internal/config" "tyrtop.com/iontk/internal/dataview" "tyrtop.com/iontk/internal/ionterm" + "tyrtop.com/iontk/internal/logging" "tyrtop.com/iontk/internal/sase" "tyrtop.com/iontk/internal/sase/api" "tyrtop.com/iontk/internal/sase/ioncli" @@ -359,6 +360,8 @@ func Run(ctx context.Context) error { } } + logging.L().Info("tui started", "version", Version, "tenant", Tenant, "config", store.Root) + model := newTUIModel(ctx, store, cfg) defer model.sessions.CloseAll() // bubbletea's own reset is OSC 111, which not every terminal implements diff --git a/internal/tui/tuimenu.go b/internal/tui/tuimenu.go index ec95b3a..91e9f12 100644 --- a/internal/tui/tuimenu.go +++ b/internal/tui/tuimenu.go @@ -11,6 +11,7 @@ import ( tea "charm.land/bubbletea/v2" "tyrtop.com/iontk/internal/app" "tyrtop.com/iontk/internal/config" + "tyrtop.com/iontk/internal/logging" "tyrtop.com/iontk/internal/output" "tyrtop.com/iontk/internal/ui" ) @@ -993,6 +994,7 @@ func (m tuiModel) startSignInAuto() (tea.Model, tea.Cmd) { if !m.browserAuthDone || why == "" { return m.startSignIn() } + logging.L().Info("automatic sign-in refused", "tsg", m.tenant.TSGID, "why", why) m.signInResume = false m.cacheState = cacheFailed m.status = m.tenantName(m.tenant.TSGID) + ": " + why +