go: switch to a custom slog-based logging solution

* make all packages use the logger
* add a couple of convenience methods on the logger that enable
  formatting using fmt syntax

go.mod

@@ -9,6 +9,7 @@ require (
 	github.com/philandstuff/dhall-golang/v6 v6.0.2
 	github.com/xiaoqidun/entps v0.0.0-20230328150929-94b1b92d8c03
 	golang.org/x/crypto v0.6.0
+	golang.org/x/exp v0.0.0-20230321023759-10a507213a29
 )
 
 require (

go.sum

@@ -101,6 +101,8 @@ github.com/zclconf/go-cty v1.8.0/go.mod h1:vVKLxnk3puL4qRAv72AO+W99LUD4da90g3uUA
 golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w=
 golang.org/x/crypto v0.6.0 h1:qfktjS5LUO+fFKeJXZ+ikTRijMmljikvG68fpMMruSc=
 golang.org/x/crypto v0.6.0/go.mod h1:OFC/31mSvZgRz0V1QTNCzfAI1aIRzbiufJtkMIlEp58=
+golang.org/x/exp v0.0.0-20230321023759-10a507213a29 h1:ooxPy7fPvB4kwsA2h+iBNHkAbp/4JxTSwCmvdjEYmug=
+golang.org/x/exp v0.0.0-20230321023759-10a507213a29/go.mod h1:CxIveKay+FTh1D0yPZemJVgC/95VzuuOLq5Qi4xnoYc=
 golang.org/x/mod v0.8.0 h1:LUYupSeNrTNCGzR/hVBk2NHZO4hXcVaW1k4Qx7rjPx8=
 golang.org/x/mod v0.8.0/go.mod h1:iBbtSCu2XBx23ZKBPSOrRkjjQPZFPuis4dIYUhu/chs=
 golang.org/x/net v0.0.0-20180906233101-161cd47e91fd/go.mod h1:mL1N/T3taQHkDXs73rZJwtUhF3w3ftmwwsq0BUmARs4=

handlers/config.go

@@ -2,24 +2,25 @@ package handlers
 
 import (
 	"io/fs"
-	"log"
 
 	"git.dotya.ml/mirre-mt/pcmt/config"
+	"git.dotya.ml/mirre-mt/pcmt/slogging"
 )
 
 var (
 	conf   *config.Config
 	appver string
+	log    *slogging.Logger
 )
 
 func setConfig(c *config.Config) {
 	if c != nil {
-		log.Printf("setting handler config to %#v", conf)
+		log.Info("setting handler config")
 		// c = conf
-		log.Printf("set handler config to %#v", c)
 		conf = c
+		log.Infof("set handler config to %#v", c)
 	} else {
-		log.Println("error passing conf to handlers")
+		log.Warn("error passing conf to handlers")
 	}
 }
 
@@ -28,11 +29,11 @@ func getConfig() *config.Config {
 }
 
 func setAppVer(v string) {
-	log.Printf("handlers version: %s", v)
 	appver = v
 }
 
 func InitHandlers(version string, appconf *config.Config, tmpls fs.FS) {
+	log = slogging.GetLogger()
 	setConfig(appconf)
 	setAppVer(version)
 	initTemplates(tmpls)

handlers/handlers.go

@@ -6,7 +6,6 @@ import (
 	"fmt"
 	"html/template"
 	"io/fs"
-	"log"
 	"net/http"
 	"path/filepath"
 	"strings"
@@ -31,12 +30,12 @@ func listAllTmpls() []string {
 		panic(err)
 	}
 
-	// log.Println(files)
 	for i, v := range files {
 		files[i] = strings.TrimPrefix(v, "templates/")
 	}
 
-	log.Println("returning files")
+	log.Info("returning files")
+
 	return files
 }
 
@@ -48,7 +47,6 @@ func setFuncMap(t *template.Template) {
 			return template.HTML(html)
 		},
 		"pageIs": func(want, got string) bool {
-			log.Printf("want: %s, got: %s", want, got)
 			if want == got {
 				return true
 			}
@@ -77,12 +75,10 @@ func getFuncMap() []template.FuncMap {
 
 func initTemplates(f fs.FS) {
 	// tmpls := tmpl
-	log.Println(tmplFS == nil)
 
 	if f != nil || f != tmplFS {
 		tmplFS = f
 	}
-	log.Println(tmplFS == nil)
 
 	// for _, funcs := range getFuncMap() {
 	// // log.Println(funcs)
@@ -146,7 +142,8 @@ func getTmpl(name string) *template.Template {
 		// tpl := template.Must(template.New(name).ParseFS(tmplFS, name))
 		// templateMap[name] = tpl
 		// return tpl
-		log.Println("re-reading tmpls")
+
+		log.Info("re-reading tmpls")
 		tpl := template.New("")
 		setFuncMap(tpl)
 		allTmpls := listAllTmpls()
@@ -228,7 +225,7 @@ func Index() echo.HandlerFunc {
 			},
 		)
 		if err != nil {
-			log.Printf("error when executing tmpl: '%q'", err)
+			log.Errorf("error when executing tmpl: '%q'", err)
 			return err
 		}
 
@@ -241,17 +238,16 @@ func Signin() echo.HandlerFunc {
 		session, err := c.Cookie("session")
 		if err != nil {
 			if err == http.ErrNoCookie {
-				log.Println("no session cookie found")
+				log.Info("no session cookie found")
 			}
 		}
 		if session != nil {
-			log.Println("got session")
+			log.Info("got session")
 			// if err := session.Valid(); err == nil && session.Expires.After(time.Now()) {
 			if err := session.Valid(); err == nil {
 				c.Redirect(302, "/home")
 			} else {
-				log.Println("invalid (or expired) session")
+				log.Warn("invalid (or expired) session", "error", err.Error())
-				log.Println("error:", err)
 			}
 		}
 
@@ -312,9 +308,9 @@ func SigninPost(client *ent.Client) echo.HandlerFunc {
 		var password string
 		if uname := c.Request().FormValue("username"); uname != "" {
 			username = uname
-			log.Printf("authenticating user '%s' at /signin", username)
+			log.Infof("authenticating user '%s' at /signin", username)
 		} else {
-			log.Printf("username was not set, returning to /signin")
+			log.Info("username was not set, returning to /signin")
 
 			c.Redirect(302, "/signin")
 
@@ -323,7 +319,7 @@ func SigninPost(client *ent.Client) echo.HandlerFunc {
 		if passwd := c.Request().FormValue("password"); passwd != "" {
 			password = passwd
 		} else {
-			log.Printf("password was not set, returning to /signin")
+			log.Info("password was not set, returning to /signin")
 
 			c.Redirect(302, "/signin")
 
@@ -334,10 +330,11 @@ func SigninPost(client *ent.Client) echo.HandlerFunc {
 		// Where(
 		// user.Username(username),
 		// ); usr != nil {
-		if usr, err := moduser.QueryUser(context.Background(), client, username); err == nil {
+		ctx := context.WithValue(context.Background(), "logger", log)
-			log.Println(usr)
+		if usr, err := moduser.QueryUser(ctx, client, username); err == nil {
+			log.Info("queried user:", &usr.ID)
 			if usr.Password != password {
-				log.Println("wrong user credentials, redirecting to /signin")
+				log.Warn("wrong user credentials, redirecting to /signin")
 
 				c.Redirect(302, "/signin")
 			}
@@ -357,11 +354,15 @@ func SigninPost(client *ent.Client) echo.HandlerFunc {
 		} else {
 			// just log the error instead of returning it to the user and
 			// redirect back to /signin.
-			log.Println(echo.NewHTTPError(
+			log.Warn(
+				http.StatusText(http.StatusUnauthorized)+" "+err.Error(),
+				echo.NewHTTPError(
 					http.StatusUnauthorized,
 					http.StatusText(http.StatusUnauthorized)+" "+err.Error(),
 				))
+
 			c.Redirect(302, "/signin")
+
 			return nil
 		}
 
@@ -389,17 +390,16 @@ func Signup() echo.HandlerFunc {
 		session, err := c.Cookie("session")
 		if err != nil {
 			if err == http.ErrNoCookie {
-				log.Println("no session cookie found")
+				log.Info("no session cookie found")
 			}
 		}
 		if session != nil {
-			log.Println("got session")
+			log.Info("got session")
 			// if err := session.Valid(); err == nil && session.Expires.After(time.Now()) {
 			if err := session.Valid(); err == nil {
 				c.Redirect(302, "/home")
 			} else {
-				log.Println("invalid (or expired) session")
+				log.Warn("invalid (or expired) session", "error", err.Error())
-				log.Println("error:", err)
 			}
 		}
 
@@ -430,7 +430,7 @@ func Signup() echo.HandlerFunc {
 			},
 		)
 		if err != nil {
-			log.Printf("error: %q", err)
+			log.Warnf("error: %q", err)
 			http.Error(c.Response().Writer, http.StatusText(http.StatusInternalServerError), http.StatusInternalServerError)
 		}
 
@@ -454,7 +454,8 @@ func SignupPost(client *ent.Client) echo.HandlerFunc {
 		if uname := c.Request().FormValue("username"); uname != "" {
 			username = uname
 			if passwd := c.Request().FormValue("password"); passwd != "" {
-				if u, err := moduser.CreateUser(context.Background(), client, username, passwd); err != nil {
+				ctx := context.WithValue(context.Background(), "logger", log)
+				if u, err := moduser.CreateUser(ctx, client, username, passwd); err != nil {
 					// TODO: don't return the error to the user, perhaps based
 					// on the devel mode.
 					return echo.NewHTTPError(
@@ -462,13 +463,13 @@ func SignupPost(client *ent.Client) echo.HandlerFunc {
 						http.StatusText(http.StatusInternalServerError)+" failed to create schema resources "+err.Error(),
 					)
 				} else {
-					log.Printf("successfully registered user '%s': %#v", username, u)
+					log.Infof("successfully registered user '%s': %#v", username, u)
 				}
 			} else {
-				log.Println("password was not set, returning to /signup")
+				log.Info("user registration: password was not set, returning to /signup")
 			}
 		} else {
-			log.Printf("username was not set, returning to /signup")
+			log.Info("user registration: username was not set, returning to /signup")
 
 			c.Redirect(302, "/signup")
 
@@ -516,12 +517,12 @@ func Home() echo.HandlerFunc {
 		if err != nil {
 			if err == http.ErrNoCookie {
 				// return err
-				log.Printf("error no cookie: %q", err)
+				log.Infof("error no cookie: %q", err)
 				http.Error(c.Response().Writer, http.StatusText(http.StatusUnauthorized), http.StatusUnauthorized)
 				return nil
 			}
 
-			log.Println("error:", err)
+			log.Infof("error: %q", err)
 			http.Error(c.Response().Writer, http.StatusText(http.StatusBadRequest), http.StatusBadRequest)
 			// fmt.Println("session cookie not found, redirecting to signin page")
 
@@ -529,12 +530,12 @@ func Home() echo.HandlerFunc {
 
 		}
 		if session != nil {
-			log.Println("got session")
+			log.Info("got session")
 			// if err := session.Valid(); err == nil && session.Expires.After(time.Now()) {
 			if err := session.Valid(); err == nil {
 				username = session.Value
 			} else {
-				log.Println("invalid or expired session?")
+				log.Warn("invalid or expired session?")
 				return echo.NewHTTPError(http.StatusUnauthorized, http.StatusText(http.StatusUnauthorized))
 			}
 		}
@@ -557,7 +558,7 @@ func Home() echo.HandlerFunc {
 		)
 		if err != nil {
 			// return err
-			log.Printf("error: %q", err)
+			log.Warnf("error: %q", err)
 			return echo.NewHTTPError(http.StatusInternalServerError, http.StatusText(http.StatusInternalServerError))
 		}
 
@@ -571,14 +572,14 @@ func Logout() echo.HandlerFunc {
 			session, err := c.Cookie("session")
 			if err != nil {
 				if errors.Is(err, http.ErrNoCookie) {
-					fmt.Println("nobody to log out, redirecting to /signin")
+					log.Info("nobody to log out, redirecting to /signin")
 
 					c.Redirect(302, "/signin")
 
 					return nil
 				}
 
-				log.Printf("error: %q", err)
+				log.Warnf("error: %q", err)
 				return nil
 			}
 
@@ -587,7 +588,7 @@ func Logout() echo.HandlerFunc {
 				username = session.Value
 			}
 
-			log.Printf("logging out user '%s'", username)
+			log.Infof("logging out user '%s'", username)
 
 			secure := c.Request().URL.Scheme == "https"
 			cookieSession := &http.Cookie{
@@ -618,7 +619,7 @@ func Logout() echo.HandlerFunc {
 			},
 		)
 		if err != nil {
-			log.Printf("error: %q", err)
+			log.Warnf("error: %q", err)
 			return echo.NewHTTPError(http.StatusInternalServerError, http.StatusText(http.StatusInternalServerError))
 		}
 

modules/user/user.go

@@ -3,14 +3,16 @@ package user
 import (
 	"context"
 	"fmt"
-	"log"
 
 	"git.dotya.ml/mirre-mt/pcmt/ent"
 	"git.dotya.ml/mirre-mt/pcmt/ent/user"
+	"git.dotya.ml/mirre-mt/pcmt/slogging"
 )
 
 // CreateUser adds a user entry to the database.
 func CreateUser(ctx context.Context, client *ent.Client, username, password string) (*ent.User, error) {
+	log := ctx.Value("logger").(*slogging.Logger)
+
 	u, err := client.User.
 		Create().
 		SetUsername(username).
@@ -20,11 +22,15 @@ func CreateUser(ctx context.Context, client *ent.Client, username, password stri
 	if err != nil {
 		return nil, fmt.Errorf("failed creating user: %w", err)
 	}
-	log.Println("user was created: ", u)
+
+	log.Infof("user was created: %#v", u)
+
 	return u, nil
 }
 
 func QueryUser(ctx context.Context, client *ent.Client, username string) (*ent.User, error) {
+	log := ctx.Value("logger").(*slogging.Logger)
+
 	u, err := client.User.
 		Query().
 		Where(user.Username(username)).
@@ -34,6 +40,8 @@ func QueryUser(ctx context.Context, client *ent.Client, username string) (*ent.U
 	if err != nil {
 		return nil, fmt.Errorf("failed querying user: %w", err)
 	}
-	log.Println("user returned: ", u)
+
+	log.Infof("user returned: %#v", u)
+
 	return u, nil
 }

slogging/log.go

@@ -0,0 +1,44 @@
+package slogging
+
+import (
+	"fmt"
+	"os"
+
+	"golang.org/x/exp/slog"
+)
+
+type Logger struct {
+	*slog.Logger
+}
+
+// var logger *slog.Logger
+var logger *Logger
+
+// func Logger() *slog.Logger {
+func GetLogger() *Logger {
+	return logger
+}
+
+func Init(jsonHandler bool) error {
+	if jsonHandler {
+		logger = &Logger{slog.New(slog.NewJSONHandler(os.Stderr))}
+	} else {
+		logger = &Logger{slog.New(slog.NewTextHandler(os.Stderr))}
+	}
+
+	logger.Info("slog logger initialised")
+
+	return nil
+}
+
+func (l *Logger) Infof(msg string, args ...any) {
+	l.Info(fmt.Sprintf(msg, args...))
+}
+
+func (l *Logger) Warnf(msg string, args ...any) {
+	l.Warn(fmt.Sprintf(msg, args...))
+}
+
+func (l *Logger) Errorf(msg string, args ...any) {
+	l.Error(fmt.Sprintf(msg, args...))
+}