Upgrading from 0.6.5 to 0.6.6 ends with (CryptoClient) uncaught exception

[stronk7]

Describe the bug Trying to upgrade from sdk 0.6.5. to 0.6.6 consistently get the follow error on startup):

node:internal/process/esm_loader:97
    internalBinding('errors').triggerUncaughtException(
                              ^

[Error: Failed to deserialize or serialize a JSON value missing field `version` at line 1 column 6856] {
  code: 'GenericFailure'
}

To Reproduce Steps to reproduce the behavior:

1. With existing and working bot, already using encrypted rooms, just update to 0.6.6:
   1. npm update matrix-bot-sdk
   2. npm ior npm ci
2. Run the bot and look to logs (LogLevel.DEBUG).
3. Process ends with the error commented above.

Expected behavior The bot starts working normally, like it was with 0.6.5.

Log snippet

...
...
Sun, 28 May 2023 08:41:52 GMT [DEBUG] [MatrixClientLite] End-to-end encryption client created
...
...
Sun, 28 May 2023 08:41:52 GMT [DEBUG] [MatrixHttpClient] (REQ-1) GET https://matrix.example.com/_matrix/client/v3/account/whoami
Sun, 28 May 2023 08:41:53 GMT [DEBUG] [MatrixHttpClient] (REQ-2) GET https://matrix.example.com/_matrix/client/v3/user/%40nextbotdev%3Aexample.com/account_data/m.direct
Sun, 28 May 2023 08:41:53 GMT [DEBUG] [MatrixHttpClient] (REQ-3) GET https://matrix.example.com/_matrix/client/v3/joined_rooms
Sun, 28 May 2023 08:41:53 GMT [DEBUG] [MatrixClientLite] Preparing end-to-end encryption
Sun, 28 May 2023 08:41:53 GMT [DEBUG] [MatrixHttpClient] (REQ-4) GET https://matrix.example.com/_matrix/client/v3/rooms/!iWhUNHQUZTUeqBZncL%3Aexample.com/state/m.room.encryption/
Sun, 28 May 2023 08:41:53 GMT [ERROR] [MatrixHttpClient] (REQ-4) { errcode: 'M_NOT_FOUND', error: 'Event not found.' }
Sun, 28 May 2023 08:41:53 GMT [DEBUG] [MatrixHttpClient] (REQ-5) GET https://matrix.example.com/_matrix/client/v3/rooms/!VlyOdAIoWKBBMwwrMU%3Aexample.com/state/m.room.encryption/
Sun, 28 May 2023 08:41:53 GMT [ERROR] [MatrixHttpClient] (REQ-5) { errcode: 'M_NOT_FOUND', error: 'Event not found.' }
Sun, 28 May 2023 08:41:53 GMT [DEBUG] [CryptoClient] Starting with device ID: NMQJEXECYB
node:internal/process/esm_loader:97
    internalBinding('errors').triggerUncaughtException(
                              ^

[Error: Failed to deserialize or serialize a JSON value missing field `version` at line 1 column 6856] {
  code: 'GenericFailure'
}

Additional context The M_NOT_FOUND errors are pre-existing, happening always, as many times as encrypted rooms the bot is in (seems like). I imagine that those errors are unrelated with the new one, reported here, causing the bot to stop on startup.

Ciao :-)

[turt2live]

I'm not able to reproduce this, unfortunately.

Adding the following to the top of your bot's main file might reveal the actual contents of /sync though, which should help narrow down what the underlying crypto library is concerned about:

LogService.muteModule("Metrics");
LogService.trace = LogService.debug;
LogService.setLevel(LogLevel.TRACE);

[stronk7]

Hi,

really, there isn't anything new when I apply for those 3 lines. Here there are the complete logs with them enabled, apart from some "own" initialisation stuff that I add at the beginning (and omited in the original report) the error happens almost immediately.

./run.sh 
Using Matrix user: xxxx
Using Database user: xxxx
Thu, 01 Jun 2023 18:05:48 GMT [INFO] [Using './config-localdev.yml' for configuration (context: 'localdev')]
Thu, 01 Jun 2023 18:05:48 GMT [INFO] [Using './storage-localdev' for storage (context: 'localdev')]
Thu, 01 Jun 2023 18:05:48 GMT [INFO] [Using already existing token]
Thu, 01 Jun 2023 18:05:48 GMT [DEBUG] [MatrixClientLite] End-to-end encryption client created
Thu, 01 Jun 2023 18:05:48 GMT [INFO] [Starting HTTP server]
Thu, 01 Jun 2023 18:05:48 GMT [INFO] [Starting database pool]
Thu, 01 Jun 2023 18:05:48 GMT [INFO] [Starting profiles cache]
Thu, 01 Jun 2023 18:05:48 GMT [INFO] [Setting Jenkins webhook]
Thu, 01 Jun 2023 18:05:48 GMT [INFO] [Checking chat logs database structures]
Thu, 01 Jun 2023 18:05:48 GMT [INFO] [Server started at http://localhost:8080]
Thu, 01 Jun 2023 18:05:48 GMT [INFO] [Setting chat logs webhook]
Thu, 01 Jun 2023 18:05:48 GMT [INFO] [Starting RSS/Atom feeds parser]
Thu, 01 Jun 2023 18:05:48 GMT [INFO] [Starting to watch feed https://example.org/something/rss.php?lang=en]
Thu, 01 Jun 2023 18:05:48 GMT [DEBUG] [MatrixHttpClient] (REQ-1) GET https://matrix.example.com/_matrix/client/v3/account/whoami
Thu, 01 Jun 2023 18:05:49 GMT [DEBUG] [MatrixHttpClient] (REQ-1 RESP-H200) {
  user_id: '@nextexamplebotdev:example.com',
  is_guest: false,
  device_id: 'NMQJEXECYB'
}
Thu, 01 Jun 2023 18:05:49 GMT [DEBUG] [MatrixHttpClient] (REQ-2) GET https://matrix.example.com/_matrix/client/v3/user/%40nextexamplebotdev%3Aexample.com/account_data/m.direct
Thu, 01 Jun 2023 18:05:49 GMT [DEBUG] [MatrixHttpClient] (REQ-2 RESP-H200) {
  '@somebody:example.com': [
    '!rAXjmWWpilNfincJDv:example.com',
    '!NiAfbGwgRBRMOhzbhU:example.com',
    '!qZVBQTjQVSiMEzMLJr:example.com',
    '!FaTQHFKtJsJunxsLAI:example.com',
    '!cknecIGrtoaFPnOUgd:example.com',
    '!KxItDVUcTHcSCduVbh:example.com',
    '!ocQzaVUSmXVWQcTTua:example.com',
    '!xYLosOSLTwBSMykCfy:example.com'
  ]
}
Thu, 01 Jun 2023 18:05:49 GMT [DEBUG] [MatrixClientLite] No filter given or invalid object - using defaults.
Thu, 01 Jun 2023 18:05:49 GMT [DEBUG] [MatrixClientLite] Populating joined rooms to avoid excessive join emits
Thu, 01 Jun 2023 18:05:49 GMT [DEBUG] [MatrixHttpClient] (REQ-3) GET https://matrix.example.com/_matrix/client/v3/joined_rooms
Thu, 01 Jun 2023 18:05:49 GMT [DEBUG] [MatrixHttpClient] (REQ-3 RESP-H200) {
  joined_rooms: [
    '!rAXjmWWpilNfincJDv:example.com',
    '!VlyOdAIoWKBBMwwrMU:example.com',
    '!OGmrDnWiywbCeUYbUW:example.com',
    '!iWhUNHQUZTUeqBZncL:example.com'
  ]
}
Thu, 01 Jun 2023 18:05:49 GMT [DEBUG] [MatrixClientLite] Preparing end-to-end encryption
Thu, 01 Jun 2023 18:05:49 GMT [DEBUG] [MatrixHttpClient] (REQ-4) GET https://matrix.example.com/_matrix/client/v3/rooms/!VlyOdAIoWKBBMwwrMU%3Aexample.com/state/m.room.encryption/
Thu, 01 Jun 2023 18:05:49 GMT [ERROR] [MatrixHttpClient] (REQ-4) { errcode: 'M_NOT_FOUND', error: 'Event not found.' }
Thu, 01 Jun 2023 18:05:49 GMT [DEBUG] [MatrixHttpClient] (REQ-5) GET https://matrix.example.com/_matrix/client/v3/rooms/!iWhUNHQUZTUeqBZncL%3Aexample.com/state/m.room.encryption/
Thu, 01 Jun 2023 18:05:49 GMT [ERROR] [MatrixHttpClient] (REQ-5) { errcode: 'M_NOT_FOUND', error: 'Event not found.' }
Thu, 01 Jun 2023 18:05:49 GMT [DEBUG] [CryptoClient] Starting with device ID: NMQJEXECYB
node:internal/process/esm_loader:97
    internalBinding('errors').triggerUncaughtException(
                              ^

[Error: Failed to deserialize or serialize a JSON value missing field `version` at line 1 column 6856] {
  code: 'GenericFailure'
}

Ciao :-)

[bertybuttface]

I'm also getting this error, clearing persistent storage and logging in again solves it but I'm hoping not to have to force everyone to do that. What do you need to help reproduce?

[stronk7]

For the records a few days ago I proceeded to update out staging bot to v0.7.1 and completely remove the storage (to get a new token and so on). It has been running @ staging without problem (just a lot of "Can't find the room key to decrypt the event" at the beginning, until it got everything updated).

So, today, I've been brave enough to apply for the same (update and delete storage) with the prod bot, and it's up and, apparently, running ok. I'll keep monitoring it, but for sure the problem reported in this issue (immediately after starting) is not happening anymore.

Ciao :-)

[stronk7]

Update: We have 0.7.1 running (after deleting storage) here since a few days ago in prod, and it seems that this problem isn't happening anymore. We are facing #346 a few times (old-known issue for us), but other than that, all ok.

Ciao :-)