This lesson's interactive features are locked, please to keep using them
One Log Per Event
While timestamps help, it's still hard to correlate independent log entries. That's why we strive for one log per event. Take a look at our sloppy example from before:
2023/10/01 12:34:57 INFO: User "alice" logged in
2023/10/01 12:34:57 INFO: Opening profile configuration for user "alice"
2023/10/01 12:34:57 ERROR: File not found
This can be compressed into a single log entry:
2023/10/01 12:34:57 severity="ERROR" message="File not found" user="alice" filename="alice_profile.json" action="open_profile"
Now one entry has all the necessary information about the event, including the user, the action being performed (opening the profile), and the specific error encountered.
While that might not seem like a big improvement at first, imagine if the 3 logs from the first example had other logs in between them, like this:
2023/10/01 12:34:57 INFO: User "alice" logged in
2023/10/01 12:34:57 ERROR: Not enough permissions
2023/10/01 12:34:57 INFO: Opening profile configuration for user "bob"
2023/10/01 12:34:57 INFO: Opening profile configuration for user "alice"
2023/10/01 12:34:57 DEBUG: Opening database connection
2023/10/01 12:34:57 ERROR: File not found
Now correlating actions becomes practically impossible unless we compress them into single log events.
Don't log every action, log the entire event.
Take a look at this function that reads a PID file:
func readPIDFile(filename string) (int, error) {
slog.Info("Opening PID file", "filename", filename)
file, err := os.Open(filename)
if err != nil {
slog.Error("Failed to open PID file", "error", err)
return 0, err
}
defer func() {
slog.Info("Closing PID file")
if err := file.Close(); err != nil {
slog.Error("Failed to close PID file", "error", err)
}
}()
slog.Info("Reading PID file")
content, err := io.ReadAll(file)
if err != nil {
slog.Error("Failed to read PID file", "error", err)
return 0, err
}
slog.Info("Parsing PID file content", "filename", filename)
pid, err := strconv.Atoi(strings.TrimSpace(string(content)))
if err != nil {
slog.Error("Failed to parse PID file content", "error", err)
return 0, err
}
slog.Info("Successfully read PID", "pid", pid)
return pid, nil
}
It's just reading a single file, but we have to read the entire play-by-play of the operation:
time=2023-10-01T12:34:57Z level=INFO msg="Opening PID file" filename="/var/run/myapp.pid"
time=2023-10-01T12:34:57Z level=INFO msg="Reading PID file"
time=2023-10-01T12:34:57Z level=INFO msg="Successfully read PID" pid=12345 filename="/var/run/myapp.pid"
time=2023-10-01T12:34:57Z level=INFO msg="Closing PID file"
Instead, log a single entry for the entire "event":
func readPIDFile(filename string) (int, error) {
file, err := os.Open(filename)
if err != nil {
slog.Error("Failed to open PID file", "error", err, "filename", filename)
return 0, err
}
defer file.Close()
content, err := io.ReadAll(file)
if err != nil {
slog.Error("Failed to read PID file", "error", err, "filename", filename)
return 0, err
}
pid, err := strconv.Atoi(strings.TrimSpace(string(content)))
if err != nil {
slog.Error("Failed to parse PID file content", "error", err, "filename", filename)
return 0, err
}
slog.Info("Successfully read PID", "pid", pid, "filename", filename)
return pid, nil
}
time=2023-10-01T12:34:57Z level=INFO msg="Successfully read PID" pid=12345 filename="/var/run/myapp.pid"
Assignment
Something very... redundant... is going on in handlerShortenLink in handlers.go.
Run and submit the CLI tests from the root of the Linko repo.