proxy: add prefix logger to log remote IP address

proxy/log.go

@@ -1,6 +1,9 @@
 package proxy
 
 import (
+	"fmt"
+	"net"
+
 	"github.com/btcsuite/btclog"
 	"github.com/lightningnetwork/lnd/build"
 )
@@ -27,3 +30,64 @@ func DisableLog() {
 func UseLogger(logger btclog.Logger) {
 	log = logger
 }
+
+// PrefixLog logs with a given static string prefix.
+type PrefixLog struct {
+	logger btclog.Logger
+	prefix string
+}
+
+// NewRemoteIPPrefixLog returns a new prefix logger that logs the remote IP
+// address.
+func NewRemoteIPPrefixLog(logger btclog.Logger, remoteAddr string) (net.IP,
+	*PrefixLog) {
+
+	remoteHost, _, err := net.SplitHostPort(remoteAddr)
+	if err != nil {
+		remoteHost = "0.0.0.0"
+	}
+	remoteIp := net.ParseIP(remoteHost)
+	if remoteIp == nil {
+		remoteIp = net.IPv4zero
+	}
+	return remoteIp, &PrefixLog{
+		logger: logger,
+		prefix: remoteIp.String(),
+	}
+}
+
+// Debugf formats message according to format specifier and writes to
+// log with LevelDebug.
+func (s *PrefixLog) Debugf(format string, params ...interface{}) {
+	s.logger.Debugf(
+		fmt.Sprintf("%s %s", s.prefix, format),
+		params...,
+	)
+}
+
+// Infof formats message according to format specifier and writes to
+// log with LevelInfo.
+func (s *PrefixLog) Infof(format string, params ...interface{}) {
+	s.logger.Infof(
+		fmt.Sprintf("%s %s", s.prefix, format),
+		params...,
+	)
+}
+
+// Warnf formats message according to format specifier and writes to
+// to log with LevelError.
+func (s *PrefixLog) Warnf(format string, params ...interface{}) {
+	s.logger.Warnf(
+		fmt.Sprintf("%s %s", s.prefix, format),
+		params...,
+	)
+}
+
+// Errorf formats message according to format specifier and writes to
+// to log with LevelError.
+func (s *PrefixLog) Errorf(format string, params ...interface{}) {
+	s.logger.Errorf(
+		fmt.Sprintf("%s %s", s.prefix, format),
+		params...,
+	)
+}

proxy/proxy.go

@@ -5,7 +5,6 @@ import (
 	"crypto/x509"
 	"fmt"
 	"io/ioutil"
-	"net"
 	"net/http"
 	"net/http/httputil"
 	"regexp"
@@ -14,7 +13,12 @@ import (
 )
 
 const (
-	formatPattern = "%s - - \"%s %s %s\" \"%s\" \"%s\""
+	// formatPattern is the pattern in which the request log will be
+	// printed. This is loosely oriented on the apache log format.
+	// An example entry would look like this:
+	// 2019-11-09 04:07:55.072 [INF] PRXY: 66.249.69.89 - - 
+	// "GET /availability/v1/btc.json HTTP/1.1" "" "Mozilla/5.0 ..."
+	formatPattern = "- - \"%s %s %s\" \"%s\" \"%s\""
 )
 
 // Proxy is a HTTP, HTTP/2 and gRPC handler that takes an incoming request,
@@ -53,17 +57,10 @@ func New(auth auth.Authenticator, services []*Service, staticRoot string) (
 func (p *Proxy) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 	// Parse and log the remote IP address. We also need the parsed IP
 	// address for the freebie count.
-	remoteHost, _, err := net.SplitHostPort(r.RemoteAddr)
+	remoteIp, prefixLog := NewRemoteIPPrefixLog(log, r.RemoteAddr)
-	if err != nil {
-		remoteHost = "0.0.0.0"
-	}
-	remoteIp := net.ParseIP(remoteHost)
-	if remoteIp == nil {
-		remoteIp = net.IPv4zero
-	}
 	logRequest := func() {
-		log.Infof(formatPattern, remoteIp.String(), r.Method,
+		prefixLog.Infof(formatPattern, r.Method, r.RequestURI, r.Proto,
-			r.RequestURI, r.Proto, r.Referer(), r.UserAgent())
+			r.Referer(), r.UserAgent())
 	}
 	defer logRequest()
 
@@ -81,8 +78,8 @@ func (p *Proxy) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 	// will return a 404 for us.
 	target, ok := matchService(r, p.services)
 	if !ok {
-		log.Debugf("Dispatching request %s to static file server.",
+		prefixLog.Debugf("Dispatching request %s to static file "+
-			r.URL.Path)
+			"server.", r.URL.Path)
 		p.staticServer.ServeHTTP(w, r)
 		return
 	}
@@ -92,6 +89,7 @@ func (p *Proxy) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 	switch {
 	case target.Auth.IsOn():
 		if !p.authenticator.Accept(&r.Header) {
+			prefixLog.Infof("Authentication failed. Sending 402.")
 			p.handlePaymentRequired(w, r)
 			return
 		}
@@ -101,7 +99,8 @@ func (p *Proxy) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 		if !p.authenticator.Accept(&r.Header) {
 			ok, err := target.freebieDb.CanPass(r, remoteIp)
 			if err != nil {
-				log.Errorf("Error querying freebie db: %v", err)
+				prefixLog.Errorf("Error querying freebie db: "+
+					"%v", err)
 				w.WriteHeader(http.StatusInternalServerError)
 				return
 			}
@@ -111,7 +110,8 @@ func (p *Proxy) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 			}
 			_, err = target.freebieDb.TallyFreebie(r, remoteIp)
 			if err != nil {
-				log.Errorf("Error updating freebie db: %v", err)
+				prefixLog.Errorf("Error updating freebie db: "+
+					"%v", err)
 				w.WriteHeader(http.StatusInternalServerError)
 				return
 			}