From b03878d8a5bedfd3d97f8843b936485b1916c258 Mon Sep 17 00:00:00 2001 From: Roman Sharkov Date: Tue, 6 Aug 2024 21:07:35 +0200 Subject: [PATCH] !feat: Add optional debug logging This breaks backwards compatibility and requires changing the configuration YAML file! Replace option "verbose" with a new option "log" that accepts either of: ["", "erronly", "verbose", "debug"]. --- example-config.yml | 9 ++-- internal/cmdrun/cmdrun.go | 4 ++ internal/config/config.go | 31 +++++++++-- internal/log/log.go | 89 +++++++++++++++++++++++++------ internal/server/server.go | 8 +++ internal/statetrack/statetrack.go | 5 ++ internal/watcher/watcher.go | 3 ++ main.go | 25 ++++++++- 8 files changed, 151 insertions(+), 23 deletions(-) diff --git a/example-config.yml b/example-config.yml index a1c4742..40ac255 100644 --- a/example-config.yml +++ b/example-config.yml @@ -12,9 +12,12 @@ templier-host: "your-application:11000" # print-js-debug-logs enables Templiér debug logs in the browser. print-js-debug-logs: true -# verbose enables verbose console logs when true. -# This doesn't affect app server logs. -verbose: true +# log allows you to chose from different log levels: +# "": empty is same as erronly +# erronly: error logs only +# verbose: verbose logging of relevant events and timings +# debug: verbose debug logging +log: erronly debounce: # debounce.templ defines how long to wait for more _templ.txt file changes diff --git a/internal/cmdrun/cmdrun.go b/internal/cmdrun/cmdrun.go index 4a563e7..8413451 100644 --- a/internal/cmdrun/cmdrun.go +++ b/internal/cmdrun/cmdrun.go @@ -23,8 +23,10 @@ func Run( c := exec.CommandContext(ctx, cmd, args...) c.Dir = workDir + log.Debugf("running command: %s", c.String()) out, err = c.CombinedOutput() if exitError, ok := err.(*exec.ExitError); ok && exitError.ExitCode() == 1 { + log.Debugf("running command (pid: %d): exited with exit code 1", c.Process.Pid) return out, ErrExitCode1 } else if err != nil { return nil, err @@ -52,6 +54,7 @@ func RunTemplWatch(ctx context.Context, workDir string, st *statetrack.Tracker) return fmt.Errorf("obtaining stdout pipe: %w", err) } + log.Debugf("starting a-h/templ in the background: %s", cmd.String()) if err := cmd.Start(); err != nil { return fmt.Errorf("starting: %w", err) } @@ -62,6 +65,7 @@ func RunTemplWatch(ctx context.Context, workDir string, st *statetrack.Tracker) scanner := bufio.NewScanner(stdout) for scanner.Scan() { b := scanner.Bytes() + log.Debugf("templ: %s", string(b)) switch { case bytes.HasPrefix(b, bytesPrefixErr): st.Set(statetrack.IndexTempl, scanner.Text()) diff --git a/internal/config/config.go b/internal/config/config.go index ea13183..7b17219 100644 --- a/internal/config/config.go +++ b/internal/config/config.go @@ -28,9 +28,12 @@ type Config struct { App ConfigApp `yaml:"app"` - // Verbose enables verbose console logs when true. - // Verbose doesn't affect app server logs. - Verbose bool `yaml:"verbose"` + // Log accepts either of: + // - "": empty string is the same as "erronly" + // - "erronly": error logs only. + // - "verbose": verbose logging of relevant events. + // - "debug": verbose debug logging. + Log Log `yaml:"log"` // Debounce is the file watcher debounce duration. Debounce struct { @@ -150,6 +153,24 @@ func (w ConfigCustomWatcher) Validate() error { return nil } +type Log log.LogLevel + +func (l *Log) UnmarshalText(text []byte) error { + switch string(text) { + case "", "erronly": + *l = Log(log.LogLevelErrOnly) + case "verbose": + *l = Log(log.LogLevelVerbose) + case "debug": + *l = Log(log.LogLevelDebug) + default: + return fmt.Errorf(`invalid log option %q, `+ + `use either of: ["" (same as erronly), "erronly", "verbose", "debug"]`, + string(text)) + } + return nil +} + type Requires action.Type func (r *Requires) UnmarshalText(text []byte) error { @@ -230,6 +251,8 @@ func MustParse(version string) *Config { flag.StringVar(&fConfigPath, "config", "./templier.yml", "config file path") flag.Parse() + log.Debugf("reading config file: %q", fConfigPath) + if fVersion { PrintVersionInfoAndExit(version) } @@ -264,11 +287,13 @@ func MustParse(version string) *Config { log.Fatalf("getting working dir: %v", err) } config.serverOutPath = path.Join(os.TempDir(), workingDir) + log.Debugf("set server output path: %q", config.serverOutPath) config.App.dirSrcRootAbsolute, err = filepath.Abs(config.App.DirSrcRoot) if err != nil { log.Fatalf("getting absolute path for app.dir-src-root: %v", err) } + log.Debugf("set source directory absolute path: %q", config.App.dirSrcRootAbsolute) return &config } diff --git a/internal/log/log.go b/internal/log/log.go index 3fafb4a..5270f1e 100644 --- a/internal/log/log.go +++ b/internal/log/log.go @@ -13,9 +13,9 @@ import ( ) var ( - lock sync.Mutex - out io.Writer - verbose atomic.Bool + lock sync.Mutex + out io.Writer + level atomic.Int32 fBlueUnderline = color.New(color.FgBlue, color.Underline) fGreen = color.New(color.FgGreen, color.Bold) @@ -27,16 +27,33 @@ func init() { out = os.Stdout } -func SetVerbose(enable bool) { verbose.Store(enable) } +type LogLevel int32 + +const ( + LogLevelErrOnly LogLevel = 0 + LogLevelVerbose LogLevel = 1 + LogLevelDebug LogLevel = 2 +) + +const TimeFormat = "3:04:05.000 PM" + +func SetLogLevel(l LogLevel) { level.Store(int32(l)) } + +func Level() LogLevel { return LogLevel(level.Load()) } // TemplierStarted prints the Templiér started log to console. func TemplierStarted(baseURL string) { - if !verbose.Load() { + if Level() < LogLevelVerbose { return } lock.Lock() defer lock.Unlock() - fmt.Fprint(out, "🤖 Templiér ") + fmt.Fprint(out, "🤖 ") + if Level() >= LogLevelDebug { + fmt.Fprint(out, time.Now().Format(TimeFormat)) + fmt.Fprint(out, " INFO: ") + } + fmt.Fprint(out, "Templiér ") fGreen.Fprint(out, "started") fmt.Fprint(out, " on ") fBlueUnderline.Fprintln(out, baseURL) @@ -44,36 +61,64 @@ func TemplierStarted(baseURL string) { // TemplierRestartingServer prints the server restart trigger log to console. func TemplierRestartingServer(cmdServerPath string) { - if !verbose.Load() { + if Level() < LogLevelVerbose { return } lock.Lock() defer lock.Unlock() - fmt.Fprint(out, "🤖 restarting ") + fmt.Fprint(out, "🤖 ") + if Level() >= LogLevelDebug { + fmt.Fprint(out, time.Now().Format(TimeFormat)) + fmt.Fprint(out, " INFO: ") + } + fmt.Fprint(out, "restarting ") fGreen.Fprintln(out, cmdServerPath) } // TemplierFileChange prints a file change log to console. func TemplierFileChange(e fsnotify.Event) { - if !verbose.Load() { + if Level() < LogLevelVerbose { return } lock.Lock() defer lock.Unlock() - fmt.Fprint(out, "🤖 file ") + fmt.Fprint(out, "🤖 ") + if Level() >= LogLevelDebug { + fmt.Fprint(out, time.Now().Format(TimeFormat)) + fmt.Fprint(out, " INFO: ") + } + fmt.Fprint(out, "file ") fmt.Fprint(out, fileOpStr(e.Op)) fmt.Fprint(out, ": ") fBlueUnderline.Fprintln(out, e.Name) } +// Debugf prints an info line to console. +func Debugf(f string, v ...any) { + if Level() < LogLevelDebug { + return + } + lock.Lock() + defer lock.Unlock() + fmt.Fprint(out, "🤖 ") + fmt.Fprint(out, time.Now().Format(TimeFormat)) + fmt.Fprint(out, " DEBUG: ") + fmt.Fprintf(out, f, v...) + fmt.Fprintln(out, "") +} + // Infof prints an info line to console. func Infof(f string, v ...any) { - if !verbose.Load() { + if Level() < LogLevelVerbose { return } lock.Lock() defer lock.Unlock() - fmt.Fprint(out, "🤖: ") + fmt.Fprint(out, "🤖 ") + if Level() >= LogLevelDebug { + fmt.Fprint(out, time.Now().Format(TimeFormat)) + fmt.Fprint(out, " INFO: ") + } fmt.Fprintf(out, f, v...) fmt.Fprintln(out, "") } @@ -82,7 +127,12 @@ func Infof(f string, v ...any) { func Errorf(f string, v ...any) { lock.Lock() defer lock.Unlock() - fRed.Fprint(out, "🤖 ERR: ") + fmt.Fprint(out, "🤖 ") + if Level() >= LogLevelDebug { + fmt.Fprint(out, time.Now().Format(TimeFormat)) + fmt.Fprint(out, " ") + } + fRed.Fprint(out, "ERR: ") fmt.Fprintf(out, f, v...) fmt.Fprintln(out, "") } @@ -91,7 +141,12 @@ func Errorf(f string, v ...any) { func Fatalf(f string, v ...any) { lock.Lock() defer lock.Unlock() - fRed.Fprint(out, "🤖 ERR: ") + fmt.Fprint(out, "🤖 ") + if Level() >= LogLevelDebug { + fmt.Fprint(out, time.Now().Format(TimeFormat)) + fmt.Fprint(out, " ") + } + fRed.Fprint(out, "ERR: ") fmt.Fprintf(out, f, v...) fmt.Fprintln(out, "") os.Exit(1) @@ -99,12 +154,16 @@ func Fatalf(f string, v ...any) { // Durf prints an error. func Durf(msg string, d time.Duration) { - if !verbose.Load() { + if Level() < LogLevelVerbose { return } lock.Lock() defer lock.Unlock() fmt.Fprint(out, "🤖 ") + if Level() >= LogLevelDebug { + fmt.Fprint(out, time.Now().Format(TimeFormat)) + fmt.Fprint(out, ": ") + } fmt.Fprint(out, msg) fmt.Fprint(out, " (") fRed.Fprintf(out, durStr(d)) diff --git a/internal/server/server.go b/internal/server/server.go index 67ddb68..94be194 100644 --- a/internal/server/server.go +++ b/internal/server/server.go @@ -200,8 +200,14 @@ func (s *Server) handleProxyEvents(w http.ResponseWriter, r *http.Request) { s.stateTracker.RemoveListener(notifyStateChange) s.reload.RemoveListener(notifyReload) cancel() + log.Debugf("websockets: disconnect (%p); %d active listener(s)", + c, s.stateTracker.NumListeners()) }() + log.Debugf( + "websockets: upgrade connection (%p): %q; %d active listener(s)", + c, r.URL.String(), s.stateTracker.NumListeners()) + go func() { defer cancel() for { @@ -216,10 +222,12 @@ func (s *Server) handleProxyEvents(w http.ResponseWriter, r *http.Request) { case <-ctx.Done(): return case <-notifyStateChange: + log.Debugf("websockets: notify state change (%p)", c) if !writeWSMsg(c, bytesMsgReload) { return // Disconnect } case <-notifyReload: + log.Debugf("websockets: notify reload (%p)", c) if !writeWSMsg(c, bytesMsgReload) { return // Disconnect } diff --git a/internal/statetrack/statetrack.go b/internal/statetrack/statetrack.go index bf246d9..0055204 100644 --- a/internal/statetrack/statetrack.go +++ b/internal/statetrack/statetrack.go @@ -58,6 +58,11 @@ func (t *Tracker) GetCustomWatcher(index int) string { return t.errMsgBuffer[IndexOffsetCustomWatcher+index] } +// NumListeners returns the number of currently active listeners. +func (s *Tracker) NumListeners() int { + return s.broadcaster.Len() +} + // AddListener adds a listener channel. // c will be written struct{}{} to when a state change happens. func (s *Tracker) AddListener(c chan<- struct{}) { diff --git a/internal/watcher/watcher.go b/internal/watcher/watcher.go index 95a676a..06b5f5f 100644 --- a/internal/watcher/watcher.go +++ b/internal/watcher/watcher.go @@ -15,6 +15,7 @@ import ( "github.com/fsnotify/fsnotify" "github.com/gobwas/glob" "github.com/romshark/templier/internal/filereg" + "github.com/romshark/templier/internal/log" ) // Watcher is a recursive file watcher. @@ -276,6 +277,7 @@ func (w *Watcher) Add(dir string) error { } func (w *Watcher) add(dir string) error { + log.Debugf("watching directory: %q", dir) err := forEachDir(dir, func(dir string) error { if err := w.isExluded(dir); err != nil { if err == errExcluded { @@ -311,6 +313,7 @@ func (w *Watcher) remove(dir string) error { if _, ok := w.watchedDirs[dir]; !ok { return nil } + log.Debugf("unwatch directory: %q", dir) delete(w.watchedDirs, dir) if err := w.removeWatcher(dir); err != nil { return err diff --git a/main.go b/main.go index dcda303..dcc6ee2 100644 --- a/main.go +++ b/main.go @@ -77,7 +77,7 @@ var version string func main() { conf := config.MustParse(version) - log.SetVerbose(conf.Verbose) + log.SetLogLevel(log.LogLevel(conf.Log)) ctx, cancel := signal.NotifyContext(context.Background(), os.Interrupt) defer cancel() @@ -85,6 +85,7 @@ func main() { defer func() { // Make sure files created by this process are cleaned up log.Infof("cleaning up all created files") filesToBeDeletedBeforeExit.ForEach(func(filePath string) { + log.Debugf("removing file before exit: %q", filePath) if err := os.RemoveAll(filePath); err != nil { log.Errorf("removing (%q): %v", filePath, err) } @@ -185,6 +186,7 @@ func main() { if err != nil { log.Fatalf("determining absolute base file path: %v", err) } + log.Debugf("set absolute base file path: %q", onChangeHandler.baseFilePath) watcher, err := watcher.New(conf.App.DirSrcRootAbsolute(), onChangeHandler.Handle) if err != nil { @@ -219,6 +221,7 @@ func main() { } <-ctx.Done() + log.Debugf("waiting for server to shut down") wg.Wait() chStopServer <- struct{}{} } @@ -262,6 +265,7 @@ func runAppLauncher( if latestSrvCmd == nil || latestSrvCmd.Process == nil { return true } + log.Debugf("stopping app server with pid %d", latestSrvCmd.Process.Pid) if err := latestSrvCmd.Process.Signal(os.Interrupt); err != nil { log.Errorf("sending interrupt signal to app server: %v", err) return false @@ -302,9 +306,11 @@ func runAppLauncher( log.TemplierRestartingServer(conf.App.DirCmd) + log.Debugf("running app server command: %s", latestSrvCmd.String()) if err := c.Start(); err != nil { log.Errorf("running %s: %v", conf.App.DirCmd, err) } + log.Debugf("app server running (pid: %d)", c.Process.Pid) var exitCode atomic.Int32 exitCode.Store(-1) @@ -319,7 +325,7 @@ func runAppLauncher( return } // Some other error occurred - panic(err) + log.Errorf("health check: waiting for process: %v", err) }() const maxRetries = 100 @@ -333,6 +339,8 @@ func runAppLauncher( return } // Wait for the server to be ready + log.Debugf("health check (%d/%d): %s %q", + retry, maxRetries, http.MethodOptions, conf.App.Host.URL.String()) r, err := http.NewRequest( http.MethodOptions, conf.App.Host.URL.String(), http.NoBody, ) @@ -343,13 +351,17 @@ func runAppLauncher( } _, err = healthCheckClient.Do(r) if err == nil { + log.Debugf("health check: OK, " + + "app server is ready to receive requests") break // Server is ready to receive requests } + log.Debugf("health check: err: %v", err) if code := exitCode.Load(); code != -1 && code != 0 { log.Errorf("health check: app server exited with exit code %d", code) stateTracker.Set(statetrack.IndexExit, bufOutputCombined.String()) return } + log.Debugf("health check: wait: %s", ServerHealthPreflightWaitInterval) time.Sleep(ServerHealthPreflightWaitInterval) } @@ -390,6 +402,7 @@ type FileChangeHandler struct { func (h *FileChangeHandler) Handle(ctx context.Context, e fsnotify.Event) error { if e.Op == fsnotify.Chmod { + log.Debugf("ignoring file operation (%s): %q", e.Op.String(), e.Name) return nil // Ignore chmod events. } @@ -401,6 +414,8 @@ func (h *FileChangeHandler) Handle(ctx context.Context, e fsnotify.Event) error ) } + log.Debugf("handling file operation (%s): %q", e.Op.String(), relativeFileName) + var wg sync.WaitGroup var customWatcherTriggered atomic.Bool var act action.SyncStatus @@ -463,17 +478,23 @@ func (h *FileChangeHandler) Handle(ctx context.Context, e fsnotify.Event) error switch act.Load() { case action.ActionNone: // Custom watchers require no further action to be taken. + log.Debugf("custom watchers: no action") return nil case action.ActionReload: // Custom watchers require just a reload of all browser tabs. + log.Debugf("custom watchers: notify reload") h.reload.BroadcastNonblock() return nil case action.ActionRestart: // Custom watchers require just a server restart. + log.Debugf("custom watchers: rerun app server") chRerunServer <- struct{}{} return nil + default: + log.Debugf("custom watchers: rebuild app server") } } else { + log.Debugf("custom watchers: no watcher triggered") // No custom watcher triggered, follow default pipeline. if strings.HasSuffix(e.Name, ".templ") { return nil // Ignore templ files, templ watch will take care of them.