Actvities fail to start when no connection is available

[sascha_silbe]

After updating Sugar there are lots of Tracebacks like the following in shell.log and at least the buddy palette doesn't show up on right-click. Haven't done much further testing (activities don't start up either) as I expect most things to be broken for the same reason.

1282409076.591667 ERROR dbus.connection: Exception in handler for D-Bus signal:
Traceback (most recent call last):
  File "/usr/lib/pymodules/python2.6/dbus/connection.py", line 214, in maybe_handle_message
    self._handler(*args, **kwargs)
  File "/home/sascha.silbe/sugar-jhbuild/install/lib/python2.6/site-packages/jarabe/model/buddy.py", line 143, in __name_owner_changed_cb
    Connection(name, path, ready_handler=self.__connection_ready_cb)
  File "/usr/lib/python2.6/dist-packages/telepathy/client/conn.py", line 49, in __init__
    object = self.bus.get_object(service_name, object_path)
  File "/usr/lib/pymodules/python2.6/dbus/bus.py", line 244, in get_object
    follow_name_owner_changes=follow_name_owner_changes)
  File "/usr/lib/pymodules/python2.6/dbus/proxies.py", line 241, in __init__
    self._named_service = conn.activate_name_owner(bus_name)
  File "/usr/lib/pymodules/python2.6/dbus/bus.py", line 183, in activate_name_owner
    self.start_service_by_name(bus_name)
  File "/usr/lib/pymodules/python2.6/dbus/bus.py", line 281, in start_service_by_name
    'su', (bus_name, flags)))
  File "/usr/lib/pymodules/python2.6/dbus/connection.py", line 630, in call_blocking
    message, timeout)
DBusException: org.freedesktop.DBus.Error.ServiceUnknown: The name org.freedesktop.Telepathy.Connection.salut.local_xmpp.Sascha_20Silbe was not provided by any .service files

FWIW, testing happened on Debian Squeeze inside a chroot. I wasn't brave enough to try running it on a "native" system.

[tomeu]

So about the buddy palette, turned out to be a typo introduced during the merge and the fix should be in a release already.

About Sugar not finding dbus services, we should do the usual dbus debugging dance and find out of the services are auto-starting correctly, if are not crashing, if dbus policy is not forbidding access, etc

Are you having any other dbus trouble in that particular environment?

[sascha_silbe]

Replying to tomeu:

So about the buddy palette, turned out to be a typo introduced during the merge and the fix should be in a release already.

Thanks, the palette works fine now.

About Sugar not finding dbus services, we should do the usual dbus debugging dance and find out of the services are auto-starting correctly, if are not crashing, if dbus policy is not forbidding access, etc

It seems telepathy-salut is dying right on startup, though without timestamps in telepathy-salut.log I can't be sure:

(telepathy-salut:14957): tp-glib/connection-DEBUG: tp_base_connection_register: bus name org.freedesktop.Telepathy.Connection.salut.local_xmpp.Sascha_20Silbe
(telepathy-salut:14957): tp-glib/connection-DEBUG: tp_base_connection_register: object path /org/freedesktop/Telepathy/Connection/salut/local_xmpp/Sascha_20Silbe
(telepathy-salut:14957): tp-glib/presence-DEBUG: tp_presence_mixin_get_simple_presence_dbus_property: called.
(telepathy-salut:14957): tp-glib/presence-DEBUG: check_status_available: requested status offline is not available
(telepathy-salut:14957): tp-glib/connection-DEBUG: tp_presence_mixin_get_contacts_dbus_property: called.
(telepathy-salut:14957): tp-glib/presence-DEBUG: tp_presence_mixin_simple_presence_set_presence: called.
(telepathy-salut:14957): tp-glib/presence-DEBUG: check_for_status: Found status "available", checking if it's available...
(telepathy-salut:14957): tp-glib/connection-DEBUG: tp_base_connection_change_status: was 4294967295, now 2, for reason 2
(telepathy-salut:14957): tp-glib/connection-DEBUG: tp_base_connection_change_status: emitting status-changed to 2, for reason 2
(telepathy-salut:14957): salut-DEBUG: salut_im_factory_close_all: closing channels

Are you having any other dbus trouble in that particular environment?

No trouble, but there's no system bus running (chroot) so Network Manager etc. will be unavailable. Also avahi-daemon isn't running for the same reason (chroot). If Salut doesn't work without those services, that's fine, but it shouldn't break Sugar.

telepathy-gabble is dying for unknown reasons as well, BTW:

(process:14904): tp-glib/proxy-DEBUG: tp_proxy_dispose: 0x1dcd060
(process:14904): tp-glib/proxy-DEBUG: tp_proxy_invalidate: 0x1dcd060: Proxy unreferenced
(process:14904): tp-glib/proxy-DEBUG: tp_proxy_finalize: 0x1dcd060
(process:14904): gabble-DEBUG: gabble_plugin_loader_probe: probing /home/sascha.silbe/sugar-jhbuild/install/lib64/telepathy/gabble-0
** (process:14904): DEBUG: gabble_plugin_create: loaded
(process:14904): gabble-DEBUG: plugin_loader_try_to_load: loaded 'Gateway registration plugin' version 0.9.17 (/home/sascha.silbe/sugar-jhbuild/install/lib64/telepathy/gabble-0/gateways.so), implementing these sidecars: org.freedesktop.Telepathy.Gabble.Plugin.Gateways
(telepathy-gabble:14904): tp-glib-DEBUG: started version 0.9.17 (telepathy-glib version 0.11.14)
(telepathy-gabble:14904): tp-glib/params-DEBUG: tp_base_protocol_sanitize_parameters: using specified value for account
(telepathy-gabble:14904): tp-glib/params-DEBUG: tp_base_protocol_sanitize_parameters: using specified value for password
(telepathy-gabble:14904): tp-glib/params-DEBUG: tp_base_protocol_sanitize_parameters: parameter server rejected by filter function
(telepathy-gabble:14904): tp-glib-DEBUG: no connections, and timed out
tp-glib-Message: Exiting
(telepathy-gabble:14904): tp-glib/proxy-DEBUG: tp_proxy_dispose: 0x1dcd0f0
(telepathy-gabble:14904): tp-glib/proxy-DEBUG: tp_proxy_invalidate: 0x1dcd0f0: Proxy unreferenced
(telepathy-gabble:14904): tp-glib/proxy-DEBUG: tp_proxy_finalize: 0x1dcd0f0

[sascha_silbe]

telepathy-salut.log

[sascha_silbe]

telepathy-gabble.log

[sascha_silbe]

shell.log

[sascha_silbe]

I've sugar.logger.trace()d __name_owner_changed_cb() for testing, BTW (it shows up in shell.log).
We're getting notified of quite a few changes. Is there anything we can do to filter these out on the bus level already?

[tomeu]

Replying to sascha_silbe:

Replying to tomeu:

About Sugar not finding dbus services, we should do the usual dbus debugging dance and find out of the services are auto-starting correctly, if are not crashing, if dbus policy is not forbidding access, etc

It seems telepathy-salut is dying right on startup, though without timestamps in telepathy-salut.log I can't be sure:

{{{
(telepathy-salut:14957): tp-glib/connection-DEBUG: tp_base_connection_register: bus name org.freedesktop.Telepathy.Connection.salut.local_xmpp.Sascha_20Silbe
(telepathy-salut:14957): tp-glib/connection-DEBUG: tp_base_connection_register: object path /org/freedesktop/Telepathy/Connection/salut/local_xmpp/Sascha_20Silbe
(telepathy-salut:14957): tp-glib/presence-DEBUG: tp_presence_mixin_get_simple_presence_dbus_property: called.
(telepathy-salut:14957): tp-glib/presence-DEBUG: check_status_available: requested status offline is not available
(telepathy-salut:14957): tp-glib/connection-DEBUG: tp_presence_mixin_get_contacts_dbus_property: called.
(telepathy-salut:14957): tp-glib/presence-DEBUG: tp_presence_mixin_simple_presence_set_presence: called.
(telepathy-salut:14957): tp-glib/presence-DEBUG: check_for_status: Found status "available", checking if it's available...
(telepathy-salut:14957): tp-glib/connection-DEBUG: tp_base_connection_change_status: was 4294967295, now 2, for reason 2
(telepathy-salut:14957): tp-glib/connection-DEBUG: tp_base_connection_change_status: emitting status-changed to 2, for reason 2
(telepathy-salut:14957): salut-DEBUG: salut_im_factory_close_all: closing channels
}}}

status 2 for reason 2 means disconnected because of network error, most likely because avahi-daemon is not running

 http://telepathy.freedesktop.org/spec/org.freedesktop.Telepathy.Connection.html#org.freedesktop.Telepathy.Connection.Connection_Status

Are you having any other dbus trouble in that particular environment?

No trouble, but there's no system bus running (chroot) so Network Manager etc. will be unavailable. Also avahi-daemon isn't running for the same reason (chroot). If Salut doesn't work without those services, that's fine, but it shouldn't break Sugar.

Yup, there's definitely something to fix in Sugar. Should be able to easily reproduce it here.

telepathy-gabble is dying for unknown reasons as well, BTW:

{{{
(process:14904): tp-glib/proxy-DEBUG: tp_proxy_dispose: 0x1dcd060
(process:14904): tp-glib/proxy-DEBUG: tp_proxy_invalidate: 0x1dcd060: Proxy unreferenced
(process:14904): tp-glib/proxy-DEBUG: tp_proxy_finalize: 0x1dcd060
(process:14904): gabble-DEBUG: gabble_plugin_loader_probe: probing /home/sascha.silbe/sugar-jhbuild/install/lib64/telepathy/gabble-0
** (process:14904): DEBUG: gabble_plugin_create: loaded
(process:14904): gabble-DEBUG: plugin_loader_try_to_load: loaded 'Gateway registration plugin' version 0.9.17 (/home/sascha.silbe/sugar-jhbuild/install/lib64/telepathy/gabble-0/gateways.so), implementing these sidecars: org.freedesktop.Telepathy.Gabble.Plugin.Gateways
(telepathy-gabble:14904): tp-glib-DEBUG: started version 0.9.17 (telepathy-glib version 0.11.14)
(telepathy-gabble:14904): tp-glib/params-DEBUG: tp_base_protocol_sanitize_parameters: using specified value for account
(telepathy-gabble:14904): tp-glib/params-DEBUG: tp_base_protocol_sanitize_parameters: using specified value for password
(telepathy-gabble:14904): tp-glib/params-DEBUG: tp_base_protocol_sanitize_parameters: parameter server rejected by filter function

Can you check what value has the server parameter in ~/.mission-control/accounts/accounts.cfg or ~/.sugar/default/accounts/accounts.cfg ?

[sascha_silbe]

Replying to tomeu:

status 2 for reason 2 means disconnected because of network error, most likely because avahi-daemon is not running

 http://telepathy.freedesktop.org/spec/org.freedesktop.Telepathy.Connection.html#org.freedesktop.Telepathy.Connection.Connection_Status

Ah, thanks for the pointer! It would still be nice if the debug log was less cryptic, though. The enum value "Network_Error" would have been much more useful than just a number.

Can you check what value has the server parameter in ~/.mission-control/accounts/accounts.cfg or ~/.sugar/default/accounts/accounts.cfg ?

param-server=

~/.mission-control/accounts/accounts.cfg attached (password changed for obvious reasons).

[sascha_silbe]

~/.mission-control/accounts/accounts.cfg (password changed)

[tomeu]

Replying to sascha_silbe:

Replying to tomeu:

status 2 for reason 2 means disconnected because of network error, most likely because avahi-daemon is not running

 http://telepathy.freedesktop.org/spec/org.freedesktop.Telepathy.Connection.html#org.freedesktop.Telepathy.Connection.Connection_Status

Ah, thanks for the pointer! It would still be nice if the debug log was less cryptic, though. The enum value "Network_Error" would have been much more useful than just a number.

Agreed:  https://bugs.freedesktop.org/show_bug.cgi?id=30104

Can you check what value has the server parameter in ~/.mission-control/accounts/accounts.cfg or ~/.sugar/default/accounts/accounts.cfg ?

{{{
param-server=
}}}

~/.mission-control/accounts/accounts.cfg attached (password changed for obvious reasons).

Filed  http://bugs.sugarlabs.org/ticket/2306

[sascha_silbe]

Replying to tomeu:

Agreed:  https://bugs.freedesktop.org/show_bug.cgi?id=30104

Thanks!

[tomeu]

Replying to sascha_silbe:

I've sugar.logger.trace()d __name_owner_changed_cb() for testing, BTW (it shows up in shell.log).
We're getting notified of quite a few changes. Is there anything we can do to filter these out on the bus level already?

For the one in buddy.py no because signal filtering works only by matching full strings. But the one in shell.py could definitively filter by service name: #2308

[tomeu]

The only way I have found in which activities fail to start when there aren't active connections is when a previously shared activity is launched:

 http://git.sugarlabs.org/projects/sugar-toolkit/repos/mainline/commits/a2b85184

If there are other situations in which activities fail to start, please attach the activity log. I'm closing this for now.

[sascha_silbe]

There are quite a few things broken currently when testing on my system and I never know if or how they're related. But here's a Traceback from Calculate that smells like this bug isn't fixed yet:

1284317110.802984 DEBUG PlotLib: Using custom plotting back-end
1284317110.832400 DEBUG root: *** Act 984c8ebe34c9cb8174aa0900a8c6a5772c2ea161, mesh instance None, scope private
1284317110.832599 DEBUG root: Creating a jobject.
1284317110.833804 DEBUG root: datastore.write
1284317110.833986 DEBUG root: write: file_path='', tree_id=None
1284317110.841910 DEBUG root: Written object (dbus.String(u'fb18b8cc-6165-44ef-a274-606ca9d3437c'), dbus.String(u'096bec19-caf2-46bc-90b3-6660523e5a72')) to the datastore.
Traceback (most recent call last):
  File "/home/sascha.silbe/sugar-jhbuild/install/bin/sugar-activity", line 21, in <module>
    main.main()
  File "/home/sascha.silbe/sugar-jhbuild/install/lib/python2.6/site-packages/sugar/activity/main.py", line 164, in main
    create_activity_instance(activity_constructor, activity_handle)
  File "/home/sascha.silbe/sugar-jhbuild/install/lib/python2.6/site-packages/sugar/activity/main.py", line 37, in create_activity_instance
    activity = constructor(handle)
  File "/home/sascha.silbe/sugar-jhbuild/install/share/sugar/activities/Calculate.activity/calculate.py", line 304, in __init__
    ShareableActivity.__init__(self, handle)
  File "/home/sascha.silbe/sugar-jhbuild/install/share/sugar/activities/Calculate.activity/shareable_activity.py", line 55, in __init__
    self._owner_id = str(self._owner._properties['nick'])
AttributeError: 'Owner' object has no attribute '_properties'
1284317110.846150 DEBUG root: _cleanup_temp_files
Exited with status 1, pid 20665 data (None, <open file '<fdopen>', mode 'w' at 0x2b0a150>, '984c8ebe34c9cb8174aa0900a8c6a5772c2ea161')

This is with the version support branch. If you can't reproduce it, I'll try mainline. Don't expect it to make any difference, though (otherwise I would have already tried).

[garycmartin]

Replying to sascha_silbe:

There are quite a few things broken currently when testing on my system and I never know if or how they're related. But here's a Traceback from Calculate that smells like this bug isn't fixed

I think I just fixed this #2245 if I read all that log correctly. Tomeu's fix is in the just released Calculate-33, .xo bundle up on ASLO, source on sunjammer at the usual place. If you have the time to test v33 as a sanity check, that would be great :)

[sascha_silbe]

Calculate works fine now. Sorry for the noise.
There's still some weird stuff going on, but it might have other reasons. Closing for now.

[tomeu]

Replying to sascha_silbe:

Calculate works fine now. Sorry for the noise.
There's still some weird stuff going on, but it might have other reasons. Closing for now.

Happy to look at logs in case it's something that can spotted like that.