"read failed: EIO (I/O error)" while calculating hash of installed app in background

This code runs within the check for an ACTION_INSERT intent in the InstalledAppProviderService. This code only gets run from one of two places:

1. FDroidApp.onCreate(...) -> InstalledAppProviderService.compareToPackageManager(context) -> insert(context, packageInfo)
2. PackageManagerReceiver.onReceive(...) receives an Intent.ACTION_PACKAGE_ADDED intent, then calls InstalledAppProviderService.insert(context, intent.getData())

In the first case, this is in response to F-Droid starting up. This could be due to a phone beint turned on (as F-Droid listens for boot events), or from a user opening F_Droid. It will not happen immediately, but should happen within a few seconds of F-Droid starting.

In the second case, it is in response to an app being installed on the device. Note that this could be due to a number of reasons, e.g.:

Using F-Droid to install an app
Using Google Play to install an app
Sideloading an app over USB
Manually opening a .apk file from a file manager on the device

Unfortunately the nature of these stack traces make it a little difficult to determine which of these is causing it. I'll try to investigate on one of my devices with Google Play to see if I can reproduce.

Let me know if I can help. I can provide adb logcat logs or any other info you may need. I was thinking about reinstalling F-Droid, but I won't do it for now because the error may disappear. I installed it a long time ago and it starts spamming with these dialogs only yesterday.

If you do have a logcat from around one of these crashes then that would be particularly helpful. Make sure that you run an eye over any contents of it before posting in case other apps are putting sensitive things in the log.

If that fails to yeild any useful info, I'll ask if you mind installing a debug build of F-Droid next to the normal version which has more logging. Perhaps that can help us nail down this problem, as I'm still having trouble reproducing :(

@Paultergeist: Also, does this only happen randomly in the background? Or is there a set of steps that you can take to reproduce it on demand on your device?

As for the bug, I've ruled out the following (by forcing the code to try to read various files):

Reading a directory instead of a .apk file: Results in: open failed: EISDIR (Is a directory).
Reading from a read-only partition such as /system/priv-app (don't know why that would matter, but thought I'd try): Doesn't throw an exception, hashes the .apk file just fine.
Trying to read a file which is not accessible (e.g. owned by root and 0600): Results in open failed: EACCES (Permission denied).
Removing a file half way through reading it in order to calculate its hash (e.g. pause the debugger midway through reading, open a shell on my device, and remove the file, then resume the debugger): Results in read failed: ENOENT (No such file or directory).

I'm starting to think that given the generic nature of the "EIO" error, whereas all my examples above give such useful and specific POSIX error numbers, that it is something higher level like a problem with the SD card. Maybe a race condition between our boot listener and the operating system mounting the SD card. I'll look further into this.

@pserwylo Unfortunately I could not figure out the sequence of actions that can reproduce the issue with high probability. It looks random and it usually shows the second dialog right after the first (doesn't matter if I press Cancel to just dismiss it or OK to send it via GMail app, in the latter case it appears while I'm editing the message in GMail). I think it reproduces more frequently after I wake up phone from standby, but I may be wrong.

Do you have an email where I can send you the adb logcat logs? I don't want to attach them here in case there are some private data I have not noticed/redacted.

@Paultergeist: Sure, my email is peter@serwylo.com. If you like, you can encrypt to my PGP key available from public key-servers with fingerprint 50C7 10A2 8A70 4E77 06C6 E670 1BA8 5527 7999 F550.

@Paultergeist: Thanks for the email with the logs. Unfortunately in those two logs there doesn't seem to be a reproduction of this error: grep "read failed" *.log turns up empty, and grep "IOException" *.log only shows two results with NetworkError. Feel free to send through any other logs if you think you managed to capture one around one of these crashes though.

Hm, but I definitely was capturing logs when window popped up. You can see

02-15 12:22:56.474 871-3078/? V/WindowManager: Adding window Window{2b2f8491 u0 org.fdroid.fdroid/org.fdroid.fdroid.acra.CrashReportActivity} at 12 of 20 (before Window{18cd5d1b u0 org.fdroid.fdroid/org.fdroid.fdroid.acra.CrashReportActivity})

in the logs. Maybe the crash itself happens while the device is sleeping, long before I start capturing the logs. I'll try to gather longer logs.

Ohm you are right. I'll have a more detailed look around wherever I can see ACRA related stuff in the logs. Thanks for the pointer.

Hmm, still not having a lot of luck with this. I can see that it is poping up an ACRA window (as I'm sure you are aware). But I can't see anything interesting happening before that. If you feel comfortable, would you mind uninstalling your F-Droid and instead installing this debug build? It has more debugging which goes to logcat. Normally we disable most logging for release builds:

F-Droid__debug_build_from_pserwylo_.apk.

I forked it from v0.102 stable and added some stuff to make all debug logging prefixed with "FDroid Debug" to make it easier to grep.

Started adb logcat before installing your build. Sent you fresh log together with exception stack trace. Hope this helps.

Thanks Paul, but could I please ask you to send the logcats again, I don't seem to have received them. Feel free to also use team@f-droid.org if you prefer (then it will reach a few of us working on F-Droid rather than just my personal email).

Resent to both emails.

Thanks @Paultergeist, received.

I can't see anything particularly enlightening in your logs. What I can see is that it scans a series of your installed apps successfully, and then crashes when it hits /mnt/asec/air.com.sumdog.Sumdog-2/base.apk:

D/Utils   (23941): FDroid Debug: Calculating sha256 hash of file: /mnt/asec/air.com.sumdog.Sumdog-2/base.apk
D/InstalledAppProviderSer(23941): FDroid Debug: Error calculating sha256 hash for /mnt/asec/air.com.sumdog.Sumdog-2/base.apk

Before crashing, it successfully reads over 130 .apk files from /data/app/*.apk, /mnt/asec/*/*.apk/system/app//.apk, /system/priv-app//.apk, and /vendor/overlay/*.apk. This means we can rule out /mnt/asec` being the problem, as other apks get read from there just fine.

I also tried to reproduce such a problem by moving an app to the sd card (which ended up in /mnt/asec such as the apk failing in your case. I had no such luck reproducing the problem.

At this stage, instead of sinking more time into trying to reproduce this, I'm considering two options when encountering installed apps which cannot have their has calculated:

(1) Skip the app entirely

This is the simplest, but perhaps the worst option. This means that the app will not appear in the list of installed apps in F-Droid which may be problematic. In your case @Paultergeist, it wont cause problems because it is an app from GooglePlay that is causing the trouble. However if it happens to other users where an F-Droid provided app crashes in this way, then it will never appear in the installed list.

(2) Record the app as installed, but don't store its hash

The hash is only used for a small number of things at this point. However if it is used more in the future then it may start to cause confusion whereby it is sometimes inexplicably null.

@eighthave, can you please commont on how bad it would be if I stored the installed app info with an empty hash? I did a find usages on the InstalledApp.hash property and it doesn't seem overly offensive.

changed title from "read failed: EIO (I/O error)" while calculating has of installed app in background to "read failed: EIO (I/O error)" while calculating hash of installed app in background

Seems like we need to find a way to get more info from the ACRA reports on this one.

If that app has a read error in it, then there is definitely something odd going on anyhow. Perhaps we can skip the app for now, that'll stop the crashing, but then still have it send the ACRA logs. Maybe the longer term solution is to schedule a retry for that app.

I really do not like the idea of inserting incomplete records, i.e. with the empty hash. That just punts the problem to somewhere else where it will be harder to track.

changed milestone to %0.103 - UX Overhaul

I made a simple app and tried to read sumdog.apk in blocks the same way as getBinaryHash does. It fails somewhere in the middle of the file. Looks like there is a filesystem issues or unreadable sectors on my SD card.

But the annoying thing with F-Droid is that these dialogs that asks whether I want to send the crash log to developers pop up in the middle of something interrupting the task user is doing. Maybe it's better to collect logs somewhere and show a notification suggesting to send available logs, instead of popping up the dialog?

Oh wow, thanks for going to that effort. Glad (well, not for you, but for our investigation) that it is likely filesystem related and out of our hands, as I was all out of ideas.

Given that this is clearly continually failing on sumdog.apk for @Paultergeist, I think we should ignore apks which fail due to this general "I/O error" exception. POSIX provides for a wide range of error codes which I encountered while trying to reproduce this. I'm confident we can skip only apps with this specific error code, then we wont be stuffing up many peoples user experience. We will also be providing a tangible benefit to people who get these crash reports at odd times.

With regards to continuing but logging via ACRA, we do already do that. However given that we never send ACRA logs without first asking, this is what causes the popup to display at odd times (i.e. when not using F-Droid).

changed milestone to %0.102.2

mentioned in merge request !440 (closed)

changed milestone to %1.1

FYI we still have this error, and now have a new user experiencing it (who sent through two crash reports for 0.103-alpha3):

USER_COMMENT=Immediate crash when launching F-droid
STACK_TRACE=java.lang.IllegalArgumentException: java.io.IOException: read failed: EIO (I/O error)
	at org.fdroid.fdroid.Utils.getBinaryHash(Utils.java:420)
	at org.fdroid.fdroid.data.InstalledAppProviderService.onHandleIntent(InstalledAppProviderService.java:199)
	at android.app.IntentService$ServiceHandler.handleMessage(IntentService.java:65)
	at android.os.Handler.dispatchMessage(Handler.java:102)
	at android.os.Looper.loop(Looper.java:135)
	at android.os.HandlerThread.run(HandlerThread.java:61)
Caused by: java.io.IOException: read failed: EIO (I/O error)
	at libcore.io.IoBridge.read(IoBridge.java:482)
	at java.io.FileInputStream.read(FileInputStream.java:177)
	at java.io.BufferedInputStream.read(BufferedInputStream.java:290)
	at java.io.InputStream.read(InputStream.java:162)
	at org.fdroid.fdroid.Utils.getBinaryHash(Utils.java:413)
	... 5 more
Caused by: android.system.ErrnoException: read failed: EIO (I/O error)
	at libcore.io.Posix.readBytes(Native Method)
	at libcore.io.Posix.read(Posix.java:165)
	at libcore.io.BlockGuardOs.read(BlockGuardOs.java:230)
	at libcore.io.IoBridge.read(IoBridge.java:472)
	... 9 more
java.io.IOException: read failed: EIO (I/O error)
	at libcore.io.IoBridge.read(IoBridge.java:482)
	at java.io.FileInputStream.read(FileInputStream.java:177)
	at java.io.BufferedInputStream.read(BufferedInputStream.java:290)
	at java.io.InputStream.read(InputStream.java:162)
	at org.fdroid.fdroid.Utils.getBinaryHash(Utils.java:413)
	at org.fdroid.fdroid.data.InstalledAppProviderService.onHandleIntent(InstalledAppProviderService.java:199)
	at android.app.IntentService$ServiceHandler.handleMessage(IntentService.java:65)
	at android.os.Handler.dispatchMessage(Handler.java:102)
	at android.os.Looper.loop(Looper.java:135)
	at android.os.HandlerThread.run(HandlerThread.java:61)
Caused by: android.system.ErrnoException: read failed: EIO (I/O error)
	at libcore.io.Posix.readBytes(Native Method)
	at libcore.io.Posix.read(Posix.java:165)
	at libcore.io.BlockGuardOs.read(BlockGuardOs.java:230)
	at libcore.io.IoBridge.read(IoBridge.java:472)
	... 9 more
android.system.ErrnoException: read failed: EIO (I/O error)
	at libcore.io.Posix.readBytes(Native Method)
	at libcore.io.Posix.read(Posix.java:165)
	at libcore.io.BlockGuardOs.read(BlockGuardOs.java:230)
	at libcore.io.IoBridge.read(IoBridge.java:472)
	at java.io.FileInputStream.read(FileInputStream.java:177)
	at java.io.BufferedInputStream.read(BufferedInputStream.java:290)
	at java.io.InputStream.read(InputStream.java:162)
	at org.fdroid.fdroid.Utils.getBinaryHash(Utils.java:413)
	at org.fdroid.fdroid.data.InstalledAppProviderService.onHandleIntent(InstalledAppProviderService.java:199)
	at android.app.IntentService$ServiceHandler.handleMessage(IntentService.java:65)
	at android.os.Handler.dispatchMessage(Handler.java:102)
	at android.os.Looper.loop(Looper.java:135)
	at android.os.HandlerThread.run(HandlerThread.java:61)

closed via merge request !581 (merged)

changed milestone to %1.0

changed milestone to %1.0-alpha3

"read failed: EIO (I/O error)" while calculating hash of installed app in background

Designs

Child items 0

Activity

Admin message

Admin message

"read failed: EIO (I/O error)" while calculating hash of installed app in background

Activity