1technophile / OpenMQTTGateway

MQTT gateway for ESP8266 or ESP32 with bidirectional 433mhz/315mhz/868mhz, Infrared communications, BLE, Bluetooth, beacons detection, mi flora, mi jia, LYWSD02, LYWSD03MMC, Mi Scale, TPMS, BBQ thermometer compatibility & LoRa.
https://docs.openmqttgateway.com
GNU General Public License v3.0
3.5k stars 775 forks source link

Exception when several commands arrive in a short time #1424

Open sebbo2002 opened 1 year ago

sebbo2002 commented 1 year ago

Describe the bug If several ble_write_address commands are sent in a too short time interval, I get an exception and the command is not executed.

To Reproduce Steps to reproduce the behavior:

  1. Publish two (or more) write commands directly after each other. Example:
    
    {"ble_write_address":"DD:A2:6E:62:B8:2F","ble_write_service":"cba20d00-224d-11e6-9fb8-0002a5d5c51b","ble_write_char":"cba20002-224d-11e6-9fb8-0002a5d5c51b","ble_write_value":"570F450105FF00","value_type":"HEX","mac_type":1,"ttl":5,"immediate":true}

{"ble_write_address":"EC:B9:3A:06:BF:96","ble_write_service":"cba20d00-224d-11e6-9fb8-0002a5d5c51b","ble_write_char":"cba20002-224d-11e6-9fb8-0002a5d5c51b","ble_write_value":"570F450105FF00","value_type":"HEX","mac_type":1,"ttl":5,"immediate":true}


2. See exception

16:51:25.610 -> N: [ MQTT->OMG ]: {"ble_write_address":"DD:A2:6E:62:B8:2F","ble_write_service":"cba20d00-224d-11e6-9fb8-0002a5d5c51b","ble_write_char":"cba20002-224d-11e6-9fb8-0002a5d5c51b","ble_write_value":"570F450105FF00","value_type":"HEX","mac_type":1,"ttl":5,"immediate":true} 16:51:25.610 -> N: Send on /BTtoMQTT msg {"bleconnect":true,"interval":55555,"activescan":true,"scanbcnct":10,"onlysensors":false,"hasspresence":false,"presenceTopic":"presence/","presenceUseBeaconUuid":false,"minrssi":-100,"extDecoderEnable":false,"extDecoderTopic":"undecoded","filterConnectable":false,"pubadvdata":false,"pubBeaconUuidForTopic":false,"ignoreWBlist":false} 16:51:25.658 -> N: BLE Connect begin 16:51:25.658 -> N: [ MQTT->OMG ]: {"ble_write_address":"EC:B9:3A:06:BF:96","ble_write_service":"cba20d00-224d-11e6-9fb8-0002a5d5c51b","ble_write_char":"cba20002-224d-11e6-9fb8-0002a5d5c51b","ble_write_value":"570F450105FF00","value_type":"HEX","mac_type":1,"ttl":5,"immediate":true} 16:51:25.658 -> N: Send on /BTtoMQTT msg {"bleconnect":true,"interval":55555,"activescan":true,"scanbcnct":10,"onlysensors":false,"hasspresence":false,"presenceTopic":"presence/","presenceUseBeaconUuid":false,"minrssi":-100,"extDecoderEnable":false,"extDecoderTopic":"undecoded","filterConnectable":false,"pubadvdata":false,"pubBeaconUuidForTopic":false,"ignoreWBlist":false} 16:51:26.041 -> Guru Meditation Error: Core 1 panic'ed (LoadProhibited). Exception was unhandled. 16:51:26.041 -> Core 1 register dump: 16:51:26.041 -> PC : 0x400fdf2f PS : 0x00060730 A0 : 0x800f6a2e A1 : 0x3ffeae90
16:51:26.041 -> A2 : 0x00000000 A3 : 0x3ffc43e8 A4 : 0x00060720 A5 : 0x00000001
16:51:26.041 -> A6 : 0x00060d20 A7 : 0x00000000 A8 : 0x800f607e A9 : 0x3ffeae80
16:51:26.080 -> A10 : 0x3ffc43dc A11 : 0x00000000 A12 : 0x00000038 A13 : 0x3ffc4414
16:51:26.080 -> A14 : 0x0000200d A15 : 0x00000003 SAR : 0x00000018 EXCCAUSE: 0x0000001c
16:51:26.080 -> EXCVADDR: 0x00000000 LBEG : 0x4000c46c LEND : 0x4000c477 LCOUNT : 0x00000000
16:51:26.080 -> 16:51:26.080 -> ELF file SHA256: 0000000000000000 16:51:26.080 -> 16:51:26.080 -> Backtrace: 0x400fdf2f:0x3ffeae90 0x400f6a2b:0x3ffeaeb0 0x400effcf:0x3ffeaf10 0x400f0036:0x3ffeaf40 0x400d47ce:0x3ffeaf80 0x400dd657:0x3ffeafd0 0x400d629d:0x3ffeb030 0x400d71d2:0x3ffeb0a0 0x400d754e:0x3ffeb110 0x40090dba:0x3ffeb150 16:51:26.113 -> 16:51:26.113 -> Rebooting... 16:51:26.754 -> N: 16:51:26.754 -> ***** WELCOME TO OpenMQTTGateway **



**Expected behavior**
Since both write requests have the `immediate` flag set, I would expect both requests to be written to a queue, the scan to be interrupted, and then both requests to be processed in sequence.

**Environment:**
* OpenMQTTGateway version used
  * I use the dev build that was provided in [#1412](https://github.com/1technophile/OpenMQTTGateway/issues/1412#issuecomment-1399539559), as this version has decoding support for Switchbot Curtains. I have not tested the current / stable release, as I assume this test build is otherwise up to date.
* ~~Library version related to the problem you have (if you have troubles with RF provide the version of RCSwitch library)~~
* ~~For IR and RF clarify if you tested with the basic examples given with these libraries~~

**Additional context**
- I used the web installer to upload OpenMQTTGateway (environment `esp32dev-ble`)

---

* [x] You should not have a compilation error if you use the versions of the libraries linked into the libraries folder, this badges show you the state of the compilation 
[![Build Status](https://github.com/1technophile/OpenMQTTGateway/workflows/Build/badge.svg?branch=master)](https://github.com/1technophile/OpenMQTTGateway/actions)
- [x] If you are not sure this is a bug or an enhancement post your question to the forum below
[![Community forum](https://img.shields.io/badge/community-forum-brightgreen.svg)](https://community.openmqttgateway.com)
1technophile commented 1 year ago

Thanks for pointing this.

With immediate:false the BT action will go to a queue and be processed at the next connect time. You can play with the time between connects to reduce the time. This will work but is not ideal as other actions are processed within this connect function, retrieving battery level of MiFloras or sensors values of some connectable sensors (LYWSD03MMC, MHO_C401 with stock firmware). If you don't have those it may be interesting to try this.

In the meantime I will check how this mechanism can be improved.

sebbo2002 commented 1 year ago

My current workaround is that I have a fixed delay between both curtains of 10 seconds via the home automation. I also experimented with immediate: false first, but I prefer that at least one of the curtains moves immediately.

In the meantime I will check how this mechanism can be improved.

Thank you 🙏🏼

DigiH commented 1 year ago

More details with the same sending of two successive WRITE commands, with decoded backtrace

N: [ MQTT->OMG ]: {"ble_write_address":"AA:AA:AA:DD:EE:FF","mac_type":0,"ble_write_service":"ff02","ble_write_char":"fffb","ble_write_value":"00ff000000000100","value_type":"HEX","ttl":10,"immediate":true}
N: Send on /BTtoMQTT msg {"bleconnect":false,"interval":20000,"adaptivescan":false,"intervalacts":180000,"intervalcnct":3600000,"scanduration":10000,"onlysensors":false,"randommacs":false,"hasspresence":false,"presenceTopic":"presence/","presenceUseBeaconUuid":false,"minrssi":-100,"extDecoderEnable":false,"extDecoderTopic":"undecoded","filterConnectable":false,"pubadvdata":true,"pubBeaconUuidForTopic":false,"ignoreWBlist":false,"presenceawaytimer":120000,"btqblck":5,"btqsum":63,"btqsnd":41,"btqavg":1.536585}
N: BLE Connect begin
N: [ MQTT->OMG ]: {"ble_write_address":"BB:BB:BB:DD:EE:FF","mac_type":0,"ble_write_service":"ff02","ble_write_char":"fffb","ble_write_value":"00ff000000000100","value_type":"HEX","ttl":10,"immediate":true}
N: Send on /BTtoMQTT msg {"bleconnect":false,"interval":20000,"adaptivescan":false,"intervalacts":180000,"intervalcnct":3600000,"scanduration":10000,"onlysensors":false,"randommacs":false,"hasspresence":false,"presenceTopic":"presence/","presenceUseBeaconUuid":false,"minrssi":-100,"extDecoderEnable":false,"extDecoderTopic":"undecoded","filterConnectable":false,"pubadvdata":true,"pubBeaconUuidForTopic":false,"ignoreWBlist":false,"presenceawaytimer":120000,"btqblck":5,"btqsum":63,"btqsnd":41,"btqavg":1.536585}
E: Connect to: aa:aa:aa:dd:ee:ff failed
Guru Meditation Error: Core  1 panic'ed (LoadProhibited). Exception was unhandled.

Core  1 register dump:
PC      : 0x400d73c6  PS      : 0x00060d30  A0      : 0x800d9cc6  A1      : 0x3ffeb970  
A2      : 0x3ffe33f0  A3      : 0x3ffe87f8  A4      : 0x00000012  A5      : 0x3ffdc740  
A6      : 0x3ffc58f8  A7      : 0x3ffe87f8  A8      : 0x800d75f6  A9      : 0x3ffeb950  
A10     : 0x3ffeb97c  A11     : 0x3ffc53fc  A12     : 0x3ffe87f8  A13     : 0x3ffc775c  
A14     : 0x3ffe9c04  A15     : 0x3ffc4718  SAR     : 0x0000001b  EXCCAUSE: 0x0000001c  
EXCVADDR: 0x0000002d  LBEG    : 0x40090968  LEND    : 0x4009097e  LCOUNT  : 0x00000000  

Backtrace: 0x400d73c3:0x3ffeb970 0x400d9cc3:0x3ffeb9d0

  #0  0x400d73c3:0x3ffeb970 in BLEconnect() at main/ZgatewayBT.ino:737 (discriminator 1)
  #1  0x400d9cc3:0x3ffeb9d0 in immediateBTAction(void*) at main/ZgatewayBT.ino:1237

ELF file SHA256: de46383a51952943
Rebooting...
h2zero commented 1 year ago

This looks to be caused by the bleconnect loop still iterating when the command arrives which then swaps the queue when immediate is used. A semaphore or other blocking mechanism my be required.

github-actions[bot] commented 9 months ago

This issue is stale because it has been open for 30 days with no activity.

sebbo2002 commented 9 months ago

This bug is still present in the current version 1.6.0... #unstale

github-actions[bot] commented 6 months ago

This issue is stale because it has been open for 90 days with no activity.

DigiH commented 6 months ago

Bump