search

apache / mynewt-nimble

Apache mynewt
https://mynewt.apache.org/
Apache License 2.0
683 stars 392 forks source link

Callback triggered multiple times for same request #382

Open HendrikVE opened 5 years ago

HendrikVE commented 5 years ago

Hello,

I have an issue with nimble on RIOT. My testing environment is the following:

If I read the read- and writeable characteristic, then its callback is called twice, the readonly characteristic only once. But if i write to the rw characteristic and read it again, the callback is called once from there on. In another application a callback is called 6 times on a read operation, which leads to empty messages if I don't handle every single callback, but that's problematic because it's a ringbuffer and I get the message exactly one time.

@haukepetersen experienced the same issue on his board with the nimble_gatt example.

Is that behaviour intended? I thought as a callback it should be only called once, when the characteristic is read from or wrote to, or am I wrong?

Below is my terminal output:

2019-03-23 17:23:19,013 - INFO # main(): This is RIOT! (Version: 2019.04-devel-597-gc0d90)
2019-03-23 17:23:19,015 - INFO # NimBLE GATT Server Example

2019-03-23 17:24:30,496 - INFO # service 'rw demo' callback triggered
2019-03-23 17:24:30,499 - INFO # access to characteristic 'rw demo (write)'
2019-03-23 17:24:30,501 - INFO # read from characteristic
2019-03-23 17:24:30,508 - INFO # current value of rm_demo_write_data: 'This characteristic is read- and writeable!'
2019-03-23 17:24:30,509 - INFO # 
2019-03-23 17:24:30,642 - INFO # service 'rw demo' callback triggered
2019-03-23 17:24:30,646 - INFO # access to characteristic 'rw demo (write)'
2019-03-23 17:24:30,648 - INFO # read from characteristic
2019-03-23 17:24:30,655 - INFO # current value of rm_demo_write_data: 'This characteristic is read- and writeable!'
2019-03-23 17:24:30,655 - INFO # 

2019-03-23 17:24:34,395 - INFO # service 'rw demo' callback triggered
2019-03-23 17:24:34,399 - INFO # access to characteristic 'rw demo (read-only)'
2019-03-23 17:24:34,401 - INFO # new random number: 8
2019-03-23 17:24:34,402 - INFO # 

2019-03-23 17:24:45,657 - INFO # service 'rw demo' callback triggered
2019-03-23 17:24:45,660 - INFO # access to characteristic 'rw demo (write)'
2019-03-23 17:24:45,662 - INFO # write to characteristic
2019-03-23 17:24:45,669 - INFO # old value of rm_demo_write_data: 'This characteristic is read- and writeable!'
2019-03-23 17:24:45,673 - INFO # new value of rm_demo_write_data: 'test'
2019-03-23 17:24:45,674 - INFO # 

2019-03-23 17:24:48,192 - INFO # service 'rw demo' callback triggered
2019-03-23 17:24:48,195 - INFO # access to characteristic 'rw demo (write)'
2019-03-23 17:24:48,198 - INFO # read from characteristic
2019-03-23 17:24:48,201 - INFO # current value of rm_demo_write_data: 'test'
2019-03-23 17:24:48,202 - INFO #
sjanc commented 5 years ago

Hi,we just released NimBLE 1.1.0, could you check if this is stil an issue?

HendrikVE commented 5 years ago

Hello,

I've tested it again and edited the file "pkg/nimble/Makefile" in the RIOT repository. I've set the PKG_VERSION to the latest commit of nimble (18afa6b76c12607b4cf45fa922c1c77c9163c8eb), but I still get multiple calls on my callbacks.

rymanluk commented 5 years ago

Is this issues still valid? I have just looked quickly into the code and I don't see a way that access callback would be triggered twice. Would you mind sending btsnoop logs matching those terminal logs?

HendrikVE commented 5 years ago

Yes, sadly I still have this issue. Here you go: hci_snoop20190516161721.cfa.zip

hurricanefrog commented 7 months ago

Funny, I experienced a similar problem with a quick sample app I did (just one read characteristic). The read callback would be called twice in quick succession.

I printed the backtrace and got this:

(my code..)

0x400ec541: ble_gatts_val_access at C:/VSCode/esp/esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_gatts.c:375
 (inlined by) ble_gatts_val_access at C:/VSCode/esp/esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_gatts.c:340

0x400ec5d5: ble_gatts_chr_val_access at C:/VSCode/esp/esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_gatts.c:421

0x400ef359: ble_att_svr_read at C:/VSCode/esp/esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_att_svr.c:398

0x400ef5fa: ble_att_svr_read_handle at C:/VSCode/esp/esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_att_svr.c:473

0x400efcf1: ble_att_svr_rx_read at C:/VSCode/esp/esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_att_svr.c:1478

0x400e9739: ble_att_rx at C:/VSCode/esp/esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_att.c:511

0x400e961b: ble_hs_hci_evt_acl_process at C:/VSCode/esp/esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_hs_hci_evt.c:994

0x400e8f04: ble_hs_process_rx_data_queue at C:/VSCode/esp/esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_hs.c:238
...

(my code)...
0x400ec541: ble_gatts_val_access at C:/VSCode/esp/esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_gatts.c:375
 (inlined by) ble_gatts_val_access at C:/VSCode/esp/esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_gatts.c:340

0x400ec5d5: ble_gatts_chr_val_access at C:/VSCode/esp/esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_gatts.c:421

0x400ef359: ble_att_svr_read at C:/VSCode/esp/esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_att_svr.c:398

0x400ef5fa: ble_att_svr_read_handle at C:/VSCode/esp/esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_att_svr.c:473

0x400efd75: ble_att_svr_rx_read_blob at C:/VSCode/esp/esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_att_svr.c:1528

0x400e9739: ble_att_rx at C:/VSCode/esp/esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_att.c:511

0x400e961b: ble_hs_hci_evt_acl_process at C:/VSCode/esp/esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_hs_hci_evt.c:994

0x400e8f04: ble_hs_process_rx_data_queue at C:/VSCode/esp/esp-idf/components/bt/host/nimble/nimble/nimble/host/src/ble_hs.c:238

It appears to me that the nRF Connect app calls the read request twice, which appears at NumBLE as BLE_ATT_OP_READ_REQ and BLE_ATT_OP_READ_BLOB_REQ.

If I use https://sensboston.github.io/BLEConsole/, I only get one read request.

(ESP-IDF 4.4.6)

sjanc commented 7 months ago

Hi,

yes, this is how GATT defines procedure for long reads (when data is larger than current ATT MTU), as NimBLE hides some details of long reads on server side it appears as multiple read callbacks, some more discussion on this (and how we could extend API to give application more context) is in https://github.com/apache/mynewt-nimble/issues/1090