Quick Improvement on existing log format to ease debugging

[BillCarsonFr]

Come with a best log format / content => Improve the logs with session ID / sender key, we log the same thing
+> Apply on each platform

Existing
Web
```2021-10-05T14:19:50.676Z I m.room_key_request cancellation for @hubert:uhoreg.ca:KQWTWCJCOX (id m1633443579272.2) 2021-10-05T14:19:53.040Z I received to_device m.room.encrypted from: @dgrig:erethon.com id: undefined 2021-10-05T14:19:53.164Z I decryptMessage: Olm Session ID ExxsoxdVt9gJw6PTVcKc5cfzN5sZagfdl7+sUcmc+sU from p5YY7dWIzxugh38oPX9IRat6KQEFWnDGR36uLLg4Mmo: sender chain index: 0 receiver chain indices: 2 1 1 1 1 skipped message keys:```

Goal:

Add some Tags/Data to each line related to a message encryption that would allow to quickly filter out all relevant lines for debugging an issue.

[poljar]

What's the expected timeline for this? We discussed that I should check and write down when we should log and what we should log, but the issue also mentions that this should be applied to every client?

Is the expectation here to also fix the clients or just write down things?

[BillCarsonFr]

Is the expectation here to also fix the clients or just write down things?

Just write down the things

[poljar]

How to read this:

Each number denotes a operation that the crypto layer needs to go through before
it can encrypt or decrypt m.megolm.v1.aes-sha2 messages. Each numbered item
might have multiple items describing a log line.

The log line starts with the log level, followed by a description separated by a
colon. The next lines staring with Data then describe a list of structured
data that should be attached to the log entry.

Encryption

1. Collect room key recipients

   • Debug: Note down the list of users that should get a room key
     Data:
     * [UserId]

2. Claim keys for recipients that don't have an Olm session

   • Debug: Note down the list of users that we're going to claim keys for
     Data: Map<UserId, Map<DeviceId, DeviceKeyAlgorithm>>
   • Warn: If a device doesn't support our m.olm.v1.curve25519-aes-sha2 algorithm
     Data:
     * UserId,
     * DeviceId,
     * [Algorithms],
   • Warn: If a device doesn't have a curve25519 key.

3. Handle the keys/claim response and establish new Olm sessions

   • Debug: Log the failures that were part of the request
     Data:
     * Map<ServerName, Object>
   • Info: Note down the list of newly established Olm sessions
     Data:
     * Map<UserId, Set<DeviceId>>
   • Warn: If a device can't be found, so we don't have the curve25519 key for the 3DH
     Data:
     * UserId,
     * DeviceId,
   • Warn: If the Olm session couldn't be established (e.g. signature error, invalid key)
     Data:
     * UserId,
     * DeviceId,
     * Error,

4. Encrypt the room key using each recipients Olm session

   • Info: Note down all the user/device pairs that should get a room key
     Data:
     * Map<UserId, Set<DeviceId>,
     * RoomId,
     * SessionId,
   • Info: Note down all the user/device pairs that the room key was encrypted for,
     and the user/device pairs the room key was witheld from. If possible, note
     down the transaction ids the to-device requests will use.
     Data:
     * Map<UserId, Set<DeviceId>,
     * Map<UserId, Map<DeviceId, WithHeldReason>,
     * [TransactionId],
     * RoomId,
     * SessionId,

5. Mark the to-device request from step 4. as sent

   • Info: Request carrying a room key was sent
     Data:
     * Map<UserId, Set<DeviceId>,
     * TransactionId,

Decryption

Decrypting to-device events

1. Receive a to-device message

   • Trace: Log that we're attempting to decrypt a to-device event
     Data:
     * sender,
   • Warn: If the algorithm isn't supported
     Data:
     * sender,
     * algorithm,
   • Warn: If the message doesn't contain a ciphertext for us.
     * sender,
     * sender_key,
   • Warn: If the message is missing event fields or has an invalid Olm message_type
     * sender,
     * sender_key,
     * error,

2. Attempt to decrypt the to-device message with existing sessions

   • Warn: If a matching session is found, but decryption failed
     Data:
     * sender,
     * sender_key,
     * error,
   • Warn: If decryption failed with every available session and the Olm message isn't a pre-key message
     Data:
     * sender,
     * sender_key,

3. If decryption failed with all existing sessions, attempt to create a new session

   • Warn: If we fail to create a new session from a pre-key message
     Data:
     * sender,
     * sender_key,
     * error,

   • Info: Log if decryption failed because the Olm message got replayed
     Data:
     * sender,
     * sender_key,

   • Warn: If we failed to decrypt the message for any other reason.
     Data:
     * sender,
     * sender_key,

   • Info: Log if we're marking the session to be unwedged
     Data:
     * sender,
     * sender_key,

4. Parsing and handling of the decrypted to-device event

   • Warn: If the event fails to validate/deserialize
     Data:
     * sender,
     * sender_key,
     * error,
   • Trace: Note down that we received a to-device event that was decrypted
     Data:
     * sender,
     * sender_key,
     * event_type,
   • Info: Note down that we received a room key, mention if the room key is forwarded or not
     Data:
     * sender,
     * sender_key,
     * room_id,
     * session_id,
   • Warn: If a received room key couldn't produce a group session of if the algorithm is unsupported
     Data:
     * sender,
     * sender_key,
     * room_id,
     * algorithm,
   • Info: Log if we received a forwarded room key but we already have a better version of it
     Data:
     * sender,
     * sender_key,
     * claimed_sender_key,
     * room_id,
     * session_id,
   • Warn: If we received a forwarded room key that we did not request.
     Data:
     * sender,
     * sender_key,
     * claimed_sender_key,
     * room_id,
     * session_id,

Decrypting room events

1. Decrypting the event
   • Debug: If decryption fails because the room key is missing
     Data:
     * sender,
     * sender_key,
     * room_id,
     * session_id,
     * withheld_reason¹,
   • Warn: If decryption fails for some other reason (storage error, invalid event format, metadata mismatch)
     Data:
     * sender,
     * sender_key,
     * room_id,
     * session_id,
     * error,

Footnotes

1. The withheld reason might be missing in many cases, but we should log this if it's available. ↩

[poljar]

So this should be it for the encryption/decryption codepaths. There are some other places which we'll need to improve:

1. If lazy loading is enabled we need to fetch the members in a separate request since they won't arrive through the sync response. Have members been synced, was there an error fetching the list of members from the store...
2. Device tracking and /keys/query response handling.

Both of those places might cause a room key not arriving at a given device or multiple devices.

The related rust-sdk PR can be found here: matrix-org/matrix-rust-sdk#383

[poljar]

Oh another thing. If we figure out from real world usage that the logging levels should be modified or if something should be added/removed, we should probably modify this document and have a changelog at the end.

This will allow the modifications to propagate to the implementations more easily since people can check which modifications they need to do.