feat: also log http requests and responses in irma libraries

internal/servercore/api.go

@@ -287,6 +287,27 @@ func (s *Server) HandleProtocolMessage(
 	method string,
 	headers map[string][]string,
 	message []byte,
+) (int, []byte, *server.SessionResult) {
+	var start time.Time
+	if s.conf.Verbose >= 2 {
+		start = time.Now()
+		server.LogRequest(method, path, "", "", http.Header(headers))
+	}
+
+	status, output, result := s.handleProtocolMessage(path, method, headers, message)
+
+	if s.conf.Verbose >= 2 {
+		server.LogResponse(status, time.Now().Sub(start), output)
+	}
+
+	return status, output, result
+}
+
+func (s *Server) handleProtocolMessage(
+	path string,
+	method string,
+	headers map[string][]string,
+	message []byte,
 ) (status int, output []byte, result *server.SessionResult) {
 	// Parse path into session and action
 	if len(path) > 0 { // Remove any starting and trailing slash

server/api.go

@@ -12,6 +12,7 @@ import (
 	"runtime"
 	"runtime/debug"
 	"strings"
+	"time"
 
 	"github.com/go-errors/errors"
 	"github.com/privacybydesign/gabi"
@@ -397,6 +398,29 @@ func LogWarning(err error) error {
 	return log(logrus.WarnLevel, err)
 }
 
+func LogRequest(method string, uri, proto, recipient string, headers http.Header) {
+	fields := logrus.Fields{
+		"method":  method,
+		"uri":     uri,
+		"headers": ToJson(headers),
+	}
+	if proto != "" {
+		fields["proto"] = proto
+	}
+	if recipient != "" {
+		fields["recipient"] = recipient
+	}
+	Logger.WithFields(fields).Tracef("=> request")
+}
+
+func LogResponse(status int, duration time.Duration, response []byte) {
+	Logger.WithFields(logrus.Fields{
+		"status":   status,
+		"duration": duration.String(),
+		"response": string(response),
+	}).Tracef("<= response")
+}
+
 func ToJson(o interface{}) string {
 	bts, _ := json.Marshal(o)
 	return string(bts)

server/requestorserver/server.go

@@ -179,7 +179,9 @@ func (s *Server) ClientHandler() http.Handler {
 func (s *Server) Handler() http.Handler {
 	router := chi.NewRouter()
 	router.Use(cors.New(corsOptions).Handler)
-	router.Use(s.logHandler)
+	if s.conf.Verbose >= 2 {
+		router.Use(s.logHandler)
+	}
 
 	if !s.conf.separateClientServer() {
 		// Mount server for irmaclient
@@ -205,37 +207,31 @@ func (s *Server) Handler() http.Handler {
 	return router
 }
 
-// Wrapper for logging HTTP traffic
+// logHandler is middleware for logging HTTP requests and responses.
 func (s *Server) logHandler(next http.Handler) http.Handler {
 	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-		ww := middleware.NewWrapResponseWriter(w, r.ProtoMajor)
-		if s.conf.Verbose >= 2 {
-			t1 := time.Now()
-			respBuf := bytes.NewBufferString(": ") // : for printing format
-			ww.Tee(respBuf)                        // Copy result into buffer for logging
-			scheme := "http"
-			if r.TLS != nil {
-				scheme = "https"
-			}
+		// /irma/ is handled by the servercore library which does its own logging of these endpoints
+		if strings.HasPrefix(r.URL.EscapedPath(), "/irma/") {
+			next.ServeHTTP(w, r)
+			return
+		}
 
-			recipient := ""
-			// IP addresses of irmaclient users are hidden in logs for privacy
-			if !strings.HasPrefix(r.URL.EscapedPath(), "/irma/") {
-				recipient = " from " + r.RemoteAddr
+		server.LogRequest(r.Method, r.URL.EscapedPath(), r.Proto, r.RemoteAddr, r.Header)
+
+		// copy output of HTTP handler to our buffer for later logging
+		ww := middleware.NewWrapResponseWriter(w, r.ProtoMajor)
+		respBuf := new(bytes.Buffer)
+		ww.Tee(respBuf)
+
+		// print response after HTTP is served
+		start := time.Now()
+		defer func() {
+			var resp []byte
+			if ww.BytesWritten() > 0 {
+				resp = respBuf.Bytes()
 			}
-			s.conf.Logger.Tracef("=> New message \"%s %s://%s%s %s\"%s",
-				r.Method, scheme, r.Host, r.RequestURI, r.Proto, recipient)
-			s.conf.Logger.Trace("HTTP headers: ", server.ToJson(r.Header))
-
-			defer func() {
-				// Printing response after HTTP is served
-				resp := ""
-				if ww.BytesWritten() > 0 {
-					resp = respBuf.String()
-				}
-				s.conf.Logger.Tracef("<= Responded with %d in %s%s", ww.Status(), time.Since(t1).String(), resp)
-			}()
-		}
+			server.LogResponse(ww.Status(), time.Since(start), resp)
+		}()
 
 		next.ServeHTTP(ww, r)
 		return