Keeps crashing after taking pictures in interval mode

[mvglasow]

To reproduce:

1. Enable Geotagging (not sure if it is related, but it was on in my case.)
2. Disable the camera flash (again, not sure if it is related, but auto flash has caused OS issues with other camera apps)
3. Select interval mode, 2s interval, repeat indefinitely.
4. Go outside and start taking pictures.

Expected result:

No fuss, FreeDCam keeps taking pictures until I stop it (or until storage space is exhausted)

Actual result:

FreeDCam starts taking pictures and crashes after 45 seconds. Any attempt to restart FreeDCam results in further crashes.

Environment:

• FreeDCam@ d3a06ac, built from source
• Nexus S running CyanogenMod 11 (Android 4.4.4)

Further information:

When examining the pictures taken, I see that none of them has location data. The Nexus S is slow to pick up a GPS signal (acquiring a fix can take well beyond 45 seconds), thus not seeing any location data is normal, though I am wondering whether acquiring the fix had anything to do with the crash.

The logcat attached is from a crash on a subsequent launch; the original one had already rotated out of the log.

I did not find a file named log.txt in the DCIM folder, thus all I have is the logcat (attached). The crash message implies that FreeDCam might be calling a method which is not available on KitKat yet.

alogcat.2020-02-19-16-09-47+0100.txt

[mvglasow]

Additional information: even force stopping FreeDCam, clearing all app data and retrying did not help—it would still crash on the next launch. A reboot solved this, however. To my surprise, all my settings still seemed to be there, implying they are not stored in the usual suspect locations and thus survive an app data wipe operation.

Settings attached; they should be as they were when I first experienced the crash.

Nexus S_CameraParameters.txt

[KillerInk]

this seem to be the problem that its crashing

02-19 16:09:33.144 E/AndroidRuntime(26122): FATAL EXCEPTION: pool-3-thread-1
02-19 16:09:33.144 E/AndroidRuntime(26122): Process: troop.com.freedcam, PID: 26122
02-19 16:09:33.144 E/AndroidRuntime(26122): java.lang.NoSuchMethodError: android.media.ExifInterface.<init>
02-19 16:09:33.144 E/AndroidRuntime(26122):     at freed.viewer.screenslide.ScreenSlideFragment$ExifLoader.process(ScreenSlideFragment.java:440)
02-19 16:09:33.144 E/AndroidRuntime(26122):     at freed.image.ImageTask.run(ImageTask.java:21)
02-19 16:09:33.144 E/AndroidRuntime(26122):     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
02-19 16:09:33.144 E/AndroidRuntime(26122):     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
02-19 16:09:33.144 E/AndroidRuntime(26122):     at java.lang.Thread.run(Thread.java:841)
02-19 16:09:33.148 W/ActivityManager(  392):   Force finishing activity troop.com.freedcam/freed.cam.ActivityFreeDcamMain

looks like i forgot to reenable the api check for files. its currently forced to use the SAF, wich was introduced with L and bevor wont work.

pls uncomment this line and remove the true flag:

https://github.com/KillerInk/FreeDcam/blob/master/app/src/main/java/freed/file/FileListController.java#L42

Additional information: even force stopping FreeDCam, clearing all app data and retrying did not help—it would still crash on the next launch.

in that case the cameraservice died silent in background. Only way to get it back working is to reboot.

[mvglasow]

Thanks, I’ll give it a try.

FYI: today I had another crash right after opening FreeDcam (last usage was a few days back, no crash). So the crashes seem to be completely sporadic in nature, not linked to any particular user action.

[mvglasow]

Even with the fix you suggested I am still having crashes. Looking at the logcats, there are multiple issues causing this.

The first one was right on startup, logcat attached (lines 741–919 is where the action is): alogcat.2020-02-22-13-49-20+0100.txt

In short, after a bunch of class members not being found (which appears non-critical), an NPE occurs at freed.cam.ui.themesample.cameraui.CameraUiFragment.onViewCreated(CameraUiFragment.java:320). Again, sporadic in nature, haven’t looked too deeply into the code to be able to tell what triggers it.

The second one happened while taking pictures, after slightly less than 2 minutes. The crash is is in lines 667–721: alogcat.2020-02-22-16-34-50+0100.txt

This one appears to be caused by PagerAdapter#notifyDataSetChanged not getting called under all circumstances after changing the adapter’s contents. However, lines 651–656 indicate that another (native?) thread has exited with an unhandled exception just a second earlier; could that be related?

[KillerInk]

the first one seems to have something todo with the fragment restoring. looks like the activity is not availible because the fragment is not attached. depending on the free memory availible, android free memory from paused apps. im not able to reproduce it here. but in theory it should be enough to check if(getActivity != null) https://github.com/KillerInk/FreeDcam/blob/d3a06ac40ee4ac1efc9170a7ca31d81d3fc9f479/app/src/main/java/freed/cam/ui/themesample/cameraui/CameraUiFragment.java#L320 because onViewCreated gets called again when it get attached.

the second is abit confusing. there is still something odd on camera1 interval.

[mvglasow]

As for the NPE, this may well be the case, as it occurred when I (re-)started FreeDcam after not using it for a couple of hours at least.

The IllegalStateException still occurs with the fixes applied. New logcat attached: alogcat.2020-02-24-22-02-35+0100.txt

[KillerInk]

hm its realy funny. my theory ist that there a race condition happen.

https://github.com/KillerInk/FreeDcam/blob/189905c27e342a35e002abc8eaa455a3dadb556a/app/src/main/java/freed/viewer/screenslide/ScreenSlidePagerAdapter.java#L47

pls try to change it to

public synchronized void setFiles

[mvglasow]

I’ll try that and report back.

Any ideas as to what kind of race condition we are dealing with? Multiple overlapping calls to this method from multiple threads? Or multiple threads concurrently accessing the same data structure, but involving different sections of code? In the latter case, we’d need to identify other portions of the code in which the same fields are accesses and make sure all of these chunks are synchronized against the same object instance.

[mvglasow]

Same exception again, logcat attached. alogcat.2020-02-25-19-50-42+0100.txt

See above question: is it just this one method which touches the data structures in question?

[KillerInk]

the problematic part ist this: https://github.com/KillerInk/FreeDcam/blob/189905c27e342a35e002abc8eaa455a3dadb556a/app/src/main/java/freed/file/FileListController.java#L227-L235

it get called from multiple threads. if the lock is released next thread add its file to the list.but it meantime pageradapter trys to update its content, wich is increased. it should be enough to move the

if (notifyFilesChanged != null)
            notifyFilesChanged.onFilesChanged();

into the syncronized block to avoid it.

have redo some parts that its more thread safe.

[KillerInk]

hm that seems not to work. found a way to reproduce the problem

[mvglasow]

Unfortunately that still didn’t help, see logcat: alogcat.2020-02-26-17-25-42+0100.txt

For the record, I left your previously suggested fix in ScreenSlidePagerAdapter.java#47 (declaring the method as synchronized). That shouldn’t do any harm, though.

I see FileListController has a member named files, while DeleteFiles() also takes a files argument. That might lead to some ambiguities (e.g. the code syncs against the argument, not the class member—is this intended that way?)

Also, the following still access files without synchronization:

• FileListControl#deleteFile()
• FileListControl#getFiles() (returns the list, which the caller can then manipulate without synchronization)
• FileListControl#loadDefaultFiles()

[mvglasow]

Furthermore, the result of FileListControl#getFiles() is used (among others) by ImageAdapter#getCount() and GridViewFragment#notifyDataSetChanged(), without synchronization.

Some methods in FileListControl reassign files: not sure how this interacts with synchronization, it might be better to use clear() and addAll() instead:

• LoadDCIMDirs()
• loadDefaultFiles()
• LoadFolder()
• LoadFreeDcamDCIMDirsFiles()

[mvglasow]

Even after inserting more synchronizations in the places I mentioned (except the onClick() handlers which access getFiles()), I am getting the same crash again. But I might have missed something…

[KillerInk]

Furthermore, the result of FileListControl#getFiles() is used (among others) by ImageAdapter#getCount() and GridViewFragment#notifyDataSetChanged(), without synchronization.

yes but that should not cause the problem because that stuff runs inside the syncronized method. the problem appears while adding new files to the fileController. after a image is captured and saved this get called:

https://github.com/KillerInk/FreeDcam/blob/86a4529e390e2dcdc9689a5d415a8b32821f43eb/app/src/main/java/freed/cam/apis/basecamera/modules/ModuleAbstract.java#L136-L139

calls this from the imagesave task thread(i know this can get replaced direct with the bottom call): https://github.com/KillerInk/FreeDcam/blob/86a4529e390e2dcdc9689a5d415a8b32821f43eb/app/src/main/java/freed/cam/ActivityFreeDcamMain.java#L383-L389

wich end there in mainthread: https://github.com/KillerInk/FreeDcam/blob/86a4529e390e2dcdc9689a5d415a8b32821f43eb/app/src/main/java/freed/cam/ActivityFreeDcamMain.java#L108-L112

goes there:

https://github.com/KillerInk/FreeDcam/blob/86a4529e390e2dcdc9689a5d415a8b32821f43eb/app/src/main/java/freed/file/FileListController.java#L223-L232

wich finaly ends there(the post is also not needed cause we are already in mainthread): https://github.com/KillerInk/FreeDcam/blob/86a4529e390e2dcdc9689a5d415a8b32821f43eb/app/src/main/java/freed/cam/ActivityFreeDcamMain.java#L78-L84

i would say uiViewPager.post(() -> cause the problem because it runs outside of the sync block due the handler call

that messed up code is caused due the rework i have todo with the forced saf with supportlibs 29 >= pie

[mvglasow]

As for the SAF, on Q (API 29, Android 10) there is still an option to request legacy shared storage in the manifest, but this will be discontinued in a later release. Not sure if Android 11 still supports it.

[KillerInk]

if this is also not working will do a rework of the intervalmodule. that it keep all files while a capture is in progress and post them only to the screenslide when its done.

android11 no longer support it.

[mvglasow]

Bad news first: it still crashes—but with a different exception, which may be good news: alogcat.2020-02-27-14-55-28+0100.txt L749–777 shows an OutOfMemoryError exception.

As above, this happened after slightly under 2 minutes of taking pictures at 2-second intervals.

[mvglasow]

Another crash, again for a different reason (around L768). There’s a bunch of exceptions in the log, can’t figure out which caused the crash: alogcat.2020-02-27-16-06-58+0100.txt

[mvglasow]

Looking at it again, this time the fault seems to be an NPE in ImageFragment when writing to histogramData. Declaring createHistogramm() and onDestroyView() (the latter resets it to null) seems to fix this, but now I am getting another out-of-memory condition in ImageFragment:207 (the declaration of pixels). I’ll see what happens if I turn pixels into a field which is (re-)allocated only when needed…

[mvglasow]

This seems to have fixed it, but now I am getting another OutOfMemory exception somewhere else :-(

02-27 17:54:42.809 E/AndroidRuntime(14514): java.lang.OutOfMemoryError
02-27 17:54:42.809 E/AndroidRuntime(14514):     at android.graphics.BitmapFactory.nativeDecodeFileDescriptor(Native Method)
02-27 17:54:42.809 E/AndroidRuntime(14514):     at android.graphics.BitmapFactory.decodeFileDescriptor(BitmapFactory.java:657)
02-27 17:54:42.809 E/AndroidRuntime(14514):     at freed.viewer.helper.CacheHelper.getBitmapFromDiskCache(CacheHelper.java:162)
02-27 17:54:42.809 E/AndroidRuntime(14514):     at freed.viewer.helper.BitmapHelper.getCacheBitmap(BitmapHelper.java:89)
02-27 17:54:42.809 E/AndroidRuntime(14514):     at freed.viewer.helper.BitmapHelper.getBitmap(BitmapHelper.java:60)
02-27 17:54:42.809 E/AndroidRuntime(14514):     at freed.viewer.screenslide.ImageFragment$BitmapLoader.process(ImageFragment.java:170)
02-27 17:54:42.809 E/AndroidRuntime(14514):     at freed.image.ImageTask.run(ImageTask.java:21)
02-27 17:54:42.809 E/AndroidRuntime(14514):     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
02-27 17:54:42.809 E/AndroidRuntime(14514):     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
02-27 17:54:42.809 E/AndroidRuntime(14514):     at java.lang.Thread.run(Thread.java:841)

[mvglasow]

The PR should fix the NPE in ImageFragment when writing to histogramData, as well as the OutOfMemoryError caused by gratuitous re-allocation of pixels.

The next exception down the road is the aforementioned OutOfMemoryError in CacheHelper#getBitmapFromDiskCache(). Again, we’re apparently allocating a local variable of several megabytes every 2–3 seconds. However, the fix is not as simple here as the bitmap is instantiated somewhere else… running out of ideas again here.

[mvglasow]

After some more experimentation, it turns out that the FileInputStream in getBitmapFromDiskCache() isn’t needed any more once we have the file descriptor and can be closed. (Which also simplifies the code—getting the file descriptor apparently never throws an exception, hence we can close the stream right afterwards and drop the finally block.)

I have added this, and the camera has been shooting for some 74 minutes now. Seems this solves it, hang on for the PR.

[mvglasow]

107 is ready to merge from my side.

[mvglasow]

Note I am still getting NPEs on launch. In this case FreeDcam had been in the background for ~2 hrs: alogcat.2020-02-27-21-58-47+0100.txt

Maybe ActivityFreeDcamMain#getUserMessageHandler() returns null at that stage?

[mvglasow]

I’ve added another check to the PR. Not really a memory issue but related to our crash-busting mission here.

[KillerInk]

great! about the npe i look tomorrow into it. bit busy today.

FATAL EXCEPTION: main
02-27 21:58:36.557 E/AndroidRuntime(21324): Process: troop.com.freedcam, PID: 21324
02-27 21:58:36.557 E/AndroidRuntime(21324): java.lang.RuntimeException: Unable to start activity ComponentInfo{troop.com.freedcam/freed.cam.ActivityFreeDcamMain}: java.lang.NullPointerException
02-27 21:58:36.557 E/AndroidRuntime(21324):     at android.app.ActivityThread.performLaunchActivity(ActivityThread.java:2212)
02-27 21:58:36.557 E/AndroidRuntime(21324):     at android.app.ActivityThread.handleLaunchActivity(ActivityThread.java:2271)
02-27 21:58:36.557 E/AndroidRuntime(21324):     at android.app.ActivityThread.access$800(ActivityThread.java:144)
02-27 21:58:36.557 E/AndroidRuntime(21324):     at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1205)
02-27 21:58:36.557 E/AndroidRuntime(21324):     at android.os.Handler.dispatchMessage(Handler.java:102)
02-27 21:58:36.557 E/AndroidRuntime(21324):     at android.os.Looper.loop(Looper.java:136)
02-27 21:58:36.557 E/AndroidRuntime(21324):     at android.app.ActivityThread.main(ActivityThread.java:5146)
02-27 21:58:36.557 E/AndroidRuntime(21324):     at java.lang.reflect.Method.invokeNative(Native Method)
02-27 21:58:36.557 E/AndroidRuntime(21324):     at java.lang.reflect.Method.invoke(Method.java:515)
02-27 21:58:36.557 E/AndroidRuntime(21324):     at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:732)
02-27 21:58:36.557 E/AndroidRuntime(21324):     at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:566)
02-27 21:58:36.557 E/AndroidRuntime(21324):     at dalvik.system.NativeStart.main(Native Method)
02-27 21:58:36.557 E/AndroidRuntime(21324): Caused by: java.lang.NullPointerException
02-27 21:58:36.557 E/AndroidRuntime(21324):     at freed.cam.ui.themesample.cameraui.CameraUiFragment.onViewCreated(CameraUiFragment.java:321)
02-27 21:58:36.557 E/AndroidRuntime(21324):     at androidx.fragment.app.FragmentManagerImpl.moveToState(FragmentManagerImpl.java:892)
02-27 21:58:36.557 E/AndroidRuntime(21324):     at androidx.fragment.app.FragmentManagerImpl.moveFragmentToExpectedState(FragmentManagerImpl.java:1238)
02-27 21:58:36.557 E/AndroidRuntime(21324):     at androidx.fragment.app.FragmentManagerImpl.moveToState(FragmentManagerImpl.java:1303)
02-27 21:58:36.557 E/AndroidRuntime(21324):     at androidx.fragment.app.FragmentManagerImpl.dispatchStateChange(FragmentManagerImpl.java:2659)
02-27 21:58:36.557 E/AndroidRuntime(21324):     at androidx.fragment.app.FragmentManagerImpl.dispatchActivityCreated(FragmentManagerImpl.java:2613)
02-27 21:58:36.557 E/AndroidRuntime(21324):     at androidx.fragment.app.FragmentController.dispatchActivityCreated(FragmentController.java:246)
02-27 21:58:36.557 E/AndroidRuntime(21324):     at androidx.fragment.app.FragmentActivity.onStart(FragmentActivity.java:542)
02-27 21:58:36.557 E/AndroidRuntime(21324):     at androidx.appcompat.app.AppCompatActivity.onStart(AppCompatActivity.java:201)
02-27 21:58:36.557 E/AndroidRuntime(21324):     at android.app.Instrumentation.callActivityOnStart(Instrumentation.java:1171)
02-27 21:58:36.557 E/AndroidRuntime(21324):     at android.app.Activity.performStart(Activity.java:5241)
02-27 21:58:36.557 E/AndroidRuntime(21324):     at android.app.ActivityThread.performLaunchActivity(ActivityThread.java:2178)

[mvglasow]

Fine with me. For the moment it looks like everything works (or at the worst can be made to work).

On February 28, 2020 5:54:42 AM GMT+01:00, KillerInk notifications@github.com wrote:

great! about the npe i look tomorrow into it. bit busy today

-- You are receiving this because you authored the thread. Reply to this email directly or view it on GitHub: https://github.com/KillerInk/FreeDcam/issues/104#issuecomment-592313141

-- Sent from my Android phone with K-9 Mail. Please excuse my brevity.

[mvglasow]

PS: the NPE should be fixed in the PR, if the issue is what I think it is.

[KillerInk]

seems to be fixed too.

[mvglasow]

The 6-hour endurance test did not reveal any more crashes (except that the app froze at some point, see #108), so I guess this one is resolved. Should I encounter any further crashes, I’ll open another issue.