Server Logging in Go

README.md

Server Event Logging in Go

Inspo

Many thanks to https://github.com/jadekler/git-go-websiteskeleton who got me started in this direction. Jadekler was in turn inspired by https://gist.github.com/cespare/3985516. Ultimately, this implementation has a lot more in common with cespare's. There are a few minor differences. I mainly wrote this one to teach myself exactly what was going on (hence all the comments) and to demonstrate the inclusion of the gorilla/mux framework without using Jadekler's technique of two separate http muxes.

handlers.go

package main

import (
  "io"
  "net/http"
)

func Home(resp http.ResponseWriter, req *http.Request) {
  io.WriteString(resp, "Hello World!")
}
  

logger.go

package main

import (
	"fmt"
	"io"
	"net/http"
	"strings"
	"time"
)

// wraps our http multiplexer
// includes an io.Writer for logging
type ServerLogger struct {
	mux http.Handler
	out io.Writer
}

type serverEvent struct {
	// composed of http.ResponseWriter so that we can
	// intercept Write and WriteHeader for logging purposes
	http.ResponseWriter

	ip                    string
	time                  time.Time
	method, uri, protocol string
	status                int
	responseBytes         int64
	elapsedTime           time.Duration
}

func NewServerLogger(mux http.Handler, out io.Writer) http.Handler {
	return &ServerLogger{
		mux: mux,
		out: out,
	}
}

func (s *ServerLogger) ServeHTTP(resp http.ResponseWriter, req *http.Request) {
	// RemoteAddr allows HTTP servers and other software to record
	// the network address that sent the request, usually for
	// logging. The HTTP server in this package
	// sets RemoteAddr to an "IP:port"
	clientIP := req.RemoteAddr
	if port := strings.LastIndex(clientIP, ":"); port != -1 {
		clientIP = clientIP[:port]
	}

	event := &serverEvent{
		ResponseWriter: resp,
		ip:             clientIP,
		time:           time.Time{},
		method:         req.Method,
		uri:            req.RequestURI,
		protocol:       req.Proto,
		status:         http.StatusOK,
		elapsedTime:    time.Duration(0),
	}

	startTime := time.Now()
	// we hand off the request, using our event as the response writer
	s.mux.ServeHTTP(event, req)
	finishTime := time.Now()

	event.time = finishTime.UTC()
	event.elapsedTime = finishTime.Sub(startTime)

	event.Log(s.out)
}

func (e *serverEvent) Write(p []byte) (int, error) {
	written, err := e.ResponseWriter.Write(p)
	// we interrupt this regularly scheduled response
	// to take note of how many bytes were written
	e.responseBytes += int64(written)
	return written, err
}

func (e *serverEvent) WriteHeader(status int) {
	// we interrupt this regularly scheduled header
	// to take note of the status and overwrite the
	// http.StatusOK placeholder we initialized the event with
	e.status = status
	e.ResponseWriter.WriteHeader(status)
}

func (e *serverEvent) Log(out io.Writer) {
	timestamp := e.time.Format("Jan _2 2006 03:04:05")
	requestLine := strings.Join([]string{e.method, e.uri, e.protocol}, " ")
	fmt.Fprintf(out, "%s - - [%s] \"%s\" %d %d (load time: %.4f)\n", e.ip, timestamp,
		requestLine, e.status, e.responseBytes, e.elapsedTime.Seconds())
}

main.go

package main

import (
	"net/http"
	"os"
	"github.com/gorilla/mux"
)

func main() {
	router := mux.NewRouter()

	router.HandleFunc("/", Home)

	serverLogger := NewServerLogger(router, os.Stderr)
	server := &http.Server{
		Addr:    ":4000",
		Handler: serverLogger,
	}
	server.ListenAndServe()
}