Support logging requests

Resolves #6.
10 months ago · 7820dd9723
10 changed files with 174 additions and 148 deletions
--- a/CONFIGURATION.md
+++ b/CONFIGURATION.md
@ -106,6 +106,11 @@ Cache duration (in seconds). Set to `0` to disable caching entirely. This is an
 out-of-spec feature. See [PROPOSALS.md](https://gitlab.com/tslocum/twins/blob/master/PROPOSALS.md)
 for more information.

+##### Log
+
+Path to log file. Requests are logged in [Apache format](https://httpd.apache.org/docs/2.2/logs.html#combined),
+excluding IP address and query.
+
 ##### SymLinks

 When enabled, symbolic links may be accessed. This attribute is disabled by default.
@ -169,6 +174,7 @@ hosts:
  default: # Default host configuration
    paths: # Default path attributes
      -
+        log: /srv/log/gemini.log
        symlinks: true # Follow symbolic links
  gemini.rocks:
    cert: /srv/gemini.rocks/data/cert.crt
--- a/config.go
+++ b/config.go
@ -49,6 +49,9 @@ type pathConfig struct {
 	// FastCGI server address
 	FastCGI string

+	// Log file
+	Log string
+
 	r     *regexp.Regexp
 	cmd   []string
 	cache int64
@ -162,6 +165,9 @@ func readconfig(configPath string) error {
 					if defaultPath.FastCGI != "" && serve.FastCGI == "" {
 						serve.FastCGI = defaultPath.FastCGI
 					}
+					if defaultPath.Log != "" && serve.Log == "" {
+						serve.Log = defaultPath.Log
+					}
 				}
 			} else if len(defaultHost.Paths) > 1 {
 				log.Fatal("only one path may be defined for the default host")
--- a/go.mod
+++ b/go.mod
@ -6,6 +6,6 @@ require (
 	github.com/h2non/filetype v1.1.0
 	github.com/kballard/go-shellquote v0.0.0-20180428030007-95032a82bc51
 	github.com/yookoala/gofast v0.4.1-0.20201013050739-975113c54107
-	golang.org/x/tools v0.0.0-20201110030525-169ad6d6ecb2 // indirect
+	golang.org/x/tools v0.0.0-20201112171726-b38955972a18 // indirect
 	gopkg.in/yaml.v3 v3.0.0-20200615113413-eeeca48fe776
 )
--- a/go.sum
+++ b/go.sum
@ -34,8 +34,8 @@ golang.org/x/tools v0.0.0-20180917221912-90fa682c2a6e/go.mod h1:n7NCudcB/nEzxVGm
 golang.org/x/tools v0.0.0-20190328211700-ab21143f2384/go.mod h1:LCzVGOaR6xXOjkQ3onu1FJEFr0SW1gC7cKk1uF8kGRs=
 golang.org/x/tools v0.0.0-20191119224855-298f0cb1881e/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo=
 golang.org/x/tools v0.0.0-20200908211811-12e1bf57a112/go.mod h1:Cj7w3i3Rnn0Xh82ur9kSqwfTHTeVxaDqrfMjpcNT6bE=
-golang.org/x/tools v0.0.0-20201110030525-169ad6d6ecb2 h1:5GmCe1Mc5HsGGl6E0kOVQRzVp+AgZf4Ffw4DadiVpd4=
-golang.org/x/tools v0.0.0-20201110030525-169ad6d6ecb2/go.mod h1:emZCQorbCU4vsT4fOWvOPXz4eW1wZW4PmDk9uLelYpA=
+golang.org/x/tools v0.0.0-20201112171726-b38955972a18 h1:zCVX0Qx6zEiwi5lM2jprfSFA6i6GWMXmY8o0VxPyCfo=
+golang.org/x/tools v0.0.0-20201112171726-b38955972a18/go.mod h1:emZCQorbCU4vsT4fOWvOPXz4eW1wZW4PmDk9uLelYpA=
 golang.org/x/xerrors v0.0.0-20190717185122-a985d3407aa7/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=
 golang.org/x/xerrors v0.0.0-20191011141410-1b5146add898/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=
 golang.org/x/xerrors v0.0.0-20200804184101-5ec99f83aff1/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=
--- a/main.go
+++ b/main.go
@ -16,6 +16,8 @@ func init() {
 var verbose bool

 func main() {
+	log.SetFlags(0)
+
 	configFile := flag.String("config", "", "path to configuration file")
 	flag.BoolVar(&verbose, "verbose", false, "print request and response information")
 	flag.Parse()
@ -45,7 +47,5 @@ func main() {
 		log.Fatalf("failed to read configuration file at %s: %v\nSee CONFIGURATION.md for information on configuring twins", *configFile, err)
 	}

-	log.Printf("twins running on %s:%d", config.hostname, config.port)
-
 	listen(config.Listen)
 }
--- a/serve_command.go
+++ b/serve_command.go
@ -2,14 +2,13 @@ package main

 import (
 	"bytes"
-	"log"
 	"net"
 	"net/url"
 	"os/exec"
 	"strings"
 )

-func serveCommand(c net.Conn, serve *pathConfig, request *url.URL, command []string) {
+func serveCommand(c net.Conn, serve *pathConfig, request *url.URL, command []string) (int, int64) {
 	var args []string
 	if len(command) > 0 {
 		args = command[1:]
@ -20,8 +19,7 @@ func serveCommand(c net.Conn, serve *pathConfig, request *url.URL, command []str
 	if request.RawQuery != "" {
 		requestQuery, err := url.QueryUnescape(request.RawQuery)
 		if err != nil {
-			writeStatus(c, statusBadRequest)
-			return
+			return writeStatus(c, statusBadRequest), -1
 		}
 		cmd.Stdin = strings.NewReader(requestQuery + "\n")
 	}
@ -30,14 +28,11 @@ func serveCommand(c net.Conn, serve *pathConfig, request *url.URL, command []str

 	err := cmd.Run()
 	if err != nil {
-		writeStatus(c, statusProxyError)
-		return
+		return writeStatus(c, statusProxyError), -1
 	}

 	writeSuccess(c, serve, geminiType, int64(buf.Len()))
 	c.Write(buf.Bytes())

-	if verbose {
-		log.Printf("< %s\n", command)
-	}
+	return statusSuccess, int64(buf.Len())
 }
--- a/serve_fcgi.go
+++ b/serve_fcgi.go
@ -4,7 +4,6 @@ import (
 	"bytes"
 	"io"
 	"io/ioutil"
-	"log"
 	"net"
 	"net/http"
 	"net/url"
@ -55,8 +54,4 @@ func serveFastCGI(c net.Conn, connFactory gofast.ConnFactory, u *url.URL, filePa
 			gofast.SimpleClientFactory(connFactory, 0),
 		).
 		ServeHTTP(newResponseWriter(c), r)
-
-	if verbose {
-		log.Printf("< exec %s\n", filePath)
-	}
 }
--- a/serve_file.go
+++ b/serve_file.go
@ -13,7 +13,7 @@ import (
 	"github.com/h2non/filetype"
 )

-func serveDirList(c net.Conn, serve *pathConfig, request *url.URL, dirPath string) {
+func serveDirList(c net.Conn, serve *pathConfig, request *url.URL, dirPath string) int {
 	var (
 		files    []os.FileInfo
 		numDirs  int
@ -37,8 +37,7 @@ func serveDirList(c net.Conn, serve *pathConfig, request *url.URL, dirPath strin
 		return nil
 	})
 	if err != nil {
-		writeStatus(c, statusTemporaryFailure)
-		return
+		return writeStatus(c, statusTemporaryFailure)
 	}
 	// List directories first
 	sort.Slice(files, func(i, j int) bool {
@ -91,6 +90,7 @@ func serveDirList(c net.Conn, serve *pathConfig, request *url.URL, dirPath strin
 		}
 		c.Write([]byte(modified + " - " + formatFileSize(info.Size()) + newLine + newLine))
 	}
+	return statusSuccess
 }

 func serveFile(c net.Conn, serve *pathConfig, filePath string) {
--- a/serve_proxy.go
+++ b/serve_proxy.go
@ -3,15 +3,12 @@ package main
 import (
 	"crypto/tls"
 	"io"
-	"log"
 	"net"
 	"net/url"
 	"strings"
 )

-func serveProxy(c net.Conn, request *url.URL, proxyURL string) {
-	original := proxyURL
-
+func serveProxy(c net.Conn, request *url.URL, proxyURL string) int {
 	tlsConfig := &tls.Config{}
 	if strings.HasPrefix(proxyURL, "gemini://") {
 		proxyURL = proxyURL[9:]
@ -21,8 +18,7 @@ func serveProxy(c net.Conn, request *url.URL, proxyURL string) {
 	}
 	proxy, err := tls.Dial("tcp", proxyURL, tlsConfig)
 	if err != nil {
-		writeStatus(c, statusProxyError)
-		return
+		return writeStatus(c, statusProxyError)
 	}
 	defer proxy.Close()

@ -33,7 +29,5 @@ func serveProxy(c net.Conn, request *url.URL, proxyURL string) {
 	// Forward response
 	io.Copy(c, proxy)

-	if verbose {
-		log.Printf("< %s\n", original)
-	}
+	return statusSuccess
 }
--- a/server.go
+++ b/server.go
@ -14,6 +14,7 @@ import (
 	"regexp"
 	"strconv"
 	"strings"
+	"sync"
 	"time"
 	"unicode/utf8"
 )
@ -51,15 +52,14 @@ var slashesRegexp = regexp.MustCompile(`[^\\]\/`)

 var newLine = "\r\n"

-func writeHeader(c net.Conn, code int, meta string) {
-	fmt.Fprintf(c, "%d %s%s", code, meta, newLine)
+var logLock sync.Mutex

-	if verbose {
-		log.Printf("< %d %s\n", code, meta)
-	}
+func writeHeader(c net.Conn, code int, meta string) int {
+	fmt.Fprintf(c, "%d %s%s", code, meta, newLine)
+	return code
 }

-func writeStatus(c net.Conn, code int) {
+func writeStatus(c net.Conn, code int) int {
 	var meta string
 	switch code {
 	case statusTemporaryFailure:
@ -74,9 +74,10 @@ func writeStatus(c net.Conn, code int) {
 		meta = "Proxy request refused"
 	}
 	writeHeader(c, code, meta)
+	return code
 }

-func writeSuccess(c net.Conn, serve *pathConfig, contentType string, size int64) {
+func writeSuccess(c net.Conn, serve *pathConfig, contentType string, size int64) int {
 	meta := contentType
 	if serve.Type != "" {
 		meta = serve.Type
@ -91,6 +92,7 @@ func writeSuccess(c net.Conn, serve *pathConfig, contentType string, size int64)
 	}

 	writeHeader(c, statusSuccess, meta)
+	return statusSuccess
 }

 func scanCRLF(data []byte, atEOF bool) (advance int, token []byte, err error) {
@ -123,7 +125,7 @@ func replaceWithUserInput(command []string, request *url.URL) []string {
 	return newCommand
 }

-func servePath(c *tls.Conn, request *url.URL, serve *pathConfig) {
+func servePath(c *tls.Conn, request *url.URL, serve *pathConfig) (int, int64) {
 	resolvedPath := request.Path
 	requestSplit := strings.Split(request.Path, "/")
 	pathSlashes := len(slashesRegexp.FindAllStringIndex(serve.Path, -1))
@ -142,8 +144,7 @@ func servePath(c *tls.Conn, request *url.URL, serve *pathConfig) {
 	if !serve.HiddenFiles {
 		for _, piece := range requestSplit {
 			if len(piece) > 0 && piece[0] == '.' {
-				writeStatus(c, statusTemporaryFailure)
-				return
+				return writeStatus(c, statusTemporaryFailure), -1
 			}
 		}
 	}
@ -159,8 +160,7 @@ func servePath(c *tls.Conn, request *url.URL, serve *pathConfig) {
 			for i := range requestSplit[pathSlashes:] {
 				info, err := os.Lstat(path.Join(root, strings.Join(requestSplit[pathSlashes:pathSlashes+i+1], "/")))
 				if err != nil || info.Mode()&os.ModeSymlink == os.ModeSymlink {
-					writeStatus(c, statusTemporaryFailure)
-					return
+					return writeStatus(c, statusTemporaryFailure), -1
 				}
 			}
 		}
@ -169,12 +169,10 @@ func servePath(c *tls.Conn, request *url.URL, serve *pathConfig) {
 	}

 	if serve.Proxy != "" {
-		serveProxy(c, request, serve.Proxy)
-		return
+		return serveProxy(c, request, serve.Proxy), -1
 	} else if serve.FastCGI != "" {
 		if filePath == "" {
-			writeStatus(c, statusNotFound)
-			return
+			return writeStatus(c, statusNotFound), -1
 		}

 		contentType := geminiType
@ -184,37 +182,32 @@ func servePath(c *tls.Conn, request *url.URL, serve *pathConfig) {
 		writeSuccess(c, serve, contentType, -1)

 		serveFastCGI(c, config.fcgiPools[serve.FastCGI], request, filePath)
-		return
+		return statusSuccess, -1
 	} else if serve.cmd != nil {
 		requireInput := serve.Input != "" || serve.SensitiveInput != ""
 		if requireInput {
 			newCommand := replaceWithUserInput(serve.cmd, request)
 			if newCommand != nil {
-				serveCommand(c, serve, request, newCommand)
-				return
+				return serveCommand(c, serve, request, newCommand)
 			}
 		}
-		serveCommand(c, serve, request, serve.cmd)
-		return
+		return serveCommand(c, serve, request, serve.cmd)
 	}

 	if filePath == "" {
-		writeStatus(c, statusNotFound)
-		return
+		return writeStatus(c, statusNotFound), -1
 	}

 	fi, err := os.Stat(filePath)
 	if err != nil {
-		writeStatus(c, statusNotFound)
-		return
+		return writeStatus(c, statusNotFound), -1
 	}

 	mode := fi.Mode()
 	hasTrailingSlash := len(request.Path) > 0 && request.Path[len(request.Path)-1] == '/'
 	if mode.IsDir() {
 		if !hasTrailingSlash {
-			writeHeader(c, statusRedirectPermanent, request.String()+"/")
-			return
+			return writeHeader(c, statusRedirectPermanent, request.String()+"/"), -1
 		}

 		_, err := os.Stat(path.Join(filePath, "index.gmi"))
@ -222,11 +215,9 @@ func servePath(c *tls.Conn, request *url.URL, serve *pathConfig) {
 			_, err := os.Stat(path.Join(filePath, "index.gemini"))
 			if err != nil {
 				if serve.ListDirectory {
-					serveDirList(c, serve, request, filePath)
-					return
+					return serveDirList(c, serve, request, filePath), -1
 				}
-				writeStatus(c, statusNotFound)
-				return
+				return writeStatus(c, statusNotFound), -1
 			}
 			filePath = path.Join(filePath, "index.gemini")
 		} else {
@ -234,14 +225,105 @@ func servePath(c *tls.Conn, request *url.URL, serve *pathConfig) {
 		}
 	} else if hasTrailingSlash && len(request.Path) > 1 {
 		r := request.String()
-		writeHeader(c, statusRedirectPermanent, r[:len(r)-1])
-		return
+		return writeHeader(c, statusRedirectPermanent, r[:len(r)-1]), -1
 	}

 	serveFile(c, serve, filePath)
+	return statusSuccess, fi.Size()
+}
+
+func handleRequest(c *tls.Conn, request *url.URL, requestData string) (int, int64, string) {
+	if request.Path == "" {
+		// Redirect to /
+		return writeHeader(c, statusRedirectPermanent, requestData+"/"), -1, ""
+	}
+
+	pathBytes := []byte(request.Path)
+	strippedPath := request.Path
+	if strippedPath[0] == '/' {
+		strippedPath = strippedPath[1:]
+	}
+
+	var matchedHost bool
+	requestHostname := request.Hostname()
+	for hostname := range config.Hosts {
+		if requestHostname != hostname {
+			continue
+		}
+		matchedHost = true
+
+		for _, serve := range config.Hosts[hostname].Paths {
+			matchedRegexp := serve.r != nil && serve.r.Match(pathBytes)
+			matchedPrefix := serve.r == nil && strings.HasPrefix(request.Path, serve.Path)
+			if !matchedRegexp && !matchedPrefix {
+				continue
+			}
+
+			requireInput := serve.Input != "" || serve.SensitiveInput != ""
+			if request.RawQuery == "" && requireInput {
+				if serve.Input != "" {
+					return writeHeader(c, statusInput, serve.Input), -1, ""
+				} else if serve.SensitiveInput != "" {
+					return writeHeader(c, statusSensitiveInput, serve.SensitiveInput), -1, ""
+				}
+			}
+
+			if matchedRegexp || matchedPrefix {
+				status, size := servePath(c, request, serve)
+				return status, size, serve.Log
+			}
+		}
+		break
+	}
+
+	if matchedHost {
+		return writeStatus(c, statusNotFound), -1, ""
+	}
+	return writeStatus(c, statusProxyRequestRefused), -1, ""
 }

-func serveConn(c *tls.Conn) {
+func handleConn(c *tls.Conn) {
+	t := time.Now()
+	var request *url.URL
+	var logPath string
+	status := 0
+	size := int64(-1)
+
+	defer func() {
+		if !verbose && logPath == "" {
+			return
+		}
+
+		entry := logEntry(request, status, size, time.Since(t))
+
+		if verbose {
+			log.Println(string(entry))
+		}
+
+		if logPath == "" {
+			return
+		}
+
+		logLock.Lock()
+		defer logLock.Unlock()
+
+		f, err := os.OpenFile(logPath, os.O_APPEND|os.O_WRONLY|os.O_CREATE, 0600)
+		if err != nil {
+			log.Printf("ERROR: Failed to open log file at %s: %s", logPath, err)
+			return
+		}
+		defer f.Close()
+
+		if _, err = f.Write(entry); err != nil {
+			log.Printf("ERROR: Failed to write to log file at %s: %s", logPath, err)
+			return
+		}
+		f.Write([]byte("\n"))
+	}()
+
+	defer c.Close()
+	c.SetReadDeadline(time.Now().Add(readTimeout))
+
 	var requestData string
 	scanner := bufio.NewScanner(c)
 	if !config.SaneEOL {
@ -251,7 +333,7 @@ func serveConn(c *tls.Conn) {
 		requestData = scanner.Text()
 	}
 	if err := scanner.Err(); err != nil {
-		writeStatus(c, statusBadRequest)
+		status = writeStatus(c, statusBadRequest)
 		return
 	}

@ -266,24 +348,21 @@ func serveConn(c *tls.Conn) {
 		clientCertKeys = append(clientCertKeys, pubKey)
 	}

-	if verbose {
-		log.Printf("> %s\n", requestData)
-	}
-
 	if len(requestData) > urlMaxLength || !utf8.ValidString(requestData) {
-		writeStatus(c, statusBadRequest)
+		status = writeStatus(c, statusBadRequest)
 		return
 	}

-	request, err := url.Parse(requestData)
+	var err error
+	request, err = url.Parse(requestData)
 	if err != nil {
-		writeStatus(c, statusBadRequest)
+		status = writeStatus(c, statusBadRequest)
 		return
 	}

 	requestHostname := request.Hostname()
 	if requestHostname == "" || strings.ContainsRune(requestHostname, ' ') {
-		writeStatus(c, statusBadRequest)
+		status = writeStatus(c, statusBadRequest)
 		return
 	}

@ -299,79 +378,41 @@ func serveConn(c *tls.Conn) {
 		request.Scheme = "gemini"
 	}
 	if request.Scheme != "gemini" || (requestPort > 0 && requestPort != config.port) {
-		writeStatus(c, statusProxyRequestRefused)
-	}
-
-	if request.Path == "" {
-		// Redirect to /
-		writeHeader(c, statusRedirectPermanent, requestData+"/")
+		status = writeStatus(c, statusProxyRequestRefused)
 		return
 	}

-	pathBytes := []byte(request.Path)
-	strippedPath := request.Path
-	if strippedPath[0] == '/' {
-		strippedPath = strippedPath[1:]
-	}
-
-	var matchedHost bool
-	for hostname := range config.Hosts {
-		if requestHostname != hostname {
-			continue
-		}
-		matchedHost = true
-
-		for _, serve := range config.Hosts[hostname].Paths {
-			matchedRegexp := serve.r != nil && serve.r.Match(pathBytes)
-			matchedPrefix := serve.r == nil && strings.HasPrefix(request.Path, serve.Path)
-			if !matchedRegexp && !matchedPrefix {
-				continue
-			}
-
-			requireInput := serve.Input != "" || serve.SensitiveInput != ""
-			if request.RawQuery == "" && requireInput {
-				if serve.Input != "" {
-					writeHeader(c, statusInput, serve.Input)
-					return
-				} else if serve.SensitiveInput != "" {
-					writeHeader(c, statusSensitiveInput, serve.SensitiveInput)
-					return
-				}
-			}
+	status, size, logPath = handleRequest(c, request, requestData)
+}

-			if matchedRegexp || matchedPrefix {
-				servePath(c, request, serve)
-				return
-			}
+func logEntry(request *url.URL, status int, size int64, elapsed time.Duration) []byte {
+	hostFormatted := "-"
+	if request.Hostname() != "" {
+		hostFormatted = request.Hostname()
+		if request.Port() != "" {
+			hostFormatted += ":" + request.Port()
+		} else {
+			hostFormatted += ":1965"
 		}
-		break
 	}
-
-	if matchedHost {
-		writeStatus(c, statusNotFound)
-	} else {
-		writeStatus(c, statusProxyRequestRefused)
+	timeFormatted := time.Now().Format("02/Jan/2006 03:04:05")
+	sizeFormatted := "-"
+	if size >= 0 {
+		sizeFormatted = strconv.FormatInt(size, 10)
 	}
-}

-func handleConn(c *tls.Conn) {
-	if verbose {
-		t := time.Now()
-		defer func() {
-			d := time.Since(t)
-			if d > time.Second {
-				d = d.Round(time.Second)
-			} else {
-				d = d.Round(time.Millisecond)
-			}
-			log.Printf("took %s", d)
-		}()
-	}
+	return []byte(fmt.Sprintf(`%s - - - [%s] "GET %s Gemini" %d %s %.4f`, hostFormatted, timeFormatted, request.Path, status, sizeFormatted, elapsed.Seconds()))
+}

-	defer c.Close()
-	c.SetReadDeadline(time.Now().Add(readTimeout))
+func handleListener(l net.Listener) {
+	for {
+		conn, err := l.Accept()
+		if err != nil {
+			log.Fatal(err)
+		}

-	serveConn(c)
+		go handleConn(conn.(*tls.Conn))
+	}
 }

 func getCertificate(info *tls.ClientHelloInfo) (*tls.Certificate, error) {
@ -385,17 +426,6 @@ func getCertificate(info *tls.ClientHelloInfo) (*tls.Certificate, error) {
 	return nil, nil
 }

-func handleListener(l net.Listener) {
-	for {
-		conn, err := l.Accept()
-		if err != nil {
-			log.Fatal(err)
-		}
-
-		go handleConn(conn.(*tls.Conn))
-	}
-}
-
 func listen(address string) {
 	tlsConfig := &tls.Config{
 		ClientAuth:     tls.RequestClientCert,