gpslogger icon indicating copy to clipboard operation
gpslogger copied to clipboard
verified publisher icon mendhak

Online logging does not work correctly after some time

Open finkandreas opened this issue 4 years ago • 6 comments

I am trying to use GPSLogger with only online logging, i.e. I disabled all local file logging but something seems rather strange after some time of logging. I have setup an interval of 30 seconds. I have added a log from the server-side, where you can see that at some point the timestamp stops changing by much (i.e. it advances in much smaller intervals than 30 seconds, which does not reflect the current time at which it was really sent), also the smartphone starts to get very very slow with time. Only restarting the smartphone makes it usable again. The longer the logging is turned on, the slower the phone gets. No idea what is going on there. Server log (anonymised by changing lon/lat/alt to 0.0):

[15/Jun/2021:07:09:22 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623733769&hdop=0.8&altitude=0.0&speed=0.0&battery=94.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:10:00 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623733807&hdop=1.0&altitude=0.0&speed=2.83&battery=94.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:10:51 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623733845&hdop=1.4&altitude=0.0&speed=0.0&battery=94.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:11:44 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623733881&hdop=0.8&altitude=0.0&speed=0.0&battery=94.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:11:51 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623733919&hdop=0.9&altitude=0.0&speed=0.0&battery=94.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:12:27 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623733955&hdop=1.3&altitude=0.0&speed=0.0&battery=94.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:13:05 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623733993&hdop=1.1&altitude=0.0&speed=0.0&battery=94.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:13:42 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623734029&hdop=1.1&altitude=0.0&speed=1.11&battery=93.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:14:20 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623734068&hdop=1.1&altitude=0.0&speed=0.34&battery=93.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:14:58 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623734104&hdop=1.3&altitude=0.0&speed=0.31&battery=93.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:15:41 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623734148&hdop=1.4&altitude=0.0&speed=0.83&battery=93.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:17:25 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623734221&hdop=&altitude=0.0&speed=1.96&battery=93.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:17:29 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623734257&hdop=1.2&altitude=0.0&speed=0.15&battery=93.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:18:09 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623734296&hdop=1.1&altitude=0.0&speed=0.48&battery=93.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:19:08 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623734356&hdop=1.3&altitude=0.0&speed=0.9&battery=93.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:19:49 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623734396&hdop=1.2&altitude=0.0&speed=0.52&battery=93.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:20:27 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623734435&hdop=1.2&altitude=0.0&speed=0.25&battery=93.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:21:19 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623734486&hdop=1.4&altitude=0.0&speed=0.39&battery=93.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:21:59 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623734524&hdop=1.0&altitude=0.0&speed=0.0&battery=93.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:22:41 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623734565&hdop=1.0&altitude=0.0&speed=0.0&battery=93.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:23:24 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623734608&hdop=1.0&altitude=0.0&speed=0.0&battery=93.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:24:06 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623734653&hdop=1.0&altitude=0.0&speed=0.0&battery=92.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:24:44 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623734691&hdop=1.3&altitude=0.0&speed=0.0&battery=92.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:25:21 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623734728&hdop=1.1&altitude=0.0&speed=0.0&battery=92.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:26:01 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623734768&hdop=&altitude=0.0&speed=0.0&battery=92.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:26:36 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623734804&hdop=1.0&altitude=0.0&speed=0.0&battery=92.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:27:14 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623734841&hdop=1.0&altitude=0.0&speed=0.0&battery=92.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:27:53 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623734879&hdop=1.4&altitude=0.0&speed=0.0&battery=92.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:28:30 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623734917&hdop=0.8&altitude=0.0&speed=0.0&battery=92.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:29:15 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623734963&hdop=1.3&altitude=0.0&speed=2.17&battery=92.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:29:52 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623735000&hdop=1.2&altitude=0.0&speed=0.0&battery=92.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:30:37 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623735040&hdop=1.0&altitude=0.0&speed=0.0&battery=92.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:31:08 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623735065&hdop=&altitude=0.0&speed=0.0&battery=92.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:31:41 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623735080&hdop=&altitude=0.0&speed=0.0&battery=92.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:32:12 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623735091&hdop=&altitude=0.0&speed=0.0&battery=91.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:32:46 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623735101&hdop=&altitude=0.0&speed=0.0&battery=91.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:33:17 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623735109&hdop=&altitude=0.0&speed=0.0&battery=91.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:33:51 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623735117&hdop=&altitude=0.0&speed=0.0&battery=90.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:34:25 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623735127&hdop=&altitude=0.0&speed=0.0&battery=90.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:34:58 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623735137&hdop=&altitude=0.0&speed=0.0&battery=90.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:35:29 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623735145&hdop=&altitude=0.0&speed=0.0&battery=90.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:36:16 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623735156&hdop=&altitude=0.0&speed=0.0&battery=90.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:36:51 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623735163&hdop=&altitude=0.0&speed=0.0&battery=89.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:37:24 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623735169&hdop=&altitude=0.0&speed=0.0&battery=89.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:37:58 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623735175&hdop=&altitude=0.0&speed=0.0&battery=89.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:38:30 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623735180&hdop=&altitude=0.0&speed=0.0&battery=89.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:39:01 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623735185&hdop=&altitude=0.0&speed=0.0&battery=89.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:39:36 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623735190&hdop=&altitude=0.0&speed=0.0&battery=89.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:40:13 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623735195&hdop=&altitude=0.0&speed=0.0&battery=89.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:40:49 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623735200&hdop=&altitude=0.0&speed=0.0&battery=88.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:41:22 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623735205&hdop=&altitude=0.0&speed=0.0&battery=88.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:41:56 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623735210&hdop=&altitude=0.0&speed=0.0&battery=88.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:42:33 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623735215&hdop=1.4&altitude=0.0&speed=0.0&battery=88.0 HTTP/1.1" 200 "okhttp/3.7.0"
[15/Jun/2021:07:43:13 +0200] "GET /osmand/tracker.php?lat=0.0&lon=0.0&timestamp=1623735220&hdop=1.4&altitude=0.0&speed=0.0&battery=87.0 HTTP/1.1" 200 "okhttp/3.7.0"

finkandreas avatar Jun 15 '21 05:06 finkandreas

Looking at the server log, when it starts to stop working seems to be related an empty hdop parameter. Once hdop is empty it starts to send old locations, and not the current one. Any idea what I could try for further debugging / fixing the issue?

finkandreas avatar Jun 15 '21 07:06 finkandreas

If you're several same locations in a row, that could be due to network locations. I think the Custom URL lets you send a provider too, you could try sending that and you may see that pattern reflected in your logs.

If you turn network locations off you should see more accurate locations sent. The hdop is usually included with GPS location listener.

The other thing you mentioned, I can't figure out why the phone would start to slow down. This app uses a job queue which queues up the sending of the URLs and should be efficient and runs in the background!

mendhak avatar Jul 08 '21 19:07 mendhak

I believe I am suffering a similar problem. The device is mostly offline, and used to queue up information and send it successfully when back on line. Now sections of the queued information is missing or I appear to suffer the mentioned slowdown problem when online data resumes. If the data is kept online, not how the device normally works, the information is generally present. What are next steps to troubleshoot?

qsysopr1 avatar Sep 26 '21 11:09 qsysopr1

Maybe it could make sense to restart the logging service when loc.getTime() differs significantly (e.g. >30 seconds) compared to the current system timestamp. I think somewhere here one could check it and restart if necessary.

Unlike @qsysopr1 I cannot confirm that my device is offline, it is online all the time, only that loc.getTime() suddenly starts to have the wrong time. I.e. the timestamp parameter that is sent to the server is completely different than the time as it is printed in the LogView of the application. Just tested it with the newest version from F-Droid, and it still happens.

finkandreas avatar Sep 30 '21 12:09 finkandreas

Additionally I should mention that the GPS mode is set to "Device only", i.e. it should never be network locations (global Android setting, not a setting in the application). I tried to set the GPS mode to "High accuracy" but also there after some time the timestamp starts to diverge from the real system time (and also the location latitude/longitude is from the place where I was in the past, and not where I currently am). E.g. it is already in real life 15:00, but the location timestamp is 14:30, and the location latitude/longitude is from where I was at 14:30. However between 14:30 and 15:00 every 30 seconds a location was sent, i.e. it continuously sends some information, only that the information does not move forward in time as fast as real life (compare e.g. the last line of my log in the first post, there real life time is 07:43:13, but the location timestamp is from 07:33:40).

finkandreas avatar Sep 30 '21 13:09 finkandreas

In version 119 (updated in November) I've added a Custom URL Sender feature. Normal logging will still log to URL, but the auto send feature will happen on an interval from a CSV file (autosending Custom URL will enable CSV logging)

So another way to approach this is you can also enable CSV logging and 'upload' it to custom URL, where each line in the CSV gets translated to an HTTP request and sent.

That should help with the reliability aspect, or at least eliminate it being related to lost HTTP requests.

On the time drift aspect. I've also been trying out just Custom URL logging without any file writes but everything's fine, nothing is being missed and I'm not seeing anything like you're describing. Could you try out the Auto Send feature instead and maybe that is good enough to 'ignore' the problem?

mendhak avatar Dec 17 '21 11:12 mendhak