Skip to content

Commit

Permalink
provisioning/{LinkWaitForScan,LinkWaitForAccount}: use structured log…
Browse files Browse the repository at this point in the history 
…ging

Signed-off-by: Sumner Evans <[email protected]>
  • Loading branch information
@sumnerevans
sumnerevans committed Dec 30, 2023
1 parent 87e73c7 commit 0135941
Showing 1 changed file with 47 additions and 26 deletions.
73 changes: 47 additions & 26 deletions provisioning.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -370,11 +370,12 @@ func (prov *ProvisioningAPI) loginOrSendError(ctx context.Context, w http.Respon
return handle, nil
}

func (prov *ProvisioningAPI) checkSessionAndReturnHandle(w http.ResponseWriter, r *http.Request, currentSession int) *provisioningHandle {
user := r.Context().Value("user").(*User)
func (prov *ProvisioningAPI) checkSessionAndReturnHandle(ctx context.Context, w http.ResponseWriter, currentSession int) *provisioningHandle {
log := zerolog.Ctx(ctx).With().Str("function", "checkSessionAndReturnHandle").Logger()
user := ctx.Value("user").(*User)
handle := prov.existingSession(user)
if handle == nil {
prov.log.Warn().Msgf("checkSessionAndReturnHandle: from %v, no session found", user.MXID)
log.Warn().Msg("no session found")
jsonResponse(w, http.StatusNotFound, Error{
Success: false,
Error: "No session found",
Expand All @@ -383,7 +384,10 @@ func (prov *ProvisioningAPI) checkSessionAndReturnHandle(w http.ResponseWriter,
return nil
}
if handle.id != currentSession {
prov.log.Warn().Msgf("checkSessionAndReturnHandle: from %v, session_id %v does not match user's current session_id %v", user.MXID, currentSession, handle.id)
log.Warn().
Int("handle_id", handle.id).
Int("current_session", currentSession).
Msg("session_id does not match user's session_id")
jsonResponse(w, http.StatusBadRequest, Error{
Success: false,
Error: "session_id does not match user's session_id",
Expand Down Expand Up @@ -456,11 +460,13 @@ func (prov *ProvisioningAPI) LinkNew(w http.ResponseWriter, r *http.Request) {
}
}

type LinkWaitForScanRequest struct {
SessionID string `json:"session_id"`
}

func (prov *ProvisioningAPI) LinkWaitForScan(w http.ResponseWriter, r *http.Request) {
user := r.Context().Value("user").(*User)
body := struct {
SessionID string `json:"session_id"`
}{}
var body LinkWaitForScanRequest
err := json.NewDecoder(r.Body).Decode(&body)
if err != nil {
jsonResponse(w, http.StatusBadRequest, Error{
Expand All @@ -480,20 +486,26 @@ func (prov *ProvisioningAPI) LinkWaitForScan(w http.ResponseWriter, r *http.Requ
return
}

prov.log.Debug().Msgf("LinkWaitForScan from %v, session_id: %v", user.MXID, sessionID)
log := prov.log.With().
Str("action", "link_wait_for_scan").
Str("user_id", user.MXID.String()).
Str("session_id", body.SessionID).
Logger()
ctx := log.WithContext(r.Context())
log.Debug().Msg("waiting for scan")

handle := prov.checkSessionAndReturnHandle(w, r, sessionID)
handle := prov.checkSessionAndReturnHandle(ctx, w, sessionID)
if handle == nil {
return
}

select {
case resp := <-handle.channel:
if resp.Err != nil || resp.State == signalmeow.StateProvisioningError {
prov.log.Err(resp.Err).Msg("Error waiting for scan")
log.Err(resp.Err).Msg("Error waiting for scan")
// If context was cancelled be chill
if errors.Is(resp.Err, context.Canceled) {
prov.log.Debug().Msg("Context cancelled waiting for scan")
log.Debug().Msg("Context cancelled waiting for scan")
return
}
// If we error waiting for the scan, treat it as a normal error not 5xx
Expand All @@ -507,15 +519,15 @@ func (prov *ProvisioningAPI) LinkWaitForScan(w http.ResponseWriter, r *http.Requ
return
}
if resp.State != signalmeow.StateProvisioningDataReceived {
prov.log.Err(err).Msgf("LinkWaitForScan 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("LinkWaitForScan from %v, provisioning data received", user.MXID)
log.Debug().Msg("provisioning data received")
jsonResponse(w, http.StatusOK, Response{
Success: true,
Status: "provisioning_data_received",
Expand All @@ -529,7 +541,7 @@ func (prov *ProvisioningAPI) LinkWaitForScan(w http.ResponseWriter, r *http.Requ
}
return
case <-time.After(45 * time.Second):
prov.log.Warn().Msg("Timeout waiting for provisioning response (scan)")
log.Warn().Msg("Timeout waiting for provisioning response (scan)")
// Using 400 here to match the old bridge
jsonResponse(w, http.StatusBadRequest, Error{
Success: false,
Expand All @@ -540,12 +552,14 @@ func (prov *ProvisioningAPI) LinkWaitForScan(w http.ResponseWriter, r *http.Requ
}
}

type LinkWaitForAccountRequest struct {
SessionID string `json:"session_id"`
DeviceName string `json:"device_name"` // TODO this seems to not be used anywhere
}

func (prov *ProvisioningAPI) LinkWaitForAccount(w http.ResponseWriter, r *http.Request) {
user := r.Context().Value("user").(*User)
body := struct {
SessionID string `json:"session_id"`
DeviceName string `json:"device_name"`
}{}
var body LinkWaitForAccountRequest
err := json.NewDecoder(r.Body).Decode(&body)
if err != nil {
jsonResponse(w, http.StatusBadRequest, Error{
Expand All @@ -566,17 +580,24 @@ func (prov *ProvisioningAPI) LinkWaitForAccount(w http.ResponseWriter, r *http.R
}
deviceName := body.DeviceName

prov.log.Debug().Msgf("LinkWaitForAccount from %v, session_id: %v, device_name: %v", user.MXID, sessionID, deviceName)
log := prov.log.With().
Str("action", "link_wait_for_account").
Str("user_id", user.MXID.String()).
Int("session_id", sessionID).
Str("device_name", deviceName).
Logger()
ctx := log.WithContext(r.Context())
log.Debug().Msg("waiting for account")

handle := prov.checkSessionAndReturnHandle(w, r, sessionID)
handle := prov.checkSessionAndReturnHandle(ctx, w, sessionID)
if handle == nil {
return
}

select {
case resp := <-handle.channel:
if resp.Err != nil || resp.State == signalmeow.StateProvisioningError {
prov.log.Err(resp.Err).Msg("Error waiting for account")
log.Err(resp.Err).Msg("Error waiting for account")
jsonResponse(w, http.StatusInternalServerError, Error{
Success: false,
Error: resp.Err.Error(),
Expand All @@ -585,16 +606,16 @@ func (prov *ProvisioningAPI) LinkWaitForAccount(w http.ResponseWriter, r *http.R
return
}
if resp.State != signalmeow.StateProvisioningPreKeysRegistered {
prov.log.Err(err).Msgf("LinkWaitForAccount 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("LinkWaitForAccount from %v, prekeys registered", user.MXID)
log.Debug().Msg("prekeys registered")
jsonResponse(w, http.StatusOK, Response{
Success: true,
Status: "prekeys_registered",
Expand All @@ -606,7 +627,7 @@ func (prov *ProvisioningAPI) LinkWaitForAccount(w http.ResponseWriter, r *http.R
user.Connect()
return
case <-time.After(30 * time.Second):
prov.log.Warn().Msg("Timeout waiting for provisioning response (account)")
log.Warn().Msg("Timeout waiting for provisioning response (account)")
jsonResponse(w, http.StatusGatewayTimeout, Error{
Success: false,
Error: "Timeout waiting for provisioning response (account)",
Expand Down

0 comments on commit 0135941

Please sign in to comment.