GATT: gatt_write_ccc_rsp with error (0x0e) removes always beginning from subscriptions head

[marcoster]

Describe the bug
In a multicentral application when gatt_write_ccc_rsp is called with error "0x0e", the subscriptions always get removed beginning from the head, since in the call of gatt_subscription_remove tmp is provided as the second parameter instead of prev.

To Reproduce
Not sure, what error "0x0e" is actually.
I'm testing around with many (20+) connections from one central with one subscription to each peripheral device. I guess it hapens, on enabling the notifications to the last connected device (or during connection.

To see the issue, i added a counter to bt_gatt_notification to see, how many elements are present in subscriptions. (see log output below, bt_gatt.bt_gatt_notification: handle 0x000d length 15 it 44 --> 44 subscriptions; later on only 1 subscription).

Expected behavior
Only the subscription of the disconnected device is removed.

Impact
No notifications passed to devices connected before this happens.

Screenshots or console output

[00:07:29.383,483] <dbg> bt_gatt.bt_gatt_notification: handle 0x000d length 15 it 44
[00:07:29.383,483] <dbg> bt_conn.bt_conn_unref: handle 36 ref 2
[00:07:29.492,736] <dbg> bt_conn.bt_conn_ref: handle 44 ref 3
[00:07:29.492,767] <dbg> bt_conn.bt_conn_unref: handle 44 ref 2
[00:07:29.492,797] <dbg> bt_conn.tx_complete_work: conn 0x20002fbc
[00:07:29.492,797] <dbg> bt_conn.tx_notify: conn 0x20002fbc
[00:07:29.492,828] <dbg> bt_conn.tx_notify: tx 0x2000142c cb 0x0000890d user_data 0x00000000
[00:07:29.588,165] <dbg> bt_conn.bt_conn_ref: handle 28 ref 3
[00:07:29.588,195] <dbg> bt_conn.tx_notify: conn 0x200025bc
[00:07:29.588,195] <dbg> bt_conn.bt_conn_recv: handle 28 len 22 flags 02
[00:07:29.588,195] <dbg> bt_conn.bt_conn_recv: First, len 22 final 18
[00:07:29.588,195] <dbg> bt_conn.bt_conn_recv: rx_len 0
[00:07:29.588,195] <dbg> bt_conn.bt_conn_recv: Successfully parsed 22 byte L2CAP packet
[00:07:29.588,348] <inf> mc: notification from e1:f5:e4:a9:21:37 (random) length 15
[00:07:29.588,378] <dbg> bt_gatt.bt_gatt_notification: handle 0x000d length 15 it 44
[00:07:29.588,409] <dbg> bt_conn.bt_conn_unref: handle 28 ref 2
[00:07:29.740,081] <dbg> bt_conn.bt_conn_ref: handle 43 ref 3
[00:07:29.740,112] <dbg> bt_conn.bt_conn_set_state: connected -> disconnected
[00:07:29.740,142] <dbg> bt_conn.tx_notify: conn 0x20002f1c
[00:07:29.740,142] <dbg> bt_conn.bt_conn_unref: handle 0 ref 2
[00:07:29.740,203] <dbg> bt_conn.bt_conn_prepare_events: 
[00:07:29.740,386] <dbg> bt_conn.conn_update_timeout: conn 0x20002f1c
[00:07:29.740,417] <dbg> bt_gatt.gatt_write_ccc_rsp: err 0x0e
[00:07:29.740,417] <dbg> bt_gatt.gatt_subscription_remove: gatt_subscription_remove
[00:07:29.740,509] <inf> mc: [UNSUBSCRIBED] eb:c1:0d:41:e5:26 (random)
[00:07:29.740,509] <dbg> bt_gatt.bt_gatt_disconnected: conn 0x20002f1c
[00:07:29.740,692] <dbg> bt_gatt.remove_subscriptions: remove_subscriptions
[00:07:29.740,692] <dbg> bt_gatt.gatt_subscription_remove: gatt_subscription_remove
[00:07:29.740,783] <inf> mc: [UNSUBSCRIBED] eb:c1:0d:41:e5:26 (random)
[00:07:29.740,997] <dbg> bt_conn.bt_conn_unref: handle 0 ref 1
[00:07:29.740,997] <inf> mc: Disconnected: eb:c1:0d:41:e5:26 (random) (reason 0x08)(44/64)

[00:07:29.741,027] <dbg> bt_conn.bt_conn_unref: handle 0 ref 0
[00:07:29.867,767] <dbg> bt_conn.bt_conn_ref: handle 44 ref 3
[00:07:29.867,767] <dbg> bt_conn.bt_conn_unref: handle 44 ref 2
[00:07:29.868,225] <dbg> bt_conn.bt_conn_ref: handle 44 ref 3
[00:07:29.868,225] <dbg> bt_conn.tx_notify: conn 0x20002fbc
[00:07:29.868,225] <dbg> bt_conn.bt_conn_recv: handle 44 len 14 flags 02
[00:07:29.868,225] <dbg> bt_conn.bt_conn_recv: First, len 14 final 10
[00:07:29.868,225] <dbg> bt_conn.bt_conn_recv: rx_len 0
[00:07:29.868,225] <dbg> bt_conn.bt_conn_recv: Successfully parsed 14 byte L2CAP packet
[00:07:29.868,255] <dbg> bt_gatt.gatt_find_info_rsp: err 0x00
[00:07:29.868,286] <dbg> bt_gatt.gatt_find_info_rsp: handle 0x000e uuid 2902
[00:07:29.868,408] <inf> xibu: [e2:7c:1a:18:93:28 (random)]: xibu_discover_func (536968620)
[00:07:29.868,438] <dbg> bt_gatt.gatt_write_ccc: handle 0x000e value 0x0001
[00:07:29.868,438] <inf> xibu:   up descriptor discovered, subscribe returned 0
[00:07:29.868,469] <dbg> bt_conn.bt_conn_le_param_update: conn 0x20002fbc features 0x25 params (2800-3200 0 1000)
[00:07:29.868,469] <dbg> bt_conn.send_conn_le_param_update: conn 0x20002fbc features 0x25 params (2800-3200 0 1000)
[00:07:29.868,591] <dbg> bt_conn.bt_conn_prepare_events: 
[00:07:29.868,743] <dbg> bt_conn.bt_conn_send_cb: conn handle 44 buf len 9 cb 0x0000890d user_data 0x00000000
[00:07:29.868,774] <dbg> bt_conn.bt_conn_unref: handle 44 ref 2
[00:07:29.868,835] <dbg> bt_conn.bt_conn_process_tx: conn 0x20002fbc
[00:07:29.868,835] <dbg> bt_conn.send_buf: conn 0x20002fbc buf 0x200199a8 len 9
[00:07:29.868,865] <dbg> bt_conn.send_frag: conn 0x20002fbc buf 0x200199a8 len 9 flags 0x00
[00:07:29.868,865] <dbg> bt_conn.bt_conn_prepare_events: 
[00:07:29.869,018] <inf> mc: 
Starting scanner (44/64)
[00:07:29.869,171] <dbg> bt_conn.bt_conn_prepare_events: 
[00:07:29.869,445] <dbg> bt_conn.bt_conn_prepare_events: 
[00:07:29.869,659] <dbg> bt_conn.bt_conn_prepare_events: 
[00:07:30.170,898] <inf> mc: Connecting to device f8:2d:b3:63:1e:c8 (random)
[00:07:30.171,142] <dbg> bt_conn.bt_conn_prepare_events: 
[00:07:30.171,447] <dbg> bt_conn.bt_conn_set_state: disconnected -> connect-scan
[00:07:30.171,447] <dbg> bt_conn.bt_conn_ref: handle 0 ref 2
[00:07:30.171,508] <dbg> bt_conn.bt_conn_ref: handle 0 ref 3
[00:07:30.171,508] <dbg> bt_conn.bt_conn_unref: handle 0 ref 2
[00:07:30.171,630] <dbg> bt_conn.bt_conn_prepare_events: 
[00:07:30.171,905] <dbg> bt_conn.bt_conn_prepare_events: 
[00:07:30.172,088] <dbg> bt_conn.bt_conn_prepare_events: 
[00:07:30.184,448] <dbg> bt_conn.bt_conn_ref: handle 12 ref 3
[00:07:30.184,478] <dbg> bt_conn.tx_notify: conn 0x20001bbc
[00:07:30.184,478] <dbg> bt_conn.bt_conn_recv: handle 12 len 22 flags 02
[00:07:30.184,478] <dbg> bt_conn.bt_conn_recv: First, len 22 final 18
[00:07:30.184,478] <dbg> bt_conn.bt_conn_recv: rx_len 0
[00:07:30.184,509] <dbg> bt_conn.bt_conn_recv: Successfully parsed 22 byte L2CAP packet
[00:07:30.184,509] <dbg> bt_gatt.bt_gatt_notification: handle 0x000d length 15 it 1

Environment (please complete the following information):

• OS: Linux
• Toolchain Zephyr SDK
• Commit SHA 5af5407
• Target: nrf52840_pca10056

Additional context
I'll provide a pull-request for this soon.