deblan-mirror/mautrix-go
1
0
Fork 0
mirror of https://mau.dev/mautrix/go.git synced 2026-03-14 14:25:53 +01:00
Code Issues Projects Releases Packages Wiki Activity Actions 2

Add some logs and utilities for tracking message handling duration

Browse source
This commit is contained in:
Tulir Asokan 2022-07-11 13:35:51 +03:00
commit a5a1e7e5df
4 changed files with 16 additions and 6 deletions
Download patch file Download diff file Expand all files Collapse all files

1
appservice/http.go
View file

@ -182,6 +182,7 @@ func (as *AppService) handleDeviceLists(dl *mautrix.DeviceLists) {
func (as *AppService) handleEvents(evts []*event.Event, defaultTypeClass event.TypeClass) {
for _, evt := range evts {
evt.Mautrix.ReceivedAt = time.Now()
if len(evt.ToUserID) > 0 {
evt.Type.Class = event.ToDeviceEventType
} else if defaultTypeClass != event.UnknownEventType {

16
bridge/matrix.go
View file

@ -381,7 +381,7 @@ func deviceUnverifiedErrorWithExplanation(trust id.TrustState) error {
return fmt.Errorf("%w (%s)", errDeviceNotTrusted, explanation)
}
func (mx *MatrixHandler) postDecrypt(decrypted *event.Event, retryCount int, errorEventID id.EventID) {
func (mx *MatrixHandler) postDecrypt(decrypted *event.Event, retryCount int, errorEventID id.EventID, duration time.Duration) {
minLevel := mx.bridge.Config.Bridge.GetEncryptionConfig().VerificationLevels.Send
if decrypted.Mautrix.TrustState < minLevel {
deviceDesc := "unknown device"
@ -397,6 +397,8 @@ func (mx *MatrixHandler) postDecrypt(decrypted *event.Event, retryCount int, err
mx.bridge.SendMessageSuccessCheckpoint(decrypted, MsgStepDecrypted, retryCount)
decrypted.Mautrix.CheckpointSent = true
decrypted.Mautrix.DecryptionDuration = duration
mx.log.Debugfln("Successfully decrypted %s", decrypted.ID)
mx.bridge.EventProcessor.Dispatch(decrypted)
if errorEventID != "" {
_, _ = mx.bridge.Bot.RedactEvent(decrypted.RoomID, errorEventID)
@ -408,19 +410,21 @@ func (mx *MatrixHandler) HandleEncrypted(evt *event.Event) {
if mx.shouldIgnoreEvent(evt) || mx.bridge.Crypto == nil {
return
}
content := evt.Content.AsEncrypted()
mx.log.Debugfln("Decrypting %s (%s)", evt.ID, content.SessionID)
decryptionStart := time.Now()
decrypted, err := mx.bridge.Crypto.Decrypt(evt)
decryptionRetryCount := 0
if errors.Is(err, NoSessionFound) {
decryptionRetryCount = 1
content := evt.Content.AsEncrypted()
mx.log.Debugfln("Couldn't find session %s trying to decrypt %s, waiting %d seconds...", content.SessionID, evt.ID, int(sessionWaitTimeout.Seconds()))
mx.bridge.SendMessageErrorCheckpoint(evt, MsgStepDecrypted, err, false, 0)
if mx.bridge.Crypto.WaitForSession(evt.RoomID, content.SenderKey, content.SessionID, sessionWaitTimeout) {
mx.log.Debugfln("Got session %s after waiting, trying to decrypt %s again", content.SessionID, evt.ID)
decrypted, err = mx.bridge.Crypto.Decrypt(evt)
} else {
go mx.waitLongerForSession(evt)
go mx.waitLongerForSession(evt, decryptionStart)
return
}
}
@ -430,13 +434,13 @@ func (mx *MatrixHandler) HandleEncrypted(evt *event.Event) {
go mx.sendCryptoStatusError(evt, "", err, decryptionRetryCount, true)
return
}
mx.postDecrypt(decrypted, decryptionRetryCount, "")
mx.postDecrypt(decrypted, decryptionRetryCount, "", time.Since(decryptionStart))
}
const firstDecryptionErrorMsg = "the bridge hasn't received the decryption keys. The bridge will retry for %d seconds"
const finalDecryptionErrorMsg = "the bridge hasn't received the decryption keys"
func (mx *MatrixHandler) waitLongerForSession(evt *event.Event) {
func (mx *MatrixHandler) waitLongerForSession(evt *event.Event, decryptionStart time.Time) {
const extendedTimeout = sessionWaitTimeout * 2
content := evt.Content.AsEncrypted()
@ -460,7 +464,7 @@ func (mx *MatrixHandler) waitLongerForSession(evt *event.Event) {
return
}
mx.postDecrypt(decrypted, 2, errorEventID)
mx.postDecrypt(decrypted, 2, errorEventID, time.Since(decryptionStart))
}
func (mx *MatrixHandler) HandleMessage(evt *event.Event) {

1
crypto/decryptmegolm.go
View file

@ -129,6 +129,7 @@ func (mach *OlmMachine) DecryptMegolmEvent(evt *event.Event) (*event.Event, erro
TrustSource: device,
ForwardedKeys: forwardedKeys,
WasEncrypted: true,
ReceivedAt: evt.Mautrix.ReceivedAt,
},
}, nil
}

4
event/events.go
View file

@ -8,6 +8,7 @@ package event
import (
"encoding/json"
"time"
"maunium.net/go/mautrix/id"
)
@ -109,6 +110,9 @@ type MautrixInfo struct {
WasEncrypted bool
TrustSource *id.Device
ReceivedAt time.Time
DecryptionDuration time.Duration
CheckpointSent bool
}