The bluetooth/bluez-internal-uc-tests_User channel open - Success test, fails intermittently.

[EstebanVg15]

Bug Description

When running the bluez-automated test plan on Tegra devices, we have seen that from time to time the bluetooth/bluez-internal-uc-tests_User channel open - Success test (i.e., sometimes fails failure.zip and some times succeeds success.zip). We have executed the tests outside the snap confinement installing bluez-tests and including the -d flag for debug

$ sudo apt install bluez-tests
$ sudo userchan-tester -p "User channel open - Success" -d

User channel open - Success - init
  mgmt: [0xffff] command 0x0003
  mgmt: < 03 00 ff ff 00 00                                ......          
  mgmt: > 01 00 ff ff 07 00 03 00 00 01 00 00 00           .............   
  mgmt: [0xffff] command 0x0003 complete: 0x00
  Read Index List callback
    Status: 0x00
  New hciemu instance created
  mgmt: > 04 00 01 00 00 00                                ......          
  mgmt: [0x0001] event 0x0004
  Index Added callback
    Index: 0x0001
  mgmt: > 06 00 01 00 04 00 c0 00 00 00                    ..........      
  mgmt: [0x0001] event 0x0006
  mgmt: [0x0001] command 0x0004
  mgmt: < 04 00 01 00 00 00                                ......          
  mgmt: > 01 00 01 00 1b 01 04 00 00 01 00 00 01 aa 00 05  ................
  mgmt:   f1 05 ff 10 01 00 c1 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00                                               .               
  mgmt: [0x0001] command 0x0004 complete: 0x00
  Read Info callback
    Status: 0x00
    Address: 00:AA:01:00:00:01
    Version: 0x05
    Manufacturer: 0x05f1
    Supported settings: 0x000110ff
    Current settings: 0x000000c1
    Class: 0x000000
    Name: 
    Short name: 
User channel open - Success - setup
User channel open - Success - setup complete
User channel open - Success - run
User channel open - Success - test failed
  mgmt: > 06 00 01 00 04 00 c1 00 00 00                    ..........      
  mgmt: [0x0001] event 0x0006
User channel open - Success - teardown
  mgmt: > 06 00 01 00 04 00 c0 00 00 00                    ..........      
  mgmt: [0x0001] event 0x0006
  mgmt: > 05 00 01 00 00 00                                ......          
  mgmt: [0x0001] event 0x0005
  Index Removed callback
    Index: 0x0001
User channel open - Success - teardown complete
User channel open - Success - done


Test Summary
------------
User channel open - Success                          Failed       0.003 seconds
Total: 1, Passed: 0 (0.0%), Failed: 1, Not Run: 0
Overall execution time: 0.00263 seconds

According to the output above, these are our findings.

• Event 0x0006 (New Settings): The controller settings change to 0x000000c1. Bit 0 is set, meaning the controller is Powered On.
• But to open an HCI User Channel, there is required that the device is Powered Off (the interface must be down). If any process (like bluetoothd) has already powered the controller or is using it, the HCI_USER_CHANNEL bind request will fail with EBUSY.

To confirm this, We manually stopped the Blue-tooth service, and ran userchan-tester 100 times (all worked) then re-started the service and ran ran userchan-tester 100 times (only 80 worked and 20 failed ), so definitely the BT service is indirectly introducing noise to this test.

$ sudo systemctl stop bluetooth
$ for i in {1..100}; do echo "$i"; sudo userchan-tester -p "User channel open - Success"; done
$ sudo systemctl start bluetooth
$ for i in {1..100}; do echo "$i"; sudo userchan-tester -p "User channel open - Success"; done

Cert-blocker Test Case

• cert-blocker

To Reproduce

1. Install bluez-tests

$ sudo apt install bluez-tests

2. Stop the bluetooth service and run 100 times the userchan-tester (All will work fine).

$ sudo systemctl stop bluetooth
$ for i in {1..100}; do echo "$i"; sudo userchan-tester -p "User channel open - Success"; done

3. Restart the bluetooth service and run 100 times the userchan-tester (Some tests will fail others will succeed).

$ sudo systemctl start bluetooth
$ for i in {1..100}; do echo "$i"; sudo userchan-tester -p "User channel open - Success"; done

Expected Result

The tests should work anyways, since the bluetooth/bluez-internal-uc-tests_User channel open - Success checkbox test case is being executed without stopping the Bluetooth service.

Actual Result

The tests fail from time to time, sometimes they work other times they fail.

Environment

• OS: Ubuntu 22.04 LTS
• Checkbox type: Snap checkbox22 7.0.0-dev150 2434 latest/beta ce-certification-qa
• Checkbox version: checkbox22 7.0.0.dev150
• Hardware being tested: nvidia-jetson-orin-nano

Relevant log output

ubuntu@ubuntu:~$ sudo userchan-tester -p "User channel open - Success" -d

User channel open - Success - init
  mgmt: [0xffff] command 0x0003
  mgmt: < 03 00 ff ff 00 00                                ......          
  mgmt: > 01 00 ff ff 07 00 03 00 00 01 00 00 00           .............   
  mgmt: [0xffff] command 0x0003 complete: 0x00
  Read Index List callback
    Status: 0x00
  New hciemu instance created
  mgmt: > 04 00 01 00 00 00                                ......          
  mgmt: [0x0001] event 0x0004
  Index Added callback
    Index: 0x0001
  mgmt: > 06 00 01 00 04 00 c0 00 00 00                    ..........      
  mgmt: [0x0001] event 0x0006
  mgmt: [0x0001] command 0x0004
  mgmt: < 04 00 01 00 00 00                                ......          
  mgmt: > 01 00 01 00 1b 01 04 00 00 01 00 00 01 aa 00 05  ................
  mgmt:   f1 05 ff 10 01 00 c1 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00                                               .               
  mgmt: [0x0001] command 0x0004 complete: 0x00
  Read Info callback
    Status: 0x00
    Address: 00:AA:01:00:00:01
    Version: 0x05
    Manufacturer: 0x05f1
    Supported settings: 0x000110ff
    Current settings: 0x000000c1
    Class: 0x000000
    Name: 
    Short name: 
User channel open - Success - setup
User channel open - Success - setup complete
User channel open - Success - run
User channel open - Success - test failed
  mgmt: > 06 00 01 00 04 00 c1 00 00 00                    ..........      
  mgmt: [0x0001] event 0x0006
User channel open - Success - teardown
  mgmt: > 06 00 01 00 04 00 c0 00 00 00                    ..........      
  mgmt: [0x0001] event 0x0006
  mgmt: > 05 00 01 00 00 00                                ......          
  mgmt: [0x0001] event 0x0005
  Index Removed callback
    Index: 0x0001
User channel open - Success - teardown complete
User channel open - Success - done


Test Summary
------------
User channel open - Success                          Failed       0.003 seconds
Total: 1, Passed: 0 (0.0%), Failed: 1, Not Run: 0
Overall execution time: 0.00263 seconds

ubuntu@ubuntu:/snap/checkbox22/current/providers/checkbox-provider-base$ sudo userchan-tester -p "User channel open - Success" -d

User channel open - Success - init
  mgmt: [0xffff] command 0x0003
  mgmt: < 03 00 ff ff 00 00                                ......          
  mgmt: > 01 00 ff ff 07 00 03 00 00 01 00 00 00           .............   
  mgmt: [0xffff] command 0x0003 complete: 0x00
  Read Index List callback
    Status: 0x00
  New hciemu instance created
  mgmt: > 04 00 01 00 00 00                                ......          
  mgmt: [0x0001] event 0x0004
  Index Added callback
    Index: 0x0001
  mgmt: [0x0001] command 0x0004
  mgmt: < 04 00 01 00 00 00                                ......          
  mgmt: > 01 00 01 00 1b 01 04 00 00 01 00 00 01 aa 00 05  ................
  mgmt:   f1 05 ff 10 01 00 80 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
  mgmt:   00                                               .               
  mgmt: [0x0001] command 0x0004 complete: 0x00
  Read Info callback
    Status: 0x00
    Address: 00:AA:01:00:00:01
    Version: 0x05
    Manufacturer: 0x05f1
    Supported settings: 0x000110ff
    Current settings: 0x00000080
    Class: 0x000000
    Name: 
    Short name: 
User channel open - Success - setup
User channel open - Success - setup complete
User channel open - Success - run
  mgmt: > 05 00 01 00 00 00                                ......          
  mgmt: [0x0001] event 0x0005
  Index Removed callback
    Index: 0x0001
User channel open - Success - test passed
  mgmt: > 04 00 01 00 00 00                                ......          
  mgmt: [0x0001] event 0x0004
  Index Added callback
    Index: 0x0001
User channel open - Success - teardown
  mgmt: > 05 00 01 00 00 00                                ......          
  mgmt: [0x0001] event 0x0005
  Index Removed callback
    Index: 0x0001
User channel open - Success - teardown complete
User channel open - Success - done


Test Summary
------------
User channel open - Success                          Passed       0.003 seconds
Total: 1, Passed: 1 (100.0%), Failed: 0, Not Run: 0
Overall execution time: 0.00258 seconds

Additional context

No response

[syncronize-issues-to-jira]

Thank you for reporting your feedback to us!

The internal ticket has been created: https://warthogs.atlassian.net/browse/CHECKBOX-2180.

This message was autogenerated