feat: added JSON logging

Author: a-h

filesystem.go

@@ -11,6 +11,8 @@ import (
 	"path/filepath"
 	"sort"
 	"strings"
+
+	"github.com/a-h/gemini/log"
 )
 
 type Dir string
@@ -48,7 +50,7 @@ func DirectoryListingHandler(path string, f File) Handler {
 	return HandlerFunc(func(w ResponseWriter, r *Request) {
 		files, err := f.Readdir(-1)
 		if err != nil {
-			//TODO: Log.
+			log.Error("DirectoryListingHandler: readdir failed", err, log.String("path", r.URL.Path), log.String("url", r.URL.String()))
 			w.SetHeader(CodeTemporaryFailure, "readdir failed")
 			return
 		}
@@ -90,13 +92,13 @@ func FileSystemHandler(fs FileSystem) Handler {
 		}
 		f, err := fs.Open(r.URL.Path)
 		if err != nil {
-			//TODO: Log.
+			log.Error("FileSystemHandler: file open failed", err, log.String("path", r.URL.Path), log.String("url", r.URL.String()))
 			w.SetHeader(CodeTemporaryFailure, "file open failed")
 			return
 		}
 		stat, err := f.Stat()
 		if err != nil {
-			//TODO: Log.
+			log.Error("FileSystemHandler: file stat failed", err, log.String("path", r.URL.Path), log.String("url", r.URL.String()))
 			w.SetHeader(CodeTemporaryFailure, "file stat failed")
 			return
 		}

go.mod

@@ -1,13 +1,3 @@
 module github.com/a-h/gemini
 
 go 1.14
-
-require (
-	github.com/gdamore/tcell v1.3.0
-	github.com/lucasb-eyer/go-colorful v1.0.3 // indirect
-	github.com/mattn/go-runewidth v0.0.9
-	github.com/natefinch/atomic v0.0.0-20200526193002-18c0533a5b09
-	github.com/pkg/browser v0.0.0-20180916011732-0a3d74bf9ce4
-	golang.org/x/sys v0.0.0-20200817155316-9781c653f443 // indirect
-	golang.org/x/text v0.3.2 // indirect
-)

go.sum

@@ -1,22 +0,0 @@
-github.com/DATA-DOG/go-sqlmock v1.3.3/go.mod h1:f/Ixk793poVmq4qj/V1dPUg2JEAKC73Q5eFN3EC/SaM=
-github.com/gdamore/encoding v1.0.0 h1:+7OoQ1Bc6eTm5niUzBa0Ctsh6JbMW6Ra+YNuAtDBdko=
-github.com/gdamore/encoding v1.0.0/go.mod h1:alR0ol34c49FCSBLjhosxzcPHQbf2trDkoo5dl+VrEg=
-github.com/gdamore/tcell v1.3.0 h1:r35w0JBADPZCVQijYebl6YMWWtHRqVEGt7kL2eBADRM=
-github.com/gdamore/tcell v1.3.0/go.mod h1:Hjvr+Ofd+gLglo7RYKxxnzCBmev3BzsS67MebKS4zMM=
-github.com/lucasb-eyer/go-colorful v1.0.2/go.mod h1:0MS4r+7BZKSJ5mw4/S5MPN+qHFF1fYclkSPilDOKW0s=
-github.com/lucasb-eyer/go-colorful v1.0.3 h1:QIbQXiugsb+q10B+MI+7DI1oQLdmnep86tWFlaaUAac=
-github.com/lucasb-eyer/go-colorful v1.0.3/go.mod h1:R4dSotOR9KMtayYi1e77YzuveK+i7ruzyGqttikkLy0=
-github.com/mattn/go-runewidth v0.0.4/go.mod h1:LwmH8dsx7+W8Uxz3IHJYH5QSwggIsqBzpuz5H//U1FU=
-github.com/mattn/go-runewidth v0.0.9 h1:Lm995f3rfxdpd6TSmuVCHVb/QhupuXlYr8sCI/QdE+0=
-github.com/mattn/go-runewidth v0.0.9/go.mod h1:H031xJmbD/WCDINGzjvQ9THkh0rPKHF+m2gUSrubnMI=
-github.com/natefinch/atomic v0.0.0-20200526193002-18c0533a5b09 h1:DXR0VtCesBD2ss3toN9OEeXszpQmW9dc3SvUbUfiBC0=
-github.com/natefinch/atomic v0.0.0-20200526193002-18c0533a5b09/go.mod h1:1rLVY/DWf3U6vSZgH16S7pymfrhK2lcUlXjgGglw/lY=
-github.com/pkg/browser v0.0.0-20180916011732-0a3d74bf9ce4 h1:49lOXmGaUpV9Fz3gd7TFZY106KVlPVa5jcYD1gaQf98=
-github.com/pkg/browser v0.0.0-20180916011732-0a3d74bf9ce4/go.mod h1:4OwLy04Bl9Ef3GJJCoec+30X3LQs/0/m4HFRt/2LUSA=
-golang.org/x/sys v0.0.0-20190626150813-e07cf5db2756/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
-golang.org/x/sys v0.0.0-20200817155316-9781c653f443 h1:X18bCaipMcoJGm27Nv7zr4XYPKGUy92GtqboKC2Hxaw=
-golang.org/x/sys v0.0.0-20200817155316-9781c653f443/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
-golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=
-golang.org/x/text v0.3.2 h1:tW2bmiBqwgJj/UpqtC8EpXEZVYOwU0yG4iWbprSVAcs=
-golang.org/x/text v0.3.2/go.mod h1:bEr9sfX3Q8Zfm5fL9x+3itogRgK3+ptLWKqgva+5dAk=
-golang.org/x/tools v0.0.0-20180917221912-90fa682c2a6e/go.mod h1:n7NCudcB/nEzxVGmLbDWY5pfWTLqBcC2KZ6jyYvM4mQ=

log/log.go

@@ -0,0 +1,82 @@
+package log
+
+import (
+	"encoding/json"
+	"fmt"
+	"os"
+	"sync"
+	"time"
+)
+
+type Field func() (k string, v interface{})
+
+func String(name string, value string) Field {
+	return func() (k string, v interface{}) {
+		return name, value
+	}
+}
+func Int(name string, value int) Field {
+	return func() (k string, v interface{}) {
+		return name, value
+	}
+}
+func Int64(name string, value int64) Field {
+	return func() (k string, v interface{}) {
+		return name, value
+	}
+}
+func Interface(name string, value interface{}) Field {
+	return func() (k string, v interface{}) {
+		return name, value
+	}
+}
+
+func Info(msg string, fields ...Field) {
+	std.Write("INFO", msg, fields...)
+}
+
+func Warn(msg string, fields ...Field) {
+	std.Write("WARN", msg, fields...)
+}
+
+func Error(msg string, err error, fields ...Field) {
+	if err != nil {
+		fields = append(fields, String("error", err.Error()))
+	}
+	std.Write("ERROR", msg, fields...)
+}
+
+type Logger struct {
+	stdout  sync.Mutex
+	stderr  sync.Mutex
+	enc     json.Encoder
+	newLine []byte
+}
+
+func (s *Logger) Write(level string, msg string, fields ...Field) {
+	entry := make(map[string]interface{})
+	entry["time"] = time.Now().UTC().Format(time.RFC3339)
+	entry["level"] = level
+	entry["msg"] = msg
+	for i := 0; i < len(fields); i++ {
+		k, v := fields[i]()
+		entry[k] = v
+	}
+	j, err := json.Marshal(entry)
+	if err != nil {
+		j = []byte(fmt.Sprintf("log.Write: failed to marshal entry '%+v': %v", entry, err))
+	}
+	if level == "ERROR" {
+		s.stderr.Lock()
+		defer s.stderr.Unlock()
+		os.Stderr.Write(j)
+		os.Stderr.Write(s.newLine)
+		return
+	}
+	s.stdout.Lock()
+	defer s.stdout.Unlock()
+	os.Stdout.Write(j)
+	os.Stderr.Write(s.newLine)
+}
+
+var std = &Logger{newLine: []byte("\n")}

server.go

@@ -8,11 +8,13 @@ import (
 	"errors"
 	"fmt"
 	"io"
-	"log"
 	"net"
 	"net/url"
+	"reflect"
 	"strings"
 	"time"
+
+	"github.com/a-h/gemini/log"
 )
 
 // Handler of Gemini content.
@@ -114,10 +116,6 @@ type Server struct {
 	HandlerTimeout  time.Duration
 }
 
-func (srv *Server) logf(format string, v ...interface{}) {
-	log.Printf(format, v...)
-}
-
 // Set the server listening on the specified port.
 func (srv *Server) ListenAndServe() error {
 	// Don't start if the server is already closing down.
@@ -128,7 +126,7 @@ func (srv *Server) ListenAndServe() error {
 	if addr == "" {
 		addr = ":1965"
 	}
-	srv.logf("gemini: starting on %v", addr)
+	log.Info("gemini: starting", log.String("addr", addr))
 	ln, err := net.Listen("tcp", addr)
 	if err != nil {
 		return err
@@ -137,15 +135,15 @@ func (srv *Server) ListenAndServe() error {
 	if srv.Insecure {
 		err = srv.serveInsecure(ln)
 		if err != nil {
-			srv.logf("gemini: failure in serveInsecure")
+			log.Error("gemini: serveInsecure failure", err, log.String("addr", addr))
 		}
 	} else {
 		err = srv.serveTLS(ln)
 		if err != nil {
-			srv.logf("gemini: failure in serveTLS: %v", err)
+			log.Error("gemini: serveTLS failure", err, log.String("addr", addr))
 		}
 	}
-	srv.logf("gemini: stopped")
+	log.Info("gemini: stopped")
 	return err
 }
 
@@ -162,12 +160,12 @@ func (srv *Server) serveInsecure(l net.Listener) (err error) {
 	}
 	for {
 		if err = srv.Context.Err(); err != nil {
-			srv.logf("gemini: context caused shutdown: %v", err)
+			log.Error("gemini: context caused shutdown", err)
 			return err
 		}
 		rw, err := l.Accept()
 		if err != nil {
-			srv.logf("gemini: insecure listener error: %v", err)
+			log.Error("gemini: insecure listener error", err)
 			continue
 		}
 		go func() {
@@ -196,12 +194,12 @@ func (srv *Server) serveTLS(l net.Listener) (err error) {
 	tlsListener := tls.NewListener(l, config)
 	for {
 		if err = srv.Context.Err(); err != nil {
-			srv.logf("gemini: context caused shutdown: %v", err)
+			log.Error("gemini: context caused shutdown", err)
 			return err
 		}
 		conn, err := tlsListener.Accept()
 		if err != nil {
-			srv.logf("gemini: tls listener error: %v", err)
+			log.Error("gemini: tls listener error", err)
 			continue
 		}
 		tlsConn, ok := conn.(*tls.Conn)
@@ -215,7 +213,7 @@ func (srv *Server) serveTLS(l net.Listener) (err error) {
 func (srv *Server) handleTLS(conn *tls.Conn) {
 	defer conn.Close()
 	if err := conn.Handshake(); err != nil {
-		srv.logf("gemini: failed TLS handshake from %s: %v", conn.RemoteAddr(), err)
+		log.Info("gemini: failed TLS handshake", log.String("remote", conn.RemoteAddr().String()), log.String("reason", err.Error()))
 		return
 	}
 	var certificate Certificate
@@ -235,7 +233,7 @@ func (srv *Server) handleTLS(conn *tls.Conn) {
 	serverName := conn.ConnectionState().ServerName
 	dh, ok := srv.DomainToHandler[serverName]
 	if !ok {
-		srv.logf("gemini: failed to find domain handler for serverName: %q", serverName)
+		log.Warn("gemini: failed to find domain handler", log.String("serverName", serverName))
 	}
 	srv.handle(dh, certificate, conn)
 }
@@ -246,11 +244,10 @@ func (srv *Server) handle(dh *DomainHandler, certificate Certificate, conn net.C
 	conn.SetReadDeadline(time.Now().Add(srv.ReadTimeout))
 	r, ok, err := srv.parseRequest(conn)
 	if err != nil {
-		srv.logf("gemini: failed to parse request: %v", err)
+		log.Info("gemini: failed to parse request", log.String("reason", err.Error()))
 		return
 	}
 	if !ok {
-		srv.logf("gemini: could not parse request")
 		return
 	}
 	r.Certificate = certificate
@@ -261,7 +258,7 @@ func (srv *Server) handle(dh *DomainHandler, certificate Certificate, conn net.C
 	w := NewWriter(conn)
 	defer func() {
 		if p := recover(); p != nil {
-			srv.logf("gemini: server error: %v: %v", r.URL.Path, p)
+			log.Error("gemini: server error", nil, log.String("url", r.URL.String()), log.Interface("recover", p))
 			w.SetHeader(CodeCGIError, "internal error")
 		}
 	}()
@@ -271,10 +268,18 @@ func (srv *Server) handle(dh *DomainHandler, certificate Certificate, conn net.C
 	}
 	dh.Handler.ServeGemini(w, r)
 	if w.Code == "" {
-		srv.logf("gemini: handler for %q resulted in empty response, sending empty document", r.URL.Path)
+		log.Error("gemini: handler resulted in empty response", nil, log.String("url", r.URL.String()), log.String("handlerType", reflect.TypeOf(dh.Handler).PkgPath()))
 		w.SetHeader(CodeCGIError, "empty response")
 	}
-	srv.logf("gemini: %v response: %v time: %v", r.URL.Path, w.Code, time.Now().Sub(start))
+	duration := time.Now().Sub(start)
+	log.Info("gemini: response",
+		log.String("url", r.URL.String()),
+		log.String("path", r.URL.Path),
+		log.String("code", w.Code),
+		log.String("handlerType", reflect.TypeOf(dh.Handler).PkgPath()),
+		log.Int64("ms", duration.Milliseconds()),
+		log.Int64("us", int64(duration.Microseconds())),
+	)
 }
 
 func (srv *Server) parseRequest(rw io.ReadWriter) (r *Request, ok bool, err error) {
@@ -284,17 +289,18 @@ func (srv *Server) parseRequest(rw io.ReadWriter) (r *Request, ok bool, err erro
 		return
 	}
 	if !ok {
+		log.Info("gemini: request too long or malformed", log.String("request", string(request)))
 		writeHeaderToWriter(CodeBadRequest, "request too long or malformed", rw)
 		return
 	}
 	ok = false
 	url, err := url.Parse(strings.TrimSpace(string(request)))
 	if err != nil {
-		srv.logf("gemini: malformed request: %q", string(request))
+		log.Info("gemini: malformed request", log.String("request", string(request)))
 		writeHeaderToWriter(CodeBadRequest, "request malformed", rw)
 		return
 	}
-	srv.logf("gemini: received request: %s", url)
+	log.Info("gemini: received request", log.String("request", url.String()))
 	r = &Request{
 		URL: url,
 	}

server_test.go

@@ -2,10 +2,13 @@ package gemini
 
 import (
 	"bytes"
+	"context"
 	"io/ioutil"
+	"net"
 	"reflect"
 	"strings"
 	"testing"
+	"time"
 )
 
 func TestServer(t *testing.T) {
@@ -186,6 +189,7 @@ func TestServer(t *testing.T) {
 				DomainToHandler: map[string]*DomainHandler{
 					"": dh,
 				},
+				Context: context.Background(),
 			}
 			s.handle(dh, tt.cert, rec)
 
@@ -241,3 +245,27 @@ func (rec *Recorder) Read(p []byte) (n int, err error) {
 	rec.read += n
 	return n, err
 }
+
+func (rec *Recorder) Close() error {
+	return nil
+}
+
+func (rec *Recorder) LocalAddr() net.Addr {
+	return &net.IPAddr{}
+}
+
+func (rec *Recorder) RemoteAddr() net.Addr {
+	return &net.IPAddr{}
+}
+
+func (rec *Recorder) SetDeadline(t time.Time) error {
+	return nil
+}
+
+func (rec *Recorder) SetReadDeadline(t time.Time) error {
+	return nil
+}
+
+func (rec *Recorder) SetWriteDeadline(t time.Time) error {
+	return nil
+}