feat: replace stdlib logger with logf

- replace log.Logger with logf.Logger
- add optional debug logging for logging OTP pushes

cmd/otpgateway/handlers.go

@@ -17,6 +17,7 @@ import (
 	"github.com/go-chi/chi"
 	"github.com/knadh/otpgateway/v3/internal/models"
 	"github.com/knadh/otpgateway/v3/internal/store"
+	"github.com/zerodha/logf"
 )
 
 const (
@@ -176,7 +177,7 @@ func handleSetOTP(w http.ResponseWriter, r *http.Request) {
 		return
 	} else if id == "" {
 		if i, err := generateRandomString(32, alphaNumChars); err != nil {
-			app.lo.Printf("error generating ID: %v", err)
+			app.lo.Error("error generating ID", "error", err)
 			sendErrorResponse(w, "Error generating ID.", http.StatusInternalServerError, nil)
 			return
 		} else {
@@ -188,7 +189,7 @@ func handleSetOTP(w http.ResponseWriter, r *http.Request) {
 	if otpVal == "" {
 		o, err := generateRandomString(p.provider.MaxOTPLen(), numChars)
 		if err != nil {
-			app.lo.Printf("error generating OTP: %v", err)
+			app.lo.Error("error generating OTP", "error", err)
 			sendErrorResponse(w, "Error generating OTP.", http.StatusInternalServerError, nil)
 			return
 		}
@@ -198,7 +199,7 @@ func handleSetOTP(w http.ResponseWriter, r *http.Request) {
 	// Check if the OTP attempts have exceeded the quota.
 	otp, err := app.store.Check(namespace, id, false)
 	if err != nil && err != store.ErrNotExist {
-		app.lo.Printf("error checking OTP status: %v", err)
+		app.lo.Error("error checking OTP status", "error", err)
 		sendErrorResponse(w, "Error checking OTP status.", http.StatusBadRequest, nil)
 		return
 	}
@@ -228,15 +229,15 @@ func handleSetOTP(w http.ResponseWriter, r *http.Request) {
 		MaxAttempts: maxAttempts,
 	})
 	if err != nil {
-		app.lo.Printf("error setting OTP: %v", err)
+		app.lo.Error("error setting OTP", "error", err)
 		sendErrorResponse(w, "Error setting OTP.", http.StatusInternalServerError, nil)
 		return
 	}
 
 	// Push the OTP out.
 	if to != "" {
-		if err := push(newOTP, p, app.constants.RootURL); err != nil {
-			app.lo.Printf("error sending OTP: %s: %v", p.provider.ID(), err)
+		if err := push(app.lo, newOTP, p, app.constants.RootURL); err != nil {
+			app.lo.Error("error sending OTP", "error", err, "provider", p.provider.ID())
 			sendErrorResponse(w, "Error sending OTP.", http.StatusInternalServerError, nil)
 			return
 		}
@@ -267,7 +268,7 @@ func handleCheckOTPStatus(w http.ResponseWriter, r *http.Request) {
 			return
 		}
 
-		app.lo.Printf("error checking OTP: %v", err)
+		app.lo.Error("error checking OTP", "error", err)
 		sendErrorResponse(w, err.Error(), http.StatusBadRequest, nil)
 		return
 	}
@@ -392,8 +393,8 @@ func handleOTPView(w http.ResponseWriter, r *http.Request) {
 	// It's a resend request.
 	if action == actResend {
 		msg = "OTP resent"
-		if err := push(out, pro, app.constants.RootURL); err != nil {
-			app.lo.Printf("error sending OTP: %s: %v", pro.provider.ID(), err)
+		if err := push(app.lo, out, pro, app.constants.RootURL); err != nil {
+			app.lo.Error("error sending OTP", "error", err, "provider", pro.provider.ID())
 			otpErr = errors.New("error resending OTP.")
 		}
 	}
@@ -457,7 +458,7 @@ func handleAddressView(w http.ResponseWriter, r *http.Request) {
 					Please re-initiate the verification.`,
 			})
 		} else {
-			app.lo.Printf("error checking OTP: %v", err)
+			app.lo.Error("error checking OTP", "error", err)
 			app.tpl.ExecuteTemplate(w, "message", webviewTpl{App: app.constants,
 				Title:       "Internal error",
 				Description: `Please try later.`,
@@ -491,8 +492,8 @@ func handleAddressView(w http.ResponseWriter, r *http.Request) {
 			msg = err.Error()
 		} else {
 			out.To = to
-			if err := push(out, pro, app.constants.RootURL); err != nil {
-				app.lo.Printf("error sending OTP: %s: %v", pro.provider.ID(), err)
+			if err := push(app.lo, out, pro, app.constants.RootURL); err != nil {
+				app.lo.Error("error sending OTP", "error", err, "provider", pro.provider.ID())
 				msg = "error sending OTP"
 			} else {
 				http.Redirect(w, r, fmt.Sprintf(uriViewOTP, out.Namespace, out.ID),
@@ -519,7 +520,7 @@ func verifyOTP(namespace, id, otp string, deleteOnVerify bool, app *App) (models
 	out, err := app.store.Check(namespace, id, true)
 	if err != nil {
 		if err != store.ErrNotExist {
-			app.lo.Printf("error checking OTP: %v", err)
+			app.lo.Error("error checking OTP", "error", err)
 			return out, err
 		}
 		return out, errors.New("error checking OTP.")
@@ -602,7 +603,7 @@ func isLocked(otp models.OTP) bool {
 }
 
 // push compiles a message template and pushes it to the provider.
-func push(otp models.OTP, p *provider, rootURL string) error {
+func push(lo logf.Logger, otp models.OTP, p *provider, rootURL string) error {
 	var (
 		subj = &bytes.Buffer{}
 		out  = &bytes.Buffer{}
@@ -630,6 +631,7 @@ func push(otp models.OTP, p *provider, rootURL string) error {
 		}
 	}
 
+	lo.Debug("sending otp", "to", otp.To, "provider", p.provider.ID(), "namespace", otp.Namespace)
 	return p.provider.Push(otp, subj.String(), out.Bytes())
 }
 

cmd/otpgateway/handlers_test.go

@@ -105,7 +105,7 @@ func init() {
 
 	// Dummy app.
 	app := &App{
-		lo:        lo,
+		lo:        initLogger(true),
 		providers: map[string]*provider{dummyProvider: &provider{provider: &dummyProv{}}},
 		providerTpls: map[string]*providerTpl{
 			dummyProvider: &providerTpl{

cmd/otpgateway/init.go

@@ -17,11 +17,21 @@ import (
 	"github.com/knadh/otpgateway/v3/internal/providers/pinpoint"
 	"github.com/knadh/otpgateway/v3/internal/providers/smtp"
 	"github.com/knadh/otpgateway/v3/internal/providers/webhook"
+	"github.com/zerodha/logf"
 
 	"github.com/knadh/stuffbin"
 	flag "github.com/spf13/pflag"
 )
 
+// initLogger initializes logger instance.
+func initLogger(debug bool) logf.Logger {
+	opts := logf.Opts{EnableCaller: true}
+	if debug {
+		opts.Level = logf.DebugLevel
+	}
+	return logf.New(opts)
+}
+
 type constants struct {
 	OtpTTL         time.Duration
 	OtpMaxAttempts int

cmd/otpgateway/main.go

@@ -13,6 +13,7 @@ import (
 	"github.com/knadh/otpgateway/v3/internal/store"
 	"github.com/knadh/otpgateway/v3/internal/store/redis"
 	"github.com/knadh/stuffbin"
+	"github.com/zerodha/logf"
 )
 
 // App is the global app context that groups the necessary
@@ -21,7 +22,7 @@ type App struct {
 	store        store.Store
 	providers    map[string]*provider
 	providerTpls map[string]*providerTpl
-	lo           *log.Logger
+	lo           logf.Logger
 	tpl          *template.Template
 	fs           stuffbin.FileSystem
 	constants    constants
@@ -41,7 +42,7 @@ func main() {
 	app := &App{
 		fs:        initFS(os.Args[0]),
 		providers: initProviders(ko),
-		lo:        lo,
+		lo:        initLogger(ko.Bool("app.enable_debug_logs")),
 
 		constants: constants{
 			OtpTTL:         ko.MustDuration("app.otp_ttl") * time.Second,
@@ -60,13 +61,13 @@ func main() {
 	// Compile static templates.
 	tpl, err := stuffbin.ParseTemplatesGlob(nil, app.fs, "/static/*.html")
 	if err != nil {
-		lo.Fatalf("error compiling template: %v", err)
+		app.lo.Fatal("error compiling template", "error", err)
 	}
 	app.tpl = tpl
 
 	authCreds := initAuth()
 	if len(authCreds) == 0 {
-		lo.Fatal("no auth entries found in config")
+		app.lo.Fatal("no auth entries found in config")
 	}
 
 	// Register HTTP handlers.
@@ -98,8 +99,8 @@ func main() {
 		Handler:      r,
 	}
 
-	lo.Printf("starting on %s", srv.Addr)
+	app.lo.Info("starting server", "address", srv.Addr)
 	if err := srv.ListenAndServe(); err != nil {
-		lo.Fatalf("couldn't start server: %v", err)
+		app.lo.Fatal("couldn't start server", "error", err)
 	}
 }

config.sample.toml

@@ -1,6 +1,7 @@
 [app]
 address = "0.0.0.0:9000"
 server_timeout = "5s"
+enable_debug_logs = true
 
 # TTL / Expiry for the OTP in seconds.
 otp_ttl = 300

go.mod

@@ -13,7 +13,7 @@ require (
 	github.com/knadh/stuffbin v1.1.0
 	github.com/mitchellh/mapstructure v1.4.3 // indirect
 	github.com/spf13/pflag v1.0.5
-	github.com/stretchr/testify v1.7.0
+	github.com/stretchr/testify v1.8.0
 	github.com/yuin/gopher-lua v0.0.0-20190125051437-7b9317363aa9 // indirect
-	gopkg.in/yaml.v3 v3.0.0-20210107192922-496545a6307b // indirect
+	github.com/zerodha/logf v0.5.5
 )

go.sum

@@ -77,6 +77,11 @@ github.com/knadh/smtppool v0.4.0 h1:335iXPwZ6katJVhauV4O6e8uPvvPmO6YLrfDQhb6UvE=
 github.com/knadh/smtppool v0.4.0/go.mod h1:3DJHouXAgPDBz0kC50HukOsdapYSwIEfJGwuip46oCA=
 github.com/knadh/stuffbin v1.1.0 h1:f5S5BHzZALjuJEgTIOMC9NidEnBJM7Ze6Lu1GHR/lwU=
 github.com/knadh/stuffbin v1.1.0/go.mod h1:yVCFaWaKPubSNibBsTAJ939q2ABHudJQxRWZWV5yh+4=
+github.com/kr/pretty v0.1.0 h1:L/CwN0zerZDmRFUapSPitk6f+Q3+0za1rQkzVuMiMFI=
+github.com/kr/pretty v0.1.0/go.mod h1:dAy3ld7l9f0ibDNOQOHHMYYIIbhfbHSm3C4ZsoJORNo=
+github.com/kr/pty v1.1.1/go.mod h1:pFQYn66WHrOpPYNljwOMqo10TkYh1fy3cYio2l3bCsQ=
+github.com/kr/text v0.1.0 h1:45sCR5RtlFHMR4UwH9sdQ5TC8v0qDQCHnXt+kaKSTVE=
+github.com/kr/text v0.1.0/go.mod h1:4Jbv+DJW3UT/LiOwJeYQe1efqtUx/iVham/4vfdArNI=
 github.com/mattn/go-colorable v0.0.9/go.mod h1:9vuHe8Xs5qXnSaW/c/ABM9alt+Vo+STaOChaDxuIBZU=
 github.com/mattn/go-isatty v0.0.3/go.mod h1:M+lRXTBqGeGNdLjl/ufCoiOlB5xdOkqRJdNxMWT7Zi4=
 github.com/mitchellh/cli v1.0.0/go.mod h1:hNIlj7HEI86fIcpObd7a0FcrxTWetlwJDGcceTlRvqc=
@@ -110,12 +115,17 @@ github.com/ryanuber/go-glob v1.0.0/go.mod h1:807d1WSdnB0XRJzKNil9Om6lcp/3a0v4qIH
 github.com/spf13/pflag v1.0.5 h1:iy+VFUOCP1a+8yFto/drg2CJ5u0yRoB7fZw3DKv/JXA=
 github.com/spf13/pflag v1.0.5/go.mod h1:McXfInJRrz4CZXVZOBLb0bTZqETkiAhM9Iw0y3An2Bg=
 github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
+github.com/stretchr/objx v0.4.0/go.mod h1:YvHI0jy2hoMjB+UWwv71VJQ9isScKT/TqJzVSSt89Yw=
 github.com/stretchr/testify v1.2.2/go.mod h1:a8OnRcib4nhh0OaRAV+Yts87kKdq0PP7pXfy6kDkUVs=
 github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI=
-github.com/stretchr/testify v1.7.0 h1:nwc3DEeHmmLAfoZucVR881uASk0Mfjw8xYJ99tb5CcY=
 github.com/stretchr/testify v1.7.0/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg=
+github.com/stretchr/testify v1.7.1/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg=
+github.com/stretchr/testify v1.8.0 h1:pSgiaMZlXftHpm5L7V1+rVB+AZJydKsMxsQBIJw4PKk=
+github.com/stretchr/testify v1.8.0/go.mod h1:yNjHg4UonilssWZ8iaSj1OCr/vHnekPRkoO+kdMU+MU=
 github.com/yuin/gopher-lua v0.0.0-20190125051437-7b9317363aa9 h1:Wy3fAQLBPP0JSWdq3kBnmbFgXDHcyhtPpd+8kENV7mU=
 github.com/yuin/gopher-lua v0.0.0-20190125051437-7b9317363aa9/go.mod h1:fFiAh+CowNFr0NK5VASokuwKwkbacRmHsVA7Yb1Tqac=
+github.com/zerodha/logf v0.5.5 h1:AhxHlixHNYwhFjvlgTv6uO4VBKYKxx2I6SbHoHtWLBk=
+github.com/zerodha/logf v0.5.5/go.mod h1:HWpfKsie+WFFpnUnUxelT6Z0FC6xu9+qt+oXNMPg6y8=
 golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w=
 golang.org/x/exp v0.0.0-20190121172915-509febef88a4/go.mod h1:CJ0aWSM057203Lf6IL+f9T1iT9GByDxfZKAQTCR3kQA=
 golang.org/x/lint v0.0.0-20181026193005-c67002cb31c3/go.mod h1:UVdnD1Gm6xHRNCYTkRU2/jEulfH38KcIWyp/GAMgvoE=
@@ -165,13 +175,14 @@ google.golang.org/grpc v1.14.0/go.mod h1:yo6s7OP7yaDglbqo1J04qKzAhqBH6lvTonzMVmE
 google.golang.org/grpc v1.19.0/go.mod h1:mqu4LbDTu4XGKhr4mRzUsmM4RtVoemTSY81AxZiDr8c=
 google.golang.org/grpc v1.22.0/go.mod h1:Y5yQAOtifL1yxbo5wqy6BxZv8vAUGQwXBOALyacEbxg=
 gopkg.in/asn1-ber.v1 v1.0.0-20181015200546-f715ec2f112d/go.mod h1:cuepJuh7vyXfUyUwEgHQXw849cJrilpS5NeIjOWESAw=
-gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405 h1:yhCVgyC4o1eVCa2tZl7eS0r+SDo693bJlVdllGtEeKM=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
+gopkg.in/check.v1 v1.0.0-20180628173108-788fd7840127 h1:qIbj1fsPNlZgppZ+VLlY7N33q108Sa+fhmuc+sWQYwY=
+gopkg.in/check.v1 v1.0.0-20180628173108-788fd7840127/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
 gopkg.in/square/go-jose.v2 v2.3.1/go.mod h1:M9dMgbHiYLoDGQrXy7OpJDJWiKiU//h+vD76mk0e1AI=
 gopkg.in/yaml.v2 v2.2.8 h1:obN1ZagJSUGI0Ek/LBmuj4SNLPfIny3KsKFopxRdj10=
 gopkg.in/yaml.v2 v2.2.8/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI=
 gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM=
-gopkg.in/yaml.v3 v3.0.0-20210107192922-496545a6307b h1:h8qDotaEPuJATrMmW04NCwg7v22aHH28wwpauUhK9Oo=
-gopkg.in/yaml.v3 v3.0.0-20210107192922-496545a6307b/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM=
+gopkg.in/yaml.v3 v3.0.1 h1:fxVm/GzAzEWqLHuvctI91KS9hhNmmWOoWu0XTYJS7CA=
+gopkg.in/yaml.v3 v3.0.1/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM=
 honnef.co/go/tools v0.0.0-20190102054323-c2f93a96b099/go.mod h1:rf3lG4BRIbNafJWhAfAdb/ePZxsR/4RtNHQocxwk9r4=
 honnef.co/go/tools v0.0.0-20190523083050-ea95bdfd59fc/go.mod h1:rf3lG4BRIbNafJWhAfAdb/ePZxsR/4RtNHQocxwk9r4=