Attachment 26924 Details for Bug 22023 – gabble debug output from test-vcard-race failing

gabble debug output from test-vcard-race failing

failing.log (text/plain), 13.51 KB, created by Will Thompson on 2009-06-18 08:53:08 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Will Thompson

Created: 2009-06-18 08:53:08 UTC

Size: 13.51 KB

patch

obsolete

>tp-glib-DEBUG: tp_proxy_borrow_interface_by_id: 0xe3e0f0: org.freedesktop.DBus DBusGProxy is 0xe3e2b0
>tp-glib-DEBUG: started version 0.7.28.1 (telepathy-glib version 0.7.32)
>tp-glib-DEBUG: tp_cm_param_setter_offset: account = "test@localhost/Resource"
>tp-glib-DEBUG: tp_cm_param_setter_offset: password = <hidden>
>tp-glib-DEBUG: tp_cm_param_setter_offset: server = "localhost"
>tp-glib-DEBUG: tp_cm_param_setter_offset: resource = "Resource"
>tp-glib-DEBUG: tp_cm_param_setter_offset: priority = 0 = 0x0
>tp-glib-DEBUG: tp_cm_param_setter_offset: port = 4242 = 0x1092
>tp-glib-DEBUG: tp_cm_param_setter_offset: old-ssl = FALSE
>tp-glib-DEBUG: tp_cm_param_setter_offset: require-encryption = FALSE
>tp-glib-DEBUG: tp_cm_param_setter_offset: register = FALSE
>tp-glib-DEBUG: tp_cm_param_setter_offset: low-bandwidth = FALSE
>tp-glib-DEBUG: parse_parameters: https-proxy-server not given, using default behaviour
>tp-glib-DEBUG: tp_cm_param_setter_offset: https-proxy-port = 443 = 0x1bb
>tp-glib-DEBUG: parse_parameters: fallback-conference-server not given, using default behaviour
>tp-glib-DEBUG: parse_parameters: stun-server not given, using default behaviour
>tp-glib-DEBUG: tp_cm_param_setter_offset: stun-port = 3478 = 0xd96
>tp-glib-DEBUG: tp_cm_param_setter_offset: fallback-stun-server = "stun.collabora.co.uk"
>tp-glib-DEBUG: tp_cm_param_setter_offset: fallback-stun-port = 3478 = 0xd96
>tp-glib-DEBUG: tp_cm_param_setter_offset: ignore-ssl-errors = FALSE
>tp-glib-DEBUG: parse_parameters: alias not given, using default behaviour
>tp-glib-DEBUG: tp_cm_param_setter_offset: fallback-socks5-proxies = []
>tp-glib-DEBUG: tp_cm_param_setter_offset: keepalive-interval = 30 = 0x1e
>tp-glib-DEBUG: tp_base_connection_class_init: Initializing (TpBaseConnectionClass *)0xe3da80
>gabble-DEBUG: gabble_connection_class_init: Initializing (GabbleConnectionClass *)0xe4a090
>tp-glib-DEBUG: tp_presence_mixin_class_init: called.
>tp-glib-DEBUG: tp_base_connection_init: Initializing (TpBaseConnection *)0xe52080
>gabble-DEBUG: gabble_connection_init: Initializing (GabbleConnection *)0xe52080
>tp-glib-DEBUG: tp_base_connection_constructor: Post-construction: (TpBaseConnection *)0xe52080
>tp-glib-DEBUG: tp_base_connection_constructor: Handle repo for type #0 at (nil)
>tp-glib-DEBUG: tp_base_connection_constructor: Handle repo for type #1 at 0xe49aa0
>tp-glib-DEBUG: tp_base_connection_constructor: Handle repo for type #2 at 0xe49b00
>tp-glib-DEBUG: tp_base_connection_constructor: Handle repo for type #3 at 0xe40860
>tp-glib-DEBUG: tp_base_connection_constructor: Handle repo for type #4 at 0xe49b60
>gabble-DEBUG: gabble_roomlist_manager_constructed: 0xe55400
>tp-glib-DEBUG: tp_base_connection_constructor: Channel manager #0 at 0xe4e340
>tp-glib-DEBUG: tp_base_connection_constructor: Channel manager #1 at 0xe4ded0
>tp-glib-DEBUG: tp_base_connection_constructor: Channel manager #2 at 0xe55400
>tp-glib-DEBUG: tp_base_connection_constructor: Channel manager #3 at 0xe57800
>tp-glib-DEBUG: tp_base_connection_constructor: Channel manager #4 at 0xe556d0
>tp-glib-DEBUG: tp_base_connection_constructor: Channel manager #5 at 0xe599e0
>tp-glib-DEBUG: tp_base_connection_constructor: Channel manager #6 at 0xe43080
>tp-glib-DEBUG: tp_base_connection_constructor: Channel manager #7 at 0xe430c0
>gabble-DEBUG: gabble_connection_constructor: Post-construction: (GabbleConnection *)0xe52080
>tp-glib-DEBUG: tp_presence_mixin_init: called.
>gabble-DEBUG: gabble_signal_connect_weak: connecting to 0xe43140:item-found with context 0xe44d40
>gabble-DEBUG: gabble_signal_connect_weak: connecting to 0xe52080:status-changed with context 0xe44c00
>gabble-DEBUG: gabble_connection_constructed: defaulted resource to Telepathy.43cd8783
>tp-glib-DEBUG: tp_base_connection_register: bus name org.freedesktop.Telepathy.Connection.gabble.jabber.test_40localhost_2fResource
>tp-glib-DEBUG: tp_base_connection_register: object path /org/freedesktop/Telepathy/Connection/gabble/jabber/test_40localhost_2fResource
>gabble-DEBUG: _gabble_connection_connect: disabling SRV because "server" or "port" parameter specified, will connect to localhost
>gabble-DEBUG: do_connect: calling lm_connection_open
>Going to connect to localhost:4242
>tp-glib-DEBUG: tp_base_connection_change_status: was 4294967295, now 1, for reason 1
>tp-glib-DEBUG: tp_base_connection_change_status: emitting status-changed to 1, for reason 1
>gabble-DEBUG: connection_status_changed_cb: adding callbacks
>gabble-DEBUG: connection_status_changed_cb: adding callbacks
>gabble-DEBUG: connection_status_changed_cb: adding callbacks
>Trying ::1 port 4242...
>Connection failed.
>Connection failed: Connection refused (error 111)
>Freeing up IOChannel and file descriptor
>Trying 127.0.0.1 port 4242...
>Connection success (1).
>
>SEND:
>-----------------------------------
><?xml version='1.0' encoding='UTF-8'?>
>-----------------------------------
>
>SEND:
>-----------------------------------
><stream:stream version="1.0" xmlns="jabber:client" xmlns:stream="http://etherx.jabber.org/streams" to="localhost" id="547841908297">
>-----------------------------------
>
>RECV [107]:
>-----------------------------------
>'<stream:stream xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:client' id='624c65432652ddea'>'
>-----------------------------------
>gabble-DEBUG: do_auth: authenticating with username: test, password: <hidden>, resource: Resource
>
>SEND:
>-----------------------------------
><iq type="get" id="540757910204"> <query xmlns="jabber:iq:auth"> <username>test</username>
></query>
></iq>
>
>-----------------------------------
>
>RECV [135]:
>-----------------------------------
>'<iq type='result' id='540757910204'><query xmlns='jabber:iq:auth'><username>test</username><password/><digest/><resource/></query></iq>'
>-----------------------------------
>
>SEND:
>-----------------------------------
><iq type="set" id="542788911842"> <query xmlns="jabber:iq:auth"> <username>test</username>
> <digest>cae2c8a3c98f18bbbbaa544d7f4b217fa670ffc5</digest>
> <resource>Resource</resource>
></query>
></iq>
>
>-----------------------------------
>
>RECV [37]:
>-----------------------------------
>'<iq type='result' id='542788911842'/>'
>-----------------------------------
>gabble-DEBUG: connection_auth_cb: Created self handle 1, our JID is test@localhost/Resource
>gabble-DEBUG: gabble_presence_set_capabilities: about to add caps 140261 to resource Resource with serial 1
>gabble-DEBUG: gabble_presence_set_capabilities: found resource Resource
>gabble-DEBUG: gabble_presence_set_capabilities: new serial 1, old 0, clearing caps
>gabble-DEBUG: gabble_presence_set_capabilities: adding caps 140261 to resource Resource
>gabble-DEBUG: gabble_presence_set_capabilities: resource Resource caps now 140261
>gabble-DEBUG: gabble_presence_set_capabilities: total caps now 140261
>gabble-DEBUG: gabble_disco_request_with_timeout: Creating disco request 0xe431c0 for localhost
>
>SEND:
>-----------------------------------
><iq type="get" to="localhost" id="544789914234"> <query xmlns="http://jabber.org/protocol/disco#info"></query>
></iq>
>
>-----------------------------------
>
>RECV [159]:
>-----------------------------------
>'<iq to='localhost' type='result' id='544789914234'> <query xmlns='http://jabber.org/protocol/disco#info'><identity category='pubsub' type='pep'/></query>
></iq>'
>-----------------------------------
>gabble-DEBUG: connection_disco_cb: got:
><query xmlns="http://jabber.org/protocol/disco#info"> <identity type="pep" category="pubsub"></identity>
></query>
>
>gabble-DEBUG: connection_disco_cb: set features flags to 16
>
>SEND:
>-----------------------------------
><presence id="545817915349"> <x xmlns="vcard-temp:x:update"></x>
> <c ver="L/lOGHTCbxvV8FduYaTnQ4d+J6U=" node="http://telepathy.freedesktop.org/caps" hash="sha-1" xmlns="http://jabber.org/protocol/caps"></c>
></presence>
>
>-----------------------------------
>tp-glib-DEBUG: tp_base_connection_change_status: was 1, now 0, for reason 1
>tp-glib-DEBUG: tp_base_connection_change_status: emitting status-changed to 0, for reason 1
>gabble-DEBUG: connection_status_changed_cb: requesting roster
>
>SEND:
>-----------------------------------
><iq type="get" id="546905916092"> <query xmlns="jabber:iq:roster"></query>
></iq>
>
>-----------------------------------
>gabble-DEBUG: gabble_disco_conn_status_changed_cb: connected, initiating service discovery on localhost
>gabble-DEBUG: gabble_disco_request_with_timeout: Creating disco request 0xe43200 for localhost
>
>SEND:
>-----------------------------------
><iq type="get" to="localhost" id="546888916202"> <query xmlns="http://jabber.org/protocol/disco#items"></query>
></iq>
>
>-----------------------------------
>gabble-DEBUG: gabble_vcard_manager_request: Created request 0xe5fed0 to retrieve <1>'s vCard
>gabble-DEBUG: cache_entry_ensure_queued: Cache entry 0xe5fea0 is my own, not setting @to
>gabble-DEBUG: gabble_request_pipeline_enqueue: enqueued new request as item 0xe5ff00
>gabble-DEBUG: cache_entry_ensure_queued: adding request to cache entry 0xe5fea0 and queueing the <iq>
>tp-glib-DEBUG: tp_presence_mixin_emit_presence_update: called.
>tp-glib-DEBUG: construct_presence_hash: called.
>tp-glib-DEBUG: construct_simple_presence_hash: called.
>
>SEND:
>-----------------------------------
><iq type="set" id="656411918547"> <pubsub xmlns="http://jabber.org/protocol/pubsub"> <publish node="http://laptop.org/xmpp/activities"> <item> <activities xmlns="http://laptop.org/xmpp/activities"></activities>
></item>
></publish>
></pubsub>
></iq>
>
>-----------------------------------
>
>SEND:
>-----------------------------------
><iq type="set" id="656479918622"> <pubsub xmlns="http://jabber.org/protocol/pubsub"> <publish node="http://laptop.org/xmpp/activity-properties"> <item> <activities xmlns="http://laptop.org/xmpp/activity-properties"></activities>
></item>
></publish>
></pubsub>
></iq>
>
>-----------------------------------
>gabble-DEBUG: query_socks5_proxies: Need 5 more proxies
>gabble-DEBUG: delayed_run_pipeline: calling gabble_request_pipeline_go
>gabble-DEBUG: gabble_request_pipeline_go: called
>gabble-DEBUG: send_next_request: processing request 0xe5ff00
>
>SEND:
>-----------------------------------
><iq type="get" id="546894916327"> <vCard xmlns="vcard-temp"></vCard>
></iq>
>
>-----------------------------------
>
>RECV [95]:
>-----------------------------------
>'<iq type='result' id='546894916327'><vCard xmlns='vcard-temp'/><vCard xmlns='vcard-temp'/></iq>'
>-----------------------------------
>gabble-DEBUG: gabble_connection_set_aliases: called
>
>SEND:
>-----------------------------------
><iq type="set" id="660558955756"> <pubsub xmlns="http://jabber.org/protocol/pubsub"> <publish node="http://jabber.org/protocol/nick"> <item> <nick xmlns="http://jabber.org/protocol/nick">Some Guy</nick>
></item>
></publish>
></pubsub>
></iq>
>
>-----------------------------------
>gabble-DEBUG: gabble_vcard_manager_edit: called; invalidating cache
>gabble-DEBUG: cache_entry_attempt_to_free: Not freeing vCard cache entry 0xe5fea0: it has a pipeline_item 0xe5ff00
>gabble-DEBUG: gabble_vcard_manager_edit: checking if we have pending requests already
>gabble-DEBUG: gabble_vcard_manager_edit: NICKNAME => value of length 8 starting Some Guy
>gabble-DEBUG: response_cb: got reply for request 0xe5ff00
>gabble-DEBUG: pipeline_reply_cb: called for entry 0xe5fea0
>gabble-DEBUG: pipeline_reply_cb: will patch vcard
>gabble-DEBUG: gabble_request_pipeline_enqueue: enqueued new request as item 0xe65ad0
>gabble-DEBUG: observe_vcard: got no vCard alias for handle 1
>
>SEND:
>-----------------------------------
><presence id="662608957636"> <x xmlns="vcard-temp:x:update"> <photo></photo>
></x>
> <c ver="L/lOGHTCbxvV8FduYaTnQ4d+J6U=" node="http://telepathy.freedesktop.org/caps" hash="sha-1" xmlns="http://jabber.org/protocol/caps"></c>
></presence>
>
>-----------------------------------
>gabble-DEBUG: delete_request: Discarding request 0xe5fed0
>gabble-DEBUG: cache_entry_attempt_to_free: Not freeing vCard cache entry 0xe5fea0: it has a cached vCard 0xe638d0
>gabble-DEBUG: delete_item: deleting item 0xe5ff00
>gabble-DEBUG: response_cb: calling gabble_request_pipeline_go
>gabble-DEBUG: gabble_request_pipeline_go: called
>gabble-DEBUG: send_next_request: processing request 0xe65ad0
>
>SEND:
>-----------------------------------
><iq type="set" id="661601957150"> <vCard xmlns="vcard-temp"> <NICKNAME>Some Guy</NICKNAME>
></vCard>
></iq>
>
>-----------------------------------
>gabble-DEBUG: gabble_connection_set_avatar: called
>gabble-DEBUG: gabble_vcard_manager_edit: called; invalidating cache
>gabble-DEBUG: gabble_vcard_manager_edit: checking if we have pending requests already
>gabble-DEBUG: gabble_vcard_manager_edit: we don't, create one
>gabble-DEBUG: gabble_vcard_manager_request: Created request 0xe65b90 to retrieve <1>'s vCard
>gabble-DEBUG: cache_entry_ensure_queued: Cache entry 0xe65b60 is my own, not setting @to
>gabble-DEBUG: gabble_request_pipeline_enqueue: enqueued new request as item 0xe66800
>gabble-DEBUG: cache_entry_ensure_queued: adding request to cache entry 0xe65b60 and queueing the <iq>
>gabble-DEBUG: gabble_vcard_manager_edit: PHOTO => value of length 18 starting image/png aGVsbG8=
>gabble-DEBUG: delayed_run_pipeline: calling gabble_request_pipeline_go
>gabble-DEBUG: gabble_request_pipeline_go: called
>gabble-DEBUG: send_next_request: processing request 0xe66800
>
>SEND:
>-----------------------------------
><iq type="get" id="662608958027"> <vCard xmlns="vcard-temp"></vCard>
></iq>
>
>-----------------------------------
>
>RECV [95]:
>-----------------------------------
>'<iq type='result' id='662608958027'><vCard xmlns='vcard-temp'/><vCard xmlns='vcard-temp'/></iq>'
>-----------------------------------
>gabble-DEBUG: response_cb: got reply for request 0xe66800
>gabble-DEBUG: pipeline_reply_cb: called for entry 0xe65b60
>gabble-DEBUG: pipeline_reply_cb: will patch vcard
>**
>gabble:ERROR:vcard-manager.c:1010:manager_patch_vcard: assertion failed: (priv->edit_pipeline_item == NULL)

Actions: View

Attachments on bug 22023: 26924 | 26925 | 26926

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.