implement access log

mostly copied from gorrila's LogginHandler but changed to make it not
block finishing the request and to add time the request took.

app/access_logs.go

@@ -0,0 +1,31 @@
+package app
+
+import (
+	"fmt"
+	"io"
+	"os"
+)
+
+const accessLogFilePerm = 0600
+
+// open an access log with the appropriate permissions on the file
+// if it isn't open yet. Return the already open otherwise
+func (a accessLogs) openAccessLog(file string) (io.Writer, error) {
+	if accessLog, ok := a[file]; ok {
+		return accessLog, nil
+	}
+	accessLog, err := os.OpenFile(
+		file,
+		os.O_CREATE|os.O_WRONLY|os.O_APPEND,
+		accessLogFilePerm,
+	)
+	if err != nil {
+		return nil, fmt.Errorf("error opening access log `%s`- %s",
+			file, err)
+	}
+	a[file] = accessLog
+	return accessLog, nil
+}
+
+// helper type to facilitate not opening the same access_log twice
+type accessLogs map[string]io.Writer

app/app.go

@@ -40,6 +40,8 @@ type Application struct {
 	// a types.RequestHandler.
 	virtualHosts map[string]*VirtualHost
 
+	notConfiguredHandler types.RequestHandler
+
 	// A map from cache zone ID (from the config) to types.CacheZone
 	// that is resposible for this cache zone.
 	cacheZones map[string]*types.CacheZone

app/init.go

@@ -2,6 +2,8 @@ package app
 
 import (
 	"fmt"
+	"io"
+	"net/http"
 	"time"
 
 	"golang.org/x/net/context"
@@ -19,6 +21,9 @@ import (
 // initFromConfig should be called when starting or reloading the app. It makes
 // all the connections between cache zones, virtual hosts and upstreams.
 func (a *Application) initFromConfig() (err error) {
+	var accessLogs = accessLogs(make(map[string]io.Writer))
+	accessLogs[""] = nil // for the non configured
+
 	// Make the vhost and cacheZone maps
 	a.virtualHosts = make(map[string]*VirtualHost)
 	a.cacheZones = make(map[string]*types.CacheZone)
@@ -55,9 +60,25 @@ func (a *Application) initFromConfig() (err error) {
 
 		a.cacheZones[cfgCz.ID] = cz
 	}
+	a.notConfiguredHandler = newNotConfiguredHandler()
+	if accessLog, err := accessLogs.openAccessLog(a.cfg.HTTP.AccessLog); err == nil {
+		a.notConfiguredHandler = loggingHandler(a.notConfiguredHandler, accessLog)
+	} else {
+		return err
+	}
 
 	// Initialize all vhosts
 	for _, cfgVhost := range a.cfg.HTTP.Servers {
+		var accessLog io.Writer
+		if cfgVhost.AccessLog != "" {
+			var err error
+			accessLog, err = accessLogs.openAccessLog(cfgVhost.AccessLog)
+			if err != nil {
+				return fmt.Errorf("error opening access log for virtual host %s - %s",
+					cfgVhost.Name, err)
+			}
+		}
+
 		vhost := VirtualHost{
 			Location: types.Location{
 				Name:                  cfgVhost.Name,
@@ -92,11 +113,11 @@ func (a *Application) initFromConfig() (err error) {
 			vhost.Cache = cz
 		}
 
-		if vhost.Handler, err = adapt(&vhost.Location, cfgVhost.Handlers); err != nil {
+		if vhost.Handler, err = adapt(&vhost.Location, cfgVhost.Handlers, accessLog); err != nil {
 			return err
 		}
 		var locations []*types.Location
-		if locations, err = a.initFromConfigLocationsForVHost(cfgVhost.Locations); err != nil {
+		if locations, err = a.initFromConfigLocationsForVHost(cfgVhost.Locations, accessLog); err != nil {
 			return err
 		}
 
@@ -110,7 +131,7 @@ func (a *Application) initFromConfig() (err error) {
 	return nil
 }
 
-func (a *Application) initFromConfigLocationsForVHost(cfgLocations []*config.Location) ([]*types.Location, error) {
+func (a *Application) initFromConfigLocationsForVHost(cfgLocations []*config.Location, accessLog io.Writer) ([]*types.Location, error) {
 	var err error
 	var locations = make([]*types.Location, len(cfgLocations))
 	for index, locCfg := range cfgLocations {
@@ -134,7 +155,7 @@ func (a *Application) initFromConfigLocationsForVHost(cfgLocations []*config.Loc
 			locations[index].Cache = cz
 		}
 
-		if locations[index].Handler, err = adapt(locations[index], locCfg.Handlers); err != nil {
+		if locations[index].Handler, err = adapt(locations[index], locCfg.Handlers, accessLog); err != nil {
 			return nil, err
 		}
 
@@ -188,13 +209,32 @@ func (a *Application) reloadCache(cz *types.CacheZone) {
 	}()
 }
 
-func adapt(location *types.Location, handlers []config.Handler) (types.RequestHandler, error) {
+func adapt(location *types.Location, handlers []config.Handler, accessLog io.Writer) (types.RequestHandler, error) {
 	var res types.RequestHandler
 	var err error
 	for index := len(handlers) - 1; index >= 0; index-- {
 		if res, err = handler.New(&handlers[index], location, res); err != nil {
 			return nil, err
 		}
 	}
-	return res, nil
+	return loggingHandler(res, accessLog), nil
+}
+
+func loggingHandler(next types.RequestHandler, accessLog io.Writer) types.RequestHandler {
+	if accessLog == nil {
+		return next
+	}
+
+	return types.RequestHandlerFunc(
+		func(ctx context.Context, w http.ResponseWriter, r *http.Request) {
+			t := time.Now()
+			l := &responseLogger{ResponseWriter: w}
+			url := *r.URL
+			next.RequestHandle(ctx, l, r)
+			defer func() {
+				go func() {
+					writeLog(accessLog, r, url, t, l.Status(), l.Size())
+				}()
+			}()
+		})
 }

app/net.go

@@ -4,6 +4,8 @@ import (
 	"net/http"
 	"strings"
 
+	"golang.org/x/net/context"
+
 	"github.com/ironsmile/nedomi/types"
 )
 
@@ -29,7 +31,7 @@ func (app *Application) ServeHTTP(writer http.ResponseWriter, req *http.Request)
 
 	if location == nil || location.Handler == nil {
 		defer app.stats.notConfigured()
-		http.NotFound(writer, req)
+		app.notConfiguredHandler.RequestHandle(app.ctx, writer, req)
 		return
 	}
 	// location matched
@@ -38,3 +40,9 @@ func (app *Application) ServeHTTP(writer http.ResponseWriter, req *http.Request)
 	location.Handler.RequestHandle(app.ctx, writer, req)
 	// after request is handled
 }
+
+func newNotConfiguredHandler() types.RequestHandler {
+	return types.RequestHandlerFunc(func(_ context.Context, w http.ResponseWriter, r *http.Request) {
+		http.NotFound(w, r)
+	})
+}

app/net_test.go

@@ -47,6 +47,7 @@ func TestLocationMatching(t *testing.T) {
 		t.Fatal("Error while creating test LocationMuxer", err)
 	}
 	app := &Application{
+		notConfiguredHandler: newNotConfiguredHandler(),
 		virtualHosts: map[string]*VirtualHost{
 			"localhost": {
 				Location: types.Location{

app/write_log.go

@@ -0,0 +1,163 @@
+// Copyright 2013 The Gorilla Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+package app
+
+import (
+	"io"
+	"net"
+	"net/http"
+	"net/url"
+	"strconv"
+	"time"
+	"unicode/utf8"
+)
+
+// The file is mostly a copy of the source from gorilla's handlers.go
+
+// buildCommonLogLine builds a log entry for req in Apache Common Log Format.
+// ts is the timestamp with which the entry should be logged.
+// status and size are used to provide the response HTTP status and size.
+// Additionally the time since the timestamp is being written
+func buildCommonLogLine(req *http.Request, url url.URL, ts time.Time, status int, size int) []byte {
+	username := "-"
+	if url.User != nil {
+		if name := url.User.Username(); name != "" {
+			username = name
+		}
+	}
+
+	host, _, err := net.SplitHostPort(req.RemoteAddr)
+
+	if err != nil {
+		host = req.RemoteAddr
+	}
+
+	uri := url.RequestURI()
+	ranFor := int(time.Since(ts).Nanoseconds())
+
+	buf := make([]byte, 0, 3*(len(host)+len(username)+len(req.Method)+len(uri)+len(req.Proto)+50)/2)
+	buf = append(buf, host...)
+	buf = append(buf, " - "...)
+	buf = append(buf, username...)
+	buf = append(buf, " ["...)
+	buf = append(buf, ts.Format("02/Jan/2006:15:04:05 -0700")...)
+	buf = append(buf, `] "`...)
+	buf = append(buf, req.Method...)
+	buf = append(buf, " "...)
+	buf = appendQuoted(buf, uri)
+	buf = append(buf, " "...)
+	buf = append(buf, req.Proto...)
+	buf = append(buf, `" `...)
+	buf = append(buf, strconv.Itoa(status)...)
+	buf = append(buf, " "...)
+	buf = append(buf, strconv.Itoa(size)...)
+	buf = append(buf, " "...)
+	buf = append(buf, strconv.Itoa(ranFor)...)
+	return buf
+}
+
+// writeLog writes a log entry for req to w in Apache Common Log Format.
+// ts is the timestamp with which the entry should be logged.
+// status and size are used to provide the response HTTP status and size.
+func writeLog(w io.Writer, req *http.Request, url url.URL, ts time.Time, status, size int) {
+	buf := buildCommonLogLine(req, url, ts, status, size)
+	buf = append(buf, '\n')
+	w.Write(buf)
+}
+
+func appendQuoted(buf []byte, s string) []byte {
+	var runeTmp [utf8.UTFMax]byte
+	for width := 0; len(s) > 0; s = s[width:] {
+		r := rune(s[0])
+		width = 1
+		if r >= utf8.RuneSelf {
+			r, width = utf8.DecodeRuneInString(s)
+		}
+		if width == 1 && r == utf8.RuneError {
+			buf = append(buf, `\x`...)
+			buf = append(buf, lowerhex[s[0]>>4])
+			buf = append(buf, lowerhex[s[0]&0xF])
+			continue
+		}
+		if r == rune('"') || r == '\\' { // always backslashed
+			buf = append(buf, '\\')
+			buf = append(buf, byte(r))
+			continue
+		}
+		if strconv.IsPrint(r) {
+			n := utf8.EncodeRune(runeTmp[:], r)
+			buf = append(buf, runeTmp[:n]...)
+			continue
+		}
+		switch r {
+		case '\a':
+			buf = append(buf, `\a`...)
+		case '\b':
+			buf = append(buf, `\b`...)
+		case '\f':
+			buf = append(buf, `\f`...)
+		case '\n':
+			buf = append(buf, `\n`...)
+		case '\r':
+			buf = append(buf, `\r`...)
+		case '\t':
+			buf = append(buf, `\t`...)
+		case '\v':
+			buf = append(buf, `\v`...)
+		default:
+			switch {
+			case r < ' ':
+				buf = append(buf, `\x`...)
+				buf = append(buf, lowerhex[s[0]>>4])
+				buf = append(buf, lowerhex[s[0]&0xF])
+			case r > utf8.MaxRune:
+				r = 0xFFFD
+				fallthrough
+			case r < 0x10000:
+				buf = append(buf, `\u`...)
+				for s := 12; s >= 0; s -= 4 {
+					buf = append(buf, lowerhex[r>>uint(s)&0xF])
+				}
+			default:
+				buf = append(buf, `\U`...)
+				for s := 28; s >= 0; s -= 4 {
+					buf = append(buf, lowerhex[r>>uint(s)&0xF])
+				}
+			}
+		}
+	}
+	return buf
+}
+
+const lowerhex = "0123456789abcdef"
+
+type responseLogger struct {
+	http.ResponseWriter
+	status int
+	size   int
+}
+
+func (l *responseLogger) Write(b []byte) (int, error) {
+	if l.status == 0 {
+		// The status will be StatusOK if WriteHeader has not been called yet
+		l.status = http.StatusOK
+	}
+	size, err := l.ResponseWriter.Write(b)
+	l.size += size
+	return size, err
+}
+
+func (l *responseLogger) WriteHeader(s int) {
+	l.ResponseWriter.WriteHeader(s)
+	l.status = s
+}
+
+func (l *responseLogger) Status() int {
+	return l.status
+}
+
+func (l *responseLogger) Size() int {
+	return l.size
+}

config.example.json

@@ -28,6 +28,7 @@
 
         "default_handlers": [ {"type": "via", "settings" : {"text": "baba 1.1"}}, { "type" : "cache" }, { "type" : "proxy" }],
         "default_cache_zone": "default",
+        "access_log": "/tmp/access.log",
 
         "virtual_hosts": {
             "localhost": {

config/section_http.go

@@ -17,6 +17,7 @@ type BaseHTTP struct {
 	// Defaults for vhosts:
 	DefaultHandlers  []Handler `json:"default_handlers"`
 	DefaultCacheZone string    `json:"default_cache_zone"`
+	AccessLog        string    `json:"access_log"`
 	Logger           Logger    `json:"logger"`
 }
 

config/section_vhost.go

@@ -21,6 +21,7 @@ type baseVirtualHost struct {
 // VirtualHost contains all configuration options for virtual hosts. It
 // redefines some of the baseLocation fields to use the correct types.
 type VirtualHost struct {
+	AccessLog string `json:"access_log"`
 	baseVirtualHost
 	Location
 	Locations []*Location `json:"locations"`
@@ -118,7 +119,9 @@ func (vh *VirtualHost) GetSubsections() []Section {
 }
 
 func newVHostFromHTTP(h *HTTP) VirtualHost {
-	return VirtualHost{parent: h,
+	return VirtualHost{
+		parent:    h,
+		AccessLog: h.AccessLog,
 		Location: Location{
 			baseLocation: baseLocation{
 				Handlers:  append([]Handler(nil), h.DefaultHandlers...),