Structured Logging with zap

Goal

By the end of this lesson, Tasker writes structured logs with zap, the logging library from Uber. Normally, users see no logs at all. With --verbose, Tasker shows what happens inside: which command runs, which file it reads, how many tasks it loads and saves, and how long each step takes. Logs go to standard error, so output for users and scripts stays clean.

What you will learn

• What logs are for, and how they differ from normal output
• What structured logging is, and why it beats fmt.Println for logs
• Log levels: debug, info, warn, and error
• How to create a zap logger and write messages with typed fields
• How to add context with Named and With
• How to pass a logger as a dependency, with a safe "no-op" default
• How to see logs in tests with zaptest

Why this matters

When a user reports "Tasker lost my task", you need to know what happened: which file it used, how many tasks it loaded, and whether the save succeeded. Logs answer these questions without a debugger.

For the API in Part 2, logs become even more important. A server runs without anyone watching. Logs are how you find out what it did, and tools such as Grafana Loki or Elasticsearch search millions of log lines. That only works when logs have a clear structure.

Step 1: Output and logs are different things

Tasker already prints two kinds of text:

• Output is the result the user asked for, such as the task list. It goes to stdout.
• Errors explain why a command failed. They go to stderr.

Logs are a third kind: messages about what the program is doing, mainly for developers and operators. They also go to stderr, so they never mix with the output that scripts read. And by default, a command-line tool shows only important logs, so users are not flooded with details.

Step 2: Why structured logs?

A log line written with fmt looks like this:

saved 2 tasks to /home/ana/.tasker/tasks.json in 168µs

A person can read it, but a program cannot reliably extract the number of tasks or the duration. Structured logging keeps the message and the data separate:

DEBUG	storage	saved tasks	{"path": "/home/ana/.tasker/tasks.json", "count": 2, "bytes": 236, "took": "168.186µs"}

The message, saved tasks, is always the same text, so you can search for it. The details are fields with names and types. In production, the same log is written as JSON, and log tools can filter by count or sort by took.

Step 3: Log levels

Every log message has a level that says how important it is:

Level	Use it for	Example
debug	Details for developers	"loaded 2 tasks in 70µs"
info	Normal, notable events	"task file does not exist yet"
warn	Something unusual that the program handled	"config file has an unknown key"
error	Something failed	"could not save tasks"

A logger has a minimum level. It writes only messages at that level or above. Tasker's default is warn, so normal use shows nothing. --verbose lowers the minimum to debug and shows everything.

Step 4: Add zap and create a logger

go get go.uber.org/zap@latest

Create internal/cli/logger.go:

package cli

import (
	"fmt"
	"io"

	"go.uber.org/zap"
	"go.uber.org/zap/zapcore"
)

// newLogger returns a logger that writes readable lines to w.
// It only writes messages at the given level or above:
// "debug", "info", "warn", or "error".
func newLogger(level string, w io.Writer) (*zap.Logger, error) {
	lvl, err := zapcore.ParseLevel(level)
	if err != nil {
		return nil, fmt.Errorf("log level: %w", err)
	}

	encoderConfig := zap.NewDevelopmentEncoderConfig()
	encoderConfig.EncodeTime = zapcore.TimeEncoderOfLayout("15:04:05.000")
	encoder := zapcore.NewConsoleEncoder(encoderConfig)

	core := zapcore.NewCore(encoder, zapcore.AddSync(w), lvl)
	return zap.New(core), nil
}

A zap logger is built from three parts, combined in a core:

• An encoder decides the format. NewConsoleEncoder writes readable lines with tabs. zap also has a JSON encoder, which you use for the API in Part 2. The time format uses the layout rules from Lesson 2.1.
• A writer decides where logs go. Here it is any io.Writer, the same interface you used for the shell.
• A level decides which messages are written.

zapcore.ParseLevel turns text such as "debug" into a level and returns an error for unknown text.

zap also has ready-made loggers: zap.NewDevelopment() and zap.NewProduction(). They always write to stderr and use fixed settings. Building the core yourself lets you choose the writer, which you need for tests.

Step 5: Connect the logger to the commands

Open internal/cli/root.go. Add a logger to options:

type options struct {
	configFile string
	v          *viper.Viper
	log        *zap.Logger
}

Start with a logger that does nothing:

	opts := &options{v: viper.New(), log: zap.NewNop()}

zap.NewNop() returns a "no operation" logger that throws every message away. It means opts.log is never nil, so code can always log safely, even before the real logger exists.

Add two flags next to --file:

	root.PersistentFlags().String("log-level", "warn", "log level: debug, info, warn, or error")
	opts.v.BindPFlag("log.level", root.PersistentFlags().Lookup("log-level"))
	root.PersistentFlags().Bool("verbose", false, "show debug logs (same as --log-level=debug)")
	opts.v.BindPFlag("verbose", root.PersistentFlags().Lookup("verbose"))

In config.go, add a default in loadConfig:

	v.SetDefault("log.level", "warn")

Because the level is a Viper setting, it also works as TASKER_LOG_LEVEL and as log.level in the config file.

Now create the logger in PersistentPreRunE, after the config is loaded:

		PersistentPreRunE: func(cmd *cobra.Command, args []string) error {
			if err := loadConfig(opts.v, opts.configFile); err != nil {
				return err
			}

			level := opts.v.GetString("log.level")
			if opts.v.GetBool("verbose") {
				level = "debug"
			}
			log, err := newLogger(level, cmd.ErrOrStderr())
			if err != nil {
				return err
			}
			opts.log = log

			opts.log.Debug("starting command",
				zap.String("command", cmd.Name()),
				zap.String("version", Version),
				zap.String("config", opts.v.ConfigFileUsed()),
			)
			return nil
		},

• cmd.ErrOrStderr() is the error stream of the command. Logs go to stderr, and tests can replace it, like OutOrStdout.
• opts.log.Debug(message, fields...) writes a message at debug level. Each field has a type: zap.String, zap.Int, zap.Duration, zap.Error, and many more. Typed fields are one reason zap is very fast: it does not need to inspect values at run time to find out their type.

Step 6: Log inside the file storage

The file storage is where interesting things happen: reading, writing, and timing. Give it a logger. In internal/storage/file.go, change the struct and the constructor:

// File stores tasks as JSON in a file.
type File struct {
	path string
	log  *zap.Logger
}

// NewFile returns a storage that uses the file at path and writes logs to log.
func NewFile(path string, log *zap.Logger) *File {
	return &File{path: path, log: log.With(zap.String("path", path))}
}

log.With(...) returns a new logger that adds the given fields to every message. The file path is part of every storage log, so you set it once instead of repeating it in each call.

Update the imports. By convention, third-party packages form their own group between the standard library and your own packages:

import (
	"encoding/json"
	"errors"
	"fmt"
	"os"
	"path/filepath"
	"time"

	"go.uber.org/zap"

	"github.com/yourname/tasker/internal/task"
)

In Load, record the start time and log the two outcomes:

func (f *File) Load() ([]task.Task, error) {
	start := time.Now()
	data, err := os.ReadFile(f.path)
	if errors.Is(err, os.ErrNotExist) {
		f.log.Info("task file does not exist yet, starting with no tasks")
		return nil, nil
	}
	if err != nil {
		return nil, fmt.Errorf("read task file: %w", err)
	}

	var tasks []task.Task
	if err := json.Unmarshal(data, &tasks); err != nil {
		return nil, fmt.Errorf("parse %s: %w", f.path, err)
	}

	f.log.Debug("loaded tasks",
		zap.Int("count", len(tasks)),
		zap.Int("bytes", len(data)),
		zap.Duration("took", time.Since(start)),
	)
	return tasks, nil
}

In Save, add start := time.Now() as the first line, and add this before the final return nil:

	f.log.Debug("saved tasks",
		zap.Int("count", len(tasks)),
		zap.Int("bytes", len(data)),
		zap.Duration("took", time.Since(start)),
	)

time.Since(start) returns how much time has passed, as a time.Duration.

Notice what is not logged: the errors. Load and Save return their errors, and main prints them. Follow this rule: either log an error or return it, not both. If every layer logged the error and returned it too, one problem would appear many times in the logs, and it would be hard to see where it really happened.

Finally, give the storage its logger in openStore:

	return task.Open(storage.NewFile(path, o.log.Named("storage")))

Named("storage") adds a name to every message from this logger. When a program has many parts, the name shows which part wrote each line.

Step 7: Update the tests

NewFile now needs a logger, so the storage tests must pass one. Use zaptest.NewLogger(t). It writes logs into the test's own output, which Go shows only when the test fails or when you use -v.

In internal/storage/file_test.go, add the import "go.uber.org/zap/zaptest" and change each NewFile(path) call to:

	f := NewFile(path, zaptest.NewLogger(t))

In internal/cli/cli_test.go, add one more line to setupHome, so a log level in your own environment cannot affect the tests:

	t.Setenv("TASKER_LOG_LEVEL", "")

Run the tests with -v for one storage test:

go test -v -run TestFileSaveAndLoad ./internal/storage

=== RUN   TestFileSaveAndLoad
    logger.go:146: 2026-10-16T22:58:44.821Z	DEBUG	saved tasks	{"path": "/tmp/TestFileSaveAndLoad1964640913/001/tasks.json", "count": 2, "bytes": 249, "took": "228.993µs"}
    logger.go:146: 2026-10-16T22:58:44.821Z	DEBUG	loaded tasks	{"path": "/tmp/TestFileSaveAndLoad1964640913/001/tasks.json", "count": 2, "bytes": 249, "took": "41.23µs"}
--- PASS: TestFileSaveAndLoad (0.00s)

When a test fails, these logs show you what the code did just before the failure.

Step 8: Try it

go mod tidy
go test ./...
go build ./cmd/tasker

A normal command shows no logs:

./tasker add Buy milk

Added: 1. [ ] Buy milk

With --verbose, you see inside:

./tasker --verbose add Pay rent

22:58:27.605	DEBUG	starting command	{"command": "add", "version": "0.2.0", "config": ""}
22:58:27.606	DEBUG	storage	loaded tasks	{"path": "/home/ana/.tasker/tasks.json", "count": 1, "bytes": 119, "took": "70.951µs"}
22:58:27.606	DEBUG	storage	saved tasks	{"path": "/home/ana/.tasker/tasks.json", "count": 2, "bytes": 236, "took": "168.186µs"}
Added: 2. [ ] Pay rent

Each line shows the time, the level, the logger name (storage), the message, and the fields.

Prove that logs go to stderr. 2>/dev/null throws stderr away:

./tasker --verbose list 2>/dev/null

1. [ ] Buy milk
2. [ ] Pay rent

Only the output remains. Scripts that read tasker list are not disturbed by logs, even in verbose mode.

A wrong level gives a clear error:

TASKER_LOG_LEVEL=loud ./tasker list

error: log level: unrecognized level: "loud"

Why it works: logs are a dependency too

The storage does not create its own logger, and it does not use a global one. It receives a logger from the outside, exactly like the store receives its storage. That gives you full control:

• In the program, the logger writes to stderr at the level the user chose.
• In tests, zaptest sends logs to the test output.
• Where you do not care about logs, zap.NewNop() throws them away.

In Part 2, the API server uses the same approach with a JSON encoder. Every HTTP request gets a logger with a request ID field, created with With, and every log line for that request carries the ID.

Exercises

1. Log the command result. In add.go, log the new task at debug level with zap.Int("id", t.ID) and zap.Strings("tags", t.Tags).
2. JSON logs. Add a log.format setting (console or json). For json, use zapcore.NewJSONEncoder(zap.NewProductionEncoderConfig()). Run ./tasker --verbose list with both formats and compare.
3. A warning. In loadConfig, you cannot log yet, because the logger does not exist. Change the order so that Tasker logs a warning when the task file setting points to a folder instead of a file. Hint: use os.Stat and info.IsDir() in openStore.
4. Check logs in a test. zap has an observer package (go.uber.org/zap/zaptest/observer). Use observer.New(zap.DebugLevel) to create a logger, pass it to NewFile, call Save, and check that exactly one log entry with the message saved tasks was written.
5. The sugared logger. Read about logger.Sugar() in the zap documentation. Rewrite one log call with Debugw. When would you choose the sugared logger, and when the normal one?

Checkpoint

You have finished Module 5 if you can:

• Explain the difference between output, errors, and logs, and where each one goes
• Explain what structured logging is and why it helps
• Name the four log levels and give an example for each
• Create a zap logger with an encoder, a writer, and a level
• Use With and Named to add context to a logger
• Explain the rule "log an error or return it, not both"
• Use zap.NewNop() and zaptest.NewLogger(t) where they fit