Bug: ring-mqtt startup fails with initial error "Message dropped as it could not be decrypted: crypto-key is missing"

cerebrate commented 1 month ago

Is there an existing issue for this?

[X] I have searched all existing open/closed issues

Is this really a bug or just a usage/support question?

[X] I'm confident this is a bug.

Have you read and followed any recommendations in the Support and Troubleshooting section of the wiki?

[X] I have read the support wiki and followed any applicable steps.

Did this issue start after an upgrade?

[X] This not an upgrade issue or I have read the release notes and performed any applicable steps that match my issue.

Are you prepared to respond and provide all relevant information (logs, screenshots, etc)

[X] I am prepared to provide logs, answer questions, and respond in a reasonable timeframe.

Describe the Bug

ring-mqtt startup fails with initial error "Message dropped as it could not be decrypted: crypto-key is missing"

Steps to Reproduce

This error began occurring on a previously correctly operating ring-mqtt installation without any changes having been made to configuration, data files, etc. Steps to reproduce are therefore unknown.

Expected Behavior

ring-mqtt starts up and operates normally

Log Output

-------------------------------------------------------
ring-mqtt.js version: 5.7.1
Node version v20.15.1
NPM version 10.8.0
git version 2.45.2
-------------------------------------------------------
Running ring-mqtt...
2024-09-25T18:50:13.334Z ring-mqtt Detected runmode: docker
ring-mqtt.js version: 5.7.1
Node version v20.15.1
NPM version 10.8.0
git version 2.45.2
-------------------------------------------------------
Running ring-mqtt...
2024-09-25T18:50:13.334Z ring-mqtt Detected runmode: docker
2024-09-25T18:50:13.341Z ring-mqtt Configuration file: /data/config.json
2024-09-25T18:50:13.992Z ring-mqtt Reading latest data from state file: /data/ring-state.json
2024-09-25T18:50:13.994Z ring-mqtt MQTT URL: mqtt://mosquitto.homeassistant.svc.cluster.local:1883
2024-09-25T18:50:14.037Z ring-mqtt Attempting connection to Ring API using saved refresh token...
2024-09-25T18:50:16.576Z ring-mqtt Successfully established connection to Ring API using saved token
2024-09-25T18:50:16.578Z ring-mqtt Received updated refresh token
2024-09-25T18:50:16.579Z ring-mqtt Saving updated refresh token to state file
2024-09-25T18:50:17.775Z ring-mqtt Successfully saved updated state file: /data/ring-state.json
2024-09-25T18:50:18.577Z ring-mqtt Attempting connection to MQTT broker...
2024-09-25T18:50:18.625Z ring-mqtt MQTT connection established, processing Ring locations...
2024-09-25T18:50:18.671Z ring-mqtt Home Assistant state topic homeassistant/status received message: offline
2024-09-25T18:50:20.978Z ring-mqtt ------------------------------------------------------------------------------------------
2024-09-25T18:50:20.978Z ring-mqtt This account has access to the following locations:
2024-09-25T18:50:20.978Z ring-mqtt            Wichita (9ydy89-4qqb1-0)
2024-09-25T18:50:20.978Z ring-mqtt                                                                                           
2024-09-25T18:50:20.978Z ring-mqtt IMPORTANT: If *ANY* alarm or smart lighting hubs at these locations are *OFFLINE* 
2024-09-25T18:50:20.978Z ring-mqtt            the device discovery process below will hang and no devices will be    
2024-09-25T18:50:20.978Z ring-mqtt            published!                                                             
2024-09-25T18:50:20.978Z ring-mqtt                                                                                           
2024-09-25T18:50:20.978Z ring-mqtt            If the message "Device Discovery Complete!" is not logged below, please
2024-09-25T18:50:20.978Z ring-mqtt            carefully check the Ring app for any hubs or smart lighting devices    
2024-09-25T18:50:20.979Z ring-mqtt            that are in offline state and either remove them from the location or  
2024-09-25T18:50:20.979Z ring-mqtt            bring them back online prior to restarting ring-mqtt.                  
2024-09-25T18:50:20.979Z ring-mqtt                                                                                           
2024-09-25T18:50:20.979Z ring-mqtt            If desired, the "location_ids" config option can be used to restrict   
2024-09-25T18:50:20.979Z ring-mqtt            discovery to specific locations. See the documentation for details.    
2024-09-25T18:50:20.979Z ring-mqtt ------------------------------------------------------------------------------------------
2024-09-25T18:50:20.979Z ring-mqtt Starting Device Discovery...
2024-09-25T18:50:20.979Z ring-mqtt                                                                                           
2024-09-25T18:50:20.979Z ring-mqtt New location: Wichita (9ydy89-4qqb1-0)
Message dropped as it could not be decrypted: crypto-key is missing
2024-09-25T18:50:21.360Z ring-mqtt ERROR - Uncaught Exception
2024-09-25T18:50:21.360Z ring-mqtt Maximum call stack size exceeded
2024-09-25T18:50:21.360Z ring-mqtt RangeError: Maximum call stack size exceeded
    at new BufferReader (/app/ring-mqtt/node_modules/protobufjs/src/reader_buffer.js:17:22)
    at #handleGotMessageSize (/app/ring-mqtt/node_modules/@eneris/push-receiver/dist/parser.js:103:24)
    at #waitForData (/app/ring-mqtt/node_modules/@eneris/push-receiver/dist/parser.js:77:43)
    at #handleGotMessageSize (/app/ring-mqtt/node_modules/@eneris/push-receiver/dist/parser.js:122:30)
    at #waitForData (/app/ring-mqtt/node_modules/@eneris/push-receiver/dist/parser.js:77:43)
    at #handleGotMessageSize (/app/ring-mqtt/node_modules/@eneris/push-receiver/dist/parser.js:122:30)
    at #waitForData (/app/ring-mqtt/node_modules/@eneris/push-receiver/dist/parser.js:77:43)
    at #handleGotMessageSize (/app/ring-mqtt/node_modules/@eneris/push-receiver/dist/parser.js:122:30)
    at #waitForData (/app/ring-mqtt/node_modules/@eneris/push-receiver/dist/parser.js:77:43)
    at #handleGotMessageSize (/app/ring-mqtt/node_modules/@eneris/push-receiver/dist/parser.js:122:30)

[normal device discovery information elided]

2024-09-25T18:50:22.367Z ring-mqtt The ring-mqtt process is shutting down...
2024-09-25T18:50:22.368Z ring-mqtt Setting all devices offline...
2024-09-25T18:50:22.537Z ring-mqtt [Side Door] Unable to retrieve most recent ding event for this doorbell
2024-09-25T18:50:23.318Z ring-mqtt [Wichita Base Station] Account has access to set volume on base station, enabling volume control
2024-09-25T18:50:23.548Z ring-mqtt Successfully saved updated state file: /data/ring-state.json
2024-09-25T18:50:25.369Z ring-mqtt Exit code: 2

Screenshots

No response

Config File

{
    "mqtt_url": "mqtt://mosquitto.homeassistant.svc.cluster.local:1883",
    "mqtt_options": "",
    "livestream_user": "",
    "livestream_pass": "",
    "disarm_code": "[REDACTED]",
    "enable_cameras": true,
    "enable_modes": false,
    "enable_panic": true,
    "hass_topic": "homeassistant/status",
    "ring_topic": "ring",
    "location_ids": [
        ""
    ]
}

Install Type

k8s

Version

x5.7.1

Operating System

Debian bookworm

Architecture

amd64

Machine Details

k8s v1.30.2 on Debian bookworm on physical amd64 (Intel NUC)

tsightler commented 1 month ago

I don't believe this issue is related to "Message dropped" as that is just an informational message as sometimes it's not possible to decrypt push messages for various reasons.

Rather it seems that the process is exiting due to stack size exception. Unfortunately, this error appears to be coming from push-receiver dependency and not from ring-mqtt itself which means it will basically be impossible for me to troubleshoot this since there is no method to reproduce the issue and I can't even easily add debug option to the code since it is outside of my control.

Unless you have troubleshooting/development skills and are able to dig into it yourself, my best suggestion is to follow the standard notification troubleshooting steps in the wiki, which should reset the current push notification queue.

cerebrate commented 1 month ago

Makes sense. I'll give that a try.

Is there an alternate way to get the name of the device affected other than the web UI? The ring-mqtt container won't stay up long enough for me to access that.

cerebrate commented 1 month ago

...actually, scratch that. I was trying to figure out a way to get that information when, lo and behold, the repeatedly restarting container stopped restarting and started running normally as suddenly and with as little local cause as it stopped working in the first place.

Which is frustrating in its way, but I guess I'll take it. 🤷🏻‍♂️

tsightler commented 1 month ago

Not a complete surprise I guess. In theory ring-client-api should be storing the ID of the last received push notifications and passing that back to the API on reconnect, but, as of today, it doesn't do that. This leads to the case that, during startup, FCM re-sends any past push notifications that are still in the queue even if they've already been delivered previously. I'm not sure how long such messages stay in the queue, it seems like it's just a few hours at most, but eventually, they are removed. It feels like there was somehow a corrupted message, or maybe a message much longer than push-receiver expects, that was still in the queue, and once it finally timed out, everything started working again.

Currently the code just ignores any messages received during the first few seconds after the API connection is established. I'm guessing if it were implemented correctly by storing the push ID, this problem wouldn't exist.

tsightler / ring-mqtt