anongit / mytracks

Automatically exported from code.google.com/p/mytracks
0 stars 0 forks source link

Stops recording on its own after a short period of time #189

Closed GoogleCodeExporter closed 9 years ago

GoogleCodeExporter commented 9 years ago
What steps will reproduce the problem?
1.Start recording a track after GPS lock
2.Let the phone screen shut off 
3.When I hit stop recording some time later, only the first bit (usually ~1 
mile) is recorded

What is the expected output? What do you see instead?
I expected to see the entire track recorded since the phone says that it is 
being recorded

What version of MyTracks are you using? On what version of Android? On what
phone?
1.0.19, 2.1, Samsung Vibrant

If possible please provide a log.  Either upload here or send to mytracks-
support@google.com.
Detailed instructions can be found here:
http://code.google.com/p/mytracks/wiki/HowToReportErrors

Please provide any additional information here:

Original issue reported on code.google.com by danthompsen@gmail.com on 13 Oct 2010 at 6:09

GoogleCodeExporter commented 9 years ago
[deleted comment]
GoogleCodeExporter commented 9 years ago
What steps will reproduce the problem?
I think it stops recording after 50 to 80 km, possibly if I receive a 
notification or make a phone call during recording. It does not prompt to save 
the track, it just looks like it might be still recording but it isn't.

What is the expected output? What do you see instead?
During cycling, it just stops recording after 50 to 80 kms. 

What version of MyTracks are you using? On what version of Android? On what
phone?
My Tracks 1.0.19, Android 2.2, Google Nexus One.

Attached two separate GPX files from the same bike ride, note the first one 
silently stopped after ~30km when I made a phone call, the second after I 
restarted at the 90km waypoint and then it silently stopped ~80km after that.

Original comment by matt...@gmail.com on 17 Oct 2010 at 9:04

Attachments:

GoogleCodeExporter commented 9 years ago
I had a similar problem with MyTracks 1.0.19 on Motorola Doid 2.2

Symptoms:
- Track was stopped before I tried to stop it.  When I opened MyTacks to stop 
my track, it was already closed.  All I could do was open another track (even 
though the logo was showing in the status bar).
- The stats for the ride are messed up.  Total Time was 28:42 and riding time 
was 3:28.  The average speed of 111 was a little off.  The moving speed of 15 
is more reasonable (but my bike computer showed about 18 mph).  However 
MyTracks seems to always show slower times.

The uploaded doc entry is as follows:  The map should show you all the details:

Sat Oct 16 07:28:55 CDT 2010 0:28:42 3:28:12 53.5 mi 111.82 15.42 35.44 mi/h 
1571 804 1053 ft 
http://maps.google.com/maps/ms?msa=0&msid=208070149580967782133.000492c0231a4c1c
7f8e1

I had just rebooted the Motorola Droid before running MyTracks and it was the 
only app I had manually started.

I've attached the log file.

Original comment by bhecht4...@gmail.com on 19 Oct 2010 at 4:25

Attachments:

GoogleCodeExporter commented 9 years ago
Thanks for the log.  That makes a huge difference.  It looks like for some 
reason the StatsBuilder object is not getting resumed properly.  Here are the 
key log snippets:
10-16 11:01:22.783 D/MyTracks( 9983): TrackRecordingService.onLocationChanged
10-16 11:01:22.798 W/MyTracks( 9983): Tried to account for location while track 
is paused
10-16 11:01:22.814 D/MyTracksProvider( 9983): 
MyTracksProviderUtilsImpl.insertTrackPoint
10-16 11:01:22.814 D/MyTracksProvider( 9983): MyTracksProvider.insert

This should only happen if the StatsBuilder object is set to paused.  That 
should be reset in both startNewTrack and onCreate if resuming an old track.

I am kind of stumped how this is occurring but this should help sort it out a 
lot.

Original comment by sandordo...@google.com on 19 Oct 2010 at 4:42

GoogleCodeExporter commented 9 years ago
That's good news. I've got Log Collector installed now so will send in logs 
when the next incident occurs.

Thanks.

Original comment by matt...@gmail.com on 19 Oct 2010 at 8:42

GoogleCodeExporter commented 9 years ago
Sandor, are you working on a fix?  If not, I'm more than happy to take on this 
one.

Original comment by ba...@google.com on 22 Oct 2010 at 7:45

GoogleCodeExporter commented 9 years ago
I don't have a fix.  I am not sure how exactly this state is occurring.  [It 
seems impossible by reading the code.]  There are probably two fixes:
1. Understand how this happens and make sure it never does. I think it has to 
do with resuming a crashed service.
2. Recover gracefully when it does.  It would be trivial to detect this 
situation and just resume the stats builder.

Original comment by sandordo...@google.com on 22 Oct 2010 at 7:50

GoogleCodeExporter commented 9 years ago

Original comment by ba...@google.com on 22 Oct 2010 at 7:59

GoogleCodeExporter commented 9 years ago
I analyzed the code and here is what I've found so far:
i) TripStatisticsBuilder is in paused mode if, and only if it's freshly 
constructed or it has been paused by a call to pauseAt.
ii) statsBuilder from TrackRecordingService is instantiated when the service is 
created (so it is in paused mode) and can be resumed in 
startNewTrack/restoreStats. This is only possible when recordingTrack is null:
    recordingTrack = getRecordingTrack();
    if (recordingTrack != null) {
      restoreStats(recordingTrack);
      isRecording = true;
    }
iii) Ad. 1) I also strongly suspect (but I'm not 100% sure), that this is 
related to resuming a crashed service. Unfortunately, by looking at the 
attached log, it's not possible to tell when the problem occurs for the first 
time, but I can clearly see a bug in the way we handle recovery from a crashed 
service:
10-16 11:03:08.861 D/MyTracks( 1470): MyTracks.onResume
10-16 11:03:08.861 D/MyTracks( 1470): MyTracks: Trying to bind to track 
recording service...
10-16 11:03:08.869 D/MyTracks( 1470): MyTracks: ...bind finished!
10-16 11:03:08.876 D/MyTracks( 1470): MyTracksMap.onResume
10-16 11:03:09.181 D/MyTracks( 1470): MyTracksMap: ContentObserver.onChange
10-16 11:03:09.298 E/MyTracks( 1470): MyTracks: Remote exception.
10-16 11:03:09.298 E/MyTracks( 1470): android.os.DeadObjectException
10-16 11:03:09.298 E/MyTracks( 1470): at android.os.BinderProxy.transact(Native 
Method)
10-16 11:03:09.298 E/MyTracks( 1470): at 
com.google.android.apps.mytracks.services.ITrackRecordingService$Stub$Proxy.isRe
cording(ITrackRecordingService.java:198)
10-16 11:03:09.298 E/MyTracks( 1470): at 
com.google.android.apps.mytracks.MyTracks.isRecording(MyTracks.java:240)
10-16 11:03:09.298 E/MyTracks( 1470): at 
com.google.android.apps.mytracks.MyTracksMap$8.onChange(MyTracksMap.java:332)
10-16 11:03:09.298 E/MyTracks( 1470): at 
com.google.android.apps.mytracks.MyTracksMap.onResume(MyTracksMap.java:444)
10-16 11:03:09.298 E/MyTracks( 1470): at 
android.app.Instrumentation.callActivityOnResume(Instrumentation.java:1149)
10-16 11:03:09.298 E/MyTracks( 1470): at 
android.app.Activity.performResume(Activity.java:3823)

I've seen this issue a few times, but this time I want to really fix it.  The 
problem is with the fact that we try to bind in MyTracks (which is 
non-blocking), and later on, in another activity we assume that the service is 
already bound by calling MyTracks.getInstance().isRecording().  This may leave 
the service in a partially initialized state.

Ad.2. While I agree this would immediately resolve the issue (and is easy as 
well), I want to resolve 1) to avoid 2).

We are having similar complaints from users, e.g. see this post: 
http://groups.google.com/group/mytracks/browse_thread/thread/b24e97dbb17d95e8, 
which I strongly suspect may be related to this bug.

iv) Another possibility could be related to the fact that statsBuilder is 
accessed by different threads (onLocationChanged could be called from a 
different thread).  There is no synchronization in StatsBuilder class and VM is 
not required to perform when doing a context switch.  I can imagine having one 
thread set paused=false and another still seeing paused=true.

Still investigating...

Original comment by ba...@google.com on 22 Oct 2010 at 9:47

GoogleCodeExporter commented 9 years ago
I've just reproduced it by driving about 20 miles.  More details soon.

Original comment by ba...@google.com on 22 Oct 2010 at 10:51

GoogleCodeExporter commented 9 years ago
I think I've reproduced the issue again. Log Collector logs attached. (is there 
a better way to get logs for these issues?)
Note, I see the Notification item stating "Recording your track...", but when I 
open MyTracks it isn't recording as I have the option to "Record track" again, 
and my location is no where near the track shown. I also don't have the option 
of saving the track as a result, at least not in this instance. In the past Ive 
been able to recover the track up until the point where it silently stopping 
recording.

Original comment by matt...@gmail.com on 23 Oct 2010 at 6:27

Attachments:

GoogleCodeExporter commented 9 years ago
Thanks for the report.  Unfortunately, it seems that it was caught too late and 
there is no useful information to help with diagnosing the original issue (at 
least not obvious to me).

The best way to dump a log is to press and hold the trackball together with the 
volume up (N1). After ~1-2sec you should feel a vibration and it means that a 
bug report was dumped.  It's usually about ~2MB.  You can find it on your SD 
card.

Also, I made some progress with regard to this issue:
1) I know why the service gets killed from time to time (with a message "No 
longer want...").  It's just expected.  A solution is to use 
startForeground(...) in onCreate which puts the service into a different 
priority group and makes it almost unkillable (unless there is really low 
memory).
2) I found a few issues related to resuming service if it's terminated 
abnormally
3) There is no synchronization between binding and accessing service's data 
which results in DeadObjectException

I'm working on fixes for all of the above issues, however I still haven't found 
the culprit of the bug in question (stats paused).

Thanks for your continuous investigation!

Bart

Original comment by ba...@google.com on 23 Oct 2010 at 6:46

GoogleCodeExporter commented 9 years ago

Original comment by ba...@google.com on 23 Oct 2010 at 6:47

GoogleCodeExporter commented 9 years ago
Attached is another log file.  Hope it helps.

Droid 2.2
MyTracks 1.0.19
Motorola Droid

This time, it didn't seem to record anything for the entire 4 hour ride.  
Sigh....

Here is the uploaded data:

Track 174       Sat Oct 23 07:34:39 CDT 
2010    4:24:42 0:00:00 0   mi  0   NaN 0   mi/h    0   ∞ -∞    ft  http://maps.google.com/maps
/ms?msa=0&msid=208070149580967782133.0004934e8d35eb15c7c99              

Original comment by bhecht4...@gmail.com on 23 Oct 2010 at 8:43

Attachments:

GoogleCodeExporter commented 9 years ago
Thanks for the report.  This is the top priority for us now and a fix should be 
included in the next release version.

Original comment by ba...@google.com on 23 Oct 2010 at 10:19

GoogleCodeExporter commented 9 years ago

Original comment by ba...@google.com on 24 Oct 2010 at 2:19

GoogleCodeExporter commented 9 years ago
Thanks all for your patience.  I've identified many bugs related to this issue 
and fixed most of them (http://code.google.com/p/mytracks/issues/detail?id=199).

I can post the new binary for download, if anyone is willing to test it on 
his/her own risk :)

Bart

Original comment by ba...@google.com on 25 Oct 2010 at 4:37

GoogleCodeExporter commented 9 years ago

Original comment by ba...@google.com on 25 Oct 2010 at 4:38

GoogleCodeExporter commented 9 years ago
More than happy to trial, will it have the issue 9 code experimental code
rolled into it too? I'll go for a good ride (100km+) this weekend and try
and collect bug data for you.

As an aside, do you think issue 110 is related? I've often, but not always
experienced issue 110 after experiencing issue 189.

Original comment by matt...@gmail.com on 25 Oct 2010 at 4:44

GoogleCodeExporter commented 9 years ago
I think that issue 110 is related, although I cannot confirm it for 100%.  I 
personally experienced it a few times in the past, but not recently.

As of now, I don't experience any stability related issues with MyTracks (so I 
hope all of them were fixed), but I need to run more tests.

Issue 9 won't be included.  The new version (1.0.20) will most likely include 
only bug fixes as we don't want to introduce new features until we resolve 
existing critical issues.

If this issue is closed, perhaps Sandor can sync again with head and provide an 
update for you.

Original comment by ba...@google.com on 25 Oct 2010 at 5:31

GoogleCodeExporter commented 9 years ago
Sounds good. I'd much rather be able to reliably use MyTracks than have the
HRM functionality... Do you have any specific tests the community should
perform on this test version?

Original comment by matt...@gmail.com on 25 Oct 2010 at 5:41

GoogleCodeExporter commented 9 years ago
Yes, here is a list of things I'd like to verify:
1) No lag during track drawing.  Go for a fast ride and monitor whether the 
track being drawn keeps up with the current location (note, the best test is to 
drive in a car as a passenger and watch the map)
2) Start recording a track and try to disrupt MyTracks app by opening other 
apps, loading large web pages, removing the battery. Put a lot of stress on 
your phone :)  None of these actions should crash the app nor stop recording 
(in case of battery removal, you obviously have to restart the phone :) ).
3) Select different statistic screens while recording a track, observe the stats
4) Check the app logs for any exceptions and warnings ("Tried to account for 
location while track is paused" is gone so should be "DeadObjectException").
5) Now for experienced testers:
   adb root
   abd shell
   ps   (and locate the PID of trackrecording service)
   kill -9 <PID> 
Check if service is properly restarted.

I went through all of the steps above and they work on my N1, but you 
experience may vary.

I will attach the APK for testing once I fix one more minor issue.

Thanks a lot!

Original comment by ba...@google.com on 25 Oct 2010 at 5:55

GoogleCodeExporter commented 9 years ago
I've uploaded a test version here: 
http://code.google.com/p/mytracks/downloads/list.  Please test at your own risk 
and make sure you backup your data before trying.

Good luck!

Original comment by ba...@google.com on 25 Oct 2010 at 8:16

GoogleCodeExporter commented 9 years ago
Hi. I setup shell script to kill the trackrecorder process every four minutes. 
I had one instance of it not getting restarted. Before I started my ride, I 
watched the script kill the process a few times and then think it failed to 
restart. I couldn't see the "recording track..." item in the notification bar, 
so ended up stopping then restarting the track. I don't know if that means I 
was just impatient (how long should it take to restart it given default 
settings?) or it really didn't restart the trackrecorder process for some 
reason.

I've attached the bugreport logs, but didn't spot any "Tried to account" 
errors, just four or five DeadObjectExceptions. It looks like I've only got ~5 
minutes of /var/log/system logs.. not sure how I can keep these logs for 
longer, maybe a job to export the syslogs every few minutes???

Original comment by matt...@gmail.com on 26 Oct 2010 at 8:17

GoogleCodeExporter commented 9 years ago
[deleted comment]
GoogleCodeExporter commented 9 years ago
Hey, that's a pretty nice test :) Thanks!

Android uses exponential back-off when restarting a crashed service. It's 
something like 5sec, 20sec, 80sec etc.  I don't know exactly when the counter 
resets, but if you happen to have frequent crashes (like every 4 min), you may 
need to wait a while :)

A more realistic test would be to restart it every 30min or so.

The log you attached is too short to find the message from ActivityManager 
about restarting the service, but normally you would see something like 
"restarting a crashed service in NNN ms".

As with regard to DeadObjectException, I think I can slightly improve the 
response of the app.  I will send an update tomorrow.

Thanks again for testing.

Original comment by ba...@google.com on 26 Oct 2010 at 8:57

GoogleCodeExporter commented 9 years ago
I did a search to find out how to grab longer logs, but didn't turn up 
anything, any suggestions on how to capture longer than 5 minutes of logs in a 
bugreport (trackball + volume up)? 

Bugs? I noticed if I record a track whilst in the stats pane and then stop the 
track and then switch to map view, I only see my previously recorded track, not 
the current one. I am able to get the most recent track to load by going to 
"tracks" and selecting the most recently saved track. I haven't reproduced it 
again (haven't had time) but thought I'd mention it.

Original comment by matt...@gmail.com on 27 Oct 2010 at 1:26

GoogleCodeExporter commented 9 years ago
Ok. reproduced. After stopping the track from recording, I switch to map view 
to find only the previously recorded track displayed, not the track I just 
recorded. I forgot to grab a bugreport, next time.

Original comment by matt...@gmail.com on 27 Oct 2010 at 10:18

GoogleCodeExporter commented 9 years ago
Thanks!  This is a known issue, and as a matter of fact I discussed it 
yesterday with the team members.  The question was whether we want to keep the 
previously selected track or automatically select the track that has just 
finished recording.

I'm slightly inclined into the latter, what do you think?

Original comment by ba...@google.com on 27 Oct 2010 at 3:42

GoogleCodeExporter commented 9 years ago
My first reaction was "wha..., where'd it go?!...". I'm also inclined to see 
the track that has just finished recording automatically selected. If it shows 
this track during recording, it seems logical that it'd still be selected after 
you press stop.

Original comment by matt...@gmail.com on 30 Oct 2010 at 11:49

GoogleCodeExporter commented 9 years ago
I download version 20 and did a couple of rides (3 hours ride time, 4 hours 
total).  Everything looked great.  The speeds and distance matched my cycle 
computer (in previous versions, myTracks was consistently slower and shorter).  
We usually ride at an average of about 18 mph.

I know this is really anecdotal evidence, but it put a smile on my face and I 
give it a thumbs up.

Original comment by bhecht4...@gmail.com on 1 Nov 2010 at 1:14

GoogleCodeExporter commented 9 years ago
bhecht4737@: Great to hear that, thanks!

Matt@: I've fixed the issue with auto-selecting the recording track.  I also 
feel that this is more intuitive than going back to previously selected track.

Original comment by ba...@google.com on 1 Nov 2010 at 4:50

GoogleCodeExporter commented 9 years ago
This issue has been fixed.  We will be release a new version sometime next week.

Original comment by ba...@google.com on 5 Nov 2010 at 3:44

GoogleCodeExporter commented 9 years ago
Hi Bart, 

An observation: if I kill the trackrecord process whilst recording, once the 
process re-spawns the Average Speed calculates very high and Total Time is not 
time since start of track. My guess is Average Speed is calculated using Total 
Distance from start of track and the time since the trackrecord process last 
started. Total Time doesn't reflect time from start of track but time 
trackrecord process has been running. Is this a different issue or does it 
belong in here?

This was already discussed: if I kill the process a few times (>3) even with 
several minutes between kills, it won't re-spawn the process. I know its an 
exceptional case to have the process die so frequently within a (~20 minute) 
period but if it did happen, then the track would be lost. Would it be feasible 
to have an alert/alarm if the trackrecord process remained dead for a defined 
period (eg >minute) so the user could intervene.

Thanks for all the work,  excluding my synthetic testing above, Its working 
great in real-world everyday use.

Original comment by matt...@gmail.com on 8 Nov 2010 at 8:33

GoogleCodeExporter commented 9 years ago
Hi Matt,

You've brought up two different issues here:

1) Inaccurate stats after the service has been restarted
2) A feature request to add an alarm in case service is down for excessive 
amount of time (user configurable).

I don't think they belong here, and I I will create separate Issues to track 
them down.

BTW, we will be releasing a new version, 1.0.20, sometime this week.  It 
includes a lot of stability fixes and I'm really excited to see it hit the 
market soon.

Original comment by ba...@google.com on 8 Nov 2010 at 5:59

GoogleCodeExporter commented 9 years ago
Thanks Bart!

It may be that point 1 belongs under issue 77(?), I had previously
experienced something like this during in a failed track and noted it there.
Point 2 would be great to ensure we never loose the entire track, but if its
just addressing a synthetic issue... time will tell.

Can't wait for 1.0.20! :)

Original comment by matt...@gmail.com on 8 Nov 2010 at 8:31

GoogleCodeExporter commented 9 years ago
Matt,
I've posted a new release candidate (RC2) in Downloads section: 
http://code.google.com/p/mytracks/downloads/detail?name=MyTracks-1.0.20-rc2.apk.
  Give it a try, if you want.

This is most likely the final version coming up this week.

Original comment by ba...@google.com on 9 Nov 2010 at 4:17

GoogleCodeExporter commented 9 years ago
I noticed the first track I record (after install or cache/data wipe) doesn't 
display on the map view after I stop recording, just the start marker. I can 
scroll through the other screens and see data (elevation/speed and metrics 
views), but nothing on the map view. 
I reproduced this via clearing the data under 'manage applications'. I also had 
the same issue one other time (haven't reproduced it yet) after recording and 
stopping the track whilst on the metrics view (not sure if this is relevant), 
switching to the map view displayed only the start point, no track once again.

Closing and re-opening the app gets the data to display as does reloading the 
track from the track list.

Original comment by matt...@gmail.com on 11 Nov 2010 at 3:22

GoogleCodeExporter commented 9 years ago
Hey Matt, thanks for constantly helping with tracking down stability issues.  
I've reopend this bug and will create a unit test to cover this particular 
scenario.

This is most likely one of the border conditions that haven't been well tested.

Original comment by ba...@google.com on 11 Nov 2010 at 5:47

GoogleCodeExporter commented 9 years ago
Matt,
I've fixed this issue after we decided to simplify the process management (have 
only 1 process instead of 2), thus marking as fixed.

Original comment by ba...@google.com on 18 Nov 2010 at 7:10

GoogleCodeExporter commented 9 years ago
That's great Bart, I can't wait to test it out. Will there be an alpha 1.0.20 
apk? I'll let my friends (who I cycle with) know about it too as they've all 
been having the same issue with recording reliability.
- Matt

Original comment by matt...@gmail.com on 18 Nov 2010 at 7:28

GoogleCodeExporter commented 9 years ago
Yes, if everything goes smoothly, I can post a new release candidate before 
this weekend.  So far so good, so maybe tonight :)

Original comment by ba...@google.com on 18 Nov 2010 at 5:19

GoogleCodeExporter commented 9 years ago
Matt, feel free to try the new version here: 
http://code.google.com/p/mytracks/downloads/list.  It's most likely a final 
version unless we discover a major issue.

Original comment by ba...@google.com on 22 Nov 2010 at 8:24