Implement structured logging

go.mod

@@ -4,5 +4,15 @@ go 1.22
 
 require (
 	github.com/golang-jwt/jwt/v5 v5.2.0
+	github.com/rs/zerolog v1.29.0
+	go.mau.fi/zeroconfig v0.1.2
 	gopkg.in/yaml.v2 v2.2.2
 )
+
+require (
+	github.com/coreos/go-systemd/v22 v22.3.3-0.20220203105225-a9a7ef127534 // indirect
+	github.com/mattn/go-colorable v0.1.12 // indirect
+	github.com/mattn/go-isatty v0.0.14 // indirect
+	golang.org/x/sys v0.0.0-20210927094055-39ccf1dd6fa6 // indirect
+	gopkg.in/natefinch/lumberjack.v2 v2.2.1 // indirect
+)

go.sum

@@ -1,6 +1,32 @@
+github.com/coreos/go-systemd/v22 v22.3.3-0.20220203105225-a9a7ef127534 h1:rtAn27wIbmOGUs7RIbVgPEjb31ehTVniDwPGXyMxm5U=
+github.com/coreos/go-systemd/v22 v22.3.3-0.20220203105225-a9a7ef127534/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc=
+github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c=
+github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
+github.com/godbus/dbus/v5 v5.0.4/go.mod h1:xhWf0FNVPg57R7Z0UbKHbJfkEywrmjJnf7w5xrFpKfA=
 github.com/golang-jwt/jwt/v5 v5.2.0 h1:d/ix8ftRUorsN+5eMIlF4T6J8CAt9rch3My2winC1Jw=
 github.com/golang-jwt/jwt/v5 v5.2.0/go.mod h1:pqrtFR0X4osieyHYxtmOUWsAWrfe1Q5UVIyoH402zdk=
+github.com/mattn/go-colorable v0.1.12 h1:jF+Du6AlPIjs2BiUiQlKOX0rt3SujHxPnksPKZbaA40=
+github.com/mattn/go-colorable v0.1.12/go.mod h1:u5H1YNBxpqRaxsYJYSkiCWKzEfiAb1Gb520KVy5xxl4=
+github.com/mattn/go-isatty v0.0.14 h1:yVuAays6BHfxijgZPzw+3Zlu5yQgKGP2/hcQbHb7S9Y=
+github.com/mattn/go-isatty v0.0.14/go.mod h1:7GGIvUiUoEMVVmxf/4nioHXj79iQHKdU27kJ6hsGG94=
+github.com/pkg/errors v0.9.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0=
+github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM=
+github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
+github.com/rs/xid v1.4.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg=
+github.com/rs/zerolog v1.29.0 h1:Zes4hju04hjbvkVkOhdl2HpZa+0PmVwigmo8XoORE5w=
+github.com/rs/zerolog v1.29.0/go.mod h1:NILgTygv/Uej1ra5XxGf82ZFSLk58MFGAUS2o6usyD0=
+github.com/stretchr/testify v1.8.1 h1:w7B6lhMri9wdJUVmEZPGGhZzrYTPvgJArz7wNPgYKsk=
+github.com/stretchr/testify v1.8.1/go.mod h1:w2LPCIKwWwSfY2zedu0+kehJoqGctiVI29o6fzry7u4=
+go.mau.fi/zeroconfig v0.1.2 h1:DKOydWnhPMn65GbXZOafgkPm11BvFashZWLct0dGFto=
+go.mau.fi/zeroconfig v0.1.2/go.mod h1:NcSJkf180JT+1IId76PcMuLTNa1CzsFFZ0nBygIQM70=
+golang.org/x/sys v0.0.0-20210630005230-0f9fa26af87c/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
+golang.org/x/sys v0.0.0-20210927094055-39ccf1dd6fa6 h1:foEbQz/B0Oz6YIqu/69kfXPYeFQAuuMYFkjaqXzl5Wo=
+golang.org/x/sys v0.0.0-20210927094055-39ccf1dd6fa6/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405 h1:yhCVgyC4o1eVCa2tZl7eS0r+SDo693bJlVdllGtEeKM=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
+gopkg.in/natefinch/lumberjack.v2 v2.2.1 h1:bBRl1b0OH9s/DuPhuXpNl+VtCaJXFZ5/uEFST95x9zc=
+gopkg.in/natefinch/lumberjack.v2 v2.2.1/go.mod h1:YD8tP3GAjkrDg1eZH7EGmyESg/lsYskCTPBJVb9jqSc=
 gopkg.in/yaml.v2 v2.2.2 h1:ZCJp+EgiOT7lHqUV2J862kp8Qj64Jo6az82+3Td9dZw=
 gopkg.in/yaml.v2 v2.2.2/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI=
+gopkg.in/yaml.v3 v3.0.1 h1:fxVm/GzAzEWqLHuvctI91KS9hhNmmWOoWu0XTYJS7CA=
+gopkg.in/yaml.v3 v3.0.1/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM=

linear.go

@@ -6,10 +6,11 @@ import (
 	"encoding/json"
 	"fmt"
 	"io"
-	"log"
 	"net/http"
 	"strings"
 	"time"
+
+	"github.com/rs/zerolog"
 )
 
 const (
@@ -195,7 +196,7 @@ func isValidEmailLocalpart(localpart string) bool {
 	return true
 }
 
-func getLinearID(email, token string) string {
+func getLinearID(ctx context.Context, email, token string) string {
 	if len(email) > 100 {
 		return ""
 	}
@@ -214,45 +215,61 @@ func getLinearID(email, token string) string {
 	if ok {
 		return userID
 	}
-	fmt.Println("ID for", email, "not cached, fetching from Linear")
+	log := zerolog.Ctx(ctx).With().
+		Str("email", email).
+		Str("user_id", userID).
+		Logger()
+
+	log.Warn().Msg("Linear user ID for email is not cached, fetching from Linear")
+
 	var userResp GetUserEmailsResponse
-	err := LinearRequest(&GraphQLRequest{
+	err := LinearRequest(ctx, &GraphQLRequest{
 		Token: token,
 		Query: queryFindUserByEmail,
 		Variables: map[string]any{
 			"filter": map[string]any{"email": map[string]any{"eq": email}},
 		},
 	}, &userResp)
 	if err != nil {
-		fmt.Printf("Error finding linear ID of %s: %v\n", email, err)
+		log.Err(err).Msg("Error finding linear user ID for email")
 		emailToLinearIDCache[email] = ""
 		return ""
 	}
 	for _, user := range userResp.Users.Nodes {
-		fmt.Printf("Found linear ID for %s (%s) -> %s\n", user.Email, user.Name, user.ID)
+		log.Info().
+			Str("found_email", user.Email).
+			Str("found_name", user.Name).
+			Str("found_id", user.ID).
+			Msg("Found linear user ID for email")
 		emailToLinearIDCache[user.Email] = user.ID
 	}
 	return emailToLinearIDCache[email]
 }
 
-func fillEmailCache(token string) error {
+func fillEmailCache(ctx context.Context, token string) error {
 	var userResp GetUserEmailsResponse
-	err := LinearRequest(&GraphQLRequest{
+	err := LinearRequest(ctx, &GraphQLRequest{
 		Token: token,
 		Query: queryGetUserEmails,
 	}, &userResp)
 	if err != nil {
 		return err
 	}
 	for _, user := range userResp.Users.Nodes {
-		fmt.Printf("Found linear ID for %s (%s) -> %s\n", user.Email, user.Name, user.ID)
+		zerolog.Ctx(ctx).Info().
+			Str("email", user.Email).
+			Str("name", user.Name).
+			Str("user_id", user.ID).
+			Msg("Found linear user ID for email")
 		emailToLinearIDCache[user.Email] = user.ID
 	}
 	return nil
 }
 
-func LinearRequest(payload *GraphQLRequest, into interface{}) error {
-	ctx, cancel := context.WithTimeout(context.Background(), 1*time.Minute)
+func LinearRequest(ctx context.Context, payload *GraphQLRequest, into any) error {
+	log := zerolog.Ctx(ctx).With().Str("action", "linear_request").Logger()
+
+	ctx, cancel := context.WithTimeout(ctx, 1*time.Minute)
 	defer cancel()
 	var buf bytes.Buffer
 	err := json.NewEncoder(&buf).Encode(payload)
@@ -271,13 +288,17 @@ func LinearRequest(payload *GraphQLRequest, into interface{}) error {
 	}
 	defer resp.Body.Close()
 	var respData GraphQLResponse
-	data, _ := io.ReadAll(resp.Body)
-	if resp.StatusCode != 200 {
-		log.Printf("Got non-200 response %d: %s", resp.StatusCode, data)
+	data, err := io.ReadAll(resp.Body)
+	if err != nil {
+		return err
+	} else if resp.StatusCode != 200 {
+		log.Error().Int("status_code", resp.StatusCode).Str("resp_data", string(data)).Msg("Got non-200 response")
+	} else if json.Valid(data) {
+		log.Info().RawJSON("resp_data", data).Msg("Received GraphQL response from Linear")
+	} else {
+		log.Warn().Str("resp_data_invalid", string(data)).Msg("Received non-JSON GraphQL response from Linear")
 	}
-	fmt.Printf("%s\n", data)
 	err = json.Unmarshal(data, &respData)
-	//err = json.NewDecoder(resp.Body).Decode(&respData)
 	if err != nil {
 		return fmt.Errorf("failed to unmarshal response JSON (status %d): %w: %s", resp.StatusCode, err, data)
 	}

logserver.go

@@ -18,14 +18,16 @@ package main
 
 import (
 	"compress/gzip"
+	"context"
 	"io"
-	"log"
 	"net/http"
 	"os"
 	"path"
 	"path/filepath"
 	"strconv"
 	"strings"
+
+	"github.com/rs/zerolog"
 )
 
 // logServer is an http.handler which will serve up bugreports
@@ -35,13 +37,18 @@ type logServer struct {
 
 func (f *logServer) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 	upath := r.URL.Path
+	log := zerolog.Ctx(r.Context()).With().
+		Str("component", "log_server").
+		Str("url_path", upath).
+		Logger()
+	ctx := log.WithContext(r.Context())
 
 	if !strings.HasPrefix(upath, "/") {
 		upath = "/" + upath
 		r.URL.Path = upath
 	}
 
-	log.Println("Serving", upath)
+	log.Info().Msg("Serving report logs")
 
 	// eliminate ., .., //, etc
 	upath = path.Clean(upath)
@@ -65,10 +72,11 @@ func (f *logServer) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 		return
 	}
 
-	serveFile(w, r, upath)
+	serveFile(ctx, w, r, upath)
 }
 
-func serveFile(w http.ResponseWriter, r *http.Request, path string) {
+func serveFile(ctx context.Context, w http.ResponseWriter, r *http.Request, path string) {
+	log := zerolog.Ctx(ctx).With().Str("action", "serve_file").Logger()
 	d, err := os.Stat(path)
 	if err != nil {
 		msg, code := toHTTPError(err)
@@ -81,7 +89,7 @@ func serveFile(w http.ResponseWriter, r *http.Request, path string) {
 
 	// if it's a directory, serve a listing
 	if d.IsDir() {
-		log.Println("Serving", path)
+		log.Info().Msg("Serving listing")
 		http.ServeFile(w, r, path)
 		return
 	}

main.go

@@ -17,16 +17,19 @@ limitations under the License.
 package main
 
 import (
+	"context"
 	"crypto/subtle"
 	"flag"
 	"fmt"
-	"log"
 	"net"
 	"net/http"
 	"os"
 	"strings"
 
 	"github.com/golang-jwt/jwt/v5"
+	"github.com/rs/zerolog"
+	globallog "github.com/rs/zerolog/log"
+	"go.mau.fi/zeroconfig"
 	"gopkg.in/yaml.v2"
 )
 
@@ -47,6 +50,8 @@ type config struct {
 	APIServerURLs map[string]string `yaml:"api_server_url"`
 
 	WebhookURL string `yaml:"webhook_url"`
+
+	Logging zeroconfig.Config `yaml:"logging"`
 }
 
 const (
@@ -66,6 +71,8 @@ func basicAuthOrJWTAuthenticated(handler http.Handler, username, password, realm
 	}
 
 	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		log := zerolog.Ctx(r.Context())
+
 		user, pass, ok := r.BasicAuth() // pull creds from the request
 		if !ok && len(jwtSecret) == 0 { // if no basic auth and no JWT auth, return unauthorized
 			unauthorized(w)
@@ -79,27 +86,27 @@ func basicAuthOrJWTAuthenticated(handler http.Handler, username, password, realm
 				return jwtSecret, nil
 			})
 			if err != nil {
-				log.Printf("Error parsing JWT: %v", err)
+				log.Err(err).Msg("Error parsing JWT")
 				unauthorized(w)
 				return
 			}
 
 			claims, ok := token.Claims.(*jwt.RegisteredClaims)
 			if !token.Valid || !ok {
-				log.Printf("Token invalid or claims not RegisteredClaims: %v", err)
+				log.Error().Msg("Token invalid or claims not RegisteredClaims")
 				unauthorized(w)
 				return
 			} else if claims.Issuer != rageshakeIssuer && claims.Issuer != apiServerIssuer {
-				log.Printf("Token issuer not rageshake or API server: %s", claims.Issuer)
+				log.Error().Str("issuer", claims.Issuer).Msg("Token issuer not rageshake or API server")
 				unauthorized(w)
 				return
 			} else if claims.Subject != r.URL.Path {
-				log.Printf("Token subject (%s) not the request path (%s)", claims.Subject, r.URL.Path)
+				log.Error().Str("subject", claims.Subject).Str("path", r.URL.Path).Msg("Token subject not the request path")
 				unauthorized(w)
 				return
 			}
 
-			log.Printf("Valid token from %s for accessing %s", claims.Issuer, claims.Subject)
+			log.Info().Str("subject", claims.Subject).Str("issuer", claims.Issuer).Msg("Valid token")
 		} else if subtle.ConstantTimeCompare([]byte(user), []byte(username)) != 1 || subtle.ConstantTimeCompare([]byte(pass), []byte(password)) != 1 { // check user and pass securely
 			unauthorized(w)
 			return
@@ -114,29 +121,33 @@ func main() {
 
 	cfg, err := loadConfig(*configPath)
 	if err != nil {
-		log.Fatalf("Invalid config file: %s", err)
+		globallog.Fatal().Err(err).Str("config_path", *configPath).Msg("Failed to load config")
+	}
+	log, err := cfg.Logging.Compile()
+	if err != nil {
+		globallog.Fatal().Err(err).Msg("Failed to compile logging configuration")
 	}
+	zerolog.DefaultContextLogger = log
 
 	if cfg.LinearToken == "" {
-		panic("No linear_token configured. Reporting bugs to Linear is disabled.")
+		log.Fatal().Msg("No linear_token configured. Reporting bugs to Linear is disabled.")
 	}
-	err = fillEmailCache(cfg.LinearToken)
+	err = fillEmailCache(context.TODO(), cfg.LinearToken)
 	if err != nil {
-		log.Fatalln("Failed to fetch internal user IDs from Linear:", err)
+		log.Fatal().Err(err).Msg("Failed to fetch internal user IDs from Linear")
 	}
 
 	apiPrefix := cfg.APIPrefix
 	if apiPrefix == "" {
 		_, port, err := net.SplitHostPort(*bindAddr)
 		if err != nil {
-			log.Fatal(err)
+			log.Fatal().Err(err).Msg("failed to parse bind address")
 		}
 		apiPrefix = fmt.Sprintf("http://localhost:%s/api", port)
 	} else {
 		// remove trailing /
 		apiPrefix = strings.TrimRight(apiPrefix, "/")
 	}
-	log.Printf("Using %s/listing as public URI", apiPrefix)
 
 	http.Handle("/api/submit", &submitServer{apiPrefix: apiPrefix, cfg: cfg})
 
@@ -152,19 +163,22 @@ func main() {
 		fmt.Fprint(w, "ok")
 	})
 
-	log.Println("Listening on", *bindAddr)
+	log.Info().
+		Str("api_prefix", apiPrefix).
+		Str("bind_addr", *bindAddr).
+		Msg("Starting rageshake server HTTP listener")
 
-	log.Fatal(http.ListenAndServe(*bindAddr, nil))
+	if err := http.ListenAndServe(*bindAddr, nil); err != nil {
+		log.Fatal().Err(err).Msg("HTTP listener failed")
+	}
 }
 
 func loadConfig(configPath string) (*config, error) {
-	contents, err := os.ReadFile(configPath)
+	file, err := os.Open(configPath)
 	if err != nil {
 		return nil, err
 	}
 	var cfg config
-	if err = yaml.Unmarshal(contents, &cfg); err != nil {
-		return nil, err
-	}
-	return &cfg, nil
+	err = yaml.NewDecoder(file).Decode(&cfg)
+	return &cfg, err
 }

rageshake.sample.yaml

@@ -18,3 +18,10 @@ api_server_url:
 
 # A custom webhook URL that receives all the relevant data about the rageshake.
 webhook_url: https://example.com/rageshake-webhook
+
+# See https://github.com/tulir/zeroconfig for details.
+logging:
+  min_level: debug
+  writers:
+    - type: stdout
+      format: json