Logging Lessons
In Go, the standard library provides a simple yet effective logging package that can be quite handy for small to medium-sized applications. While it may not be the most feature-rich logging solution, it has its merits, especially for less demanding projects.
Advantages of Standard Logging
The Go standard log package offers several advantages for logging in your applications:
- Simplicity: The standard logger is easy to set up and use, making it a suitable choice for projects with straightforward logging requirements.
- Minimal Dependencies: Since it's part of the standard library, you don't need to add external dependencies to your project.
- Consistency: Using the standard logger ensures that your logs have a consistent format, making it easier to read and parse them.
- Concurrency Safety: One advantage of the standard logger is that it is inherently concurrency-safe. You don't need to worry about managing locks or mutexes to protect your log statements when multiple goroutines (concurrent threads in Go) are writing to the log simultaneously. The standard logger handles concurrency gracefully.
Logging Functions
The standard log package provides four primary logging functions:
log.Printandlog.Printf: These functions are used for regular program output. You can use them to log informational messages or data. For example:
log.Print("This is a regular log message")
log.Printf("Logged value: %s", someValue)
log.Errorandlog.Errorf: These functions serve for logging error messages and formatted error messages, respectively. They are useful for recording errors and issues in your application. For example:
log.Error("An error occurred")
log.Errorf("Error: %v", err)
log.Fatalandlog.Fatalf: These functions are designed for error handling. When you useFatalorFatalf, the program terminates after logging the error message. For example:
log.Fatal("An error occurred. Program will exit.")
log.Fatalf("Critical error: %s", err)
The ...F suffix in the function names indicates the formatted version, allowing you to include variables and format specifiers in the log messages.
log.Println: Similar tolog.Print,log.Printlnis used for regular program output. The key difference is that it automatically appends a newline character (\n) to the end of the log message, making it suitable for logging messages that you want to separate by line breaks.
log.Println("This message will appear on one line.")
log.Println("This message", "will appear", "on a new line.")
In the second line, the commas between the arguments separate the values to be logged. Each value is concatenated with a space character by default, resulting in a single log message with spaces between the values. This can be useful when you want to log multiple pieces of information in a single log entry.
Leveled Logging
For more advanced logging needs, you can implement leveled logging with the standard log package by creating separate logger instances for different log levels. Here's an example of how you can do it:
infoLog := log.New(os.Stderr, "[INF] ", log.Ldate|log.Ltime)
warnLog := log.New(os.Stderr, "[WRN] ", log.Ldate|log.Ltime)
errorLog := log.New(os.Stderr, "[ERR] ", log.Ldate|log.Ltime)
With these instances, you can log messages at different levels (info, warning, error) with appropriate prefixes and settings. This allows you to organize and filter your logs effectively.
To explore all available constants for customizing logging, visit the log package documentation.
Output Redirection
When running a Go program, you can redirect both standard output (stdout) and standard error (stderr) to different destinations using shell commands. This practice can be valuable for separating regular program output from error messages and organizing your log data effectively.
For example, you can use the following command to redirect stdout to a file called output.log and stderr to a file called error.log:
$ go run ./main.go >> output.log 2>> error.log`
>> output.log: This part of the command appends the standard output (stdout) of the Go program to theoutput.logfile. Any regular program output, such as log messages or data, will be added tooutput.log.2>> error.log: This portion of the command appends the standard error (stderr) of the Go program to theerror.logfile. Any error messages or diagnostic information generated by the program will be appended toerror.log.
Using this approach, we can effectively separate regular program output from error messages and store them in separate log files (output.log for standard output and error.log for errors). This makes it easier to manage and analyze your program's logs.
Let's add some logging to our app
In main.go
// Log a message to indicate that the application is listening
log.Println("Listening on port 8080...")
// Start the HTTP server and listen on port 8080
err := http.ListenAndServe(":8080", r)
if err != nil {
log.Fatal(err) // Log and terminate the program if there's an error
}
But also in ShowBoard handlers from internal/controller/board.go,
func ShowBoard(w http.ResponseWriter, r *http.Request) {
// Hidden for clarity: Sample tasks definition
// Function logic to fetch and process data would go here.
// Extract board ID from the request parameters.
vars := mux.Vars(r)
id := vars["id"]
// Log the board ID that is being shown.
log.Printf("Showing board with ID: %s\n", id)
// Hidden for clarity: pageData initialization and template rendering.
// Template parsing and execution code.
ts, err := template.ParseFiles(
"assets/templates/default.tmpl",
"assets/templates/pages/board.tmpl",
"assets/templates/partials/column.tmpl")
if err != nil {
log.Println(err.Error())
http.Error(w, "Unable to parse template", http.StatusInternalServerError)
return
}
err = ts.ExecuteTemplate(w, "default", pageData)
if err != nil {
log.Println(err.Error())
http.Error(w, "Failed to execute template", http.StatusInternalServerError)
}
}
In our application, logging will be an important aspect to consider, and it's needed not only in the main.go file but also in other packages. Fortunately, the standard log package in Go is readily available wherever we need it, which makes it incredibly convenient. It doesn't require any elaborate setup, and we can use it seamlessly across different parts of our application.
However, what happens when we want to introduce more advanced logging capabilities, such as leveled loggers with different log levels like info, warning, and error? Should we instantiate each of these loggers (e.g., infoLog, warnLog, errLog) in every package where we need them? This approach could lead to redundancy and lack of consistency.
Moreover, if we decide to create these loggers in our main.go file and pass them as additional parameters to our handler functions, it might break the clean and standardized interface provided by the net/http package (e.g., (w http.ResponseWriter, r *http.Request)). This approach could also make our code less elegant and harder to maintain.
And what if we need additional log levels like debugtoo? Adding more loggers in this manner doesn't seem very neat or scalable. Surely, there must be a better way to handle advanced logging without cluttering our code with numerous logger instances and breaking the clean interface provided by the standard library.
Building our Custom Logger
When it comes to logging in to our Kanban board application, we recognize the need for a leveled logger. A leveled logger provides different levels of granularity for logging, such as debug, info, and error. While some logging frameworks include a warning level, we've made a conscious choice to exclude it. This decision aligns with a point made by Dave Cheney in his blog post Let's Talk About Logging:
Let’s talk about warnings: Let’s start with the easiest one. Nobody needs a warning log level.
Cheney's perspective highlights that warnings often go unnoticed because, by definition, they signify that nothing has gone wrong yet. In practice, if you're using leveled logging, you're more likely to set the level at info or error. Setting the level to warning may indicate that you're essentially logging errors at the warning level. Therefore, we eliminate the warning level, simplifying our logger with just three levels: debug, info, and error.
Our custom logger will be built on top of Go's standard library log package, providing an efficient and straightforward solution for our logging needs. This custom logger will reside in the internal/sys/log package within our application's codebase.
Before delving into the concrete implementation details of our custom logger, we want to introduce an essential concept: an interface that our application entities can use for their logging needs. This interface, located in the internal/log package defines a common set of methods for logging, including setting the log level and various logging functions:
$ mkdir -p internal/sys/log
$ touch internal/sys/log/log.go
package log
type LogLevel int
type Logger interface {
SetLogLevel(level LogLevel)
Debug(v ...interface{})
Debugf(format string, a ...interface{})
Debugln(v ...interface{})
Info(v ...interface{})
Infof(format string, a ...interface{})
Infoln(v ...interface{})
Error(v ...interface{})
Errorf(format string, a ...interface{})
Errorln(v ...interface{})
}
By adopting this interface, we ensure that our application entities remain agnostic to the specific logging implementation. If, for any reason, you decide to switch to another logger for performance, scalability, or other reasons, you can create an adapter wrapper around that preferred logger. This approach allows you to seamlessly integrate a new logger without having to modify a single line of your existing codebase beyond the new logger's implementation. It provides flexibility and maintainability, vital aspects of any robust software project.
Defining a custom LogLevel type as an integer provides several advantages over using plain string or integer values. It offers strong typing, enhancing code clarity and reducing the likelihood of runtime errors. With this custom type, we can enforce a specific set of log levels, preventing accidental misspellings or the use of arbitrary log-level strings or integers.
Furthermore, it allows us to create meaningful constants like Debug, Info, and Error, making the code more self-documenting and improving readability. This approach simplifies comparisons and conditionals related to log levels, promoting cleaner and more maintainable code. Additionally, the custom LogLevel type supports future extensibility, enabling us to introduce new log levels or modify existing ones consistently throughout the codebase. Overall, it enhances the robustness, consistency, and maintainability of our logging infrastructure.
In the upcoming sections, we will delve into the implementation details of our custom logger, demonstrating how it aligns with the defined interface and serves as a dependable tool for managing logs throughout our Kanban board application.
Implementing the Logger Interface
To bring our custom logger to life and implement the Logger interface defined in the internal/log package, we'll start by defining a set of constants for our log levels: Debug, Info, and Error. These constants will help us maintain consistency and readability in our logging code.
const (
Debug LogLevel = iota
Info
Error
)
Next, we create a constructor function, NewLoggerwhich accepts a log level string and returns an instance of our custom logger, SimpleLogger. This function leverages the LevelFromString helper to convert the provided log-level string into our custom LogLevel type.
func NewLogger(logLevelStr string) *SimpleLogger {
logLevel := LevelFromString(logLevelStr)
return newLogger(logLevel)
}
The newLogger the function takes the validated LogLevel and constructs a SimpleLogger. This logger is equipped with three distinct loggers—one for each log level (debug, info, and error), configured to output to the appropriate destinations.
func newLogger(logLevel LogLevel) *SimpleLogger {
return &SimpleLogger{
debug: log.New(os.Stdout, "[DBG] ", log.LstdFlags),
info: log.New(os.Stdout, "[INF] ", log.LstdFlags),
error: log.New(os.Stderr, "[ERR] ", log.LstdFlags),
logLevel: logLevel,
}
}
Now, let's take a closer look at the initial functions, such as Debug and Debugf. The approach for these functions is consistent across all log levels, ensuring uniform behavior. For instance, the Debug function logs messages when the log level is set to debug:
func (l *SimpleLogger) Debug(args ...interface{}) {
if l.logLevel <= Debug {
l.debug.Print(args...)
}
}
Similarly, the Debugf function formats and logs debug messages based on the log level:
func (l *SimpleLogger) Debugf(format string, args ...interface{}) {
if l.logLevel <= Debug {
l.debug.Printf(format, args...)
}
}
This consistent pattern extends to all other log levels, including Info and Error, ensuring that our custom logger is a reliable and flexible tool for managing logs throughout our Kanban board application. The remaining functions, such as Info, Infof, Infoln, Error, Errorf, and Errorln, follow the same structure, differing only in the log level they handle.
Structured Logging with slog
In Go 1.21, a new package called golang.org/x/exp/slog was introduced, providing structured logging capabilities. Structured logging allows you to organize log records in a machine-readable format, making it easier to work with logs in complex applications and distributed systems.
While we won't delve slog in-depth into this article series, rest assured that we'll explore it thoroughly in a future post. slog offers features such as customizable output formats, dynamic level configuration, and context-aware logging, making it a powerful tool for managing logs effectively in modern Go applications.
For more details on slog and how to integrate it into your Go projects, you can refer to the official documentation at https://pkg.go.dev/golang.org/x/exp/slog. Stay tuned for our upcoming article dedicated to exploring the full potential of structured logging with slog.
Dependency Injection
Dependency injection is a fundamental design pattern in software engineering that addresses the management of dependencies within an application. It provides a systematic approach to decoupling components, enhancing testability, promoting reusability, and improving overall code maintainability.
At its core, dependency injection involves providing dependencies to components, such as objects or functions, from external sources, rather than having the components create these dependencies themselves. By doing so, you establish a clear separation of concerns and enable greater flexibility in configuring and extending your application.
The Basics
At a fundamental level, dependency injection encompasses two key concepts:
- Dependency: A dependency is an external component or service that another component relies on to perform its function. Dependencies can include databases, network services, configuration settings, and much more.
- Injection: Injection refers to the process of supplying these dependencies to the dependent component. Instead of the component creating or managing its dependencies, they are "injected" into the component from an external source.
Benefits of Dependency Injection
Dependency injection offers several significant benefits:
- Decoupling: It reduces tight coupling between components, making it easier to change, replace, or upgrade dependencies without affecting the dependent components.
- Testability: Dependency injection facilitates unit testing by allowing you to inject mock or test-specific dependencies, ensuring that individual components can be tested in isolation.
- Reusability: Components with well-defined dependencies can be reused in various parts of an application or even across different projects, promoting code reuse.
- Maintainability: It enhances code maintainability by promoting a clear separation of concerns and reducing code complexity.
Beyond Logging
In the upcoming section, we'll delve into the process of restructuring our code to facilitate the injection of our recently implemented logger into our handlers. Currently, these handlers exist as non-receiver functions within a package, which presents some challenges. Here's why we need to address these issues:
Avoiding Package-Level References: It's considered best practice to avoid package-level variables, as they introduce a global state into your application, making it challenging to reason about the flow of data and dependencies. For instance, one "ugly" way to inject the logger is to instantiate it in the main function and then set a package-level reference for the logger in the controller package (which holds the handler functions). While this approach technically works, it's far from ideal due to the lack of encapsulation and clarity.
Maintaining Clean Code: Passing the logger as an argument to each function within the package might seem like a workaround, but it can clutter the function signatures and make the code harder to read and maintain. Injecting the logger provides a cleaner and more elegant solution.
Enabling Modularity: Our goal is to promote modularity within our application. We want to ensure that each component is self-contained and has clear dependencies.
While the primary focus here is on injecting a logger, it's essential to recognize that this approach extends beyond logging. We'll adopt a similar methodology to attach other required dependencies throughout our application, ensuring clean code organization and efficient management of various aspects such as configuration settings, third-party service integration, and future enhancements.
BoardController
In the context of our Kanban board application, the BoardController will be responsible for managing and handling board-related HTTP operations, making it an essential component of our application's architecture.dispatches. This controller encapsulates the logic for processing HTTP requests and dispatches them to the appropriate services.
The BoardController struct, in essence, facilitates the use of the constructor-based dependency injection pattern, which is highly favored in Go for streamlined dependency management. By accepting its dependencies through its constructor, the BoardController is well-prepared to fulfill its responsibilities.
// BoardController is responsible for handling board-related operations.
type BoardController struct {
log log.Logger
}
// NewBoardController creates a new BoardController instance.
func NewBoardController(logger log.Logger) *BoardController {
return &BoardController{log: logger}
}
In the constructor functionNewBoardController, you'll notice that we accept a log.Logger interface as a parameter instead of relying on the concrete implementation log.SimpleLogger. This choice offers several benefits. First and foremost, it provides flexibility by allowing us to inject any implementation that satisfies the log.Logger interface. Secondly, it adheres to Go's idiomatic use of interfaces for dependency injection, which promotes decoupling and maintainability.
Furthermore, by depending on an interface rather than a concrete type, the BoardController remains agnostic to the specific details of the logger's implementation. This makes it easier to switch to a different logger in the future or introduce new logging features without modifying the BoardController code. If, down the road, you decide to implement a new logger from scratch or wrap an existing one, you can simply create a small adapter that satisfies the log.Logger interface, allowing for a seamless replacement of our current logger implementation.
Within the BoardController, we are going to include a helpful function
// Log returns the logger associated with this controller.
func (bc *BoardController) Log() log.Logger {
return bc.log
}
This function provides a convenient way to access the logger associated with the BoardController. While it may not be immediately apparent why we're introducing this indirection, it will prove valuable in the future as we start abstracting common functionality into smaller, embedded structures.
Leveraging BoardController
We'll refactor the existing handlers in the controller package to utilize the newly introduced BoardController. This change will enable these handlers to access the controller's internal properties and features.
// BoardsIndexH lists all boards.
func (bc *BoardController) BoardsIndexH(w http.ResponseWriter, r *http.Request) {
// Function body intentionally omitted for clarity.
}
// NewBoard displays a form for creating a new board.
func (bc *BoardController) NewBoard(w http.ResponseWriter, r *http.Request) {
// Function body intentionally omitted for clarity.
}
// CreateBoard creates a new board.
func (bc *BoardController) CreateBoard(w http.ResponseWriter, r *http.Request) {
// Function body intentionally omitted for clarity.
}
// ShowBoard displays a board with the specified ID.
func (bc *BoardController) ShowBoard(w http.ResponseWriter, r *http.Request) {
// Function body intentionally omitted for clarity.
}
// EditBoard displays a form for editing a board.
func (bc *BoardController) EditBoard(w http.ResponseWriter, r *http.Request) {
// Function body intentionally omitted for clarity.
}
// UpdateBoard updates a board with the specified ID.
func (bc *BoardController) UpdateBoard(w http.ResponseWriter, r *http.Request) {
// Function body intentionally omitted for clarity.
}
// DeleteBoard deletes a board with the specified ID.
func (bc *BoardController) DeleteBoard(w http.ResponseWriter, r *http.Request) {
// Function body intentionally omitted for clarity.
}
// DeleteConfirm confirms the deletion of a board with the specified ID.
func (bc *BoardController) DeleteConfirm(w http.ResponseWriter, r *http.Request) {
// Function body intentionally omitted for clarity.
}
Now let's focus on the upgraded ShowBoad function
package controller
import (
...
"github.com/solutioncrafting/plykan/internal/log"
)
// ShowBoard displays a board with the specified ID.
func (bc *BoardController) ShowBoard(w http.ResponseWriter, r *http.Request) {
vars := mux.Vars(r)
id := vars["id"]
bc.Log().Infof("Showing board with ID: %s\n", id)
// In the future, we will fetch these from the database
sampleToDoTasks := []string{"Task 1", "Task 2"}
sampleInProgressTasks := []string{"Task 3", "Task 4"}
sampleDoneTasks := []string{"Task 5", "Task 6"}
pageData := &Page{
Head: HeadData{
Title: "Plykan - Your Personal Kanban Board",
Description: "Achieve more, stress less",
},
Board: BoardData{
ID: id,
// Populate data for each Kanban column
Columns: []ColumnData{
{ColumnName: "To Do", Tasks: sampleToDoTasks, Color: "blue-200"},
{ColumnName: "In Progress", Tasks: sampleInProgressTasks, Color: "green-200"},
{ColumnName: "Done", Tasks: sampleDoneTasks, Color: "yellow-200"},
},
},
}
ts, err := template.ParseFiles(
"assets/templates/default.tmpl",
"assets/templates/pages/board.tmpl",
"assets/templates/partials/column.tmpl")
if err != nil {
bc.Log().Error(err)
http.Error(w, "Unable to parse template", http.StatusInternalServerError)
return
}
err = ts.ExecuteTemplate(w, "default", pageData)
if err != nil {
bc.Log().Error(err)
http.Error(w, "Failed to execute template", http.StatusInternalServerError)
}
}
In the updated ShowBoard function, we've not only replaced the standard library 'log' but also enhanced the logging behavior. Now, Info and Error messages are correctly labeled as [INF] and [ERR], respectively, along with a timestamp for each event. These improvements ensure that our application's log output is not only more informative but also consistent, making it easier to identify and troubleshoot issues when they arise.
Verifying the Changes
Now that we've made the necessary updates to our code, let's see the improvements in action. Start by running the application.
$ go run main.go
With the application running, open your web browser and navigate to http://localhost:8080/boards/111. As you access this route, you'll notice the terminal output displaying log entries like the following.
[INF] 2023/10/17 12:36:34 Listening on port 8080...
[INF] 2023/10/17 12:36:39 Showing board with ID: 111
These new log entries provide valuable information about the application's activity, including timestamps, log levels, and the corresponding log messages letting you monitor your application's behavior and troubleshoot issues more effectively.
Up Next: Configuration
In the upcoming phase of our Kanban board application's evolution, we'll delve into the realm of application configuration management. You'll discover techniques to fine-tune your application's behavior using flags and harness the power of environment variables, creating a flexible configuration strategy adaptable to various deployment scenarios. We'll guide you in setting sensible default values for essential settings and leverage the magic of Go interfaces to facilitate a seamless transition to a widely adopted configuration management library. Get ready to elevate your configuration skills and join us on this thrilling journey to becoming a configuration pro.
