@pierre-gilles @cicoub13 small progress
Summary by chatGPT:
Complete freeze of Gladys when updating a Zigbee2MQTT device
I encounter a reproducible blockage of Gladys when updating a socket named Computer Station from the Zigbee2MQTT interface.
Originally, I simply wanted to update this device because some features related to energy/consumption were missing.
Symptoms
When updating the device from Gladys:
-
the request times out;
-
the interface becomes partially or completely unusable;
-
SQLite writes then start to fail with:
SequelizeTimeoutError
SQLITE_BUSY: database is locked
For example:
Unable to reset failure count of integration ...
SQLITE_BUSY: database is locked
The HTTP server itself continues to respond on port 8455.
DB Configuration
The SQLite database is quite large:
gladys-production.db ~12 GB
gladys-production.db-wal ~1 GB
gladys-production.duckdb ~1.9 GB
SQLite is running in WAL mode:
PRAGMA journal_mode;
wal
A passive checkpoint works:
PRAGMA wal_checkpoint(PASSIVE);
0|227|227
Simple queries on SQLite remain fast:
SELECT COUNT(*) FROM t_device_feature;
446
real 0m0.090s
And:
SELECT COUNT(*) FROM t_device_feature_state;
0
The states therefore seem to have been successfully migrated to DuckDB.
Device concerned
The device is:
id:
fd928ba6-ca0d-4a0d-8483-5b74cfddce8c
external_id:
zigbee2mqtt:Computer Station
Before the update attempt, its recorded features include:
Switch
Consumed power
Consumed current
Average voltage
Consumed energy
Signal strength
Access control mode
The « Access control mode » feature corresponds to:
zigbee2mqtt:Computer Station:access-control:mode:child_lock
Investigation in device.create.js
I instrumented:
/src/server/lib/device/device.create.js
aiming to precisely determine where the transaction is blocked.
The beginning of the update works normally:
[DEBUG DEVICE CREATE] START zigbee2mqtt:Computer Station
[DEBUG DEVICE CREATE] BEFORE getDeviceInDb zigbee2mqtt:Computer Station
[DEBUG DEVICE CREATE] AFTER getDeviceInDb zigbee2mqtt:Computer Station
[DEBUG DEVICE CREATE] BEFORE device update zigbee2mqtt:Computer Station
[DEBUG DEVICE CREATE] AFTER device update zigbee2mqtt:Computer Station
[DEBUG DEVICE CREATE] BEFORE feature cleanup zigbee2mqtt:Computer Station
The blockage therefore occurs during this part of device.create.js:
await Promise.map(deviceInDb.features, async (existingFeature) => {
if (!matchFeatureInList(existingFeature, features)) {
await existingFeature.destroy({ transaction });
}
});
I then instrumented each feature.
Result:
[DEBUG FEATURE CLEANUP] ...:switch:binary:state matched= true
[DEBUG FEATURE CLEANUP] ...:switch:power:power matched= true
[DEBUG FEATURE CLEANUP] ...:switch:current:current matched= true
[DEBUG FEATURE CLEANUP] ...:switch:voltage:voltage matched= true
[DEBUG FEATURE CLEANUP] ...:switch:energy:energy matched= true
Then:
[DEBUG FEATURE CLEANUP] zigbee2mqtt:Computer Station:access-control:mode:child_lock matched= false
[DEBUG FEATURE DESTROY] BEFORE zigbee2mqtt:Computer Station:access-control:mode:child_lock
And no DEBUG FEATURE DESTROY AFTER appears.
The next feature is still inspected by the Promise.map:
[DEBUG FEATURE CLEANUP] ...:signal:integer:linkquality matched= true
but the Promise.map never completes because the destroy() of child_lock remains blocked.
What seems to be happening
The new definition returned by Zigbee2MQTT no longer contains the feature:
access-control:mode:child_lock
Gladys therefore logically considers this old feature as deleted and executes:
await existingFeature.destroy({ transaction });
It is precisely this call that does not return.
The device.create() transaction then remains open.
Shortly after, other components of Gladys try to write to SQLite and start producing:
SQLITE_BUSY: database is locked
For example, updates to t_service:
UPDATE `t_service`
SET `failure_count`=$1,`updated_at`=$2
WHERE `id` = $3
end in SequelizeTimeoutError.
This therefore gives, at this stage, the following sequence:
Z2M device update
↓
device.create()
↓
deviceInDb.update() OK
↓
cleanup of old features
↓
child_lock absent from new device
↓
existingFeature.destroy({transaction})
↓
BLOCKAGE
↓
SQLite transaction remaining open
↓
other writes
↓
SQLITE_BUSY / database is locked
About energy
The problem occurred while I was trying to retrieve the energy consumption features of this socket, which had initially led me to the new energy monitoring code.
However, the traces now show that the blockage occurs before the creation/update of the energy features.
The existing energy feature is indeed correctly recognized:
zigbee2mqtt:Computer Station:switch:energy:energy matched=true
The blockage is triggered by the attempt to delete the old child_lock feature.
Other observation
During the freeze, the Energy Monitoring service continues to start its processes and indicates in particular:
Found 52 energy devices
Found 0 devices with both INDEX and thirty-minutes-consumption features
Then the SQLITE_BUSY errors appear in different parts of Gladys.
I also checked t_job: the SQLite → DuckDB migration jobs and DuckDB orphaned state purge are marked success.
Tested patch without success
I had also tested a modification of device.create.js to only trigger the state purge when keep_history actually changes from true to false:
const keepHistoryBeforeUpdate = deviceFeature.keep_history;
await deviceFeature.update(featureToUpdate, { transaction });
if (keepHistoryBeforeUpdate !== false && deviceFeature.keep_history === false) {
deviceFeaturesIdsToPurge.push(deviceFeature.id);
}
This does not fix the problem: thanks to the additional logs, we now know that the freeze occurs earlier, during the destroy() of the obsolete feature.
Current state of the diagnosis
The reproducible blockage point is now quite precisely identified:
existingFeature.destroy({ transaction })
for:
zigbee2mqtt:Computer Station:access-control:mode:child_lock