After an evaluation, GNOME has moved from Bugzilla to GitLab. Learn more about GitLab.
No new issues can be reported in GNOME Bugzilla anymore.
To report an issue in a GNOME project, go to GNOME GitLab.
Do not go to GNOME Gitlab for: Bluefish, Doxygen, GnuCash, GStreamer, java-gnome, LDTP, NetworkManager, Tomboy.
Bug 595051 - Presence is sometimes broken
Presence is sometimes broken
Status: RESOLVED OBSOLETE
Product: ekiga
Classification: Applications
Component: Presence stack
3.2.x
Other Linux
: Normal major
: ---
Assigned To: Ekiga maintainers
Ekiga maintainers
Depends on:
Blocks:
 
 
Reported: 2009-09-13 06:36 UTC by Yannick
Modified: 2011-09-10 11:55 UTC
See Also:
GNOME target: ---
GNOME version: ---


Attachments
d4 and bt (43.79 KB, application/x-bzip)
2009-09-13 06:36 UTC, Yannick
Details

Description Yannick 2009-09-13 06:36:26 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
Comment 1 Yannick 2009-09-13 06:40:48 UTC
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
Comment 2 Snark 2009-09-13 07:36:28 UTC
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 :-(
Comment 3 Damien Sandras 2009-09-13 08:03:53 UTC
I'll mail Robert.

Snark, I'm not sure you are talking about the same problem.
Comment 4 Damien Sandras 2009-09-13 08:07:40 UTC
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.
Comment 5 Yannick 2009-09-19 09:07:33 UTC
Hi,

I can not reproduce easily...
Comment 6 Eugen Dedu 2011-09-10 11:55:39 UTC
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.