Request logging

Chapter 6.3.

Let’s continue in the same vein and add some middleware to log HTTP requests. Specifically, we’re going to use the structured logger that we created earlier to record the IP address of the user, and the method, URI and HTTP version for the request.

Open your middleware.go file and create a logRequest() method using the standard middleware pattern, like so:

File: cmd/web/middleware.go

package main

...

func (app *application) logRequest(next http.Handler) http.Handler {
    return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        var (
            ip     = r.RemoteAddr
            proto  = r.Proto
            method = r.Method
            uri    = r.URL.RequestURI()
        )

        app.logger.Info("received request", "ip", ip, "proto", proto, "method", method, "uri", uri)

        next.ServeHTTP(w, r)
    })
}

Notice that this time we’re implementing the middleware as a method on application?

This is perfectly valid to do. Our middleware method has the same signature as before, but because it is a method against application it also has access to the handler dependencies including the structured logger.

Now let’s update our routes.go file so that the logRequest middleware is executed first, and for all requests, so that the flow of control (reading from left to right) looks like this:

logRequest ↔ commonHeaders ↔ servemux ↔ application handler

File: cmd/web/routes.go

package main

import "net/http"

func (app *application) routes() http.Handler {
    mux := http.NewServeMux()

    fileServer := http.FileServer(http.Dir("./ui/static/"))
    mux.Handle("GET /static/", http.StripPrefix("/static", fileServer))

    mux.HandleFunc("GET /{$}", app.home)
    mux.HandleFunc("GET /snippet/view/{id}", app.snippetView)
    mux.HandleFunc("GET /snippet/create", app.snippetCreate)
    mux.HandleFunc("POST /snippet/create", app.snippetCreatePost)

    // Wrap the existing chain with the logRequest middleware.
    return app.logRequest(commonHeaders(mux))
}

Alright… let’s give it a try!

Restart your application, browse around, and then check your terminal window. You should see log output which looks a bit like this:

$ go run ./cmd/web
time=2024-03-18T11:29:23.000+00:00 level=INFO msg="starting server" addr=:4000
time=2024-03-18T11:29:23.000+00:00 level=INFO msg="received request" ip=127.0.0.1:56536 proto=HTTP/1.1 method=GET uri=/
time=2024-03-18T11:29:23.000+00:00 level=INFO msg="received request" ip=127.0.0.1:56536 proto=HTTP/1.1 method=GET uri=/static/css/main.css
time=2024-03-18T11:29:23.000+00:00 level=INFO msg="received request" ip=127.0.0.1:56546 proto=HTTP/1.1 method=GET uri=/static/js/main.js
time=2024-03-18T11:29:23.000+00:00 level=INFO msg="received request" ip=127.0.0.1:56536 proto=HTTP/1.1 method=GET uri=/static/img/logo.png
time=2024-03-18T11:29:23.000+00:00 level=INFO msg="received request" ip=127.0.0.1:56536 proto=HTTP/1.1 method=GET uri=/static/img/favicon.ico
time=2024-03-18T11:29:23.000+00:00 level=INFO msg="received request" ip=127.0.0.1:56536 proto=HTTP/1.1 method=GET uri="/snippet/view/2"