Update provisioning API logging

go.mod

@@ -3,6 +3,7 @@ module go.mau.fi/mautrix-gmessages
 go 1.21
 
 require (
+	github.com/beeper/libserv v0.0.0-20231231202820-c7303abfc32c
 	github.com/gabriel-vasile/mimetype v1.4.3
 	github.com/lib/pq v1.10.9
 	github.com/mattn/go-sqlite3 v1.14.22
@@ -26,6 +27,7 @@ require (
 	github.com/mattn/go-colorable v0.1.13 // indirect
 	github.com/mattn/go-isatty v0.0.19 // indirect
 	github.com/rogpeppe/go-internal v1.10.0 // indirect
+	github.com/rs/xid v1.5.0 // indirect
 	github.com/tidwall/gjson v1.17.1 // indirect
 	github.com/tidwall/match v1.1.1 // indirect
 	github.com/tidwall/pretty v1.2.0 // indirect

go.sum

@@ -1,5 +1,7 @@
 github.com/DATA-DOG/go-sqlmock v1.5.2 h1:OcvFkGmslmlZibjAjaHm3L//6LiuBgolP7OputlJIzU=
 github.com/DATA-DOG/go-sqlmock v1.5.2/go.mod h1:88MAG/4G7SMwSE3CeA0ZKzrT5CiOU3OJ+JlNzwDqpNU=
+github.com/beeper/libserv v0.0.0-20231231202820-c7303abfc32c h1:WqjRVgUO039eiISCjsZC4F9onOEV93DJAk6v33rsZzY=
+github.com/beeper/libserv v0.0.0-20231231202820-c7303abfc32c/go.mod h1:b9FFm9y4mEm36G8ytVmS1vkNzJa0KepmcdVY+qf7qRU=
 github.com/coreos/go-systemd/v22 v22.5.0 h1:RrqgGjYQKalulkV8NGVIfkXQf6YYmOyiJKk8iXXhfZs=
 github.com/coreos/go-systemd/v22 v22.5.0/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc=
 github.com/creack/pty v1.1.9/go.mod h1:oKZEueFk5CKHvIhNR5MUki03XCEU+Q6VDXinZuGJ33E=
@@ -39,6 +41,7 @@ github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZN
 github.com/rogpeppe/go-internal v1.9.0/go.mod h1:WtVeX8xhTBvf0smdhujwtBcq4Qrzq/fJaraNFVN+nFs=
 github.com/rogpeppe/go-internal v1.10.0 h1:TMyTOH3F/DB16zRVcYyreMH6GnZZrwQVAoYjRBZyWFQ=
 github.com/rogpeppe/go-internal v1.10.0/go.mod h1:UQnix2H7Ngw/k4C5ijL5+65zddjncjaFoBhdsK/akog=
+github.com/rs/xid v1.5.0 h1:mKX4bl4iPYJtEIxp6CYiUuLQ/8DYMoz0PUdtGgMFRVc=
 github.com/rs/xid v1.5.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg=
 github.com/rs/zerolog v1.32.0 h1:keLypqrlIjaFsbmJOBdB/qvyF8KEtCWHwobLp5l/mQ0=
 github.com/rs/zerolog v1.32.0/go.mod h1:/7mN4D5sKwJLZQ2b/znpjC3/GQWY/xaDXUM0kKWRHss=

main.go

@@ -101,7 +101,7 @@ func (br *GMBridge) Init() {
 
 	ss := br.Config.Bridge.Provisioning.SharedSecret
 	if len(ss) > 0 && ss != "disable" {
-		br.Provisioning = &ProvisioningAPI{bridge: br}
+		br.Provisioning = &ProvisioningAPI{bridge: br, log: br.ZLog.With().Str("component", "provisioning").Logger()}
 	}
 }
 

provisioning.go

@@ -24,13 +24,12 @@ import (
 	"net/http"
 	_ "net/http/pprof"
 	"strings"
-	"time"
 
+	"github.com/beeper/libserv/pkg/requestlog"
 	"github.com/rs/zerolog"
+	"github.com/rs/zerolog/hlog"
 	"google.golang.org/protobuf/proto"
 
-	log "maunium.net/go/maulogger/v2"
-
 	"maunium.net/go/mautrix/bridge/status"
 	"maunium.net/go/mautrix/id"
 
@@ -40,16 +39,14 @@ import (
 
 type ProvisioningAPI struct {
 	bridge *GMBridge
-	log    log.Logger
-	zlog   zerolog.Logger
+	log    zerolog.Logger
 }
 
 func (prov *ProvisioningAPI) Init() {
-	prov.log = prov.bridge.Log.Sub("Provisioning")
-	prov.zlog = prov.bridge.ZLog.With().Str("component", "provisioning").Logger()
-
-	prov.log.Debugln("Enabling provisioning API at", prov.bridge.Config.Bridge.Provisioning.Prefix)
+	prov.log.Debug().Str("path_prefix", prov.bridge.Config.Bridge.Provisioning.Prefix).Msg("Enabling provisioning API")
 	r := prov.bridge.AS.Router.PathPrefix(prov.bridge.Config.Bridge.Provisioning.Prefix).Subrouter()
+	r.Use(hlog.NewHandler(prov.log))
+	r.Use(requestlog.AccessLogger(true))
 	r.Use(prov.AuthMiddleware)
 	r.HandleFunc("/v1/ping", prov.Ping).Methods(http.MethodGet)
 	r.HandleFunc("/v1/login", prov.Login).Methods(http.MethodPost)
@@ -65,7 +62,7 @@ func (prov *ProvisioningAPI) Init() {
 	prov.bridge.AS.Router.HandleFunc("/_matrix/app/com.beeper.bridge_state", prov.BridgeStatePing).Methods(http.MethodPost)
 
 	if prov.bridge.Config.Bridge.Provisioning.DebugEndpoints {
-		prov.zlog.Debug().Msg("Enabling debug API at /debug")
+		prov.log.Debug().Msg("Enabling debug API at /debug")
 		r := prov.bridge.AS.Router.PathPrefix("/debug").Subrouter()
 		r.Use(prov.AuthMiddleware)
 		r.PathPrefix("/pprof").Handler(http.DefaultServeMux)
@@ -75,24 +72,14 @@ func (prov *ProvisioningAPI) Init() {
 	r.HandleFunc("/v1/delete_connection", prov.Disconnect).Methods(http.MethodPost)
 }
 
-type responseWrap struct {
-	http.ResponseWriter
-	statusCode int
-}
-
-func (rw *responseWrap) WriteHeader(statusCode int) {
-	rw.ResponseWriter.WriteHeader(statusCode)
-	rw.statusCode = statusCode
-}
-
 func (prov *ProvisioningAPI) AuthMiddleware(h http.Handler) http.Handler {
 	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 		auth := r.Header.Get("Authorization")
 		if strings.HasPrefix(auth, "Bearer ") {
 			auth = auth[len("Bearer "):]
 		}
 		if auth != prov.bridge.Config.Bridge.Provisioning.SharedSecret {
-			prov.log.Infof("Authentication token does not match shared secret")
+			hlog.FromRequest(r).Warn().Msg("Authentication token does not match shared secret")
 			jsonResponse(w, http.StatusForbidden, map[string]interface{}{
 				"error":   "Authentication token does not match shared secret",
 				"errcode": "M_FORBIDDEN",
@@ -101,11 +88,7 @@ func (prov *ProvisioningAPI) AuthMiddleware(h http.Handler) http.Handler {
 		}
 		userID := r.URL.Query().Get("user_id")
 		user := prov.bridge.GetUserByMXID(id.UserID(userID))
-		start := time.Now()
-		wWrap := &responseWrap{w, 200}
-		h.ServeHTTP(wWrap, r.WithContext(context.WithValue(r.Context(), "user", user)))
-		duration := time.Now().Sub(start).Seconds()
-		prov.log.Infofln("%s %s from %s took %.2f seconds and returned status %d", r.Method, r.URL.Path, user.MXID, duration, wWrap.statusCode)
+		h.ServeHTTP(w, r.WithContext(context.WithValue(r.Context(), "user", user)))
 	})
 }
 
@@ -174,7 +157,7 @@ func (prov *ProvisioningAPI) ListContacts(w http.ResponseWriter, r *http.Request
 			ErrCode: "no session",
 		})
 	} else if contacts, err := user.Client.ListContacts(); err != nil {
-		prov.log.Errorfln("Failed to fetch %s's contacts: %v", user.MXID, err)
+		hlog.FromRequest(r).Err(err).Msg("Failed to fetch user's contacts")
 		jsonResponse(w, http.StatusInternalServerError, Error{
 			Error:   "Internal server error while fetching contact list",
 			ErrCode: "failed to get contacts",
@@ -226,7 +209,7 @@ func (prov *ProvisioningAPI) StartChat(w http.ResponseWriter, r *http.Request) {
 	}
 	resp, err := user.Client.GetOrCreateConversation(&reqData)
 	if err != nil {
-		prov.zlog.Err(err).Msg("Failed to start chat")
+		hlog.FromRequest(r).Err(err).Msg("Failed to start chat")
 		jsonResponse(w, http.StatusInternalServerError, Error{
 			Error:   "Failed to start chat",
 			ErrCode: "unknown error",
@@ -240,7 +223,7 @@ func (prov *ProvisioningAPI) StartChat(w http.ResponseWriter, r *http.Request) {
 		return
 	}
 	if resp.GetConversation() == nil {
-		prov.zlog.Warn().
+		hlog.FromRequest(r).Warn().
 			Int("req_number_count", len(req.Numbers)).
 			Str("status", resp.GetStatus().String()).
 			Msg("No conversation in chat create response")
@@ -252,11 +235,11 @@ func (prov *ProvisioningAPI) StartChat(w http.ResponseWriter, r *http.Request) {
 	}
 	convCopy := proto.Clone(resp.Conversation).(*gmproto.Conversation)
 	convCopy.LatestMessage = nil
-	prov.zlog.Debug().Any("conversation_data", convCopy).Msg("Got conversation data for start chat")
+	hlog.FromRequest(r).Debug().Any("conversation_data", convCopy).Msg("Got conversation data for start chat")
 	portal := user.GetPortalByID(resp.Conversation.ConversationID)
 	err = portal.CreateMatrixRoom(r.Context(), user, resp.Conversation, false)
 	if err != nil {
-		prov.zlog.Err(err).Msg("Failed to create matrix room")
+		hlog.FromRequest(r).Err(err).Msg("Failed to create matrix room")
 		jsonResponse(w, http.StatusInternalServerError, Error{
 			Error:   "Failed to create matrix room",
 			ErrCode: "unknown error",
@@ -335,7 +318,7 @@ func (prov *ProvisioningAPI) GoogleLoginStart(w http.ResponseWriter, r *http.Req
 	userID := r.URL.Query().Get("user_id")
 	user := prov.bridge.GetUserByMXID(id.UserID(userID))
 
-	log := prov.zlog.With().Str("user_id", user.MXID.String()).Str("endpoint", "login").Logger()
+	log := hlog.FromRequest(r)
 
 	if user.IsLoggedIn() {
 		jsonResponse(w, http.StatusOK, LoginResponse{Status: "success", ErrCode: "already logged in"})
@@ -388,7 +371,7 @@ func (prov *ProvisioningAPI) GoogleLoginWait(w http.ResponseWriter, r *http.Requ
 	userID := r.URL.Query().Get("user_id")
 	user := prov.bridge.GetUserByMXID(id.UserID(userID))
 
-	log := prov.zlog.With().Str("user_id", user.MXID.String()).Str("endpoint", "login").Logger()
+	log := hlog.FromRequest(r)
 
 	err := user.AsyncLoginGoogleWait(r.Context())
 	if err != nil {
@@ -442,7 +425,7 @@ func (prov *ProvisioningAPI) Login(w http.ResponseWriter, r *http.Request) {
 	userID := r.URL.Query().Get("user_id")
 	user := prov.bridge.GetUserByMXID(id.UserID(userID))
 
-	log := prov.zlog.With().Str("user_id", user.MXID.String()).Str("endpoint", "login").Logger()
+	log := hlog.FromRequest(r)
 
 	if user.IsLoggedIn() {
 		jsonResponse(w, http.StatusOK, LoginResponse{Status: "success", ErrCode: "already logged in"})