[PATCH 1/1] mesh: Remove StopNotify method to avoid reading data twice on some mesh nodes

[PATCH 1/1] mesh: Remove StopNotify method to avoid reading data twice on some mesh nodes

[Laczen JMS]

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.

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,

Re: [PATCH 1/1] mesh: Remove StopNotify method to avoid reading data twice on some mesh nodes

[Luiz Augusto von Dentz]

Hi Jehudi,

On Fri, Sep 8, 2017 at 3:30 PM, Laczen JMS <laczenjms@gmail.com> 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@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html



-- 
Luiz Augusto von Dentz

Re: [PATCH 1/1] mesh: Remove StopNotify method to avoid reading data twice on some mesh nodes

[Luiz Augusto von Dentz]

Hi,

On Fri, Sep 8, 2017 at 4:47 PM, Luiz Augusto von Dentz
<luiz.dentz@gmail.com> wrote:
> Hi Jehudi,
>
> On Fri, Sep 8, 2017 at 3:30 PM, Laczen JMS <laczenjms@gmail.com> 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,

Btw please have a look in our HACKING document on how to contribute patches:

https://git.kernel.org/pub/scm/bluetooth/bluez.git/tree/HACKING

-- 
Luiz Augusto von Dentz

Re: [PATCH 1/1] mesh: Remove StopNotify method to avoid reading data twice on some mesh nodes

[Laczen JMS]

[-- Attachment #1: Type: text/plain, Size: 2860 bytes --]

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@gmail.com>:
> Hi Jehudi,
>
> On Fri, Sep 8, 2017 at 3:30 PM, Laczen JMS <laczenjms@gmail.com> 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@vger.kernel.org
>> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>
>
>
> --
> Luiz Augusto von Dentz

[-- Attachment #2: bt.log --]
[-- Type: text/x-log, Size: 7905 bytes --]

> 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

Re: [PATCH 1/1] mesh: Remove StopNotify method to avoid reading data twice on some mesh nodes

[Stotland, Inga]

[-- Attachment #1: Type: text/plain, Size: 3543 bytes --]

Hi Jehudi,

On Fri, 2017-09-08 at 16:25 +0200, Laczen JMS wrote:
> 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@gmail.c
> om>:
> > Hi Jehudi,
> > 
> > On Fri, Sep 8, 2017 at 3:30 PM, Laczen JMS <laczenjms@gmail.com>
> > 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@vger.kernel.org
> > > More majordomo info at  http://vger.kernel.org/majordomo-info.htm
> > > l
> > 
> > 
> > 
> > --
> > Luiz Augusto von Dentz


Thank you for your analysis of the issue. A patch (subject "PATCH
BlueZ] mesh: Add characteristic property name check") has been
submitted and (I believe) should take care of seeing duplicate GATT-RX
output.

Regards,

Inga

[-- Attachment #2: smime.p7s --]
[-- Type: application/x-pkcs7-signature, Size: 3266 bytes --]