diff --git a/crypto/decryptolm.go b/crypto/decryptolm.go index 9cd5c336..1ece7ec4 100644 --- a/crypto/decryptolm.go +++ b/crypto/decryptolm.go @@ -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) } diff --git a/crypto/encryptmegolm.go b/crypto/encryptmegolm.go index 0f55fddf..5eb6519d 100644 --- a/crypto/encryptmegolm.go +++ b/crypto/encryptmegolm.go @@ -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 } diff --git a/crypto/machine.go b/crypto/machine.go index a7d9bcf5..e61d4468 100644 --- a/crypto/machine.go +++ b/crypto/machine.go @@ -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) { diff --git a/crypto/machine_test.go b/crypto/machine_test.go index b8ccc948..27d917dc 100644 --- a/crypto/machine_test.go +++ b/crypto/machine_test.go @@ -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) }