In __hci_req_enable_advertising, the HCI_LE_ADV hdev flag is temporarily
cleared to allow the random address to be set, which exposes a race
condition when an advertisement is configured immediately (<10ms) after
software rotation starts to refresh an advertisement.
In normal operation, the HCI_LE_ADV flag is updated as follows:
1. adv_timeout_expire is called, HCI_LE_ADV gets cleared in
__hci_req_enable_advertising, but hci_req configures an enable
request
2. hci_req is run, enable callback re-sets HCI_LE_ADV flag
However, in this race condition, the following occurs:
1. adv_timeout_expire is called, HCI_LE_ADV gets cleared in
__hci_req_enable_advertising, but hci_req configures an enable
request
2. add_advertising is called, which also calls
__hci_req_enable_advertising. Because HCI_LE_ADV was cleared in Step
1, no "disable" command is queued.
3. hci_req for adv_timeout_expire is run, which enables advertising and
re-sets HCI_LE_ADV
4. hci_req for add_advertising is run, but because no "disable" command
was queued, we try to set advertising parameters while advertising is
active, causing a Command Disallowed error, failing the registration.
To resolve the issue, this patch removes the check for the HCI_LE_ADV
flag, and always queues the "disable" request, since HCI_LE_ADV could be
very temporarily out-of-sync. According to the spec, there is no harm in
calling "disable" when advertising is not active.
An example trace showing the HCI error in setting advertising parameters
is included below, with some notes annotating the states I mentioned
above:
@ MGMT Command: Add Ext Adv.. (0x0055) plen 35 {0x0001} [hci0]04:05.884
Instance: 3
Advertising data length: 24
16-bit Service UUIDs (complete): 2 entries
Location and Navigation (0x1819)
Phone Alert Status Service (0x180e)
Company: not assigned (65283)
Data: 3a3b3c3d3e
Service Data (UUID 0x9993): 3132333435
Scan response length: 0
@ MGMT Event: Advertising Ad.. (0x0023) plen 1 {0x0005} [hci0]04:05.885
Instance: 3
=== adv_timeout_expire request starts running. This request was created
before our add advertising requestHCI Event: Command Complete (0x0e) plen 4 #220 [hci0]04:05.993
LE Set Advertising Data (0x08|0x0008) ncmd 1
Status: Success (0x00)
< HCI Command: LE Set Scan.. (0x08|0x0009) plen 32 #221 [hci0]04:05.993
Length: 24
Service Data (UUID 0xabcd): 161718191a1b1c1d1e1f2021222324252627HCI Event: Command Complete (0x0e) plen 4 #222 [hci0]04:05.995
LE Set Scan Response Data (0x08|0x0009) ncmd 1
Status: Success (0x00)
< HCI Command: LE Set Adver.. (0x08|0x000a) plen 1 #223 [hci0]04:05.995
Advertising: Disabled (0x00)HCI Event: Command Complete (0x0e) plen 4 #224 [hci0]04:05.997
LE Set Advertise Enable (0x08|0x000a) ncmd 1
Status: Success (0x00)
< HCI Command: LE Set Adve.. (0x08|0x0006) plen 15 #225 [hci0]04:05.997
Min advertising interval: 200.000 msec (0x0140)
Max advertising interval: 200.000 msec (0x0140)
Type: Connectable undirected - ADV_IND (0x00)
Own address type: Public (0x00)
Direct address type: Public (0x00)
Direct address: 00:00:00:00:00:00 (OUI 00-00-00)
Channel map: 37, 38, 39 (0x07)
Filter policy: Allow Scan Request, Connect from Any (0x00)HCI Event: Command Complete (0x0e) plen 4 #226 [hci0]04:05.998
LE Set Advertising Parameters (0x08|0x0006) ncmd 1
Status: Success (0x00)
< HCI Command: LE Set Adver.. (0x08|0x000a) plen 1 #227 [hci0]04:05.999
Advertising: Enabled (0x01)HCI Event: Command Complete (0x0e) plen 4 #228 [hci0]04:06.000
LE Set Advertise Enable (0x08|0x000a) ncmd 1
Status: Success (0x00)
=== Our new add_advertising request starts running
< HCI Command: Read Local N.. (0x03|0x0014) plen 0 #229 [hci0]04:06.001HCI Event: Command Complete (0x0e) plen 252 #230 [hci0]04:06.005
Read Local Name (0x03|0x0014) ncmd 1
Status: Success (0x00)
Name: Chromebook_FB3D
=== Although the controller is advertising, no disable command is sent
< HCI Command: LE Set Adve.. (0x08|0x0006) plen 15 #231 [hci0]04:06.005
Min advertising interval: 200.000 msec (0x0140)
Max advertising interval: 200.000 msec (0x0140)
Type: Connectable undirected - ADV_IND (0x00)
Own address type: Public (0x00)
Direct address type: Public (0x00)
Direct address: 00:00:00:00:00:00 (OUI 00-00-00)
Channel map: 37, 38, 39 (0x07)
Filter policy: Allow Scan Request, Connect from Any (0x00)HCI Event: Command Complete (0x0e) plen 4 #232 [hci0]04:06.005
LE Set Advertising Parameters (0x08|0x0006) ncmd 1
Status: Command Disallowed (0x0c)
Reviewed-by: Miao-chen Chou <redacted>
Signed-off-by: Daniel Winkler <redacted>
---
Changes in v2:
- Added btmon snippet showing HCI command failure
net/bluetooth/hci_request.c | 6 ++++--
1 file changed, 4 insertions(+), 2 deletions(-)
diff --git a/net/bluetooth/hci_request.c b/net/bluetooth/hci_request.c
index 8ace5d34b01efe..2b4b99f4cedf21 100644
--- a/net/bluetooth/hci_request.c
+++ b/net/bluetooth/hci_request.c
@@ -1547,8 +1547,10 @@ void __hci_req_enable_advertising(struct hci_request *req)
if (!is_advertising_allowed(hdev, connectable))
return;
- if (hci_dev_test_flag(hdev, HCI_LE_ADV))
- __hci_req_disable_advertising(req);
+ /* Request that the controller stop advertising. This can be called
+ * whether or not there is an active advertisement.
+ */
+ __hci_req_disable_advertising(req);
/* Clear the HCI_LE_ADV bit temporarily so that the
* hci_update_random_address knows that it's safe to go ahead
--
2.31.0.291.g576ba9dcdaf-goog
Hi all,
It looks like my change breaks the expectations of one mgmt-tester
test, which uses an Adv Enable (True) as a test condition. It is
surprised to first see an Adv Enable (False) in the HCI traffic, and
fails. I think my suggested approach here is the simplest and most
robust to solve this race condition, so if the maintainers are happy
with it, I can look into changing the test expectations to suit the
new scenario. Please advise.
Thanks in advance,
Daniel
On Wed, Mar 24, 2021 at 11:47 AM Daniel Winkler
[off-list ref] wrote:
quoted hunk
In __hci_req_enable_advertising, the HCI_LE_ADV hdev flag is temporarily
cleared to allow the random address to be set, which exposes a race
condition when an advertisement is configured immediately (<10ms) after
software rotation starts to refresh an advertisement.
In normal operation, the HCI_LE_ADV flag is updated as follows:
1. adv_timeout_expire is called, HCI_LE_ADV gets cleared in
__hci_req_enable_advertising, but hci_req configures an enable
request
2. hci_req is run, enable callback re-sets HCI_LE_ADV flag
However, in this race condition, the following occurs:
1. adv_timeout_expire is called, HCI_LE_ADV gets cleared in
__hci_req_enable_advertising, but hci_req configures an enable
request
2. add_advertising is called, which also calls
__hci_req_enable_advertising. Because HCI_LE_ADV was cleared in Step
1, no "disable" command is queued.
3. hci_req for adv_timeout_expire is run, which enables advertising and
re-sets HCI_LE_ADV
4. hci_req for add_advertising is run, but because no "disable" command
was queued, we try to set advertising parameters while advertising is
active, causing a Command Disallowed error, failing the registration.
To resolve the issue, this patch removes the check for the HCI_LE_ADV
flag, and always queues the "disable" request, since HCI_LE_ADV could be
very temporarily out-of-sync. According to the spec, there is no harm in
calling "disable" when advertising is not active.
An example trace showing the HCI error in setting advertising parameters
is included below, with some notes annotating the states I mentioned
above:
@ MGMT Command: Add Ext Adv.. (0x0055) plen 35 {0x0001} [hci0]04:05.884
Instance: 3
Advertising data length: 24
16-bit Service UUIDs (complete): 2 entries
Location and Navigation (0x1819)
Phone Alert Status Service (0x180e)
Company: not assigned (65283)
Data: 3a3b3c3d3e
Service Data (UUID 0x9993): 3132333435
Scan response length: 0
@ MGMT Event: Advertising Ad.. (0x0023) plen 1 {0x0005} [hci0]04:05.885
Instance: 3
=== adv_timeout_expire request starts running. This request was created
before our add advertising requestquoted
HCI Event: Command Complete (0x0e) plen 4 #220 [hci0]04:05.993
LE Set Advertising Data (0x08|0x0008) ncmd 1
Status: Success (0x00)
< HCI Command: LE Set Scan.. (0x08|0x0009) plen 32 #221 [hci0]04:05.993
Length: 24
Service Data (UUID 0xabcd): 161718191a1b1c1d1e1f2021222324252627quoted
HCI Event: Command Complete (0x0e) plen 4 #222 [hci0]04:05.995
LE Set Scan Response Data (0x08|0x0009) ncmd 1
Status: Success (0x00)
< HCI Command: LE Set Adver.. (0x08|0x000a) plen 1 #223 [hci0]04:05.995
Advertising: Disabled (0x00)quoted
HCI Event: Command Complete (0x0e) plen 4 #224 [hci0]04:05.997
LE Set Advertise Enable (0x08|0x000a) ncmd 1
Status: Success (0x00)
< HCI Command: LE Set Adve.. (0x08|0x0006) plen 15 #225 [hci0]04:05.997
Min advertising interval: 200.000 msec (0x0140)
Max advertising interval: 200.000 msec (0x0140)
Type: Connectable undirected - ADV_IND (0x00)
Own address type: Public (0x00)
Direct address type: Public (0x00)
Direct address: 00:00:00:00:00:00 (OUI 00-00-00)
Channel map: 37, 38, 39 (0x07)
Filter policy: Allow Scan Request, Connect from Any (0x00)quoted
HCI Event: Command Complete (0x0e) plen 4 #226 [hci0]04:05.998
LE Set Advertising Parameters (0x08|0x0006) ncmd 1
Status: Success (0x00)
< HCI Command: LE Set Adver.. (0x08|0x000a) plen 1 #227 [hci0]04:05.999
Advertising: Enabled (0x01)quoted
HCI Event: Command Complete (0x0e) plen 4 #228 [hci0]04:06.000
LE Set Advertise Enable (0x08|0x000a) ncmd 1
Status: Success (0x00)
=== Our new add_advertising request starts running
< HCI Command: Read Local N.. (0x03|0x0014) plen 0 #229 [hci0]04:06.001quoted
HCI Event: Command Complete (0x0e) plen 252 #230 [hci0]04:06.005
Read Local Name (0x03|0x0014) ncmd 1
Status: Success (0x00)
Name: Chromebook_FB3D
=== Although the controller is advertising, no disable command is sent
< HCI Command: LE Set Adve.. (0x08|0x0006) plen 15 #231 [hci0]04:06.005
Min advertising interval: 200.000 msec (0x0140)
Max advertising interval: 200.000 msec (0x0140)
Type: Connectable undirected - ADV_IND (0x00)
Own address type: Public (0x00)
Direct address type: Public (0x00)
Direct address: 00:00:00:00:00:00 (OUI 00-00-00)
Channel map: 37, 38, 39 (0x07)
Filter policy: Allow Scan Request, Connect from Any (0x00)quoted
HCI Event: Command Complete (0x0e) plen 4 #232 [hci0]04:06.005
LE Set Advertising Parameters (0x08|0x0006) ncmd 1
Status: Command Disallowed (0x0c)
Reviewed-by: Miao-chen Chou <redacted>
Signed-off-by: Daniel Winkler <redacted>
---
Changes in v2:
- Added btmon snippet showing HCI command failure
net/bluetooth/hci_request.c | 6 ++++--
1 file changed, 4 insertions(+), 2 deletions(-)
diff --git a/net/bluetooth/hci_request.c b/net/bluetooth/hci_request.c
index 8ace5d34b01efe..2b4b99f4cedf21 100644
--- a/net/bluetooth/hci_request.c
+++ b/net/bluetooth/hci_request.c
@@ -1547,8 +1547,10 @@ void __hci_req_enable_advertising(struct hci_request *req)
if (!is_advertising_allowed(hdev, connectable))
return;
- if (hci_dev_test_flag(hdev, HCI_LE_ADV))
- __hci_req_disable_advertising(req);
+ /* Request that the controller stop advertising. This can be called
+ * whether or not there is an active advertisement.
+ */
+ __hci_req_disable_advertising(req);
/* Clear the HCI_LE_ADV bit temporarily so that the
* hci_update_random_address knows that it's safe to go ahead
--2.31.0.291.g576ba9dcdaf-goog
Hi maintainers,
Please disregard this patch. While most chipsets honor the "Disabling
advertising when it is already disabled has no effect" clause in the
spec, I discovered over the weekend that some (WP2, ThP2, for
instance) controllers will return an error status if there is no
advertising active when the disable request is submitted. This patch
regresses advertising on these platforms, so I will look into a
different approach to solve this race condition.
Best,
Daniel Winkler
On Thu, Mar 25, 2021 at 10:27 AM Daniel Winkler
[off-list ref] wrote:
Hi all,
It looks like my change breaks the expectations of one mgmt-tester
test, which uses an Adv Enable (True) as a test condition. It is
surprised to first see an Adv Enable (False) in the HCI traffic, and
fails. I think my suggested approach here is the simplest and most
robust to solve this race condition, so if the maintainers are happy
with it, I can look into changing the test expectations to suit the
new scenario. Please advise.
Thanks in advance,
Daniel
On Wed, Mar 24, 2021 at 11:47 AM Daniel Winkler
[off-list ref] wrote:
quoted
In __hci_req_enable_advertising, the HCI_LE_ADV hdev flag is temporarily
cleared to allow the random address to be set, which exposes a race
condition when an advertisement is configured immediately (<10ms) after
software rotation starts to refresh an advertisement.
In normal operation, the HCI_LE_ADV flag is updated as follows:
1. adv_timeout_expire is called, HCI_LE_ADV gets cleared in
__hci_req_enable_advertising, but hci_req configures an enable
request
2. hci_req is run, enable callback re-sets HCI_LE_ADV flag
However, in this race condition, the following occurs:
1. adv_timeout_expire is called, HCI_LE_ADV gets cleared in
__hci_req_enable_advertising, but hci_req configures an enable
request
2. add_advertising is called, which also calls
__hci_req_enable_advertising. Because HCI_LE_ADV was cleared in Step
1, no "disable" command is queued.
3. hci_req for adv_timeout_expire is run, which enables advertising and
re-sets HCI_LE_ADV
4. hci_req for add_advertising is run, but because no "disable" command
was queued, we try to set advertising parameters while advertising is
active, causing a Command Disallowed error, failing the registration.
To resolve the issue, this patch removes the check for the HCI_LE_ADV
flag, and always queues the "disable" request, since HCI_LE_ADV could be
very temporarily out-of-sync. According to the spec, there is no harm in
calling "disable" when advertising is not active.
An example trace showing the HCI error in setting advertising parameters
is included below, with some notes annotating the states I mentioned
above:
@ MGMT Command: Add Ext Adv.. (0x0055) plen 35 {0x0001} [hci0]04:05.884
Instance: 3
Advertising data length: 24
16-bit Service UUIDs (complete): 2 entries
Location and Navigation (0x1819)
Phone Alert Status Service (0x180e)
Company: not assigned (65283)
Data: 3a3b3c3d3e
Service Data (UUID 0x9993): 3132333435
Scan response length: 0
@ MGMT Event: Advertising Ad.. (0x0023) plen 1 {0x0005} [hci0]04:05.885
Instance: 3
=== adv_timeout_expire request starts running. This request was created
before our add advertising requestquoted
HCI Event: Command Complete (0x0e) plen 4 #220 [hci0]04:05.993
LE Set Advertising Data (0x08|0x0008) ncmd 1
Status: Success (0x00)
< HCI Command: LE Set Scan.. (0x08|0x0009) plen 32 #221 [hci0]04:05.993
Length: 24
Service Data (UUID 0xabcd): 161718191a1b1c1d1e1f2021222324252627quoted
HCI Event: Command Complete (0x0e) plen 4 #222 [hci0]04:05.995
LE Set Scan Response Data (0x08|0x0009) ncmd 1
Status: Success (0x00)
< HCI Command: LE Set Adver.. (0x08|0x000a) plen 1 #223 [hci0]04:05.995
Advertising: Disabled (0x00)quoted
HCI Event: Command Complete (0x0e) plen 4 #224 [hci0]04:05.997
LE Set Advertise Enable (0x08|0x000a) ncmd 1
Status: Success (0x00)
< HCI Command: LE Set Adve.. (0x08|0x0006) plen 15 #225 [hci0]04:05.997
Min advertising interval: 200.000 msec (0x0140)
Max advertising interval: 200.000 msec (0x0140)
Type: Connectable undirected - ADV_IND (0x00)
Own address type: Public (0x00)
Direct address type: Public (0x00)
Direct address: 00:00:00:00:00:00 (OUI 00-00-00)
Channel map: 37, 38, 39 (0x07)
Filter policy: Allow Scan Request, Connect from Any (0x00)quoted
HCI Event: Command Complete (0x0e) plen 4 #226 [hci0]04:05.998
LE Set Advertising Parameters (0x08|0x0006) ncmd 1
Status: Success (0x00)
< HCI Command: LE Set Adver.. (0x08|0x000a) plen 1 #227 [hci0]04:05.999
Advertising: Enabled (0x01)quoted
HCI Event: Command Complete (0x0e) plen 4 #228 [hci0]04:06.000
LE Set Advertise Enable (0x08|0x000a) ncmd 1
Status: Success (0x00)
=== Our new add_advertising request starts running
< HCI Command: Read Local N.. (0x03|0x0014) plen 0 #229 [hci0]04:06.001quoted
HCI Event: Command Complete (0x0e) plen 252 #230 [hci0]04:06.005
Read Local Name (0x03|0x0014) ncmd 1
Status: Success (0x00)
Name: Chromebook_FB3D
=== Although the controller is advertising, no disable command is sent
< HCI Command: LE Set Adve.. (0x08|0x0006) plen 15 #231 [hci0]04:06.005
Min advertising interval: 200.000 msec (0x0140)
Max advertising interval: 200.000 msec (0x0140)
Type: Connectable undirected - ADV_IND (0x00)
Own address type: Public (0x00)
Direct address type: Public (0x00)
Direct address: 00:00:00:00:00:00 (OUI 00-00-00)
Channel map: 37, 38, 39 (0x07)
Filter policy: Allow Scan Request, Connect from Any (0x00)quoted
HCI Event: Command Complete (0x0e) plen 4 #232 [hci0]04:06.005
LE Set Advertising Parameters (0x08|0x0006) ncmd 1
Status: Command Disallowed (0x0c)
Reviewed-by: Miao-chen Chou <redacted>
Signed-off-by: Daniel Winkler <redacted>
---
Changes in v2:
- Added btmon snippet showing HCI command failure
net/bluetooth/hci_request.c | 6 ++++--
1 file changed, 4 insertions(+), 2 deletions(-)
diff --git a/net/bluetooth/hci_request.c b/net/bluetooth/hci_request.c
index 8ace5d34b01efe..2b4b99f4cedf21 100644
--- a/net/bluetooth/hci_request.c
+++ b/net/bluetooth/hci_request.c
@@ -1547,8 +1547,10 @@ void __hci_req_enable_advertising(struct hci_request *req)
if (!is_advertising_allowed(hdev, connectable))
return;
- if (hci_dev_test_flag(hdev, HCI_LE_ADV))
- __hci_req_disable_advertising(req);
+ /* Request that the controller stop advertising. This can be called
+ * whether or not there is an active advertisement.
+ */
+ __hci_req_disable_advertising(req);
/* Clear the HCI_LE_ADV bit temporarily so that the
* hci_update_random_address knows that it's safe to go ahead
--2.31.0.291.g576ba9dcdaf-goog