Fix slog usage for proper structured logging (#4)

.github/workflows/staticcheck.yml

@@ -22,10 +22,7 @@ jobs:
       - name: Setup Go
         uses: actions/setup-go@v4.3.0
         with:
-          go-version: 1.25
-
-      - name: Install staticcheck
-        run: make install
+          go-version: 1.26
 
       - name: Run staticcheck
         run: make lint

.gitignore

@@ -4,3 +4,6 @@
 .vscode
 glide.lock
 vendor
+CLAUDE.md
+sample
+sample-ctx

MODERNIZATION.md

@@ -49,7 +49,7 @@ This removes the `jonbodner/stackerr` dependency entirely.
 
 ---
 
-## 4. Fix `slog` Usage — Structured Logging Done Right
+## ~~4. Fix `slog` Usage — Structured Logging Done Right~~ (DONE)
 
 The recent migration to `slog` (commit c52e1f8) left behind anti-patterns. The code uses `slog.Log` with `fmt.Sprintln`/`fmt.Sprintf` to pre-format messages, which defeats the entire purpose of structured logging.
 
@@ -392,7 +392,7 @@ If `Build` returns an error, `productDao` will have nil function fields. Subsequ
 - ~~#1 — `interface{}` to `any`~~ *(DONE)*
 - ~~#2 — Replace `multierr` with `errors.Join`~~ *(DONE)*
 - #3 — Replace `stackerr` with stdlib error handling
-- #4 — Fix slog usage for proper structured logging
+- ~~#4 — Fix slog usage for proper structured logging~~ *(DONE)*
 - #11 — Update dependencies
 
 **Lower priority (cleanup):**

Makefile

@@ -27,17 +27,13 @@ fmt:
 .PHONY:fmt
 
 lint: fmt
-	staticcheck ./...
+	go tool staticcheck ./...
 .PHONY:lint
 
 vet: fmt
 	go vet ./...
 .PHONY:vet
 
-build: vet
-	go build github.com/jonbodner/proteus/cmd/sample
+build: vet lint
+	go build github.com/jonbodner/proteus/cmd/sample-ctx
 .PHONY:build
-
-install:
-	go install honnef.co/go/tools/cmd/staticcheck@latest
-.PHONY:install

builder.go

@@ -251,7 +251,7 @@ func validIdentifier(ctx context.Context, curVar string) (string, error) {
 loop:
 	for {
 		pos, tok, lit := s.Scan()
-		slog.Log(ctx, slog.LevelDebug, fmt.Sprintf("%s\t%s\t%q\n", fset.Position(pos), tok, lit))
+		slog.DebugContext(ctx, "token scan", "position", fset.Position(pos), "token", tok, "literal", lit)
 		switch tok {
 		case token.EOF:
 			if first || lastPeriod {

cmd/null/main.go

@@ -59,16 +59,21 @@ func run(productDao Product2Dao) {
 
 	populate(ctx, tx, productDao)
 
-	slog.Log(ctx, slog.LevelDebug, fmt.Sprintln(productDao.FindByID(ctx, tx, 10)))
+	product, err := productDao.FindByID(ctx, tx, 10)
+	slog.DebugContext(ctx, "FindByID", "product", product, "err", err)
 	cost := sql.NullFloat64{
 		Float64: 56.23,
 		Valid:   true,
 	}
 	p := Product2{10, "Thingie", cost}
-	slog.Log(ctx, slog.LevelDebug, fmt.Sprintln(productDao.Update(ctx, tx, p)))
-	slog.Log(ctx, slog.LevelDebug, fmt.Sprintln(productDao.FindByID(ctx, tx, 10)))
-	slog.Log(ctx, slog.LevelDebug, fmt.Sprintln(productDao.FindByNameAndCost(ctx, tx, "fred", 54.10)))
-	slog.Log(ctx, slog.LevelDebug, fmt.Sprintln(productDao.FindByNameAndCost(ctx, tx, "Thingie", 56.23)))
+	rowsAffected, err := productDao.Update(ctx, tx, p)
+	slog.DebugContext(ctx, "Update", "rowsAffected", rowsAffected, "err", err)
+	product, err = productDao.FindByID(ctx, tx, 10)
+	slog.DebugContext(ctx, "FindByID after update", "product", product, "err", err)
+	products, err := productDao.FindByNameAndCost(ctx, tx, "fred", 54.10)
+	slog.DebugContext(ctx, "FindByNameAndCost fred", "products", products, "err", err)
+	products, err = productDao.FindByNameAndCost(ctx, tx, "Thingie", 56.23)
+	slog.DebugContext(ctx, "FindByNameAndCost Thingie", "products", products, "err", err)
 }
 
 func defineSchema(ctx context.Context, tx proteus.ContextWrapper) error {
@@ -78,7 +83,7 @@ func defineSchema(ctx context.Context, tx proteus.ContextWrapper) error {
 	`
 	_, err := tx.ExecContext(ctx, sqlStmt)
 	if err != nil {
-		slog.Log(ctx, slog.LevelError, fmt.Sprintf("%q: %s\n", err, sqlStmt))
+		slog.ErrorContext(ctx, "exec failed", "err", err, "statement", sqlStmt)
 		return err
 	}
 	return nil
@@ -88,13 +93,13 @@ func setupDBPostgres(ctx context.Context) (proteus.ContextWrapper, closer) {
 	db, err := sql.Open("postgres", "postgres://pro_user:pro_pwd@localhost/proteus?sslmode=disable")
 
 	if err != nil {
-		slog.Log(ctx, slog.LevelError, fmt.Sprintln(err))
+		slog.ErrorContext(ctx, "db open failed", "err", err)
 		os.Exit(1)
 	}
 
 	tx, err := db.Begin()
 	if err != nil {
-		slog.Log(ctx, slog.LevelError, fmt.Sprintln(err))
+		slog.ErrorContext(ctx, "begin tx failed", "err", err)
 		os.Exit(1)
 	}
 
@@ -114,9 +119,9 @@ func populate(ctx context.Context, w proteus.ContextWrapper, productDao Product2
 		}
 		rowCount, err := productDao.Insert(ctx, w, i, fmt.Sprintf("person%d", i), cost)
 		if err != nil {
-			slog.Log(ctx, slog.LevelError, fmt.Sprintln(err))
+			slog.ErrorContext(ctx, "insert failed", "err", err)
 			os.Exit(1)
 		}
-		slog.Log(ctx, slog.LevelDebug, fmt.Sprintln(rowCount))
+		slog.DebugContext(ctx, "inserted row", "rowCount", rowCount)
 	}
 }

cmd/sample-ctx/main.go

@@ -67,39 +67,64 @@ func run(setupDb setupDb, productDAO ProductDAO) {
 	}
 	defer func() { _ = tx.Rollback() }()
 
-	slog.Log(ctx, slog.LevelDebug, fmt.Sprintln(productDAO.FindByID(ctx, tx, 10)))
+	product, err := productDAO.FindByID(ctx, tx, 10)
+	slog.DebugContext(ctx, "FindByID", "product", product, "err", err)
+
 	cost := new(float64)
 	*cost = 56.23
 	p := Product{10, "Thingie", cost}
-	slog.Log(ctx, slog.LevelDebug, fmt.Sprintln(productDAO.Update(ctx, tx, p)))
-	slog.Log(ctx, slog.LevelDebug, fmt.Sprintln(productDAO.FindByID(ctx, tx, 10)))
-	slog.Log(ctx, slog.LevelDebug, fmt.Sprintln(productDAO.FindByNameAndCost(ctx, tx, "fred", 54.10)))
-	slog.Log(ctx, slog.LevelDebug, fmt.Sprintln(productDAO.FindByNameAndCost(ctx, tx, "Thingie", 56.23)))
+	rowsAffected, err := productDAO.Update(ctx, tx, p)
+	slog.DebugContext(ctx, "Update", "rowsAffected", rowsAffected, "err", err)
+
+	product, err = productDAO.FindByID(ctx, tx, 10)
+	slog.DebugContext(ctx, "FindByID after update", "product", product, "err", err)
+
+	products, err := productDAO.FindByNameAndCost(ctx, tx, "fred", 54.10)
+	slog.DebugContext(ctx, "FindByNameAndCost fred", "products", products, "err", err)
+
+	products, err = productDAO.FindByNameAndCost(ctx, tx, "Thingie", 56.23)
+	slog.DebugContext(ctx, "FindByNameAndCost Thingie", "products", products, "err", err)
 
 	//using a map of [string]any works too!
-	slog.Log(ctx, slog.LevelDebug, fmt.Sprintln((productDAO.FindByIDMap(ctx, tx, 10))))
-	slog.Log(ctx, slog.LevelDebug, fmt.Sprintln((productDAO.FindByNameAndCostMap(ctx, tx, "Thingie", 56.23))))
+	m2, err := productDAO.FindByIDMap(ctx, tx, 10)
+	slog.DebugContext(ctx, "FindByIDMap", "result", m2, "err", err)
+
+	maps, err := productDAO.FindByNameAndCostMap(ctx, tx, "Thingie", 56.23)
+	slog.DebugContext(ctx, "FindByNameAndCostMap", "results", maps, "err", err)
+
+	product, err = productDAO.FindByID(ctx, tx, 11)
+	slog.DebugContext(ctx, "FindByID 11", "product", product, "err", err)
 
-	slog.Log(ctx, slog.LevelDebug, fmt.Sprintln((productDAO.FindByID(ctx, tx, 11))))
 	m := map[string]any{
 		"Id":   11,
 		"Name": "bobbo",
 		"Cost": 12.94,
 	}
-	slog.Log(ctx, slog.LevelDebug, fmt.Sprintln((productDAO.UpdateMap(ctx, tx, m))))
-	slog.Log(ctx, slog.LevelDebug, fmt.Sprintln((productDAO.FindByID(ctx, tx, 11))))
+	rowsAffected, err = productDAO.UpdateMap(ctx, tx, m)
+	slog.DebugContext(ctx, "UpdateMap", "rowsAffected", rowsAffected, "err", err)
+
+	product, err = productDAO.FindByID(ctx, tx, 11)
+	slog.DebugContext(ctx, "FindByID after UpdateMap", "product", product, "err", err)
 
 	//searching using a slice
-	slog.Log(ctx, slog.LevelDebug, fmt.Sprintln((productDAO.FindByIDSlice(ctx, tx, []int{1, 3, 5}))))
-	slog.Log(ctx, slog.LevelDebug, fmt.Sprintln((productDAO.FindByIDSliceAndName(ctx, tx, []int{1, 3, 5}, "person1"))))
-	slog.Log(ctx, slog.LevelDebug, fmt.Sprintln((productDAO.FindByIDSliceNameAndCost(ctx, tx, []int{1, 3, 5}, "person3", nil))))
-	slog.Log(ctx, slog.LevelDebug, fmt.Sprintln((productDAO.FindByIDSliceCostAndNameSlice(ctx, tx, []int{1, 3, 5}, []string{"person3", "person5"}, nil))))
+	products, err = productDAO.FindByIDSlice(ctx, tx, []int{1, 3, 5})
+	slog.DebugContext(ctx, "FindByIDSlice", "products", products, "err", err)
+
+	products, err = productDAO.FindByIDSliceAndName(ctx, tx, []int{1, 3, 5}, "person1")
+	slog.DebugContext(ctx, "FindByIDSliceAndName", "products", products, "err", err)
+
+	products, err = productDAO.FindByIDSliceNameAndCost(ctx, tx, []int{1, 3, 5}, "person3", nil)
+	slog.DebugContext(ctx, "FindByIDSliceNameAndCost", "products", products, "err", err)
+
+	products, err = productDAO.FindByIDSliceCostAndNameSlice(ctx, tx, []int{1, 3, 5}, []string{"person3", "person5"}, nil)
+	slog.DebugContext(ctx, "FindByIDSliceCostAndNameSlice", "products", products, "err", err)
 
 	//using positional parameters instead of names
-	slog.Log(ctx, slog.LevelDebug, fmt.Sprintln((productDAO.FindByNameAndCostUnlabeled(ctx, tx, "Thingie", 56.23))))
+	products, err = productDAO.FindByNameAndCostUnlabeled(ctx, tx, "Thingie", 56.23)
+	slog.DebugContext(ctx, "FindByNameAndCostUnlabeled", "products", products, "err", err)
 
 	if err := tx.Commit(); err != nil {
-		slog.Log(ctx, slog.LevelError, fmt.Sprintln(err))
+		slog.ErrorContext(ctx, "commit failed", "err", err)
 	}
 }
 
@@ -108,15 +133,15 @@ func setupDbPostgres(ctx context.Context, productDAO ProductDAO) *sql.DB {
 	db, err := sql.Open("timer", "postgres postgres://pro_user:pro_pwd@localhost/proteus?sslmode=disable")
 
 	if err != nil {
-		slog.Log(ctx, slog.LevelError, fmt.Sprintln(err))
+		slog.ErrorContext(ctx, "db open failed", "err", err)
 	}
 	sqlStmt := `
 	drop table if exists product;
 	create table product (id integer not null primary key, name text, cost real);
 	`
 	_, err = db.Exec(sqlStmt)
 	if err != nil {
-		slog.Log(ctx, slog.LevelError, fmt.Sprintf("%q: %s\n", err, sqlStmt))
+		slog.ErrorContext(ctx, "exec failed", "err", err, "statement", sqlStmt)
 		return nil
 	}
 	populate(ctx, db, productDAO)
@@ -126,7 +151,7 @@ func setupDbPostgres(ctx context.Context, productDAO ProductDAO) *sql.DB {
 func populate(ctx context.Context, db *sql.DB, productDao ProductDAO) {
 	tx, err := db.Begin()
 	if err != nil {
-		slog.Log(ctx, slog.LevelError, fmt.Sprintln(err))
+		slog.ErrorContext(ctx, "begin tx failed", "err", err)
 		return
 	}
 	defer func() { _ = tx.Rollback() }()
@@ -139,12 +164,12 @@ func populate(ctx context.Context, db *sql.DB, productDao ProductDAO) {
 		}
 		rowCount, err := productDao.Insert(ctx, tx, i, fmt.Sprintf("person%d", i), cost)
 		if err != nil {
-			slog.Log(ctx, slog.LevelError, fmt.Sprintln(err))
+			slog.ErrorContext(ctx, "insert failed", "err", err)
 		}
-		slog.Log(ctx, slog.LevelDebug, fmt.Sprintln(rowCount))
+		slog.DebugContext(ctx, "inserted row", "rowCount", rowCount)
 	}
 
 	if err := tx.Commit(); err != nil {
-		slog.Log(ctx, slog.LevelError, fmt.Sprintln(err))
+		slog.ErrorContext(ctx, "commit failed", "err", err)
 	}
 }

cmd/sample/main.go

@@ -66,39 +66,64 @@ func run(setupDb setupDb, productDAO ProductDAO) {
 	}
 	defer func() { _ = tx.Rollback() }()
 
-	slog.Log(ctx, slog.LevelDebug, fmt.Sprintln(productDAO.FindByID(tx, 10)))
+	product, err := productDAO.FindByID(tx, 10)
+	slog.DebugContext(ctx, "FindByID", "result", product, "error", err)
+
 	cost := new(float64)
 	*cost = 56.23
 	p := Product{10, "Thingie", cost}
-	slog.Log(ctx, slog.LevelDebug, fmt.Sprintln(productDAO.Update(tx, p)))
-	slog.Log(ctx, slog.LevelDebug, fmt.Sprintln(productDAO.FindByID(tx, 10)))
-	slog.Log(ctx, slog.LevelDebug, fmt.Sprintln(productDAO.FindByNameAndCost(tx, "fred", 54.10)))
-	slog.Log(ctx, slog.LevelDebug, fmt.Sprintln(productDAO.FindByNameAndCost(tx, "Thingie", 56.23)))
+	rowsAffected, err := productDAO.Update(tx, p)
+	slog.DebugContext(ctx, "Update", "result", rowsAffected, "error", err)
+
+	product, err = productDAO.FindByID(tx, 10)
+	slog.DebugContext(ctx, "FindByID after update", "result", product, "error", err)
+
+	results, err := productDAO.FindByNameAndCost(tx, "fred", 54.10)
+	slog.DebugContext(ctx, "FindByNameAndCost fred", "result", results, "error", err)
+
+	results, err = productDAO.FindByNameAndCost(tx, "Thingie", 56.23)
+	slog.DebugContext(ctx, "FindByNameAndCost Thingie", "result", results, "error", err)
 
 	//using a map of [string]any works too!
-	slog.Log(ctx, slog.LevelDebug, fmt.Sprintln((productDAO.FindByIDMap(tx, 10))))
-	slog.Log(ctx, slog.LevelDebug, fmt.Sprintln((productDAO.FindByNameAndCostMap(tx, "Thingie", 56.23))))
+	mapResult, err := productDAO.FindByIDMap(tx, 10)
+	slog.DebugContext(ctx, "FindByIDMap", "result", mapResult, "error", err)
+
+	mapResults, err := productDAO.FindByNameAndCostMap(tx, "Thingie", 56.23)
+	slog.DebugContext(ctx, "FindByNameAndCostMap", "result", mapResults, "error", err)
+
+	product, err = productDAO.FindByID(tx, 11)
+	slog.DebugContext(ctx, "FindByID 11", "result", product, "error", err)
 
-	slog.Log(ctx, slog.LevelDebug, fmt.Sprintln((productDAO.FindByID(tx, 11))))
 	m := map[string]any{
 		"Id":   11,
 		"Name": "bobbo",
 		"Cost": 12.94,
 	}
-	slog.Log(ctx, slog.LevelDebug, fmt.Sprintln((productDAO.UpdateMap(tx, m))))
-	slog.Log(ctx, slog.LevelDebug, fmt.Sprintln((productDAO.FindByID(tx, 11))))
+	rowsAffected, err = productDAO.UpdateMap(tx, m)
+	slog.DebugContext(ctx, "UpdateMap", "result", rowsAffected, "error", err)
+
+	product, err = productDAO.FindByID(tx, 11)
+	slog.DebugContext(ctx, "FindByID after UpdateMap", "result", product, "error", err)
 
 	//searching using a slice
-	slog.Log(ctx, slog.LevelDebug, fmt.Sprintln((productDAO.FindByIDSlice(tx, []int{1, 3, 5}))))
-	slog.Log(ctx, slog.LevelDebug, fmt.Sprintln((productDAO.FindByIDSliceAndName(tx, []int{1, 3, 5}, "person1"))))
-	slog.Log(ctx, slog.LevelDebug, fmt.Sprintln((productDAO.FindByIDSliceNameAndCost(tx, []int{1, 3, 5}, "person3", nil))))
-	slog.Log(ctx, slog.LevelDebug, fmt.Sprintln((productDAO.FindByIDSliceCostAndNameSlice(tx, []int{1, 3, 5}, []string{"person3", "person5"}, nil))))
+	results, err = productDAO.FindByIDSlice(tx, []int{1, 3, 5})
+	slog.DebugContext(ctx, "FindByIDSlice", "result", results, "error", err)
+
+	results, err = productDAO.FindByIDSliceAndName(tx, []int{1, 3, 5}, "person1")
+	slog.DebugContext(ctx, "FindByIDSliceAndName", "result", results, "error", err)
+
+	results, err = productDAO.FindByIDSliceNameAndCost(tx, []int{1, 3, 5}, "person3", nil)
+	slog.DebugContext(ctx, "FindByIDSliceNameAndCost", "result", results, "error", err)
+
+	results, err = productDAO.FindByIDSliceCostAndNameSlice(tx, []int{1, 3, 5}, []string{"person3", "person5"}, nil)
+	slog.DebugContext(ctx, "FindByIDSliceCostAndNameSlice", "result", results, "error", err)
 
 	//using positional parameters instead of names
-	slog.Log(ctx, slog.LevelDebug, fmt.Sprintln((productDAO.FindByNameAndCostUnlabeled(tx, "Thingie", 56.23))))
+	results, err = productDAO.FindByNameAndCostUnlabeled(tx, "Thingie", 56.23)
+	slog.DebugContext(ctx, "FindByNameAndCostUnlabeled", "result", results, "error", err)
 
 	if err := tx.Commit(); err != nil {
-		slog.Log(ctx, slog.LevelError, fmt.Sprintln(err))
+		slog.ErrorContext(ctx, "commit failed", "err", err)
 	}
 }
 
@@ -107,15 +132,15 @@ func setupDbPostgres(ctx context.Context, productDAO ProductDAO) *sql.DB {
 	db, err := sql.Open("timer", "postgres postgres://pro_user:pro_pwd@localhost/proteus?sslmode=disable")
 
 	if err != nil {
-		slog.Log(ctx, slog.LevelError, fmt.Sprintln(err))
+		slog.ErrorContext(ctx, "db open failed", "err", err)
 	}
 	sqlStmt := `
 	drop table if exists product;
 	create table product (id integer not null primary key, name text, cost real);
 	`
 	_, err = db.Exec(sqlStmt)
 	if err != nil {
-		slog.Log(ctx, slog.LevelError, fmt.Sprintf("%q: %s\n", err, sqlStmt))
+		slog.ErrorContext(ctx, "exec failed", "err", err, "statement", sqlStmt)
 		return nil
 	}
 	populate(ctx, db, productDAO)
@@ -125,7 +150,7 @@ func setupDbPostgres(ctx context.Context, productDAO ProductDAO) *sql.DB {
 func populate(ctx context.Context, db *sql.DB, productDao ProductDAO) {
 	tx, err := db.Begin()
 	if err != nil {
-		slog.Log(ctx, slog.LevelError, fmt.Sprintln(err))
+		slog.ErrorContext(ctx, "begin tx failed", "err", err)
 		return
 	}
 	defer func() { _ = tx.Rollback() }()
@@ -138,12 +163,12 @@ func populate(ctx context.Context, db *sql.DB, productDao ProductDAO) {
 		}
 		rowCount, err := productDao.Insert(tx, i, fmt.Sprintf("person%d", i), cost)
 		if err != nil {
-			slog.Log(ctx, slog.LevelError, fmt.Sprintln(err))
+			slog.ErrorContext(ctx, "insert failed", "err", err)
 		}
-		slog.Log(ctx, slog.LevelDebug, fmt.Sprintln(rowCount))
+		slog.DebugContext(ctx, "inserted row", "rowCount", rowCount)
 	}
 
 	if err := tx.Commit(); err != nil {
-		slog.Log(ctx, slog.LevelError, fmt.Sprintln(err))
+		slog.ErrorContext(ctx, "commit failed", "err", err)
 	}
 }