HTC Desire Z boot hang, an innocent cache wipe, and a reflash

· 11 min read
Contents

The boot animation loops. Animated circles, no launcher, no error, and it has been at it long enough that I have stopped expecting the next loop to be the last. The phone is an HTC Desire Z, the 2010 Android slider with a hardware keyboard that I'm setting up for mesh networking, on CyanogenMod 7 (Android 2.3, on the Dalvik VM) with ClockworkMod (CWM) recovery, the small maintenance system the phone boots instead of Android to flash and wipe, and the last thing I did to it was put in an SD card.

I wiped cache to fix that loop, and the loop did not notice. Later the reflash failed inside recovery four times, in a way of its own. Neither time did anything print an error that explained anything. The phone stopped cooperating and left the guessing to me.

Step one: strip bloat APKs from /system/app/; the phone boots fine afterwards. Step two: a blank SD card goes in, and the phone ends up stuck on its boot animation. I format the card FAT32 and reboot: still stuck, and soon a bootloop. Step three: fastboot erase cache, sent from my computer to the phone's bootloader over USB, fails, so I boot into recovery and pick "wipe cache partition". Step four: the loop from the top of this post, which does not stop.

The stuck boot, before and after the cache wipe#

Before the wipe, logcat for the stuck boot ends with system_server, the process that hosts every Android system service, starting its Mount Service and the package manager reporting on the SD card:

I/SystemServer( 1315): Mount Service
I/PackageManager( 1315): Updating external media status from unmounted to unmounted

dumpsys window reports mCurrentFocus=null: no window on the screen has focus.

After the wipe, the same boot gains seven lines at the front:

D/dalvikvm( 1228): DexOpt: --- BEGIN 'core.jar' (bootstrap=1) ---
D/dalvikvm( 1228): DexOpt: --- BEGIN 'bouncycastle.jar' (bootstrap=1) ---
D/dalvikvm( 1228): DexOpt: --- BEGIN 'ext.jar' (bootstrap=1) ---
D/dalvikvm( 1228): DexOpt: --- BEGIN 'framework.jar' (bootstrap=1) ---
D/dalvikvm( 1228): DexOpt: --- BEGIN 'android.policy.jar' (bootstrap=1) ---
D/dalvikvm( 1228): DexOpt: --- BEGIN 'services.jar' (bootstrap=1) ---
D/dalvikvm( 1228): DexOpt: --- BEGIN 'core-junit.jar' (bootstrap=1) ---

Then the same Mount Service line, the same package manager line, the same mCurrentFocus=null.

The cache wipe was my first suspect, on the strength of being the last thing I touched. It had an alibi. The loop was at least eight minutes old when I wiped, and it looked the same on both sides of the wipe.

Where CyanogenMod 7 keeps the Dalvik cache#

Dalvik does not run the bytecode in a .jar or .apk as shipped. On first use, dexopt writes an optimized copy into a dalvik-cache directory, and the VM runs that copy. This ROM has two such directories: the init.rc inside the ROM zip I flashed creates /data/dalvik-cache and /cache/dalvik-cache (lines 177-183). Dalvik on CyanogenMod 7 puts the optimized code for everything under /system, framework jars and system apps alike, into /cache/dalvik-cache, and apps installed under /data into /data/dalvik-cache. The ROM ships no .odex files, so every optimized copy of system code lives on /cache.

So "wipe cache partition" emptied /cache/dalvik-cache, and the next boot rebuilt it: those are the seven DexOpt lines above. The rebuild worked. system_server came up on the fresh copies of core.jar and framework.jar and 38 services were registered with the service manager when the boot stopped.

At the time, this looked like the smoking gun:

$ adb shell ls /data/dalvik-cache/ | wc -l
1
$ adb shell ls /data/dalvik-cache/
data@app@com.mesh.launcher-1.apk@classes.dex

One optimized file, against 80 APKs in /system/app. It is what that directory holds on this ROM: app code only. The one file belongs to MeshLauncher, the launcher I wrote for this build and installed under /data/app. A day later, on the same phone and healthy, /data/dalvik-cache held entries for apps under /data/app, /data/local and /mnt/asec, and nothing from /system/app.

Everything I tried on the stuck boot#

The device: HTC Desire Z, a single 800 MHz Scorpion core, 512 MB of RAM. Thirty-eight services registered, and the boot log stops here:

I/SystemServer( 1336): Mount Service
I/SystemServer( 1336): Profile Manager

No crash from the boot itself, no launcher, no progress. Just a phone-shaped space heater playing a loop of animated circles. The process was alive:

$ adb shell ps | grep system_server
system    1336  1236  168628 31304 ffffffff afd0b91c S system_server

Its main thread was asleep in the kernel, waiting on a Binder reply, Android's IPC, that never came:

$ pid=$(adb shell ps | grep system_server | awk '{print $2}')
$ adb shell "cat /proc/$pid/wchan" 2>/dev/null
binder_thread_read

I asked for a thread dump with kill -3 1336, which writes Java stack traces to /data/anr/traces.txt. Nothing came back, and the directory explains why:

$ adb shell "ls /data/anr/" 2>/dev/null
ls: /data/anr/: No such file or directory

Then the move of a man with no better ideas:

$ adb shell setprop sys.boot_completed 1
$ adb shell am broadcast -a android.intent.action.BOOT_COMPLETED 2>&1
Broadcasting: Intent { act=android.intent.action.BOOT_COMPLETED }
java.lang.IllegalStateException: Cannot broadcast before boot completed

You cannot convince the system it's done booting by telling it it's done booting. I tried anyway, which tells you where I was by then.

Put DrmProvider and ThemeManager back in /system/app: stuck. Put back every APK I had moved: stuck. Mounted the SD card by hand with vdc volume mount sdcard: it mounted, and the boot stayed stuck. Checked settings.db: intact, 36 rows in secure, 58 in system, device_provisioned set to 1.

What system_server was waiting for, I never found out. The record shows the sleep in binder_thread_read, not the service on the other end of it.

The factory reset that got the boot back#

A factory reset from CWM wipes /data and /cache. sys.boot_completed read 1 less than two and a half minutes after I started the reset, wipe included. Whatever held the boot, the reset took it away along with everything else, the evidence included.

Why the phone needed a reflash anyway#

The debloat had left the phone with crash dialogs and a Home button that did nothing (the debloat post and the Home key post have that part). Later that day came a second factory reset. The window list after it held no crash dialog, nothing but the status bar, the keyboard, the launcher and the wallpaper:

$ adb shell dumpsys window 2>/dev/null | grep "Window #" | head -10
  Window #5 Window{405619d8 StatusBar paused=false}:
  Window #4 Window{40738938 StatusBarExpanded paused=false}:
  Window #3 Window{405788b8 TrackingView paused=false}:
  Window #2 Window{4070c420 InputMethod paused=false}:
  Window #1 Window{4057ac18 com.android.launcher/com.android.launcher.Launcher paused=false}:
  Window #0 Window{407856d8 com.android.wallpaper.nexus.NexusWallpaper paused=false}:

The Home button still did nothing. So I reflashed the ROM.

CWM status 1, four times#

I booted into recovery, put the ROM zip on the phone and picked "install zip". Installation aborted, status 1. Again. Again. Again, about half an hour after the first. Status 1 of what, CWM? It did not elaborate, and the place it saves its elaborations was the partition that had gone read-only.

CWM writes the log of the current run to /tmp/recovery.log, on a tmpfs that is gone after the next reboot, and keeps the copy for later in /cache/recovery/last_log. On this phone /cache had stopped taking writes, which comes next.

So I ran the installer myself. The ROM zip carries its own update-binary, the program recovery runs to apply the zip; I pulled it out of the zip on my computer, pushed it to /tmp on the phone and ran it from adb:

$ adb -s <SERIAL> shell "/tmp/update-binary 3 1 /sdcard/cm-7.2.0-vision.zip" 2>&1
about to run program [/tmp/backuptool.sh] with 2 args
mount: mounting /dev/block/mmcblk0p25 on /system failed: Invalid argument
grep: /system/build.prop: No such file or directory
Not backing up files from incompatible version.
umount: can't umount /system: Invalid argument
progress 0.500000 0
Creating filesystem with parameters:
    Size: 585104896
    Block size: 4096
    Blocks per group: 32768
    Inodes per group: 7143
    Inode size: 256
    Journal blocks: 2232
    Label: 
    Blocks: 142847
    Block groups: 5
    Reserved block group size: 39
Created filesystem with 11/35715 inodes and 4603/142847 blocks
error: file_write: write: I/O error

There is the elaboration. The installer made a fresh filesystem on /system, mmcblk0p25, and could not write to it.

/cache went read-only, then the reads failed#

Recovery had mounted /cache as ext3, read-write:

/dev/block/mmcblk0p27 on /cache type ext3 (rw,nodev,noatime,nodiratime,errors=continue,data=writeback)

Pushing the ROM zip there failed with remote Read-only file system. The kernel had already changed its mind, 26 seconds after it started:

<2>[   26.850036] EXT3-fs error (device mmcblk0p27): ext3_journal_start_sb: Detected aborted journal
<2>[   26.851654] Remounting filesystem read-only

e2fsck could not read the partition at all:

e2fsck 1.41.6 (30-May-2009)
e2fsck: Attempt to read block from filesystem resulted in short read while trying to open /dev/block/mmcblk0p27
Could this be a zero-length partition?

Earlier, booted into Android, the phone had /data and /cache both mounted read-only. Between install attempts I also ran busybox mke2fs from recovery on /cache, /system and /data, again and again over about twenty minutes. After those runs the failures reached the block layer. A mount of /system:

mount: mounting /dev/block/mmcblk0p25 on /system failed: Invalid argument
<3>[  220.016754] end_request: I/O error, dev mmcblk0, sector 200706
<3>[  220.017211] EXT4-fs (mmcblk0p25): unable to read superblock
<3>[  220.020538] mmc_blk_issue_rq failed!!

A raw dd of 100 blocks of zeros onto /system went through, and reading the same blocks back failed with I/O error.

The wipe I blamed for the boot had done exactly what its menu item says. The partition it wiped was the one that later stopped taking writes.

Why the eMMC went read-only: never settled#

The obvious diagnosis is a dying flash chip. I refused it at the time, and nothing since has given me a reason to accept it or a better one: the next day the phone was running apps off the same chip. The other guess at the time was an MMC controller left in a bad state by all the format attempts. Nobody tested that guess.

The earliest odd line in the record is from the night of the hang. At the step-three fastboot erase cache, fastboot printed FAILED (Device sent unknown status code: t). Whether that was the same problem, the record can't say.

What I do know is what got the phone flashed.

fastboot erase: the step that worked#

From the bootloader:

$ sudo fastboot erase system
Erasing 'system'                                   OKAY [  1.263s]
Finished. Total time: 1.268s
$ sudo fastboot erase cache
Erasing 'cache'                                    OKAY [  1.035s]
Finished. Total time: 1.040s
$ sudo fastboot erase userdata
Erasing 'userdata'                                 OKAY [  6.137s]
Finished. Total time: 6.143s

Not format. Erase, which leaves the three partitions with no filesystem on them at all. Then fastboot reboot recovery, a tmpfs mounted at /sdcard, so the zip sat in RAM rather than on any of the three partitions, the ROM pushed there, and "install zip" from CWM. It said complete.

The first boot after flashing: /data was never formatted#

First boot after flashing: init.svc.zygote reads restarting, over and over, and logcat has this:

E/dalvikvm( 2356): No valid entries found in bootclasspath '/system/framework/core.jar:/system/framework/bouncycastle.jar:/system/framework/ext.jar:/system/framework/framework.jar:/system/framework/android.policy.jar:/system/framework/services.jar:/system/framework/core-junit.jar'

Dalvik can't use its own runtime classes, and /data is not mounted. grep data matches only the data=ordered mount option on two other partitions:

$ adb shell "mount | grep data"
/dev/block/mmcblk0p25 on /system type ext4 (ro,relatime,barrier=1,data=ordered)
/dev/block/mmcblk0p28 on /devlog type ext4 (rw,nosuid,nodev,noatime,barrier=1,data=ordered)

Because /data was erased but not formatted: fastboot erase empties a partition and does not create a filesystem on it.

Back to CWM. "Wipe data/factory reset", which formats /data. Reboot. About three minutes from "data wipe complete" to sys.boot_completed. The lock screen works. The Home button works.

What the reflash settled#

In the run that worked, three tools touched these partitions: fastboot erased them, CWM flashed the ROM and formatted /data, and init mounted the result. Why the eMMC went read-only, the phone never told me, and the one file built to explain a failed install lives on /cache.

So the phone left this part with one rule and one correction. The rule: when recovery's partitions go read-only, stop working from inside recovery, go back to fastboot, erase and flash again. The correction is to how I pick suspects: the last thing I touched comes first only after I check that it really was the last thing. Both came from the phone, which teaches exclusively by refusing to boot.

Filed under: android, debugging, systems

Sources#