[lib] improve Olm-related logging
ClosedPublic
Actions

Authored by kamil on May 12 2025, 1:57 PM.

Details

Reviewers

tomek

Commits

rCOMM65ed1ee58423: [lib] improve Olm-related logging

Summary

ENG-10755.

This diff has a lot of changes, but those are easy, not changing logic, and only about logging, so I am publishing this at once.

Note that this diff adds logging to also successful operations, this is needed because without this, we're not able to detect when we decrypt an already decrypted message or perform session reset multiple times.

This should also help us to investigate how many crypto operations we're performing on device.

Created ENG-10765 to revert that after the investigation is done.

Test Plan

Use apps and check that any encrypt/decrypt and session creation operations are logged.

[
  {
    title: 'Olm LOG',
    message:
      '{"operation":"contentInboundSessionCreator","peer":{"userID":"4BB05DB1-C3A2-47A6-9D8C-F40B452CD3D1","deviceID":"Fxn3sy4/SMqMNWc5crKFVAG5rch+/wBiuTMCiuw5z4U"},"encryptedData":{"messageType":0,"sessionVersion":1},"success":true,"resultDescription":"Created inbound session with device Fxn3sy4/SMqMNWc5crKFVAG5rch+/wBiuTMCiuw5z4U: {\\"type\\":\\"init\\"}, session version: 1"}',
    timestamp: 1747130112751,
  },
  {
    title: 'Olm LOG',
    message:
      '{"operation":"decryptAndPersist","messageID":"2025-05-13T09:55:12.462819254+00:00#c640a378-7bf6-4313-b647-bbb807558c38","peer":{"deviceID":"Fxn3sy4/SMqMNWc5crKFVAG5rch+/wBiuTMCiuw5z4U","userID":"4BB05DB1-C3A2-47A6-9D8C-F40B452CD3D1"},"encryptedData":{"messageType":0,"sessionVersion":1},"decryptedData":{"type":"DM_OPERATION","dmOpData":{"type":"create_thread"}},"success":true,"resultDescription":"Decrypted message from device Fxn3sy4/SMqMNWc5crKFVAG5rch+/wBiuTMCiuw5z4U"}',
    timestamp: 1747130112794,
  },
  {
    title: 'Olm LOG',
    message:
      '{"operation":"decryptAndPersist","messageID":"2025-05-13T09:55:12.815972364+00:00#ca9604c6-c5c3-4f91-8306-6fdfeff25b78","peer":{"deviceID":"Fxn3sy4/SMqMNWc5crKFVAG5rch+/wBiuTMCiuw5z4U","userID":"4BB05DB1-C3A2-47A6-9D8C-F40B452CD3D1"},"encryptedData":{"messageType":0,"sessionVersion":1},"decryptedData":{"type":"DM_OPERATION","dmOpData":{"type":"send_text_message","messageID":"ea6433cd-91d1-4dc8-bfb3-b592c7af29e4"}},"success":true,"resultDescription":"Decrypted message from device Fxn3sy4/SMqMNWc5crKFVAG5rch+/wBiuTMCiuw5z4U"}',
    timestamp: 1747130112921,
  },
  {
    title: 'Olm LOG',
    message:
      '{"operation":"decryptAndPersist","messageID":"2025-05-13T09:55:16.877479677+00:00#8ca04a65-4a67-4aa4-93c0-26694139b4fd","peer":{"deviceID":"Fxn3sy4/SMqMNWc5crKFVAG5rch+/wBiuTMCiuw5z4U","userID":"4BB05DB1-C3A2-47A6-9D8C-F40B452CD3D1"},"encryptedData":{"messageType":0,"sessionVersion":1},"decryptedData":{"type":"DM_OPERATION","dmOpData":{"type":"update_relationship","messageID":"9cb6e340-34c8-4d30-a0fc-6554de74c440"}},"success":true,"resultDescription":"Decrypted message from device Fxn3sy4/SMqMNWc5crKFVAG5rch+/wBiuTMCiuw5z4U"}',
    timestamp: 1747130116991,
  },
  {
    title: 'Olm LOG',
    message:
      '{"operation":"decryptAndPersist","messageID":"2025-05-13T09:55:27.530006288+00:00#b4589f0b-c733-4d85-b079-3cbcf74fc418","peer":{"deviceID":"Fxn3sy4/SMqMNWc5crKFVAG5rch+/wBiuTMCiuw5z4U","userID":"4BB05DB1-C3A2-47A6-9D8C-F40B452CD3D1"},"encryptedData":{"messageType":0,"sessionVersion":1},"decryptedData":{"type":"DM_OPERATION","dmOpData":{"type":"send_reaction_message","messageID":"cdc43a50-79e1-4468-9cba-443a0c1544c6","targetMessageID":"ea6433cd-91d1-4dc8-bfb3-b592c7af29e4"}},"success":true,"resultDescription":"Decrypted message from device Fxn3sy4/SMqMNWc5crKFVAG5rch+/wBiuTMCiuw5z4U"}',
    timestamp: 1747130127522,
  },
  {
    title: 'Olm LOG',
    message:
      '{"operation":"decryptAndPersist","messageID":"2025-05-13T09:55:40.260596449+00:00#b6ed7a04-af09-4e74-98d6-2870241e2e7c","peer":{"deviceID":"Fxn3sy4/SMqMNWc5crKFVAG5rch+/wBiuTMCiuw5z4U","userID":"4BB05DB1-C3A2-47A6-9D8C-F40B452CD3D1"},"encryptedData":{"messageType":0,"sessionVersion":1},"decryptedData":{"type":"DM_OPERATION","dmOpData":{"type":"create_sidebar","sourceMessageID":"ea6433cd-91d1-4dc8-bfb3-b592c7af29e4"}},"success":true,"resultDescription":"Decrypted message from device Fxn3sy4/SMqMNWc5crKFVAG5rch+/wBiuTMCiuw5z4U"}',
    timestamp: 1747130140240,
  },
  {
    title: 'Olm LOG',
    message:
      '{"operation":"decryptAndPersist","messageID":"2025-05-13T09:55:41.744899466+00:00#aae9d6f4-bdb3-44b6-8d51-cff3fe23a9a9","peer":{"deviceID":"Fxn3sy4/SMqMNWc5crKFVAG5rch+/wBiuTMCiuw5z4U","userID":"4BB05DB1-C3A2-47A6-9D8C-F40B452CD3D1"},"encryptedData":{"messageType":0,"sessionVersion":1},"decryptedData":{"type":"DM_OPERATION","dmOpData":{"type":"send_text_message","messageID":"cfd0a079-e065-4de1-81df-118159ab7c37"}},"success":true,"resultDescription":"Decrypted message from device Fxn3sy4/SMqMNWc5crKFVAG5rch+/wBiuTMCiuw5z4U"}',
    timestamp: 1747130141717,
  },
  {
    title: 'Olm LOG',
    message:
      '{"operation":"encryptAndPersist","messageID":"84424ee9-3602-4711-878e-0132d9b2d940","peer":{"userID":"BE0476AD-BF60-44C6-9207-C6B6C04FF1EF","deviceID":"HSiyzNA8/VONsPV58tXhsNgHRHEvxPeQJXmmzx5gdx0"},"status":"persisted","supportsAutoRetry":true,"success":true,"resultDescription":"message encrypted"}',
    timestamp: 1747130148196,
  },
  {
    title: 'Olm LOG',
    message:
      '{"operation":"encryptAndPersist","messageID":"e2734826-be87-4897-8361-ef5d80f6ee1e","peer":{"userID":"BE0476AD-BF60-44C6-9207-C6B6C04FF1EF","deviceID":"HSiyzNA8/VONsPV58tXhsNgHRHEvxPeQJXmmzx5gdx0"},"status":"persisted","supportsAutoRetry":true,"success":true,"resultDescription":"message encrypted"}',
    timestamp: 1747130148979,
  },
  {
    title: 'Olm LOG',
    message:
      '{"operation":"encryptAndPersist","messageID":"74cd1079-981e-4959-b646-dc8d6ab62edf","peer":{"userID":"BE0476AD-BF60-44C6-9207-C6B6C04FF1EF","deviceID":"HSiyzNA8/VONsPV58tXhsNgHRHEvxPeQJXmmzx5gdx0"},"status":"persisted","supportsAutoRetry":true,"success":true,"resultDescription":"message encrypted"}',
    timestamp: 1747130155141,
  },
];