provisioning/LinkNew: use structured logging

Signed-off-by: Sumner Evans <me@sumnerevans.com>

pkg/signalmeow/provisioning.go

@@ -63,6 +63,21 @@ const (
 	StateProvisioningPreKeysRegistered
 )
 
+func (s ProvisioningState) String() string {
+	switch s {
+	case StateProvisioningError:
+		return "StateProvisioningError"
+	case StateProvisioningURLReceived:
+		return "StateProvisioningURLReceived"
+	case StateProvisioningDataReceived:
+		return "StateProvisioningDataReceived"
+	case StateProvisioningPreKeysRegistered:
+		return "StateProvisioningPreKeysRegistered"
+	default:
+		return fmt.Sprintf("ProvisioningState(%d)", s)
+	}
+}
+
 // Enum for the provisioningUrl, ProvisioningMessage, and error
 type ProvisioningResponse struct {
 	State            ProvisioningState

provisioning.go

@@ -352,32 +352,20 @@ func (prov *ProvisioningAPI) clearSession(user *User) {
 
 // ** Provisioning API Helpers ** //
 
-func (prov *ProvisioningAPI) loginOrSendError(w http.ResponseWriter, user *User) *provisioningHandle {
+func (prov *ProvisioningAPI) loginOrSendError(w http.ResponseWriter, user *User) (*provisioningHandle, error) {
 	newSessionLoggedIn, handle, err := prov.newOrExistingSession(user)
 	if err != nil {
-		prov.log.Err(err).Msg("Error logging in")
-		jsonResponse(w, http.StatusInternalServerError, Error{
-			Success: false,
-			Error:   "Error logging in",
-			ErrCode: "M_INTERNAL",
-		})
-		return nil
+		return nil, err
 	}
 	if !newSessionLoggedIn {
 		prov.log.Debug().Msgf("LinkNew from %v, user already has a pending provisioning request (%d), cancelling", user.MXID, handle.id)
 		prov.clearSession(user)
 		newSessionLoggedIn, handle, err = prov.newOrExistingSession(user)
 		if err != nil {
-			prov.log.Err(err).Msg("Error logging in after cancelling existing session")
-			jsonResponse(w, http.StatusInternalServerError, Error{
-				Success: false,
-				Error:   "Error logging in",
-				ErrCode: "M_INTERNAL",
-			})
-			return nil
+			return nil, fmt.Errorf("error logging in after cancelling existing session: %w", err)
 		}
 	}
-	return handle
+	return handle, nil
 }
 
 func (prov *ProvisioningAPI) checkSessionAndReturnHandle(w http.ResponseWriter, r *http.Request, currentSession int) *provisioningHandle {
@@ -408,16 +396,29 @@ func (prov *ProvisioningAPI) checkSessionAndReturnHandle(w http.ResponseWriter,
 
 func (prov *ProvisioningAPI) LinkNew(w http.ResponseWriter, r *http.Request) {
 	user := r.Context().Value("user").(*User)
+	log := prov.log.With().
+		Str("action", "link_new").
+		Str("user_id", user.MXID.String()).
+		Logger()
+	log.Debug().Msg("starting login")
 
-	prov.log.Debug().Msgf("LinkNew from %v, starting login", user.MXID)
-	handle := prov.loginOrSendError(w, user)
+	handle, err := prov.loginOrSendError(w, user)
+	if err != nil {
+		jsonResponse(w, http.StatusInternalServerError, Error{
+			Success: false,
+			Error:   err.Error(),
+			ErrCode: "M_INTERNAL",
+		})
+		return
+	}
 
-	prov.log.Debug().Msgf("LinkNew from %v, waiting for provisioning response (session: %v)", user.MXID, handle.id)
+	log = log.With().Int("session_id", handle.id).Logger()
+	log.Debug().Msg("waiting for provisioning response")
 
 	select {
 	case resp := <-handle.channel:
 		if resp.Err != nil || resp.State == signalmeow.StateProvisioningError {
-			prov.log.Err(resp.Err).Msg("Error getting provisioning URL")
+			log.Err(resp.Err).Msg("Error getting provisioning URL")
 			jsonResponse(w, http.StatusInternalServerError, Error{
 				Success: false,
 				Error:   resp.Err.Error(),
@@ -426,31 +427,29 @@ func (prov *ProvisioningAPI) LinkNew(w http.ResponseWriter, r *http.Request) {
 			return
 		}
 		if resp.State != signalmeow.StateProvisioningURLReceived {
-			prov.log.Error().Msgf("LinkNew from %v, unexpected state: %v", user.MXID, resp.State)
+			log.Err(resp.Err).Str("state", resp.State.String()).Msg("unexpected state")
 			jsonResponse(w, http.StatusInternalServerError, Error{
 				Success: false,
-				Error:   "Unexpected state",
+				Error:   fmt.Sprintf("Unexpected state %s", resp.State.String()),
 				ErrCode: "M_INTERNAL",
 			})
 			return
 		}
 
-		prov.log.Debug().Msgf("LinkNew from %v, provisioning URL received", user.MXID)
+		log.Debug().Str("provisioning_url", resp.ProvisioningUrl).Msg("provisioning URL received")
 		jsonResponse(w, http.StatusOK, Response{
 			Success:   true,
 			Status:    "provisioning_url_received",
-			SessionID: fmt.Sprintf("%v", handle.id),
+			SessionID: fmt.Sprintf("%d", handle.id),
 			URI:       resp.ProvisioningUrl,
 		})
-		return
 	case <-time.After(30 * time.Second):
-		prov.log.Warn().Msg("Timeout waiting for provisioning response (new)")
+		log.Warn().Msg("Timeout waiting for provisioning response (new)")
 		jsonResponse(w, http.StatusGatewayTimeout, Error{
 			Success: false,
 			Error:   "Timeout waiting for provisioning response (new)",
 			ErrCode: "M_TIMEOUT",
 		})
-		return
 	}
 }