provisioning/LinkNew: use structured logging

Signed-off-by: Sumner Evans <[email protected]>

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
  }
 }