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 474692 - Ekiga 2.0.9 takes years to register with SIP and to make calls
Ekiga 2.0.9 takes years to register with SIP and to make calls
Status: RESOLVED FIXED
Product: ekiga
Classification: Applications
Component: OPAL
2.0.x
Other Linux
: Normal normal
: ---
Assigned To: Ekiga maintainers
Ekiga maintainers
Depends on:
Blocks:
 
 
Reported: 2007-09-07 22:17 UTC by cheaterjs
Modified: 2008-04-02 19:18 UTC
See Also:
GNOME target: ---
GNOME version: 2.19/2.20


Description cheaterjs 2007-09-07 22:17:12 UTC 
Ekiga 2.0.9 takes a very long time to register to my sip registrar. Tested with sip.qsc.de and sip.ekiga.net.

It also takes years before a call is estambilished. 

I suspect problems holding the connection with my SIP provider...

ekiga -d6:

----

2007/09/08 00:12:20.493   0:00.993                        ekiga Detected audio plugins: ALSA
2007/09/08 00:12:20.496   0:00.996                        ekiga Detected video plugins: Picture,V4L2,V4L
2007/09/08 00:12:20.498   0:00.997                        ekiga Detected audio plugins: ALSA
2007/09/08 00:12:20.500   0:00.999                        ekiga Detected video plugins: Picture,V4L2,V4L
2007/09/08 00:12:21.304   0:01.803                        ekiga Detected the following audio input devices: Default,VIA 8235,VIA 82XX modem with plugin ALSA
2007/09/08 00:12:21.306   0:01.805                        ekiga Detected the following audio output devices: Default,VIA 8235,VIA 82XX modem with plugin ALSA
2007/09/08 00:12:21.309   0:01.809                        ekiga Detected the following video input devices: No device found with plugin V4L
2007/09/08 00:12:21.315   0:01.814                        ekiga Detected the following audio input devices: Default,VIA 8235,VIA 82XX modem with plugin ALSA
2007/09/08 00:12:21.317   0:01.816                        ekiga Detected the following audio output devices: Default,VIA 8235,VIA 82XX modem with plugin ALSA
2007/09/08 00:12:21.319   0:01.818                        ekiga Detected the following video input devices: No device found with plugin V4L
2007/09/08 00:12:21.352   0:01.852                        ekiga AVAHI   Failed to create client: Daemon not running
2007/09/08 00:12:23.359   0:03.858                        ekiga Ekiga version 2.0.9
2007/09/08 00:12:23.361   0:03.860                        ekiga OPAL version 2.2.8
2007/09/08 00:12:23.362   0:03.861                        ekiga PWLIB version 1.10.7
2007/09/08 00:12:23.364   0:03.864                        ekiga GNOME support enabled
2007/09/08 00:12:23.366   0:03.865                        ekiga Fullscreen support enabled
2007/09/08 00:12:23.367   0:03.867                        ekiga DBUS support enabled
2007/09/08 00:12:23.405   0:03.905                        ekiga Set TCP port range to 30000:30010
2007/09/08 00:12:23.408   0:03.907                        ekiga Set RTP port range to 5000:5059
2007/09/08 00:12:23.410   0:03.909                        ekiga Set UDP port range to 5060:5100
2007/09/08 00:12:23.412   0:03.911                        ekiga OpalEP  Created endpoint: h323
2007/09/08 00:12:23.414   0:03.913                        ekiga H323    Created endpoint.
2007/09/08 00:12:23.418   0:03.918                        ekiga OpalMan Added route "pc:.*=h323:<da>"
2007/09/08 00:12:23.420   0:03.920                        ekiga OpalEP  Created endpoint: sip
2007/09/08 00:12:23.422   0:03.921                        ekiga SIP     Created endpoint.
2007/09/08 00:12:23.438   0:03.937                        ekiga OpalMan Added route "pc:.*=sip:<da>"
2007/09/08 00:12:23.440   0:03.939                        ekiga OpalEP  Created endpoint: pc
2007/09/08 00:12:23.444   0:03.958                        ekiga PCSS    Created PC sound system endpoint.
2007/09/08 00:12:23.462   0:03.961                        ekiga OpalMan Added route "h323:.*=pc:<da>"
2007/09/08 00:12:23.464   0:03.963                        ekiga OpalMan Added route "sip:.*=pc:<da>"
2007/09/08 00:12:23.923   0:04.422                        ekiga AVAHI   Error initializing Avahi: %sDaemon not running
2007/09/08 00:12:23.927   0:04.426        Opal Listener:855d160 Listen  Started listening thread on tcp$192.168.100.3:1720
2007/09/08 00:12:23.928   0:04.427        Opal Listener:855d160 Listen  Waiting on socket accept on tcp$192.168.100.3:1720
2007/09/08 00:12:23.929   0:04.428        Opal Listener:855d928 Listen  Started listening thread on udp$192.168.100.3:5060
2007/09/08 00:12:23.929   0:04.429        Opal Listener:855d928 Listen  Waiting on UDP packet on udp$192.168.100.3:5060
^[[5~2007/09/08 00:12:40.089      0:20.588        GMStunClient:0862fe60 OPAL   STUN server "stun.ekiga.net" replies Cone NAT, external IP 87.234.128.14
2007/09/08 00:13:00.161   0:40.661      GMAccounts...t:0855eef8 OpalUDP Binding to interface: 192.168.100.3:32854
2007/09/08 00:13:00.162   0:40.661      GMAccounts...t:0855eef8 SIP     Created transport udp$0.0.0.0<if=udp$192.168.100.3:32854>
2007/09/08 00:13:00.213   0:40.712      GMAccounts...t:0855eef8 OpalUDP Started connect to 213.148.136.2:5060
2007/09/08 00:13:00.252   0:40.752      GMAccounts...t:0855eef8 OpalUDP STUN created socket: 87.234.128.14:63265
2007/09/08 00:13:00.253   0:40.752      GMAccounts...t:0855eef8 SIP     Created Transport for Registrar udp$213.148.136.2:5060<if=udp$87.234.128.14:63265>
2007/09/08 00:13:00.258   0:40.758      GMAccounts...t:0855eef8 SIP     Sending PDU on udp$213.148.136.2:5060<if=udp$87.234.128.14:63265>
REGISTER sip:sip.qsc.de SIP/2.0
CSeq: 1 REGISTER
Via: SIP/2.0/UDP 87.234.128.14:63265;branch=z9hG4bK0a89ed29-fd5b-dc11-8878-000cf61444a9;rport
User-Agent: Ekiga/2.0.9
From: <sip:MYNUMBER@sip.qsc.de>;tag=1673ed29-fd5b-dc11-8878-000cf61444a9
Call-ID: 7a04df29-fd5b-dc11-8878-000cf61444a9@jan-laptop
To: <sip:MYNUMBER@sip.qsc.de>
Contact: <sip:MYNUMBER@87.234.128.14:63265;transport=udp>
Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,REFER,MESSAGE
Expires: 3600
Content-Length: 0
Max-Forwards: 70


2007/09/08 00:13:00.261   0:40.760        SIP Transport:8630ca0 SIP     Read thread started.
2007/09/08 00:13:00.261   0:40.760        SIP Transport:8630ca0 SIP     Waiting for PDU on udp$213.148.136.2:5060<if=udp$87.234.128.14:63265>
2007/09/08 00:13:00.304   0:40.803        SIP Transport:8630ca0 SIP     PDU Received on udp$213.148.136.2:5060<if=udp$87.234.128.14:63265>
SIP/2.0 401 Unauthorized
CSeq: 1 REGISTER
Via: SIP/2.0/UDP 87.234.128.14:63265;branch=z9hG4bK0a89ed29-fd5b-dc11-8878-000cf61444a9;rport=63265
Server: QSC SIP Router
From: <sip:MYNUMBER@sip.qsc.de>;tag=1673ed29-fd5b-dc11-8878-000cf61444a9
Call-ID: 7a04df29-fd5b-dc11-8878-000cf61444a9@jan-laptop
To: <sip:MYNUMBER@sip.qsc.de>;tag=07fe0ada
Content-Length: 0
WWW-Authenticate: Digest realm="qsc.de",nonce="46e1d3bd8565ad725df37dc21261e4b7a7806136",qop="auth"


2007/09/08 00:13:00.307   0:40.806        SIP Transport:8630ca0 SIP     Transaction 1 REGISTER completed.
2007/09/08 00:13:00.308   0:40.807        SIP Transport:8630ca0 OpalUDP Ended connect, selecting 87.234.128.14:63265
2007/09/08 00:13:00.308   0:40.807        SIP Transport:8630ca0 SIP     Received Authentication Required response
2007/09/08 00:13:00.309   0:40.808        SIP Transport:8630ca0 SIP     Updated realm to qsc.de
2007/09/08 00:13:00.319   0:40.818        SIP Transport:8630ca0 SIP     Adding authentication information
2007/09/08 00:13:00.321   0:40.820        SIP Transport:8630ca0 SIP     Sending PDU on udp$213.148.136.2:5060<if=udp$87.234.128.14:63265>
REGISTER sip:sip.qsc.de SIP/2.0
CSeq: 2 REGISTER
Via: SIP/2.0/UDP 87.234.128.14:63265;branch=z9hG4bKf832f629-fd5b-dc11-8878-000cf61444a9;rport
User-Agent: Ekiga/2.0.9
Authorization: Digest username="MYNUMBER", realm="qsc.de", nonce="46e1d3bd8565ad725df37dc21261e4b7a7806136", uri="sip:sip.qsc.de", algorithm=md5, response="afecac619430f27dd01f826556993d9e"
From: <sip:MYNUMBER@sip.qsc.de>;tag=1673ed29-fd5b-dc11-8878-000cf61444a9
Call-ID: 7a04df29-fd5b-dc11-8878-000cf61444a9@jan-laptop
To: <sip:MYNUMBER@sip.qsc.de>
Contact: <sip:MYNUMBER@87.234.128.14:63265;transport=udp>
Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,REFER,MESSAGE
Expires: 3600
Content-Length: 0
Max-Forwards: 70


2007/09/08 00:13:00.322   0:40.821        SIP Transport:8630ca0 SIP     Waiting for PDU on udp$213.148.136.2:5060<if=udp$87.234.128.14:63265>
2007/09/08 00:13:00.368   0:40.868        SIP Transport:8630ca0 SIP     PDU Received on udp$213.148.136.2:5060<if=udp$87.234.128.14:63265>
SIP/2.0 200 OK
CSeq: 2 REGISTER
Via: SIP/2.0/UDP 87.234.128.14:63265;branch=z9hG4bKf832f629-fd5b-dc11-8878-000cf61444a9;rport=63265
Server: QSC SIP Router
From: <sip:MYNUMBER@sip.qsc.de>;tag=1673ed29-fd5b-dc11-8878-000cf61444a9
Call-ID: 7a04df29-fd5b-dc11-8878-000cf61444a9@jan-laptop
To: <sip:MYNUMBER@sip.qsc.de>;tag=7c2fc0b7
Contact: <sip:MYNUMBER@87.234.128.14:63265>;expires=2698,<sip:MYNUMBER@87.234.128.14:63265>;expires=1359,<sip:MYNUMBER@87.234.128.14:63265>;expires=2495,<sip:MYNUMBER@87.234.128.14:63265>;expires=3600
Expires: 2698
Content-Length: 0


2007/09/08 00:13:00.369   0:40.869        SIP Transport:8630ca0 SIP     Transaction 2 REGISTER completed.
2007/09/08 00:13:00.387   0:40.886        SIP Transport:8630ca0 SIP     Waiting for PDU on udp$213.148.136.2:5060<if=udp$87.234.128.14:63265>
2007/09/08 00:13:01.310   0:41.809                  Housekeeper SIP     Set state Terminated_Success for transaction 1 REGISTER
2007/09/08 00:13:01.373   0:41.873                  Housekeeper SIP     Set state Terminated_Success for transaction 2 REGISTER
2007/09/08 00:13:04.197   0:44.696        SIP Transport:8630ca0 SIP     Bad Request-Line received on udp$213.148.136.2:5060<if=udp$87.234.128.14:63265>
2007/09/08 00:13:04.197   0:44.696        SIP Transport:8630ca0 SIP     Read thread finished.
2007/09/08 00:13:20.263   1:00.762      GMAccounts...t:0855eef8 OpalUDP Binding to interface: 192.168.100.3:32855
2007/09/08 00:13:20.263   1:00.762      GMAccounts...t:0855eef8 SIP     Created transport udp$0.0.0.0<if=udp$192.168.100.3:32855>
2007/09/08 00:13:20.265   1:00.764      GMAccounts...t:0855eef8 OpalUDP Started connect to 213.148.136.2:5060
2007/09/08 00:13:20.303   1:00.802      GMAccounts...t:0855eef8 OpalUDP STUN created socket: 87.234.128.14:64175
2007/09/08 00:13:20.304   1:00.803      GMAccounts...t:0855eef8 SIP     Created Transport for Registrar udp$213.148.136.2:5060<if=udp$87.234.128.14:64175>
2007/09/08 00:13:20.308   1:00.807      GMAccounts...t:0855eef8 SIP     Sending PDU on udp$213.148.136.2:5060<if=udp$87.234.128.14:64175>
SUBSCRIBE sip:MYNUMBER@sip.qsc.de SIP/2.0
CSeq: 3 SUBSCRIBE
Via: SIP/2.0/UDP 87.234.128.14:64175;branch=z9hG4bK1ef3e035-fd5b-dc11-8878-000cf61444a9;rport
User-Agent: Ekiga/2.0.9
From: <sip:MYNUMBER@sip.qsc.de>;tag=06e3e035-fd5b-dc11-8878-000cf61444a9
Call-ID: 342ada35-fd5b-dc11-8878-000cf61444a9@jan-laptop
To: <sip:MYNUMBER@sip.qsc.de>
Contact: <sip:MYNUMBER@87.234.128.14:64175;transport=udp>
Accept: application/simple-message-summary
Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,REFER,MESSAGE
Expires: 3600
Event: message-summary
Content-Length: 0
Max-Forwards: 70


2007/09/08 00:13:20.309   1:00.808        SIP Transport:86cba10 SIP     Read thread started.
2007/09/08 00:13:20.310   1:00.809        SIP Transport:86cba10 SIP     Waiting for PDU on udp$213.148.136.2:5060<if=udp$87.234.128.14:64175>
2007/09/08 00:13:20.344   1:00.843        SIP Transport:86cba10 SIP     PDU Received on udp$213.148.136.2:5060<if=udp$87.234.128.14:64175>
SIP/2.0 489 Bad Event
CSeq: 3 SUBSCRIBE
Via: SIP/2.0/UDP 87.234.128.14:64175;branch=z9hG4bK1ef3e035-fd5b-dc11-8878-000cf61444a9;rport=64175
From: <sip:MYNUMBER@sip.qsc.de>;tag=06e3e035-fd5b-dc11-8878-000cf61444a9
Call-ID: 342ada35-fd5b-dc11-8878-000cf61444a9@jan-laptop
To: <sip:MYNUMBER@sip.qsc.de>;tag=9bb91e1f
Warning: 399 sx3000 "Unsupported Event"
Allow-Events: presence,keep-alive
Content-Length: 0


2007/09/08 00:13:20.345   1:00.844        SIP Transport:86cba10 SIP     Transaction 3 SUBSCRIBE completed.
2007/09/08 00:13:20.346   1:00.845        SIP Transport:86cba10 OpalUDP Ended connect, selecting 87.234.128.14:64175
2007/09/08 00:13:20.346   1:00.845        SIP Transport:86cba10 SIP     Waiting for PDU on udp$213.148.136.2:5060<if=udp$87.234.128.14:64175>
2007/09/08 00:13:21.346   1:01.846                  Housekeeper SIP     Set state Terminated_Success for transaction 3 SUBSCRIBE
2007/09/08 00:13:42.515   1:23.014        GMURLHandler:086ce688 OpalMan Set up call from pc:* to sip:NUMBER_TO_CALL@sip.qsc.de
2007/09/08 00:13:42.515   1:23.014        GMURLHandler:086ce688 Call    Created Call[1]
2007/09/08 00:13:42.515   1:23.014        GMURLHandler:086ce688 OpalMan Set up connection to "pc:*"
2007/09/08 00:13:42.518   1:23.017        GMURLHandler:086ce688 OpalCon Created connection Call[1]-EP<pc>[VIA 8235]
2007/09/08 00:13:42.518   1:23.017        GMURLHandler:086ce688 RFC2833 Handler created
2007/09/08 00:13:42.519   1:23.018        GMURLHandler:086ce688 Silence Handler created
2007/09/08 00:13:42.519   1:23.018        GMURLHandler:086ce688 Echo Canceler  Handler created
2007/09/08 00:13:42.519   1:23.018        GMURLHandler:086ce688 PCSS    Created PC sound system connection.
2007/09/08 00:13:42.519   1:23.018        GMURLHandler:086ce688 OpalMan On incoming connection Call[1]-EP<pc>[VIA 8235]
2007/09/08 00:13:42.519   1:23.018        GMURLHandler:086ce688 Call    GetOtherPartyConnection Call[1]-EP<pc>[VIA 8235]
2007/09/08 00:13:42.519   1:23.018        GMURLHandler:086ce688 OpalMan Set up connection to "sip:NUMBER_TO_CALL@sip.qsc.de"
2007/09/08 00:13:42.521   1:23.020        GMURLHandler:086ce688 OpalCon Created connection Call[1]-EP<sip>[f8af1e43-fd5b-dc11-8878-000cf61444a9@jan-laptop]
2007/09/08 00:13:42.521   1:23.020        GMURLHandler:086ce688 RFC2833 Handler created
2007/09/08 00:13:57.494   1:37.993                        ekiga Call    Clearing Call[1] reason=EndedByLocalUser
2007/09/08 00:13:57.494   1:37.993                        ekiga OpalCon Releasing Call[1]-EP<pc>[VIA 8235]
2007/09/08 00:13:57.495   1:37.994                        ekiga OpalCon Call end reason for VIA 8235 set to EndedByLocalUser
2007/09/08 00:13:57.495   1:37.994                        ekiga OpalCon SetPhase from SetUpPhase to ReleasingPhase
2007/09/08 00:13:57.495   1:37.994                        ekiga OpalCon Releasing Call[1]-EP<sip>[f8af1e43-fd5b-dc11-8878-000cf61444a9@jan-laptop]
2007/09/08 00:13:57.495   1:37.994                        ekiga OpalCon Call end reason for f8af1e43-fd5b-dc11-8878-000cf61444a9@jan-laptop set to EndedByLocalUser
2007/09/08 00:13:57.495   1:37.994                        ekiga OpalCon SetPhase from UninitialisedPhase to ReleasingPhase
2007/09/08 00:13:57.498   1:37.998            OnRelease:867c788 OpalCon OnReleased Call[1]-EP<pc>[VIA 8235]
2007/09/08 00:13:57.499   1:37.998            OnRelease:867c788 OpalCon Media stream threads closed.
2007/09/08 00:13:57.499   1:37.998            OnRelease:86fa400 SIP     OnReleased: Call[1]-EP<sip>[f8af1e43-fd5b-dc11-8878-000cf61444a9@jan-laptop], phase = ReleasingPhase
2007/09/08 00:13:57.500   1:37.999            OnRelease:86fa400 OpalCon SetPhase from ReleasingPhase to ReleasingPhase
2007/09/08 00:13:57.500   1:37.999            OnRelease:86fa400 OpalCon Media stream threads closed.
2007/09/08 00:13:57.500   1:37.999            OnRelease:86fa400 OpalCon SetPhase from ReleasingPhase to ReleasedPhase

I PRESSED EXIT!

Segmentation fault

----

Greetings,
Jan Schiefer!
Comment 1 Damien Sandras 2007-09-08 09:34:55 UTC 
You issue the register at :
00:13:00.258

You are registered at :
00:13:00.368

I do not consider 100 ms as a long time to register...

As for the segfault, we can not do anything without a backtrace with debug symbols.
Comment 2 cheaterjs 2007-09-08 14:53:43 UTC 
It seems the gui is unresponsive.
Before SEEING, that I'm registered it took me at least 20 seconds.

Before the call "started" ( after clicking connect in the gui ), it took about the same amount of time.

Maybe a problem with bleeding edge gnome/gtk?

Greetings,
Jan Schiefer!
Comment 3 Damien Sandras 2007-09-08 15:10:48 UTC 
I run things with GTK+2.11 without noticing that kind of problem...
Comment 4 cheaterjs 2007-09-08 15:30:52 UTC 
You want remote desktop access to see and diagnose the problem?

Greetings,
Jan Schiefer!
Comment 5 Damien Sandras 2007-09-08 15:36:36 UTC 
Remote access is slow by definition, so I don't think it will help unfortunately.

Notice the STUN test takes 40 seconds. Perhaps it is the slowness problem you encounter ?

You start ekiga at 00:12, and it is registered at 00:13 because the STUN test takes long (which can be normal, especially with a linux gateway).
Comment 6 cheaterjs 2007-09-08 16:05:58 UTC 
Ok, but it doesn't help with the problem starting calls.
Also the second accounts registration ( in the trace not activated ) takes an equal amount of time.
Comment 7 Damien Sandras 2008-04-02 19:18:30 UTC 
We found out what was the problem at a later stage. OPAL is doing DNS SRV requests regularly even when it is not needed. Some (broken) DNS servers take a long time to answer those requests.

There are 2 solutions : 
- Use Ekiga TRUNK with OPAL/PTLIB TRUNK
or
- Use another DNS server