react-native-background-geolocation icon indicating copy to clipboard operation
react-native-background-geolocation copied to clipboard

Published 20 hours ago • verified publisher icon transistorsoft

No data collected for a car trip

Open giulianogiannico-vidiemme opened this issue 3 years ago • 7 comments

Your Environment

  • Plugin version: 4.4.6
  • Platform: iOS
  • OS version: 15.4.1
  • Device manufacturer / model: Apple iPhone 11
  • React Native version (react-native -v): 0.66.0
  • Plugin config
BackgroundGeolocation.ready({
  desiredAccuracy: BackgroundGeolocation.DESIRED_ACCURACY_NAVIGATION,
  showsBackgroundLocationIndicator: true,
  distanceFilter: 0,
  stopTimeout: 5,
  preventSuspend: true,
  heartbeatInterval: 30,
  foregroundService: true,
  debug: false,
  logLevel: BackgroundGeolocation.LOG_LEVEL_VERBOSE,
  stopOnTerminate: true,
  startOnBoot: false,
  batchSync: false,
  autoSync: false,
});

Expected Behavior

A collegue did a car trip on June 4th 2022 precisely started at 9:56 AM and stopped at 10:08 AM (as you can see on the attached logs). I expected to see location updates and/or heartbeat interval callback in the logs during the trip as usual.

Actual Behavior

Despite the library was configured with preventSuspend: true flag and heartbeatInterval I can't see any trace of location updates and heartbeat callback as well in the logs. Have you any ideas for possible reasons of this behavior?

Steps to Reproduce

  1. configure the library via BackgroundGeolocation.ready using above options
  2. start monitoring using BackgroundGeolocation.start()
  3. stop monitoring using BackgroundGeolocation.stop()

Context

Monitor a car trip with our app which usually works good (iOS/Android).

Debug logs

Logs 
2022-06-04 09:56:34.166 ℹ️-[TSLocationManager log:message:] [RNCustomLog] | LEVEL: debug --- listenStartAutomaticMonitoring ----> BLUETOOTH - BT start Callback!

2022-06-04 09:56:34.237 ℹ️-[TSLocationManager log:message:] [RNCustomLog] | LEVEL: debug --- startMonitoring ----> TRIP STARTING - BEFORE initTrip! ||| appVersion --> bundle: com.****.stag --- version: 0.7.5 --- build: 90108 ||| BT --> true ||| device --> {"platform":"iOS","manufacturer":"Apple","model":"iPhone12,1","framework":"react-native","version":"15.4.1"}

2022-06-04 09:56:51.203 ℹ️-[TSConfig persist] 

2022-06-04 09:56:51.209 ℹ️-[TSLocationManager log:message:] [RNBackgroundGeolocation startObserving]

2022-06-04 09:56:51.210 
╔═══════════════════════════════════════════════════════════
║ -[TSLocationManager start] 
╚═══════════════════════════════════════════════════════════

2022-06-04 09:56:51.210 ℹ️-[TSLocationManager doStart:] trackingMode: 1

2022-06-04 09:56:51.215 ℹ️-[TSLocationManager log:message:] [RNCustomLog] | LEVEL: debug --- startMonitoring ----> TRIP 3003 STARTED

2022-06-04 09:57:27.151 ℹ️-[TSDBLogger db_save] Log committed

2022-06-04 09:58:28.157 ℹ️-[TSDBLogger db_save] Log committed

2022-06-04 09:59:29.016 ℹ️-[TSDBLogger db_save] Log committed

2022-06-04 10:00:30.019 ℹ️-[TSDBLogger db_save] Log committed

2022-06-04 10:00:35.078 ℹ️-[TSDBLogger db_delete] maxAge: 604800

2022-06-04 10:01:30.163 ℹ️-[TSDBLogger db_save] Log committed

2022-06-04 10:02:31.151 ℹ️-[TSDBLogger db_save] Log committed

2022-06-04 10:03:32.008 ℹ️-[TSDBLogger db_save] Log committed

2022-06-04 10:04:33.015 ℹ️-[TSDBLogger db_save] Log committed

2022-06-04 10:05:34.003 ℹ️-[TSDBLogger db_save] Log committed

2022-06-04 10:05:35.095 ℹ️-[TSDBLogger db_delete] maxAge: 604800

2022-06-04 10:06:34.997 ℹ️-[TSDBLogger db_save] Log committed

2022-06-04 10:07:35.155 ℹ️-[TSDBLogger db_save] Log committed

2022-06-04 10:08:24.571 ℹ️-[TSLocationManager log:message:] [RNCustomLog] | LEVEL: debug --- listenStopAutomaticMonitoring ----> BLUETOOTH - BT stop Callback!

2022-06-04 10:08:24.609 ℹ️-[TSLocationManager log:message:] [RNCustomLog] | LEVEL: debug --- startMonitoring ----> TRIP STOPPING - BEFORE endTrip!, tripId: 3003

2022-06-04 10:08:24.615 ℹ️-[TSLocationManager log:message:] [RNBackgroundGeolocation stopObserving]

2022-06-04 10:08:24.615 
╔═══════════════════════════════════════════════════════════
║ -[TSLocationManager stop] 
╚═══════════════════════════════════════════════════════════

2022-06-04 10:08:24.616 ℹ️-[TSLocationManager clearLastOdometerLocation] 

2022-06-04 10:08:24.617 🔴-[TSGeofenceManager stop] 

2022-06-04 10:08:24.617 🔴-[TSGeofenceManager stopMonitoringGeofences] 

2022-06-04 10:08:24.618 🔴-[TSLocationManager stopUpdatingLocation] 

2022-06-04 10:08:24.618 🔴-[TSLocationManager stopMonitoringBackgroundFetch] BackgroundFetch: OFF

2022-06-04 10:08:24.618 🔴-[TSLocationManager stopMonitoringSignificantLocationChanges] 

2022-06-04 10:08:24.628 ℹ️-[TSLocationManager log:message:] [RNCustomLog] | LEVEL: debug --- fetchTripData ----> tripId: 3003 - locations length: 0 | trip length: 0

2022-06-04 10:08:32.082 ℹ️-[TSLocationManager log:message:] [RNCustomLog] | LEVEL: debug --- finishTrip ----> FINISHED TRIP: 3003 - endTrip -> true

2022-06-04 10:08:32.093 ℹ️-[TSLocationManager log:message:] [RNCustomLog] | LEVEL: debug --- stopMonitoring ----> TRIP 3003 STOPPED!

giulianogiannico-vidiemme avatar Jun 06 '22 10:06 giulianogiannico-vidiemme

autosync false? not sure how things will go from device to server if you don't have some sync configured, I think that might be it also I think the version is out of date - 4.7.1 is current here

mikehardy avatar Jun 06 '22 13:06 mikehardy

autosync false? not sure how things will go from device to server if you don't have some sync configured, I think that might be it also I think the version is out of date - 4.7.1 is current here

Yes, autosync flag is set to false due to business requirements. It seems that library didn't logged location updates and/or heartbeat intervals.

giulianogiannico-vidiemme avatar Jun 06 '22 13:06 giulianogiannico-vidiemme

Here's the logs I see when executing .start(). Are you sure you're using LOG_LEVEL_VERBOSE?

022-06-06 10:01:54.158049-0400 BG Geo[1014:45625] 
╔═══════════════════════════════════════════════════════════
║ -[TSLocationManager start] 
╚═══════════════════════════════════════════════════════════
2022-06-06 10:01:54.158292-0400 BG Geo[1014:45625] ℹ️-[TSLocationManager doStart:] trackingMode: 1
2022-06-06 10:01:54.158433-0400 BG Geo[1014:45625] ℹ️-[TSConfig persist]
2022-06-06 10:01:54.165093-0400 BG Geo[1014:44786]  [enabledchange] - true
2022-06-06 10:01:54.166950-0400 BG Geo[1014:45625] 🎾-[TSGeofenceManager start]
2022-06-06 10:01:54.167164-0400 BG Geo[1014:44786]  [connectivitychange] - [ConnectivityChangeEvent connected: true]
2022-06-06 10:01:54.170651-0400 BG Geo[1014:44786]  [location] - [Location {coords: {speed_accuracy: -1.0, speed: -1.0, longitude: -73.60048384426705, floor: 2146959360, heading_accuracy: -1.0, latitude: 45.51885986328125, accuracy: 35.0, altitude_accuracy: 13.9, altitude: 83.2, heading: -1.0}, sample: true, timestampMeta: {systemTime: 1654524114170, time: 1654524100300, systemClockElapsedRealtime: 3851000}, is_moving: false, extras: {foo: bar}, odometer: 32711885.6, uuid: D7030FAA-1A2D-4064-A441-09CC1FA21D46, activity: {type: still, confidence: 100}, battery: {level: -1.0, is_charging: false}, timestamp: 2022-06-06T14:01:40.300Z}]
2022-06-06 10:01:54.171445-0400 BG Geo[1014:45627] 🎾-[SOMotionDetector startDetection]
2022-06-06 10:01:54.172250-0400 BG Geo[1014:45625] 🔵-[TSLocationManager setPace:] 0
2022-06-06 10:01:54.172649-0400 BG Geo[1014:45625] 🎾-[TSLocationManager startUpdatingLocation] Location-services: ON
2022-06-06 10:01:54.172900-0400 BG Geo[1014:44786]  [start] success: [State enabled: true, isMoving: false, trackingMode: 1, desiredAccuracy: -1, distanceFilter: 50.0, odometer: 32711885.550896674, schedulerEnabled: true, foregroundService: null]
2022-06-06 10:01:54.172974-0400 BG Geo[1014:45625] 
╔═══════════════════════════════════════════════════════════
║ -[TSHttpService flush:] 
╚═══════════════════════════════════════════════════════════
2022-06-06 10:01:54.173975-0400 BG Geo[1014:44843] 
╔═══════════════════════════════════════════════════════════
║ -[TSHttpService finish:error:] Success: 1
╚═══════════════════════════════════════════════════════════
2022-06-06 10:01:54.179191-0400 BG Geo[1014:45627] ℹ️+[LocationAuthorization run:onCancel:] status: 3
2022-06-06 10:01:54.179530-0400 BG Geo[1014:45627] 🎾-[TSLocationManager startMonitoringBackgroundFetch] BackgroundFetch: ON
2022-06-06 10:01:54.184697-0400 BG Geo[1014:45627] ✅-[SOMotionDetector startDetection]_block_invoke Enabled M7 MotionActivity updates
2022-06-06 10:01:54.185385-0400 BG Geo[1014:45633] 
📍<+45.51886484,-73.60048384> +/- 35.00m (speed -1.00 mps / course -1.00) @ 2022-06-06, 10:01:31 AM Eastern Daylight Saving Time
2022-06-06 10:01:54.185566-0400 BG Geo[1014:44843] 
╔═══════════════════════════════════════════════════════════
║ -[TSLocationManager locationManager:didUpdateLocations:] Enabled: 1 | isMoving: 0 | df: -1.0m | age: 22.9s
╚═══════════════════════════════════════════════════════════
2022-06-06 10:01:54.185665-0400 BG Geo[1014:44843] ℹ️-[TSLocationManager locationManager:didUpdateLocations:] Received stale motionchange location.  Retrying...
2022-06-06 10:01:54.185923-0400 BG Geo[1014:45627] 
╔═══════════════════════════════════════════════════════════
║ -[TSLocationManager createMotionTypeChangedHandler]_block_invoke | still/100 | isMoving: 0
╚═══════════════════════════════════════════════════════════
2022-06-06 10:01:54.185948-0400 BG Geo[1014:44786]  [activitychange] - [ActivityChangeEvent still (100%)]
2022-06-06 10:01:54.189682-0400 BG Geo[1014:44843] 
📍<+45.51886484,-73.60048384> +/- 35.00m (speed -1.00 mps / course -1.00) @ 2022-06-06, 10:01:40 AM Eastern Daylight Saving Time
2022-06-06 10:01:54.189716-0400 BG Geo[1014:44843] 
╔═══════════════════════════════════════════════════════════
║ -[TSLocationManager locationManager:didUpdateLocations:] Enabled: 1 | isMoving: 0 | df: -1.0m | age: 13.9s
╚═══════════════════════════════════════════════════════════
2022-06-06 10:01:54.189765-0400 BG Geo[1014:45627] ℹ️-[TSLocationManager locationManager:didUpdateLocations:] Received stale motionchange location.  Retrying...
2022-06-06 10:01:54.261502-0400 BG Geo[1014:44843] 
📍<+45.51885534,-73.60049704> +/- 35.00m (speed -1.00 mps / course -1.00) @ 2022-06-06, 10:01:54 AM Eastern Daylight Saving Time
2022-06-06 10:01:54.261620-0400 BG Geo[1014:45626] 
╔═══════════════════════════════════════════════════════════
║ -[TSLocationManager locationManager:didUpdateLocations:] Enabled: 1 | isMoving: 0 | df: -1.0m | age: 0.1s
╚═══════════════════════════════════════════════════════════
2022-06-06 10:01:54.262026-0400 BG Geo[1014:45626] ✅-[TSLocationManager locationManager:didUpdateLocations:] Acquired motionchange position: <+45.51886484,-73.60048384> +/- 35.00m (speed -1.00 mps / course -1.00) @ 2022-06-06, 10:01:31 AM Eastern Daylight Saving Time
2022-06-06 10:01:54.262692-0400 BG Geo[1014:45627] 🔵-[TSLocationManager startMonitoringStationaryRegion:radius:] Radius: 60
2022-06-06 10:01:54.263793-0400 BG Geo[1014:45627] 🔴-[TSLocationManager stopUpdatingLocation]
2022-06-06 10:01:54.263933-0400 BG Geo[1014:45633] 🔵-[TSLocationManager calculateMedianLocationAccuracy:] Median location accuracy: 35.0
2022-06-06 10:01:54.264294-0400 BG Geo[1014:44786]  [motionchange] - [Location {coords: {speed_accuracy: -1.0, speed: -1.0, longitude: -73.60048384426705, floor: null, heading_accuracy: -1.0, latitude: 45.51886483618149, accuracy: 35.0, altitude_accuracy: 13.9, altitude: 83.2, heading: -1.0}, timestampMeta: {systemTime: 1654524114263, time: 1654524091300, systemClockElapsedRealtime: 3851000}, extras: {foo: bar}, is_moving: false, event: motionchange, odometer: 32711885.6, uuid: 703077A7-9949-405F-94F6-FEBEAE648C9F, activity: {type: still, confidence: 100}, battery: {level: 0.9800000190734863, is_charging: true}, timestamp: 2022-06-06T14:01:31.300Z}]
2022-06-06 10:01:54.264635-0400 BG Geo[1014:44786]  [location] - [Location {coords: {speed_accuracy: -1.0, speed: -1.0, longitude: -73.60048384426705, floor: null, heading_accuracy: -1.0, latitude: 45.51886483618149, accuracy: 35.0, altitude_accuracy: 13.9, altitude: 83.2, heading: -1.0}, timestampMeta: {systemTime: 1654524114264, time: 1654524091300, systemClockElapsedRealtime: 3851000}, extras: {foo: bar}, is_moving: false, event: motionchange, odometer: 32711885.6, uuid: 703077A7-9949-405F-94F6-FEBEAE648C9F, activity: {type: still, confidence: 100}, battery: {level: 0.9800000190734863, is_charging: true}, timestamp: 2022-06-06T14:01:31.300Z}]
2022-06-06 10:01:54.266712-0400 BG Geo[1014:44843] ✅-[TSLocationManager persistLocation:]_block_invoke INSERT: 703077A7-9949-405F-94F6-FEBEAE648C9F
2022-06-06 10:01:54.267512-0400 BG Geo[1014:45627] 
╔═══════════════════════════════════════════════════════════
║ -[TSHttpService flush:] 
╚═══════════════════════════════════════════════════════════
2022-06-06 10:01:54.275719-0400 BG Geo[1014:45645] ✅-[BackgroundTaskManager createBackgroundTask] 10
2022-06-06 10:01:54.275843-0400 BG Geo[1014:45645] ✅-[TSHttpService schedulePost] LOCKED: 703077A7-9949-405F-94F6-FEBEAE648C9F
2022-06-06 10:01:55.319171-0400 BG Geo[1014:45645] 🔵-[HttpResponse handleResponse] Response: 200
2022-06-06 10:01:55.326517-0400 BG Geo[1014:45625] ✅-[TSHttpService post:]_block_invoke DESTROY: 703077A7-9949-405F-94F6-FEBEAE648C9F
2022-06-06 10:01:55.326988-0400 BG Geo[1014:45625] 
╔═══════════════════════════════════════════════════════════
║ -[TSHttpService finish:error:] Success: 1
╚═══════════════════════════════════════════════════════════
2022-06-06 10:01:55.327095-0400 BG Geo[1014:45625] ✅-[BackgroundTaskManager stopBackgroundTask:]_block_invoke 10 OF (
    10
)
2022-06-06 10:01:55.327967-0400 BG Geo[1014:44786]  [http] - [HttpEvent {success: true, status: 200, responseText: {"success":true}}]

christocracy avatar Jun 06 '22 14:06 christocracy

And here's my logs for calling .start() with {autoSync: false, preventSuspend: true}:

2022-06-06 10:05:25.440318-0400 BG Geo[1014:46588] 
╔═══════════════════════════════════════════════════════════
║ -[TSLocationManager start] 
╚═══════════════════════════════════════════════════════════
2022-06-06 10:05:25.440396-0400 BG Geo[1014:46588] ℹ️-[TSLocationManager doStart:] trackingMode: 1
2022-06-06 10:05:25.440463-0400 BG Geo[1014:46588] ℹ️-[TSConfig persist]
2022-06-06 10:05:25.441769-0400 BG Geo[1014:44786]  [enabledchange] - true
2022-06-06 10:05:25.441806-0400 BG Geo[1014:46769] 🎾-[TSGeofenceManager start]
2022-06-06 10:05:25.442997-0400 BG Geo[1014:44786]  [connectivitychange] - [ConnectivityChangeEvent connected: true]
2022-06-06 10:05:25.443300-0400 BG Geo[1014:46588] 🎾-[SOMotionDetector startDetection]
2022-06-06 10:05:25.443349-0400 BG Geo[1014:46769] 🔵-[TSLocationManager setPace:] 0
2022-06-06 10:05:25.445382-0400 BG Geo[1014:44786]  [location] - [Location {coords: {speed_accuracy: -1.0, speed: -1.0, longitude: -73.60053144768699, floor: 2146959360, heading_accuracy: -1.0, latitude: 45.51873779296875, accuracy: 35.0, altitude_accuracy: 16.4, altitude: 84.4, heading: -1.0}, sample: true, timestampMeta: {systemTime: 1654524325444, time: 1654524325444, systemClockElapsedRealtime: 4062000}, is_moving: false, extras: {foo: bar}, odometer: 32711885.6, uuid: DC3F0798-38E3-4E26-9026-4D0F514A5292, activity: {type: still, confidence: 33}, battery: {level: -1.0, is_charging: false}, timestamp: 2022-06-06T14:05:25.444Z}]
2022-06-06 10:05:25.446501-0400 BG Geo[1014:46588] 🎾-[TSLocationManager startUpdatingLocation] Location-services: ON
2022-06-06 10:05:25.448881-0400 BG Geo[1014:44786]  [start] success: [State enabled: true, isMoving: false, trackingMode: 1, desiredAccuracy: -1, distanceFilter: 50.0, odometer: 32711885.550896674, schedulerEnabled: true, foregroundService: null]
2022-06-06 10:05:25.453815-0400 BG Geo[1014:46769] ℹ️+[LocationAuthorization run:onCancel:] status: 3
2022-06-06 10:05:25.453916-0400 BG Geo[1014:46787] 🎾-[TSLocationManager startMonitoringBackgroundFetch] BackgroundFetch: ON
2022-06-06 10:05:25.459785-0400 BG Geo[1014:46787] ✅-[SOMotionDetector startDetection]_block_invoke Enabled M7 MotionActivity updates
2022-06-06 10:05:25.460988-0400 BG Geo[1014:46986] 
📍<+45.51875027,-73.60053145> +/- 35.00m (speed -1.00 mps / course -1.00) @ 2022-06-06, 10:05:23 AM Eastern Daylight Saving Time
2022-06-06 10:05:25.461060-0400 BG Geo[1014:46787] 
╔═══════════════════════════════════════════════════════════
║ -[TSLocationManager locationManager:didUpdateLocations:] Enabled: 1 | isMoving: 0 | df: -1.0m | age: 1.6s
╚═══════════════════════════════════════════════════════════
2022-06-06 10:05:25.461362-0400 BG Geo[1014:47101] ✅-[TSLocationManager locationManager:didUpdateLocations:] Acquired motionchange position: <+45.51875027,-73.60053145> +/- 35.00m (speed -1.00 mps / course -1.00) @ 2022-06-06, 10:05:23 AM Eastern Daylight Saving Time
2022-06-06 10:05:25.461959-0400 BG Geo[1014:46986] 🔵-[TSLocationManager startMonitoringStationaryRegion:radius:] Radius: 60
2022-06-06 10:05:25.462761-0400 BG Geo[1014:47101] 🔵-[TSLocationManager beginHeartbeat] 900
2022-06-06 10:05:25.462835-0400 BG Geo[1014:46986] 🔴-[TSLocationManager stopUpdatingLocation]
2022-06-06 10:05:25.463016-0400 BG Geo[1014:47101] 🔵-[TSLocationManager calculateMedianLocationAccuracy:] Median location accuracy: 35.0
2022-06-06 10:05:25.463393-0400 BG Geo[1014:44786]  [motionchange] - [Location {coords: {speed_accuracy: -1.0, speed: -1.0, longitude: -73.60053144768699, floor: null, heading_accuracy: -1.0, latitude: 45.51875026737692, accuracy: 35.0, altitude_accuracy: 16.4, altitude: 84.4, heading: -1.0}, timestampMeta: {systemTime: 1654524325463, time: 1654524323906, systemClockElapsedRealtime: 4062000}, extras: {foo: bar}, is_moving: false, event: motionchange, odometer: 32711885.6, uuid: 00E3CB74-8C2C-428C-902D-68F84468C4C0, activity: {type: still, confidence: 100}, battery: {level: 1.0, is_charging: true}, timestamp: 2022-06-06T14:05:23.907Z}]
2022-06-06 10:05:25.463776-0400 BG Geo[1014:44786]  [location] - [Location {coords: {speed_accuracy: -1.0, speed: -1.0, longitude: -73.60053144768699, floor: null, heading_accuracy: -1.0, latitude: 45.51875026737692, accuracy: 35.0, altitude_accuracy: 16.4, altitude: 84.4, heading: -1.0}, timestampMeta: {systemTime: 1654524325463, time: 1654524323906, systemClockElapsedRealtime: 4062000}, extras: {foo: bar}, is_moving: false, event: motionchange, odometer: 32711885.6, uuid: 00E3CB74-8C2C-428C-902D-68F84468C4C0, activity: {type: still, confidence: 100}, battery: {level: 1.0, is_charging: true}, timestamp: 2022-06-06T14:05:23.907Z}]
2022-06-06 10:05:25.464570-0400 BG Geo[1014:47101] 
╔═══════════════════════════════════════════════════════════
║ -[TSLocationManager createMotionTypeChangedHandler]_block_invoke | still/100 | isMoving: 0
╚═══════════════════════════════════════════════════════════
2022-06-06 10:05:25.466917-0400 BG Geo[1014:44786]  [activitychange] - [ActivityChangeEvent still (100%)]
2022-06-06 10:05:25.470469-0400 BG Geo[1014:46588] ✅-[BackgroundTaskManager createBackgroundTask] 13
2022-06-06 10:05:25.470613-0400 BG Geo[1014:46787] ✅-[TSLocationManager persistLocation:]_block_invoke INSERT: 00E3CB74-8C2C-428C-902D-68F84468C4C0
2022-06-06 10:05:39.240998-0400 BG Geo[1014:46787] ℹ️-[TSDBLogger db_save] Log committed

christocracy avatar Jun 06 '22 14:06 christocracy

Here's the logs I see when executing .start(). Are you sure you're using LOG_LEVEL_VERBOSE?

Yes, I'm pretty sure 😕

giulianogiannico-vidiemme avatar Jun 06 '22 14:06 giulianogiannico-vidiemme

Execute the method .emailLog(yourEmailAddress). Attach the received log-file here (as a file attachment)

christocracy avatar Jun 06 '22 15:06 christocracy

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions. You may also mark this issue as a "discussion" and I will leave this open.

stale[bot] avatar Sep 21 '22 03:09 stale[bot]