feat(api): add HTTP access request logging

api/access_log.go

@@ -0,0 +1,29 @@
+package api
+
+import (
+	"io"
+	"net/http"
+	"strings"
+	"time"
+
+	"github.com/gorilla/handlers"
+	log "github.com/sirupsen/logrus"
+)
+
+func accessLogFormatter(_ io.Writer, params handlers.LogFormatterParams) {
+	if strings.HasSuffix(params.URL.Path, "/api/ping") {
+		return
+	}
+	log.WithFields(log.Fields{
+		"method":   params.Request.Method,
+		"path":     params.URL.Path,
+		"status":   params.StatusCode,
+		"size":     params.Size,
+		"duration": time.Since(params.TimeStamp).String(),
+		"remote":   params.Request.RemoteAddr,
+	}).Debug("http request")
+}
+
+func AccessLogMiddleware(next http.Handler) http.Handler {
+	return handlers.CustomLoggingHandler(nil, next, accessLogFormatter)
+}

api/access_log_test.go

@@ -0,0 +1,68 @@
+package api
+
+import (
+	"net/http"
+	"net/http/httptest"
+	"testing"
+
+	log "github.com/sirupsen/logrus"
+	"github.com/sirupsen/logrus/hooks/test"
+)
+
+func TestAccessLogMiddleware(t *testing.T) {
+	log.SetLevel(log.DebugLevel)
+	hook := test.NewLocal(log.StandardLogger())
+
+	handler := AccessLogMiddleware(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		w.WriteHeader(http.StatusOK)
+		w.Write([]byte("ok"))
+	}))
+
+	req := httptest.NewRequest("GET", "/api/projects", nil)
+	req.RemoteAddr = "192.0.2.1:12345"
+	rr := httptest.NewRecorder()
+	handler.ServeHTTP(rr, req)
+
+	if len(hook.Entries) != 1 {
+		t.Fatalf("expected 1 log entry, got %d", len(hook.Entries))
+	}
+
+	entry := hook.LastEntry()
+	if entry.Level != log.DebugLevel {
+		t.Errorf("expected debug level, got %v", entry.Level)
+	}
+	for _, field := range []string{"method", "path", "status", "size", "duration", "remote"} {
+		if _, ok := entry.Data[field]; !ok {
+			t.Errorf("missing expected log field %q", field)
+		}
+	}
+
+	if entry.Data["method"] != "GET" {
+		t.Errorf("expected method GET, got %v", entry.Data["method"])
+	}
+	if entry.Data["path"] != "/api/projects" {
+		t.Errorf("expected path /api/projects, got %v", entry.Data["path"])
+	}
+	if entry.Data["status"] != http.StatusOK {
+		t.Errorf("expected status %d, got %v", http.StatusOK, entry.Data["status"])
+	}
+}
+
+func TestAccessLogMiddleware_SkipsPing(t *testing.T) {
+	hook := test.NewLocal(log.StandardLogger())
+
+	handler := AccessLogMiddleware(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		w.WriteHeader(http.StatusOK)
+	}))
+
+	for _, path := range []string{"/api/ping", "/semaphore/api/ping"} {
+		hook.Reset()
+		req := httptest.NewRequest("GET", path, nil)
+		rr := httptest.NewRecorder()
+		handler.ServeHTTP(rr, req)
+
+		if len(hook.Entries) != 0 {
+			t.Errorf("expected no log entries for %s, got %d", path, len(hook.Entries))
+		}
+	}
+}

cli/cmd/root.go

@@ -197,6 +197,7 @@ func runService() {
 
 	var router http.Handler = route
 
+	router = api.AccessLogMiddleware(router)
 	router = handlers.ProxyHeaders(router)
 	http.Handle("/", router)