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 more detailed logs for debugging olm decryption delays

Browse source
This commit is contained in:
Tulir Asokan 2021-12-17 00:51:47 +02:00
commit 72d5a9abf0
4 changed files with 44 additions and 14 deletions
Download patch file Download diff file Expand all files Collapse all files

34
crypto/decryptolm.go
View file

@ -43,7 +43,7 @@ type DecryptedOlmEvent struct {
Content event.Content `json:"content"`
}
func (mach *OlmMachine) decryptOlmEvent(evt *event.Event) (*DecryptedOlmEvent, error) {
func (mach *OlmMachine) decryptOlmEvent(evt *event.Event, traceID string) (*DecryptedOlmEvent, error) {
content, ok := evt.Content.Parsed.(*event.EncryptedEventContent)
if !ok {
return nil, IncorrectEncryptedContentType
@ -54,7 +54,7 @@ func (mach *OlmMachine) decryptOlmEvent(evt *event.Event) (*DecryptedOlmEvent, e
if !ok {
return nil, NotEncryptedForMe
}
decrypted, err := mach.decryptAndParseOlmCiphertext(evt.Sender, content.SenderKey, ownContent.Type, ownContent.Body)
decrypted, err := mach.decryptAndParseOlmCiphertext(evt.Sender, content.SenderKey, ownContent.Type, ownContent.Body, traceID)
if err != nil {
return nil, err
}
@ -66,16 +66,20 @@ type OlmEventKeys struct {
Ed25519 id.Ed25519 `json:"ed25519"`
}
func (mach *OlmMachine) decryptAndParseOlmCiphertext(sender id.UserID, senderKey id.SenderKey, olmType id.OlmMsgType, ciphertext string) (*DecryptedOlmEvent, error) {
func (mach *OlmMachine) decryptAndParseOlmCiphertext(sender id.UserID, senderKey id.SenderKey, olmType id.OlmMsgType, ciphertext string, traceID string) (*DecryptedOlmEvent, error) {
if olmType != id.OlmMsgTypePreKey && olmType != id.OlmMsgTypeMsg {
return nil, UnsupportedOlmMessageType
}
plaintext, err := mach.tryDecryptOlmCiphertext(sender, senderKey, olmType, ciphertext)
endTimeTrace := mach.timeTrace("decrypting olm ciphertext", traceID, 5*time.Second)
plaintext, err := mach.tryDecryptOlmCiphertext(sender, senderKey, olmType, ciphertext, traceID)
endTimeTrace()
if err != nil {
return nil, err
}
defer mach.timeTrace("parsing decrypted olm event", traceID, time.Second)()
var olmEvt DecryptedOlmEvent
err = json.Unmarshal(plaintext, &olmEvt)
if err != nil {
@ -99,11 +103,13 @@ func (mach *OlmMachine) decryptAndParseOlmCiphertext(sender id.UserID, senderKey
return &olmEvt, nil
}
func (mach *OlmMachine) tryDecryptOlmCiphertext(sender id.UserID, senderKey id.SenderKey, olmType id.OlmMsgType, ciphertext string) ([]byte, error) {
func (mach *OlmMachine) tryDecryptOlmCiphertext(sender id.UserID, senderKey id.SenderKey, olmType id.OlmMsgType, ciphertext string, traceID string) ([]byte, error) {
endTimeTrace := mach.timeTrace("waiting for olm lock", traceID, 5*time.Second)
mach.olmLock.Lock()
endTimeTrace()
defer mach.olmLock.Unlock()
plaintext, err := mach.tryDecryptOlmCiphertextWithExistingSession(senderKey, olmType, ciphertext)
plaintext, err := mach.tryDecryptOlmCiphertextWithExistingSession(senderKey, olmType, ciphertext, traceID)
if err != nil {
if err == DecryptionFailedWithMatchingSession {
mach.Log.Warn("Found matching session yet decryption failed for sender %s with key %s", sender, senderKey)
@ -127,34 +133,44 @@ func (mach *OlmMachine) tryDecryptOlmCiphertext(sender id.UserID, senderKey id.S
}
mach.Log.Trace("Trying to create inbound session for %s/%s", sender, senderKey)
endTimeTrace = mach.timeTrace("creating inbound olm session", traceID, time.Second)
session, err := mach.createInboundSession(senderKey, ciphertext)
endTimeTrace()
if err != nil {
go mach.unwedgeDevice(sender, senderKey)
return nil, fmt.Errorf("failed to create new session from prekey message: %w", err)
}
mach.Log.Debug("Created inbound olm session %s for %s/%s: %s", session.ID(), sender, senderKey, session.Describe())
endTimeTrace = mach.timeTrace(fmt.Sprintf("decrypting prekey olm message with %s/%s", senderKey, session.ID()), traceID, time.Second)
plaintext, err = session.Decrypt(ciphertext, olmType)
endTimeTrace()
if err != nil {
return nil, fmt.Errorf("failed to decrypt olm event with session created from prekey message: %w", err)
}
endTimeTrace = mach.timeTrace(fmt.Sprintf("updating new session %s/%s in database", senderKey, session.ID()), traceID, time.Second)
err = mach.CryptoStore.UpdateSession(senderKey, session)
endTimeTrace()
if err != nil {
mach.Log.Warn("Failed to update new olm session in crypto store after decrypting: %v", err)
}
return plaintext, nil
}
func (mach *OlmMachine) tryDecryptOlmCiphertextWithExistingSession(senderKey id.SenderKey, olmType id.OlmMsgType, ciphertext string) ([]byte, error) {
func (mach *OlmMachine) tryDecryptOlmCiphertextWithExistingSession(senderKey id.SenderKey, olmType id.OlmMsgType, ciphertext string, traceID string) ([]byte, error) {
endTimeTrace := mach.timeTrace(fmt.Sprintf("getting sessions with %s", senderKey), traceID, time.Second)
sessions, err := mach.CryptoStore.GetSessions(senderKey)
endTimeTrace()
if err != nil {
return nil, fmt.Errorf("failed to get session for %s: %w", senderKey, err)
}
for _, session := range sessions {
if olmType == id.OlmMsgTypePreKey {
endTimeTrace = mach.timeTrace(fmt.Sprintf("checking if prekey olm message matches session %s/%s", senderKey, session.ID()), traceID, time.Second)
matches, err := session.Internal.MatchesInboundSession(ciphertext)
endTimeTrace()
if err != nil {
return nil, fmt.Errorf("failed to check if ciphertext matches inbound session: %w", err)
} else if !matches {
@ -162,13 +178,17 @@ func (mach *OlmMachine) tryDecryptOlmCiphertextWithExistingSession(senderKey id.
}
}
mach.Log.Trace("Trying to decrypt olm message from %s with session %s: %s", senderKey, session.ID(), session.Describe())
endTimeTrace = mach.timeTrace(fmt.Sprintf("decrypting olm message with %s/%s", senderKey, session.ID()), traceID, time.Second)
plaintext, err := session.Decrypt(ciphertext, olmType)
endTimeTrace()
if err != nil {
if olmType == id.OlmMsgTypePreKey {
return nil, DecryptionFailedWithMatchingSession
}
} else {
endTimeTrace = mach.timeTrace(fmt.Sprintf("updating session %s/%s in database", senderKey, session.ID()), traceID, time.Second)
err = mach.CryptoStore.UpdateSession(senderKey, session)
endTimeTrace()
if err != nil {
mach.Log.Warn("Failed to update olm session in crypto store after decrypting: %v", err)
}

2
crypto/encryptmegolm.go
View file

@ -85,7 +85,7 @@ func (mach *OlmMachine) EncryptMegolmEvent(roomID id.RoomID, evtType event.Type,
func (mach *OlmMachine) newOutboundGroupSession(roomID id.RoomID) *OutboundGroupSession {
session := NewOutboundGroupSession(roomID, mach.StateStore.GetEncryptionEvent(roomID))
signingKey, idKey := mach.account.Keys()
mach.createGroupSession(idKey, signingKey, roomID, session.ID(), session.Internal.Key())
mach.createGroupSession(idKey, signingKey, roomID, session.ID(), session.Internal.Key(), "create")
return session
}

20
crypto/machine.go
View file

@ -131,6 +131,16 @@ func (mach *OlmMachine) FlushStore() error {
return mach.CryptoStore.Flush()
}
func (mach *OlmMachine) timeTrace(thing, trace string, expectedDuration time.Duration) func() {
start := time.Now()
return func() {
duration := time.Now().Sub(start)
if duration > expectedDuration {
mach.Log.Warn("%s took %s (trace: %s)", thing, duration, trace)
}
}
}
func Fingerprint(signingKey id.SigningKey) string {
spacedSigningKey := make([]byte, len(signingKey)+(len(signingKey)-1)/4)
var ptr = 0
@ -279,7 +289,7 @@ func (mach *OlmMachine) HandleToDeviceEvent(evt *event.Event) {
switch content := evt.Content.Parsed.(type) {
case *event.EncryptedEventContent:
mach.Log.Debug("Handling encrypted to-device event from %s/%s (trace: %s)", evt.Sender, content.SenderKey, traceID)
decryptedEvt, err := mach.decryptOlmEvent(evt)
decryptedEvt, err := mach.decryptOlmEvent(evt, traceID)
if err != nil {
mach.Log.Error("Failed to decrypt to-device event: %v (trace: %s)", err, traceID)
return
@ -288,7 +298,7 @@ func (mach *OlmMachine) HandleToDeviceEvent(evt *event.Event) {
switch decryptedContent := decryptedEvt.Content.Parsed.(type) {
case *event.RoomKeyEventContent:
mach.receiveRoomKey(decryptedEvt, decryptedContent)
mach.receiveRoomKey(decryptedEvt, decryptedContent, traceID)
mach.Log.Trace("Handled room key event from %s/%s (trace: %s)", decryptedEvt.Sender, decryptedEvt.SenderDevice, traceID)
case *event.ForwardedRoomKeyEventContent:
if mach.importForwardedRoomKey(decryptedEvt, decryptedContent) {
@ -406,7 +416,7 @@ func (mach *OlmMachine) SendEncryptedToDevice(device *DeviceIdentity, evtType ev
return err
}
func (mach *OlmMachine) createGroupSession(senderKey id.SenderKey, signingKey id.Ed25519, roomID id.RoomID, sessionID id.SessionID, sessionKey string) {
func (mach *OlmMachine) createGroupSession(senderKey id.SenderKey, signingKey id.Ed25519, roomID id.RoomID, sessionID id.SessionID, sessionKey string, traceID string) {
igs, err := NewInboundGroupSession(senderKey, signingKey, roomID, sessionKey)
if err != nil {
mach.Log.Error("Failed to create inbound group session: %v", err)
@ -454,14 +464,14 @@ func (mach *OlmMachine) WaitForSession(roomID id.RoomID, senderKey id.SenderKey,
}
}
func (mach *OlmMachine) receiveRoomKey(evt *DecryptedOlmEvent, content *event.RoomKeyEventContent) {
func (mach *OlmMachine) receiveRoomKey(evt *DecryptedOlmEvent, content *event.RoomKeyEventContent, traceID string) {
// TODO nio had a comment saying "handle this better" for the case where evt.Keys.Ed25519 is none?
if content.Algorithm != id.AlgorithmMegolmV1 || evt.Keys.Ed25519 == "" {
mach.Log.Debug("Ignoring weird room key from %s/%s: alg=%s, ed25519=%s, sessionid=%s, roomid=%s", evt.Sender, evt.SenderDevice, content.Algorithm, evt.Keys.Ed25519, content.SessionID, content.RoomID)
return
}
mach.createGroupSession(evt.SenderKey, evt.Keys.Ed25519, content.RoomID, content.SessionID, content.SessionKey)
mach.createGroupSession(evt.SenderKey, evt.Keys.Ed25519, content.RoomID, content.SessionID, content.SessionKey, traceID)
}
func (mach *OlmMachine) handleRoomKeyWithheld(content *event.RoomKeyWithheldEventContent) {

2
crypto/machine_test.go
View file

@ -112,7 +112,7 @@ func TestOlmMachineOlmMegolmSessions(t *testing.T) {
for _, content := range content.OlmCiphertext {
// decrypt olm ciphertext
decrypted, err := machineIn.decryptAndParseOlmCiphertext("user1", senderKey, content.Type, content.Body)
decrypted, err := machineIn.decryptAndParseOlmCiphertext("user1", senderKey, content.Type, content.Body, "test")
if err != nil {
t.Errorf("Error decrypting olm content: %v", err)
}