Message ID | 20210324114645.v2.1.I53e6be1f7df0be198b7e55ae9fc45c7f5760132d@changeid (mailing list archive) |
---|---|
State | New, archived |
Headers | show |
Series | [v2] Bluetooth: Always call advertising disable before setting params | expand |
This is automated email and please do not reply to this email! Dear submitter, Thank you for submitting the patches to the linux bluetooth mailing list. This is a CI test results with your patch series: PW Link:https://patchwork.kernel.org/project/bluetooth/list/?series=454833 ---Test result--- ############################## Test: CheckPatch - PASS ############################## Test: CheckGitLint - PASS ############################## Test: CheckBuildK - PASS ############################## Test: CheckTestRunner: Setup - PASS ############################## Test: CheckTestRunner: l2cap-tester - FAIL Total: 40, Passed: 31 (77.5%), Failed: 3, Not Run: 6 ############################## Test: CheckTestRunner: bnep-tester - PASS Total: 1, Passed: 1 (100.0%), Failed: 0, Not Run: 0 ############################## Test: CheckTestRunner: mgmt-tester - FAIL Total: 416, Passed: 348 (83.7%), Failed: 6, Not Run: 62 Failed Test Cases Add Advertising - Success 3 (!Powered, Adv Enable) Failed 0.020 seconds ############################## Test: CheckTestRunner: rfcomm-tester - PASS Total: 9, Passed: 9 (100.0%), Failed: 0, Not Run: 0 ############################## Test: CheckTestRunner: sco-tester - PASS Total: 8, Passed: 8 (100.0%), Failed: 0, Not Run: 0 ############################## Test: CheckTestRunner: smp-tester - FAIL Total: 8, Passed: 4 (50.0%), Failed: 4, Not Run: 0 ############################## Test: CheckTestRunner: userchan-tester - PASS Total: 3, Passed: 3 (100.0%), Failed: 0, Not Run: 0 --- Regards, Linux Bluetooth
This is automated email and please do not reply to this email! Dear submitter, Thank you for submitting the patches to the linux bluetooth mailing list. This is a CI test results with your patch series: PW Link:https://patchwork.kernel.org/project/bluetooth/list/?series=454833 ---Test result--- ############################## Test: CheckPatch - PASS ############################## Test: CheckGitLint - PASS ############################## Test: CheckBuildK - PASS ############################## Test: CheckTestRunner: Setup - PASS ############################## Test: CheckTestRunner: l2cap-tester - FAIL Total: 40, Passed: 31 (77.5%), Failed: 3, Not Run: 6 Failed Test Cases L2CAP LE Server - Success Timed out 2.553 seconds L2CAP LE Server - Nval SCID Timed out 2.001 seconds L2CAP LE ATT Server - Success Timed out 1.875 seconds ############################## Test: CheckTestRunner: bnep-tester - PASS Total: 1, Passed: 1 (100.0%), Failed: 0, Not Run: 0 ############################## Test: CheckTestRunner: mgmt-tester - FAIL Total: 416, Passed: 348 (83.7%), Failed: 6, Not Run: 62 Failed Test Cases Pairing Acceptor - LE 1 Timed out 2.266 seconds Pairing Acceptor - LE 2 Timed out 1.999 seconds Pairing Acceptor - LE 3 Timed out 2.000 seconds Pairing Acceptor - LE 4 Timed out 2.001 seconds Pairing Acceptor - LE 5 Timed out 1.998 seconds Add Advertising - Success 3 (!Powered, Adv Enable) Failed 0.025 seconds ############################## Test: CheckTestRunner: rfcomm-tester - PASS Total: 9, Passed: 9 (100.0%), Failed: 0, Not Run: 0 ############################## Test: CheckTestRunner: sco-tester - PASS Total: 8, Passed: 8 (100.0%), Failed: 0, Not Run: 0 ############################## Test: CheckTestRunner: smp-tester - FAIL Total: 8, Passed: 4 (50.0%), Failed: 4, Not Run: 0 Failed Test Cases SMP Server - Basic Request 1 Timed out 2.468 seconds SMP Server - Invalid Request 1 Timed out 1.984 seconds SMP Server - Invalid Request 2 Timed out 2.004 seconds SMP Server - Invalid Request 3 Timed out 1.996 seconds ############################## Test: CheckTestRunner: userchan-tester - PASS Total: 3, Passed: 3 (100.0%), Failed: 0, Not Run: 0 --- Regards, Linux Bluetooth
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 <danielwinkler@google.com> wrote: > > 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 request > > 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): 161718191a1b1c1d1e1f2021222324252627 > > 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) > > 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.001 > > 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) > > 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 <mcchou@chromium.org> > Signed-off-by: Daniel Winkler <danielwinkler@google.com> > --- > > 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 <danielwinkler@google.com> 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 > <danielwinkler@google.com> wrote: > > > > 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 request > > > 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): 161718191a1b1c1d1e1f2021222324252627 > > > 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) > > > 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.001 > > > 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) > > > 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 <mcchou@chromium.org> > > Signed-off-by: Daniel Winkler <danielwinkler@google.com> > > --- > > > > 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 > >
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