crypto: Log details about olm session after encryption/decryption

[richvdh]

Together with matrix-org/vodozemac#133, this produces output like:

 DEBUG matrix_sdk_crypto::olm::session: Successfully encrypted an event
    olm_session=Session { session_id: "p7/wyUC7jF3QoQykzVS0a4nhwc+GUNxg4IcO/UbND4M", sending_ratchet: DoubleRatchet(ActiveDoubleRatchet { parent_ratchet_key: Some("curve25519:Tm4Tg+61UDj3hdQy9RA8KBqWlrpLRCLsx/LIbg8HIUw"), ratchet_key: RatchetPublicKey("curve25519:0KLirzBvhFYoVEUNtaAMA5xIeRw8DieSFy+8sgWqDwg"), chain_index: 1, .. }), receiving_chains: [ReceiverChain { ratchet_key: "curve25519:HpzTu3kDkFLaL043GvmDa78QkYx5UJw7Eh31ccWlMHQ", chain_index: 1, skipped_message_keys: [], .. }, ReceiverChain { ratchet_key: "curve25519:fvesXrxw35teK2guQ183emcwGbuPE5VUy4EhcfnrkDE", chain_index: 1, skipped_message_keys: [], .. }, ReceiverChain { ratchet_key: "curve25519:iPXoz18BWAEGYHLrXr/JP2xGxCW4QJgRgfHrNK85Y1U", chain_index: 1, skipped_message_keys: [], .. }, ReceiverChain { ratchet_key: "curve25519:Tm4Tg+61UDj3hdQy9RA8KBqWlrpLRCLsx/LIbg8HIUw", chain_index: 2, skipped_message_keys: [], .. }], config: SessionConfig { version: V1 }, .. }
    at /home/rav/work/matrix-rust-sdk/crates/matrix-sdk-crypto/src/olm/session.rs:131
    in matrix_sdk_crypto::identities::device::encrypt with recipient="@t:xps9320.sw1v.org" recipient_device="PWEGIRZHZL" recipient_key=Some("curve25519:IU7l9RQQEBr4Fsuxf8m45o+4FgQ902ZnItiV+hDdbBY") message_id="cb3d3c0ef06a4fc88b9256b0d3793b08"

and:

 DEBUG matrix_sdk_crypto::olm::session: Decrypted an Olm message
    session=Session { session_id: "8QZ5J7zTOTm/CiewTdl0Ogf4NZI3hw0+EfAccBmiY5I", sending_ratchet: DoubleRatchet(InactiveDoubleRatchet { ratchet_key: "curve25519:IzlCl+Rt1JcNCSTVFq9ZWPUsZb3BF5Z7IOaRnAMrZTE", .. }), receiving_chains: [ReceiverChain { ratchet_key: "curve25519:+kCvSHbmusowgJJAnxSEBGvtnPFcdf48xCpOnoyuQWE", chain_index: 1, skipped_message_keys: [], .. }, ReceiverChain { ratchet_key: "curve25519:Ppe7WGeSTHXJXLwp4HZ/HHIEYFh67B/6AwdAf7LwGiY", chain_index: 1, skipped_message_keys: [], .. }, ReceiverChain { ratchet_key: "curve25519:IzlCl+Rt1JcNCSTVFq9ZWPUsZb3BF5Z7IOaRnAMrZTE", chain_index: 3, skipped_message_keys: [], .. }], config: SessionConfig { version: V1 }, .. }
    at /home/rav/work/matrix-rust-sdk/crates/matrix-sdk-crypto/src/olm/session.rs:87
    in matrix_sdk_crypto::olm::account::decrypt_and_parse_olm_message with sender="@a:xps9320.sw1v.org" sender_key="curve25519:Ftj2NSlSQ4XQJWp0JrPlHDaP0/0kW4X+qVhV+pPpPCg" Normal(Message { version: 3, ratchet_key: "curve25519:IzlCl+Rt1JcNCSTVFq9ZWPUsZb3BF5Z7IOaRnAMrZTE", chain_index: 2, .. }) session_id="8QZ5J7zTOTm/CiewTdl0Ogf4NZI3hw0+EfAccBmiY5I"
    in matrix_sdk_crypto::olm::account::decrypt_olm_v1 with sender_key="curve25519:Ftj2NSlSQ4XQJWp0JrPlHDaP0/0kW4X+qVhV+pPpPCg"
    in matrix_sdk_crypto::olm::account::decrypt_to_device_event with algorithm="m.olm.v1.curve25519-aes-sha2"
    in matrix_sdk_crypto::machine::receive_to_device_event with sender="@a:xps9320.sw1v.org" event_type="m.room.encrypted" message_id="a7a6cab1d381427f8c86822b9658de89"
    in matrix_sdk_crypto::machine::receive_sync_changes

[richvdh]

I'm deliberately moving this field from the span, to the individual event. Firstly, it's quite a lot of data and, if there were more than one event in this span, we wouldn't want to log it on every event. More importantly, it's important that we capture the state of the session after the encryption happens (we want to know if it's stepped the DH ratchet, etc.) Given that the state of the session changes over the lifetime of the span, it feels inappropriate to attach it to the span.

[codecov]

Codecov Report

All modified and coverable lines are covered by tests ✅

Project coverage is 83.74%. Comparing base (82bcf48) to head (a952e2e).
Report is 1 commits behind head on main.

Additional details and impacted files

@@           Coverage Diff           @@
##             main    #3242   +/-   ##
=======================================
  Coverage   83.73%   83.74%           
=======================================
  Files         238      238           
  Lines       24567    24565    -2     
=======================================
- Hits        20572    20571    -1     
+ Misses       3995     3994    -1     

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

[poljar]

Don't you want to bump the vodozemac dep as well?

[richvdh]

Well I do, but this can land independently, so I thought I'd put it up for review while we're still dealing with vodozemac PRs.