location queue seems slow to empty via http service

[robsoden]

Your Environment

• Plugin version: 4.14.5
• Platform: iOS
• OS version: 17.2.1
• Device manufacturer / model: iPhone 15 Pro
• React Native version (react-native -v): 0.72.5
• Plugin config

{
      // Geolocation Config
      desiredAccuracy: BackgroundGeolocation.DESIRED_ACCURACY_HIGH,
      distanceFilter: 1,
      // Activity Recognition
      stopTimeout: 5,
      // Application config
      debug: false, // <-- enable this hear sounds for background-geolocation life-cycle.
      logLevel: BackgroundGeolocation.LOG_LEVEL_VERBOSE,
      stopOnTerminate: false, // <-- Allow the background-service to continue tracking when user closes the app.
      startOnBoot: true, // <-- Auto start tracking when device is powered-up.
      locationAuthorizationRequest: 'Always',
      // API
      url: Config.EVENT_API_ENDPOINT,
      params: {
        userId: userData?.id,
        eventType: 'location',
      },
      backgroundPermissionRationale: {
        title: "Allow {applicationName} to access to this device's location in the background?",
        message:
          'In order to track your location in the background, please enable {backgroundPermissionOptionLabel} location permission',
        positiveAction: 'Change to {backgroundPermissionOptionLabel}',
        negativeAction: 'Cancel',
      },
    }

Expected Behavior

Expecting our HTTP service to receive location events as they happen

Actual Behavior

HTTP service seems to only get events when the app is open/focused. As a result, users have stale locations.

Steps to Reproduce

Context

The location tracking seems to be working as expected, but we've noticed that the location sample queue is very slow to empty. If a user has the app open, we see live location pings to our service. However if the user has the device closed, the location stops updating in realtime, and the SQLite queue doesn't start to empty until they open the app again. Http requests via background fetch don't seem to be working for some reason, although I see them scheduled via the logger/debugger.

I'm assuming I have some kind of config issue on my end but I'm having trouble determining the problem.

Our distance filter is set very low just for testing - is it just recording too many events and overwhelming the background service?

I see a lot of these entries in the log: [TSHttpService flush:] Busy with previous request And I'm curious what this means, and what the expected fallback is.

For sample logs below, here's location record 5A4B755A-322C-435C-BB53-D0868A5C346A being recorded, and then note that it doesn't actually leave the queue until ~ 3 hours later.

Debug logs

Logs

2024-01-29 17:25:43.045 
╔═══════════════════════════════════════════════════════════
║ -[TSLocationManager locationManager:didUpdateLocations:] Enabled: 1 | isMoving: 1 | df: 4.0m | age: 44 ms
╚═══════════════════════════════════════════════════════════

2024-01-29 17:25:43.045 🔵-[TSLocationManager calculateMedianLocationAccuracy:] Median location accuracy: 4.7

2024-01-29 17:25:43.045 ℹ️-[TSConfig persist] 

2024-01-29 17:25:43.047 🔵-[TSConfig incrementOdometer:] 2139268.1

2024-01-29 17:25:43.047 ℹ️-[PolygonGeofencingService setLocation:] Already updating location <IGNORED>

2024-01-29 17:25:43.056 ✅-[TSLocationManager persistLocation:]_block_invoke INSERT: 5A4B755A-322C-435C-BB53-D0868A5C346A

2024-01-29 17:25:43.056 
╔═══════════════════════════════════════════════════════════
║ -[TSHttpService flush:] 
╚═══════════════════════════════════════════════════════════

2024-01-29 17:25:43.056 ⚠️-[TSHttpService flush:] Busy with previous request

2024-01-29 17:25:43.947 
╔═══════════════════════════════════════════════════════════
║ -[TSLocationManager createMotionTypeChangedHandler]_block_invoke | in_vehicle/100 | isMoving: 1
╚═══════════════════════════════════════════════════════════

2024-01-29 17:25:44.035 
📍<+36.08576120,-96.00675452> +/- 4.71m (speed 15.68 mps / course 179.51) @ 1/29/24, 5:25:44 PM Central Standard Time

2024-01-29 17:25:44.035 
╔═══════════════════════════════════════════════════════════
║ -[TSLocationManager locationManager:didUpdateLocations:] Enabled: 1 | isMoving: 1 | df: 4.0m | age: 34 ms
╚═══════════════════════════════════════════════════════════

2024-01-29 17:25:44.035 🔵-[TSLocationManager calculateMedianLocationAccuracy:] Median location accuracy: 4.7

2024-01-29 17:25:44.035 ℹ️-[TSConfig persist] 

2024-01-29 17:25:44.037 🔵-[TSConfig incrementOdometer:] 2139283.6

2024-01-29 17:25:44.037 ℹ️-[PolygonGeofencingService setLocation:] Already updating location <IGNORED>

2024-01-29 17:25:44.046 ✅-[TSLocationManager persistLocation:]_block_invoke INSERT: CF0B859F-EED1-420F-9F55-8C98C6EE13B3

2024-01-29 17:25:44.046 
╔═══════════════════════════════════════════════════════════
║ -[TSHttpService flush:] 
╚═══════════════════════════════════════════════════════════

2024-01-29 17:25:44.046 ⚠️-[TSHttpService flush:] Busy with previous request

2024-01-29 17:25:44.118 🔵-[HttpResponse handleResponse] Response: 200

2024-01-29 17:25:44.120 ✅-[TSHttpService post:]_block_invoke DESTROY: B3C55925-5002-4B99-BD03-54E4FBEFB89F

2024-01-29 17:25:44.122 ✅-[TSHttpService schedulePost] LOCKED: 0DA7B572-EA42-49CF-8E42-A75E6EF48B92

2024-01-29 17:25:45.034 
📍<+36.08562692,-96.00675657> +/- 4.72m (speed 15.29 mps / course 179.51) @ 1/29/24, 5:25:45 PM Central Standard Time

2024-01-29 17:25:45.034 
╔═══════════════════════════════════════════════════════════
║ -[TSLocationManager locationManager:didUpdateLocations:] Enabled: 1 | isMoving: 1 | df: 4.0m | age: 33 ms
╚═══════════════════════════════════════════════════════════

2024-01-29 17:25:45.034 🔵-[TSLocationManager calculateMedianLocationAccuracy:] Median location accuracy: 4.7

2024-01-29 17:25:45.034 ℹ️-[TSConfig persist] 

2024-01-29 17:25:45.036 🔵-[TSConfig incrementOdometer:] 2139298.5

2024-01-29 17:25:45.036 ℹ️-[PolygonGeofencingService setLocation:] Already updating location <IGNORED>

2024-01-29 17:25:45.045 ✅-[TSLocationManager persistLocation:]_block_invoke INSERT: 332BA1E0-15FF-4CAC-9FEA-60A0D2E6B8B5

2024-01-29 17:25:45.045 
╔═══════════════════════════════════════════════════════════
║ -[TSHttpService flush:] 
╚═══════════════════════════════════════════════════════════

2024-01-29 17:25:45.045 ⚠️-[TSHttpService flush:] Busy with previous request

2024-01-29 17:25:46.045 
📍<+36.08547807,-96.00674366> +/- 4.70m (speed 15.36 mps / course 179.51) @ 1/29/24, 5:25:46 PM Central Standard Time

2024-01-29 17:25:46.045 
╔═══════════════════════════════════════════════════════════
║ -[TSLocationManager locationManager:didUpdateLocations:] Enabled: 1 | isMoving: 1 | df: 4.0m | age: 45 ms
╚═══════════════════════════════════════════════════════════

2024-01-29 17:25:46.046 🔵-[TSLocationManager calculateMedianLocationAccuracy:] Median location accuracy: 4.7

2024-01-29 17:25:46.046 ℹ️-[TSConfig persist] 

2024-01-29 17:25:46.047 🔵-[TSConfig incrementOdometer:] 2139315.1

2024-01-29 17:25:46.048 ℹ️-[PolygonGeofencingService setLocation:] Already updating location <IGNORED>

2024-01-29 17:25:46.056 ✅-[TSLocationManager persistLocation:]_block_invoke INSERT: 8C43CB95-2CBD-4E14-8B9D-62C1FCE18FBD

2024-01-29 17:25:46.057 
╔═══════════════════════════════════════════════════════════
║ -[TSHttpService flush:] 
╚═══════════════════════════════════════════════════════════

2024-01-29 17:25:46.057 ⚠️-[TSHttpService flush:] Busy with previous request

2024-01-29 17:25:47.038 
📍<+36.08534604,-96.00674794> +/- 4.71m (speed 15.36 mps / course 179.51) @ 1/29/24, 5:25:47 PM Central Standard Time

2024-01-29 17:25:47.038 
╔═══════════════════════════════════════════════════════════
║ -[TSLocationManager locationManager:didUpdateLocations:] Enabled: 1 | isMoving: 1 | df: 4.0m | age: 38 ms
╚═══════════════════════════════════════════════════════════

2024-01-29 17:25:47.038 🔵-[TSLocationManager calculateMedianLocationAccuracy:] Median location accuracy: 4.7

2024-01-29 17:25:47.039 ℹ️-[TSConfig persist] 

2024-01-29 17:25:47.041 🔵-[TSConfig incrementOdometer:] 2139329.8

2024-01-29 17:25:47.041 ℹ️-[PolygonGeofencingService setLocation:] Already updating location <IGNORED>

2024-01-29 17:25:47.050 ✅-[TSLocationManager persistLocation:]_block_invoke INSERT: 8795D775-8003-4156-ADBC-04BFE7EF7EEF

2024-01-29 17:25:47.050 
╔═══════════════════════════════════════════════════════════
║ -[TSHttpService flush:] 
╚═══════════════════════════════════════════════════════════

2024-01-29 17:25:47.050 ⚠️-[TSHttpService flush:] Busy with previous request

2024-01-29 17:25:48.046 
📍<+36.08522061,-96.00675664> +/- 4.68m (speed 15.31 mps / course 179.51) @ 1/29/24, 5:25:48 PM Central Standard Time

2024-01-29 17:25:48.046 
╔═══════════════════════════════════════════════════════════
║ -[TSLocationManager locationManager:didUpdateLocations:] Enabled: 1 | isMoving: 1 | df: 4.0m | age: 46 ms
╚═══════════════════════════════════════════════════════════

2024-01-29 17:25:48.046 🔵-[TSLocationManager calculateMedianLocationAccuracy:] Median location accuracy: 4.7

2024-01-29 17:25:48.046 ℹ️-[TSConfig persist] 

2024-01-29 17:25:48.049 🔵-[TSConfig incrementOdometer:] 2139343.7

2024-01-29 17:25:48.049 ℹ️-[PolygonGeofencingService setLocation:] Already updating location <IGNORED>

2024-01-29 17:25:48.058 ✅-[TSLocationManager persistLocation:]_block_invoke INSERT: E6DD4B0E-ED8E-4719-AC25-D4882507D4F2

2024-01-29 17:25:48.058 
╔═══════════════════════════════════════════════════════════
║ -[TSHttpService flush:] 
╚═══════════════════════════════════════════════════════════

2024-01-29 17:25:48.058 ⚠️-[TSHttpService flush:] Busy with previous request

... omitting some logs just because it's very long, but happy to provide more

2024-01-29 20:04:46.135 ✅-[TSHttpService schedulePost] LOCKED: 5A4B755A-322C-435C-BB53-D0868A5C346A

2024-01-29 20:04:47.704 🔵-[HttpResponse handleResponse] Response: 200

2024-01-29 20:04:47.714 ✅-[TSHttpService post:]_block_invoke DESTROY: 5A4B755A-322C-435C-BB53-D0868A5C346A

2024-01-29 20:04:47.717 ✅-[TSHttpService schedulePost] LOCKED: CF0B859F-EED1-420F-9F55-8C98C6EE13B3

2024-01-29 20:04:49.309 🔵-[HttpResponse handleResponse] Response: 200

2024-01-29 20:04:49.321 ✅-[TSHttpService post:]_block_invoke DESTROY: CF0B859F-EED1-420F-9F55-8C98C6EE13B3

2024-01-29 20:04:49.324 ✅-[TSHttpService schedulePost] LOCKED: 332BA1E0-15FF-4CAC-9FEA-60A0D2E6B8B5

2024-01-29 20:04:50.774 🔵-[HttpResponse handleResponse] Response: 200

2024-01-29 20:04:50.783 ✅-[TSHttpService post:]_block_invoke DESTROY: 332BA1E0-15FF-4CAC-9FEA-60A0D2E6B8B5

2024-01-29 20:04:50.787 ✅-[TSHttpService schedulePost] LOCKED: 8C43CB95-2CBD-4E14-8B9D-62C1FCE18FBD

2024-01-29 20:04:52.207 🔵-[HttpResponse handleResponse] Response: 200

2024-01-29 20:04:52.217 ✅-[TSHttpService post:]_block_invoke DESTROY: 8C43CB95-2CBD-4E14-8B9D-62C1FCE18FBD

2024-01-29 20:04:52.221 ✅-[TSHttpService schedulePost] LOCKED: 8795D775-8003-4156-ADBC-04BFE7EF7EEF

2024-01-29 20:04:53.701 🔵-[HttpResponse handleResponse] Response: 200

2024-01-29 20:04:53.710 ✅-[TSHttpService post:]_block_invoke DESTROY: 8795D775-8003-4156-ADBC-04BFE7EF7EEF

2024-01-29 20:04:53.714 ✅-[TSHttpService schedulePost] LOCKED: E6DD4B0E-ED8E-4719-AC25-D4882507D4F2

2024-01-29 20:04:55.106 🔵-[HttpResponse handleResponse] Response: 200

2024-01-29 20:04:55.115 ✅-[TSHttpService post:]_block_invoke DESTROY: E6DD4B0E-ED8E-4719-AC25-D4882507D4F2

2024-01-29 20:04:55.119 ✅-[TSHttpService schedulePost] LOCKED: 473365DB-49FB-4710-BA59-A2275C2BA2B6

2024-01-29 20:04:56.859 🔵-[HttpResponse handleResponse] Response: 200

2024-01-29 20:04:56.868 ✅-[TSHttpService post:]_block_invoke DESTROY: 473365DB-49FB-4710-BA59-A2275C2BA2B6

2024-01-29 20:04:56.872 ✅-[TSHttpService schedulePost] LOCKED: D75E01EC-10BC-43FB-9B39-C87BA17E1D97

2024-01-29 20:04:59.083 🔵-[HttpResponse handleResponse] Response: 200

2024-01-29 20:04:59.092 ✅-[TSHttpService post:]_block_invoke DESTROY: D75E01EC-10BC-43FB-9B39-C87BA17E1D97

2024-01-29 20:04:59.095 ✅-[TSHttpService schedulePost] LOCKED: 4F6608C5-2352-4B40-9710-3EE71DBDAA03

2024-01-29 20:05:00.458 🔵-[HttpResponse handleResponse] Response: 200

2024-01-29 20:05:00.466 ✅-[TSHttpService post:]_block_invoke DESTROY: 4F6608C5-2352-4B40-9710-3EE71DBDAA03

2024-01-29 20:05:00.470 ✅-[TSHttpService schedulePost] LOCKED: 4366AB71-975B-4076-ABC2-85AAE6055F6F

Thank you in advance for any help/pointers!

[christocracy]

And I'm curious what this means, and what the expected fallback is.

The plug-in executes http requests synchronously one-at-time. If an http request is currently executing, it is "busy" and no need to execute another.

When the current http request completes, it will check the database for more records. If count > 0, the plug-in automatically selects another record and executes another http request, continuing until the database is empty.

If you find http requests are "slow", it's your server which is slow.

Read api docs "HTTP Guide", linked throughout.

[robsoden]

my concern is not necessarily with the "slowness" of the individual calls to the HTTP service, it's that the plugin seems to not be sending requests until the user opens the app again - per the example above, 3 hours later

for clarification - in the event where I see [TSHttpService flush:] Busy with previous request in the log, does this mean the http service is skipping scheduling the background fetch event?

if so, I feel like this might explain the behavior we're seeing. locations are in the sqlite log, but no background event was scheduled (because flush was busy) so they don't start emptying out until the app gets opened again.

is this a possibility?

[christocracy]

You are free to call .sync() manually at any time. You can also call .getCount() to learn how many records are in the database.

[robsoden]

the issue only occurs when the app is backgrounded - when it's in focus sync works fine (which negates my need to call it manually)

what i'm hoping to understand better is why sometimes flush schedules a background task, and sometimes it doesn't. if the background task does NOT get scheduled, then nothing is going to sync these locations via HTTP until the user opens the app again.

If I'm understanding correctly, it seems like Flush will NOT schedule a background fetch task if it's "busy with previous request" (it will just write the log to SQLite for later), and it might be busy with previous request if the HTTP call is taking an inordinately long time.

is the solution to just try and make sure that i'm able to fully complete the network request before the next log event?

again, I'm not trying to claim there's some kind of bug here, I'm just trying to make sure I fully understand the mechanism so I can fix my use case

[christocracy]

it seems like Flush will NOT schedule a background fetch task if it's "busy with previous request"

If it's "busy", an http request is already executing.

Background-fetch tasks are scheduled once and the OS executes them when it feels like it. The flush task doesn't "re-schedule" a new one. The next time the Os fires a fetch event, the plug-ins http service will query the database for records.

The issue is likely at your own server. You can easily test with the demo server at https://tracker.transistorsoft.com using TransistorAuthorizationToken (see the api docs).

[robsoden]

if the problem is with my server I would love to better understand why everything works fine when the app is in the foreground. it's the same server, same endpoint.

My confusion is why I don't see a similar number of entries in my log for [BackgroundTaskManager createBackgroundTask] and [TSLocationManager locationManager:didUpdateLocations:]

if the app is in the background, shouldn't this basically be 1-1? Why wouldn't these tasks be scheduled on every location update?

[christocracy]

if the app is in the background, shouldn't this basically be 1-1?

No. The http service initiates an iOS "background-task" (nothing to do with background-fetch) which signals to the OS that your app is doing important work and shouldn't be suspended.

The http service can initiate multiple http requests within the window of a single background-task.

[github-actions[bot]]

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

[github-actions[bot]]

This issue was closed because it has been inactive for 14 days since being marked as stale.