logging with zerolog

cmd/main.go

@@ -71,7 +71,5 @@ func main() {
 	utils.Check(err, "could not run database AutoMigrate")
 
 	w := watcher.NewWatcher()
-
-	log.Printf("started watcher loop")
 	w.Watch()
 }

go.mod

@@ -4,6 +4,7 @@ go 1.21.1
 
 require (
 	github.com/spf13/viper v1.18.2
+	gopkg.in/gomail.v2 v2.0.0-20160411212932-81ebce5c23df
 	gorm.io/driver/sqlite v1.5.4
 	gorm.io/gorm v1.25.6
 )
@@ -14,9 +15,12 @@ require (
 	github.com/jinzhu/inflection v1.0.0 // indirect
 	github.com/jinzhu/now v1.1.5 // indirect
 	github.com/magiconair/properties v1.8.7 // indirect
+	github.com/mattn/go-colorable v0.1.13 // indirect
+	github.com/mattn/go-isatty v0.0.20 // indirect
 	github.com/mattn/go-sqlite3 v1.14.17 // indirect
 	github.com/mitchellh/mapstructure v1.5.0 // indirect
 	github.com/pelletier/go-toml/v2 v2.1.0 // indirect
+	github.com/rs/zerolog v1.31.0 // indirect
 	github.com/sagikazarmark/locafero v0.4.0 // indirect
 	github.com/sagikazarmark/slog-shim v0.1.0 // indirect
 	github.com/sourcegraph/conc v0.3.0 // indirect
@@ -27,10 +31,9 @@ require (
 	go.uber.org/atomic v1.9.0 // indirect
 	go.uber.org/multierr v1.9.0 // indirect
 	golang.org/x/exp v0.0.0-20230905200255-921286631fa9 // indirect
-	golang.org/x/sys v0.15.0 // indirect
+	golang.org/x/sys v0.16.0 // indirect
 	golang.org/x/text v0.14.0 // indirect
 	gopkg.in/alexcesaro/quotedprintable.v3 v3.0.0-20150716171945-2caba252f4dc // indirect
-	gopkg.in/gomail.v2 v2.0.0-20160411212932-81ebce5c23df // indirect
 	gopkg.in/ini.v1 v1.67.0 // indirect
 	gopkg.in/yaml.v3 v3.0.1 // indirect
 )

go.sum

@@ -1,3 +1,4 @@
+github.com/coreos/go-systemd/v22 v22.5.0/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc=
 github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
 github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
 github.com/davecgh/go-spew v1.1.2-0.20180830191138-d8f796af33cc h1:U9qPSI2PIWSS1VwoXQT9A3Wy9MM3WgvqSxFWenqJduM=
@@ -6,6 +7,7 @@ github.com/frankban/quicktest v1.14.6 h1:7Xjx+VpznH+oBnejlPUj8oUpdxnVs4f8XU8WnHk
 github.com/frankban/quicktest v1.14.6/go.mod h1:4ptaffx2x8+WTWXmUCuVU6aPUX1/Mz7zb5vbUoiM6w0=
 github.com/fsnotify/fsnotify v1.7.0 h1:8JEhPFa5W2WU7YfeZzPNqzMP6Lwt7L2715Ggo0nosvA=
 github.com/fsnotify/fsnotify v1.7.0/go.mod h1:40Bi/Hjc2AVfZrqy+aj+yEI+/bRxZnMJyTJwOpGvigM=
+github.com/godbus/dbus/v5 v5.0.4/go.mod h1:xhWf0FNVPg57R7Z0UbKHbJfkEywrmjJnf7w5xrFpKfA=
 github.com/google/go-cmp v0.5.9 h1:O2Tfq5qg4qc4AmwVlvv0oLiVAGB7enBSJ2x2DqQFi38=
 github.com/google/go-cmp v0.5.9/go.mod h1:17dUlkBOakJ0+DkrSSNjCkIjxS6bF9zb3elmeNGIjoY=
 github.com/hashicorp/hcl v1.0.0 h1:0Anlzjpi4vEasTeNFn2mLJgTSwt0+6sfsiTG8qcWGx4=
@@ -20,17 +22,27 @@ github.com/kr/text v0.2.0 h1:5Nx0Ya0ZqY2ygV366QzturHI13Jq95ApcVaJBhpS+AY=
 github.com/kr/text v0.2.0/go.mod h1:eLer722TekiGuMkidMxC/pM04lWEeraHUUmBw8l2grE=
 github.com/magiconair/properties v1.8.7 h1:IeQXZAiQcpL9mgcAe1Nu6cX9LLw6ExEHKjN0VQdvPDY=
 github.com/magiconair/properties v1.8.7/go.mod h1:Dhd985XPs7jluiymwWYZ0G4Z61jb3vdS329zhj2hYo0=
+github.com/mattn/go-colorable v0.1.13 h1:fFA4WZxdEF4tXPZVKMLwD8oUnCTTo08duU7wxecdEvA=
+github.com/mattn/go-colorable v0.1.13/go.mod h1:7S9/ev0klgBDR4GtXTXX8a3vIGJpMovkB8vQcUbaXHg=
+github.com/mattn/go-isatty v0.0.16/go.mod h1:kYGgaQfpe5nmfYZH+SKPsOc2e4SrIfOl2e/yFXSvRLM=
+github.com/mattn/go-isatty v0.0.19/go.mod h1:W+V8PltTTMOvKvAeJH7IuucS94S2C6jfK/D7dTCTo3Y=
+github.com/mattn/go-isatty v0.0.20 h1:xfD0iDuEKnDkl03q4limB+vH+GxLEtL/jb4xVJSWWEY=
+github.com/mattn/go-isatty v0.0.20/go.mod h1:W+V8PltTTMOvKvAeJH7IuucS94S2C6jfK/D7dTCTo3Y=
 github.com/mattn/go-sqlite3 v1.14.17 h1:mCRHCLDUBXgpKAqIKsaAaAsrAlbkeomtRFKXh2L6YIM=
 github.com/mattn/go-sqlite3 v1.14.17/go.mod h1:2eHXhiwb8IkHr+BDWZGa96P6+rkvnG63S2DGjv9HUNg=
 github.com/mitchellh/mapstructure v1.5.0 h1:jeMsZIYE/09sWLaz43PL7Gy6RuMjD2eJVyuac5Z2hdY=
 github.com/mitchellh/mapstructure v1.5.0/go.mod h1:bFUtVrKA4DC2yAKiSyO/QUcy7e+RRV2QTWOzhPopBRo=
 github.com/pelletier/go-toml/v2 v2.1.0 h1:FnwAJ4oYMvbT/34k9zzHuZNrhlz48GB3/s6at6/MHO4=
 github.com/pelletier/go-toml/v2 v2.1.0/go.mod h1:tJU2Z3ZkXwnxa4DPO899bsyIoywizdUvyaeZurnPPDc=
+github.com/pkg/errors v0.9.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0=
 github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
 github.com/pmezard/go-difflib v1.0.1-0.20181226105442-5d4384ee4fb2 h1:Jamvg5psRIccs7FGNTlIRMkT8wgtp5eCXdBlqhYGL6U=
 github.com/pmezard/go-difflib v1.0.1-0.20181226105442-5d4384ee4fb2/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
 github.com/rogpeppe/go-internal v1.9.0 h1:73kH8U+JUqXU8lRuOHeVHaa/SZPifC7BkcraZVejAe8=
 github.com/rogpeppe/go-internal v1.9.0/go.mod h1:WtVeX8xhTBvf0smdhujwtBcq4Qrzq/fJaraNFVN+nFs=
+github.com/rs/xid v1.5.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg=
+github.com/rs/zerolog v1.31.0 h1:FcTR3NnLWW+NnTwwhFWiJSZr4ECLpqCm6QsEnyvbV4A=
+github.com/rs/zerolog v1.31.0/go.mod h1:/7mN4D5sKwJLZQ2b/znpjC3/GQWY/xaDXUM0kKWRHss=
 github.com/sagikazarmark/locafero v0.4.0 h1:HApY1R9zGo4DBgr7dqsTH/JJxLTTsOt7u6keLGt6kNQ=
 github.com/sagikazarmark/locafero v0.4.0/go.mod h1:Pe1W6UlPYUk/+wc/6KFhbORCfqzgYEpgQ3O5fPuL3H4=
 github.com/sagikazarmark/slog-shim v0.1.0 h1:diDBnUNK9N/354PgrxMywXnAwEr1QZcOr6gto+ugjYE=
@@ -61,8 +73,11 @@ go.uber.org/multierr v1.9.0 h1:7fIwc/ZtS0q++VgcfqFDxSBZVv/Xo49/SYnDFupUwlI=
 go.uber.org/multierr v1.9.0/go.mod h1:X2jQV1h+kxSjClGpnseKVIxpmcjrj7MNnI0bnlfKTVQ=
 golang.org/x/exp v0.0.0-20230905200255-921286631fa9 h1:GoHiUyI/Tp2nVkLI2mCxVkOjsbSXD66ic0XW0js0R9g=
 golang.org/x/exp v0.0.0-20230905200255-921286631fa9/go.mod h1:S2oDrQGGwySpoQPVqRShND87VCbxmc6bL1Yd2oYrm6k=
-golang.org/x/sys v0.15.0 h1:h48lPFYpsTvQJZF4EKyI4aLHaev3CxivZmv7yZig9pc=
-golang.org/x/sys v0.15.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA=
+golang.org/x/sys v0.0.0-20220811171246-fbc7d0a398ab/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
+golang.org/x/sys v0.6.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
+golang.org/x/sys v0.12.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
+golang.org/x/sys v0.16.0 h1:xWw16ngr6ZMtmxDyKyIgsE93KNKz5HKmMa3b8ALHidU=
+golang.org/x/sys v0.16.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA=
 golang.org/x/text v0.14.0 h1:ScX5w1eTa3QqT8oi6+ziP7dTV1S2+ALU0bI+0zXKWiQ=
 golang.org/x/text v0.14.0/go.mod h1:18ZOQIKpY8NJVqYksKHtTdi31H5itFRjB5/qKTNYzSU=
 gopkg.in/alexcesaro/quotedprintable.v3 v3.0.0-20150716171945-2caba252f4dc h1:2gGKlE2+asNV9m7xrywl36YYNnBG5ZQ0r/BOOxqPpmk=

internal/watcher/fetch.go

@@ -5,14 +5,15 @@ import (
 	"encoding/json"
 	"errors"
 	"io"
-	"log"
 	"net"
 	"net/http"
 	"strings"
 
 	"github.com/gweebg/ipwatcher/internal/config"
 )
 
+var fetchLogger = logger.With().Str("service", "fetcher").Logger()
+
 func RequestAddress(version string) (string, string, error) {
 
 	conf := config.GetConfig()
@@ -31,26 +32,27 @@ func RequestAddress(version string) (string, string, error) {
 
 		url, err := source.Url.GetUrl(version)
 		if err != nil {
-			log.Printf("source '%v' does not have any 'IP%v' url specified, skipping\n", source.Name, version)
+			fetchLogger.Error().Err(err).Str("source_name", source.Name).Msgf("source does not have any 'IP%v' url specified, skipping", version)
 			continue
 		}
 
 		response, err := sendRequest(url)
 		if err != nil {
-			log.Printf("failed to send request to source '%v', skipping\n", source.Name)
+			fetchLogger.Error().Err(err).Str("source_name", source.Name).Msg("failed to send request to source")
 			continue
 		}
 
 		address = parseResponse(response, source)
 
 		valid := net.ParseIP(address)
 		if valid == nil {
-			log.Printf("source '%v' did not return a valid IP address: '%v', skipping\n", source.Name, address)
+			fetchLogger.Error().Err(err).Str("source_name", source.Name).Msgf("source did not return a valid IP address: '%v', skipping", address)
 			continue
 		}
 
 		fromSource = url
-		log.Printf("valid address from source '%v'\n", source.Name)
+		fetchLogger.Debug().Str("source", url).Msgf("valid address from source '%v'", source.Name)
+
 		break
 	}
 
@@ -68,7 +70,7 @@ func parseResponse(response *http.Response, source config.Source) string {
 
 	// check if http response status code is 'positive' (200<=status<300)
 	if !(response.StatusCode >= 200 && response.StatusCode < 300) {
-		log.Printf("'%v' returned %d\n", source.Name, response.StatusCode)
+		fetchLogger.Warn().Msgf("'%v' returned %d", source.Name, response.StatusCode)
 		return ""
 	}
 
@@ -81,7 +83,7 @@ func parseResponse(response *http.Response, source config.Source) string {
 		var address bytes.Buffer
 		_, err := io.Copy(&address, response.Body)
 		if err != nil {
-			log.Printf("error reading response body from source '%v'", source.Name)
+			fetchLogger.Error().Err(err).Str("source_name", source.Name).Msg("error reading response body")
 			return ""
 		}
 
@@ -93,20 +95,20 @@ func parseResponse(response *http.Response, source config.Source) string {
 		var responseBody map[string]interface{}
 		err := json.NewDecoder(response.Body).Decode(&responseBody)
 		if err != nil {
-			log.Printf("error decoding JSON response from source '%v'", source.Name)
+			fetchLogger.Error().Err(err).Str("source_name", source.Name).Msg("error decoding JSON response")
 			return ""
 		}
 
 		address, ok := responseBody[*source.Field]
 		if !ok {
-			log.Printf("expected field '%v' present on response:\n\t%v", *source.Field, responseBody)
+			fetchLogger.Error().Str("source_name", source.Name).Msgf("expected field '%v' to be present on response", *source.Field)
 			return ""
 		}
 
 		return address.(string)
 	}
 
-	log.Printf("content type between response and config mismatch, expected '%s' but got '%s'\n", source.Type, contentType)
+	fetchLogger.Error().Str("source_name", source.Name).Msgf("content type between response and config mismatch, expected '%s' but got '%s'", source.Type, contentType)
 	return ""
 }
 

internal/watcher/notifier.go

@@ -5,10 +5,11 @@ import (
 	"fmt"
 	"github.com/gweebg/ipwatcher/internal/config"
 	"gopkg.in/gomail.v2"
-	"log"
 	"time"
 )
 
+var notifierLogger = logger.With().Str("service", "notifier").Logger()
+
 // Recipient represents a email recipient defined as per the configuration file
 type Recipient struct {
 	// Name of the recipient
@@ -45,7 +46,7 @@ func NewNotifier() *Notifier {
 	var recipients []Recipient
 	err := c.UnmarshalKey("watcher.smtp.recipients", &recipients)
 	if err != nil {
-		log.Fatalf("invalid 'watcher.smtp.recipients' configuration: %v\n", err.Error())
+		notifierLogger.Fatal().Err(err).Msgf("invalid 'watcher.smtp.recipients' configuration")
 	}
 
 	return &Notifier{
@@ -57,6 +58,8 @@ func NewNotifier() *Notifier {
 
 func (n *Notifier) NotifyMail(ctx context.Context) error {
 
+	notifierLogger.Debug().Msg("dialing smtp server")
+
 	s, err := n.emailDialer.Dial()
 	if err != nil {
 		return err
@@ -73,7 +76,7 @@ func (n *Notifier) NotifyMail(ctx context.Context) error {
 		m.SetBody("text/html", generateMailBody(ctx))
 
 		if err := gomail.Send(s, m); err != nil {
-			log.Printf("could not send email to %q: %v", r.Address, err)
+			notifierLogger.Error().Err(err).Msgf("cannot send email to '%s'", r.Address)
 		}
 		m.Reset()
 	}
@@ -119,7 +122,7 @@ func generateOnChange(ctx context.Context) string {
 	</head>
 	<body style="font-family: Arial, sans-serif;">
 		<div style="background-color: #f0f0f0; padding: 20px;">
-			<h1 style="color: #333;">Your Public IP Address Has Updated</h1>
+			<h1 style="color: #333;">Watcher Update (Change)</h1>
 			<p style="font-size: 16px;">Hello <strong>%s</strong>, your public IP address has been changed. Here are the details:</p>
 			<ul style="font-size: 16px;">
 				<li><strong>Previous Address:</strong> %s</li>
@@ -146,7 +149,7 @@ func generateOnMatch(ctx context.Context) string {
 	</head>
 	<body style="font-family: Arial, sans-serif;">
 		<div style="background-color: #f0f0f0; padding: 20px;">
-			<h1 style="color: #333;">Your Public IP Address Has <strong>Not</strong> Changed</h1>
+			<h1 style="color: #333;">Watcher Update (Match)</h1>
 			<p style="font-size: 16px;">Hello <strong>%s</strong>, your public IP address is still the same. Here are the details:</p>
 			<ul style="font-size: 16px;">
 				<li><strong>At:</strong> %s</li>

internal/watcher/watcher.go

@@ -5,12 +5,21 @@ import (
 	"errors"
 	"github.com/gweebg/ipwatcher/internal/config"
 	"github.com/gweebg/ipwatcher/internal/database"
-	"log"
+	"github.com/rs/zerolog"
 	"os"
 	"os/signal"
 	"time"
 )
 
+var logger = zerolog.New(zerolog.ConsoleWriter{Out: os.Stderr, TimeFormat: time.RFC3339}).
+	Level(zerolog.TraceLevel).
+	With().
+	Timestamp().
+	Caller().
+	Logger()
+
+var watcherLogger = logger.With().Str("service", "watcher").Logger()
+
 var (
 	ErrorDatabase = errors.New("database error")
 	ErrorNotifier = errors.New("notifier error")
@@ -22,19 +31,18 @@ type Watcher struct {
 
 	// Version indicates the versions the watcher is supposed to track (v4|v6|all)
 	Version string
-
 	// allowApi exposes an API with the database records
 	allowApi bool
 	// allowExec enables the execution of actions upon an event
 	allowExec bool
 
 	// notifier allows for email notification sending
 	notifier *Notifier
-
 	// Timeout represents the duration between each address query
 	Timeout time.Duration
 	// ticker is a *time.Ticker object responsible for waiting Timeout
 	ticker *time.Ticker
+
 	// tickerQuitChan allows the stop of the ticker
 	tickerQuitChan chan struct{}
 	// errorChan handles errors coming from the event handlers
@@ -59,23 +67,25 @@ func NewWatcher() *Watcher {
 		allowExec: c.GetBool("flags.exec"),
 
 		notifier: notifier,
+		Timeout:  timeout,
+		ticker:   time.NewTicker(timeout),
 
-		Timeout:        timeout,
-		ticker:         time.NewTicker(timeout),
 		tickerQuitChan: make(chan struct{}),
 		errorChan:      make(chan error),
 	}
 }
 
 func (w *Watcher) Watch() {
 
+	watcherLogger.Info().Msg("watcher service is now running")
+
 	c := make(chan os.Signal, 1)
 	signal.Notify(c, os.Interrupt)
 
 	go w.check()
 
 	for sig := range c {
-		log.Printf("received %v signal, stopping the application\n", sig.String())
+		watcherLogger.Warn().Msgf("received %v signal, stopping watcher...", sig.String())
 		w.Stop()
 		return
 	}
@@ -104,7 +114,7 @@ func (w *Watcher) HandleEvent(eventType string, ctx context.Context) {
 		handler = events.OnError
 
 	default:
-		log.Fatalf("unknown event type '%v', skipping\n", eventType)
+		watcherLogger.Fatal().Msgf("unknown event type '%v', skipping", eventType)
 	}
 
 	if handler != nil {
@@ -114,27 +124,30 @@ func (w *Watcher) HandleEvent(eventType string, ctx context.Context) {
 			if err != nil {
 				w.errorChan <- errors.Join(err, ErrorNotifier)
 			}
+			watcherLogger.Debug().
+				Str("event", eventType).
+				Msgf("recipients (%d) notified", len(w.notifier.Recipients))
 		}
 
 		for _, exec := range handler.Actions {
-			log.Printf("executing '%s %s %s'\n\n", exec.Type, exec.Path, exec.Args)
+			watcherLogger.Info().Msgf("executing '%s %s %s'\n\n", exec.Type, exec.Path, exec.Args)
 		}
 	}
 }
 
 func (w *Watcher) errors() {
 
 	ctx := context.Background()
+	ctx = context.WithValue(ctx, "timestamp", time.Now())
 
 	for err := range w.errorChan {
-		details := errors.Unwrap(err)
 
 		if !errors.Is(err, ErrorNotifier) {
-			ctx = context.WithValue(ctx, "error", details)
+			ctx = context.WithValue(ctx, "error", err)
 			w.HandleEvent("on_error", ctx) // handle on_error
 		}
 
-		log.Printf("an error occured:\n'%v'\n", err.Error())
+		watcherLogger.Error().Err(err).Msg("unexpected error")
 	}
 }
 
@@ -177,6 +190,11 @@ func (w *Watcher) check() {
 			// compare addresses and handle accordingly
 			if address != previousAddress.Address {
 
+				watcherLogger.Info().
+					Str("previous_address", previousAddress.Address).
+					Str("current_address", address).
+					Msgf("detected address change")
+
 				_, err = records.Create(address, w.Version, previousAddress.Address) // insert new record onto the database
 				if err != nil {
 					w.errorChan <- errors.Join(err, ErrorDatabase)
@@ -190,6 +208,9 @@ func (w *Watcher) check() {
 				go w.HandleEvent("on_change", ctx) // handle on_change
 
 			} else {
+
+				watcherLogger.Debug().Msgf("no address changes")
+
 				ctx = context.WithValue(ctx, "source", source)
 				go w.HandleEvent("on_match", ctx) // handle on_match
 			}