Bug 89782

Summary: 2nd client app gets invalid location & causes critical warnings
Product: GeoClue Reporter: Fabrice Bellet <fabrice>
Component: GeneralAssignee: Geoclue Bugs <geoclue-bugs>
Status: RESOLVED FIXED QA Contact: Geoclue Bugs <geoclue-bugs>
Severity: normal    
Priority: medium CC: fabrice, zeenix
Version: unspecified   
Hardware: Other   
OS: All   
Whiteboard:
i915 platform: i915 features:
Attachments: service-client: Don't steal location ref
backtrace of the where-am-i client just after the GLib-CRITICAL
geoclue log with G_MESSAGES_DEBUG=all G_DBUS_DEBUG=message
where-am-i log with G_MESSAGES_DEBUG=all G_DBUS_DEBUG=message
service-client: Delay unrefing ServiceLocation

Description Fabrice Bellet 2015-03-26 22:23:42 UTC
Here is what I observe: first I launch src/geoclue -t 10, then I start a first where-am-i -a 8 -t 120 :

[bellet@bonobo geoclue (master *%)]$ ./demo/where-am-i -a 8  -t 120
Client object: /org/freedesktop/GeoClue2/Client/1

New location:
Latitude: 45.767600
Longitude: 4.834500
Accuracy (in meters): 50000.000000

New location:
Latitude: 45.885012
Longitude: -1.189927
Accuracy (in meters): 1.000000

GPS lat/lon are not coherent, but this is normal, I made fake gps NMEA traces in ModemManager to test stuff without going outside to have good satellites signal:)

And then I start a second where-am-i -a 8 -t 120, while the first one is still running :
[bellet@bonobo geoclue (master *%)]$  ./demo/where-am-i -a 8  -t 120
Client object: /org/freedesktop/GeoClue2/Client/2

(where-am-i:1785): GLib-CRITICAL **: g_variant_get_type: assertion 'value != NULL' failed

(where-am-i:1785): GLib-CRITICAL **: g_variant_type_is_subtype_of: assertion 'g_variant_type_check (type)' failed

(where-am-i:1785): GLib-CRITICAL **: g_variant_get_double: assertion 'g_variant_is_of_type (value, G_VARIANT_TYPE_DOUBLE)' failed

(where-am-i:1785): GLib-CRITICAL **: g_variant_get_type: assertion 'value != NULL' failed

(where-am-i:1785): GLib-CRITICAL **: g_variant_type_is_subtype_of: assertion 'g_variant_type_check (type)' failed

(where-am-i:1785): GLib-CRITICAL **: g_variant_get_double: assertion 'g_variant_is_of_type (value, G_VARIANT_TYPE_DOUBLE)' failed

(where-am-i:1785): GLib-CRITICAL **: g_variant_get_type: assertion 'value != NULL' failed

(where-am-i:1785): GLib-CRITICAL **: g_variant_type_is_subtype_of: assertion 'g_variant_type_check (type)' failed

(where-am-i:1785): GLib-CRITICAL **: g_variant_get_double: assertion 'g_variant_is_of_type (value, G_VARIANT_TYPE_DOUBLE)' failed

(where-am-i:1785): GLib-CRITICAL **: g_variant_get_type: assertion 'value != NULL' failed

(where-am-i:1785): GLib-CRITICAL **: g_variant_type_is_subtype_of: assertion 'g_variant_type_check (type)' failed

(where-am-i:1785): GLib-CRITICAL **: g_variant_get_double: assertion 'g_variant_is_of_type (value, G_VARIANT_TYPE_DOUBLE)' failed

New location:
Latitude: 0.000000
Longitude: 0.000000
Accuracy (in meters): 0.000000
Altitude (in meters): 0.000000

(where-am-i:1785): GLib-CRITICAL **: g_variant_get_string: assertion 'value != NULL' failed
Description: (null)

New location:
Latitude: 45.767600
Longitude: 4.834500
Accuracy (in meters): 50000.000000

New location:
Latitude: 45.885012
Longitude: -1.189927
Accuracy (in meters): 1.000000
^C

The log of the server :
(gdb) r
`/home/bellet/Development/geoclue/src/geoclue' has changed; re-reading symbols.
Starting program: /home/bellet/Development/geoclue/src/geoclue -t 10
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
[New Thread 0x7fffee7b8700 (LWP 1771)]
[New Thread 0x7fffedfb7700 (LWP 1772)]
(geoclue:1769): Geoclue-DEBUG: Available accuracy level from GClueWifi: 4
(geoclue:1769): Geoclue-DEBUG: New agent for user ID '1000'
(geoclue:1769): Geoclue-DEBUG: New modem '/org/freedesktop/ModemManager1/Modem/0'
(geoclue:1769): Geoclue-DEBUG: Modem '/org/freedesktop/ModemManager1/Modem/0' has location capabilities
(geoclue:1769): Geoclue-DEBUG: Available accuracy level from GClue3G: 5
(geoclue:1769): Geoclue-DEBUG: Available accuracy level from GClueModemGPS: 8
(geoclue:1769): Geoclue-DEBUG: Number of connected clients: 1
(geoclue:1769): Geoclue-DEBUG: Service now in use
(geoclue:1769): Geoclue-DEBUG: GClueLocator now active
(geoclue:1769): Geoclue-DEBUG: GClue3G now active
(geoclue:1769): Geoclue-DEBUG: Not starting GClueCDMA (accuracy level: 0). Requested accuracy level: 8.
(geoclue:1769): Geoclue-DEBUG: GClueWifi now active
(geoclue:1769): Geoclue-DEBUG: Network available
(geoclue:1769): Geoclue-DEBUG: Sending following request to 'https://location.services.mozilla.com/v1/geolocate?key=geoclue':
{}
(geoclue:1769): Geoclue-DEBUG: GClueModemGPS now active
(geoclue:1769): Geoclue-DEBUG: 'geoclue-where-am-i' started.
(geoclue:1769): Geoclue-DEBUG: manager '/org/freedesktop/ModemManager1/Modem/0' enabled.
(geoclue:1769): Geoclue-DEBUG: manager '/org/freedesktop/ModemManager1/Modem/0' enabled.
(geoclue:1769): Geoclue-DEBUG: Modem '/org/freedesktop/ModemManager1/Modem/0' setup.
(geoclue:1769): Geoclue-DEBUG: Network available
(geoclue:1769): Geoclue-DEBUG: Sending following request to 'https://location.services.mozilla.com/v1/geolocate?key=geoclue':
{"radioType":"gsm","cellTowers":[{"cellId":26476705,"mobileCountryCode":208,"mobileNetworkCode":20,"locationAreaCode":20041}]}
(geoclue:1769): Geoclue-DEBUG: No GGA trace
(geoclue:1769): Geoclue-DEBUG: New 3GPP location is same as last one
[New Thread 0x7fffe6a00700 (LWP 1784)]
(geoclue:1769): Geoclue-DEBUG: No GGA trace
(geoclue:1769): Geoclue-DEBUG: Modem '/org/freedesktop/ModemManager1/Modem/0' setup.
(geoclue:1769): Geoclue-DEBUG: New 3GPP location is same as last one
(geoclue:1769): Geoclue-DEBUG: No GGA trace
(geoclue:1769): Geoclue-DEBUG: Got following response from 'https://location.services.mozilla.com/v1/geolocate?key=geoclue':
{"location": {"lat": 45.7676, "lng": 4.8345}, "accuracy": 50000.0}
(geoclue:1769): Geoclue-DEBUG: New location available
(geoclue:1769): Geoclue-DEBUG: Got following response from 'https://location.services.mozilla.com/v1/geolocate?key=geoclue':
{"location": {"lat": 45.7526265, "lng": 4.8570056}, "accuracy": 139320.0}
(geoclue:1769): Geoclue-DEBUG: New location available
(geoclue:1769): Geoclue-DEBUG: Ignoring less accurate new location
(geoclue:1769): Geoclue-DEBUG: New 3GPP location is same as last one
(geoclue:1769): Geoclue-DEBUG: New GPGGA trace: $GPGGA,192436.000,4553.1007,N,00111.3956,W,1,5,1.72,290.9,M,48.5,M,,*55

(geoclue:1769): Geoclue-WARNING **: Failed to create submission query: No WiFi devices available
(geoclue:1769): Geoclue-DEBUG: New location available
[Thread 0x7fffe6a00700 (LWP 1784) exited](geoclue:1769): Geoclue-DEBUG: Number of connected clients: 2
(geoclue:1769): Geoclue-DEBUG: GClueLocator now active
(geoclue:1769): Geoclue-DEBUG: New location available
(geoclue:1769): Geoclue-DEBUG: XXX prev_loc=0 loc=0
(geoclue:1769): Geoclue-DEBUG: GClue3G already active, not starting.
(geoclue:1769): Geoclue-DEBUG: Not starting GClueCDMA (accuracy level: 0). Requested accuracy level: 8.
(geoclue:1769): Geoclue-DEBUG: New location available
(geoclue:1769): Geoclue-DEBUG: GClueWifi already active, not starting.
(geoclue:1769): Geoclue-DEBUG: New location available
(geoclue:1769): Geoclue-DEBUG: GClueModemGPS already active, not starting.
(geoclue:1769): Geoclue-DEBUG: 'geoclue-where-am-i' started.

it seems to be related to the g_clear_object (&priv->prev_location); in function on_locator_location_changed(). Removing the g_clear_object(), and the second "where-am-i" invocation displays the 3 consecutive location updates :
[bellet@bonobo geoclue (master *%)]$  ./demo/where-am-i -a 8  -t 120
Client object: /org/freedesktop/GeoClue2/Client/2

New location:
Latitude: 45.752626
Longitude: 4.857006
Accuracy (in meters): 139320.000000

New location:
Latitude: 45.767600
Longitude: 4.834500
Accuracy (in meters): 50000.000000

New location:
Latitude: 45.885012
Longitude: -1.189927
Accuracy (in meters): 1.000000

The dbus debugging flags reveal this error server-side:
========================================================================
GDBus-debug:Message:
  <<<< RECEIVED D-Bus message (222 bytes)
  Type:    method-call
  Flags:   none
  Version: 0
  Serial:  34
  Headers:
    path -> objectpath '/org/freedesktop/GeoClue2/Client/2/Location/0'
    interface -> 'org.freedesktop.DBus.Properties'
    member -> 'GetAll'
    destination -> ':1.10217'
    sender -> ':1.10219'
    signature -> signature 's'
  Body: ('org.freedesktop.GeoClue2.Location',)
  UNIX File Descriptors:
    (none)
========================================================================
GDBus-debug:Incoming:
 <<<< METHOD INVOCATION org.freedesktop.DBus.Properties.GetAll()
      on object /org/freedesktop/GeoClue2/Client/2/Location/0
      invoked by name :1.10219
      serial 34
========================================================================
GDBus-debug:Message:
  >>>> SENT D-Bus message (232 bytes)
  Type:    error
  Flags:   no-reply-expected
  Version: 0
  Serial:  101
  Headers:
    error-name -> 'org.freedesktop.DBus.Error.UnknownMethod'
    reply-serial -> uint32 34
    destination -> ':1.10219'
    signature -> signature 's'
  Body: ("No such interface 'org.freedesktop.DBus.Properties' on object at path /org/freedesktop/GeoClue2/Client/2/Location/0",)
  UNIX File Descriptors:
    (none)
========================================================================
Comment 1 Zeeshan Ali 2015-03-26 23:49:11 UTC
Thanks for the bug and so many details! I'll look into this tomorrow.
Comment 2 Fabrice Bellet 2015-03-27 00:07:57 UTC
it seems most (but not all) of these objects are unref()ed anyway, when closing the client :

#0  0x000000000040b785 in gclue_service_location_finalize (object=0xa02b60 [GClueServiceLocation]) at gclue-service-location.c:58
#1  0x00007ffff7080c46 in g_object_unref (_object=0xa02b60) at gobject.c:3170
#2  0x000000000040aa8f in gclue_service_client_finalize (object=0xa13340 [GClueServiceClient]) at gclue-service-client.c:444
#3  0x00007ffff7080c46 in g_object_unref (_object=0xa13340) at gobject.c:3170
#4  0x00007ffff6d6b2b8 in g_hash_table_remove_internal (hash_table=0x654270 = {...}, key=0x68d900, notify=1) at ghash.c:1300
#5  0x0000000000408b39 in on_peer_vanished (info=0x6ab1e0 [GClueClientInfo], user_data=0x6541f0) at gclue-service-manager.c:113
#6  0x00007ffff707be84 in _g_closure_invoke_va (closure=closure@entry=0xa134f0,	return_value=return_value@entry=0x0, instance=ins
tance@entry=0x6ab1e0, args=args@entry=0x7fffffffd540, n_params=<optimized out>,	param_types=0x0) at gclosure.c:831
#7  0x00007ffff7095b00 in g_signal_emit_valist (instance=0x6ab1e0, signal_id=<optimized out>, detail=0, var_args=var_args@entry=0
x7fffffffd540) at gsignal.c:3218
#8  0x00007ffff709634f in g_signal_emit (instance=<optimized out>, signal_id=<optimized out>, detail=<optimized out>) at gsignal.
c:3365
#9  0x000000000041582d in on_name_vanished (connection=0x651280 [GDBusConnection], name=0x6935f0 ":1.10718", user_data=0x6ab1e0)
at gclue-client-info.c:177
#10 0x00007ffff739320a in do_call (client=client@entry=0xa710d0, call_type=call_type@entry=CALL_TYPE_NAME_VANISHED) at gdbusnamew
atching.c:216
#11 0x00007ffff7393415 in call_vanished_handler (client=client@entry=0xa710d0, ignore_cancelled=0) at gdbusnamewatching.c:242
#12 0x00007ffff73936f8 in on_name_owner_changed (connection=<optimized out>, sender_name=0x7fffe0009ac0 "org.freedesktop.DBus",	o
bject_path=<optimized out>, interface_name=0x7fffe000b280 "org.freedesktop.DBus", signal_name=<optimized out>, parameters=0x7fffe
0007120, user_data=0xa710d0) at gdbusnamewatching.c:307
#13 0x00007ffff73841e4 in emit_signal_instance_in_idle_cb (data=0x7fffe0003190)	at gdbusconnection.c:3753
#14 0x00007ffff6d7c7fb in g_main_context_dispatch (context=0x64d4e0) at gmain.c:3111
#15 0x00007ffff6d7c7fb in g_main_context_dispatch (context=context@entry=0x64d4e0) at gmain.c:3710
#16 0x00007ffff6d7cb98 in g_main_context_iterate (context=0x64d4e0, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimiz
ed out>) at gmain.c:3781
#17 0x00007ffff6d7cec2 in g_main_loop_run (loop=0x652210) at gmain.c:3975
#18 0x0000000000407b45 in main (argc=1, argv=0x7fffffffd948) at gclue-main.c:192
Comment 3 Fabrice Bellet 2015-03-27 09:45:41 UTC
A possible fix could be to add another *previous previous* location, and to g_clear_object() this one, but it wont scale very well :)
Comment 4 Zeeshan Ali 2015-03-28 15:56:03 UTC
Created attachment 114683 [details] [review]
service-client: Don't steal location ref

gclue_location_source_get_location() doesn't transfer ownership of the
return location object so caller must add its own reference to it.

This fixes the issue of 2nd app causing criticals warnings on geoclue's
log and getting wrong and invalid location.
Comment 5 Zeeshan Ali 2015-03-28 15:57:25 UTC
Try the patch I just attached.
Comment 6 Zeeshan Ali 2015-03-28 16:01:24 UTC
(In reply to Zeeshan Ali from comment #5)
> Try the patch I just attached.

Actually ignore that patch, I should grab lunch before looking into this.. :)
Comment 7 Zeeshan Ali 2015-03-28 17:17:38 UTC
(In reply to Fabrice Bellet from comment #3)
> A possible fix could be to add another *previous previous* location, and to
> g_clear_object() this one, but it wont scale very well :)

To come up with the proper fix, we first need to figure what exactly is the issue. Removing a g_clear_object() call doesn't really explains this to me. Each client has its own ServiceClient instance and also ServiceLocation (even though the internal Locator & Location instance might be the same).

A backtrace of the first warning/critical on geoclue, would likely help.
Comment 8 Fabrice Bellet 2015-03-31 19:28:36 UTC
Created attachment 114784 [details]
backtrace of the where-am-i client just after the GLib-CRITICAL

The backtrace of the client at line where-am-i.c:102, the location GDBusProxy concerned by this is the first Location announced by geoclue "/org/freedesktop/GeoClue2/Client/3/Location/0" for this client. We will see this is important in the following logs, because two other locations are following, sent by geoclue, but not received by the client.
Comment 9 Fabrice Bellet 2015-03-31 19:30:21 UTC
Created attachment 114785 [details]
geoclue log with G_MESSAGES_DEBUG=all G_DBUS_DEBUG=message

Debug log of geoclue.
Comment 10 Fabrice Bellet 2015-03-31 19:41:50 UTC
Created attachment 114786 [details]
where-am-i log with G_MESSAGES_DEBUG=all G_DBUS_DEBUG=message

This second log is the one from where-am-i, and matches the geoclue log. I hope it'll provide more details:

from geoclue side :
 * 3 consecutive LocationUpdated messages are sent (serial 95, 96 and 97)
 * The GetAll message from where-am-i is received _after_ that batch (serial 34, 35 and 36)
 * first reply from geoclue is: "No such interface" (serial 100, for Location/0)
 * Replies for Location/1 and Location/2 contains a Body with an actual location (serial 101 and 102)

from where-am-i side:
 * first reply from geoclue (serial 100) causes the warning.
 * 2nd the 3rd replies from geoclue (serial 101 and 102) are correctly handled.
Comment 11 Zeeshan Ali 2015-04-01 12:29:42 UTC
I think I have a clue of whats going on and I think need for 2 clients to reproduce it is simply helping to realize the bug but not the actual cause of it. What happens (or at least could happen) is that we end up unrefing (and therefore destroying the Location dbus service object) while its being used/accessed by the app still. The reason this happens only with second client is that if sources are already active, the location is updated multiple times in a very short window of time and hence we end-up destroying a location dbus object while client is still accessing it.
Comment 12 Zeeshan Ali 2015-04-01 17:27:26 UTC
Created attachment 114819 [details] [review]
service-client: Delay unrefing ServiceLocation

Lets try to ensure that apps are not still accessing the last location
before unrefing (and therefore destroying) it by delaying the unref
operation by 5 seconds after a ServiceLocation object becomes obsolete.
Comment 13 Zeeshan Ali 2015-04-01 17:28:00 UTC
(In reply to Zeeshan Ali from comment #12)
> Created attachment 114819 [details] [review] [review]
> service-client: Delay unrefing ServiceLocation

Could you please test if this helps?
Comment 14 Fabrice Bellet 2015-04-01 20:34:27 UTC
Yes, it works fine with this patch. But note that the behaviour I observed initially in this bug report is now different since bug #89719 has been fixed : we don't have three "new location" notifications consecutively, since we correctly order the sources to only provide the best location. But this problem is still there, and may reappear back in the future for other reasons, so I think this fix is still needed anyway.
Comment 15 Zeeshan Ali 2015-04-02 10:43:51 UTC
(In reply to Fabrice Bellet from comment #14)
> Yes, it works fine with this patch. But note that the behaviour I observed
> initially in this bug report is now different since bug #89719 has been
> fixed : we don't have three "new location" notifications consecutively,
> since we correctly order the sources to only provide the best location. But
> this problem is still there, and may reappear back in the future for other
> reasons, so I think this fix is still needed anyway.

Thanks for testing. Just to be sure, you tried it w/o patches in bug#89719 ? And yes, I agree that this potential issue will still be good to fix.
Comment 16 Fabrice Bellet 2015-04-02 20:51:28 UTC
(In reply to Zeeshan Ali from comment #15)

> Thanks for testing. Just to be sure, you tried it w/o patches in bug#89719 ?

Yes, I tested without the patch from bug #89719
Comment 17 Zeeshan Ali 2015-04-03 14:59:23 UTC
(In reply to Fabrice Bellet from comment #16)
> (In reply to Zeeshan Ali from comment #15)
> 
> > Thanks for testing. Just to be sure, you tried it w/o patches in bug#89719 ?
> 
> Yes, I tested without the patch from bug #89719

Thanks. I'll push it then.
Comment 18 Zeeshan Ali 2015-04-03 15:02:15 UTC
Pushed attachment#114819 [details] [review].

Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.