docd: add slog and JSON logging (#149)

.github/workflows/go.yml

@@ -11,7 +11,7 @@ jobs:
     runs-on: ubuntu-latest
     strategy:
       matrix:
-        go: ["1.21", "1.20"]
+        go: ["1.21"]
     steps:
       - uses: actions/checkout@v2
 

README.md

@@ -69,10 +69,6 @@ The `docd` tool runs as either:
 ### Optional flags
 
 - `addr` - the bind address for the HTTP server, default is ":8888"
-- `log-level`
-  - 0: errors & critical info
-  - 1: inclues 0 and logs each request as well
-  - 2: include 1 and logs the response payloads
 - `readability-length-low` - sets the readability length low if the ?readability=1 parameter is set
 - `readability-length-high` - sets the readability length high if the ?readability=1 parameter is set
 - `readability-stopwords-low` - sets the readability stopwords low if the ?readability=1 parameter is set
@@ -83,11 +79,8 @@ The `docd` tool runs as either:
 
 ### How to start the service
 
-    $ # This will only log errors and critical info
-    $ docd -log-level 0
-
-    $ # This will run on port 8000 and log each request
-    $ docd -addr :8000 -log-level 1
+    $ # This runs on port 8000
+    $ docd -addr :8000
 
 ## Example usage (code)
 
@@ -104,15 +97,14 @@ package main
 
 import (
 	"fmt"
-	"log"
 
 	"code.sajari.com/docconv"
 )
 
 func main() {
 	res, err := docconv.ConvertPath("your-file.pdf")
 	if err != nil {
-		log.Fatal(err)
+		// TODO: handle
 	}
 	fmt.Println(res)
 }
@@ -125,7 +117,6 @@ package main
 
 import (
 	"fmt"
-	"log"
 
 	"code.sajari.com/docconv/client"
 )
@@ -136,7 +127,7 @@ func main() {
 
 	res, err := client.ConvertPath(c, "your-file.pdf")
 	if err != nil {
-		log.Fatal(err)
+		// TODO: handle
 	}
 	fmt.Println(res)
 }

docd/appengine/Dockerfile

@@ -2,4 +2,4 @@
 # of its runtime dependencies.
 # https://cloud.google.com/appengine/docs/flexible/custom-runtimes/about-custom-runtimes
 FROM sajari/docd:1.3.7
-CMD ["-addr", ":8080", "-error-reporting"]
+CMD ["-addr", ":8080", "-json-cloud-logging", "-error-reporting"]

docd/convert.go

@@ -6,7 +6,7 @@ import (
 	"encoding/json"
 	"fmt"
 	"io"
-	"log"
+	"log/slog"
 	"net/http"
 	"os"
 
@@ -17,6 +17,7 @@ import (
 )
 
 type convertServer struct {
+	l  *slog.Logger
 	er internal.ErrorReporter
 }
 
@@ -27,9 +28,7 @@ func (s *convertServer) convert(w http.ResponseWriter, r *http.Request) {
 	var readability bool
 	if r.FormValue("readability") == "1" {
 		readability = true
-		if *logLevel >= 2 {
-			log.Println("Readability is on")
-		}
+		s.l.DebugContext(ctx, "Readability is on")
 	}
 
 	path := r.FormValue("path")
@@ -73,9 +72,7 @@ func (s *convertServer) convert(w http.ResponseWriter, r *http.Request) {
 		mimeType = docconv.MimeTypeByExtension(info.Filename)
 	}
 
-	if *logLevel >= 1 {
-		log.Printf("Received file: %v (%v)", info.Filename, mimeType)
-	}
+	s.l.InfoContext(ctx, "Received file", "filename", info.Filename, "mimeType", mimeType)
 
 	data, err := docconv.Convert(file, mimeType, readability)
 	if err != nil {
@@ -91,7 +88,7 @@ func (s *convertServer) clientError(ctx context.Context, w http.ResponseWriter,
 		Error: fmt.Sprintf(pattern, args...),
 	})
 
-	log.Printf(pattern, args...)
+	s.l.InfoContext(ctx, fmt.Sprintf(pattern, args...))
 }
 
 func (s *convertServer) serverError(ctx context.Context, w http.ResponseWriter, r *http.Request, err error) {
@@ -104,7 +101,7 @@ func (s *convertServer) serverError(ctx context.Context, w http.ResponseWriter,
 	}
 	s.er.Report(e)
 
-	log.Printf("%v", err)
+	s.l.ErrorContext(ctx, err.Error(), "error", err)
 }
 
 func (s *convertServer) respond(ctx context.Context, w http.ResponseWriter, r *http.Request, code int, resp interface{}) {

docd/internal/cloudtrace/context.go

@@ -0,0 +1,25 @@
+package cloudtrace
+
+import (
+	"context"
+)
+
+type traceKey struct{}
+type spanKey struct{}
+
+func contextWithTraceInfo(ctx context.Context, traceHeader string) context.Context {
+	traceID, spanID := parseHeader(traceHeader)
+	if traceID != "" {
+		ctx = context.WithValue(ctx, traceKey{}, traceID)
+	}
+	if spanID != "" {
+		ctx = context.WithValue(ctx, spanKey{}, spanID)
+	}
+	return ctx
+}
+
+func traceInfoFromContext(ctx context.Context) (traceID, spanID string) {
+	traceID, _ = ctx.Value(traceKey{}).(string)
+	spanID, _ = ctx.Value(spanKey{}).(string)
+	return
+}

docd/internal/cloudtrace/header.go

@@ -0,0 +1,16 @@
+package cloudtrace
+
+import "strings"
+
+// The header specification is:
+// "X-Cloud-Trace-Context: TRACE_ID/SPAN_ID;o=TRACE_TRUE"
+const CloudTraceContextHeader = "X-Cloud-Trace-Context"
+
+func parseHeader(value string) (traceID, spanID string) {
+	var found bool
+	traceID, after, found := strings.Cut(value, "/")
+	if found {
+		spanID, _, _ = strings.Cut(after, ";")
+	}
+	return
+}

docd/internal/cloudtrace/http_handler.go

@@ -0,0 +1,14 @@
+package cloudtrace
+
+import "net/http"
+
+type HTTPHandler struct {
+	// Handler to wrap.
+	Handler http.Handler
+}
+
+func (h *HTTPHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
+	ctx := contextWithTraceInfo(r.Context(), r.Header.Get(CloudTraceContextHeader))
+
+	h.Handler.ServeHTTP(w, r.WithContext(ctx))
+}

docd/internal/cloudtrace/logger.go

@@ -0,0 +1,72 @@
+package cloudtrace
+
+// Inspired by https://github.com/remko/cloudrun-slog
+
+import (
+	"context"
+	"fmt"
+	"log/slog"
+	"os"
+)
+
+// Extra log level supported by Cloud Logging
+const LevelCritical = slog.Level(12)
+
+// Handler that outputs JSON understood by the structured log agent.
+// See https://cloud.google.com/logging/docs/agent/logging/configuration#special-fields
+type CloudLoggingHandler struct {
+	handler   slog.Handler
+	projectID string
+}
+
+var _ slog.Handler = (*CloudLoggingHandler)(nil)
+
+func NewCloudLoggingHandler(projectID string, level slog.Level) *CloudLoggingHandler {
+	return &CloudLoggingHandler{
+		projectID: projectID,
+		handler: slog.NewJSONHandler(os.Stderr, &slog.HandlerOptions{
+			AddSource: true,
+			Level:     level,
+			ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr {
+				if a.Key == slog.MessageKey {
+					a.Key = "message"
+				} else if a.Key == slog.SourceKey {
+					a.Key = "logging.googleapis.com/sourceLocation"
+				} else if a.Key == slog.LevelKey {
+					a.Key = "severity"
+					level := a.Value.Any().(slog.Level)
+					if level == LevelCritical {
+						a.Value = slog.StringValue("CRITICAL")
+					}
+				}
+				return a
+			},
+		}),
+	}
+}
+
+func (h *CloudLoggingHandler) Enabled(ctx context.Context, level slog.Level) bool {
+	return h.handler.Enabled(ctx, level)
+}
+
+func (h *CloudLoggingHandler) Handle(ctx context.Context, rec slog.Record) error {
+	traceID, spanID := traceInfoFromContext(ctx)
+	if traceID != "" {
+		rec = rec.Clone()
+		// https://cloud.google.com/logging/docs/agent/logging/configuration#special-fields
+		trace := fmt.Sprintf("projects/%s/traces/%s", h.projectID, traceID)
+		rec.Add("logging.googleapis.com/trace", slog.StringValue(trace))
+		if spanID != "" {
+			rec.Add("logging.googleapis.com/spanId", slog.StringValue(spanID))
+		}
+	}
+	return h.handler.Handle(ctx, rec)
+}
+
+func (h *CloudLoggingHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
+	return &CloudLoggingHandler{handler: h.handler.WithAttrs(attrs)}
+}
+
+func (h *CloudLoggingHandler) WithGroup(name string) slog.Handler {
+	return &CloudLoggingHandler{handler: h.handler.WithGroup(name)}
+}

docd/internal/debug/context.go

@@ -0,0 +1,15 @@
+package debug
+
+import (
+	"context"
+)
+
+type debugEnabledKey struct{}
+
+func debugEnabledInContext(ctx context.Context) bool {
+	enabled, ok := ctx.Value(debugEnabledKey{}).(bool)
+	if !ok {
+		return false
+	}
+	return enabled
+}

docd/internal/debug/http_handler.go

@@ -0,0 +1,22 @@
+package debug
+
+import (
+	"context"
+	"net/http"
+	"strconv"
+)
+
+type HTTPHandler struct {
+	// Handler to wrap.
+	Handler http.Handler
+}
+
+func (h *HTTPHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
+	ctx := r.Context()
+
+	if ok, _ := strconv.ParseBool(r.Header.Get(DebugHeader)); ok {
+		ctx = context.WithValue(ctx, debugEnabledKey{}, true)
+	}
+
+	h.Handler.ServeHTTP(w, r.WithContext(ctx))
+}

docd/internal/debug/logger.go

@@ -0,0 +1,33 @@
+package debug
+
+import (
+	"context"
+	"log/slog"
+)
+
+const DebugHeader = "X-Debug"
+
+type debugHandler struct {
+	slog.Handler
+}
+
+func NewDebugHandler(h slog.Handler) *debugHandler {
+	return &debugHandler{Handler: h}
+}
+
+var _ slog.Handler = (*debugHandler)(nil)
+
+func (h *debugHandler) Enabled(ctx context.Context, level slog.Level) bool {
+	if debugEnabledInContext(ctx) {
+		return true
+	}
+	return h.Handler.Enabled(ctx, level)
+}
+
+func (h *debugHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
+	return &debugHandler{Handler: h.Handler.WithAttrs(attrs)}
+}
+
+func (h *debugHandler) WithGroup(name string) slog.Handler {
+	return &debugHandler{Handler: h.Handler.WithGroup(name)}
+}

docd/internal/recovery.go

@@ -3,23 +3,24 @@ package internal
 import (
 	"errors"
 	"fmt"
-	"log"
+	"log/slog"
 	"net/http"
 	"runtime/debug"
 
 	"cloud.google.com/go/errorreporting"
 )
 
 type recoveryHandler struct {
+	l       *slog.Logger
 	er      ErrorReporter
 	handler http.Handler
 }
 
 // RecoveryHandler is HTTP middleware that recovers from a panic, writes a
 // 500, reports the panic, logs the panic and continues to the next handler.
-func RecoveryHandler(er ErrorReporter) func(h http.Handler) http.Handler {
+func RecoveryHandler(l *slog.Logger, er ErrorReporter) func(h http.Handler) http.Handler {
 	return func(h http.Handler) http.Handler {
-		return &recoveryHandler{er: er, handler: h}
+		return &recoveryHandler{l: l, er: er, handler: h}
 	}
 }
 
@@ -45,8 +46,7 @@ func (h recoveryHandler) handle(r *http.Request, err error) {
 	}
 	h.er.Report(e)
 
-	log.Println(err)
-	log.Printf("%s", stack)
+	h.l.ErrorContext(r.Context(), err.Error(), "error", err, "stack", string(stack))
 }
 
 // recovered represents the return value from a call to recover.