Koenkk / zigbee2mqtt

Zigbee 🐝 to MQTT bridge 🌉, get rid of your proprietary Zigbee bridges 🔨
https://www.zigbee2mqtt.io
GNU General Public License v3.0
12.15k stars 1.68k forks source link

Unstable network on EmberZNet #23086

Open JacekKac opened 5 months ago

JacekKac commented 5 months ago

What happened?

Many timeouts, route problems

What did you expect to happen?

normal behaviour

How to reproduce it (minimal and precise)

No response

Zigbee2MQTT version

1.38.0 commit: f1847301

Adapter firmware version

7.4.2 [GA]

Adapter

SONOF E DONGLE

Setup

raspberry pi with zigbeemqtt

Debug log

Publish 'set' 'state' to 'Light_7c' failed: 'Error: ZCL command 0xa4c138e9e32158fa/1 genOnOff.off({}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":false,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed ({"target":18925,"apsFrame":{"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":86},"zclSequence":227,"commandIdentifier":11} timed out after 10000ms)'

Received network/route error ROUTE_ERROR_MANY_TO_ONE_ROUTE_FAILURE for "18925". Received network/route error ROUTE_ERROR_MANY_TO_ONE_ROUTE_FAILURE for "47121". (many different id's)

Network is very unstable but the distances are very small. 38 repaters TS011F_plug_1 and TS0002

Nerivec commented 4 months ago

You can try https://nerivec.github.io/z2m-ember-helper/#help if you have a long enough log file (too short timeframe gives irrelevant results). It should help identify potential sources of problems. I can help translate if you need more details on the results.

JacekKac commented 4 months ago

@Nerivec thank you i uploaded a cmobined log file and the result are confirming my problem.

Number of routers: 39 Number of end devices: 1 Routers to end devices ratio: 39 (Ideal: above 0.5)

ines: 188120 Start: 2024-06-26 11:37:34 End: 2024-06-27 18:10:43 Ignore before (avoid starting "noise"): 2024-06-26 11:38:34 Duration: 30.55 hours NCP Counters: 9 ASH Counters: 9 Network/Router Errors: 76 CCA failure count is high (0.6472 vs 0.0102 "ideal") Stale neighbors count is high (163.11 vs 1 "ideal")

image

image

Nerivec commented 4 months ago

Can you try to scan your environment (Scan network) with https://github.com/Nerivec/ember-zli ? Mostly Channels usage / RSSI, but you can also see if there are any other Zigbee networks around (Existing networks, if your location makes it possible). Set the same transmit power that you use in Z2M (if you haven't configured it in Z2M, default is 5). It's all interactive, so you just launch ember-zli stack and follow what it asks (navigate menus with the arrow keys). Then post the results, along with what channel you are using in Z2M (if you set one, otherwise default is 11).

JacekKac commented 4 months ago

My config: TP : 5 default, channel 11 default, not zigbee network near.\

scan is finishing with an error pi@iSMART-10:~ $ sudo ember-zli stack [2024-06-27T17:28:00.939Z] info: cli: Data folder: /root/ember-zli. ? Adapter firmware baudrate 115200 ? Adapter connection type Serial ? Serial port ITEAD usb-ITEAD_SONOFF_Zigbee_3.0_USB_Dongle_Plus_V2_20240123154135-if00 (/dev/ttyACM0) ? Flow control Software Flow Control (rtscts=false) [2024-06-27T17:28:07.781Z] info: zh:ember:ezsp: ======== EZSP starting ======== [2024-06-27T17:28:07.786Z] info: zh:ember:uart:ash: ======== ASH NCP reset ======== [2024-06-27T17:28:07.793Z] info: zh:ember:uart:ash: RTS/CTS config is off, enabling software flow control. [2024-06-27T17:28:07.811Z] info: zh:ember:uart:ash: Serial port opened [2024-06-27T17:28:07.814Z] info: zh:ember:uart:ash: ======== ASH starting ======== [2024-06-27T17:28:07.838Z] error: zh:ember:uart:ash: Received ERROR from NCP while connecting, with code=ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT. [2024-06-27T17:28:07.840Z] error: zh:ember:uart:ash: ASH disconnected | NCP status: ASH_NCP_FATAL_ERROR [2024-06-27T17:28:07.842Z] error: zh:ember:uart:ash: Error while parsing received frame, status=ASH_NCP_FATAL_ERROR. [2024-06-27T17:28:07.848Z] info: zh:ember:uart:ash: ======== ASH NCP reset ======== [2024-06-27T17:28:07.850Z] info: zh:ember:uart:ash: ======== ASH starting ======== [2024-06-27T17:28:08.958Z] info: zh:ember:uart:ash: ======== ASH connected ======== [2024-06-27T17:28:08.981Z] info: zh:ember:uart:ash: ======== ASH started ======== [2024-06-27T17:28:08.982Z] info: zh:ember:ezsp: ======== EZSP started ======== [2024-06-27T17:28:09.027Z] info: ember: NCP version: {"ezsp":13,"revision":"7.4.2 [GA]","build":0,"major":7,"minor":4,"patch":2,"special":0,"type":170} ? Menu Scan network ? Radio transmit power [0-20] 5 ? Type of scan Scan each channel for its RSSI value ? Duration of scan per channel 998 msec █████████████████████░░░░░░░░░░░░░░░░░░░ 53% | ETA: 8sfile:///usr/lib/node_modules/ember-zli/dist/commands/stack/index.js:340 reportedValues.push(Channel ${channel}: ${BULLET_FULL.repeat(full)}${BULLET_EMPTY.repeat(empty)} [${maxRssiValue} dBm]`); ^

RangeError: Invalid count value: -1 at String.repeat () at ezsp.ezspEnergyScanResultHandler (file:///usr/lib/node_modules/ember-zli/dist/commands/stack/index.js:340:96) at Ezsp.callbackDispatch (/usr/lib/node_modules/ember-zli/node_modules/zigbee-herdsman/dist/adapter/ember/ezsp/ezsp.js:474:22) at Ezsp.tick (/usr/lib/node_modules/ember-zli/node_modules/zigbee-herdsman/dist/adapter/ember/ezsp/ezsp.js:238:22) at listOnTimeout (node:internal/timers:573:17) at process.processTimers (node:internal/timers:514:7)

Node.js v20.14.0 `

JacekKac commented 4 months ago

@Nerivec can you look at this error?

JacekKac commented 4 months ago

how to decode this hex devices ids to sth more relevant for zigbee2mqtt frontend? image

Nerivec commented 4 months ago

@JacekKac The error you encountered should be fixed in latest version (well, it shouldn't crash anymore, but it seems you had a failure during one of the scans). Update (npm update -g ember-zli) and try again, see what results you get now. The hex value is the one used in zigbee2mqtt frontend. In the IEEE Address column, it's the one in parentheses, or in a device's page, it's Network address.

JacekKac commented 4 months ago

ok it's working right now:

? Menu Scan network
? Radio transmit power [-128-127] 5
? Type of scan Scan each channel for its RSSI value
? Duration of scan per channel 998 msec
[2024-07-11 10:57:23.735] info:         cli: Channel 11: ••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙ [-28 dBm]
[2024-07-11 10:57:23.737] info:         cli: Channel 12: •••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••∙∙∙∙∙∙∙∙∙∙∙ [-11 dBm]
[2024-07-11 10:57:23.738] info:         cli: Channel 13: •••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••∙∙∙∙∙∙∙ [-7 dBm]
[2024-07-11 10:57:23.740] info:         cli: Channel 14: •••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••∙∙∙∙∙ [-5 dBm]
[2024-07-11 10:57:23.742] info:         cli: Channel 15: ••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••∙∙∙∙∙∙∙∙ [-8 dBm]
[2024-07-11 10:57:23.743] info:         cli: Channel 16: ERROR
[2024-07-11 10:57:23.745] info:         cli: Channel 17: ERROR
[2024-07-11 10:57:23.746] info:         cli: Channel 18: ERROR
[2024-07-11 10:57:23.747] info:         cli: Channel 19: •••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••∙∙∙ [-3 dBm]
[2024-07-11 10:57:23.748] info:         cli: Channel 20: ••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙ [-28 dBm]
[2024-07-11 10:57:23.750] info:         cli: Channel 21: •••••••••••••••••••••••••••••••••••••••••••••••••••••••••••∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙ [-31 dBm]
[2024-07-11 10:57:23.751] info:         cli: Channel 22: ••••••••••••••••••••••••••••••••••••••••••••••••••••••••∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙ [-34 dBm]
[2024-07-11 10:57:23.752] info:         cli: Channel 23: •••••••••••••••••••••••••••••••••••••••••••••••••••∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙ [-39 dBm]
[2024-07-11 10:57:23.754] info:         cli: Channel 24: ••••••••••••••••••••••••••••••••••••••••••••∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙ [-46 dBm]
[2024-07-11 10:57:23.755] info:         cli: Channel 25: ••••••••••••••••••••••••••••••••••••••••••••••∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙ [-44 dBm]
[2024-07-11 10:57:23.756] info:         cli: Channel 26: •••••••••••••••••••••••••••••••••••••••••∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙ [-49 dBm]

and

? Radio transmit power [-128-127] 20
? Type of scan Scan each channel for existing networks
? Duration of scan per channel 998 msec
[2024-07-11 10:58:39.231] info:         cli: Found network:
[2024-07-11 10:58:39.234] info:         cli:   - PAN ID: 6754
[2024-07-11 10:58:39.236] info:         cli:   - Ext PAN ID: 221,221,221,221,221,221,221,221
[2024-07-11 10:58:39.238] info:         cli:   - Channel: 11
[2024-07-11 10:58:39.240] info:         cli:   - Allowing join: no
[2024-07-11 10:58:39.242] info:         cli:   - Node RSSI: -83 dBm | LQI: 68
[2024-07-11 10:58:39.244] info:         cli: Found network:
[2024-07-11 10:58:39.246] info:         cli:   - PAN ID: 6754
[2024-07-11 10:58:39.248] info:         cli:   - Ext PAN ID: 221,221,221,221,221,221,221,221
[2024-07-11 10:58:39.249] info:         cli:   - Channel: 11
[2024-07-11 10:58:39.250] info:         cli:   - Allowing join: no
[2024-07-11 10:58:39.252] info:         cli:   - Node RSSI: -65 dBm | LQI: 140
[2024-07-11 10:58:39.253] info:         cli: Found network:
[2024-07-11 10:58:39.254] info:         cli:   - PAN ID: 6754
[2024-07-11 10:58:39.255] info:         cli:   - Ext PAN ID: 221,221,221,221,221,221,221,221
[2024-07-11 10:58:39.257] info:         cli:   - Channel: 11
[2024-07-11 10:58:39.258] info:         cli:   - Allowing join: no
[2024-07-11 10:58:39.259] info:         cli:   - Node RSSI: -69 dBm | LQI: 124
[2024-07-11 10:58:39.260] info:         cli: Found network:
[2024-07-11 10:58:39.262] info:         cli:   - PAN ID: 6754
[2024-07-11 10:58:39.263] info:         cli:   - Ext PAN ID: 221,221,221,221,221,221,221,221
[2024-07-11 10:58:39.264] info:         cli:   - Channel: 11
[2024-07-11 10:58:39.265] info:         cli:   - Allowing join: no
[2024-07-11 10:58:39.266] info:         cli:   - Node RSSI: -75 dBm | LQI: 100
[2024-07-11 10:58:39.268] info:         cli: Found network:
[2024-07-11 10:58:39.269] info:         cli:   - PAN ID: 6754
[2024-07-11 10:58:39.270] info:         cli:   - Ext PAN ID: 221,221,221,221,221,221,221,221
[2024-07-11 10:58:39.271] info:         cli:   - Channel: 11
[2024-07-11 10:58:39.272] info:         cli:   - Allowing join: no
[2024-07-11 10:58:39.274] info:         cli:   - Node RSSI: -28 dBm | LQI: 255
[2024-07-11 10:58:39.275] info:         cli: Found network:
[2024-07-11 10:58:39.276] info:         cli:   - PAN ID: 6754
[2024-07-11 10:58:39.277] info:         cli:   - Ext PAN ID: 221,221,221,221,221,221,221,221
[2024-07-11 10:58:39.279] info:         cli:   - Channel: 11
[2024-07-11 10:58:39.280] info:         cli:   - Allowing join: no
[2024-07-11 10:58:39.281] info:         cli:   - Node RSSI: -76 dBm | LQI: 96
[2024-07-11 10:58:39.282] info:         cli: Found network:
[2024-07-11 10:58:39.284] info:         cli:   - PAN ID: 6754
[2024-07-11 10:58:39.285] info:         cli:   - Ext PAN ID: 221,221,221,221,221,221,221,221
[2024-07-11 10:58:39.286] info:         cli:   - Channel: 11
[2024-07-11 10:58:39.287] info:         cli:   - Allowing join: no
[2024-07-11 10:58:39.287] info:         cli:   - Node RSSI: -70 dBm | LQI: 120
[2024-07-11 10:58:39.288] info:         cli: Found network:
[2024-07-11 10:58:39.289] info:         cli:   - PAN ID: 6754
[2024-07-11 10:58:39.290] info:         cli:   - Ext PAN ID: 221,221,221,221,221,221,221,221
[2024-07-11 10:58:39.291] info:         cli:   - Channel: 11
[2024-07-11 10:58:39.292] info:         cli:   - Allowing join: no
[2024-07-11 10:58:39.293] info:         cli:   - Node RSSI: -62 dBm | LQI: 152
[2024-07-11 10:58:39.294] info:         cli: Found network:
[2024-07-11 10:58:39.295] info:         cli:   - PAN ID: 6754
[2024-07-11 10:58:39.296] info:         cli:   - Ext PAN ID: 221,221,221,221,221,221,221,221
[2024-07-11 10:58:39.297] info:         cli:   - Channel: 11
[2024-07-11 10:58:39.298] info:         cli:   - Allowing join: no
[2024-07-11 10:58:39.300] info:         cli:   - Node RSSI: -57 dBm | LQI: 172
[2024-07-11 10:58:39.301] info:         cli: Found network:
[2024-07-11 10:58:39.302] info:         cli:   - PAN ID: 6754
[2024-07-11 10:58:39.303] info:         cli:   - Ext PAN ID: 221,221,221,221,221,221,221,221
[2024-07-11 10:58:39.304] info:         cli:   - Channel: 11
[2024-07-11 10:58:39.305] info:         cli:   - Allowing join: no
[2024-07-11 10:58:39.306] info:         cli:   - Node RSSI: -43 dBm | LQI: 228
[2024-07-11 10:58:39.307] info:         cli: Found network:
[2024-07-11 10:58:39.308] info:         cli:   - PAN ID: 6754
[2024-07-11 10:58:39.308] info:         cli:   - Ext PAN ID: 221,221,221,221,221,221,221,221
[2024-07-11 10:58:39.309] info:         cli:   - Channel: 11
[2024-07-11 10:58:39.310] info:         cli:   - Allowing join: no
[2024-07-11 10:58:39.311] info:         cli:   - Node RSSI: -31 dBm | LQI: 255
[2024-07-11 10:58:39.312] info:         cli: Found network:
[2024-07-11 10:58:39.313] info:         cli:   - PAN ID: 6754
[2024-07-11 10:58:39.314] info:         cli:   - Ext PAN ID: 221,221,221,221,221,221,221,221
[2024-07-11 10:58:39.315] info:         cli:   - Channel: 11
[2024-07-11 10:58:39.316] info:         cli:   - Allowing join: no
[2024-07-11 10:58:39.317] info:         cli:   - Node RSSI: -60 dBm | LQI: 160
[2024-07-11 10:58:39.318] info:         cli: Found network:
[2024-07-11 10:58:39.319] info:         cli:   - PAN ID: 6754
[2024-07-11 10:58:39.320] info:         cli:   - Ext PAN ID: 221,221,221,221,221,221,221,221
[2024-07-11 10:58:39.321] info:         cli:   - Channel: 11
[2024-07-11 10:58:39.322] info:         cli:   - Allowing join: no
[2024-07-11 10:58:39.323] info:         cli:   - Node RSSI: -52 dBm | LQI: 192
JacekKac commented 4 months ago

Results of my log:

CCA failure count is high (0.3125 vs 0.0102 "ideal") This can indicate interferences on the 2.4GHz band on or around the current channel (WiFi, other Zigbee...).

Stale neighbors count is high (62.5 vs 1 "ideal") This can indicate devices are regularly losing connection to the network.

image

image

JacekKac commented 4 months ago

and my findings about the devices:

but still there is a lot of routers neer

Nerivec commented 4 months ago

I'd suggest you try changing the channel to 25 for your network. It seems anything before 20 is getting terrible interference in your environment, and you are currently on 11. You can do that in the configuration.yaml as usual (shutdown Z2M, make the change, then start it again). ember has support for channel switching, so it should move most of your devices automatically after starting (it may take a little while, best to leave it alone). Note that some devices may not respond well to this operation, so you may have to re-pair a few (if that happens, it's usually battery-powered ones).

Once this is done, report back in a day or two, after everything settles. Things should improve a fair amount based on your scan results. You may want to ensure your adapter is also using a good extension cord in case some of the interferences are coming from the USB.

JacekKac commented 4 months ago

ok i have switched the network to channel 25, only one device get lost, i will let you now if this helped :) Thank you so much for your tools and time;)

JacekKac commented 4 months ago

ok my results are: CCA failure count is high (0.3125 vs 0.0102 "ideal") Packet retry count is high (17.1167 vs 2.0597 "ideal") Stale neighbors count is high (26.33 vs 1 "ideal")

image

Nerivec commented 4 months ago

Looks a lot better than previous results already. Note: "Ideal" is a very strict base, a network with nearly zero error, so, being a bit above it, is normal for most networks. I'm assuming this is based on the logs starting right after the channel change? To get a more accurate read, you would have to remove ~24h after the channel change, to remove any impact the change itself had.

How is the network otherwise? Any issues actually using it?

JacekKac commented 3 months ago

I was on a site yesterday and added a usb extension cable, added some devices, but still sometimes see lags in communication.

[2024-07-24 18:42:44.927] info: cli: Channel 11: •••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙ [-25 dBm] [2024-07-24 18:42:44.929] info: cli: Channel 12: ERROR [2024-07-24 18:42:44.930] info: cli: Channel 13: ERROR [2024-07-24 18:42:44.932] info: cli: Channel 14: ERROR [2024-07-24 18:42:44.934] info: cli: Channel 15: ERROR [2024-07-24 18:42:44.935] info: cli: Channel 16: ERROR [2024-07-24 18:42:44.937] info: cli: Channel 17: ERROR [2024-07-24 18:42:44.938] info: cli: Channel 18: ERROR [2024-07-24 18:42:44.939] info: cli: Channel 19: ERROR [2024-07-24 18:42:44.940] info: cli: Channel 20: •••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙ [-21 dBm] [2024-07-24 18:42:44.942] info: cli: Channel 21: ••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙ [-18 dBm] [2024-07-24 18:42:44.943] info: cli: Channel 22: ••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙ [-30 dBm] [2024-07-24 18:42:44.944] info: cli: Channel 23: ••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙ [-28 dBm] [2024-07-24 18:42:44.945] info: cli: Channel 24: •••••••••••••••••••••••••••••••••••••••••••••••••∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙ [-41 dBm] [2024-07-24 18:42:44.947] info: cli: Channel 25: •••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙ [-23 dBm] [2024-07-24 18:42:44.948] info: cli: Channel 26: ••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••••∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙ [-24 dBm]

JacekKac commented 3 months ago

i will let you know in 2-3 days

Nerivec commented 3 months ago

Current dev/edge (next release), should be much better at cooperating with misbehaving devices, so if that's the cause of your lag troubles, hopefully that will fix it :wink:

JacekKac commented 3 months ago

My main problem is that i am using devices https://www.zigbee2mqtt.io/devices/TS0001.html#tuya-ts0001 mainly...

for a stairway behaviour so i am making rules in openhab if DeviceA is turning on turn ON DeviceB, to keep the light switches correct state. I made some rate limit rules etc, but sometimes all the stairway switches are going crazy and sending ON/OFF command all the time in a loop - i think it's connected with the lags of sending the commands by zigbee network. I made some java rules for limiting the commands - 1,5 second 'rate limit' but maybe there is a way to fix the problem in zigbee2mqtt drectly? not sure how to solve it right ;(

JacekKac commented 3 months ago

These is what i get very often when i send the ON command 2024-07-24 20:01:58z2m: Publish 'set' 'state' to 'Light_5a' failed: 'Error: ZCL command 0xa4c1380166606c03/1 genOnOff.on({}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":false,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed ({"target":24132,"apsFrame":{"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":66},"zclSequence":7,"commandIdentifier":11} timed out after 10000ms)'

JacekKac commented 3 months ago

5 failed 1 sucess

2024-07-24 20:01:58z2m: Publish 'set' 'state' to 'Light_5a' failed: 'Error: ZCL command 0xa4c1380166606c03/1 genOnOff.on({}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":false,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed ({"target":24132,"apsFrame":{"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":66},"zclSequence":7,"commandIdentifier":11} timed out after 10000ms)' Error 2024-07-24 20:03:19z2m: Publish 'set' 'state' to 'Light_5a' failed: 'Error: ZCL command 0xa4c1380166606c03/1 genOnOff.off({}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":false,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed ({"target":24132,"apsFrame":{"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":111},"zclSequence":11,"commandIdentifier":11} timed out after 10000ms)' Error 2024-07-24 20:03:44z2m: Publish 'set' 'state' to 'Light_5a' failed: 'Error: ZCL command 0xa4c1380166606c03/1 genOnOff.on({}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":false,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed ({"target":24132,"apsFrame":{"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":118},"zclSequence":12,"commandIdentifier":11} timed out after 10000ms)' Error 2024-07-24 20:03:55z2m: Publish 'set' 'state' to 'Light_5a' failed: 'Error: ZCL command 0xa4c1380166606c03/1 genOnOff.off({}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":false,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed ({"target":24132,"apsFrame":{"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":124},"zclSequence":14,"commandIdentifier":11} timed out after 10000ms)' Error 2024-07-24 20:05:07z2m: Publish 'set' 'state' to 'Light_5a' failed: 'Error: ZCL command 0xa4c1380166606c03/1 genOnOff.off({}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":false,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed ({"target":24132,"apsFrame":{"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":164},"zclSequence":22,"commandIdentifier":11} timed out after 10000ms)' Error 2024-07-24 20:05:17z2m: Publish 'set' 'state' to 'Light_5a' failed: 'Error: ZCL command 0xa4c1380166606c03/1 genOnOff.on({}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":false,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed ({"target":24132,"apsFrame":{"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":174},"zclSequence":25,"commandIdentifier":11} timed out after 10000ms)'

JacekKac commented 3 months ago

and now just after 1 minute 5 ON / OFF commands - all received without lags and working ok..

JacekKac commented 3 months ago

Hi there, i addes another sonoff e-dongle this time acting as a router, i will post my result in a few days but for now i have a question - should i do sth more than pairing sonoff with router firmare or network should automaticly adapt routing etc.

Nerivec commented 3 months ago

It will take a while (each device does this at its own pace), but the network should adjust automatically. You just need to pair it to Z2M, and done. Then you can do a network map in a couple of days, see how things are.

Belox86 commented 1 month ago

Hi, did you manage to solve yout problem? i'm having very similar issues particualry with TS0001. z2m: Publish 'set' 'state' to 'Apri Cancello' failed: 'Error: ZCL command 0xa4c138698401f01a/1 genOnOff.on({}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":false,"direction":0,"reservedBits":0,"writeUndiv":false}) failed (Delivery failed for {"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4160,"groupId":0,"sequence":229})'

JacekKac commented 1 month ago

still some issues.

devices without lags, ON / OFF reaction very quick, but sometimes random device even in close proximity to coordinator is getting terrible lag and after few seconds back to normal. Don't have a clue what is happening.

my main problem is not LAG between command and reaction but the devices are often going crazy and blinking ON/OFF it seems like they are trying to react to commands which are repeated/delayed. Some times i send ON to a switch and the switch is turning ON and oFF several times. Current result Channel: [2024-09-19 17:01:51.352] info: cli: Channel 25: ••••••••••••••••••••••••••••••••••••••••••••••∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙∙ [-44 dBm]

Logs:

image

Nerivec commented 1 month ago

@JacekKac You updated to 1.40.1, right? Sounds like temporary interference of some kind (or the PI gets really overloaded sometimes?). Any chance you have Bluetooth devices or wireless mouse/keyboard (sort of devices with proprietary dongles like Logitech Unify) in proximity to either the coordinator or the problem devices? These can affect the 2.4GHz band too (like WiFi). Any Thread devices nearby (Nest, etc.)?

Those Tuya TS aren't very stable routers, but that's pretty high values still. Can you share the logs behind that last Helper screenshot?

JacekKac commented 1 month ago

Did the update today, made some changes to the placement of router (new edongle as a router).

  1. i moved the pi to small rack, usb extension outside the rack with the dongle.
  2. in the rack there are some goovee leds with are indeed bluetooth and wifi enabled but they were not with the PI befor and the network was also not stable.
  3. no other 2.4 nearby i will garther new logs from today and share during the weekend
JacekKac commented 1 month ago

in case of PI it was also my thought. I am on RP3b with 1GB ram. the cpu is rather sleeping all the time, memory is high i addes some swap but it's on sdcard

pi@....:~ $ free total used free shared buff/cache available Mem: 929100 775256 52840 40 163548 153844 Swap: 2097148 678912 1418236

JacekKac commented 1 month ago

merged-file.zip

JacekKac commented 1 month ago

What i notice in the logs - my devices are very often publishing messages to coordinator / mqtt. even if no operation is done. Look ate the switches:

 2024-09-19 21:36:56z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Light_23', payload '{"last_seen":"2024-09-19T19:36:56.840Z","linkquality":152,"power_on_behavior":"previous","state":"OFF","update":{"installed_version":4110,"latest_version":4110,"state":"idle"},"update_available":null}'
info 2024-09-19 21:36:57z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Light_23', payload '{"last_seen":"2024-09-19T19:36:56.903Z","linkquality":148,"power_on_behavior":"previous","state":"OFF","update":{"installed_version":4110,"latest_version":4110,"state":"idle"},"update_available":null}'
info 2024-09-19 21:36:57z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Light_23', payload '{"last_seen":"2024-09-19T19:36:56.943Z","linkquality":152,"power_on_behavior":"previous","state":"OFF","update":{"installed_version":4110,"latest_version":4110,"state":"idle"},"update_available":null}'
info 2024-09-19 21:36:57z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Light_23', payload '{"last_seen":"2024-09-19T19:36:56.987Z","linkquality":156,"power_on_behavior":"previous","state":"OFF","update":{"installed_version":4110,"latest_version":4110,"state":"idle"},"update_available":null}'

or wall socket - probably because of current consumtion

2024-09-19 21:37:45z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Wall_5', payload '{"child_lock":"LOCK","countdown":0,"current":0.86,"energy":53.07,"indicator_mode":"off/on","last_seen":"2024-09-19T19:37:45.732Z","linkquality":148,"power":166,"power_outage_memory":"on","state":"ON","update":{"installed_version":192,"latest_version":192,"state":"idle"},"update_available":null,"voltage":222}'
info 2024-09-19 21:37:50z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Wall_5', payload '{"child_lock":"LOCK","countdown":0,"current":0.24,"energy":53.07,"indicator_mode":"off/on","last_seen":"2024-09-19T19:37:50.678Z","linkquality":152,"power":166,"power_outage_memory":"on","state":"ON","update":{"installed_version":192,"latest_version":192,"state":"idle"},"update_available":null,"voltage":222}'
info 2024-09-19 21:37:50z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Wall_5', payload '{"child_lock":"LOCK","countdown":0,"current":0.24,"energy":53.07,"indicator_mode":"off/on","last_seen":"2024-09-19T19:37:50.704Z","linkquality":152,"power":79,"power_outage_memory":"on","state":"ON","update":{"installed_version":192,"latest_version":192,"state":"idle"},"update_available":null,"voltage":222}'
info 2024-09-19 21:37:55z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Wall_5', payload '{"child_lock":"LOCK","countdown":0,"current":0.46,"energy":53.07,"indicator_mode":"off/on","last_seen":"2024-09-19T19:37:55.684Z","linkquality":156,"power":79,"power_outage_memory":"on","state":"ON","update":{"installed_version":192,"latest_version":192,"state":"idle"},"update_available":null,"voltage":222}'
info 2024-09-19 21:37:55z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Wall_5', payload '{"child_lock":"LOCK","countdown":0,"current":0.46,"energy":53.07,"indicator_mode":"off/on","last_seen":"2024-09-19T19:37:55.722Z","linkquality":156,"power":163,"power_outage_memory":"on","state":"ON","update":{"installed_version":192,"latest_version":192,"state":"idle"},"update_available":null,"voltage":222}'
info 2024-09-19 21:38:00z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Wall_5', payload '{"child_lock":"LOCK","countdown":0,"current":0.86,"energy":53.07,"indicator_mode":"off/on","last_seen":"2024-09-19T19:38:00.689Z","linkquality":152,"power":163,"power_outage_memory":"on","state":"ON","update":{"installed_version":192,"latest_version":192,"state":"idle"},"update_available":null,"voltage":222}'
info 2024-09-19 21:38:00z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Wall_5', payload '{"child_lock":"LOCK","countdown":0,"current":0.86,"energy":53.07,"indicator_mode":"off/on","last_seen":"2024-09-19T19:38:00.731Z","linkquality":152,"power":133,"power_outage_memory":"on","state":"ON","update":{"installed_version":192,"latest_version":192,"state":"idle"},"update_available":null,"voltage":222}'
info 2024-09-19 21:38:05z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Wall_5', payload '{"child_lock":"LOCK","countdown":0,"current":0.86,"energy":53.07,"indicator_mode":"off/on","last_seen":"2024-09-19T19:38:05.680Z","linkquality":156,"power":179,"power_outage_memory":"on","state":"ON","update":{"installed_version":192,"latest_version":192,"state":"idle"},"update_available":null,"voltage":222}'
info 2024-09-19 21:38:18z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Wall_5', payload '{"child_lock":"LOCK","countdown":0,"current":0.86,"energy":53.07,"indicator_mode":"off/on","last_seen":"2024-09-19T19:38:18.680Z","linkquality":108,"power":160,"power_outage_memory":"on","state":"ON","update":{"installed_version":192,"latest_version":192,"state":"idle"},"update_available":null,"voltage":222}'
info 2024-09-19 21:38:22z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Wall_5', payload '{"child_lock":"LOCK","countdown":0,"current":0.59,"energy":53.07,"indicator_mode":"off/on","last_seen":"2024-09-19T19:38:22.685Z","linkquality":144,"power":160,"power_outage_memory":"on","state":"ON","update":{"installed_version":192,"latest_version":192,"state":"idle"},"update_available":null,"voltage":222}'
info 2024-09-19 21:38:23z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Wall_5', payload '{"child_lock":"LOCK","countdown":0,"current":0.59,"energy":53.07,"indicator_mode":"off/on","last_seen":"2024-09-19T19:38:23.686Z","linkquality":144,"power":118,"power_outage_memory":"on","state":"ON","update":{"installed_version":192,"latest_version":192,"state":"idle"},"update_available":null,"voltage":222}'
info 2024-09-19 21:38:31z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Wall_5', payload '{"child_lock":"LOCK","countdown":0,"current":0.59,"energy":53.07,"indicator_mode":"off/on","last_seen":"2024-09-19T19:38:31.682Z","linkquality":144,"power":118,"power_outage_memory":"on","state":"ON","update":{"installed_version":192,"latest_version":192,"state":"idle"},"update_available":null,"voltage":222}'
info 2024-09-19 21:38:31z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Wall_5', payload '{"child_lock":"LOCK","countdown":0,"current":0.59,"energy":53.07,"indicator_mode":"off/on","last_seen":"2024-09-19T19:38:31.717Z","linkquality":144,"power":118,"power_outage_memory":"on","state":"ON","update":{"installed_version":192,"latest_version":192,"state":"idle"},"update_available":null,"voltage":222}'
info 2024-09-19 21:38:36z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Wall_5', payload '{"child_lock":"LOCK","countdown":0,"current":0.79,"energy":53.07,"indicator_mode":"off/on","last_seen":"2024-09-19T19:38:36.690Z","linkquality":108,"power":118,"power_outage_memory":"on","state":"ON","update":{"installed_version":192,"latest_version":192,"state":"idle"},"update_available":null,"voltage":222}'
info 2024-09-19 21:38:36z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Wall_5', payload '{"child_lock":"LOCK","countdown":0,"current":0.79,"energy":53.07,"indicator_mode":"off/on","last_seen":"2024-09-19T19:38:36.724Z","linkquality":108,"power":181,"power_outage_memory":"on","state":"ON","update":{"installed_version":192,"latest_version":192,"state":"idle"},"update_available":null,"voltage":222}'
info 2024-09-19 21:38:41z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Wall_5', payload '{"child_lock":"LOCK","countdown":0,"current":0.56,"energy":53.07,"indicator_mode":"off/on","last_seen":"2024-09-19T19:38:41.688Z","linkquality":140,"power":181,"power_outage_memory":"on","state":"ON","update":{"installed_version":192,"latest_version":192,"state":"idle"},"update_available":null,"voltage":222}'
info 2024-09-19 21:38:41z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Wall_5', payload '{"child_lock":"LOCK","countdown":0,"current":0.56,"energy":53.07,"indicator_mode":"off/on","last_seen":"2024-09-19T19:38:41.713Z","linkquality":140,"power":88,"power_outage_memory":"on","state":"ON","update":{"installed_version":192,"latest_version":192,"state":"idle"},"update_available":null,"voltage":222}'
info 2024-09-19 21:38:46z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Wall_5', payload '{"child_lock":"LOCK","countdown":0,"current":0.75,"energy":53.07,"indicator_mode":"off/on","last_seen":"2024-09-19T19:38:46.683Z","linkquality":140,"power":88,"power_outage_memory":"on","state":"ON","update":{"installed_version":192,"latest_version":192,"state":"idle"},"update_available":null,"voltage":222}'
info 2024-09-19 21:38:46z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Wall_5', payload '{"child_lock":"LOCK","countdown":0,"current":0.75,"energy":53.07,"indicator_mode":"off/on","last_seen":"2024-09-19T19:38:46.706Z","linkquality":144,"power":183,"power_outage_memory":"on","state":"ON","update":{"installed_version":192,"latest_version":192,"state":"idle"},"update_available":null,"voltage":222}'
info 2024-09-19 21:38:51z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Wall_5', payload '{"child_lock":"LOCK","countdown":0,"current":0.87,"energy":53.07,"indicator_mode":"off/on","last_seen":"2024-09-19T19:38:51.683Z","linkquality":136,"power":183,"power_outage_memory":"on","state":"ON","update":{"installed_version":192,"latest_version":192,"state":"idle"},"update_available":null,"voltage":222}'
info 2024-09-19 21:39:17z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Wall_5', payload '{"child_lock":"LOCK","countdown":0,"current":0.87,"energy":53.07,"indicator_mode":"off/on","last_seen":"2024-09-19T19:39:17.084Z","linkquality":140,"power":183,"power_outage_memory":"on","state":"ON","update":{"installed_version":192,"latest_version":192,"state":"idle"},"update_available":null,"voltage":222}'
info 2024-09-19 21:39:37z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Wall_5', payload '{"child_lock":"LOCK","countdown":0,"current":0.87,"energy":53.07,"indicator_mode":"off/on","last_seen":"2024-09-19T19:39:37.690Z","linkquality":136,"power":164,"power_outage_memory":"on","state":"ON","update":{"installed_version":192,"latest_version":192,"state":"idle"},"update_available":null,"voltage":222}'
info 2024-09-19 21:39:42z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Wall_5', payload '{"child_lock":"LOCK","countdown":0,"current":0.78,"energy":53.07,"indicator_mode":"off/on","last_seen":"2024-09-19T19:39:42.686Z","linkquality":132,"power":164,"power_outage_memory":"on","state":"ON","update":{"installed_version":192,"latest_version":192,"state":"idle"},"update_available":null,"voltage":222}'
info 2024-09-19 21:39:42z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Wall_5', payload '{"child_lock":"LOCK","countdown":0,"current":0.78,"energy":53.07,"indicator_mode":"off/on","last_seen":"2024-09-19T19:39:42.708Z","linkquality":132,"power":179,"power_outage_memory":"on","state":"ON","update":{"installed_version":192,"latest_version":192,"state":"idle"},"update_available":null,"voltage":222}'
info 2024-09-19 21:39:47z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Wall_5', payload '{"child_lock":"LOCK","countdown":0,"current":0.78,"energy":53.07,"indicator_mode":"off/on","last_seen":"2024-09-19T19:39:47.690Z","linkquality":136,"power":87,"power_outage_memory":"on","state":"ON","update":{"installed_version":192,"latest_version":192,"state":"idle"},"update_available":null,"voltage":222}'
info 2024-09-19 21:39:49z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Wall_5', payload '{"child_lock":"LOCK","countdown":0,"current":0.44,"energy":53.07,"indicator_mode":"off/on","last_seen":"2024-09-19T19:39:49.687Z","linkquality":136,"power":87,"power_outage_memory":"on","state":"ON","update":{"installed_version":192,"latest_version":192,"state":"idle"},"update_available":null,"voltage":222}'
info 2024-09-19 21:39:52z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Wall_5', payload '{"child_lock":"LOCK","countdown":0,"current":0.44,"energy":53.07,"indicator_mode":"off/on","last_seen":"2024-09-19T19:39:52.692Z","linkquality":144,"power":126,"power_outage_memory":"on","state":"ON","update":{"installed_version":192,"latest_version":192,"state":"idle"},"update_available":null,"voltage":222}'
info 2024-09-19 21:39:54z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Wall_5', payload '{"child_lock":"LOCK","countdown":0,"current":0.64,"energy":53.07,"indicator_mode":"off/on","last_seen":"2024-09-19T19:39:54.691Z","linkquality":144,"power":126,"power_outage_memory":"on","state":"ON","update":{"installed_version":192,"latest_version":192,"state":"idle"},"update_available":null,"voltage":222}'
info 2024-09-19 21:39:57z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Wall_5', payload '{"child_lock":"LOCK","countdown":0,"current":0.64,"energy":53.07,"indicator_mode":"off/on","last_seen":"2024-09-19T19:39:57.697Z","linkquality":144,"power":137,"power_outage_memory":"on","state":"ON","update":{"installed_version":192,"latest_version":192,"state":"idle"},"update_available":null,"voltage":222}'
info 2024-09-19 21:39:59z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Wall_5', payload '{"child_lock":"LOCK","countdown":0,"current":0.85,"energy":53.07,"indicator_mode":"off/on","last_seen":"2024-09-19T19:39:59.701Z","linkquality":152,"power":137,"power_outage_memory":"on","state":"ON","update":{"installed_version":192,"latest_version":192,"state":"idle"},"update_available":null,"voltage":222}'
info 2024-09-19 21:40:02z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Wall_5', payload '{"child_lock":"LOCK","countdown":0,"current":0.85,"energy":53.07,"indicator_mode":"off/on","last_seen":"2024-09-19T19:40:02.693Z","linkquality":168,"power":124,"power_outage_memory":"on","state":"ON","update":{"installed_version":192,"latest_version":192,"state":"idle"},"update_available":null,"voltage":222}'
info 2024-09-19 21:40:04z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Wall_5', payload '{"child_lock":"LOCK","countdown":0,"current":0.61,"energy":53.07,"indicator_mode":"off/on","last_seen":"2024-09-19T19:40:04.692Z","linkquality":160,"power":124,"power_outage_memory":"on","state":"ON","update":{"installed_version":192,"latest_version":192,"state":"idle"},"update_available":null,"voltage":222}'

maybe i can somehow limit this? i don;t use the current reporting at all

JacekKac commented 1 month ago

another example here :

info 2024-09-19 22:07:24z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Light_14a', payload '{"last_seen":"2024-09-19T20:07:24.305Z","linkquality":132,"power_on_behavior":"off","state":"ON"}' info 2024-09-19 22:07:26z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Light_14a', payload '{"last_seen":"2024-09-19T20:07:26.439Z","linkquality":132,"power_on_behavior":"off","state":"ON"}' info 2024-09-19 22:07:26z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Light_14a', payload '{"last_seen":"2024-09-19T20:07:26.462Z","linkquality":132,"power_on_behavior":"off","state":"ON"}' info 2024-09-19 22:07:26z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Light_14a', payload '{"last_seen":"2024-09-19T20:07:26.480Z","linkquality":132,"power_on_behavior":"off","state":"ON"}' info 2024-09-19 22:07:26z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Light_14a', payload '{"last_seen":"2024-09-19T20:07:26.548Z","linkquality":132,"power_on_behavior":"off","state":"ON"}' info 2024-09-19 22:07:26z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Light_14a', payload '{"last_seen":"2024-09-19T20:07:26.564Z","linkquality":132,"power_on_behavior":"off","state":"ON"}' info 2024-09-19 22:07:26z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Light_14a', payload '{"last_seen":"2024-09-19T20:07:26.602Z","linkquality":132,"power_on_behavior":"off","state":"ON"}' info 2024-09-19 22:07:26z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Light_14a', payload '{"last_seen":"2024-09-19T20:07:26.644Z","linkquality":132,"power_on_behavior":"off","state":"ON"}' info 2024-09-19 22:07:26z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Light_14a', payload '{"last_seen":"2024-09-19T20:07:26.678Z","linkquality":132,"power_on_behavior":"off","state":"ON"}' info 2024-09-19 22:07:26z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Light_14a', payload '{"last_seen":"2024-09-19T20:07:26.697Z","linkquality":132,"power_on_behavior":"off","state":"ON"}' info 2024-09-19 22:07:46z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Light_14b', payload '{"last_seen":"2024-09-19T20:07:46.285Z","linkquality":152,"power_on_behavior":"off","state":"ON"}' info 2024-09-19 22:08:20z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Light_14c', payload '{"last_seen":"2024-09-19T20:08:19.956Z","linkquality":132,"power_on_behavior":"previous","state":"ON"}' info 2024-09-19 22:10:23z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Light_14a', payload '{"last_seen":"2024-09-19T20:10:23.505Z","linkquality":132,"power_on_behavior":"off","state":"ON"}' info 2024-09-19 22:10:28z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Light_14b', payload '{"last_seen":"2024-09-19T20:10:28.489Z","linkquality":148,"power_on_behavior":"off","state":"ON"}' `

Nerivec commented 1 month ago

Unless the device supports turning off elec measurements, it will always send the data (even if Z2M ignores it somehow). And yes, that's definitely the measurements that are triggering the updates for that device.

Tuya devices are well known for spamming and/or duplicating responses. It's likely what you are seeing. And with availability/last seen, Z2M updates the device's state each time it sees one.

Maybe see if you can successfully change the settings in the Reporting tab. See docs for settings.

JacekKac commented 1 month ago

@Nerivec whats the best log level for this tool https://nerivec.github.io/z2m-ember-helper/#help? not sure if i need to cache using debug level or error level will be enought. Second question - i have logs from 4 days now and i can't parse them which this tool - error log level to short, i am not sure if you should strictly forbid to use this tool in case of shorter logs imho parsing them with this disclaimer can be also ok

Nerivec commented 1 month ago

Log level is required to be info or lower to work properly, otherwise, counters and route errors are not logged. Minimum duration (that prevents parsing) is currently set at 1 hour (so there's at least one occurrence of the counters). But technically, less than 5 hours is pretty irrelevant, best is over 1 day for sure. FIY: the reference data used to compare is based on 30 days.

JacekKac commented 1 month ago

@Nerivec sth is wrong with my log file then after combining it into one file. The file seems to be OK merger from many files with: ` find . -name '*.log' -exec cat {} \; > combined.log

this command is also not working find . ! -path ./merged-file -type f -exec cat {} + > merged-file

i used both of them in the past and the logs were ok but not it seems the parser is wrongly give the error "logs to short" `

combined.zip

Nerivec commented 1 month ago

The timestamps in your combined log appear to be in the wrong order (19>28>19).

JacekKac commented 1 month ago

my last week ...

proper command:

find . -name '*.log' -exec cat {} + > combined.log
sort -k 1,1 -k 2,2 combined.log > sorted_combined.log

image

JacekKac commented 1 month ago

@Nerivec i have double checked the power source and whole setup. No visible improvment. My new use / test case is to turn off all lights at the same time (10-20) devices. It's almost impossible to do it. Reaction times vary - sometimes few devices stays ON - i see a timeout with ZCL command. i can never turn them off in lets say 1 sec and rarly turn off all of them in 5 sec. it's not connected with the distance of coorrdinator / repeater even the closes one are not responding well.

Nerivec commented 1 month ago

That many commands at once, it's not surprising. The result would be highly dependent on the quality of the network. Unfortunately, Tuya stuff is definitely not the most stable, even without external factors meddling in...

How is the network in "normal" use?

A couple of things you can try:

gbilic commented 2 weeks ago

Hi all,

I experience exactly the same. zbdongle-e with 7.4.3 [GA] and a large majority of TS0002 devices.

From time to time, some of Tuya devices goes crazy keeping sending messages (2-5 per seconds). Some "ROUTE_ERROR_MANY_TO_ONE_ROUTE_FAILURE" appears regularly in the logs. The LQI for all devices is pretty good, mainly above 80/100. When in this situation some of the network devices could be unresponsive, but not all.

This is the zigbee network I installed at my mom's place. I personally own one for years with lots of devices and zstack zzh coordinator and never experienced this.

Do we have any idea what's causing this problem? Is this related to emberZnet stack ?

Thanks, Guillaume

Nerivec commented 2 weeks ago

zStack doesn't have any system for reporting routing errors, so, if any happen, you don't see anything.

As for the lags with Tuya spammers, it all depends on how good the network is (quality of routers, level of nearby interferences, etc.). Troubles + spammers = very unstable network. It just can't handle the spikes in messages (which may not always come from a problem at the coordinator, but at the routers in-between).

Like JacekKac did, see if the helper I built can help identify particular areas of concern (it only requires info level logs). If it doesn't help and you have a log file (debug) I can take a look at, maybe I can spot a particular problem. Also, you can try the 8.0.2 firmware linked above, it increases the configs on the adapter, which may help with spammers.

gbilic commented 2 weeks ago

What surprises me is that there are about ten TS0002s on my zstack network and none of them behave like a spammer.

Nerivec commented 2 weeks ago

Can you post a list of all the device models in your network (especially routers), and in your other network? Could be a single one that's messing things up for the rest. Tuya repeaters (dedicated, like this) are usually terrible for example (can break the entire network...).

gbilic commented 2 weeks ago

buggy network:

cat /opt/zigbee2mqtt_data/database.db | jq -r "[.id, .modelId, .type] | @tsv" 1 Coordinator 2 TS0224 Router 3 TS0001 Router 4 TS011F Router 5 TS011F Router 6 lumi.remote.b1acn01 EndDevice 7 TS0002 Router 8 Group 9 TS0002 Router 10 TS0002 Router 11 TS0002 Router 12 TS0002 Router 13 TS0002 Router 14 TS0002 Router 15 Group 16 Group 17 TS0601 EndDevice 18 lumi.remote.b1acn01 EndDevice 19 TS0601 Router 20 TS0601 EndDevice 21 lumi.remote.b1acn01 EndDevice 22 lumi.weather EndDevice 23 lumi.weather EndDevice 24 lumi.sensor_motion.aq2 EndDevice 25 lumi.sensor_magnet.aq2 EndDevice 26 lumi.sensor_magnet.aq2 EndDevice 27 lumi.sensor_magnet.aq2 EndDevice 28 lumi.sensor_magnet.aq2 EndDevice 29 lumi.sensor_magnet.aq2 EndDevice 30 lumi.sensor_magnet.aq2 EndDevice 31 lumi.sensor_magnet.aq2 EndDevice 32 lumi.sensor_magnet.aq2 EndDevice 33 lumi.sensor_magnet.aq2 EndDevice 34 lumi.sensor_magnet.aq2 EndDevice 35 lumi.sensor_magnet.aq2 EndDevice 36 TS011F Router

gbilic commented 2 weeks ago

working one:

cat /opt/zigbee2mqtt_data/database.db | jq -r "[.id, .modelId, .type] | @tsv" 1 Coordinator 2 TRADFRI control outlet Router 3 TS011F Router 4 TS0003 Router 5 TS0003 Router 6 TRADFRI bulb E27 CWS opal 600lm Router 7 TRADFRI remote control EndDevice 8 lumi.sensor_motion.aq2 EndDevice 9 Group 10 TRADFRI remote control EndDevice 11 TRADFRI on/off switch EndDevice 12 TS0001 Router 13 lumi.sensor_magnet.aq2 EndDevice 14 lumi.sensor_magnet.aq2 EndDevice 15 lumi.sensor_magnet.aq2 EndDevice 16 TRADFRI remote control EndDevice 17 TRADFRI bulb E27 opal 1000lm Router 18 Group 19 lumi.sensor_motion.aq2 EndDevice 20 lumi.vibration.aq1 EndDevice 21 lumi.sensor_magnet.aq2 EndDevice 22 lumi.sensor_cube.aqgl01 EndDevice 23 FLOALT panel WS 30x90 Router 24 TRADFRI remote control EndDevice 25 lumi.sensor_magnet.aq2 EndDevice 26 lumi.sensor_magnet.aq2 EndDevice 27 lumi.sensor_motion.aq2 EndDevice 28 lumi.vibration.aq1 EndDevice 29 LLC020 Router 30 TRADFRI control outlet Router 31 TRADFRI control outlet Router 32 TRADFRI bulb E27 CWS opal 600lm Router 33 lumi.weather EndDevice 34 Group 35 Group 36 Group 37 TS0002 Router 38 TS0002 Router 40 TS0001 Router 41 Group 42 lumi.remote.b1acn01 EndDevice 43 lumi.weather EndDevice 44 TS0001 Router 45 TS0501B Router 46 TS0001 Router 47 lumi.remote.b1acn01 EndDevice 48 Group 49 Group 50 lumi.remote.b1acn01 EndDevice 51 TS0601 EndDevice 52 TS0002 Router 53 TS0049 EndDevice 54 TS0049 EndDevice

gbilic commented 2 weeks ago

Both networks are on channel 25, the house is relatively far from everything and there's no wifi on channel 11 nearby.

Nerivec commented 2 weeks ago

Do you have some info (or debug) level logs that you can put through the helper I mentioned before (several hours, otherwise it won't be very precise)? Then post the results (just the important messages it reports).

gbilic commented 2 weeks ago

I'm currently travelling, I will try as soon as possible.

JacekKac commented 2 weeks ago

i did an upgrade to "ezsp_version":"8.0.2.0" i will let you know if sth changed. My devices list: [ 1, null, "Coordinator" ] [ 3, "TS011F", "Router" ] [ 4, "TS0001", "Router" ] [ 5, "TS0001", "Router" ] [ 6, "TS0002", "Router" ] [ 7, "TS0001", "Router" ] [ 9, "TS0001", "Router" ] [ 11, "TS0001", "Router" ] [ 12, "TS0001", "Router" ] [ 14, "TS011F", "Router" ] [ 16, "TS0001", "Router" ] [ 17, "TS011F", "Router" ] [ 18, "TS0001", "Router" ] [ 19, "TS0001", "Router" ] [ 21, "01MINIZB", "Router" ] [ 22, "TS011F", "Router" ] [ 24, "TS011F", "Router" ] [ 25, "TS011F", "Router" ] [ 26, "TS011F", "Router" ] [ 27, "TS011F", "Router" ] [ 29, "TS0002", "Router" ] [ 30, "TS0002", "Router" ] [ 31, "TS0001", "Router" ] [ 32, "TS011F", "Router" ] [ 33, "TS011F", "Router" ] [ 37, "TS0001", "Router" ] [ 41, "TS011F", "Router" ] [ 42, "TS0002", "Router" ] [ 43, "TS0003", "Router" ] [ 44, "TS0002", "Router" ] [ 46, "TS0012", "EndDevice" ] [ 47, "TS0001", "Router" ] [ 48, "TS0001", "Router" ] [ 49, "TS0001", "Router" ] [ 50, "TS0001", "Router" ] [ 52, "TS011F", "Router" ] [ 53, "TS0002", "Router" ] [ 54, "ZBMINIL2", "EndDevice" ] [ 55, "DONGLE-E_R", "Router" ] [ 56, "TS004F", "EndDevice" ] [ 57, "TS0001", "Router" ] [ 58, "TS0001", "Router" ] [ 59, "TS0001", "Router" ] [ 60, "TS0001", "Router" ] [ 61, "TS0044", "EndDevice" ] [ 62, "TS0043", "EndDevice" ] [ 63, "TS0001", "Router" ]

JacekKac commented 2 weeks ago

@Nerivec what do you think about trying to split the network into 2 different controllers / pans. I need to resolve the "stairway" switch problems. Straight lights and their delays are not a big issue for me, but stairways are configured to sync each other status and delays between them are not welcome. Maybe i can buy another e-dongle and runn 2 instances of zigbee2mqtt on a host and move these crutial devices to "clean" network ? of course i will use different channel