Logging improvements

* Use structured fields for all log values
* Add Context log function wrappers to auto log function/line

psiphon/server/services.go

@@ -24,7 +24,6 @@ import (
 	"os/signal"
 	"sync"
 
-	log "github.com/Psiphon-Inc/logrus"
 	"github.com/Psiphon-Labs/psiphon-tunnel-core/psiphon"
 )
 
@@ -32,7 +31,7 @@ func RunServices(encodedConfig []byte) error {
 
 	config, err := LoadConfig(encodedConfig)
 	if err != nil {
-		log.Error("RunServices failed: %s", err)
+		log.WithContextFields(LogFields{"error": err}).Error("load config failed")
 		return psiphon.ContextError(err)
 	}
 
@@ -72,9 +71,9 @@ func RunServices(encodedConfig []byte) error {
 
 	select {
 	case <-systemStopSignal:
-		log.Info("RunServices shutdown by system")
+		log.WithContext().Info("shutdown by system")
 	case err = <-errors:
-		log.Error("RunServices failed: %s", err)
+		log.WithContextFields(LogFields{"error": err}).Error("service failed")
 	}
 
 	close(shutdownBroadcast)

psiphon/server/sshService.go

@@ -26,7 +26,6 @@ import (
 	"net"
 	"sync"
 
-	log "github.com/Psiphon-Inc/logrus"
 	"github.com/Psiphon-Labs/psiphon-tunnel-core/psiphon"
 	"golang.org/x/crypto/ssh"
 )
@@ -71,7 +70,7 @@ func RunSSHServer(config *Config, shutdownBroadcast <-chan struct{}) error {
 		return psiphon.ContextError(err)
 	}
 
-	log.Info("RunSSH: starting server")
+	log.WithContext().Info("starting")
 
 	err = nil
 	errors := make(chan error)
@@ -93,7 +92,7 @@ func RunSSHServer(config *Config, shutdownBroadcast <-chan struct{}) error {
 
 			if err != nil {
 				if e, ok := err.(net.Error); ok && e.Temporary() {
-					log.Warning("RunSSH accept error: %s", err)
+					log.WithContextFields(LogFields{"error": err}).Error("accept failed")
 					// Temporary error, keep running
 					continue
 				}
@@ -112,7 +111,7 @@ func RunSSHServer(config *Config, shutdownBroadcast <-chan struct{}) error {
 
 		sshServer.stopClients()
 
-		log.Info("RunSSH: server stopped")
+		log.WithContext().Info("stopped")
 	}()
 
 	select {
@@ -124,7 +123,7 @@ func RunSSHServer(config *Config, shutdownBroadcast <-chan struct{}) error {
 
 	waitGroup.Wait()
 
-	log.Info("RunSSH: exiting")
+	log.WithContext().Info("exiting")
 
 	return err
 }
@@ -149,9 +148,9 @@ func (sshServer *sshServer) passwordCallback(conn ssh.ConnMetadata, password []b
 
 func (sshServer *sshServer) authLogCallback(conn ssh.ConnMetadata, method string, err error) {
 	if err != nil {
-		log.Warning("ssh: %s authentication failed %s", method, err)
+		log.WithContextFields(LogFields{"error": err, "method": method}).Warning("authentication failed")
 	} else {
-		log.Info("ssh: %s authentication success %s", method)
+		log.WithContextFields(LogFields{"error": err, "method": method}).Info("authentication success")
 	}
 }
 
@@ -163,7 +162,7 @@ func (sshServer *sshServer) registerClient(sshConn ssh.Conn) bool {
 	}
 	existingSshConn := sshServer.clients[string(sshConn.SessionID())]
 	if existingSshConn != nil {
-		log.Warning("sshServer.registerClient: unexpected existing connection")
+		log.WithContext().Warning("unexpected existing connection")
 		existingSshConn.Close()
 		existingSshConn.Wait()
 	}
@@ -197,19 +196,19 @@ func (sshServer *sshServer) handleClient(conn net.Conn) {
 	sshConn, channels, requests, err := ssh.NewServerConn(conn, sshServer.sshConfig)
 	if err != nil {
 		conn.Close()
-		log.Error("sshServer.handleClient: ssh establish connection failed: %s", err)
+		log.WithContextFields(LogFields{"error": err}).Warning("establish failed")
 		return
 	}
 
 	if !sshServer.registerClient(sshConn) {
 		sshConn.Close()
-		log.Error("sshServer.handleClient: failed to register client")
+		log.WithContext().Warning("register failed")
 		return
 	}
 	defer sshServer.unregisterClient(sshConn)
 
 	// TODO: don't record IP; do GeoIP
-	log.Info("connection from %s", sshConn.RemoteAddr())
+	log.WithContextFields(LogFields{"remoteAddr": sshConn.RemoteAddr()}).Warning("connection accepted")
 
 	go ssh.DiscardRequests(requests)
 
@@ -227,7 +226,12 @@ func (sshServer *sshServer) handleClient(conn net.Conn) {
 
 func (sshServer *sshServer) rejectNewChannel(newChannel ssh.NewChannel, reason ssh.RejectionReason, message string) {
 	// TODO: log more details?
-	log.Warning("ssh reject new channel: %s: %d: %s", newChannel.ChannelType(), reason, message)
+	log.WithContextFields(
+		LogFields{
+			"channelType":   newChannel.ChannelType(),
+			"rejectMessage": message,
+			"rejectReason":  reason,
+		}).Warning("reject new channel")
 	newChannel.Reject(reason, message)
 }
 
@@ -251,7 +255,7 @@ func (sshServer *sshServer) handleNewDirectTcpipChannel(newChannel ssh.NewChanne
 		directTcpipExtraData.HostToConnect,
 		directTcpipExtraData.PortToConnect)
 
-	log.Debug("sshServer.handleNewDirectTcpipChannel: dialing %s", targetAddr)
+	log.WithContextFields(LogFields{"target": targetAddr}).Debug("dialing")
 
 	// TODO: port forward dial timeout
 	// TODO: report ssh.ResourceShortage when appropriate
@@ -264,11 +268,11 @@ func (sshServer *sshServer) handleNewDirectTcpipChannel(newChannel ssh.NewChanne
 
 	fwdChannel, requests, err := newChannel.Accept()
 	if err != nil {
-		log.Warning("sshServer.handleNewDirectTcpipChannel: accept new channel failed: %s", err)
+		log.WithContextFields(LogFields{"error": err}).Warning("accept new channel failed")
 		return
 	}
 
-	log.Debug("sshServer.handleNewDirectTcpipChannel: relaying %s", targetAddr)
+	log.WithContextFields(LogFields{"target": targetAddr}).Debug("relaying")
 
 	go ssh.DiscardRequests(requests)
 
@@ -285,15 +289,15 @@ func (sshServer *sshServer) handleNewDirectTcpipChannel(newChannel ssh.NewChanne
 		defer relayWaitGroup.Done()
 		_, err := io.Copy(fwdConn, fwdChannel)
 		if err != nil {
-			log.Warning("sshServer.handleNewDirectTcpipChannel: upstream relay failed: %s", err)
+			log.WithContextFields(LogFields{"error": err}).Warning("upstream relay failed")
 		}
 	}()
 	_, err = io.Copy(fwdChannel, fwdConn)
 	if err != nil {
-		log.Warning("sshServer.handleNewDirectTcpipChannel: downstream relay failed: %s", err)
+		log.WithContextFields(LogFields{"error": err}).Warning("downstream relay failed")
 	}
 	fwdChannel.CloseWrite()
 	relayWaitGroup.Wait()
 
-	log.Info("sshServer.handleNewDirectTcpipChannel: exiting %s", targetAddr)
+	log.WithContextFields(LogFields{"target": targetAddr}).Debug("exiting")
 }

psiphon/server/webService.go

@@ -30,7 +30,6 @@ import (
 	"net/http"
 	"sync"
 
-	log "github.com/Psiphon-Inc/logrus"
 	"github.com/Psiphon-Labs/psiphon-tunnel-core/psiphon"
 )
 
@@ -61,8 +60,8 @@ func RunWebServer(config *Config, shutdownBroadcast <-chan struct{}) error {
 		Certificates: []tls.Certificate{certificate},
 	}
 
-	// TODO: inherit global log config?
-	logWriter := log.StandardLogger().Writer()
+	// TODO: inherits global log config?
+	logWriter := NewLogWriter()
 	defer logWriter.Close()
 
 	server := &psiphon.HTTPSServer{
@@ -81,7 +80,7 @@ func RunWebServer(config *Config, shutdownBroadcast <-chan struct{}) error {
 		return psiphon.ContextError(err)
 	}
 
-	log.Info("RunWebServer: starting server")
+	log.WithContext().Info("starting")
 
 	err = nil
 	errors := make(chan error)
@@ -108,7 +107,7 @@ func RunWebServer(config *Config, shutdownBroadcast <-chan struct{}) error {
 			}
 		}
 
-		log.Info("RunWebServer: server stopped")
+		log.WithContext().Info("stopped")
 	}()
 
 	select {
@@ -120,7 +119,7 @@ func RunWebServer(config *Config, shutdownBroadcast <-chan struct{}) error {
 
 	waitGroup.Wait()
 
-	log.Info("RunWebServer: exiting")
+	log.WithContext().Info("exiting")
 
 	return err
 }
@@ -135,14 +134,14 @@ func (webServer *webServer) handshakeHandler(w http.ResponseWriter, r *http.Requ
 
 	if !webServer.checkWebServerSecret(r) {
 		// TODO: log more details?
-		log.Warning("handshakeHandler: checkWebServerSecret failed")
+		log.WithContext().Warning("checkWebServerSecret failed")
 		// TODO: psi_web returns NotFound in this case
 		w.WriteHeader(http.StatusForbidden)
 		return
 	}
 
 	// TODO: validate; proper log
-	log.Info("handshake: %+v", r.URL.Query())
+	log.WithContextFields(LogFields{"queryParams": r.URL.Query()}).Info("handshake")
 
 	// TODO: necessary, in case client sends bogus request body?
 	_, err := ioutil.ReadAll(r.Body)
@@ -182,14 +181,14 @@ func (webServer *webServer) connectedHandler(w http.ResponseWriter, r *http.Requ
 
 	if !webServer.checkWebServerSecret(r) {
 		// TODO: log more details?
-		log.Warning("handshakeHandler: checkWebServerSecret failed")
+		log.WithContext().Warning("checkWebServerSecret failed")
 		// TODO: psi_web does NotFound in this case
 		w.WriteHeader(http.StatusForbidden)
 		return
 	}
 
 	// TODO: validate; proper log
-	log.Info("connected: %+v", r.URL.Query())
+	log.WithContextFields(LogFields{"queryParams": r.URL.Query()}).Info("connected")
 
 	// TODO: necessary, in case client sends bogus request body?
 	_, err := ioutil.ReadAll(r.Body)
@@ -219,14 +218,14 @@ func (webServer *webServer) statusHandler(w http.ResponseWriter, r *http.Request
 
 	if !webServer.checkWebServerSecret(r) {
 		// TODO: log more details?
-		log.Warning("handshakeHandler: checkWebServerSecret failed")
+		log.WithContext().Warning("checkWebServerSecret failed")
 		// TODO: psi_web does NotFound in this case
 		w.WriteHeader(http.StatusForbidden)
 		return
 	}
 
 	// TODO: validate; proper log
-	log.Info("status: %+v", r.URL.Query())
+	log.WithContextFields(LogFields{"queryParams": r.URL.Query()}).Info("status")
 
 	// TODO: use json.NewDecoder(r.Body)? But will that handle bogus extra data in request body?
 	requestBody, err := ioutil.ReadAll(r.Body)
@@ -236,7 +235,7 @@ func (webServer *webServer) statusHandler(w http.ResponseWriter, r *http.Request
 	}
 
 	// TODO: parse payload; validate; proper logs
-	log.Info("status payload: %s", string(requestBody))
+	log.WithContextFields(LogFields{"payload": string(requestBody)}).Info("status payload")
 
 	w.WriteHeader(http.StatusOK)
 }

psiphon/utils.go

@@ -202,18 +202,33 @@ func TrimError(err error) error {
 	return err
 }
 
-// ContextError prefixes an error message with the current function name
-func ContextError(err error) error {
-	if err == nil {
-		return nil
-	}
-	pc, _, line, _ := runtime.Caller(1)
+// getFunctionName is a helper that extracts a simple function name from
+// full name returned byruntime.Func.Name(). This is used to declutter
+// log messages containing function names.
+func getFunctionName(pc uintptr) string {
 	funcName := runtime.FuncForPC(pc).Name()
 	index := strings.LastIndex(funcName, "/")
 	if index != -1 {
 		funcName = funcName[index+1:]
 	}
-	return fmt.Errorf("%s#%d: %s", funcName, line, err)
+	return funcName
+}
+
+// GetParentContext returns the parent function name and source file
+// line number.
+func GetParentContext() string {
+	pc, _, line, _ := runtime.Caller(2)
+	return fmt.Sprintf("%s#%d", getFunctionName(pc), line)
+}
+
+// ContextError prefixes an error message with the current function
+// name and source file line number.
+func ContextError(err error) error {
+	if err == nil {
+		return nil
+	}
+	pc, _, line, _ := runtime.Caller(1)
+	return fmt.Errorf("%s#%d: %s", getFunctionName(pc), line, err)
 }
 
 // IsAddressInUseError returns true when the err is due to EADDRINUSE/WSAEADDRINUSE.