1026320 - [B2G][v1.4] USB Mass Storage never connected with PC because of delay of VolumeManager

Status: RESOLVED FIXED

(Firefox OS Graveyard :: GonkIntegration, defect)

Description

[jeremy.kim.leo [:jeremykimleo]]

STR>
1. 
settings -> Enable USB storage & 
settings -> Enable Share using USB of Internal or External SD.

2. reboot with usb plugged.
$> adb reboot or 
long press power key and Restart

3. check UMS connect with pc after reboot

Actual Result :
1/10, Can't connect USB Mass Storage with PC

Expected Result :
UMS should be connect with pc because of enabled UMS settings

Gecko Revision's
v1.4, ee2c8010ebf3f3419a31250ec0e73aba0e691014

Comment 1

[jeremy.kim.leo [:jeremykimleo]]

this is extracted log from target devices.

06-16 16:44:17.887   221   221 I AutoMounter: Unable to open volume configuration file '/system/etc/volume.cfg' - ignoring
06-16 16:44:17.887   221   509 D VolumeManager: VolumeManager constructor called
06-16 16:44:17.887   221   509 I VolumeManager: changing state from 'Uninitialized' to 'Starting'
06-16 16:44:17.887   221   221 I Gecko   : -*- SettingsService: settingsServiceLock constr!
06-16 16:44:17.887   221   509 I VolumeManager: Connected to vold
06-16 16:44:17.887   221   509 D VolumeManager: Sending command '0 volume list'
06-16 16:44:17.887   221   221 I Gecko   : -*- SettingsService: set: ums.mode: 0
06-16 16:44:17.887   221   221 I Gecko   : -*- SettingsService: set: ums.status: 0
06-16 16:44:17.897   221   509 D VolumeManager: Wrote 14 bytes (of 14)
06-16 16:44:17.897   221   509 D AutoMounter: Calling UpdateState from constructor
06-16 16:44:17.897   221   509 I AutoMounter: UpdateState: VolumeManager not ready yet
06-16 16:44:17.897   221   509 I GonkSwitch: [SwitchHandler] ConvertState 0
06-16 16:44:17.897   221   509 I GonkSwitch: [SwitchHandler] ConvertState CONFIGURED
06-16 16:44:17.897   221   221 I Gecko   : -*- SettingsService: settingsServiceLock constr!
06-16 16:44:17.897   221   509 D VolumeManager: Rcvd: 110 '0 sdcard /storage/sdcard 1'
06-16 16:44:17.897   221   509 D VolumeManager: Volume sdcard: created
06-16 16:44:17.897   221   509 D VolumeManager: Volume sdcard: Setting mountpoint to '/storage/sdcard'
06-16 16:44:17.897   221   509 I VolumeManager: Volume sdcard: changing state from Init to Idle (2 observers)
06-16 16:44:17.897   221   509 D AutoMounter: Calling UpdateState due to VolumeEventStateObserver
06-16 16:44:17.897   221   509 I AutoMounter: UpdateState: VolumeManager not ready yet
06-16 16:44:17.897   221   509 D VolumeManager: Rcvd: 110 '0 external_SD /storage/external_SD 1'
06-16 16:44:17.897   221   509 D VolumeManager: Volume external_SD: created
06-16 16:44:17.897   221   509 D VolumeManager: Volume external_SD: Setting mountpoint to '/storage/external_SD'
06-16 16:44:17.897   221   509 I VolumeManager: Volume external_SD: changing state from Init to Idle (2 observers)
06-16 16:44:17.897   221   509 D AutoMounter: Calling UpdateState due to VolumeEventStateObserver
06-16 16:44:17.897   221   509 I AutoMounter: UpdateState: VolumeManager not ready yet
06-16 16:44:17.897   221   509 D VolumeManager: Rcvd: 200 '0 Volumes listed.'
06-16 16:44:17.897   221   509 I VolumeManager: changing state from 'Starting' to 'Volumes Ready'

Comment 2

[jeremy.kim.leo [:jeremykimleo]]

(In reply to jeremy.kim.leo from comment #1)
> this is extracted log from target devices.

> 06-16 16:44:17.897   221   509 D AutoMounter: Calling UpdateState from constructor
> 06-16 16:44:17.897   221   509 I AutoMounter: UpdateState: VolumeManager not ready yet

AutoMounter initialised in here, and this will be checked value of UMS from settingService. 
and AutoMounter is suppose to be read volume info from VolumeManager.

but, VolumeManager din't ready to use at this time. so, it can't call CheckVolumeSettings() of volume.
http://mxr.mozilla.org/mozilla-central/source/dom/system/gonk/AutoMounter.cpp#188

> 06-16 16:44:17.897   221   509 I VolumeManager: changing state from 'Starting' to 'Volumes Ready'

VolumeManager changed state from 'Starting' to 'Volumes Ready' in here.

So, if it is happened, UMS never connect with pc until changing value of USB storage

Comment 3

[jeremy.kim.leo [:jeremykimleo]]

Attachment: let check value of volume's setting when it ready to use VolumeManager

how about this proposal?

if it didn't ready to use VolumeManager on constructor of automounter.
re-check after ready to use VolumeManager.

Comment 4

[jeremy.kim.leo [:jeremykimleo]]

Dear. dhylands

can u guide to me?

Comment 5

[Dave Hylands [:dhylands]]

Yeah - that looks bad. You're right, it's basically a race condition and the CheckVolumeSettings call is happening too early.

I think that this block of code from the AutoMounter constructor:

>    VolumeManager::VolumeArray::size_type numVolumes = VolumeManager::NumVolumes();
>    VolumeManager::VolumeArray::index_type i;
>    for (i = 0; i < numVolumes; i++) {
>      RefPtr<Volume> vol = VolumeManager::GetVolume(i);
>      if (vol) {
>        vol->RegisterObserver(&mVolumeEventObserver);
>        // We need to pick up the intial value of the
>        // ums.volume.NAME.enabled setting.
>        AutoMounterSetting::CheckVolumeSettings(vol->Name());
>      }
>    }
>
>    DBG("Calling UpdateState from constructor");
>    UpdateState();

should be moved into the AutoVolumeManagerStateObserver::Notify function.

The Notify function should do something like:

>  if (VolumeManager::State() == VolumeManager::VOLUMES_READY) {
>  ... insert block of code from AutoMounter constructor here...
>  }

Do you want to try a patch for that? If not, I'd be happy to code one up and send it to you.

Comment 6

[Dave Hylands [:dhylands]]

Hmm. It's actually a bit more complicated than that. Let me work up a patch and I'll attach it here for you to try out.

Comment 7

[Dave Hylands [:dhylands]]

Attachment: Deal with race condition due to slow response from VolumeManager

Can you try this patch out and let me know if it resolves your problem?

Comment 8

[jeremy.kim.leo [:jeremykimleo]]

(In reply to Dave Hylands [:dhylands] from comment #7)
> Created attachment 8441109 [details] [diff] [review]
> Deal with race condition due to slow response from VolumeManager
> 
> Can you try this patch out and let me know if it resolves your problem?

Thanks dhylands.
it's good to my case and better than my proposal.

Comment 9

[jeremy.kim.leo [:jeremykimleo]]

opps~
sorry my mistakes.

Comment 10

[Dave Hylands [:dhylands]]

https://hg.mozilla.org/integration/b2g-inbound/rev/147235714bca

Comment 11

[Hema Koka [:hema]]

At this point only critical bugs are going into 1.4. Based on "the 1/10 times cannot connect to mass storage" removing from 1.4 nom.

Not blocking for 2.0 either, but can approve for landing in 2.0 because of low-risk patch

Thanks
Hema

Comment 12

[Dave Hylands [:dhylands]]

Comment on attachment 8441109 [details] [diff] [review]
Deal with race condition due to slow response from VolumeManager

[Approval Request Comment]
Bug caused by (feature/regressing bug #): Has been present since beginning
User impact if declined: USB Mass Storage may appear to not work properly. Can usually be recovered by rebooting/power cycling phone. Currently only reported on leo phone, but could happen on any phone.
Testing completed (on m-c, etc.): Currently there are no automated tests for USB Mass Storage (our test infrastructure isn't set up for it). I've manually tested on my flame.
Risk to taking this patch (and alternatives if risky): Low
String or IDL/UUID changes made by this patch: None

NOTE: This flag is now for security issues only. Please see https://wiki.mozilla.org/Release_Management/B2G_Landing to better understand the B2G approval process and landings.

[Approval Request Comment]
Bug caused by (feature/regressing bug #): 
User impact if declined: 
Testing completed: 
Risk to taking this patch (and alternatives if risky): 
String or UUID changes made by this patch:

Comment 13

[Dave Hylands [:dhylands]]

Comment on attachment 8441109 [details] [diff] [review]
Deal with race condition due to slow response from VolumeManager

[Approval Request Comment]
Bug caused by (feature/regressing bug #): None - has been present since coded
User impact if declined: USB Mass Storage may appear to not work properly. Can usually be recovered by rebooting/power cycling phone. Currently only reported on leo phone, but could happen on any phone.
Testing completed (on m-c, etc.): Currently there are no automated tests for USB Mass Storage (our test infrastructure isn't set up for it). I've manually tested on my flame.
Risk to taking this patch (and alternatives if risky): Low
String or IDL/UUID changes made by this patch: None

Comment 14

[Lawrence Mandel [:lmandel] (use needinfo)]

Comment on attachment 8441109 [details] [diff] [review]
Deal with race condition due to slow response from VolumeManager

Looks like a safe fix. Aurora approval granted.

Comment 15

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/147235714bca

Comment 16

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/5e4c58fb6a40

Comment 17

[Elie]

Attachment: VIDEO0154_Compress.MP4

This issue has been successfully verified on Flame 2.0:
Gaia-Rev        856863962362030174bae4e03d59c3ebbc182473
Gecko-Rev       https://hg.mozilla.org/releases/mozilla-b2g32_v2_0/rev/e40fe21e37f1
Build-ID        20141207000206
Version         32.0
Device-Name     flame
FW-Release      4.4.2

This issue has been successfully verified on Flame 2.1:
Gaia-Rev        38e17b0219cbc50a4ad6f51101898f89e513a552
Gecko-Rev       https://hg.mozilla.org/releases/mozilla-b2g34_v2_1/rev/8b92c4b8f59a
Build-ID        20141205001201
Version         34.0
Device-Name     flame
FW-Release      4.4.2