Friday, 22 July 2016

Encryption never starts, stays at boot animation.



Hey there!

For security purposes, I'd like to encrypt the data on my Nexus 6P. However, the encryption process fails to start. My phone goes into the boot animation, and it stays there permanently. Interrupting the process does not result in data loss: the phone reboots just fine, all my data is accessible, and it runs good as new. What this tells me is that something is preventing the encryption process from starting in the first place. My problem is that I am not particularly well versed in these matters, and I'm at a loss for how to proceed.

I have made a full Nandroid backup and saved it on my PC, so I'm willing to do some experimenting if there's no easy solution.

I am running the MTC19X build of stock Android. I've made two significant modifications: SuperSU systemless root, and systemless Xposed. In terms of other weird stuff, I have AdAway (from F-Droid) running.

Things I've attempted which did not solve the problem:
  • Starrted encryption process, left running overnight. No joy. I'm fairly sure it's not just me being impatient, but I'm open to just leaving the thing plugged in for 24 hours to see if that works.

  • Disabled Xposed Framework and used SuperSU app to disable root. Tried again, nothing changed. Open to trying again by fully uninstalling these and seeing what happens, but would prefer not to re-root and set up from scratch again.

  • Inspired by a solution that worked for a similar problem on my old Moto G, I reduced the size of the /data partition by a small amount, leaving a small amount of unallocated space on my device. (On the Moto G, this solved a problem where Android had no place to put certain data relating to the encrypted files.) Worked with the Moto, but no such luck this time. Could go in and reverse this change if necessary, or reduce the size of the partition even more.


One interesting idea comes from a Nexus support thread (which I can't link because this is my first post), which suggests that some app or another could be holding files open and preventing the process from starting. I'm not sure what could be doing that, aside from Xposed or other root-related stuff, but I feel I covered that by disabling root on my last attempt. If anyone has any ideas on this front, though, I'm all ears.

I also took the liberty of running ADB's logcat feature, which suggests that the "data is busy" hypothesis is correct:


Code:


07-21 23:30:02.845  7604  7604 W boinc  : type=1400 audit(0.0:6477): avc: denied { search } for name="1" dev="proc" ino=50414 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:init:s0 tclass=dir permissive=0
07-21 23:30:02.845  7604  7604 W boinc  : type=1400 audit(0.0:6478): avc: denied { search } for name="2" dev="proc" ino=50415 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:02.845  7604  7604 W boinc  : type=1400 audit(0.0:6479): avc: denied { search } for name="3" dev="proc" ino=50416 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:02.845  7604  7604 W boinc  : type=1400 audit(0.0:6480): avc: denied { search } for name="4" dev="proc" ino=50417 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:02.849  7604  7604 W boinc  : type=1400 audit(0.0:6481): avc: denied { search } for name="5" dev="proc" ino=50418 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:02.849  7604  7604 W boinc  : type=1400 audit(0.0:6482): avc: denied { search } for name="6" dev="proc" ino=50419 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:02.849  7604  7604 W boinc  : type=1400 audit(0.0:6483): avc: denied { search } for name="7" dev="proc" ino=50420 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:02.849  7604  7604 W boinc  : type=1400 audit(0.0:6484): avc: denied { search } for name="8" dev="proc" ino=50421 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:02.849  7604  7604 W boinc  : type=1400 audit(0.0:6485): avc: denied { search } for name="9" dev="proc" ino=50422 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:02.849  7604  7604 W boinc  : type=1400 audit(0.0:6486): avc: denied { search } for name="10" dev="proc" ino=50423 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:02.849  7604  7604 W boinc  : type=1400 audit(0.0:6487): avc: denied { search } for name="11" dev="proc" ino=50424 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:02.849  7604  7604 W boinc  : type=1400 audit(0.0:6488): avc: denied { search } for name="12" dev="proc" ino=50425 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:02.849  7604  7604 W boinc  : type=1400 audit(0.0:6489): avc: denied { search } for name="13" dev="proc" ino=50426 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:02.849  7604  7604 W boinc  : type=1400 audit(0.0:6490): avc: denied { search } for name="14" dev="proc" ino=50427 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:02.849  7604  7604 W boinc  : type=1400 audit(0.0:6491): avc: denied { search } for name="15" dev="proc" ino=50428 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:02.849  7604  7604 W boinc  : type=1400 audit(0.0:6492): avc: denied { search } for name="16" dev="proc" ino=50429 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:02.849  7604  7604 W boinc  : type=1400 audit(0.0:6493): avc: denied { search } for name="17" dev="proc" ino=50430 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:02.849  7604  7604 W boinc  : type=1400 audit(0.0:6494): avc: denied { search } for name="18" dev="proc" ino=50431 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:02.849  7604  7604 W boinc  : type=1400 audit(0.0:6495): avc: denied { search } for name="19" dev="proc" ino=50432 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:02.849  7604  7604 W boinc  : type=1400 audit(0.0:6496): avc: denied { search } for name="20" dev="proc" ino=50433 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:02.849  7604  7604 W boinc  : type=1400 audit(0.0:6497): avc: denied { search } for name="21" dev="proc" ino=50434 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:02.849  7604  7604 W boinc  : type=1400 audit(0.0:6498): avc: denied { search } for name="22" dev="proc" ino=50435 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:02.849  7604  7604 W boinc  : type=1400 audit(0.0:6499): avc: denied { search } for name="23" dev="proc" ino=50436 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:02.849  7604  7604 W boinc  : type=1400 audit(0.0:6500): avc: denied { search } for name="24" dev="proc" ino=50437 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:02.849  7604  7604 W boinc  : type=1400 audit(0.0:6501): avc: denied { search } for name="25" dev="proc" ino=50438 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:02.849  7604  7604 W boinc  : type=1400 audit(0.0:6502): avc: denied { search } for name="26" dev="proc" ino=50439 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:02.849  7604  7604 W boinc  : type=1400 audit(0.0:6503): avc: denied { search } for name="27" dev="proc" ino=50440 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:02.849  7604  7604 W boinc  : type=1400 audit(0.0:6504): avc: denied { search } for name="28" dev="proc" ino=50441 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:12.879  7604  7604 W boinc  : type=1400 audit(0.0:6808): avc: denied { search } for name="1" dev="proc" ino=50414 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:init:s0 tclass=dir permissive=0
07-21 23:30:12.882  7604  7604 W boinc  : type=1400 audit(0.0:6809): avc: denied { search } for name="2" dev="proc" ino=50415 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:12.882  7604  7604 W boinc  : type=1400 audit(0.0:6810): avc: denied { search } for name="3" dev="proc" ino=50416 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:12.882  7604  7604 W boinc  : type=1400 audit(0.0:6811): avc: denied { search } for name="4" dev="proc" ino=50417 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:12.882  7604  7604 W boinc  : type=1400 audit(0.0:6812): avc: denied { search } for name="5" dev="proc" ino=50418 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:12.882  7604  7604 W boinc  : type=1400 audit(0.0:6813): avc: denied { search } for name="6" dev="proc" ino=50419 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:12.882  7604  7604 W boinc  : type=1400 audit(0.0:6814): avc: denied { search } for name="7" dev="proc" ino=50420 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:12.882  7604  7604 W boinc  : type=1400 audit(0.0:6815): avc: denied { search } for name="8" dev="proc" ino=50421 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:12.882  7604  7604 W boinc  : type=1400 audit(0.0:6816): avc: denied { search } for name="9" dev="proc" ino=50422 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:12.882  7604  7604 W boinc  : type=1400 audit(0.0:6817): avc: denied { search } for name="10" dev="proc" ino=50423 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:12.882  7604  7604 W boinc  : type=1400 audit(0.0:6818): avc: denied { search } for name="11" dev="proc" ino=50424 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:12.882  7604  7604 W boinc  : type=1400 audit(0.0:6819): avc: denied { search } for name="12" dev="proc" ino=50425 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:12.882  7604  7604 W boinc  : type=1400 audit(0.0:6820): avc: denied { search } for name="13" dev="proc" ino=50426 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:12.882  7604  7604 W boinc  : type=1400 audit(0.0:6821): avc: denied { search } for name="14" dev="proc" ino=50427 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:12.882  7604  7604 W boinc  : type=1400 audit(0.0:6822): avc: denied { search } for name="15" dev="proc" ino=50428 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:12.882  7604  7604 W boinc  : type=1400 audit(0.0:6823): avc: denied { search } for name="16" dev="proc" ino=50429 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:12.882  7604  7604 W boinc  : type=1400 audit(0.0:6824): avc: denied { search } for name="17" dev="proc" ino=50430 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:12.882  7604  7604 W boinc  : type=1400 audit(0.0:6825): avc: denied { search } for name="18" dev="proc" ino=50431 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:12.882  7604  7604 W boinc  : type=1400 audit(0.0:6826): avc: denied { search } for name="19" dev="proc" ino=50432 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:12.882  7604  7604 W boinc  : type=1400 audit(0.0:6827): avc: denied { search } for name="20" dev="proc" ino=50433 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:kernel:s0 tclass=dir permissive=0
07-21 23:30:17.629  371  371 W vold    : type=1400 audit(0.0:7139): avc: denied { read } for name="fd" dev="proc" ino=56498 scontext=u:r:vold:s0 tcontext=u:r:logd:s0 tclass=dir permissive=0
07-21 23:30:17.629  371  371 W vold    : type=1400 audit(0.0:7140): avc: denied { getattr } for path="/proc/340/cwd" dev="proc" ino=56500 scontext=u:r:vold:s0 tcontext=u:r:logd:s0 tclass=lnk_file permissive=0
07-21 23:30:17.632  371  371 W vold    : type=1400 audit(0.0:7141): avc: denied { getattr } for path="/proc/340/root" dev="proc" ino=56501 scontext=u:r:vold:s0 tcontext=u:r:logd:s0 tclass=lnk_file permissive=0
07-21 23:30:17.632  371  371 W vold    : type=1400 audit(0.0:7142): avc: denied { getattr } for path="/proc/340/exe" dev="proc" ino=56502 scontext=u:r:vold:s0 tcontext=u:r:logd:s0 tclass=lnk_file permissive=0
07-21 23:30:17.665  342  371 E ProcessKiller: Process /data/data/edu.berkeley.boinc/client/boinc (7604) has open file /data/data/edu.berkeley.boinc/client/stdoutdae.txt
07-21 23:30:17.671  342  371 E Cryptfs : unmounting /data failed: Device or resource busy
07-21 23:30:17.705  371  371 W vold    : type=1400 audit(0.0:7143): avc: denied { read } for name="fd" dev="proc" ino=56498 scontext=u:r:vold:s0 tcontext=u:r:logd:s0 tclass=dir permissive=0
07-21 23:30:17.705  371  371 W vold    : type=1400 audit(0.0:7144): avc: denied { getattr } for path="/proc/340/cwd" dev="proc" ino=56500 scontext=u:r:vold:s0 tcontext=u:r:logd:s0 tclass=lnk_file permissive=0
07-21 23:30:17.705  371  371 W vold    : type=1400 audit(0.0:7145): avc: denied { getattr } for path="/proc/340/root" dev="proc" ino=56501 scontext=u:r:vold:s0 tcontext=u:r:logd:s0 tclass=lnk_file permissive=0
07-21 23:30:17.705  371  371 W vold    : type=1400 audit(0.0:7146): avc: denied { getattr } for path="/proc/340/exe" dev="proc" ino=56502 scontext=u:r:vold:s0 tcontext=u:r:logd:s0 tclass=lnk_file permissive=0
07-21 23:30:17.727  342  371 E ProcessKiller: Process /data/data/edu.berkeley.boinc/client/boinc (7604) has open file /data/data/edu.berkeley.boinc/client/stdoutdae.txt
07-21 23:30:17.727  342  371 W ProcessKiller: Sending Killed to process 7604
07-21 23:30:17.736  342  371 D Cryptfs : Just asked init to shut down class main
07-21 23:30:17.736  342  371 W vold    : emulated unmount requires state mounted
07-21 23:30:37.799  371  371 W vold    : type=1400 audit(0.0:7147): avc: denied { read } for name="fd" dev="proc" ino=56498 scontext=u:r:vold:s0 tcontext=u:r:logd:s0 tclass=dir permissive=0
07-21 23:30:37.802  371  371 W vold    : type=1400 audit(0.0:7148): avc: denied { getattr } for path="/proc/340/cwd" dev="proc" ino=56500 scontext=u:r:vold:s0 tcontext=u:r:logd:s0 tclass=lnk_file permissive=0
07-21 23:30:37.802  371  371 W vold    : type=1400 audit(0.0:7149): avc: denied { getattr } for path="/proc/340/root" dev="proc" ino=56501 scontext=u:r:vold:s0 tcontext=u:r:logd:s0 tclass=lnk_file permissive=0
07-21 23:30:37.802  371  371 W vold    : type=1400 audit(0.0:7150): avc: denied { getattr } for path="/proc/340/exe" dev="proc" ino=56502 scontext=u:r:vold:s0 tcontext=u:r:logd:s0 tclass=lnk_file permissive=0
07-21 23:30:37.836  342  371 E Cryptfs : unmounting /data failed: Device or resource busy
07-21 23:30:37.840  342  371 W SocketClient: write error (Broken pipe)
07-21 23:30:37.840  342  371 W SocketClient: Unable to send msg '200 8 -1'
07-21 23:36:21.690  522  522 I rmt_storage: rmt_storage_connect_cb: clnt_h=0x9 conn_h=0x7f9d77a000
07-21 23:36:21.690  522  522 I rmt_storage: rmt_storage_rw_iovec_cb: /boot/modem_fs2: clnt_h=0x9: req_h=0x9 msg_id=3: R/W request received
07-21 23:36:21.690  522  522 I rmt_storage: wakelock acquired: 1, error no: 42
07-21 23:36:21.691  522  917 I rmt_storage: rmt_storage_client_thread: /boot/modem_fs2: clnt_h=0x9 Unblock worker thread (th_id: 548098016320)
07-21 23:36:21.843  522  917 I rmt_storage: rmt_storage_client_thread: /boot/modem_fs2: clnt_h=0x9: req_h=0x9 msg_id=3: Bytes written = 1572864
07-21 23:36:21.843  522  917 I rmt_storage: rmt_storage_client_thread: /boot/modem_fs2: clnt_h=0x9: req_h=0x9 msg_id=3: Send response: res=0 err=0
07-21 23:36:21.844  522  917 I rmt_storage: rmt_storage_client_thread: /boot/modem_fs2: clnt_h=0x9 About to block rmt_storage client thread (th_id: 548098016320) wakelock released: 1, error no: 0
07-21 23:36:21.844  522  917 I rmt_storage:
07-21 23:36:21.848  522  522 I rmt_storage: rmt_storage_disconnect_cb: clnt_h=0x9 conn_h=0x7f9d77a000


Looking these over makes me think the BOINC app might be the problem, so I figured I'd uninstall it and try again. I'm watching the boot animation right now; wish me luck!

Anyway, if anyone else has any other ideas (especially after reading those logs, I'm not at all an expert on these matters so I definitely don't completely know what I'm looking at), I'm all ears.

Thank you all for your time.



No comments:

Post a Comment