There's no file /sys/devices/virtual/switch/usb_configuration/state on Kitkat. On emulator-kk I see lots of error messages like > E/AutoMounter( 63): Error reading file '/sys/devices/virtual/switch/usb_configuration/state': No such file or directory > I/AutoMounter( 63): UpdateState: ums:A0C0E0 mtp:A0C0E0 mode:0 usb:0 tryToShare:0 state:IDLE > I/AutoMounter( 63): UpdateState: Volume sdcard is Mounted and missing @ /storage/sdcard gen 11 locked 0 sharing en-n > E/AutoMounter( 63): Error reading file '/sys/devices/virtual/switch/usb_configuration/state': No such file or directory > I/AutoMounter( 63): UpdateState: ums:A0C0E0 mtp:A0C0E0 mode:0 usb:0 tryToShare:0 state:IDLE > I/AutoMounter( 63): UpdateState: Volume sdcard is Mounted and missing @ /storage/sdcard gen 11 locked 0 sharing en-n

Dave, can you take a look at this bug?

Yeah - I'll take a look at it. The file doesn't exist because the emulator doesn't support USB. The AutoMounter still runs though, so this was probably a side-effect of introducing MTP support.

I took a look at this and it seems to be an issue with vold. Everything works fine until the emulator decides to goto sleep. Then I see this: > 22:12:51.470 62/ 542 libsuspend E Error writing to /sys/power/wakeup_count: Invalid argument > 22:12:51.630 62/ 542 libsuspend E Error writing to /sys/power/state: Device or resource busy followed by a cycle of (just showing vold and libsuspend) > 22:12:51.640 51/ 92 DirectVolume D Volume sdcard /mnt/media_rw/sdcard disk 179:0 removed > 22:12:51.640 51/ 92 Vold D Volume sdcard state changing 4 (Mounted) -> 0 (No-Media) > 22:12:51.720 51/ 92 Vold D Volume sdcard state changing 0 (No-Media) -> 1 (Idle-Unmounted) > 22:12:51.770 51/ 106 Vold W Volume is idle but appears to be mounted - fixing > 22:12:51.770 51/ 106 Vold D Volume sdcard state changing 1 (Idle-Unmounted) -> 4 (Mounted) > 22:12:52.230 51/ 92 DirectVolume D Volume sdcard /mnt/media_rw/sdcard disk 179:8 removed > 22:12:52.250 62/ 542 libsuspend E Error writing to /sys/power/state: Device or resource busy > 22:12:52.250 51/ 92 Vold D Volume sdcard state changing 4 (Mounted) -> 0 (No-Media) I ran ueventmon and as soon as the emulator is powered off, then the kernel generates a stream of these events: remove@/devices/virtual/bdi/179:8 ACTION=remove DEVPATH=/devices/virtual/bdi/179:8 SUBSYSTEM=bdi SEQNUM=3360 remove@/devices/platform/goldfish_mmc.0/mmc_host/mmc0/mmc0:e118/block/mmcblk0 ACTION=remove DEVPATH=/devices/platform/goldfish_mmc.0/mmc_host/mmc0/mmc0:e118/block/mmcblk0 SUBSYSTEM=block MAJOR=179 MINOR=8 DEVNAME=mmcblk0 DEVTYPE=disk NPARTS=0 SEQNUM=3361 remove@/devices/platform/goldfish_mmc.0/mmc_host/mmc0/mmc0:e118 ACTION=remove DEVPATH=/devices/platform/goldfish_mmc.0/mmc_host/mmc0/mmc0:e118 SUBSYSTEM=mmc MMC_TYPE=SD MMC_NAME=SU02G MODALIAS=mmc:block SEQNUM=3362 add@/devices/platform/goldfish_mmc.0/mmc_host/mmc0/mmc0:e118 ACTION=add DEVPATH=/devices/platform/goldfish_mmc.0/mmc_host/mmc0/mmc0:e118 SUBSYSTEM=mmc MMC_TYPE=SD MMC_NAME=SU02G MODALIAS=mmc:block SEQNUM=3363 add@/devices/virtual/bdi/179:8 ACTION=add DEVPATH=/devices/virtual/bdi/179:8 SUBSYSTEM=bdi SEQNUM=3364 add@/devices/platform/goldfish_mmc.0/mmc_host/mmc0/mmc0:e118/block/mmcblk0 ACTION=add DEVPATH=/devices/platform/goldfish_mmc.0/mmc_host/mmc0/mmc0:e118/block/mmcblk0 SUBSYSTEM=block MAJOR=179 MINOR=8 DEVNAME=mmcblk0 DEVTYPE=disk NPARTS=0 SEQNUM=3365

I also noticed that running: > lsof | grep sys/power on the emulator shows me that someplace in b2g is holding /sys/power/state open. I don't see this on my flame.

The problem also doesn't happen on the emulator-JB. So I think that there is a config issues on the KK kernel on the emulator. Doing a grep CONFIG_PM on the JB config shows: > CONFIG_PM=y > # CONFIG_PM_DEBUG is not set > CONFIG_PM_SLEEP=y where on the KK kernel it shows: > CONFIG_PM_SLEEP=y > # CONFIG_PM_AUTOSLEEP is not set > # CONFIG_PM_WAKELOCKS is not set > # CONFIG_PM_RUNTIME is not set > CONFIG_PM=y > # CONFIG_PM_DEBUG is not set > # CONFIG_PM_DEVFREQ is not set and the code in libsuspend that's complaining is in autosuspend_wakeup_count.c On the flame kernel, the PM config is: > CONFIG_PM_SLEEP=y > CONFIG_PM_SLEEP_SMP=y > CONFIG_PM_AUTOSLEEP=y > CONFIG_PM_WAKELOCKS=y > CONFIG_PM_WAKELOCKS_LIMIT=0 > # CONFIG_PM_WAKELOCKS_GC is not set > CONFIG_PM_RUNTIME=y > CONFIG_PM=y > # CONFIG_PM_DEBUG is not set > CONFIG_PM_CLK=y > # CONFIG_PMBUS is not set > # CONFIG_PMIC_DA903X is not set > # CONFIG_PMIC_ADP5520 is not set > CONFIG_PM_DEVFREQ=y I see lots of pm_runtime stuff throughout the mmc block driver, so I think we may need CONFIG_PM_RUNTIME enabled on the emulator. I'm doing a ni on mwu since I think he builds the emulator kernels.

I don't know much about the configuration here - it's just what we get out of the box from AOSP. I've left notes in the kernel update commits if you want to try building a new kernel with a different configuration. :jld also has plenty of experience rebuilding these kernels fwiw, though I don't think he's touched this part of the configuration either.

Quick update: I built a kernel with the options of comment 5 (including CONFIG_PM_RUNTIME), but the problem persists.

Here are some wakelock statistics. root@generic:/ # cat /sys/kernel/debug/wakeup_sources name active_count event_count wakeup_count expire_count active_since total_time max_time last_change prevent_suspend_time gecko 1 1 0 0 0 9 9 252743 0 event0-62 0 0 0 0 0 0 0 25238 0 KeyEvents 174 174 0 0 0 153 146 352732 7 radio-interface 3 63 0 0 0 3345 1338 200928 0 binder 0 0 0 0 0 0 0 4399 0 1992 1992 742 0 0 1616 20 352783 1612 eventpoll 1992 1992 582 0 0 13 0 352783 13 alarm 0 0 0 0 0 0 0 436 0 mmc0_detect 174 348 0 173 199 96442 570 352736 95877 power-supply 1 1 0 0 0 0 0 432 0 power-supply 1 1 0 0 0 0 0 432 0 autosleep 2 2 0 0 0 0 0 253641 0

Hi Dave, Michael, do you know anything about Qemu pipes? I switched on PM and some debugging and dmesg fills with the following error messages as soon as the kernel tries suspending. Maybe something's mis-configured in the emulator scripts? >>> <6>[ 272.290000] mmc0: new SD card at address e118 <6>[ 272.300000] mmcblk0: mmc0:e118 SU02G 512 MiB <6>[ 272.300000] mmcblk0: <6>[ 272.810000] PM: suspend entry 2014-11-27 15:22:22.850335004 UTC <6>[ 272.810000] PM: Syncing filesystems ... done. <6>[ 272.810000] mmc0: card e118 removed <4>[ 272.810000] Freezing user space processes ... <3>[ 272.810000] Freezing of tasks aborted after 0.00 seconds (144 tasks refusing to freeze, wq_busy=0): <4>[ 272.810000] <4>[ 272.810000] Restarting tasks ... <4>[ 272.810000] QEMU Pipe Device:rw, wait_event error <4>[ 272.820000] QEMU Pipe Device:rw, wait_event error <4>[ 272.820000] QEMU Pipe Device:rw, wait_event error <4>[ 272.820000] QEMU Pipe Device:rw, wait_event error <4>[ 272.820000] QEMU Pipe Device:rw, wait_event error <4>[ 272.820000] QEMU Pipe Device:rw, wait_event error <4>[ 272.820000] QEMU Pipe Device:rw, wait_event error <4>[ 272.820000] QEMU Pipe Device:rw, wait_event error <4>[ 272.820000] QEMU Pipe Device:rw, wait_event error <4>[ 272.820000] QEMU Pipe Device:rw, wait_event error <4>[ 272.820000] QEMU Pipe Device:rw, wait_event error <4>[ 272.820000] QEMU Pipe Device:rw, wait_event error <4>[ 272.820000] done. <6>[ 272.820000] PM: suspend exit 2014-11-27 15:22:22.864603898 UTC

The following processes hold file descriptors for /dev/qemu_pipe. There are 12 processes and 12 error messages. >>> root@generic:/ # lsof | grep qemu_pipe rild 56 radio 12 ??? ??? ??? ??? /dev/qemu_pipe mediaserv 58 media 13 ??? ??? ??? ??? /dev/qemu_pipe mediaserv 58 media 14 ??? ??? ??? ??? /dev/qemu_pipe b2g 63 root 6 ??? ??? ??? ??? /dev/qemu_pipe b2g 63 root 17 ??? ??? ??? ??? /dev/qemu_pipe b2g 63 root 56 ??? ??? ??? ??? /dev/qemu_pipe b2g 63 root 58 ??? ??? ??? ??? /dev/qemu_pipe b2g 63 root 78 ??? ??? ??? ??? /dev/qemu_pipe b2g 63 root 81 ??? ??? ??? ??? /dev/qemu_pipe rild 65 radio 12 ??? ??? ??? ??? /dev/qemu_pipe rild 67 radio 12 ??? ??? ??? ??? /dev/qemu_pipe rild 69 radio 12 ??? ??? ??? ??? /dev/qemu_pipe rild 71 radio 12 ??? ??? ??? ??? /dev/qemu_pipe rild 73 radio 12 ??? ??? ??? ??? /dev/qemu_pipe rild 75 radio 12 ??? ??? ??? ??? /dev/qemu_pipe rild 77 radio 12 ??? ??? ??? ??? /dev/qemu_pipe rild 79 radio 12 ??? ??? ??? ??? /dev/qemu_pipe adbd 90 root 3 ??? ??? ??? ??? /dev/qemu_pipe adbd 90 root 12 ??? ??? ??? ??? /dev/qemu_pipe adbd 90 root 13 ??? ??? ??? ??? /dev/qemu_pipe

The error message comes from https://github.com/mozilla-b2g/kernel_goldfish/blob/b2g-goldfish-3.4/drivers/misc/qemupipe/qemu_pipe.c#L377 Enabling CONFIG_MMC_UNSAFE_RESUME seems to make the error go away by not unmounting the MMC drive during suspend. But I guess that's not the correct solution to the problem.

(In reply to Thomas Zimmermann [:tzimmermann] [:tdz] from comment #11) > The error message comes from > > > https://github.com/mozilla-b2g/kernel_goldfish/blob/b2g-goldfish-3.4/drivers/ > misc/qemupipe/qemu_pipe.c#L377 And this fails because the process was interrupted by a signal.

Interesting: With CONFIG_MMC_UNSAFE_RESUME I see the following (successful) dmesg output. However, the emulator seems to suspend during boot. Michael, shouldn't we grab a wakelock during boot? >>> <6>[ 286.420000] PM: suspend entry 2014-11-27 16:07:31.968860665 UTC <6>[ 286.420000] PM: Syncing filesystems ... done. <4>[ 286.440000] Freezing user space processes ... <4>[ 286.440000] QEMU Pipe Device:rw, wait_event error <4>[ 286.440000] QEMU Pipe Device:rw, wait_event error <4>[ 286.440000] QEMU Pipe Device:rw, wait_event error <4>[ 286.440000] QEMU Pipe Device:rw, wait_event error <4>[ 286.440000] QEMU Pipe Device:rw, wait_event error <4>[ 286.440000] QEMU Pipe Device:rw, wait_event error <4>[ 286.440000] QEMU Pipe Device:rw, wait_event error <4>[ 286.440000] QEMU Pipe Device:rw, wait_event error <4>[ 286.440000] QEMU Pipe Device:rw, wait_event error <4>[ 286.440000] QEMU Pipe Device:rw, wait_event error <4>[ 286.440000] QEMU Pipe Device:rw, wait_event error <4>[ 286.440000] QEMU Pipe Device:rw, wait_event error <4>[ 286.460000] (elapsed 0.01 seconds) done. <4>[ 286.460000] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done. <4>[ 286.480000] Suspending console(s) (use no_console_suspend to debug) <6>[ 286.480000] PM: suspend of devices complete after 1.311 msecs <6>[ 286.480000] PM: late suspend of devices complete after 0.189 msecs <6>[ 286.480000] PM: noirq suspend of devices complete after 0.292 msecs <6>[ 286.480000] Suspended for 0.000 seconds <6>[ 286.480000] PM: noirq resume of devices complete after 0.323 msecs <6>[ 286.480000] PM: early resume of devices complete after 0.350 msecs <6>[ 286.480000] PM: resume of devices complete after 1.867 msecs <4>[ 286.480000] Restarting tasks ... done. <6>[ 286.510000] PM: suspend exit 2014-11-27 16:07:33.030025976 UTC

Comment on attachment 8532756 [details] Github pull request for kernel_goldfish Is the switch from CONFIG_EARLYSUSPEND to CONFIG_PM_AUTOSLEEP intentional? The changes look reasonable to me, though I think dhylands probably has a better grip on the config options we're changing here.

Hi Michael (In reply to Michael Wu [:mwu] from comment #17) > Comment on attachment 8532756 [details] > Github pull request for kernel_goldfish > > Is the switch from CONFIG_EARLYSUSPEND to CONFIG_PM_AUTOSLEEP intentional? There is, to my knowledge, no EARLYSUSPEND left in kernels 3.4 and later. [1] provides some information on this change. [1] https://plus.google.com/+MarcinJuszkiewicz/posts/SnuW8bsDrRA

Comment on attachment 8532757 [details] Github pull request for platform_prebuilts_qemu-kernel r=me for this or any other prebuilt kernel update related to this bug, as long as the prebuilt kernel matches an r+'d update to the kernel source.

Comment on attachment 8532756 [details] Github pull request for kernel_goldfish Looks reasonable to me.

Thanks a lot!

b2g-goldfish-3.4: https://github.com/mozilla-b2g/kernel_goldfish/commit/3bff111fec4e7c4bf8cced5f023dfd6b259dafe2 b2g-4.4.2_r1: https://github.com/mozilla-b2g/platform_prebuilts_qemu-kernel/commit/f7d9bf71cf6693474f3f2a81a4ba62c0fc5646aa