java.io.OptionalDataException when trying to start ScanJob in background

[Ch3D]

Expected behavior

Actual behavior

The crash/exception happened while the app was in background.

Steps to reproduce this behavior

Unfortunately, there are no steps, it appears every time ScanJob is trying to start in bg mode
Cannot say what has triggered this behavior

Mobile device model and OS version

Nexus 6P - Android O - DP4 (OPP4.170623.014)

Android Beacon Library version

android-beacon-library:2.12-beta3

Stacktrace:
07-26 10:30:04.745 31507-31507/com.conichi.guest.staging E/ScanState: Deserialization exception 07-26 10:30:04.756 31507-31507/com.conichi.guest.staging E/ScanState: error: java.io.OptionalDataException at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1374) at java.io.ObjectInputStream.readObject(ObjectInputStream.java:374) at java.util.HashMap.readObject(HashMap.java:1406) at java.lang.reflect.Method.invoke(Native Method) at java.io.ObjectStreamClass.invokeReadObject(ObjectStreamClass.java:1006) at java.io.ObjectInputStream.readSerialData(ObjectInputStream.java:1903) at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1804) at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1354) at java.io.ObjectInputStream.defaultReadFields(ObjectInputStream.java:2003) at java.io.ObjectInputStream.readSerialData(ObjectInputStream.java:1927) at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1804) at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1354) at java.io.ObjectInputStream.readObject(ObjectInputStream.java:374) at java.util.HashMap.readObject(HashMap.java:1408) at java.lang.reflect.Method.invoke(Native Method) at java.io.ObjectStreamClass.invokeReadObject(ObjectStreamClass.java:1006) at java.io.ObjectInputStream.readSerialData(ObjectInputStream.java:1903) at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1804) at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1354) at java.io.ObjectInputStream.defaultReadFields(ObjectInputStream.java:2003) at java.io.ObjectInputStream.readSerialData(ObjectInputStream.java:1927) at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1804) at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1354) at java.io.ObjectInputStream.readObject(ObjectInputStream.java:374) at org.altbeacon.beacon.service.ScanState.restore(ScanState.java:142) at org.altbeacon.beacon.service.ScanJob.restartScanning(ScanJob.java:150) at org.altbeacon.beacon.service.ScanJob.startScanning(ScanJob.java:190) at org.altbeacon.beacon.service.ScanJob.onStartJob(ScanJob.java:77) at android.app.job.JobService$1.onStartJob(JobService.java:71) at android.app.job.JobServiceEngine$JobHandler.handleMessage(JobServiceEngine.java:108) at android.os.Handler.dispatchMessage(Handler.java:105) at android.os.Looper.loop(Looper.java:164) at android.app.ActivityThread.main(ActivityThread.java:6541) at java.lang.reflect.Method.invoke(Native Method) at com.android.internal.os.Zygote$MethodAndArgsCaller.run(Zygote.java:240) at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:767)

[davidgyoung]

Thanks for this report.

It's unclear what happened here. The library saves the scan state using Java serialization when it schedules the ScanJob, and deserializes it when the job starts. Perhaps the app was force stopped in the middle of serialization causing a corruption, or one thread was writing to the serialization file when another one started reading it. This latter case is most likely what needs to be addressed.

Any further context on what was going on when this happened might be helpful. Did you get this exception repeatedly? Can you confirm that if you re-launch the app manually that the problem goes away?

In general if there is a deserialization problem, we simply ignore it and continue, as happened in this case. But this prevents any further beacon processing until the app starts ranging/monitoring again, and persists its settings.

[Ch3D]

@davidgyoung

Did you get this exception repeatedly?

Yes, I see it every 10-15 mins when ScanJob is running

Can you confirm that if you re-launch the app manually that the problem goes away?

Confirm, after relaunching(=bringing app to foreground) it's back to normal.

I will try to observe and find steps to reproduce if it happens again.

[davidgyoung]

OK, good info thanks. If you can reproduce, please try to do two things:

1. Look in your LogCat history for any log lines that show the details of this message:

   LogManager.e(TAG, "Error while saving scan status to file: ", e.getMessage());

2. Pull the following file off of your device from your app's data directory using ADB:

   private static final String STATUS_PRESERVATION_FILE_NAME = "android-beacon-library-scan-state";

[Ch3D]

@davidgyoung yeah, sure, I'll try that.

Btw, I accidentally found one more error on logcat:
07-26 02:09:49.375 8911-28777/? E/AndroidRuntime: FATAL EXCEPTION: pool-366-thread-9 Process: com.conichi.guest.staging, PID: 8911 java.lang.RuntimeException: An error occurred while executing doInBackground() at android.os.AsyncTask$3.done(AsyncTask.java:353) at java.util.concurrent.FutureTask.finishCompletion(FutureTask.java:383) at java.util.concurrent.FutureTask.setException(FutureTask.java:252) at java.util.concurrent.FutureTask.run(FutureTask.java:271) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1162) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:636) at java.lang.Thread.run(Thread.java:764) Caused by: java.lang.NullPointerException: Attempt to invoke virtual method 'boolean org.altbeacon.beacon.service.scanner.CycledLeScanner.getDistinctPacketsDetectedPerScan()' on a null object reference at org.altbeacon.beacon.service.ScanHelper$ScanProcessor.doInBackground(ScanHelper.java:361) at org.altbeacon.beacon.service.ScanHelper$ScanProcessor.doInBackground(ScanHelper.java:333) at android.os.AsyncTask$2.call(AsyncTask.java:333) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1162)  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:636)  at java.lang.Thread.run(Thread.java:764) 

Is it anyhow connected to this issue or I should create a separate one?

[davidgyoung]

@Ch3D, the issue with that stack trace you found in the log may be related, but it is a distinct problem. It is caused by an attempt to process queued background beacon detections from Android O before a CycledScanner instance is created. Regardless, I have put in a simple fix in this commit so no need to open a new issue b2df8be

One possible cause of the corruption in the ScanJob status preservation file (what causes the main crash described in this issue) is if the app crashes in the middle of writing out this file, leading to a corrupted file. There is a chance that the crash associated with the previous stack trace could have caused this if the timing was just right. One possible way to prevent this is to first write the serialization file to a temporary filename then rename it to the actual filename once the write is complete. I will look into making this change as a means of solving this issue.

[davidgyoung]

While there is no known way to reproduce this problem, a fix intended to prevent corruption of the serialization file was put in here 966b5ca.

I am closing this issue assuming that fixes it, but we can re-open if we can find steps to reproduce that indicate this fix does not cover it, or if we see the problem with the 2.12-beta4 release that includes that fix.

[Ch3D]

@davidgyoung thanks, I will reopen it if I notice this issue again.
Going to check 2.12-beta4 soon