Improve logging; remove useless fields

cmd/syncv3/main.go

@@ -40,6 +40,7 @@ func defaulting(in, dft string) string {
 
 func main() {
 	fmt.Printf("Sync v3 [%s] (%s)\n", version, GitCommit)
+	syncv3.Version = fmt.Sprintf("%s (%s)", version, GitCommit)
 	flagDestinationServer := os.Getenv(EnvServer)
 	flagPostgres := os.Getenv(EnvDB)
 	flagSecret := os.Getenv(EnvSecret)

internal/context.go

@@ -0,0 +1,78 @@
+package internal
+
+import (
+	"context"
+
+	"github.com/rs/zerolog"
+)
+
+type ctx string
+
+var (
+	ctxData ctx = "syncv3_data"
+)
+
+// logging metadata for a single request
+type data struct {
+	userID   string
+	since    int64
+	next     int64
+	numRooms int
+	txnID    string
+}
+
+// prepare a request context so it can contain syncv3 info
+func RequestContext(ctx context.Context) context.Context {
+	d := &data{
+		since:    -1,
+		next:     -1,
+		numRooms: -1,
+	}
+	return context.WithValue(ctx, ctxData, d)
+}
+
+// add the user ID to this request context. Need to have called RequestContext first.
+func SetRequestContextUserID(ctx context.Context, userID string) {
+	d := ctx.Value(ctxData)
+	if d == nil {
+		return
+	}
+	da := d.(*data)
+	da.userID = userID
+}
+
+func SetRequestContextResponseInfo(ctx context.Context, since, next int64, numRooms int, txnID string) {
+	d := ctx.Value(ctxData)
+	if d == nil {
+		return
+	}
+	da := d.(*data)
+	da.since = since
+	da.next = next
+	da.numRooms = numRooms
+	da.txnID = txnID
+}
+
+func DecorateLogger(ctx context.Context, l *zerolog.Event) *zerolog.Event {
+	d := ctx.Value(ctxData)
+	if d == nil {
+		return l
+	}
+	da := d.(*data)
+	if da.userID != "" {
+		l = l.Str("u", da.userID)
+	}
+	if da.since >= 0 {
+		l = l.Int64("p", da.since)
+	}
+	if da.next >= 0 {
+		l = l.Int64("q", da.next)
+	}
+	if da.txnID != "" {
+		l = l.Str("t", da.txnID)
+	}
+	if da.numRooms >= 0 {
+		l = l.Int("r", da.numRooms)
+	}
+	return l
+}

sync3/conn.go

@@ -61,6 +61,10 @@ func NewConn(connID ConnID, h ConnHandler) *Conn {
 	}
 }
 
+func (c *Conn) UserID() string {
+	return c.handler.UserID()
+}
+
 func (c *Conn) Alive() bool {
 	return c.handler.Alive()
 }

sync3/handler/handler.go

@@ -170,13 +170,14 @@ func (h *SyncLiveHandler) serve(w http.ResponseWriter, req *http.Request) error
 		hlog.FromRequest(req).Err(err).Msg("failed to get or create Conn")
 		return err
 	}
-	log := hlog.FromRequest(req).With().Str("conn_id", conn.ConnID.String()).Logger()
 	// set pos and timeout if specified
 	cpos, herr := parseIntFromQuery(req.URL, "pos")
 	if herr != nil {
 		return herr
 	}
 	requestBody.SetPos(cpos)
+	internal.SetRequestContextUserID(req.Context(), conn.UserID())
+	log := hlog.FromRequest(req).With().Str("user", conn.UserID()).Int64("pos", cpos).Logger()
 
 	var timeout int
 	if req.URL.Query().Get("timeout") == "" {
@@ -190,13 +191,16 @@ func (h *SyncLiveHandler) serve(w http.ResponseWriter, req *http.Request) error
 	}
 
 	requestBody.SetTimeoutMSecs(timeout)
-	log.Trace().Int64("pos", cpos).Int("timeout", timeout).Msg("recv")
+	log.Trace().Int("timeout", timeout).Msg("recv")
 
 	resp, herr := conn.OnIncomingRequest(req.Context(), &requestBody)
 	if herr != nil {
 		log.Err(herr).Msg("failed to OnIncomingRequest")
 		return herr
 	}
+	// for logging
+	internal.SetRequestContextResponseInfo(req.Context(), cpos, resp.PosInt(), len(resp.Rooms), requestBody.TxnID)
+
 	w.Header().Set("Content-Type", "application/json")
 	w.WriteHeader(200)
 	if err := json.NewEncoder(w).Encode(resp); err != nil {
@@ -312,9 +316,9 @@ func (h *SyncLiveHandler) setupConnection(req *http.Request, syncReq *sync3.Requ
 		return NewConnState(v2device.UserID, v2device.DeviceID, userCache, h.GlobalCache, h.Extensions, h.Dispatcher)
 	})
 	if created {
-		log.Info().Str("conn_id", conn.ConnID.String()).Msg("created new connection")
+		log.Info().Str("user", v2device.UserID).Str("conn_id", conn.ConnID.String()).Msg("created new connection")
 	} else {
-		log.Info().Str("conn_id", conn.ConnID.String()).Msg("using existing connection")
+		log.Info().Str("user", v2device.UserID).Str("conn_id", conn.ConnID.String()).Msg("using existing connection")
 	}
 	return conn, nil
 }

v3.go

@@ -5,9 +5,11 @@ import (
 	"fmt"
 	"net/http"
 	"os"
+	"strings"
 	"time"
 
 	"github.com/gorilla/mux"
+	"github.com/matrix-org/sync-v3/internal"
 	"github.com/rs/zerolog"
 	"github.com/rs/zerolog/hlog"
 )
@@ -16,6 +18,7 @@ var logger = zerolog.New(os.Stdout).With().Timestamp().Logger().Output(zerolog.C
 	Out:        os.Stderr,
 	TimeFormat: "15:04:05",
 })
+var Version string
 
 type server struct {
 	chain []func(next http.Handler) http.Handler
@@ -51,8 +54,12 @@ func RunSyncV3Server(h http.Handler, bindAddr, destV2Server string) {
 	r.Handle("/_matrix/client/unstable/org.matrix.msc3575/sync", allowCORS(h))
 
 	serverJSON, _ := json.Marshal(struct {
-		Server string `json:"server"`
-	}{destV2Server})
+		Server  string `json:"server"`
+		Version string `json:"version"`
+	}{
+		Server:  destV2Server,
+		Version: Version,
+	})
 	r.Handle("/client/server.json", allowCORS(http.HandlerFunc(func(rw http.ResponseWriter, r *http.Request) {
 		rw.Header().Set("Content-Type", "application/json")
 		rw.WriteHeader(200)
@@ -67,19 +74,25 @@ func RunSyncV3Server(h http.Handler, bindAddr, destV2Server string) {
 	srv := &server{
 		chain: []func(next http.Handler) http.Handler{
 			hlog.NewHandler(logger),
+			func(next http.Handler) http.Handler {
+				return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+					r = r.WithContext(internal.RequestContext(r.Context()))
+					next.ServeHTTP(w, r)
+				})
+			},
 			hlog.AccessHandler(func(r *http.Request, status, size int, duration time.Duration) {
 				if r.Method == "OPTIONS" {
 					return
 				}
-				hlog.FromRequest(r).Info().
-					Str("method", r.Method).
-					Int("status", status).
+				entry := internal.DecorateLogger(r.Context(), hlog.FromRequest(r).Info())
+				if !strings.HasSuffix(r.URL.Path, "/sync") {
+					entry.Str("path", r.URL.Path)
+				}
+				entry.Int("status", status).
 					Int("size", size).
 					Dur("duration", duration).
-					Str("path", r.URL.Path).
 					Msg("")
 			}),
-			hlog.RemoteAddrHandler("ip"),
 		},
 		final: r,
 	}