Improve logging

cmd/federation.go

@@ -2,7 +2,7 @@ package main
 
 import (
 	"os"
-	"participating-online/sublinks-federation/internal/http"
+	"sublinks/federation/internal/http"
 )
 
 func main() {

go.mod

@@ -1,8 +1,15 @@
-module participating-online/sublinks-federation
+module sublinks/federation
 
 go 1.21.5
 
 require (
 	github.com/gorilla/mux v1.8.1
+	github.com/rs/zerolog v1.31.0
 	golang.org/x/text v0.14.0
 )
+
+require (
+	github.com/mattn/go-colorable v0.1.13 // indirect
+	github.com/mattn/go-isatty v0.0.19 // indirect
+	golang.org/x/sys v0.12.0 // indirect
+)

go.sum

@@ -1,4 +1,19 @@
+github.com/coreos/go-systemd/v22 v22.5.0/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc=
+github.com/godbus/dbus/v5 v5.0.4/go.mod h1:xhWf0FNVPg57R7Z0UbKHbJfkEywrmjJnf7w5xrFpKfA=
 github.com/gorilla/mux v1.8.1 h1:TuBL49tXwgrFYWhqrNgrUNEY92u81SPhu7sTdzQEiWY=
 github.com/gorilla/mux v1.8.1/go.mod h1:AKf9I4AEqPTmMytcMc0KkNouC66V3BtZ4qD5fmWSiMQ=
+github.com/mattn/go-colorable v0.1.13 h1:fFA4WZxdEF4tXPZVKMLwD8oUnCTTo08duU7wxecdEvA=
+github.com/mattn/go-colorable v0.1.13/go.mod h1:7S9/ev0klgBDR4GtXTXX8a3vIGJpMovkB8vQcUbaXHg=
+github.com/mattn/go-isatty v0.0.16/go.mod h1:kYGgaQfpe5nmfYZH+SKPsOc2e4SrIfOl2e/yFXSvRLM=
+github.com/mattn/go-isatty v0.0.19 h1:JITubQf0MOLdlGRuRq+jtsDlekdYPia9ZFsB8h/APPA=
+github.com/mattn/go-isatty v0.0.19/go.mod h1:W+V8PltTTMOvKvAeJH7IuucS94S2C6jfK/D7dTCTo3Y=
+github.com/pkg/errors v0.9.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0=
+github.com/rs/xid v1.5.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg=
+github.com/rs/zerolog v1.31.0 h1:FcTR3NnLWW+NnTwwhFWiJSZr4ECLpqCm6QsEnyvbV4A=
+github.com/rs/zerolog v1.31.0/go.mod h1:/7mN4D5sKwJLZQ2b/znpjC3/GQWY/xaDXUM0kKWRHss=
+golang.org/x/sys v0.0.0-20220811171246-fbc7d0a398ab/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
+golang.org/x/sys v0.6.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
+golang.org/x/sys v0.12.0 h1:CM0HF96J0hcLAwsHPJZjfdNzs0gftsLfgKt57wWHJ0o=
+golang.org/x/sys v0.12.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/text v0.14.0 h1:ScX5w1eTa3QqT8oi6+ziP7dTV1S2+ALU0bI+0zXKWiQ=
 golang.org/x/text v0.14.0/go.mod h1:18ZOQIKpY8NJVqYksKHtTdi31H5itFRjB5/qKTNYzSU=

internal/activitypub/post.go

@@ -2,7 +2,7 @@ package activitypub
 
 import (
 	"fmt"
-	"participating-online/sublinks-federation/internal/lemmy"
+	"sublinks/federation/internal/lemmy"
 	"time"
 )
 

internal/activitypub/user.go

@@ -2,7 +2,7 @@ package activitypub
 
 import (
 	"fmt"
-	"participating-online/sublinks-federation/internal/lemmy"
+	"sublinks/federation/internal/lemmy"
 	"time"
 )
 

internal/http/routes/activity.go

@@ -3,10 +3,10 @@ package routes
 import (
 	"context"
 	"encoding/json"
-	"log"
 	"net/http"
-	"participating-online/sublinks-federation/internal/activitypub"
-	"participating-online/sublinks-federation/internal/lemmy"
+	"sublinks/federation/internal/activitypub"
+	"sublinks/federation/internal/lemmy"
+	"sublinks/federation/internal/log"
 
 	"fmt"
 
@@ -27,7 +27,7 @@ func getActivityHandler(w http.ResponseWriter, r *http.Request) {
 	case "create":
 		obj, err := GetPostActivityObject(vars["id"])
 		if err != nil {
-			log.Println("Error reading object", err)
+			log.Error("Error reading object", err)
 			w.WriteHeader(http.StatusInternalServerError)
 			return
 		}
@@ -59,7 +59,7 @@ func GetPostActivityObject(id string) (*activitypub.Post, error) {
 	c := lemmy.GetLemmyClient(ctx)
 	post, err := c.GetPost(ctx, id)
 	if err != nil {
-		log.Println("Error reading post", err)
+		log.Error("Error reading post", err)
 		return nil, err
 	}
 	return activitypub.ConvertPostToApub(post), nil

internal/http/routes/post.go

@@ -3,10 +3,10 @@ package routes
 import (
 	"context"
 	"encoding/json"
-	"log"
 	"net/http"
-	"participating-online/sublinks-federation/internal/activitypub"
-	"participating-online/sublinks-federation/internal/lemmy"
+	"sublinks/federation/internal/activitypub"
+	"sublinks/federation/internal/lemmy"
+	"sublinks/federation/internal/log"
 
 	"github.com/gorilla/mux"
 )
@@ -21,7 +21,7 @@ func getPostHandler(w http.ResponseWriter, r *http.Request) {
 	c := lemmy.GetLemmyClient(ctx)
 	post, err := c.GetPost(ctx, vars["postId"])
 	if err != nil {
-		log.Println("Error reading post", err)
+		log.Error("Error reading post", err)
 		return
 	}
 	postLd := activitypub.ConvertPostToApub(post)

internal/http/routes/routes.go

@@ -1,12 +1,48 @@
 package routes
 
-import "github.com/gorilla/mux"
+import (
+	"encoding/json"
+	"net/http"
+	"sublinks/federation/internal/log"
+
+	"github.com/gorilla/mux"
+)
 
 func SetupRoutes() *mux.Router {
 	r := mux.NewRouter()
 	SetupUserRoutes(r)
 	SetupPostRoutes(r)
 	SetupApubRoutes(r)
 	SetupActivityRoutes(r)
+	r.NotFoundHandler = http.HandlerFunc(notFound)
+	r.MethodNotAllowedHandler = http.HandlerFunc(notAllowedMethod)
+	r.Use(logMiddleware)
 	return r
 }
+
+func logMiddleware(next http.Handler) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		log.Request("", r)
+		next.ServeHTTP(w, r)
+	})
+}
+
+type RequestError struct {
+	Msg string `json:"message"`
+}
+
+func notFound(w http.ResponseWriter, r *http.Request) {
+	log.Request("404 Not Found", r)
+	w.WriteHeader(http.StatusNotFound)
+	w.Header().Add("content-type", "application/activity+json")
+	content, _ := json.Marshal(RequestError{Msg: "not found"})
+	w.Write(content)
+}
+
+func notAllowedMethod(w http.ResponseWriter, r *http.Request) {
+	log.Request("405 Method Not Allowed", r)
+	w.WriteHeader(http.StatusNotFound)
+	w.Header().Add("content-type", "application/activity+json")
+	content, _ := json.Marshal(RequestError{Msg: "method not allowed"})
+	w.Write(content)
+}

internal/http/routes/user.go

@@ -4,10 +4,10 @@ import (
 	"context"
 	"encoding/json"
 	"fmt"
-	"log"
 	"net/http"
-	"participating-online/sublinks-federation/internal/activitypub"
-	"participating-online/sublinks-federation/internal/lemmy"
+	"sublinks/federation/internal/activitypub"
+	"sublinks/federation/internal/lemmy"
+	"sublinks/federation/internal/log"
 
 	"github.com/gorilla/mux"
 )
@@ -20,10 +20,10 @@ func getUserInfoHandler(w http.ResponseWriter, r *http.Request) {
 	vars := mux.Vars(r)
 	ctx := context.Background()
 	c := lemmy.GetLemmyClient(ctx)
-	log.Println(fmt.Sprintf("Looking up user %s", vars["user"]))
+	log.Info(fmt.Sprintf("Looking up user %s", vars["user"]))
 	user, err := c.GetUser(ctx, vars["user"])
 	if err != nil {
-		log.Println("Error reading user", err)
+		log.Error("Error reading user", err)
 		return
 	}
 

internal/http/server.go

@@ -3,11 +3,11 @@ package http
 import (
 	"context"
 	"flag"
-	"log"
 	"net/http"
 	"os"
 	"os/signal"
-	"participating-online/sublinks-federation/internal/http/routes"
+	"sublinks/federation/internal/http/routes"
+	"sublinks/federation/internal/log"
 	"time"
 )
 
@@ -29,8 +29,9 @@ func RunServer() {
 
 	// Run our server in a goroutine so that it doesn't block.
 	go func() {
+		log.Info("Starting server")
 		if err := srv.ListenAndServe(); err != nil {
-			log.Println(err)
+			log.Error("Error starting server", err)
 		}
 	}()
 
@@ -51,5 +52,5 @@ func RunServer() {
 	// Optionally, you could run srv.Shutdown in a goroutine and block on
 	// <-ctx.Done() if your application should wait for other services
 	// to finalize based on context cancellation.
-	log.Println("shutting down")
+	log.Info("shutting down")
 }

internal/log/log.go

@@ -0,0 +1,67 @@
+package log
+
+import (
+	"encoding/json"
+	"io"
+	"net/http"
+
+	"github.com/rs/zerolog/log"
+)
+
+func init() {
+	log.Debug().Msg("Logger started")
+}
+
+func Info(msg string) {
+	log.Info().Msg(msg)
+}
+
+func Debug(msg string) {
+	log.Debug().Msg(msg)
+}
+
+func Error(msg string, err error) {
+	log.Error().Err(err).Msg(msg)
+}
+
+func Warn(msg string) {
+	log.Warn().Msg(msg)
+}
+
+func Request(msg string, r *http.Request) {
+	defer r.Body.Close()
+	var body interface{}
+	rawbody, err := io.ReadAll(r.Body)
+	if err != nil {
+		Error("Error reading request body", err)
+		body = nil
+	}
+	if r.ContentLength > 0 && r.Header.Get("Content-Type") == "application/json" {
+		err = json.Unmarshal(rawbody, &body)
+		if err != nil {
+			Error("Error parsing request body into json", err)
+			body = nil
+		}
+	} else {
+		body = rawbody
+	}
+	log.Debug().
+		Str("method", r.Method).
+		Str("url", r.URL.String()).
+		Str("user-agent", r.UserAgent()).
+		Int64("content-length", r.ContentLength).
+		Str("ip", r.RemoteAddr).
+		Str("real-ip", r.Header.Get("X-Real-Ip")).
+		Str("dnt", r.Header.Get("Dnt")).
+		Str("host", r.Host).
+		Str("proto", r.Proto).
+		Str("referer", r.Referer()).
+		Str("accept", r.Header.Get("Accept")).
+		Str("accept-language", r.Header.Get("Accept-Language")).
+		Str("content-type", r.Header.Get("Content-Type")).
+		Str("forwarded-for", r.Header.Get("X-Forwarded-For")).
+		Any("body", body).
+		Str("user", r.URL.User.Username()).
+		Str("query", r.URL.Query().Encode()).
+		Msg(msg)
+}