Hi Luiz,
Probably my analysis of the cause is wrong. I added a rl_printf when
the StopNotify was called, meshctl shows the following:
Notify started
Notify for Mesh Provisioning Out Data started
Open-Node: 0x102c470
Open-Prov: 0xff7000
Open-Prov: proxy 0xffe830
GATT-TX: 03 00 10
Attempting to write /org/bluez/hci0/dev_C3_F0_13_5D_5F_5E/service000a/char000b
Initiated provisioning
Characteristic property changed
/org/bluez/hci0/dev_C3_F0_13_5D_5F_5E/service000a/char000d
GATT-RX: 03 01 01 00 01 00 00 00 00 00 00 00 00
Got provisioning data (12 bytes)
01 01 00 01 00 00 00 00 00 00 00 00
Provisioning failed
Calling StopNotify --------------> added by me using rl_printf()
Characteristic property changed
/org/bluez/hci0/dev_C3_F0_13_5D_5F_5E/service000a/char000d
GATT-RX: 03 01 01 00 01 00 00 00 00 00 00 00 00
Node not found?
Notify stopped
Attempting to disconnect from C3:F0:13:5D:5F:5E
Services resolved no
As you can see the same data is received twice: GATT-RX: 03 01 01 00
01 ..., just after the Characteristic property changed line. I thought
that this Characteristic property change was the result of the not
changing of the node and keeping notifications on.
I also enable btmon during this process (see included file). In the
log I cannot find the data being send twice.
Kind regards,
Jehudi
2017-09-08 15:47 GMT+02:00 Luiz Augusto von Dentz <luiz.dentz@xxxxxxxxx>:
> Hi Jehudi,
>
> On Fri, Sep 8, 2017 at 3:30 PM, Laczen JMS <laczenjms@xxxxxxxxx> wrote:
>> Some mesh nodes do not change (e.g. zephyr) the notification when
>> given the StopNotify. As a result the data from the notification
>> channel is processed twice. This patch removes the StopNotify.
>
> What do you mean the node do not change? Perhaps this is the result of
> bluetoothd remembering the subscriptions so you don't have to
> StopNotify while disconnected, though this should not cause the data
> to be processed twice otherwise we have a bug somewhere in the daemon.
>
>> Kind regards,
>>
>> Jehudi
>>
>> diff --git a/mesh/gatt.c b/mesh/gatt.c
>> index f9615b3..7d3b869 100644
>> --- a/mesh/gatt.c
>> +++ b/mesh/gatt.c
>> @@ -589,15 +589,10 @@ bool mesh_gatt_notify(GDBusProxy *proxy, bool
>> enable, GDBusReturnFunction cb,
>> cb = notify_reply;
>> }
>> } else {
>> - if (notify_io) {
>> - notify_io_destroy();
>> - if (cb)
>> - cb(NULL, user_data);
>> - return true;
>> - } else {
>> - method = "StopNotify";
>> - cb = notify_reply;
>> - }
>> + if (notify_io) notify_io_destroy();
>> + if (cb) cb(NULL, user_data);
>> +
>> + return true;
>> }
>>
>> if (g_dbus_proxy_method_call(proxy, method, NULL, cb,
>> --
>> To unsubscribe from this list: send the line "unsubscribe linux-bluetooth" in
>> the body of a message to majordomo@xxxxxxxxxxxxxxx
>> More majordomo info at http://vger.kernel.org/majordomo-info.html
>
>
>
> --
> Luiz Augusto von Dentz
> HCI Event: LE Meta Event (0x3e) plen 41 #21 [hci0] 22.721365
LE Advertising Report (0x02)
Num reports: 1
Event type: Connectable undirected - ADV_IND (0x00)
Address type: Random (0x01)
Address: C3:F0:13:5D:5F:5E (Static)
Data length: 29
Flags: 0x06
LE General Discoverable Mode
BR/EDR Not Supported
16-bit Service UUIDs (complete): 1 entry
Mesh Provisioning (0x1827)
Service Data (UUID 0x1827): dddd00000000000000000000000000000000
RSSI: -36 dBm (0xdc)
< HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2 #22 [hci0] 22.721501
Scanning: Disabled (0x00)
Filter duplicates: Disabled (0x00)
> HCI Event: Command Complete (0x0e) plen 4 #23 [hci0] 22.723282
LE Set Scan Enable (0x08|0x000c) ncmd 1
Status: Success (0x00)
< HCI Command: LE Create Connection (0x08|0x000d) plen 25 #24 [hci0] 22.723361
Scan interval: 60.000 msec (0x0060)
Scan window: 60.000 msec (0x0060)
Filter policy: White list is not used (0x00)
Peer address type: Random (0x01)
Peer address: C3:F0:13:5D:5F:5E (Static)
Own address type: Public (0x00)
Min connection interval: 50.00 msec (0x0028)
Max connection interval: 70.00 msec (0x0038)
Connection latency: 0 (0x0000)
Supervision timeout: 420 msec (0x002a)
Min connection length: 0.000 msec (0x0000)
Max connection length: 0.000 msec (0x0000)
> HCI Event: Command Status (0x0f) plen 4 #25 [hci0] 22.740274
LE Create Connection (0x08|0x000d) ncmd 1
Status: Success (0x00)
> HCI Event: LE Meta Event (0x3e) plen 19 #26 [hci0] 24.721403
LE Connection Complete (0x01)
Status: Success (0x00)
Handle: 70
Role: Master (0x00)
Peer address type: Random (0x01)
Peer address: C3:F0:13:5D:5F:5E (Static)
Connection interval: 70.00 msec (0x0038)
Connection latency: 0 (0x0000)
Supervision timeout: 420 msec (0x002a)
Master clock accuracy: 0x00
@ Device Connected: C3:F0:13:5D:5F:5E (2) flags 0x0000
02 01 06 03 03 27 18 15 16 27 18 dd dd 00 00 00 .....'...'......
00 00 00 00 00 00 00 00 00 00 00 00 00 .............
< HCI Command: LE Read Remote Used.. (0x08|0x0016) plen 2 #27 [hci0] 24.721885
Handle: 70
> HCI Event: Command Status (0x0f) plen 4 #28 [hci0] 24.725320
LE Read Remote Used Features (0x08|0x0016) ncmd 1
Status: Success (0x00)
> HCI Event: LE Meta Event (0x3e) plen 12 #29 [hci0] 24.759324
LE Read Remote Used Features (0x04)
Status: Success (0x00)
Handle: 70
Features: 0x81 0x00 0x00 0x00 0x00 0x00 0x00 0x00
LE Encryption
Extended Scanner Filter Policies
< ACL Data TX: Handle 70 flags 0x00 dlen 7 #30 [hci0] 24.759847
ATT: Exchange MTU Request (0x02) len 2
Client RX MTU: 517
> HCI Event: Number of Completed Packets (0x13) plen 5 #31 [hci0] 24.829402
Num handles: 1
Handle: 70
Count: 1
> ACL Data RX: Handle 70 flags 0x02 dlen 7 #32 [hci0] 24.898141
ATT: Exchange MTU Response (0x03) len 2
Server RX MTU: 69
< ACL Data TX: Handle 70 flags 0x00 dlen 7 #33 [hci0] 24.898537
ATT: Read Request (0x0a) len 2
Handle: 0x0003
> HCI Event: Number of Completed Packets (0x13) plen 5 #34 [hci0] 24.968404
Num handles: 1
Handle: 70
Count: 1
> ACL Data RX: Handle 70 flags 0x02 dlen 11 #35 [hci0] 25.044735
ATT: Read Response (0x0b) len 6
Value: 5a6570687972
< ACL Data TX: Handle 70 flags 0x00 dlen 7 #36 [hci0] 25.044970
ATT: Read Request (0x0a) len 2
Handle: 0x0005
> HCI Event: Number of Completed Packets (0x13) plen 5 #37 [hci0] 25.108350
Num handles: 1
Handle: 70
Count: 1
> ACL Data RX: Handle 70 flags 0x02 dlen 7 #38 [hci0] 25.178088
ATT: Read Response (0x0b) len 2
Value: 0000
< ACL Data TX: Handle 70 flags 0x00 dlen 11 #39 [hci0] 25.178295
ATT: Read By Group Type Request (0x10) len 6
Handle range: 0x0001-0xffff
Attribute group type: Primary Service (0x2800)
> HCI Event: Number of Completed Packets (0x13) plen 5 #40 [hci0] 25.248347
Num handles: 1
Handle: 70
Count: 1
> ACL Data RX: Handle 70 flags 0x02 dlen 24 #41 [hci0] 25.318285
ATT: Read By Group Type Response (0x11) len 19
Attribute data length: 6
Attribute group list: 3 entries
Handle range: 0x0001-0x0005
UUID: Generic Access Profile (0x1800)
Handle range: 0x0006-0x0009
UUID: Generic Attribute Profile (0x1801)
Handle range: 0x000a-0x000f
UUID: Mesh Provisioning (0x1827)
< ACL Data TX: Handle 70 flags 0x00 dlen 11 #42 [hci0] 25.318603
ATT: Read By Group Type Request (0x10) len 6
Handle range: 0x0010-0xffff
Attribute group type: Primary Service (0x2800)
> HCI Event: Number of Completed Packets (0x13) plen 5 #43 [hci0] 25.388368
Num handles: 1
Handle: 70
Count: 1
> ACL Data RX: Handle 70 flags 0x02 dlen 9 #44 [hci0] 25.464793
ATT: Error Response (0x01) len 4
Read By Group Type Request (0x10)
Handle: 0x0010
Error: Attribute Not Found (0x0a)
< ACL Data TX: Handle 70 flags 0x00 dlen 9 #45 [hci0] 25.477285
ATT: Write Request (0x12) len 4
Handle: 0x0009
Data: 0200
> HCI Event: Number of Completed Packets (0x13) plen 5 #46 [hci0] 25.528413
Num handles: 1
Handle: 70
Count: 1
> ACL Data RX: Handle 70 flags 0x02 dlen 5 #47 [hci0] 25.598076
ATT: Write Response (0x13) len 0
< ACL Data TX: Handle 70 flags 0x00 dlen 9 #48 [hci0] 25.598323
ATT: Write Request (0x12) len 4
Handle: 0x000f
Data: 0100
> HCI Event: Number of Completed Packets (0x13) plen 5 #49 [hci0] 25.668344
Num handles: 1
Handle: 70
Count: 1
> ACL Data RX: Handle 70 flags 0x02 dlen 5 #50 [hci0] 25.738051
ATT: Write Response (0x13) len 0
< ACL Data TX: Handle 70 flags 0x00 dlen 10 #51 [hci0] 25.741207
ATT: Write Command (0x52) len 5
Handle: 0x000c
Data: 030010
> HCI Event: Number of Completed Packets (0x13) plen 5 #52 [hci0] 25.808367
Num handles: 1
Handle: 70
Count: 1
> ACL Data RX: Handle 70 flags 0x02 dlen 20 #53 [hci0] 25.884829
ATT: Handle Value Notification (0x1b) len 15
Handle: 0x000e
Data: 03010100010000000000000000
< ACL Data TX: Handle 70 flags 0x00 dlen 9 #54 [hci0] 25.887912
ATT: Write Request (0x12) len 4
Handle: 0x000f
Data: 0000
> HCI Event: Number of Completed Packets (0x13) plen 5 #55 [hci0] 25.948372
Num handles: 1
Handle: 70
Count: 1
> ACL Data RX: Handle 70 flags 0x02 dlen 5 #56 [hci0] 26.018078
ATT: Write Response (0x13) len 0
< HCI Command: Disconnect (0x01|0x0006) plen 3 #57 [hci0] 28.115615
Handle: 70
Reason: Remote User Terminated Connection (0x13)
> HCI Event: Command Status (0x0f) plen 4 #58 [hci0] 28.117458
Disconnect (0x01|0x0006) ncmd 1
Status: Success (0x00)
> HCI Event: Disconnect Complete (0x05) plen 4 #59 [hci0] 28.119462
Status: Success (0x00)
Handle: 70
Reason: Connection Terminated By Local Host (0x16)
@ Device Disconnected: C3:F0:13:5D:5F:5E (2) reason 2
