GNOME Bugzilla – Bug 595051
Presence is sometimes broken
Last modified: 2011-09-10 11:55:39 UTC
Created attachment 143093 [details] d4 and bt Hi, Using stable branch from 09/09/2009, I let ekiga several hours to test the presence. It was working at first, then after some hours, the presence was not updated. I still let it run all the night, at the morning the presence still do not update, I tried to place a call to 500 but Ekiga was stuck waiting the call to be established and there was no timeout... I was able to hang up using the GUI but I was not able to exit from Ekiga. In the bt i saw this: 2009/09/12 18:14:16.887 37:37.758 Opal Liste...0xb536fb90 SIP Received NOTIFY presence 2009/09/12 18:14:16.887 37:37.758 Opal Liste...0xb536fb90 SIP Found a SUBSCRIBE corresponding to the NOTIFY presence 2009/09/12 18:14:16.887 37:37.758 Opal Liste...0xb536fb90 SIP Subscription is active;expires=188 2009/09/12 18:14:16.888 37:37.759 Pool:0xb52edb90 SIP Handling PDU "22 PUBLISH <200>" for transaction=z9hG4bK8257effc-249e-de11-830d-002185488b80 2009/09/12 18:14:16.888 37:37.759 Pool:0xb52edb90 SIP PUBLISH transaction id=z9hG4bK8257effc-249e-de11-830d-002185488b80 completed. 2009/09/12 18:14:16.888 37:37.759 Pool:0xb52edb90 OpalUDP Setting interface to 82.239.207.217%eth0 2009/09/12 18:14:16.889 37:37.760 Pool:0xb52edb90 SIP Expiry time for PUBLISH set to 430 seconds. 2009/09/12 18:14:16.889 37:37.760 Pool:0xb52edb90 SIP Product Info: name="Kamailio", version="", vendor="", comments="(1.4.0-notls (i386/linux))" 2009/09/12 18:14:16.889 37:37.761 Pool:0xb52edb90 SIP Changing PUBLISH handler from Refreshing to Subscribed, target=sip:yannick@ekiga.net, id=04141fc6-1f9e-de11-830d-002185488b80@myrmidon 2009/09/12 18:14:16.890 37:37.761 Pool:0xb52edb90 SIP Handled PDU "22 PUBLISH <200>" 2009/09/12 18:14:16.902 37:37.773 Opal Liste...0xb536fb90 XML Loaded XML presence Until this point Ekiga seems to work properly, the next debug is: 2009/09/12 23:40:32.279 6:03:53.150 SIP Changing PUBLISH handler from Subscribed to Subscribing, target=sip:yannick@ekiga.net, id=04141fc6-1f9e-de11-830d-002185488b80@myrmidon Please note the time: Ekiga was silent in the debug output from 2009/09/12 18:14:16.902 to 2009/09/12 23:40:32.279, i.e. 5 hours!! Thus I suspect the origin of the bug somewhere around 2009/09/12 18:14:00 The reason why there is an output, if I remember correctly, is because I tried to change my presence status using the GUI: 2009/09/12 23:40:32.279 6:03:53.150 SIP Changing PUBLISH handler from Subscribed to Subscribing, target=sip:yannick@ekiga.net, id=04141fc6-1f9e-de11-830d-002185488b80@myrmidon 2009/09/12 23:40:32.317 6:03:53.188 SIP Transaction created. 2009/09/12 23:40:32.696 6:03:53.567 DNS SRV Lookup ekiga.net service _sip._udp 2009/09/12 23:40:32.763 6:03:53.634 SIP No SRV record found. 2009/09/12 23:40:32.763 6:03:53.634 SIP Transaction remote address is udp$ekiga.net:5060 2009/09/12 23:40:32.833 6:03:53.704 SIP Sending PDU (825 bytes) to: rem=udp$86.64.162.35:5060,local=udp$82.239.207.217:5060,if=82.239.207.217%eth0 PUBLISH sip:yannick@ekiga.net SIP/2.0 CSeq: 23 PUBLISH Via: SIP/2.0/UDP 82.239.207.217:5060;branch=z9hG4bK267c1e91-529e-de11-830d-002185488b80;rport User-Agent: Ekiga/3.2.6 From: <sip:yannick@ekiga.net>;tag=4448e990-529e-de11-830d-002185488b80 Call-ID: 04141fc6-1f9e-de11-830d-002185488b80@myrmidon To: <sip:yannick@ekiga.net> Contact: <sip:yannick@82.239.207.217> SIP-If-Match: a.1252771184.6341.5821.13 Expires: 430 Event: presence Content-Type: application/pidf+xml Content-Length: 303 Max-Forwards: 70 <?xml version="1.0" encoding="UTF-8"?> <presence xmlns="urn:ietf:params:xml:ns:pidf" entity="pres:yannick@ekiga.net"> <tuple id="sip:yannick@ekiga.net_on_myrmidon"> <note>away</note> <status> <basic>open</basic> </status> <contact priority="1">yannick@ekiga.net</contact> </tuple> </presence> 2009/09/12 23:40:32.835 6:03:53.706 OpalUDP Setting interface to 82.239.207.217%eth0 2009/09/12 23:40:32.835 6:03:53.706 SIP Transaction timers set: retry=0.500, completion=6.000 Then I decided to go to bed ;) When trying to update my presence the next morning, Ekiga debug shows: 2009/09/13 07:59:42.976 14:23:03.847 SIP Can't send Subscribing request for PUBLISH handler while in Subscribing state, target=sip:yannick@ekiga.net, id=04141fc6-1f9e-de11-830d-002185488b80@myrmidon 2009/09/13 07:59:43.141 14:23:04.012 SIP Can't send Subscribing request for PUBLISH handler while in Subscribing state, target=sip:yannick@ekiga.net, id=04141fc6-1f9e-de11-830d-002185488b80@myrmidon 2009/09/13 07:59:43.241 14:23:04.112 SIP Can't send Subscribing request for PUBLISH handler while in Subscribing state, target=sip:yannick@ekiga.net, id=04141fc6-1f9e-de11-830d-002185488b80@myrmidon The full debug output + bt is attached. Best regards, Yannick
Another funny stuff is: I tried to UNREGISTER/REGISTER manually the next morning Ekiga seems totally confused between REGISTER and PUBLISH, e.g.: 2009/09/13 08:03:38.606 14:26:59.477 subscriber:0xb4c89b90 SIP Can't send Subscribing request for REGISTER handler while in Unsubscribing state, target=sip:yannick@ekiga.net, id=6e2fa4c5-1f9e-de11-830d-002185488b80@myrmidon The relevant part is: 2009/09/13 08:02:50.566 14:26:11.437 subscriber:0xb4c89b90 SIP Changing REGISTER handler from Subscribed to Unsubscribing, target=sip:yannick@ekiga.net, id=6e2fa4c5-1f9e-de11-830d-002185488b80@myrmidon 2009/09/13 08:02:50.566 14:26:11.437 subscriber:0xb4c89b90 SIP Transaction created. 2009/09/13 08:02:50.754 14:26:11.625 subscriber:0xb4c89b90 SIP Adding authentication information 2009/09/13 08:02:50.755 14:26:11.626 subscriber:0xb4c89b90 DNS SRV Lookup ekiga.net service _sip._udp 2009/09/13 08:02:50.829 14:26:11.700 subscriber:0xb4c89b90 SIP No SRV record found. 2009/09/13 08:02:50.829 14:26:11.700 subscriber:0xb4c89b90 SIP Transaction remote address is udp$ekiga.net:5060 2009/09/13 08:02:50.830 14:26:11.701 subscriber:0xb4c89b90 SIP Sending PDU (670 bytes) to: rem=udp$86.64.162.35:5060,local=udp$82.239.207.217:5060,if=82.239.207.217%eth0 REGISTER sip:ekiga.net SIP/2.0 CSeq: 24 REGISTER Via: SIP/2.0/UDP 82.239.207.217:5060;branch=z9hG4bKaa21cebc-989e-de11-830d-002185488b80;rport User-Agent: Ekiga/3.2.6 Authorization: Digest username="yannick", realm="ekiga.net", nonce="4aabc84c0000079fba51c2bd0cedf5232e7026d1a4a50483", uri="sip:ekiga.net", algorithm=MD5, response="1b71b855c38299b2ba1e2db30bd12f56" From: <sip:yannick@ekiga.net>;tag=fa61a4c5-1f9e-de11-830d-002185488b80 Call-ID: 6e2fa4c5-1f9e-de11-830d-002185488b80@myrmidon To: <sip:yannick@ekiga.net> Contact: * Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,SUBSCRIBE,NOTIFY,REFER,MESSAGE,INFO,PING Expires: 0 Content-Length: 0 Max-Forwards: 70 2009/09/13 08:02:50.832 14:26:11.703 subscriber:0xb4c89b90 OpalUDP Setting interface to 82.239.207.217%eth0 2009/09/13 08:02:50.833 14:26:11.704 subscriber:0xb4c89b90 SIP Transaction timers set: retry=0.500, completion=6.000 2009/09/13 08:03:06.989 14:26:27.860 subscriber:0xb4c89b90 SIP Start REGISTER aor=yannick@ekiga.net registrar=ekiga.net contact= authID=yannick realm= expire=3600 restore=30 minRetry=0.000 maxRetry=0.000 2009/09/13 08:03:06.991 14:26:27.862 subscriber:0xb4c89b90 SIP Expiry time for REGISTER set to 3600 seconds. 2009/09/13 08:03:06.992 14:26:27.863 subscriber:0xb4c89b90 SIP Can't send Subscribing request for REGISTER handler while in Unsubscribing state, target=sip:yannick@ekiga.net, id=6e2fa4c5-1f9e-de11-830d-002185488b80@myrmidon 2009/09/13 08:03:07.093 14:26:27.964 subscriber:0xb4c89b90 SIP Can't send Subscribing request for REGISTER handler while in Unsubscribing state, target=sip:yannick@ekiga.net, id=6e2fa4c5-1f9e-de11-830d-002185488b80@myrmidon 2009/09/13 08:03:07.194 14:26:28.065 subscriber:0xb4c89b90 SIP Can't send Subscribing request for REGISTER handler while in Unsubscribing state, target=sip:yannick@ekiga.net, id=6e2fa4c5-1f9e-de11-830d-002185488b80@myrmidon 2009/09/13 08:03:07.294 14:26:28.166 subscriber:0xb4c89b90 SIP Can't send Subscribing request for REGISTER handler while in Unsubscribing state, target=sip:yannick@ekiga.net, id=6e2fa4c5-1f9e-de11-830d-002185488b80@myrmidon 2009/09/13 08:03:07.395 14:26:28.266 subscriber:0xb4c89b90 SIP Can't send Subscribing request for REGISTER handler while in Unsubscribing state, target=sip:yannick@ekiga.net, id=6e2fa4c5-1f9e-de11-830d-002185488b80@myrmidon 2009/09/13 08:03:07.496 14:26:28.367 subscriber:0xb4c89b90 SIP Can't send Subscribing request for REGISTER handler while in Unsubscribing state, target=sip:yannick@ekiga.net, id=6e2fa4c5-1f9e-de11-830d-002185488b80@myrmidon 2009/09/13 08:03:07.596 14:26:28.467 subscriber:0xb4c89b90 SIP Can't send Subscribing request for REGISTER handler while in Unsubscribing state, target=sip:yannick@ekiga.net, id=6e2fa4c5-1f9e-de11-830d-002185488b80@myrmidon 2009/09/13 08:03:07.697 14:26:28.568 subscriber:0xb4c89b90 SIP Can't send Subscribing request for REGISTER handler while in Unsubscribing state, target=sip:yannick@ekiga.net, id=6e2fa4c5-1f9e-de11-830d-002185488b80@myrmidon 2009/09/13 08:03:07.797 14:26:28.668 subscriber:0xb4c89b90 SIP Can't send Subscribing request for REGISTER handler while in Unsubscribing state, target=sip:yannick@ekiga.net, id=6e2fa4c5-1f9e-de11-830d-002185488b80@myrmidon 2009/09/13 08:03:07.898 14:26:28.769 subscriber:0xb4c89b90 SIP Can't send Subscribing request for REGISTER handler while in Unsubscribing state, target=sip:yannick@ekiga.net, id=6e2fa4c5-1f9e-de11-830d-002185488b80@myrmidon 2009/09/13 08:03:07.999 14:26:28.870 subscriber:0xb4c89b90 SIP Can't send Subscribing request for REGISTER handler while in Unsubscribing state, target=sip:yannick@ekiga.net, id=6e2fa4c5-1f9e-de11-830d-002185488b80@myrmidon 2009/09/13 08:03:34.274 14:26:55.145 subscriber:0xb4c89b90 SIP Already doing Unsubscribing request for REGISTER handler, target=sip:yannick@ekiga.net, id=6e2fa4c5-1f9e-de11-830d-002185488b80@myrmidon 2009/09/13 08:03:37.899 14:26:58.770 subscriber:0xb4c89b90 SIP Start REGISTER aor=yannick@ekiga.net registrar=ekiga.net contact= authID=yannick realm= expire=3600 restore=30 minRetry=0.000 maxRetry=0.000 2009/09/13 08:03:37.900 14:26:58.772 subscriber:0xb4c89b90 SIP Expiry time for REGISTER set to 3600 seconds. 2009/09/13 08:03:37.901 14:26:58.772 subscriber:0xb4c89b90 SIP Can't send Subscribing request for REGISTER handler while in Unsubscribing state, target=sip:yannick@ekiga.net, id=6e2fa4c5-1f9e-de11-830d-002185488b80@myrmidon 2009/09/13 08:03:38.002 14:26:58.873 subscriber:0xb4c89b90 SIP Can't send Subscribing request for REGISTER handler while in Unsubscribing state, target=sip:yannick@ekiga.net, id=6e2fa4c5-1f9e-de11-830d-002185488b80@myrmidon 2009/09/13 08:03:38.103 14:26:58.974 subscriber:0xb4c89b90 SIP Can't send Subscribing request for REGISTER handler while in Unsubscribing state, target=sip:yannick@ekiga.net, id=6e2fa4c5-1f9e-de11-830d-002185488b80@myrmidon 2009/09/13 08:03:38.203 14:26:59.074 subscriber:0xb4c89b90 SIP Can't send Subscribing request for REGISTER handler while in Unsubscribing state, target=sip:yannick@ekiga.net, id=6e2fa4c5-1f9e-de11-830d-002185488b80@myrmidon 2009/09/13 08:03:38.304 14:26:59.175 subscriber:0xb4c89b90 SIP Can't send Subscribing request for REGISTER handler while in Unsubscribing state, target=sip:yannick@ekiga.net, id=6e2fa4c5-1f9e-de11-830d-002185488b80@myrmidon 2009/09/13 08:03:38.405 14:26:59.276 subscriber:0xb4c89b90 SIP Can't send Subscribing request for REGISTER handler while in Unsubscribing state, target=sip:yannick@ekiga.net, id=6e2fa4c5-1f9e-de11-830d-002185488b80@myrmidon 2009/09/13 08:03:38.505 14:26:59.376 subscriber:0xb4c89b90 SIP Can't send Subscribing request for REGISTER handler while in Unsubscribing state, target=sip:yannick@ekiga.net, id=6e2fa4c5-1f9e-de11-830d-002185488b80@myrmidon 2009/09/13 08:03:38.606 14:26:59.477 subscriber:0xb4c89b90 SIP Can't send Subscribing request for REGISTER handler while in Unsubscribing state, target=sip:yannick@ekiga.net, id=6e2fa4c5-1f9e-de11-830d-002185488b80@myrmidon 2009/09/13 08:03:38.706 14:26:59.578 subscriber:0xb4c89b90 SIP Can't send Subscribing request for REGISTER handler while in Unsubscribing state, target=sip:yannick@ekiga.net, id=6e2fa4c5-1f9e-de11-830d-002185488b80@myrmidon 2009/09/13 08:03:38.807 14:26:59.678 subscriber:0xb4c89b90 SIP Can't send Subscribing request for REGISTER handler while in Unsubscribing state, target=sip:yannick@ekiga.net, id=6e2fa4c5-1f9e-de11-830d-002185488b80@myrmidon 2009/09/13 08:03:38.908 14:26:59.779 subscriber:0xb4c89b90 SIP Can't send Subscribing request for REGISTER handler while in Unsubscribing state, target=sip:yannick@ekiga.net, id=6e2fa4c5-1f9e-de11-830d-002185488b80@myrmidon
It has been broken in master too since pretty long -- I was sure I had already reported it back then, but yesterday evening, I couldn't find any mail or bug about it :-(
I'll mail Robert. Snark, I'm not sure you are talking about the same problem.
Well, no need to mail Robert. At this point, we can not determine if the bug is in Ekiga or OPAL. Can you reproduce ? When you get no debug again for some time, please hit Ctrl-C and issue a thread apply all bt command.
Hi, I can not reproduce easily...
Yannick, the problem was surely the fact that you introduced a non-ascii character as note for the presence, "présence", as shown by the last message before the 5 hours silence: 2009/09/12 18:14:16.883 37:37.754 Opal Liste...0xb536fb90 SIP PDU received: rem=udp$86.64.162.35 :5060,local=udp$82.239.207.217:5060,if=82.239.207.217%eth0 NOTIFY sip:yannick@82.239.207.217 SIP/2.0 CSeq: 28 NOTIFY Via: SIP/2.0/UDP 86.64.162.35;branch=z9hG4bK0d0b.2de0ab54.0 User-Agent: Kamailio (1.4.0-notls (i386/linux)) From: sip:yannick@ekiga.net;tag=10.5640.1252769838.4930 Call-ID: c4c8d8d3-1f9e-de11-830d-002185488b80@myrmidon To: sip:yannick@ekiga.net;tag=6a12e4d3-1f9e-de11-830d-002185488b80 Contact: <sip:86.64.162.35:5060> Subscription-State: active;expires=188 Event: presence Content-Length: 317 Content-Type: application/pidf+xml Max-Forwards: 70 <?xml version="1.0" encoding="UTF-8"?> <presence xmlns="urn:ietf:params:xml:ns:pidf" entity="pres:yannick@ekiga.net"> <tuple id="sip:yannick@ekiga.net_on_myrmidon"> <note>dnd - test pour la présence</note> <status> <basic>open</basic> </status> <contact priority="1">yannick@ekiga.net</contact> </tuple> </presence> and by the fact that the debug stopped at: 2009/09/12 18:14:16.902 37:37.773 Opal Liste...0xb536fb90 XML Loaded XML presence i.e. XML parsing generated an error (the é in présence). This also put opal "dans les choux" afterwards. I have just tried using présence as note with current unstable and everything works. So closing this bug.