search

lostzen / lost

A drop-in replacement for Google Play services location APIs for Android
http://mapzen.github.io/lost/
Other
352 stars 70 forks source link

Exception on restarting of activity #143

Closed westnordost closed 7 years ago

westnordost commented 7 years ago

Description

Phew, sorry for posting all those bugs. Especially for the last ones, I am not sure if they are not my fault somehow.

I sometimes get the following exception when the activity is stopped for deploying a new version of the app from Android Studio.

E/AndroidRuntime: FATAL EXCEPTION: main
                  Process: de.westnordost.streetcomplete, PID: 31813
                  java.lang.RuntimeException: Unable to stop activity {de.westnordost.streetcomplete/de.westnordost.streetcomplete.MainActivity}: java.lang.NullPointerException: Attempt to invoke virtual method 'com.mapzen.android.lost.api.PendingResult com.mapzen.android.lost.internal.FusedLocationProviderService.removeLocationUpdates(com.mapzen.android.lost.api.LostApiClient, com.mapzen.android.lost.api.LocationListener)' on a null object reference
                      at android.app.ActivityThread.handleSleeping(ActivityThread.java:3605)
                      at android.app.ActivityThread.access$2800(ActivityThread.java:156)
                      at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1526)
                      at android.os.Handler.dispatchMessage(Handler.java:102)
                      at android.os.Looper.loop(Looper.java:211)
                      at android.app.ActivityThread.main(ActivityThread.java:5389)
                      at java.lang.reflect.Method.invoke(Native Method)
                      at java.lang.reflect.Method.invoke(Method.java:372)
                      at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:1020)
                      at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:815)
                   Caused by: java.lang.NullPointerException: Attempt to invoke virtual method 'com.mapzen.android.lost.api.PendingResult com.mapzen.android.lost.internal.FusedLocationProviderService.removeLocationUpdates(com.mapzen.android.lost.api.LostApiClient, com.mapzen.android.lost.api.LocationListener)' on a null object reference
                      at com.mapzen.android.lost.internal.FusedLocationProviderApiImpl.removeLocationUpdates(FusedLocationProviderApiImpl.java:132)
                      at de.westnordost.streetcomplete.MainActivity.onStop(MainActivity.java:197)
                      at android.app.Instrumentation.callActivityOnStop(Instrumentation.java:1277)
                      at android.app.Activity.performStop(Activity.java:6142)
                      at android.app.ActivityThread.handleSleeping(ActivityThread.java:3602)
                      at android.app.ActivityThread.access$2800(ActivityThread.java:156) 
                      at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1526) 
                      at android.os.Handler.dispatchMessage(Handler.java:102) 
                      at android.os.Looper.loop(Looper.java:211) 
                      at android.app.ActivityThread.main(ActivityThread.java:5389) 
                      at java.lang.reflect.Method.invoke(Native Method) 
                      at java.lang.reflect.Method.invoke(Method.java:372) 
                      at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:1020) 
                      at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:815) 

Steps to Reproduce

I have not found a way yet to reproduce it reliably. I think it happens when gradle does a full rebuild. The relevant code looks like this. It may be worth to note that I have another fragment which also requests location updates, removeLocationUpdates and disconnects on stop.

@Override protected void onCreate(Bundle savedInstanceState)
{
    super.onCreate(savedInstanceState);
    lostApiClient = new LostApiClient.Builder(this).addConnectionCallbacks(
            new LostApiClient.ConnectionCallbacks()
            {
                @Override
                public void onConnected()
                {
                    initLocationTracking();
                }

                @Override
                public void onConnectionSuspended() {}
            }).build();
}

@Override public void onStart()
{
    super.onStart();
    lostApiClient.connect();
}

@Override public void onStop()
{
    super.onStop();
ln 197: LocationServices.FusedLocationApi.removeLocationUpdates(lostApiClient, this);
    lostApiClient.disconnect();
}

Lost & Android Version

2.1.1 on Android 5.0

westnordost commented 7 years ago

I think it happens when a new version is deployed, the app was the last being active but the device is currently sleeping (screen off).

ecgreb commented 7 years ago

Hey @westnordost thanks for the detailed reports and no worries about how many we appreciate the feedback! Even if some of these issues turn out to be on the app side its helpful to know how developers are using the project.

Are you able to reproduce this under normal end-user conditions (i.e. not deploying a new build from Android Studio)? For example if the app is cleared from the recent apps menu then restarted from the launcher.

Can you post the code for initLocationTracking() since that could contain some relevant info?

Finally are you able to reproduce using the Lost sample app since your code seems quite similar to what we have in the demo?

westnordost commented 7 years ago

I tested the app in front, waiting for the phone to turn off the display, then going back. Doesn't reproduce. Same with not having the app in front, then waiting for the phone to turn off the display, then switching back on and going back to the app.

The method initLocationTracking()

    private void initLocationTracking()
    {
        if (ActivityCompat.checkSelfPermission(this, Manifest.permission.ACCESS_FINE_LOCATION)
                != PackageManager.PERMISSION_GRANTED)
        {
            ActivityCompat.requestPermissions(
                    this, new String[]{ Manifest.permission.ACCESS_FINE_LOCATION },
                    LOCATION_PERMISSION_REQUEST);
            return;
        }

        LocationRequest request = LocationRequest.create()
                .setPriority(LocationRequest.PRIORITY_HIGH_ACCURACY)
                .setSmallestDisplacement(500)
                .setInterval(3*60*1000); // 3 minutes

        Location location = LocationServices.FusedLocationApi.getLastLocation(lostApiClient);
        if(location != null)
        {
            this.onLocationChanged(location);
        }

        LocationServices.FusedLocationApi.requestLocationUpdates(lostApiClient, request, this);
    }

Finally are you able to reproduce using the Lost sample app since your code seems quite similar to what we have in the demo?

Will look into it tomorrow, too late today already (1:22AM).

westnordost commented 7 years ago

I just tested it: Started the FusedLocationApi sample. Didn't touch the phone for 20min or so, made a random change to the source code, deployed again, no problems, no exception.

Well, the only obvious difference that remains between the sample code and my code is that I register/unregister for location requests at two different places in the same program, perhaps that is a clue for reproducing it.

westnordost commented 7 years ago

I could now reproduce it out of the debugging environment. The log shows that I switched from another app to my app. The former being a great Android adaption of a great boardgame by the way :-)

Here is the log:

12-01 17:13:30.395 V/WindowManager(  865): Adding window Window{3f026d35 u0 de.westnordost.streetcomplete/de.westnordost.streetcomplete.MainActivity} at 13 of 19 (after Window{349f0799 u0 com.czechgames.galaxytrucker/com.czechgames.galaxytrucker.Main})
12-01 17:13:30.433 E/AndroidRuntime(30712): FATAL EXCEPTION: main
12-01 17:13:30.433 E/AndroidRuntime(30712): Process: de.westnordost.streetcomplete, PID: 30712
12-01 17:13:30.433 E/AndroidRuntime(30712): java.lang.RuntimeException: Unable to stop activity {de.westnordost.streetcomplete/de.westnordost.streetcomplete.MainActivity}: java.lang.NullPointerException: Attempt to invoke virtual method 'com.mapzen.android.lost.api.PendingResult com.mapzen.android.lost.internal.FusedLocationProviderService.removeLocationUpdates(com.mapzen.android.lost.api.LostApiClient, com.mapzen.android.lost.api.LocationListener)' on a null object reference
12-01 17:13:30.433 E/AndroidRuntime(30712):     at android.app.ActivityThread.performDestroyActivity(ActivityThread.java:3776)
12-01 17:13:30.433 E/AndroidRuntime(30712):     at android.app.ActivityThread.handleDestroyActivity(ActivityThread.java:3830)
12-01 17:13:30.433 E/AndroidRuntime(30712):     at android.app.ActivityThread.handleRelaunchActivity(ActivityThread.java:4030)
12-01 17:13:30.433 E/AndroidRuntime(30712):     at android.app.ActivityThread.access$900(ActivityThread.java:156)
12-01 17:13:30.433 E/AndroidRuntime(30712):     at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1357)
12-01 17:13:30.433 E/AndroidRuntime(30712):     at android.os.Handler.dispatchMessage(Handler.java:102)
12-01 17:13:30.433 E/AndroidRuntime(30712):     at android.os.Looper.loop(Looper.java:211)
12-01 17:13:30.433 E/AndroidRuntime(30712):     at android.app.ActivityThread.main(ActivityThread.java:5389)
12-01 17:13:30.433 E/AndroidRuntime(30712):     at java.lang.reflect.Method.invoke(Native Method)
12-01 17:13:30.433 E/AndroidRuntime(30712):     at java.lang.reflect.Method.invoke(Method.java:372)
12-01 17:13:30.433 E/AndroidRuntime(30712):     at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:1020)
12-01 17:13:30.433 E/AndroidRuntime(30712):     at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:815)
12-01 17:13:30.433 E/AndroidRuntime(30712): Caused by: java.lang.NullPointerException: Attempt to invoke virtual method 'com.mapzen.android.lost.api.PendingResult com.mapzen.android.lost.internal.FusedLocationProviderService.removeLocationUpdates(com.mapzen.android.lost.api.LostApiClient, com.mapzen.android.lost.api.LocationListener)' on a null object reference
12-01 17:13:30.433 E/AndroidRuntime(30712):     at com.mapzen.android.lost.internal.FusedLocationProviderApiImpl.removeLocationUpdates(FusedLocationProviderApiImpl.java:132)
12-01 17:13:30.433 E/AndroidRuntime(30712):     at de.westnordost.streetcomplete.tangram.MapFragment.stopPositionTracking(MapFragment.java:128)
12-01 17:13:30.433 E/AndroidRuntime(30712):     at de.westnordost.streetcomplete.tangram.MapFragment.onStop(MapFragment.java:252)
12-01 17:13:30.433 E/AndroidRuntime(30712):     at android.app.Fragment.performStop(Fragment.java:2224)
12-01 17:13:30.433 E/AndroidRuntime(30712):     at android.app.FragmentManagerImpl.moveToState(FragmentManager.java:945)
12-01 17:13:30.433 E/AndroidRuntime(30712):     at android.app.FragmentManagerImpl.moveToState(FragmentManager.java:1067)
12-01 17:13:30.433 E/AndroidRuntime(30712):     at android.app.FragmentManagerImpl.moveToState(FragmentManager.java:1049)
12-01 17:13:30.433 E/AndroidRuntime(30712):     at android.app.FragmentManagerImpl.dispatchStop(FragmentManager.java:1887)
12-01 17:13:30.433 E/AndroidRuntime(30712):     at android.app.Activity.performStop(Activity.java:6139)
12-01 17:13:30.433 E/AndroidRuntime(30712):     at android.app.ActivityThread.performDestroyActivity(ActivityThread.java:3771)
12-01 17:13:30.433 E/AndroidRuntime(30712):     ... 11 more
ecgreb commented 7 years ago

Ok so its clear the issue is the FusedLocationProviderApiImpl has a null reference for the FusedLocationProviderService when this method is invoked.

The real question is why. Are you using separate LostApiClient instances in your activity and fragment? If so its possible when one of them disconnects the service is mistakenly set to null before the other calls removeLocationUpdates(...) which would indicate a bug in our support for multiple clients.

westnordost commented 7 years ago

Are you using separate LostApiClient instances in your activity and fragment?

Yes. Both create their own lostApiClient, using new LostApiClient.Builder(activity).build();

sarahsnow1 commented 7 years ago

@westnordost Would you mind posting a simplified version of your Activity/Fragment combo? Or looking at the example CrashActivity.txt I have and making updates to it so that it reproduces your issue?

CrashActivity.txt

westnordost commented 7 years ago

Well, that the building of two separate lost api clients is behind the crash is just one assumption why it may crash. It may be caused by something completely different, like perhaps even faulty usage of the API.

If you cannot reproduce it with your minimal case, I suggest you checkout my project - it's open source - and set a breakpoint in FusedLocationProviderApiImpl::onDisconnect, see when/why it is unjustifiably called. I could also do this myself (tomorrow, earliest), but I could probably not interpret what I see then during debugging since I do not know the LOST project's interna.

So If you want to have a go, the only classes that do anything with LOST are MainActivity and tangram/MapFragment which is part of main activity's static layout and a member of MainActivity.

The difference with my activity to your CrashActivity.txt is that

westnordost commented 7 years ago

After a little debugging session, the result is somewhat unsatisfying:

I set breakpoints in LostApiClientImpl.connect and disconnect as well as FusedLocationProviderApiImp.onDisconnect. All is triggered correctly and the in the correct order: On start of the activity, two times connect, then, when the smartphone goes to sleep, two times disconnectand finally one call to onDisconnect.

However I can still reproduce it sometimes if I deploy a new version while my smartphone is sleeping. In that case, no breakpoint is triggered at all. The explanation might be that as the build job wants to deploy a new version of the APK, the debugger is being disconnected from the currently running one and after that, the job tries to stop the old job in order to deploy the new one. This fails due to the exception and the new APK is not deployed.

So, to me it looks like that Android is calling onStop() in the activity in question twice, once on going to sleep and once later when it tries to stop the old application. Since the debugger is disconnected at this point, I cannot confirm this. I'll add some log output to see if my assumption is correct here. If it is correct, then I guess LOST just needs to be robust enough to handle the case of onStop being called several times with no onStart() in between.

westnordost commented 7 years ago

Here is another crash I got today while walking around. Slightly different trace but same cause:

12-09 18:32:04.808 21652-21652/? E/AndroidRuntime: FATAL EXCEPTION: main
                                                   Process: de.westnordost.streetcomplete, PID: 21652
                                                   java.lang.RuntimeException: Unable to stop activity {de.westnordost.streetcomplete/de.westnordost.streetcomplete.MainActivity}: java.lang.NullPointerException: Attempt to invoke virtual method 'com.mapzen.android.lost.api.PendingResult com.mapzen.android.lost.internal.FusedLocationProviderService.removeLocationUpdates(com.mapzen.android.lost.api.LostApiClient, com.mapzen.android.lost.api.LocationListener)' on a null object reference
                                                       at android.app.ActivityThread.performDestroyActivity(ActivityThread.java:3776)
                                                       at android.app.ActivityThread.handleDestroyActivity(ActivityThread.java:3830)
                                                       at android.app.ActivityThread.handleRelaunchActivity(ActivityThread.java:4030)
                                                       at android.app.ActivityThread.access$900(ActivityThread.java:156)
                                                       at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1357)
                                                       at android.os.Handler.dispatchMessage(Handler.java:102)
                                                       at android.os.Looper.loop(Looper.java:211)
                                                       at android.app.ActivityThread.main(ActivityThread.java:5389)
                                                       at java.lang.reflect.Method.invoke(Native Method)
                                                       at java.lang.reflect.Method.invoke(Method.java:372)
                                                       at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:1020)
                                                       at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:815)
                                                    Caused by: java.lang.NullPointerException: Attempt to invoke virtual method 'com.mapzen.android.lost.api.PendingResult com.mapzen.android.lost.internal.FusedLocationProviderService.removeLocationUpdates(com.mapzen.android.lost.api.LostApiClient, com.mapzen.android.lost.api.LocationListener)' on a null object reference
                                                       at com.mapzen.android.lost.internal.FusedLocationProviderApiImpl.removeLocationUpdates(FusedLocationProviderApiImpl.java:132)
                                                       at de.westnordost.streetcomplete.tangram.MapFragment.stopPositionTracking(MapFragment.java:128)
                                                       at de.westnordost.streetcomplete.tangram.MapFragment.onStop(MapFragment.java:252)
                                                       at android.app.Fragment.performStop(Fragment.java:2224)
                                                       at android.app.FragmentManagerImpl.moveToState(FragmentManager.java:945)
                                                       at android.app.FragmentManagerImpl.moveToState(FragmentManager.java:1067)
                                                       at android.app.FragmentManagerImpl.moveToState(FragmentManager.java:1049)
                                                       at android.app.FragmentManagerImpl.dispatchStop(FragmentManager.java:1887)
                                                       at android.app.Activity.performStop(Activity.java:6139)
                                                       at android.app.ActivityThread.performDestroyActivity(ActivityThread.java:3771)
                                                       at android.app.ActivityThread.handleDestroyActivity(ActivityThread.java:3830) 
                                                       at android.app.ActivityThread.handleRelaunchActivity(ActivityThread.java:4030) 
                                                       at android.app.ActivityThread.access$900(ActivityThread.java:156) 
                                                       at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1357) 
                                                       at android.os.Handler.dispatchMessage(Handler.java:102) 
                                                       at android.os.Looper.loop(Looper.java:211) 
                                                       at android.app.ActivityThread.main(ActivityThread.java:5389) 
                                                       at java.lang.reflect.Method.invoke(Native Method) 
                                                       at java.lang.reflect.Method.invoke(Method.java:372) 
                                                       at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:1020) 
                                                       at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:815) 
sarahsnow1 commented 7 years ago

Thank you for these details.

I noticed a couple unconventional things in your classes:

  1. You are not implementing connection callbacks in your fragment. While the app functions fine because the MainActivity connects a LostApiClient which triggers the underlying service to be connected by the time location updates are requested, you might want to add/implement these callbacks to ensure that you don't crash.
  2. There is an explicit call to stop the Fragment's positioning tracking from the MainActivity. This doesn't cause any problems but isn't necessary as the same call is made from the Fragment's onStop method.

Given that this bug is not reproducible under the normal application lifecycle flow (onRestart or onDestroy will always be called before another call to onStop is made) and that we have a ticket to handle NPEs in a more specific way (https://github.com/mapzen/lost/issues/89), I am going to close it. Please track that ticket for further info and feel free to open another issue if something else comes up!

westnordost commented 7 years ago

(1.) is not the case anymore, the problem still occurs though. Also on a non-development environment, see my last trace.