Somactrl throwing MTU error, stops responding

ThomasPrior commented 4 years ago

Describe the bug Periodically, seemingly without reason, soma ctrl crashes.

To Reproduce Steps to reproduce the behavior:

Wish I could reproduce this - happens at least once a day.

Expected behavior A clear and concise description of what you expected to happen.

Screenshots / Logs

root@debian:~# somactrl -d --mqtt-url REDACTED -u homeassistant -p REDACTED
  soma* No device names supplied, will stop scanning after 30 seconds +0ms
  soma* scanning for as many devices until timeout +3ms
  soma* discovered ef7fc660b28c +132ms
  soma:ef7fc660b28c mqtt topic homeassistant/cover/ef7fc660b28c +0ms
  soma:ef7fc660b28c mqtt connected +23ms
  soma* discovered eaa7e572b88f +119ms
  soma:eaa7e572b88f mqtt topic homeassistant/cover/eaa7e572b88f +0ms
  soma* discovered c6e31a0493d8 +11ms
  soma:c6e31a0493d8 mqtt topic homeassistant/cover/c6e31a0493d8 +0ms
  soma:eaa7e572b88f mqtt connected +14ms
  soma:c6e31a0493d8 mqtt connected +5ms
noble: unknown peripheral c2b66fccd9fa connected!
noble: unknown peripheral c2b66fccd9fa disconnected!
noble: unknown peripheral c2b66fccd9fa connected!
/usr/lib/node_modules/soma-ctrl/node_modules/@abandonware/noble/lib/noble.js:564
  peripheral.mtu = mtu;
                 ^

TypeError: Cannot set property 'mtu' of undefined
    at Noble.onMtu (/usr/lib/node_modules/soma-ctrl/node_modules/@abandonware/noble/lib/noble.js:564:18)
    at NobleBindings.emit (events.js:310:20)
    at NobleBindings.onMtu (/usr/lib/node_modules/soma-ctrl/node_modules/@abandonware/noble/lib/hci-socket/bindings.js:277:8)
    at Gatt.emit (events.js:310:20)
    at Object.callback (/usr/lib/node_modules/soma-ctrl/node_modules/@abandonware/noble/lib/hci-socket/gatt.js:329:10)
    at Gatt.onAclStreamData (/usr/lib/node_modules/soma-ctrl/node_modules/@abandonware/noble/lib/hci-socket/gatt.js:133:26)
    at AclStream.emit (events.js:322:22)
    at AclStream.push (/usr/lib/node_modules/soma-ctrl/node_modules/@abandonware/noble/lib/hci-socket/acl-stream.js:33:10)
    at NobleBindings.onAclDataPkt (/usr/lib/node_modules/soma-ctrl/node_modules/@abandonware/noble/lib/hci-socket/bindings.js:288:15)
    at Hci.emit (events.js:310:20)

Versions

Node/npm/OS version: Node 12.16.2, NPM 6.14.4, Debian Buster stable
Soma-ctrl version: 2.0.0
Home Assistant version (if applicable): 108.6

Additional context Same issue occurs on both a noble supported BT adapter and one not on the list, throwing the same MTU error. Tried forking and updating noble and bt-hci-socket but that has had zero impact on behaviour.

Hard to catch as -d does not appear to log to file and I have to watch the console to catch it. So far it's beyond my ability to trace this issue.

ThomasPrior commented 4 years ago

Replicated on Node 10.15.2 and latest somactrl:

soma:ef7fc660b28c disconnected +1m
  soma:ef7fc660b28c connected for 60.609 seconds +0ms
  soma:c6e31a0493d8 connected! +72ms
  soma:ef7fc660b28c connected! +186ms
  soma:ef7fc660b28c disconnected +22ms
  soma:ef7fc660b28c connected for 0.022 seconds +0ms
  soma:ef7fc660b28c connected! +57ms
  soma:eaa7e572b88f disconnected +37s
  soma:eaa7e572b88f connected for 60.616 seconds +1ms
  soma:eaa7e572b88f connected! +78ms
  soma:eaa7e572b88f disconnected +118ms
  soma:eaa7e572b88f connected for 0.118 seconds +0ms
  soma:eaa7e572b88f connected! +48ms
  soma:c2b66fccd9fa disconnected +1m
  soma:c2b66fccd9fa connected for 60.571 seconds +1ms
  soma:c2b66fccd9fa connected! +90ms
  soma:c6e31a0493d8 disconnected +1m
  soma:c6e31a0493d8 connected for 60.605 seconds +1ms
  soma:c6e31a0493d8 connected! +68ms
  soma:ef7fc660b28c disconnected +1m
  soma:ef7fc660b28c connected for 60.628 seconds +1ms
  soma:ef7fc660b28c connected! +135ms
  soma:eaa7e572b88f disconnected +1m
  soma:eaa7e572b88f connected for 60.671 seconds +0ms
  soma:eaa7e572b88f connected! +285ms
  soma:eaa7e572b88f disconnected +16ms
  soma:eaa7e572b88f connected for 0.016 seconds +0ms
  soma:eaa7e572b88f connected! +119ms
  soma:c2b66fccd9fa disconnected +1m
  soma:c2b66fccd9fa connected for 60.586 seconds +1ms
  soma:c2b66fccd9fa connected! +150ms
  soma:c2b66fccd9fa disconnected +16ms
  soma:c2b66fccd9fa connected for 0.016 seconds +0ms
  soma:c2b66fccd9fa connected! +65ms
  soma:c2b66fccd9fa disconnected +115ms
  soma:c2b66fccd9fa connected for 0.115 seconds +0ms
  soma:c2b66fccd9fa connected! +50ms
  soma:c2b66fccd9fa disconnected +114ms
  soma:c2b66fccd9fa connected for 0.114 seconds +0ms
  soma:c2b66fccd9fa connected! +40ms
  soma:c2b66fccd9fa disconnected +116ms
  soma:c2b66fccd9fa connected for 0.116 seconds +0ms
  soma:c2b66fccd9fa connected! +50ms
  soma:eaa7e572b88f requesting move to 20 +14s
  soma:eaa7e572b88f requesting move to 31 +8s
  soma:eaa7e572b88f requesting move to 24 +202ms
  soma:eaa7e572b88f requesting stop +3s
/usr/local/lib/node_modules/soma-ctrl/node_modules/@abandonware/noble/lib/hci-socket/gatt.js:548
  const characteristic = this._characteristics[serviceUuid][characteristicUuid];
                                                           ^

TypeError: Cannot read property '00001530b87f490c92cb11ba5ea5167c' of undefined
    at Gatt.write (/usr/local/lib/node_modules/soma-ctrl/node_modules/@abandonware/noble/lib/hci-socket/gatt.js:548:60)
    at NobleBindings.write (/usr/local/lib/node_modules/soma-ctrl/node_modules/@abandonware/noble/lib/hci-socket/bindings.js:399:10)
    at Noble.write (/usr/local/lib/node_modules/soma-ctrl/node_modules/@abandonware/noble/lib/noble.js:421:18)
    at Characteristic.write (/usr/local/lib/node_modules/soma-ctrl/node_modules/@abandonware/noble/lib/characteristic.js:75:15)
    at SomaShade.stop (/usr/local/lib/node_modules/soma-ctrl/src/SomaShade.js:104:34)
    at MqttClient.MQTTConnector.mqttClient.on (/usr/local/lib/node_modules/soma-ctrl/src/MQTTConnector.js:24:28)
    at MqttClient.emit (events.js:189:13)
    at MqttClient._handlePublish (/usr/local/lib/node_modules/soma-ctrl/node_modules/mqtt/lib/client.js:987:12)
    at MqttClient._handlePacket (/usr/local/lib/node_modules/soma-ctrl/node_modules/mqtt/lib/client.js:336:12)
    at work (/usr/local/lib/node_modules/soma-ctrl/node_modules/mqtt/lib/client.js:292:12)
root@debian:/usr/sbin# e

ratsept commented 4 years ago

Something very similar was/is happening in SOMA Connect as well. We have found it happens more often the more devices you have. More specifically every BLE packet exchange has a chance of this happening. We are running this on a Raspberry Pi 3 and that hardware specifically does not have flow control for the wireless chipset. Same error never happened to us on Pi 4. Might be something to look into. So far we have been able to minimize the chance of this happening but have found no way to completely fix this issue without using better hardware.

ThomasPrior commented 4 years ago

Thanks for the information! I'll grab a Pi4 and test again later this month.

andersonshatch / soma-ctrl

Somactrl throwing MTU error, stops responding #101