logging

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])
 	}

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)

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)`)

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
 	}

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"):

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
+}

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

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
 }
 

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)
+	}
+}

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