search

OpenTracksApp / OpenTracks

OpenTracks is a sport tracking application that completely respects your privacy.
https://OpenTracksApp.com
Apache License 2.0
1.01k stars 189 forks source link

Stopped in the middle of a workout #1151

Closed brianjmurrell closed 2 years ago

brianjmurrell commented 2 years ago

Describe the bug First time using OpenTracks (so no idea of frequency or reproducibiliy although statistically I guess it's 100% of the time so far :smile:) I was walking on a treadmill with a Tickr X connected to OpenTracks. Everything was going really well until OpenTracks simply suddenly stopped recording -- as if I'd hit (and held, as one is required to do -- which simply didn't happen as the phone was sitting on the console of a treadmill at the time) the stop button. I had to quickly press start again to create a new activity while I was on the Treadmill. Unfortunately now I have two activities for what was actually just a single workout.

To Reproduce Basic OpenTracks BLE sensor pairing and starting an activity.

Technical information

I'm really hoping this was a once-in-a-lifetime anomaly, but as a software engineer I know that is not likely. :-(

I wish I had logcat output, but my phone was not logcatting anywhere at the time. It typically isn't. And I had 80% more of my workout to complete so I couldn't stop and try to grab what was in the buffer when it happened.

brianjmurrell commented 2 years ago

As an aside, is this what "Resume track" in a track's menu is for? Would that have at least added the second activity to the first and kept it all in one activity?

FWIW, I find this issue quite disturbing as I only happened to notice it happened because my phone was sitting right in front of me on a treadmill console. Had I been outdoors with my phone in my pocket, I would have never noticed and would have lost 80% of my activity data.

dennisguse commented 2 years ago

Was you screen on the whole time? And did you have a GPS signal or just the sensor? Sounds like a race condition in the UI code (some kind of null pointer?). So, running with display off should be fine (recent personal experience) :)

PS/ resume track allows to continue the recording if it was stopped or OpenTracks crashed.

@brianjmurrell Can you add the Tickr X to https://github.com/OpenTracksApp/OpenTracks/blob/main/README_TESTED_SENSORS.md?

brianjmurrell commented 2 years ago

Was you screen on the whole time?

Indeed. I did have the option to keep the screen on enabled.

And did you have a GPS signal or just the sensor?

Just the sensor as it was indoors on the treadmill.

Sounds like a race condition in the UI code (some kind of null pointer?).

What's the best way to hunt that sort of thing down?

So, running with display off should be fine (recent personal experience) :)

What prevents Android from killing the app as being idle when the screen is off?

That said, I like keeping the screen on as I am heart-rate-zone-targeting so I like keeping an eye on my heart rate.

And that said, heart-rate-zone targeting/display in the app would be a nice feature. Other apps I have used for example show the heart-rate on a graph with time on the x-axis, the heart-rate on the y-axis and the graph shaded for each zone.

PS/ resume track allows to continue the recording if it was stopped or OpenTracks crashed.

I had wondered (after the fact) if that's what Resume track was all about.

@brianjmurrell Can you add the Tickr X to https://github.com/OpenTracksApp/OpenTracks/blob/main/README_TESTED_SENSORS.md?

I can. I wasn't sure if more went into calling a sensor tested other than just that somebody used one (somewhat) successfully.

When I paired the Tickr X, it showed as being available for Heart rate, Distance, Speed, and Cadence, and all of those show under the "Running" section of the Bluetooth Sensors page. When I am on the treadmill with the HRM it does seem to read heart rate and speed but shows nothing for cadence.

brianjmurrell commented 2 years ago

I had this happen twice in an outdoor (so with GPS) walk today with the screen turned off.

Fortunately I caught it quite quickly so the gaps in the track are relatively small.

But still, only because I noticed it.

dennisguse commented 2 years ago

Then I need a logcat...

You can set the logcat buffer to 16M (that's what I use), then the device stores several hours of logs. Kind of convenient if you are actually using OpenTracks and it crashes.

PS/ let's move the Tickr discussion to your PR.

brianjmurrell commented 2 years ago

Just did an outdoor walk with GPS. Screen was left on the main display and no map screen was present. App stopped twice. I have a huge logcat but obviously cannot post/paste it anywhere.

What am I looking to extract from it for you?

When the app stopped, both times I did restart it and resumed the track, so I don't even know precisely what time it stopped to go logcat spelunking.

dennisguse commented 2 years ago

Nice work!

You can filter by packe (I.e. opentracks) and then check for a an exception. Might be a nullpointer.

dennisguse commented 2 years ago

And, I guess, you can filter by log level error.

brianjmurrell commented 2 years ago

This perhaps:

03-29 14:35:23.204 30566 30566 E AndroidRuntime: FATAL EXCEPTION: main
03-29 14:35:23.204 30566 30566 E AndroidRuntime: Process: de.dennisguse.opentracks.debug, PID: 30566
03-29 14:35:23.204 30566 30566 E AndroidRuntime: java.lang.RuntimeException: Moving time cannot be negative
03-29 14:35:23.204 30566 30566 E AndroidRuntime:        at de.dennisguse.opentracks.stats.TrackStatistics.addMovingTime(TrackStatistics.java:241)
03-29 14:35:23.204 30566 30566 E AndroidRuntime:        at de.dennisguse.opentracks.stats.TrackStatistics.addMovingTime(TrackStatistics.java:235)
03-29 14:35:23.204 30566 30566 E AndroidRuntime:        at de.dennisguse.opentracks.stats.TrackStatisticsUpdater.addTrackPoint(TrackStatisticsUpdater.java:177)
03-29 14:35:23.204 30566 30566 E AndroidRuntime:        at de.dennisguse.opentracks.services.TrackRecordingManager.insertTrackPointHelper(TrackRecordingManager.java:243)
03-29 14:35:23.204 30566 30566 E AndroidRuntime:        at de.dennisguse.opentracks.services.TrackRecordingManager.insertTrackPoint(TrackRecordingManager.java:237)
03-29 14:35:23.204 30566 30566 E AndroidRuntime:        at de.dennisguse.opentracks.services.TrackRecordingManager.onNewTrackPoint(TrackRecordingManager.java:204)
03-29 14:35:23.204 30566 30566 E AndroidRuntime:        at de.dennisguse.opentracks.services.TrackRecordingService.newTrackPoint(TrackRecordingService.java:298)
03-29 14:35:23.204 30566 30566 E AndroidRuntime:        at de.dennisguse.opentracks.services.handlers.TrackPointCreator.onNewTrackPoint(TrackPointCreator.java:128)
03-29 14:35:23.204 30566 30566 E AndroidRuntime:        at de.dennisguse.opentracks.services.handlers.GPSHandler.onLocationChanged(GPSHandler.java:130)
03-29 14:35:23.204 30566 30566 E AndroidRuntime:        at android.location.LocationManager$LocationListenerTransport.acceptLocation(LocationManager.java:2745)
03-29 14:35:23.204 30566 30566 E AndroidRuntime:        at android.location.LocationManager$LocationListenerTransport.lambda$enkW18B0WwpQkSIMmVChmQ2YwC8(Unknown Source:0)
03-29 14:35:23.204 30566 30566 E AndroidRuntime:        at android.location.-$$Lambda$LocationManager$LocationListenerTransport$enkW18B0WwpQkSIMmVChmQ2YwC8.accept(Unknown Source:6)
03-29 14:35:23.204 30566 30566 E AndroidRuntime:        at com.android.internal.util.function.pooled.PooledLambdaImpl.doInvoke(PooledLambdaImpl.java:292)
03-29 14:35:23.204 30566 30566 E AndroidRuntime:        at com.android.internal.util.function.pooled.PooledLambdaImpl.invoke(PooledLambdaImpl.java:201)
03-29 14:35:23.204 30566 30566 E AndroidRuntime:        at com.android.internal.util.function.pooled.OmniFunction.run(OmniFunction.java:97)
03-29 14:35:23.204 30566 30566 E AndroidRuntime:        at android.os.Handler.handleCallback(Handler.java:938)
03-29 14:35:23.204 30566 30566 E AndroidRuntime:        at android.os.Handler.dispatchMessage(Handler.java:99)
03-29 14:35:23.204 30566 30566 E AndroidRuntime:        at android.os.Looper.loop(Looper.java:223)
03-29 14:35:23.204 30566 30566 E AndroidRuntime:        at android.app.ActivityThread.main(ActivityThread.java:7664)
03-29 14:35:23.204 30566 30566 E AndroidRuntime:        at java.lang.reflect.Method.invoke(Native Method)
03-29 14:35:23.204 30566 30566 E AndroidRuntime:        at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:592)
03-29 14:35:23.204 30566 30566 E AndroidRuntime:        at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:947)
03-29 14:35:23.212  1013  4244 I DropBoxManagerService: add tag=data_app_crash isTagEnabled=true flags=0x2
03-29 14:35:23.213  1013  2263 W ActivityTaskManager:   Force finishing activity de.dennisguse.opentracks.debug/de.dennisguse.opentracks.TrackRecordingActivity
03-29 14:35:23.234  1013  2263 W ActivityTaskManager:   Force finishing activity de.dennisguse.opentracks.debug/de.dennisguse.opentracks.TrackListActivity
brianjmurrell commented 2 years ago

For my own purposes and any one else's, it helps to search for the [re-]start of the app with:

START u0 \{act=android\.intent\.action\.MAIN cat=\[android\.intent\.category\.LAUNCHER\] flg=0x10200000 cmp=de\.dennisguse\.opentracks\.debug\/de\.dennisguse\.opentracks\.TrackListActivity

You should remove the \.debug for searching in the official, signed app.

dennisguse commented 2 years ago

That fits and it is kind of critical.

Note: the crash occurred due to a reported GPS location, so this should not happen indoors. So, there might be a 2nd problem that happens indoor (aka without GPS).

Background: We are using the real-time clock (relative time to device startup) and this should be monotonic (see MonotonicClock).

So, this should not happen.

If it does, there might be some reasons:

@brianjmurrell Can you modify the code when this exceptions is triggered to include the two timestamps and the new TrackPoint that is going to is processed? Might be helpful to debug.

brianjmurrell commented 2 years ago

I'm looking at the code, but what do you mean Include the two timestamps and the new TrackPoint how exactly?

dennisguse commented 2 years ago

Modifying this to

    public void addMovingTime(TrackPoint trackPoint, TrackPoint lastTrackPoint) {
        addMovingTime(Duration.between(lastTrackPoint.getTime(), trackPoint.getTime()));
    }

to 

    public void addMovingTime(TrackPoint trackPoint, TrackPoint lastTrackPoint) {
        try {
            addMovingTime(Duration.between(lastTrackPoint.getTime(), trackPoint.getTime()));
        } catch (RuntimeException e) {
            throw new RuntimeException("LastTrackPoint: " + lastTrackPoint + "\nTrackPoint: " + trackPoint, e);
        }
    }
brianjmurrell commented 2 years ago

Oh duh. I see. You meant adding that info to the exception. Patching and building it right now.

Just for temporary app stability, what if instead of throwing an exception (and killing the app), could we log the "LastTrackPoint: " + lastTrackPoint + "\nTrackPoint: " + trackPoint, e and skip adding any moving time and continue on in the app? Surely the missing moving time there is less harmful to the overall data than having a complete gap while the app has to be restarted and the track resumed, yes?

I'm just not sure what the alternative to the exception is to simply log. Not much of an Android developer here.

Also not sure if simply not adding to the movingTime would have any ripple effects or not.

dennisguse commented 2 years ago

Yeah, we could - actually the exception is rather new and in umasked some nasty issues like jumping GPS time and Android clock. Then I though we fixed everything using the MonotonicClock and now we found seem to have another bug. Having this exception allows us to also see rare errors that might be masked nicely if the app would not be crashing. If we find a problem that is unfixable, I will gladly revert back to just ignore the data aka `return' instead of the exception.

PS/ it just messes up the statistics nothing else.

brianjmurrell commented 2 years ago

So what would the alternative code to log instead of throwing an exception be?

    public void addMovingTime(TrackPoint trackPoint, TrackPoint lastTrackPoint) {
        try {
            addMovingTime(Duration.between(lastTrackPoint.getTime(), trackPoint.getTime()));
        } catch (RuntimeException e) {
            Log.i("opentracks", e + ": LastTrackPoint: " + lastTrackPoint + "\nTrackPoint: " + trackPoint, e);
        }
    }

Can I just use Log there or do I have to import it or somesuch?

brianjmurrell commented 2 years ago

PS/ it just messes up the statistics nothing else.

Messes up as in just loses the move accounting of that particular track point? Or does it cause further consistency errors elsewhere? I.e. Is it any worse than the app having crashed and so missing all data for the period of time it takes to start up again and resume the track?

If it's simply that the moving time is less by the amount that was not calculated in that sample, that is fine. That I think ultimately is a smaller data loss than not tracking anything while the app is restarted, assuming it's noticed to have even stopped in a quick manner.

brianjmurrell commented 2 years ago

Got some new data. OpenTracks stopped only a few minutes into a walk and I never noticed. This is what I was fearing would happen.

Anyway, from logcat:

03-31 16:39:07.591 20611 27265 D BluetoothConnectionManager: Received data from E5:F7:CA:AB:CD:EF
03-31 16:39:07.591 20611 28467 D BluetoothConnectionManager: Received data from E5:F7:CA:AB:CD:EF
03-31 16:39:07.591 20611 26888 D BluetoothConnectionManager: Received data from E5:F7:CA:AB:CD:EF
03-31 16:39:07.592 20611 26886 D BluetoothConnectionManager: Received data from E5:F7:CA:AB:CD:EF
03-31 16:39:07.593 20611 28467 I opentracks: cadence read: 124.0
03-31 16:39:07.593 20611 26888 D BluetoothConnectionManager: Decoded data from E5:F7:CA:AB:CD:EF: sensorAddress='E5:F7:CA:AB:CD:EF heart=HeartRate{value=92.0 bpm}
03-31 16:39:07.593 20611 28467 D BluetoothConnectionManager: Decoded data from E5:F7:CA:AB:CD:EF: sensorAddress='E5:F7:CA:AB:CD:EF
03-31 16:39:07.593 20611 28467 D BluetoothRemoteSensorManager: Previous: sensorAddress='E5:F7:CA:AB:CD:EF; CurrentsensorAddress='E5:F7:CA:AB:CD:EF
03-31 16:39:07.593 20611 26888 D TrackRecordingManager: Not recording TrackPoint
03-31 16:39:07.594 20611 27265 D BluetoothConnectionManager: Decoded data from E5:F7:CA:AB:CD:EF: sensorAddress='E5:F7:CA:AB:CD:EF heart=HeartRate{value=92.0 bpm}
03-31 16:39:07.595 20611 26886 I opentracks: cadence read: 124.0
03-31 16:39:07.595 20611 26886 D BluetoothConnectionManager: Decoded data from E5:F7:CA:AB:CD:EF: sensorAddress='E5:F7:CA:AB:CD:EF
03-31 16:39:07.599 20611 26886 D BluetoothRemoteSensorManager: Previous: sensorAddress='E5:F7:CA:AB:CD:EF; CurrentsensorAddress='E5:F7:CA:AB:CD:EF
03-31 16:39:07.599 20611 28467 D TrackRecordingManager: Not recording TrackPoint
03-31 16:39:07.626   789  2876 I vendor.qti.bluetooth@1.0-ibs_handler: ProcessIbsCmd: Received IBS_SLEEP_IND: 0xFE
03-31 16:39:07.626   789  2876 D vendor.qti.bluetooth@1.0-ibs_handler: SerialClockVote: vote for UART CLK OFF
03-31 16:39:07.652 20611 20611 D AndroidRuntime: Shutting down VM
03-31 16:39:07.653 20611 26886 W BluetoothGatt: Unhandled exception in callback
03-31 16:39:07.653 20611 26886 W BluetoothGatt: java.lang.SecurityException: Permission Denial: writing de.dennisguse.opentracks.data.ShareContentProvider uri content://de.dennisguse.opentracks.debug.content/trackpoints from pid=0, uid=1002 requires the provider be exported, or grantUriPermission()
03-31 16:39:07.653 20611 26886 W BluetoothGatt:     at android.content.ContentProvider.enforceWritePermissionInner(ContentProvider.java:896)
03-31 16:39:07.653 20611 26886 W BluetoothGatt:     at android.content.ContentProvider$Transport.enforceWritePermission(ContentProvider.java:696)
03-31 16:39:07.653 20611 26886 W BluetoothGatt:     at android.content.ContentProvider$Transport.insert(ContentProvider.java:322)
03-31 16:39:07.653 20611 26886 W BluetoothGatt:     at android.content.ContentResolver.insert(ContentResolver.java:2149)
03-31 16:39:07.653 20611 26886 W BluetoothGatt:     at android.content.ContentResolver.insert(ContentResolver.java:2111)
03-31 16:39:07.653 20611 26886 W BluetoothGatt:     at de.dennisguse.opentracks.data.ContentProviderUtils.insertTrackPoint(ContentProviderUtils.java:713)
03-31 16:39:07.653 20611 26886 W BluetoothGatt:     at de.dennisguse.opentracks.services.TrackRecordingManager.insertTrackPointHelper(TrackRecordingManager.java:242)
03-31 16:39:07.653 20611 26886 W BluetoothGatt:     at de.dennisguse.opentracks.services.TrackRecordingManager.insertTrackPoint(TrackRecordingManager.java:237)
03-31 16:39:07.653 20611 26886 W BluetoothGatt:     at de.dennisguse.opentracks.services.TrackRecordingManager.onNewTrackPoint(TrackRecordingManager.java:204)
03-31 16:39:07.653 20611 26886 W BluetoothGatt:     at de.dennisguse.opentracks.services.TrackRecordingService.newTrackPoint(TrackRecordingService.java:298)
03-31 16:39:07.653 20611 26886 W BluetoothGatt:     at de.dennisguse.opentracks.services.handlers.TrackPointCreator.onNewTrackPoint(TrackPointCreator.java:128)
03-31 16:39:07.653 20611 26886 W BluetoothGatt:     at de.dennisguse.opentracks.services.handlers.TrackPointCreator.onChange(TrackPointCreator.java:122)
03-31 16:39:07.653 20611 26886 W BluetoothGatt:     at de.dennisguse.opentracks.sensors.BluetoothRemoteSensorManager.onChanged(BluetoothRemoteSensorManager.java:213)
03-31 16:39:07.653 20611 26886 W BluetoothGatt:     at de.dennisguse.opentracks.sensors.BluetoothConnectionManager$1.onCharacteristicChanged(BluetoothConnectionManager.java:114)
03-31 16:39:07.653 20611 26886 W BluetoothGatt:     at android.bluetooth.BluetoothGatt$1$8.run(BluetoothGatt.java:478)
03-31 16:39:07.653 20611 26886 W BluetoothGatt:     at android.bluetooth.BluetoothGatt.runOrQueueCallback(BluetoothGatt.java:780)
03-31 16:39:07.653 20611 26886 W BluetoothGatt:     at android.bluetooth.BluetoothGatt.access$200(BluetoothGatt.java:41)
03-31 16:39:07.653 20611 26886 W BluetoothGatt:     at android.bluetooth.BluetoothGatt$1.onNotify(BluetoothGatt.java:472)
03-31 16:39:07.653 20611 26886 W BluetoothGatt:     at android.bluetooth.IBluetoothGattCallback$Stub.onTransact(IBluetoothGattCallback.java:306)
03-31 16:39:07.653 20611 26886 W BluetoothGatt:     at android.os.Binder.execTransactInternal(Binder.java:1159)
03-31 16:39:07.653 20611 26886 W BluetoothGatt:     at android.os.Binder.execTransact(Binder.java:1123)
03-31 16:39:07.654 20611 20611 E AndroidRuntime: FATAL EXCEPTION: main
03-31 16:39:07.654 20611 20611 E AndroidRuntime: Process: de.dennisguse.opentracks.debug, PID: 20611
03-31 16:39:07.654 20611 20611 E AndroidRuntime: java.lang.RuntimeException: LastTrackPoint: TrackPoint{id=null, time=2022-03-31T20:39:07.593Z, latitude=null, longitude=null, horizontalAccuracy=null, altitude=null, speed=Speed{speed_mps=1.59375}, bearing=null, sensorDistance=Distance{distance_m=7.699999999999989}, type=SENSORPOINT(2), heartRate_bpm=HeartRate{value=92.0 bpm}, cadence_rpm=Cadence{value=124.0 rpm}, power=null, altitudeGain_m=null, altitudeLoss_m=null}
03-31 16:39:07.654 20611 20611 E AndroidRuntime: TrackPoint: TrackPoint{id=null, time=2022-03-31T20:39:07.591Z, latitude=[redacted], longitude=[redacted], horizontalAccuracy=Distance{distance_m=9.648000717163086}, altitude=Altitude{altitude_m=67.6724853515625WGS84}, speed=Speed{speed_mps=1.58984375}, bearing=null, sensorDistance=Distance{distance_m=2.3000000000000114}, type=TRACKPOINT(0), heartRate_bpm=HeartRate{value=92.0 bpm}, cadence_rpm=Cadence{value=124.0 rpm}, power=null, altitudeGain_m=null, altitudeLoss_m=null}
03-31 16:39:07.654 20611 20611 E AndroidRuntime:    at de.dennisguse.opentracks.stats.TrackStatistics.addMovingTime(TrackStatistics.java:238)
03-31 16:39:07.654 20611 20611 E AndroidRuntime:    at de.dennisguse.opentracks.stats.TrackStatisticsUpdater.addTrackPoint(TrackStatisticsUpdater.java:177)
03-31 16:39:07.654 20611 20611 E AndroidRuntime:    at de.dennisguse.opentracks.services.TrackRecordingManager.insertTrackPointHelper(TrackRecordingManager.java:243)
03-31 16:39:07.654 20611 20611 E AndroidRuntime:    at de.dennisguse.opentracks.services.TrackRecordingManager.insertTrackPoint(TrackRecordingManager.java:237)
03-31 16:39:07.654 20611 20611 E AndroidRuntime:    at de.dennisguse.opentracks.services.TrackRecordingManager.onNewTrackPoint(TrackRecordingManager.java:204)
03-31 16:39:07.654 20611 20611 E AndroidRuntime:    at de.dennisguse.opentracks.services.TrackRecordingService.newTrackPoint(TrackRecordingService.java:298)
03-31 16:39:07.654 20611 20611 E AndroidRuntime:    at de.dennisguse.opentracks.services.handlers.TrackPointCreator.onNewTrackPoint(TrackPointCreator.java:128)
03-31 16:39:07.654 20611 20611 E AndroidRuntime:    at de.dennisguse.opentracks.services.handlers.GPSHandler.onLocationChanged(GPSHandler.java:130)
03-31 16:39:07.654 20611 20611 E AndroidRuntime:    at android.location.LocationManager$LocationListenerTransport.acceptLocation(LocationManager.java:2745)
03-31 16:39:07.654 20611 20611 E AndroidRuntime:    at android.location.LocationManager$LocationListenerTransport.lambda$enkW18B0WwpQkSIMmVChmQ2YwC8(Unknown Source:0)
03-31 16:39:07.654 20611 20611 E AndroidRuntime:    at android.location.-$$Lambda$LocationManager$LocationListenerTransport$enkW18B0WwpQkSIMmVChmQ2YwC8.accept(Unknown Source:6)
03-31 16:39:07.654 20611 20611 E AndroidRuntime:    at com.android.internal.util.function.pooled.PooledLambdaImpl.doInvoke(PooledLambdaImpl.java:292)
03-31 16:39:07.654 20611 20611 E AndroidRuntime:    at com.android.internal.util.function.pooled.PooledLambdaImpl.invoke(PooledLambdaImpl.java:201)
03-31 16:39:07.654 20611 20611 E AndroidRuntime:    at com.android.internal.util.function.pooled.OmniFunction.run(OmniFunction.java:97)
03-31 16:39:07.654 20611 20611 E AndroidRuntime:    at android.os.Handler.handleCallback(Handler.java:938)
03-31 16:39:07.654 20611 20611 E AndroidRuntime:    at android.os.Handler.dispatchMessage(Handler.java:99)
03-31 16:39:07.654 20611 20611 E AndroidRuntime:    at android.os.Looper.loop(Looper.java:223)
03-31 16:39:07.654 20611 20611 E AndroidRuntime:    at android.app.ActivityThread.main(ActivityThread.java:7664)
03-31 16:39:07.654 20611 20611 E AndroidRuntime:    at java.lang.reflect.Method.invoke(Native Method)
03-31 16:39:07.654 20611 20611 E AndroidRuntime:    at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:592)
03-31 16:39:07.654 20611 20611 E AndroidRuntime:    at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:947)
03-31 16:39:07.654 20611 20611 E AndroidRuntime: Caused by: java.lang.RuntimeException: Moving time cannot be negative
03-31 16:39:07.654 20611 20611 E AndroidRuntime:    at de.dennisguse.opentracks.stats.TrackStatistics.addMovingTime(TrackStatistics.java:245)
03-31 16:39:07.654 20611 20611 E AndroidRuntime:    at de.dennisguse.opentracks.stats.TrackStatistics.addMovingTime(TrackStatistics.java:236)
03-31 16:39:07.654 20611 20611 E AndroidRuntime:    ... 20 more
03-31 16:39:07.654 20611 27265 W BluetoothGatt: Unhandled exception in callback
03-31 16:39:07.654 20611 27265 W BluetoothGatt: java.lang.SecurityException: Permission Denial: writing de.dennisguse.opentracks.data.ShareContentProvider uri content://de.dennisguse.opentracks.debug.content/trackpoints from pid=0, uid=1002 requires the provider be exported, or grantUriPermission()
03-31 16:39:07.654 20611 27265 W BluetoothGatt:     at android.content.ContentProvider.enforceWritePermissionInner(ContentProvider.java:896)
03-31 16:39:07.654 20611 27265 W BluetoothGatt:     at android.content.ContentProvider$Transport.enforceWritePermission(ContentProvider.java:696)
03-31 16:39:07.654 20611 27265 W BluetoothGatt:     at android.content.ContentProvider$Transport.insert(ContentProvider.java:322)
03-31 16:39:07.654 20611 27265 W BluetoothGatt:     at android.content.ContentResolver.insert(ContentResolver.java:2149)
03-31 16:39:07.654 20611 27265 W BluetoothGatt:     at android.content.ContentResolver.insert(ContentResolver.java:2111)
03-31 16:39:07.654 20611 27265 W BluetoothGatt:     at de.dennisguse.opentracks.data.ContentProviderUtils.insertTrackPoint(ContentProviderUtils.java:713)
03-31 16:39:07.654 20611 27265 W BluetoothGatt:     at de.dennisguse.opentracks.services.TrackRecordingManager.insertTrackPointHelper(TrackRecordingManager.java:242)
03-31 16:39:07.654 20611 27265 W BluetoothGatt:     at de.dennisguse.opentracks.services.TrackRecordingManager.insertTrackPoint(TrackRecordingManager.java:237)
03-31 16:39:07.654 20611 27265 W BluetoothGatt:     at de.dennisguse.opentracks.services.TrackRecordingManager.onNewTrackPoint(TrackRecordingManager.java:204)
03-31 16:39:07.654 20611 27265 W BluetoothGatt:     at de.dennisguse.opentracks.services.TrackRecordingService.newTrackPoint(TrackRecordingService.java:298)
03-31 16:39:07.654 20611 27265 W BluetoothGatt:     at de.dennisguse.opentracks.services.handlers.TrackPointCreator.onNewTrackPoint(TrackPointCreator.java:128)
03-31 16:39:07.654 20611 27265 W BluetoothGatt:     at de.dennisguse.opentracks.services.handlers.TrackPointCreator.onChange(TrackPointCreator.java:122)
03-31 16:39:07.654 20611 27265 W BluetoothGatt:     at de.dennisguse.opentracks.sensors.BluetoothRemoteSensorManager.onChanged(BluetoothRemoteSensorManager.java:213)
03-31 16:39:07.654 20611 27265 W BluetoothGatt:     at de.dennisguse.opentracks.sensors.BluetoothConnectionManager$1.onCharacteristicChanged(BluetoothConnectionManager.java:114)
03-31 16:39:07.654 20611 27265 W BluetoothGatt:     at android.bluetooth.BluetoothGatt$1$8.run(BluetoothGatt.java:478)
03-31 16:39:07.654 20611 27265 W BluetoothGatt:     at android.bluetooth.BluetoothGatt.runOrQueueCallback(BluetoothGatt.java:780)
03-31 16:39:07.654 20611 27265 W BluetoothGatt:     at android.bluetooth.BluetoothGatt.access$200(BluetoothGatt.java:41)
03-31 16:39:07.654 20611 27265 W BluetoothGatt:     at android.bluetooth.BluetoothGatt$1.onNotify(BluetoothGatt.java:472)
03-31 16:39:07.654 20611 27265 W BluetoothGatt:     at android.bluetooth.IBluetoothGattCallback$Stub.onTransact(IBluetoothGattCallback.java:306)
03-31 16:39:07.654 20611 27265 W BluetoothGatt:     at android.os.Binder.execTransactInternal(Binder.java:1159)
03-31 16:39:07.654 20611 27265 W BluetoothGatt:     at android.os.Binder.execTransact(Binder.java:1123)
03-31 16:39:07.661  1004  4625 I DropBoxManagerService: add tag=data_app_crash isTagEnabled=true flags=0x2
03-31 16:39:07.662  1004  4823 W ActivityTaskManager:   Force finishing activity de.dennisguse.opentracks.debug/de.dennisguse.opentracks.TrackRecordingActivity

So we got our moving time debug, but notice there is a java.lang.SecurityException before that even.

brianjmurrell commented 2 years ago

Does that moving time debug help with eliminating this exception?

dennisguse commented 2 years ago

@brianjmurrell yes! It is a race condition

There was a sensor TrackPoint that was stored (also into lastTrackPoint). It could also be that this was triggered by the UI - don't know as this is not logged.

03-31 16:39:07.654 20611 20611 E AndroidRuntime: java.lang.RuntimeException: LastTrackPoint: TrackPoint{id=null, time=2022-03-31T20:39:07.593Z, latitude=null, longitude=null, horizontalAccuracy=null, altitude=null, speed=Speed{speed_mps=1.59375}, bearing=null, sensorDistance=Distance{distance_m=7.699999999999989}, type=SENSORPOINT(2), heartRate_bpm=HeartRate{value=92.0 bpm}, cadence_rpm=Cadence{value=124.0 rpm}, power=null, altitudeGain_m=null, altitudeLoss_m=null}

and then there is a GPS TrackPoint:

03-31 16:39:07.654 20611 20611 E AndroidRuntime: TrackPoint: TrackPoint{id=null, time=2022-03-31T20:39:07.591Z, latitude=[redacted], longitude=[redacted], horizontalAccuracy=Distance{distance_m=9.648000717163086}, altitude=Altitude{altitude_m=67.6724853515625WGS84}, speed=Speed{speed_mps=1.58984375}, bearing=null, sensorDistance=Distance{distance_m=2.3000000000000114}, type=TRACKPOINT(0), heartRate_bpm=HeartRate{value=92.0 bpm}, cadence_rpm=Cadence{value=124.0 rpm}, power=null, altitudeGain_m=null, altitudeLoss_m=null}

And timestamp-wise: the GPS TrackPoint is actually before the lastTrackPoint and thus crashes.

Assumption:

  1. the GPS TrackPoint was created (and then a thread switch)
  2. then the sensor/UI TrackPoint was created and processed
  3. then the GPS TrackPoint was processed => crash

Next step: use some kind of locking to prevent task switching. Only one TrackPoint can be processed at a time. But I don't know yet how to do this...

dennisguse commented 2 years ago

One more thought: lastTrackPoint in this case must be generated by a sensor, because the TrackStatisticsUpdater is cloned for every UI operation - https://github.com/OpenTracksApp/OpenTracks/blob/2e0835b2eccf6f25b4aebd666bf90fc9923278b2/src/main/java/de/dennisguse/opentracks/services/TrackRecordingManager.java#L120

That leaves the GPS vs BLE sensor race condition.

dennisguse commented 2 years ago

@brianjmurrell Can you give this https://github.com/OpenTracksApp/OpenTracks/pull/1167 a spin?

brianjmurrell commented 2 years ago

I most certainly will. Perhaps today even. Will let you know when I do.

TBH though, I'm not sure about the future of OpenTracks for my needs though, as sad as (the FOSS user and developer in me) I am to say that. That is because ultimately I want my heath data in Google Fit. I can use fitnesssyncer.com to upload activity data from OpenTracks' GPX file into Google Fit, however despite the (i.e. heart rate, etc.) data being in the an activity entry in Google Fit, it is not calculating it's Heart Points or Move Minutes activity benchmarks for it.

The activity data in an OpenTracks->fitnesssyncer.com->Google Fit entry looks the same as Google Fit activities from other activity services/apps that do calculate Heart Points and Move Minutes successfully, so it's really unclear why the GPX uploads from fitnesssyncer.com are not getting the same treatment at Google Fit.

The fitnesssyncer.com author has reached out to Google about this (now and has done previously) but they are unsurprisingly unresponsive about it, so why some data gets Heart Points and Move minutes benchmarks and other seemingly same data does not is a mystery.

Again, this makes me really sad, as I am a firm believer in FOSS. I work on FOSS for a living and have done so for 20 years or more, that's how much I believe in it. Moreover, other than Wahoo's own (shitty) app, no app other than OpenTracks takes advantage of the additional data provided by the Tickr X. Every other app just reads heart rate from it. And some of them, such as Polar Beat, are super shitty at the GPS tracking in absence of using the distance metric from the HRM.

Unfortunately fitnesssyncer.com is not FOSS so I can't even try to help debug it's GPX->Google Fit upload problem.

dennisguse commented 2 years ago

@brianjmurrell that would be sad news. Just out of curiosity: why do you want to stick with Google Fit? What do they ober that no other solution can offer?

PS thanks for you great work! Was really helpful and fun as well!

brianjmurrell commented 2 years ago

What do they ober that no other solution can offer?

What are the other solutions?

If you can accept that Google is the biggest aggregator of information, the benefit is that Google is the biggest aggregator of information. If they can do for my health and fitness what they have managed to do for my finding information on the web, giddy-up.

Maybe they are not quite there yet, indeed. But at least they are not one of many/most silos of health information out there that refuse to interoperate with anyone else. Google Fit, at least AFAICT are the one aggregator of health information that is willing to interoperate and don't hold your data hostage.

PS thanks for you great work! Was really helpful and fun as well!

I'm not ready to call it yet. I have been investigating the Google Fit API. I am hopeful that I can get fitnesssyncer.com to come around to uploading useful data. I have also not ruled out writing my own GPX->Google Fit uploader. But quite honestly between $day_job and $life, at least until I can retire, I have little time for hacking, unfortunately. And in the meanwhile, I do need to be able to track useful fitness data and at least until somebody shows me otherwise, Google Fit seems to be the place to track that.

brianjmurrell commented 2 years ago

Logcat from the test PR:

04-04 16:19:33.063 10840 24374 I TrackStatistics: java.lang.RuntimeException: Moving time cannot be negative
04-04 16:19:33.063 10840 24374 I TrackStatistics: : LastTrackPoint: TrackPoint{id=3373, time=2022-04-04T20:12:00.259Z, latitude=null, longitude=null, horizontalAccuracy=null, altitude=null, speed=Speed{speed_mps=1.71875}, bearing=null, sensorDistance=Distance{distance_m=8.600000381469727}, type=SENSORPOINT(2), heartRate_bpm=HeartRate{value=99.0 bpm}, cadence_rpm=Cadence{value=131.0 rpm}, power=null, altitudeGain_m=null, altitudeLoss_m=null}
04-04 16:19:33.063 10840 24374 I TrackStatistics: TrackPoint: TrackPoint{id=3374, time=2022-04-04T20:12:00.258Z, latitude=[redacted], longitude=[redacted], horizontalAccuracy=Distance{distance_m=9.648000717163086}, altitude=Altitude{altitude_m=61.7979736328125WGS84}, speed=Speed{speed_mps=1.734375}, bearing=null, sensorDistance=Distance{distance_m=1.5}, type=TRACKPOINT(0), heartRate_bpm=HeartRate{value=99.0 bpm}, cadence_rpm=Cadence{value=132.0 rpm}, power=null, altitudeGain_m=null, altitudeLoss_m=null}
04-04 16:19:33.063 10840 24374 I TrackStatistics: java.lang.RuntimeException: Moving time cannot be negative
04-04 16:19:33.063 10840 24374 I TrackStatistics:       at de.dennisguse.opentracks.stats.TrackStatistics.addMovingTime(TrackStatistics.java:249)
04-04 16:19:33.063 10840 24374 I TrackStatistics:       at de.dennisguse.opentracks.stats.TrackStatistics.addMovingTime(TrackStatistics.java:240)
04-04 16:19:33.063 10840 24374 I TrackStatistics:       at de.dennisguse.opentracks.stats.TrackStatisticsUpdater.addTrackPoint(TrackStatisticsUpdater.java:177)
04-04 16:19:33.063 10840 24374 I TrackStatistics:       at de.dennisguse.opentracks.ui.intervals.IntervalStatistics.addTrackPoints(IntervalStatistics.java:46)
04-04 16:19:33.063 10840 24374 I TrackStatistics:       at de.dennisguse.opentracks.ui.intervals.IntervalStatisticsModel.lambda$loadIntervalStatistics$0$de-dennisguse-opentracks-ui-intervals-IntervalStatisticsModel(IntervalStatisticsModel.java:95)
04-04 16:19:33.063 10840 24374 I TrackStatistics:       at de.dennisguse.opentracks.ui.intervals.IntervalStatisticsModel$$ExternalSyntheticLambda0.run(Unknown Source:4)
04-04 16:19:33.063 10840 24374 I TrackStatistics:       at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
04-04 16:19:33.063 10840 24374 I TrackStatistics:       at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
04-04 16:19:33.063 10840 24374 I TrackStatistics:       at java.lang.Thread.run(Thread.java:923)
04-04 16:19:33.063 10840 24374 D TrackStatisticsUpdater: Invalid speed. speed: Speed{speed_mps=1.734375} lastLocationSpeed: Speed{speed_mps=1.71875}
04-04 16:19:33.064 10840 24374 I TrackStatistics: java.lang.RuntimeException: Moving time cannot be negative
04-04 16:19:33.064 10840 24374 I TrackStatistics: : LastTrackPoint: TrackPoint{id=3375, time=2022-04-04T20:12:06.257Z, latitude=null, longitude=null, horizontalAccuracy=null, altitude=null, speed=Speed{speed_mps=1.66015625}, bearing=null, sensorDistance=Distance{distance_m=8.600000381469727}, type=SENSORPOINT(2), heartRate_bpm=HeartRate{value=99.0 bpm}, cadence_rpm=Cadence{value=128.0 rpm}, power=null, altitudeGain_m=null, altitudeLoss_m=null}
04-04 16:19:33.064 10840 24374 I TrackStatistics: TrackPoint: TrackPoint{id=3376, time=2022-04-04T20:12:06.255Z, latitude=[redacted], longitude=[redacted], horizontalAccuracy=Distance{distance_m=9.648000717163086}, altitude=Altitude{altitude_m=59.13995361328125WGS84}, speed=Speed{speed_mps=1.6640625}, bearing=null, sensorDistance=Distance{distance_m=1.600000023841858}, type=TRACKPOINT(0), heartRate_bpm=HeartRate{value=99.0 bpm}, cadence_rpm=Cadence{value=128.0 rpm}, power=null, altitudeGain_m=null, altitudeLoss_m=null}
04-04 16:19:33.064 10840 24374 I TrackStatistics: java.lang.RuntimeException: Moving time cannot be negative
04-04 16:19:33.064 10840 24374 I TrackStatistics:       at de.dennisguse.opentracks.stats.TrackStatistics.addMovingTime(TrackStatistics.java:249)
04-04 16:19:33.064 10840 24374 I TrackStatistics:       at de.dennisguse.opentracks.stats.TrackStatistics.addMovingTime(TrackStatistics.java:240)
04-04 16:19:33.064 10840 24374 I TrackStatistics:       at de.dennisguse.opentracks.stats.TrackStatisticsUpdater.addTrackPoint(TrackStatisticsUpdater.java:177)
04-04 16:19:33.064 10840 24374 I TrackStatistics:       at de.dennisguse.opentracks.ui.intervals.IntervalStatistics.addTrackPoints(IntervalStatistics.java:46)
04-04 16:19:33.064 10840 24374 I TrackStatistics:       at de.dennisguse.opentracks.ui.intervals.IntervalStatisticsModel.lambda$loadIntervalStatistics$0$de-dennisguse-opentracks-ui-intervals-IntervalStatisticsModel(IntervalStatisticsModel.java:95)
04-04 16:19:33.064 10840 24374 I TrackStatistics:       at de.dennisguse.opentracks.ui.intervals.IntervalStatisticsModel$$ExternalSyntheticLambda0.run(Unknown Source:4)
04-04 16:19:33.064 10840 24374 I TrackStatistics:       at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
04-04 16:19:33.064 10840 24374 I TrackStatistics:       at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
04-04 16:19:33.064 10840 24374 I TrackStatistics:       at java.lang.Thread.run(Thread.java:923)
04-04 16:19:33.064 10840 24374 D TrackStatisticsUpdater: Invalid speed. speed: Speed{speed_mps=1.6640625} lastLocationSpeed: Speed{speed_mps=1.66015625}
dennisguse commented 2 years ago

But that's something different. At least a different reason.

Was it while recording? Or was this an previously recorded track? The reason why I am asking is that this time it is triggered by the interval tab and not the data recording code.

brianjmurrell commented 2 years ago

Ahhh. I did open the interval tab after the walk. Let me do some time math...

Yeah, seems it was after. Started the track at 15:32-04 and TOTAL TIME on the track summary is 46:12.

dennisguse commented 2 years ago

Another reason not to catch the exception ;)

Then my best guess is that we have a problem in TrackPointInterator. One important info: the interval and the diagrams are loading the TrackPoints from SQLite db (i.e., after the TrackRecordingService did all the data processing and stored the data). One advantage is that we can then use them for live as well as existing recordings.

Just out of curiosity: is the track corrupt aka does it always crash? Can you export and import the track? If the track is corrupt: export will work, import will also result in negative moving time and subsequently fail.