!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

@@ -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

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

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
 }
 

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,53 +27,98 @@ 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)
 }
 
 // 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,20 +141,29 @@ 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)
 }
 
 // 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))

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
 			}

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

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