[HERE] Here maps webapp AGPS location detection doesn't work (WiFi OFF, mobile data ON)

[Andrea Bernabei]

Krillin, rc-proposed, r169, here webapp 1.0.7

Description:
I start the app, and expect an immediate detection of my approximate location, but that doesn't happen.

Location and GPS settings in location-indicator are enabled, though the log of the app reports multiple errors which could be the culprit of this issue.

WiFi is OFF, mobile data is connected and working.

More info:
Please find the application log below
http://pastebin.ubuntu.com/13214964/

[Alberto Mardegan (mardy)]

Hi Andrea, are you still affected by this bug? If so, could you please make sure that you have accepted the HERE terms and conditions, and then continue with

  https://wiki.ubuntu.com/Process/Merges/TestPlan/location-service#Forensics

(the "HERE test" is especially relevant)

[Andrea Bernabei (faenil)]

Hi Alberto,

it was my plan to provide more logs today using the link you posted, but unfortunately it seems to be working at the moment...

It wasn't working overy the weekend, and now that I deleted logs to start fresh and get useful logs, it's working... :/
Please leave this open until I manage to reproduce it again :)

[Andrea Bernabei (faenil)]

Ok, it finally happened again :)

My setup:
Krillin, rc-proposed (after OTA9 freeze), r232

The content of /var/log/ubuntu-location-service/com.ubuntu.location.INFO is
I0116 21:01:57.030153 3319 skeleton.cpp:290] Failed to communicate position update to client: org.freedesktop.DBus.Error.LimitsExceeded: The maximum number of pending replies per connection has been reached
I0116 21:01:57.030221 3319 skeleton.cpp:290] Failed to communicate position update to client: org.freedesktop.DBus.Error.LimitsExceeded: The maximum number of pending replies per connection has been reached
I0116 21:01:57.030285 3319 skeleton.cpp:290] Failed to communicate position update to client: org.freedesktop.DBus.Error.LimitsExceeded: The maximum number of pending replies per connection has been reached
I0116 21:01:57.030354 3319 skeleton.cpp:290] Failed to communicate position update to client: org.freedesktop.DBus.Error.LimitsExceeded: The maximum number of pending replies per connection has been reached
I0116 21:01:57.030424 3319 skeleton.cpp:290] Failed to communicate position update to client: org.freedesktop.DBus.Error.LimitsExceeded:

NOTE1: that it is referring to 16Jan, so it's not referring to the test I have just made (18Jan 16:20 UK time)

NOTE2: I have the same output in /var/log/ubuntu-location-service/com.ubuntu.location.ubuntu-phablet.invalid-user.log.INFO.20160116-205932.3293

I don't have any other file in that folder (I cleared it about a week ago, and I'm quite sure location worked OK after I cleared those logs, so I don't think they had anything useful to offer)

The file /var/log/upstart/ubuntu-location-service.log has the following content:
 name -> com.ubuntu.espoo.Service.Provider
 path -> /com/ubuntu/espoo/Service/Provider
Instantiating and configuring: gps::Provider
Instantiating and configuring: remote::Provider
Attempted to unregister path (path[0] = core path[1] = trust) which isn't registered
Attempted to unregister path (path[0] = sessions path[1] = 0) which isn't registered
Attempted to unregister path (path[0] = sessions path[1] = 1) which isn't registered
Attempted to unregister path (path[0] = sessions path[1] = 2) which isn't registered
Attempted to unregister path (path[0] = sessions path[1] = 3) which isn't registered
Attempted to unregister path (path[0] = sessions path[1] = 4) which isn't registered
Attempted to unregister path (path[0] = sessions path[1] = 5) which isn't registered
Attempted to unregister path (path[0] = sessions path[1] = 6) which isn't registered
Attempted to unregister path (path[0] = sessions path[1] = 7) which isn't registered
Attempted to unregister path (path[0] = sessions path[1] = 8) which isn't registered
Attempted to unregister path (path[0] = core path[1] = trust) which isn't registered
Attempted to unregister path (path[0] = sessions path[1] = 9) which isn't registered
Attempted to unregister path (path[0] = sessions path[1] = 10) which isn't registered
Attempted to unregister path (path[0] = sessions path[1] = 11) which isn't registered

phablet@ubuntu-phablet:~$ ubuntu-location-serviced-cli --bus system --get --property visible_space_vehicles
Visible space vehicles:
 (type: gps, prn: 2, ...

[Andrea Bernabei (faenil)]

The output of "HERE test" is probably more useful
phablet@ubuntu-phablet:~$ GLOG_logtostderr=1 GLOG_v=100 LD_LIBRARY_PATH=/custom/vendor/here/location-provider/lib/arm-linux-gnueabihf ./espoo-cli 5
I0118 16:38:37.284291 30601 cli.cpp:117] Requested number of updates is 5
I0118 16:38:37.293683 30601 cli.cpp:133] Starting location updates
I0118 16:38:37.297725 30601 cli.cpp:141] Starting GLib main loop
I0118 16:38:37.298156 30601 cli.cpp:158] General error occurred
I0118 16:38:37.298270 30601 cli.cpp:170] Remaining updates: 4
I0118 16:38:49.581379 30601 cli.cpp:158] General error occurred
I0118 16:38:49.587518 30601 cli.cpp:170] Remaining updates: 3
I0118 16:38:52.514307 30601 cli.cpp:158] General error occurred
I0118 16:38:52.516453 30601 cli.cpp:170] Remaining updates: 2
I0118 16:39:04.577224 30601 cli.cpp:158] General error occurred
I0118 16:39:04.580479 30601 cli.cpp:170] Remaining updates: 1
I0118 16:39:07.514490 30601 cli.cpp:158] General error occurred
I0118 16:39:07.516743 30601 cli.cpp:148] Stopping location updates

[Andrea Bernabei (faenil)]

Strace seems to indicate that the app fails to communicate over dbus

clock_getres(CLOCK_MONOTONIC, {0, 1}) = 0
getresuid32([32011], [32011], [32011]) = 0
getresgid32([32011], [32011], [32011]) = 0
socket(PF_LOCAL, SOCK_STREAM|SOCK_CLOEXEC, 0) = 4
connect(4, {sa_family=AF_LOCAL, sun_path="/var/run/dbus/system_bus_socket"}, 33) = 0
fcntl64(4, F_GETFL) = 0x2 (flags O_RDWR)
fcntl64(4, F_SETFL, O_RDWR|O_NONBLOCK) = 0
geteuid32() = 32011
getsockname(4, {sa_family=AF_LOCAL, NULL}, [2]) = 0
poll([{fd=4, events=POLLOUT}], 1, 0) = 1 ([{fd=4, revents=POLLOUT}])
send(4, "\0", 1, MSG_NOSIGNAL) = 1
send(4, "AUTH EXTERNAL 3332303131\r\n", 26, MSG_NOSIGNAL) = 26
poll([{fd=4, events=POLLIN}], 1, -1) = 1 ([{fd=4, revents=POLLIN}])
read(4, "OK 5e33c9b32077f683d80ff37f569bb"..., 2048) = 37
poll([{fd=4, events=POLLOUT}], 1, -1) = 1 ([{fd=4, revents=POLLOUT}])
send(4, "NEGOTIATE_UNIX_FD\r\n", 19, MSG_NOSIGNAL) = 19
poll([{fd=4, events=POLLIN}], 1, -1) = 1 ([{fd=4, revents=POLLIN}])
read(4, "AGREE_UNIX_FD\r\n", 2048) = 15
poll([{fd=4, events=POLLOUT}], 1, -1) = 1 ([{fd=4, revents=POLLOUT}])
send(4, "BEGIN\r\n", 7, MSG_NOSIGNAL) = 7
poll([{fd=4, events=POLLIN|POLLOUT}], 1, -1) = 1 ([{fd=4, revents=POLLOUT}])
sendmsg(4, {msg_name(0)=NULL, msg_iov(2)=[{"l\1\0\1\0\0\0\0\1\0\0\0n\0\0\0\1\1o\0\25\0\0\0/org/fre"..., 128}, {"", 0}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 128
clock_gettime(CLOCK_MONOTONIC, {10541, 639488651}) = 0
poll([{fd=4, events=POLLIN}], 1, 25000) = 1 ([{fd=4, revents=POLLIN}])
recvmsg(4, {msg_name(0)=NULL, msg_iov(1)=[{"l\2\1\1\v\0\0\0\1\0\0\0=\0\0\0\6\1s\0\6\0\0\0:1.483\0\0"..., 2048}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_CMSG_CLOEXEC) = 262

SEE HERE -------->>>>recvmsg(4, 0xbef11e08, MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable)

futex(0xb6fb8ca0, FUTEX_WAKE_PRIVATE, 2147483647) = 0
eventfd2(0, O_NONBLOCK|O_CLOEXEC) = 5
write(5, "\1\0\0\0\0\0\0\0", 8) = 8
fstat64(4, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0
fcntl64(4, F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK)
write(5, "\1\0\0\0\0\0\0\0", 8) = 8
clock_gettime(CLOCK_MONOTONIC, {10541, 645155267}) = 0
sendmsg(4, {msg_name(0)=NULL, msg_iov(2)=[{"l\1\0\1$\0\0\0\2\0\0\0\177\0\0\0\1\1o\0\25\0\0\0/org/fre"..., 144}, {"\37\0\0\0interface='com.here.posclien"..., 36}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 180
clock_gettime(CLOCK_MONOTONIC, {10541, 645768036}) = 0
poll([{fd=4, events=POLLIN}], 1, 25000) = 1 ([{fd=4, revents=POLLIN}])
recvmsg(4, {msg_name(0)=NULL, msg_iov(1)=[{"l\2\1\1\0\0\0\0\3\0\0\0005\0\0\0\6\1s\0\6\0\0\0:1.483\0\0"..., 2048}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_CMSG_CLOEXEC) = 72
write(5, "\1\0\0\0\0\0\0\0", 8) = 8
recvmsg(4, 0xbef11e00, MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable)
clock_gettime(CLOCK_MONOTONIC, {10541, 648660497}) = 0
sendmsg(4, {msg_name(0)=NULL, msg_iov(2)=[{"l\1\0\1Z\0\0\0\3\0\0\0\177\0\0\0\1\1o\0\25\0\0\0/org/fre"..., 144}, {"U\0\0\0interface='org.freedesktop.D"..., 90}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 234
clock_gettime(CLOCK_MO...

[Andrea Bernabei (faenil)]

backtrace of ubuntu-service-espoo, as requested by mardy on IRC:
Thread 3 (Thread 0xb5977380 (LWP 2172)):
#0 0xffffffff in epoll_wait () at /lib/arm-linux-gnueabihf/libc.so.6
#1 0xffffffff in boost::asio::detail::epoll_reactor::run(bool, boost::asio::detail::op_queue<boost::asio::detail::task_io_service_operation>&) (this=0x6fd9f0, block=block@entry=true, ops=...) at /usr/include/boost/asio/detail/impl/epoll_reactor.ipp:392
#2 0xffffffff in boost::asio::detail::task_io_service::run(boost::system::error_code&) (ec=..., this_thread=..., lock=..., this=0x6fd920)
    at /usr/include/boost/asio/detail/impl/task_io_service.ipp:368
#3 0xffffffff in boost::asio::detail::task_io_service::run(boost::system::error_code&) (this=0x6fd920, ec=...)
    at /usr/include/boost/asio/detail/impl/task_io_service.ipp:153
#4 0xffffffff in core::dbus::asio::Executor::run() (this=0xb6e1b64c <core::dbus::asio::make_executor(std::shared_ptr<core::dbus::Bus> const&)::io>)
    at /usr/include/boost/asio/impl/io_service.ipp:59
#5 0xffffffff in core::dbus::asio::Executor::run() (this=<optimized out>) at /build/dbus-cpp-__7cPF/dbus-cpp-4.3.0+15.04.20160114.2/src/core/dbus/asio/executor.cpp:386
#6 0xffffffff in core::dbus::Bus::run() (this=<optimized out>) at /build/dbus-cpp-__7cPF/dbus-cpp-4.3.0+15.04.20160114.2/src/core/dbus/bus.cpp:355
#7 0xffffffff in std::(anonymous namespace)::execute_native_thread_routine(void*) (__p=<optimized out>) at ../../../../../src/libstdc++-v3/src/c++11/thread.cc:84
#8 0xffffffff in start_thread () at /lib/arm-linux-gnueabihf/libpthread.so.0
#9 0xffffffff in () at /lib/arm-linux-gnueabihf/libc.so.6

Thread 2 (Thread 0xb5177380 (LWP 2173)):
#0 0xffffffff in poll () at /lib/arm-linux-gnueabihf/libc.so.6
#1 0xffffffff in g_main_context_iterate (priority=2147483647, n_fds=2, fds=0xb4800c78, timeout=14986, context=0x6fde70)
    at /build/buildd/glib2.0-2.44.1/./glib/gmain.c:4103
#2 0xffffffff in g_main_context_iterate (context=0x6fde70, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>)
    at /build/buildd/glib2.0-2.44.1/./glib/gmain.c:3803
#3 0xffffffff in g_main_loop_run (loop=0x6fb040) at /build/buildd/glib2.0-2.44.1/./glib/gmain.c:4002
#4 0xffffffff in std::(anonymous namespace)::execute_native_thread_routine(void*) (__p=<optimized out>) at ../../../../../src/libstdc++-v3/src/c++11/thread.cc:84
#5 0xffffffff in start_thread () at /lib/arm-linux-gnueabihf/libpthread.so.0
#6 0xffffffff in () at /lib/arm-linux-gnueabihf/libc.so.6

Thread 1 (Thread 0xb59ae000 (LWP 2132)):
#0 0xffffffff in poll () at /lib/arm-linux-gnueabihf/libc.so.6
#1 0xffffffff in () at /usr/lib/arm-linux-gnueabihf/libprocess-cpp.so.2
#2 0x00023fae in espoo::Daemon::main(espoo::Daemon::Configuration const&) ()
#3 0x00024124 in main ()

[Alberto Mardegan (mardy)]

Thanks Andrea! The backtrace doesn't tell me much, but it looks like there could be something wrong with the espoo provider. Could you please alter the verbosity level as described in

    https://wiki.ubuntu.com/Process/Merges/TestPlan/location-service#location-service_and_espoo-service_debug

then reboot, reproduce the bug and then attach the /var/log/upstart/ubuntu-espoo-service.log file here?

[Andrea Bernabei (faenil)]

after reboot, location is still not working, here's the .log

(you see the StopPositionUpdates because I closed and opened the Here app a few times)

phablet@ubuntu-phablet:~$ sudo cat /var/log/upstart/ubuntu-espoo-service.log
pure virtual method called
terminate called without an active exception
WARNING: Logging before InitGoogleLogging() is written to STDERR
I0120 14:54:09.115571 2150 provider.cpp:552] Requires
I0120 14:54:09.120601 2150 provider.cpp:552] Requires
I0120 14:55:47.475638 2150 provider.cpp:603] StartPositionUpdates
I0120 14:55:47.492801 2150 provider.cpp:122] Successfully started position updates.
I0120 14:55:47.496340 2150 provider.cpp:631] StartVelocityUpdates
I0120 14:56:40.301992 2150 provider.cpp:610] StopPositionUpdates
I0120 14:56:40.311249 2150 provider.cpp:638] StartVelocityUpdates
I0120 14:56:42.433099 2150 provider.cpp:603] StartPositionUpdates
I0120 14:56:42.449034 2150 provider.cpp:122] Successfully started position updates.
I0120 14:56:42.454790 2150 provider.cpp:631] StartVelocityUpdates
I0120 14:56:42.554195 2150 provider.cpp:610] StopPositionUpdates
I0120 14:56:42.565136 2150 provider.cpp:638] StartVelocityUpdates
I0120 14:56:47.644302 2150 provider.cpp:603] StartPositionUpdates
I0120 14:56:47.657380 2150 provider.cpp:122] Successfully started position updates.
I0120 14:57:02.487563 2150 provider.cpp:631] StartVelocityUpdates
I0120 14:57:23.282002 2150 provider.cpp:610] StopPositionUpdates
I0120 14:57:23.285527 2150 provider.cpp:638] StartVelocityUpdates
I0120 14:57:35.939375 2150 provider.cpp:603] StartPositionUpdates
I0120 14:57:35.945593 2150 provider.cpp:122] Successfully started position updates.
I0120 14:57:35.947414 2150 provider.cpp:631] StartVelocityUpdates
I0120 14:58:34.547924 2150 provider.cpp:610] StopPositionUpdates
I0120 14:58:34.561696 2150 provider.cpp:638] StartVelocityUpdates
I0120 14:58:36.339428 2150 provider.cpp:603] StartPositionUpdates
I0120 14:58:36.349509 2150 provider.cpp:122] Successfully started position updates.
I0120 14:58:36.351335 2150 provider.cpp:631] StartVelocityUpdates
I0120 14:59:34.799387 2150 provider.cpp:610] StopPositionUpdates
I0120 14:59:34.811364 2150 provider.cpp:638] StartVelocityUpdates
I0120 14:59:36.594482 2150 provider.cpp:603] StartPositionUpdates
I0120 14:59:36.605473 2150 provider.cpp:122] Successfully started position updates.
I0120 14:59:36.607898 2150 provider.cpp:631] StartVelocityUpdates
I0120 15:00:35.055575 2150 provider.cpp:610] StopPositionUpdates
I0120 15:00:35.061935 2150 provider.cpp:638] StartVelocityUpdates
I0120 15:00:36.822139 2150 provider.cpp:603] StartPositionUpdates
I0120 15:00:36.845571 2150 provider.cpp:122] Successfully started position updates.
I0120 15:00:36.848531 2150 provider.cpp:631] StartVelocityUpdates

[Andrea Bernabei (faenil)]

aaand, after 15 minutes, here it is!
I0120 15:02:37.428824 2150 provider.cpp:122] Successfully started position updates.
I0120 15:02:37.430912 2150 provider.cpp:631] StartVelocityUpdates
I0120 15:17:17.749724 2151 provider.cpp:83] Received location: Position(lat: Coordinate(51.5057 deg), lon: Coordinate(-0.0983669 deg), alt: Coordinate(nan m), hor.acc.: 19328 m, ver.acc.: nan m)
I0120 15:17:17.751444 2151 provider.cpp:493] Position changed reported by impl: Update(Position(lat: Coordinate(51.5057 deg), lon: Coordinate(-0.0983669 deg), alt: Coordinate(nan m), hor.acc.: 19328 m, ver.acc.: nan m), 1453303037750405623)
I0120 15:17:17.758611 2150 provider.cpp:573] OnReferenceLocationChanged

[Andrea Bernabei (faenil)]

sorry, it was actually more like 20mins since I started the app.

now espoo-cli reports location as well.

At this point I'm not sure if this position is coming from AGPS or GPS itself (I'm 2-3mt from a big window, maybe GPS still comes through?)

or are the logs only referring to AGPS?

[Alberto Mardegan (mardy)]

On 20/01/2016 18:28, Andrea Bernabei wrote:
> sorry, it was actually more like 20mins since I started the app.
>
> now espoo-cli reports location as well.
>
> At this point I'm not sure if this position is coming from AGPS or GPS
> itself (I'm 2-3mt from a big window, maybe GPS still comes through?)
>
> or are the logs only referring to AGPS?

The log message is coming from the espoo provider, which implements the
AGPS method; however, I think that it also receives updates coming from
the other location providers (that is, also from the GPS) and it might
be that it's just forwarding the GPS position back.

Do you happen to have the /var/log/upstart/ubuntu-location-service.log
for the same moment of time? That might tell us where the location
originated from.

[Andrea Bernabei (faenil)]

please find the log attached

[Andrea Bernabei (faenil)]

from the log above it seems that the provider actually knew the position all the time but it didn't communicate it to ubuntu-espoo?

[Alberto Mardegan (mardy)]

Thanks a lot Andrea, for your logs! My understanding of the situation, after looking at the source code, is the following:

- While it's true that the location service propagates the location updates to all providers, it seems that the Espoo provider is ignoring this information; therefore, the fix you get at 15:17:17 is actually the AGPS fix from Nokia HERE

- the on_nmea_update() handler in the GPS provider is just logging the data, it's not using it actively; GPS updates are handled via the on_location_update() method, of which there are no traces in your logs

- the NMEA $GPGGA you receive have always the "Fix quality" field set to 0, meaning that they are invalid (see http://aprs.gids.nl/nmea/#gga); this seems to be confirmed by the fact that they always have the same value, which is a bit unrealistic in a real world scenario. It's probably some cached value.

So, my conclusion is that the espoo provider took actually 15-20 minutes to deliver you a result.
The core functionality of the espoo provider is implemented in the "herepositioning" package, of which I cannot seem to be able to find the source code.

But bugs aside, Andrea, could you please describe your location? How many access points are visible? Is it in a high floor? I'm just wondering if the reason why HERE fails is that it lacks the data to correlate the visible APs with a geolocation.

[Andrea Bernabei (faenil)]

The tests above are done with GPS off, so that it only uses mobile data (3G data is working on the phone)

The location is Canonical's London office, BlueFin building, 5th floor

[Andrea Bernabei (faenil)]

with WiFi off I meant, not GPS off, sorry

[Andrea Bernabei (faenil)]

being central London I doubt HERE doesn't have enough data to correlate the GSM tower to an approximate location :)

tvoss told me location-service currently only uses 1 GSM and not the "visible towers around", but that should still be enough for a very quick approximate location detection

[Tiago Carrondo (tcarrondo)]

Is the GPS activated in the battery menu?

I think the bug isn't on the GPS itself but in the top screen switch, that doesn't actually activate it.
I say this comparing with the behaviour on the rc: when I activate GPS it get's activated on the battery menu.

[Andrea Bernabei (faenil)]

@Alberto Mardegan: can you please switch the bug back to "Confirmed"?

I still can't get position when WiFi is off and 3G is enabled and working.

Krillin, rc-proposed, r351