1116744 - [v2.2] Investigate test_toggle_bluetooth_settings intermittent failure on Jenkins

Status: RESOLVED WONTFIX

(Firefox OS Graveyard :: Gaia::UI Tests, defect)

Description

[Robert Chira [:RobertC]]

test_toggle_bluetooth_settings has been failing intermittently on Jenkins in the sanity jobs

http://jenkins1.qa.scl3.mozilla.com/job/flame-kk-319.b2g-inbound.ui.functional.sanity/5604/HTML_Report/

From the failure it looks like the device name was not found in the list. This could be a timing issue and it requires further investigation.

Comment 1

[Robert Chira [:RobertC]]

Attachment: logcat.txt

I started and adhoc and the test failed 1 out of 20.
http://jenkins1.qa.scl3.mozilla.com/view/UI/job/flame-kk.ui.adhoc/528/HTML_Report/

I have also attached the portion of the logcat that contains the failing run. Did not find anything unusual in the logcat.

Comment 2

[Robert Chira [:RobertC]]

Attachment: logcat_local_run.txt

Comment 3

[Robert Chira [:RobertC]]

I was able to reproduce the issue locally by running the automated test (logcat attached).
On local device the reproduction rate is 1 out of 10.
Link to test: https://github.com/mozilla-b2g/gaia/blob/master/tests/python/gaia-ui-tests/gaiatest/tests/functional/settings/test_settings_bluetooth.py

STR from automated test:
1. open Settings app
2. tap bluetooth settings
3. tap rename -> enter new name -> tap update
4. enable visible to all (if it is disabled)

Expected conditions:
The device should be visible via bluetooth

Actual result:
The device cannot be found and the test times out after the visible to all checkbox disables itself automatically.

I have tried adding a wait in the test for the BluetoothAdapter.discoverable property to be true, but it did not work. The property returns true and both of the toggle buttons (bluetooth and visible) are enabled. While running the test I had another phone to manually check if the test device can be seen and when it failed the test device was not in the list.

Is there a known issue regarding this?

Comment 4

[Ben Tian (inactive)]

cc Jamin to help check.

Comment 5

[Ben Tian (inactive)]

Redirect ni? to Jamin since he will help check this bug.

Comment 6

[Jamin Liu [:jaliu][:Jamin]]

Hi Robert,
Thank you for the investigation.

There is a known issue [1] that may cause inconsistency between 'visible' flag of check box and BluetoothAdapter.discoverable.  i.e. Sometimes 'visible' flag in Gaia doesn't reflect its actual value in Gecko.
Please refer to https://bugzilla.mozilla.org/show_bug.cgi?id=1098228#c6.

[1] Bug 1098228 - [Flame][Bluetooth]"Visible to all" button will keep on after you turn off /on bluetooth sometimes.

However, the STR of Bug 1098228 is quite different from this bug. I'll keep investigating.
I'd like to ask few questions about 'test_toggle_bluetooth_settings(self)'.

1. Did the test rename Bluetooth device successfully after finishing these statements ?
> bluetooth_settings.tap_rename_my_device()
> bluetooth_settings.type_phone_name(device_name)
> bluetooth_settings.tap_update_device_name_ok()
 
2. Did 'if self.is_visible_enabled != true' pass when enable_visible_to_all(self) was just called?
> if self.is_visible_enabled != 'true':
>     # Bluetooth state is stored outside the profile bug 969310
>     self.marionette.find_element(*self._visible_to_all_label_locator).tap()
>     self.wait_for_condition(lambda m: self.is_visible_enabled == 'true')

3. You mentioned you added a wait in the test in # comment 3, ...
> I have tried adding a wait in the test for the BluetoothAdapter.discoverable property to be true, but > it did not work.

  May I ask where you put it? <Time_Delay_A> or <Time_Delay_B> ?

>  bluetooth_settings.enable_bluetooth()
-----> <Time_Delay_A>

>  bluetooth_settings.tap_rename_my_device()
>  bluetooth_settings.type_phone_name(device_name)
>  bluetooth_settings.tap_update_device_name_ok()

>  bluetooth_settings.enable_visible_to_all()
-----> <Time_Delay_B>

>  # Now have host machine inquire and shouldn't find our device
>  device_found = self.bluetooth_host.is_device_visible(device_name)


Thank you :)

Comment 7

[Robert Chira [:RobertC]]

Hi Jamin,

Below you will find the answers to your questions.

1. Yes, the device was renamed successfully, but this step does not impact the failure. I modified the test to no longer rename the device and the issue is still reproduced with automation. 

http://jenkins1.qa.scl3.mozilla.com/view/UI/job/flame-kk.ui.adhoc/622/console
https://github.com/chirarobert/gaia/blob/bug_1116744/tests/python/gaia-ui-tests/gaiatest/tests/functional/settings/test_settings_bluetooth.py

2. Yes, that wait passes. The failure is at a later step.

3. The wait was added at <Time_Delay_B>, at the end of the bluetooth_settings.enable_visible_to_all() method.

If you require additional information let me know.

Comment 8

[Jamin Liu [:jaliu][:Jamin]]

(In reply to Robert Chira [:RobertC] from comment #7)
> 3. The wait was added at <Time_Delay_B>, at the end of the
> bluetooth_settings.enable_visible_to_all() method.
> 
> If you require additional information let me know.

Thank you for your reply.
Would it be possible for you to add a wait at <Time_Delay_A> as well?
It would be helpful to clarify the problem.

>  bluetooth_settings.enable_bluetooth()
-----> <Time_Delay_A>

>  bluetooth_settings.tap_rename_my_device()
>  bluetooth_settings.type_phone_name(device_name)
>  bluetooth_settings.tap_update_device_name_ok()
>  bluetooth_settings.enable_visible_to_all()
-----> <Time_Delay_B>

>  # Now have host machine inquire and shouldn't find our device
>  device_found = self.bluetooth_host.is_device_visible(device_name)



The purpose of <Time_Delay_A> it to make sure BluetoothAdapter has initialized.

When Bluetooth is enabled by setting app, Gaia will receive two events with this order.
  1. 'BluetoothManager.onenabled'
  2. 'BluetoothManager.onadapteradded'

After receiving these two events, gaia can get default adapter by calling getDefaultAdapter().

If Gaia app call setDiscoverable too early, it might fail.

//-------- correct order ---------//
 1. Gaia app enable Bluetooth 
 2. 'onenabled' fired
 3. 'onadapteradded' fired
 4. Gaia setDiscoverable

//-------- incorrect order ---------//
 1. Gaia app enable Bluetooth 
 2. 'onenabled' fired
 3. Gaia setDiscoverable   <--------- to early
 4. 'onadapteradded' fired

Thank you

Comment 9

[Robert Chira [:RobertC]]

I added a 2 second hard coded sleep at <Time_Delay_A>, but the issue was still reproduced. Tomorrow I will try adding a wait for the onadapteradded event (maybe it takes longer to trigger).

Comment 10

[Robert Chira [:RobertC]]

Jamin,

I tried waiting for getDefaultAdapter() succeed and also tried increasing the hardcoded timeout to 5 seconds, but the issue was still reproduced (these were added at time delay A).

Is there anything else I can help with?

Comment 11

[Martijn Wargers (dead)]

is_device_visible is already trying to find the named device 3 times with a 5 second delay inbetween:
http://mxr.mozilla.org/gaia/source/tests/python/gaia-ui-tests/gaiatest/utils/bluetooth/bluetooth_host.py#30
It would have been nice if device_to_find would also be logged in marionette there.

When is_device_visible passes, it is found after 1 times. When is_device_visible is failing, it is somehow looped 10 times, even though bluetooth_host.py has a loop of 3 times. I wonder how that can happen.

Comment 12

[Martijn Wargers (dead)]

I'll be changing this file in bug 1118219, btw. 
Not sure if it will change this intermittent failure, though.

Comment 13

[Robert Chira [:RobertC]]

From what I see this test should no longer fail intermittently after the changes from bug 1118219. Since the code that was searching for the bluetooth device has been removed.

My only concern here would be if the error described here is actually a bug and not an issue with the test. Martijn what do you think?

Comment 14

[Martijn Wargers (dead)]

Robert, I don't know, it could be a bug in the test as seem to be described by Jamin in comment 6, but I wouldn't really know. Hopefully this bug is resolved then, by the changes from bug 1118219

Comment 15

[Jamin Liu [:jaliu][:Jamin]]

I'm sorry for the late reply.
I'm not sure this bug is actually a bug or it's an issue with the test either.

I read the code of the function 'bluetooth_host.is_device_visible()'.
I think it's possible that 'bluetooth_host.is_device_visible()' can't find the device *by name*.

As far as I know, BlueZ use different HCI commands to discovery devices and get name from remote device.
When a remote device is found by BlueZ, only the value of BD_ADDRESS is guaranteed.
The name of remote device might not be ready when BlueZ sends 'inquiry_response'.

Although PyBluez provides a parameter on 'discover_devices' to let developer to get remote device during discovery, I believe it can't promise every device can get correct device name.
PyBluez also provide a separate function 'lookup_name(address, timeout=10)' which indicates it may return None on failure. (If the name of remote device hasn't been updated by its Bluetooth stack, it could also be an empty string.)

I used my Android phone to discover Bluetooth devices in my office many times. It appears that many remote devices can only display their BD_ADDRESS during the discovery.

I think it's would be safer to search device *by address* to check if the specific device is discoverable or not.

Comment 16

[Martijn Wargers (dead)]

At this point it doesn't matter, since the host part of the test is removed in bug 1118219.

Comment 17

[BMO Automation]

Firefox OS is not being worked on