transistorsoft / flutter_background_geolocation

Sophisticated, battery-conscious background-geolocation & geofencing with motion-detection
https://www.transistorsoft.com/shop/products/flutter-background-geolocation
Other
650 stars 241 forks source link

`stopTimeout` seems to be stopping location updates even if not stopped for full duration #1347

Closed kvenn closed 1 month ago

kvenn commented 3 months ago

Your Environment

• No issues found!

* Plugin config:
```dart <-- Syntax highlighting: DO NOT REMOVE -->
// And this one
return bg.Config(
      transistorAuthorizationToken: token,
      showsBackgroundLocationIndicator: false,
      stopOnTerminate: false,
      startOnBoot: true,
      stopTimeout: 4,
)

Expected Behavior

Locations continue to send if I stop for less than stopTimeout. And if I stop for over stopTimeout, locations should get sent again after moving 200m

From the Philosophy of Operation

If any motion is detected before this timer expires, the plugin will remain in the moving state.

Actual Behavior

Taking a short stop prevents locations from being sent. I don't get locations even after 200m+ of movement.

Steps to Reproduce

  1. stopTimeout = 4 minutes
  2. Move over 200m
  3. Stop for 60 seconds
  4. Move 200m

Context

I'm seeing high background usage and I'm trying to configure the plugin to spend less time running in the background.

I ran two builds on the same device, one with disableStopDetection: true and the other with it false and stopTimeout: 4.

The one with stopTimeout: 4 used 8 minutes in the background. The one with disableStopDetection: true used 45 minutes.

The only issue, is that the one with stopTimeout: 4 stopped reporting after a short pause.

disableStopDetection: true - you can see the point in the bottom right is further than 200m image

stopTimeout: 4 image

Relevant Logs:

----------- The screenshot time is in UTC, but it starts right before here

2024-08-12 17:12:53.520 🔵-[HttpResponse handleResponse] Response: 200

2024-08-12 17:12:53.529 ✅-[TSHttpService post:]_block_invoke DESTROY: CC5E22A9-C7C4-4F5C-BBD5-4F6760DDEEC1

2024-08-12 17:12:53.529 ✅-[BackgroundTaskManager stopBackgroundTask:]_block_invoke 126 OF (
    126
)

2024-08-12 17:13:07.451 🔵-[TSLocationManager startMotionTriggerTimer] Motion-trigger timer engaged: Stop-detection will trigger in 10 seconds...

2024-08-12 17:13:17.456 🔵-[TSLocationManager beginStopDetection] ⏲Stop-timeout engaged: 240 s...

2024-08-12 17:13:44.703 🎾-[TSLocationManager startUpdatingLocation] Location-services: ON

2024-08-12 17:13:44.704 ℹ️-[TSLocationManager resetStopTimeoutTimer] 

2024-08-12 17:13:44.730 ℹ️+[LocationAuthorization run:onCancel:] status: 3

----------- No new location updates between 17:13 -> 17:35

2024-08-12 17:35:20.123 🔵-[TSHttpService init]_block_invoke Network: WiFi | Flags: -R -------

Debug logs

Logs I think the relevant log starts here: 2024-08-12 17:13:07.451 ``` 2024-08-12 17:12:07.047 🔵-[TSLocationManager calculateMedianLocationAccuracy:] Median location accuracy: 14.2 2024-08-12 17:12:07.047 ℹ️-[TSConfig persist] 2024-08-12 17:12:07.050 🔵-[TSConfig incrementOdometer:] 26901.9 2024-08-12 17:12:07.051 ℹ️-[PolygonGeofencingService setLocation:] Already updating location 2024-08-12 17:12:07.058 ✅-[TSLocationManager persistLocation:]_block_invoke INSERT: 842A4234-2AF0-4A01-BCCE-21ECECAB6B3A 2024-08-12 17:12:07.059 ✅-[BackgroundTaskManager createBackgroundTask] 120 2024-08-12 17:12:07.062 ✅-[TSHttpService schedulePost] LOCKED: 842A4234-2AF0-4A01-BCCE-21ECECAB6B3A 2024-08-12 17:12:07.893 🔵-[HttpResponse handleResponse] Response: 200 2024-08-12 17:12:07.902 ✅-[TSHttpService post:]_block_invoke DESTROY: 842A4234-2AF0-4A01-BCCE-21ECECAB6B3A 2024-08-12 17:12:07.902 ✅-[BackgroundTaskManager stopBackgroundTask:]_block_invoke 120 OF ( 120 ) 2024-08-12 17:12:31.043 🔵-[TSLocationManager locationManager:didUpdateLocations:] Updated distanceFilter, new: 72.000000, old: 114.000000 2024-08-12 17:12:31.043 🔵-[TSLocationManager calculateMedianLocationAccuracy:] Median location accuracy: 14.2 2024-08-12 17:12:31.043 ℹ️-[TSConfig persist] 2024-08-12 17:12:31.046 🔵-[TSConfig incrementOdometer:] 27021.4 2024-08-12 17:12:31.047 ℹ️-[PolygonGeofencingService setLocation:] Already updating location 2024-08-12 17:12:31.050 ✅-[TSLocationManager persistLocation:]_block_invoke INSERT: 91030B9A-B6D1-4AF1-9A70-94AFC6734637 2024-08-12 17:12:31.051 ✅-[BackgroundTaskManager createBackgroundTask] 123 2024-08-12 17:12:31.053 ✅-[TSHttpService schedulePost] LOCKED: 91030B9A-B6D1-4AF1-9A70-94AFC6734637 2024-08-12 17:12:31.587 🔵-[HttpResponse handleResponse] Response: 200 2024-08-12 17:12:31.594 ✅-[TSHttpService post:]_block_invoke DESTROY: 91030B9A-B6D1-4AF1-9A70-94AFC6734637 2024-08-12 17:12:31.594 ✅-[BackgroundTaskManager stopBackgroundTask:]_block_invoke 123 OF ( 123 ) 2024-08-12 17:12:53.052 🔵-[TSLocationManager calculateMedianLocationAccuracy:] Median location accuracy: 14.2 2024-08-12 17:12:53.052 ℹ️-[TSConfig persist] 2024-08-12 17:12:53.054 🔵-[TSConfig incrementOdometer:] 27095.0 2024-08-12 17:12:53.055 ℹ️-[PolygonGeofencingService setLocation:] Already updating location 2024-08-12 17:12:53.062 ✅-[TSLocationManager persistLocation:]_block_invoke INSERT: CC5E22A9-C7C4-4F5C-BBD5-4F6760DDEEC1 2024-08-12 17:12:53.063 ✅-[BackgroundTaskManager createBackgroundTask] 126 2024-08-12 17:12:53.066 ✅-[TSHttpService schedulePost] LOCKED: CC5E22A9-C7C4-4F5C-BBD5-4F6760DDEEC1 2024-08-12 17:12:53.520 🔵-[HttpResponse handleResponse] Response: 200 2024-08-12 17:12:53.529 ✅-[TSHttpService post:]_block_invoke DESTROY: CC5E22A9-C7C4-4F5C-BBD5-4F6760DDEEC1 2024-08-12 17:12:53.529 ✅-[BackgroundTaskManager stopBackgroundTask:]_block_invoke 126 OF ( 126 ) 2024-08-12 17:13:07.451 🔵-[TSLocationManager startMotionTriggerTimer] Motion-trigger timer engaged: Stop-detection will trigger in 10 seconds... 2024-08-12 17:13:17.456 🔵-[TSLocationManager beginStopDetection] ⏲Stop-timeout engaged: 240 s... 2024-08-12 17:13:44.703 🎾-[TSLocationManager startUpdatingLocation] Location-services: ON 2024-08-12 17:13:44.704 ℹ️-[TSLocationManager resetStopTimeoutTimer] 2024-08-12 17:13:44.730 ℹ️+[LocationAuthorization run:onCancel:] status: 3 2024-08-12 17:35:20.123 🔵-[TSHttpService init]_block_invoke Network: WiFi | Flags: -R ------- 2024-08-12 17:35:20.125 🔵-[TSLocationManager onResume:] enabled? 1 2024-08-12 17:35:20.151 ℹ️-[LocationDAO purge:] 1 2024-08-12 17:35:20.248 🔵-[TSLocationManager calculateMedianLocationAccuracy:] Median location accuracy: 14.2 2024-08-12 17:35:20.248 ℹ️-[TSConfig persist] 2024-08-12 17:35:20.256 🔵-[TSConfig incrementOdometer:] 28027.8 ```
christocracy commented 3 months ago

I suggest you field-test with debug: true. Read the api docs Config.debug to learn what the soundFX mean.

kvenn commented 3 months ago

I will do that, but you can also imagine the field testing takes a lot of time and if it's possible that your knowledge can save me a few hours, it would be much appreciated.

I've read all of Philosophy of Operation, read all the docs a few times over, and searched for all issues related to this since I didn't want to waste your time by filing an issue. But from that research and field testing, I'm still stumped by the behavior (which I've seen after a few tests).

I found another person who was seeing the same thing as me and disableStopDetection was the solution you offered. Another user also had this issue with the react native repo and the same thing fixed it for them.

I'm hoping you might have a little bit of expertise to shed on this - is there a reason why stopTimeout (with disableStopDetection: false) would be preventing the SDK from sending locations, even before the stopTimeout is hit?

kvenn commented 3 months ago

I've now listened to a handful of "boo-ba-da-boo"s without a corresponding "booop" but with a few "boop-boop"s.

The behavior I'm observing is consistent on the example app as well. Is there any guidance that can be offered?

Thanks again

github-actions[bot] commented 2 months ago

This issue is stale because it has been open for 30 days with no activity.

kvenn commented 2 months ago

Just checking in on this, any other configuration changes I should try to improve this behavior?

Thanks!

christocracy commented 2 months ago

Just checking in on this, any other configuration changes I should try to improve this behavior?

the plug-in runs an obj-c NSTimer for stopTimeout. It doesn’t fire before it’s supposed to. Are you observing the plug-in logs when this occurs?

kvenn commented 2 months ago

Yep, I've attached the logs (and highlighted the problematic lines). I'm unable to see the source code, so don't really have any guesses as to why I'm seeing the behavior I'm seeing. resetStopTimeoutTimer is getting called, yet I'm not seeing location updates after the pause.

I've run the same test with 4 different builds. I bike to the water, I pause for 60 seconds, I bike back.

I ran the test once with the two builds of my own app installed on the same device (which the screenshots are from) - each with a different configuration from above

I ran the test twice more with the example app (with the different configurations) and observed the same behavior (and was listening to the debug sounds).

christocracy commented 2 months ago

You can also test with debug: true and the plugin will emit an obvious sound-effect when the stopTimeout expires, in addition to posting a local notification.

carmaa commented 1 month ago

I have this same issue. It is happening on iOS when field testing on a physical device when the app has been booted in the background.

Specifically, with debug: true and when stopping for a period that is shorter than the configured stopTimeout, the local notifications shows:

  1. ⏲️Stop-timeout engaged: 300 s...
  2. ⏲️Stop-timeout cancelled

After 2, no more location updates is received. Could it be that iOS suspends the app?

christocracy commented 1 month ago

@carmaa

Your Environment

carmaa commented 1 month ago

Should have posted straight away:

Your Environment

• No issues found!


Here's a snippet of the logs from the motion-trigger timer engaged:

2024-09-29 17:48:55.299 ╔═══════════════════════════════════════════════════════════ ║ -[TSLocationManager createMotionTypeChangedHandler]_block_invoke | still/33 | isMoving: 0 ╚═══════════════════════════════════════════════════════════

2024-09-29 17:48:55.299 🔵-[TSLocationManager startMotionTriggerTimer] Motion-trigger timer engaged: Stop-detection will trigger in 10 seconds...

2024-09-29 17:48:55.300 🔵-[TSLocationManager getCurrentPosition:]

2024-09-29 17:48:55.300 🎾-[LocationManager startUpdatingLocation] ON

2024-09-29 17:48:55.315 ℹ️+[LocationAuthorization run:onCancel:] status: 3

2024-09-29 17:48:55.315 📍<+59.92583427,+10.59924838> +/- 35.00m (speed -1.00 mps / course -1.00) @ 29/09/2024, 17:48:48 Central European Summer Time

2024-09-29 17:48:55.315 ╔═══════════════════════════════════════════════════════════ ║ -[LocationManager locationManager:didUpdateLocations:] Sample 1 of 3 (6332 ms old) ╚═══════════════════════════════════════════════════════════

2024-09-29 17:48:55.316 📍<+59.92583427,+10.59924838> +/- 35.00m (speed -1.00 mps / course -1.00) @ 29/09/2024, 17:48:55 Central European Summer Time

2024-09-29 17:48:55.316 ╔═══════════════════════════════════════════════════════════ ║ -[LocationManager locationManager:didUpdateLocations:] Sample 2 of 3 (13 ms old) ╚═══════════════════════════════════════════════════════════

2024-09-29 17:48:55.955 📍<+59.92574819,+10.59958264> +/- 35.00m (speed -1.00 mps / course -1.00) @ 29/09/2024, 17:48:55 Central European Summer Time

2024-09-29 17:48:55.955 ╔═══════════════════════════════════════════════════════════ ║ -[TSLocationManager locationManager:didUpdateLocations:] Enabled: 1 | isMoving: 1 | df: 10.0m | age: 15 ms ╚═══════════════════════════════════════════════════════════

2024-09-29 17:48:55.955 🔵-[TSLocationManager calculateMedianLocationAccuracy:] Median location accuracy: 5.4

2024-09-29 17:48:55.955 ℹ️-[PolygonGeofencingService setLocation:] Already updating location

2024-09-29 17:48:55.958 📍<+59.92574819,+10.59958264> +/- 35.00m (speed -1.00 mps / course -1.00) @ 29/09/2024, 17:48:55 Central European Summer Time

2024-09-29 17:48:55.958 🔴-[LocationManager stopUpdatingLocation] OFF

2024-09-29 17:48:55.958 ╔═══════════════════════════════════════════════════════════ ║ -[LocationManager locationManager:didUpdateLocations:] Sample 3 of 3 (18 ms old) ╚═══════════════════════════════════════════════════════════

2024-09-29 17:48:55.958 ℹ️-[PolygonGeofencingService setLocation:] Already updating location

2024-09-29 17:48:55.963 ✅-[TSLocationManager persistLocation:]_block_invoke INSERT: C959D2F1-C380-4377-A300-58194831324F

2024-09-29 17:48:55.963 ╔═══════════════════════════════════════════════════════════ ║ -[TSHttpService flush:] ╚═══════════════════════════════════════════════════════════

2024-09-29 17:48:55.965 ✅-[BackgroundTaskManager createBackgroundTask] 15

2024-09-29 17:48:55.973 ✅-[TSHttpService schedulePost] LOCKED: C959D2F1-C380-4377-A300-58194831324F

2024-09-29 17:48:56.147 🔵-[HttpResponse handleResponse] Response: 200

2024-09-29 17:48:56.155 ✅-[TSHttpService post:]_block_invoke DESTROY: C959D2F1-C380-4377-A300-58194831324F

2024-09-29 17:48:56.155 ╔═══════════════════════════════════════════════════════════ ║ -[TSHttpService finish:error:] Success: 1 ╚═══════════════════════════════════════════════════════════

2024-09-29 17:48:56.155 ✅-[BackgroundTaskManager stopBackgroundTask:]_block_invoke 15 OF ( 15 )

2024-09-29 17:48:58.477 ╔═══════════════════════════════════════════════════════════ ║ -[TSLocationManager createMotionTypeChangedHandler]_block_invoke | still/33 | isMoving: 0 ╚═══════════════════════════════════════════════════════════

2024-09-29 17:49:00.394 ╔═══════════════════════════════════════════════════════════ ║ -[TSLocationManager createMotionTypeChangedHandler]_block_invoke | still/100 | isMoving: 0 ╚═══════════════════════════════════════════════════════════

2024-09-29 17:49:05.305 🔵-[TSLocationManager beginStopDetection] ⏲Stop-timeout engaged: 300 s...

2024-09-29 17:49:10.900 ╔═══════════════════════════════════════════════════════════ ║ -[TSLocationManager createMotionTypeChangedHandler]_block_invoke | still/100 | isMoving: 0 ╚═══════════════════════════════════════════════════════════

2024-09-29 17:49:10.900 🔵-[TSLocationManager detectStopMotion:shakeCount:] Stationary-time: 5/300 s

2024-09-29 17:49:11.218 ╔═══════════════════════════════════════════════════════════ ║ -[TSLocationManager createMotionTypeChangedHandler]_block_invoke | on_foot/100 | isMoving: 1 ╚═══════════════════════════════════════════════════════════

2024-09-29 17:49:11.220 🎾-[TSLocationManager startUpdatingLocation] Location-services: ON

2024-09-29 17:49:11.220 ℹ️-[TSLocationManager resetStopTimeoutTimer]

2024-09-29 17:49:11.242 ℹ️+[LocationAuthorization run:onCancel:] status: 3

2024-09-29 17:49:40.024 🔵-[TSLocationManager onResume:] enabled? 1

2024-09-29 17:49:40.027 ℹ️-[TSDBLogger db_save] Log committed

2024-09-29 17:49:40.030 ℹ️-[LocationDAO purge:] 1

2024-09-29 17:49:40.033 ℹ️-[TSDBLogger db_save] Log committed

2024-09-29 17:49:40.033 ╔═══════════════════════════════════════════════════════════ ║ -[TSHttpService flush:] ╚═══════════════════════════════════════════════════════════

2024-09-29 17:49:40.033 ╔═══════════════════════════════════════════════════════════ ║ -[TSHttpService finish:error:] Success: 1 ╚═══════════════════════════════════════════════════════════

2024-09-29 17:49:40.042 ╔═══════════════════════════════════════════════════════════ ║ -[TSLocationManager createMotionTypeChangedHandler]_block_invoke | on_foot/100 | isMoving: 1 ╚═══════════════════════════════════════════════════════════

2024-09-29 17:49:40.882 📍<+59.92549691,+10.59951668> +/- 35.00m (speed -1.00 mps / course -1.00) @ 29/09/2024, 17:49:40 Central European Summer Time

2024-09-29 17:49:40.882 ╔═══════════════════════════════════════════════════════════ ║ -[TSLocationManager locationManager:didUpdateLocations:] Enabled: 1 | isMoving: 1 | df: 10.0m | age: 15 ms ╚═══════════════════════════════════════════════════════════

2024-09-29 17:49:40.882 🔵-[TSLocationManager calculateMedianLocationAccuracy:] Median location accuracy: 5.4

2024-09-29 17:49:40.882 ℹ️-[TSConfig persist]

2024-09-29 17:49:40.884 🔵-[TSConfig incrementOdometer:] 605.5

2024-09-29 17:49:40.885 ℹ️-[PolygonGeofencingService setLocation:] Already updating location

2024-09-29 17:49:54.342 📍<+59.92543914,+10.59918267> +/- 35.00m (speed -1.00 mps / course -1.00) @ 29/09/2024, 17:49:54 Central European Summer Time

2024-09-29 17:49:54.342 ╔═══════════════════════════════════════════════════════════ ║ -[TSLocationManager locationManager:didUpdateLocations:] Enabled: 1 | isMoving: 1 | df: 10.0m | age: 15 ms ╚═══════════════════════════════════════════════════════════

2024-09-29 17:49:54.343 🔵-[TSLocationManager calculateMedianLocationAccuracy:] Median location accuracy: 5.0

2024-09-29 17:49:54.343 ℹ️-[PolygonGeofencingService setLocation:] Already updating location

christocracy commented 1 month ago

showsBackgroundLocationIndicator: false,

Try setting true and go test.

carmaa commented 1 month ago

showsBackgroundLocationIndicator: false,

Try setting true and go test.

Thanks for a quick reply, that saved me from some hours of debugging.

That was it.

iOS doesn't like to hide the indicator it seems, so for anyone else ending up here because how the plugin performs when booted in the background, this may be a root cause. Could perhaps be included in the documentation. The plugin seems to perform normally when kept non-terminated by the user.

Thanks for a great plugin.

christocracy commented 1 month ago

It’s due to a recent change in iOS where they encourage not hiding the notification icon.

kvenn commented 1 month ago

Why would the existence of a stopTimeout (even if the time hasn't elapsed) cause the plugin to shut down in the background?

I'd like to keep showsBackgroundLocationIndicator set to false for my use case. So if stopTimeout can't work with showsBackgroundLocationIndicator, would it be viable for me to create my own stop timeout which calls changePace(false) after the elapsed time?

christocracy commented 1 month ago

Try it and see but I (and Apple) strongly suggest you avoid using hiding the background location indicator.

kvenn commented 1 month ago

Okay cool, I'll give it a shot and report back, thanks.

Any thoughts on the first question? I'm curious what could be causing the plugin to suspend before the timer elapses and any insight can help me avoid it in my own implementation.

carmaa commented 1 month ago

Correct me if I'm wrong, but is this the root cause from iOS 16.4 and upwards?

https://forums.developer.apple.com/forums/thread/726945?answerId=749230022#749230022

christocracy commented 1 month ago

Yes

kvenn commented 1 month ago

I added a stop timeout on my own and it seems to fully fix my issue. So I just disabled the stopTimeout in this library which wasn't working and am using this. Now it waits until the timeout timer has finished before disabling location updates.

Thanks for the guidance!

My config has:

disableStopDetection: true,
showsBackgroundLocationIndicator: false

Simplified implementation:

    const stopTimeout = Duration(minutes: 5);
    bg.BackgroundGeolocation.onActivityChange((ActivityChangeEvent event) {
      _log.debug('[onActivityChange] - $event');
      // If user is still for stopTimeout, call changePace(false)
      if (event.activity == 'still') {
        Future.delayed(stopTimeout, () {
          bg.BackgroundGeolocation.changePace(false);
        });
      }
    });
christocracy commented 1 month ago

showsBackgroundLocationIndicator: false

Just set that to true or you’re fighting against the OS. All your trouble goes away.

kvenn commented 1 month ago

Unfortunately, my competitors do not show the blue indicator and that makes it non-viable for me. From our user interviews, users associate that blue indicator with battery consumption. Which doesn't need to be the case. Now with my improved stopTimeout fix, my battery consumption and accuracy are around the same as my competitors. So should be good for now!