[jitsi-dev] Re: outgoing call fails once (initiating call)


#1

Hi,

Update on the issue posted below.
I'm attaching a screenshot of a wireshark capture right when I'm experiencing the "initiating call" problem.
Correct me if I'm wrong but it seems that Jitsi is trying to REGISTER the sip account after receiving an unauthorized reply. It does that several times but apparently fails. I still haven't checked what happens on the Asterisk server but funny thing is that right before this call it was registered and making calls just fine and right after this call fails, it succeeds right away in making a subsequent call.
So there's a glitch right in this short time lapse.
I can reproduce the problem by placing random calls until it happens.
I don't know if this is a client or server issue.

I have the full cap file if needed.

Thanks,

Vieri

···

--- On Wed, 3/20/13, Vieri <rentorbuy@yahoo.com> wrote:

Hi,

I'd like to report an issue that other users on this mailing
list already experienced.

An idle Jisti client (no active calls for several minutes)
tried to dial an extension via LAN SIP server (Asterisk) but
stayed in the "calling state" (ie. it was displaying the
message defined by service.gui.INITIATING_CALL_STATUS). The
user could not even hear the ring tone. There was complete
silence for several seconds until it hung up with an error
(I don't remember the exact error message).
After this type of error happens the Jitsi user usually can
successfully dial the destination immediately.

Maybe it can be related to sip registration timeout values
or something asterisk-specific, I don't know yet. However,
maybe the Jitsi log could be more verbose when initiating
calls so we can see at what point of the code it's waiting
so long to establish the call.

I'm pasting the last lines of the log but there's nothing
regarding the "initiating outgoing call" steps. I'm
supposing it happened around 30 seconds before 12:23 when
impl.protocol.sip.CallPeerSipImpl.hangup() was called.
The stuff at 12:10 has nothing to do with this issue but I'm
pasting it so you can see when it last logged something.

By the way, it's not a DNS name resolution timeout issue
because I'm specifying a LAN IP address for the Asterisk SIP
server.

12:10:36.458 INFO: [5191]
service.protocol.media.MediaHandler.registerDynamicPTsWithStream().966
Dynamic PT map: 96=rtpmap:-1 opus/48000 fmtp:usedtx=1;
97=rtpmap:-1 iLBC/8000; 99=rtpmap:-1 H264/90000
fmtp:profile-level-id=4DE01f; 98=rtpmap:-1 H264/90000
fmtp:profile-level-id=4DE01f;packetization-mode=1;
12:10:36.458 INFO: [5191]
service.protocol.media.MediaHandler.registerDynamicPTsWithStream().983
PT overrides []
12:10:36.626 INFO: [5215] net.sf.fmj.media.Log.info()
Starting RTPSourceStream.
12:10:36.658 INFO: [5191]
org.jitsi.impl.neomedia.MediaStreamImpl.info() audio
codec/freq: GSM/8000 Hz
12:10:36.658 INFO: [5191]
org.jitsi.impl.neomedia.MediaStreamImpl.info() audio remote
IP/port: 10.215.147.112/19696
12:10:36.658 INFO: [5191] net.sf.fmj.media.Log.info()
Starting RTPSourceStream.
12:10:37.669 INFO: [5249]
org.jitsi.impl.neomedia.MediaStreamImpl.info()
Receive stream stats: discarded RTP packets: 7
Receive stream stats: decoded with FEC: 0
12:10:37.670 INFO: [5249] net.sf.fmj.media.Log.info()
Stopping RTPSourceStream.
12:10:37.672 INFO: [5249]
org.jitsi.impl.neomedia.MediaStreamImpl.info() rtpstat:call
stats for outgoing audio stream SSRC:-2021763546
rtpstat:bytes sent: 1650
rtpstat:RTP sent: 50
rtpstat:remote reported min interarrival jitter : -1
rtpstat:remote reported max interarrival jitter : 0
rtpstat:local collisions: 0
rtpstat:remote collisions: 0
rtpstat:RTCP sent: 0
rtpstat:transmit failed: 0
12:10:37.673 INFO: [5249]
org.jitsi.impl.neomedia.MediaStreamImpl.info() rtpstat:call
stats for incoming rtpmap:3 GSM/8000 stream SSRC:1809848788
rtpstat:packets received: 61
rtpstat:bytes received: 2745
rtpstat:packets lost: 0
rtpstat:min interarrival jitter : -1
rtpstat:max interarrival jitter : 0
rtpstat:RTCPs received: 0
rtpstat:bad RTCP packets: 0
rtpstat:bad RTP packets: 0
rtpstat:local collisions: 0
rtpstat:malformed BYEs: 0
rtpstat:malformed RRs: 0
rtpstat:malformed SDESs: 0
rtpstat:malformed SRs: 0
rtpstat:packets looped: 0
rtpstat:remote collisions: 0
rtpstat:SRRs received: 0
rtpstat:transmit failed: 0
rtpstat:unknown types: 0
12:10:37.673 INFO: [5249] net.sf.fmj.media.Log.info()
net.sf.fmj.media.rtp.RTPSourceStream Total packets added:
61
12:10:37.674 INFO: [5249] net.sf.fmj.media.Log.info()
net.sf.fmj.media.rtp.RTPSourceStream Times reset() called:
0
12:10:37.674 INFO: [5249] net.sf.fmj.media.Log.info()
net.sf.fmj.media.rtp.RTPSourceStream Times grow() called: 0
12:10:37.674 INFO: [5249] net.sf.fmj.media.Log.info()
net.sf.fmj.media.rtp.RTPSourceStream Times shrink() called:
0
12:10:37.674 INFO: [5249] net.sf.fmj.media.Log.info()
net.sf.fmj.media.rtp.RTPSourceStream Times read() while
empty:0
12:10:37.675 INFO: [5249] net.sf.fmj.media.Log.info()
net.sf.fmj.media.rtp.RTPSourceStream Packets dropped because
full: 7
12:10:37.675 INFO: [5249] net.sf.fmj.media.Log.info()
net.sf.fmj.media.rtp.RTPSourceStream Packets dropped while
shrinking: 0
12:10:37.675 INFO: [5249] net.sf.fmj.media.Log.info()
net.sf.fmj.media.rtp.RTPSourceStream Packets dropped because
they were late: 0
12:10:37.675 INFO: [5249] net.sf.fmj.media.Log.info()
net.sf.fmj.media.rtp.RTPSourceStream Packets dropped because
they were late by more than MAX_SIZE: 0
12:10:37.675 INFO: [5249] net.sf.fmj.media.Log.info()
net.sf.fmj.media.rtp.RTPSourceStream Packets dropped in
reset(): 0
12:10:37.676 INFO: [5249] net.sf.fmj.media.Log.info()
net.sf.fmj.media.rtp.RTPSourceStream Max size reached: 4
12:10:37.676 INFO: [5249] net.sf.fmj.media.Log.info()
net.sf.fmj.media.rtp.RTPSourceStream Adaptive jitter buffer
mode was enabled
12:10:37.676 INFO: [5249] net.sf.fmj.media.Log.info()
Stopping RTPSourceStream.
12:10:37.696 INFO: [5249] net.sf.fmj.media.Log.info()
Stopping RTPSourceStream.
12:10:37.698 INFO: [5238] net.sf.fmj.media.Log.info()
Stopping RTPSourceStream.
12:10:37.699 INFO: [5249] net.sf.fmj.media.Log.info()
Stopping RTPSourceStream.
12:23:30.723 SEVERE: [36]
impl.protocol.sip.CallPeerSipImpl.hangup().1049 Could not
determine call peer state!

Thanks,

Vieri


#2

Hi,

I also experience this type of behavior several times a day.
I am also using an Asterisk server, though an older one (1.4.36).
Also a very simple test to reproduce strange behaviour is to
hang up a call, and reopen quickly a new one (best from call history)
and so on. Just terminate calls and reopen new ones quickly and do this
(or try to do this) several times after each other.

Cheers,
Matt

···

Am 25.03.2013 10:10, schrieb Vieri:

Hi,

Update on the issue posted below.
I'm attaching a screenshot of a wireshark capture right when I'm experiencing the "initiating call" problem.
Correct me if I'm wrong but it seems that Jitsi is trying to REGISTER the sip account after receiving an unauthorized reply. It does that several times but apparently fails. I still haven't checked what happens on the Asterisk server but funny thing is that right before this call it was registered and making calls just fine and right after this call fails, it succeeds right away in making a subsequent call.
So there's a glitch right in this short time lapse.
I can reproduce the problem by placing random calls until it happens.
I don't know if this is a client or server issue.

I have the full cap file if needed.

Thanks,

Vieri

--- On Wed, 3/20/13, Vieri <rentorbuy@yahoo.com> wrote:

Hi,

I'd like to report an issue that other users on this mailing
list already experienced.

An idle Jisti client (no active calls for several minutes)
tried to dial an extension via LAN SIP server (Asterisk) but
stayed in the "calling state" (ie. it was displaying the
message defined by service.gui.INITIATING_CALL_STATUS). The
user could not even hear the ring tone. There was complete
silence for several seconds until it hung up with an error
(I don't remember the exact error message).
After this type of error happens the Jitsi user usually can
successfully dial the destination immediately.

Maybe it can be related to sip registration timeout values
or something asterisk-specific, I don't know yet. However,
maybe the Jitsi log could be more verbose when initiating
calls so we can see at what point of the code it's waiting
so long to establish the call.

I'm pasting the last lines of the log but there's nothing
regarding the "initiating outgoing call" steps. I'm
supposing it happened around 30 seconds before 12:23 when
impl.protocol.sip.CallPeerSipImpl.hangup() was called.
The stuff at 12:10 has nothing to do with this issue but I'm
pasting it so you can see when it last logged something.

By the way, it's not a DNS name resolution timeout issue
because I'm specifying a LAN IP address for the Asterisk SIP
server.

12:10:36.458 INFO: [5191]
service.protocol.media.MediaHandler.registerDynamicPTsWithStream().966
Dynamic PT map: 96=rtpmap:-1 opus/48000 fmtp:usedtx=1;
97=rtpmap:-1 iLBC/8000; 99=rtpmap:-1 H264/90000
fmtp:profile-level-id=4DE01f; 98=rtpmap:-1 H264/90000
fmtp:profile-level-id=4DE01f;packetization-mode=1;
12:10:36.458 INFO: [5191]
service.protocol.media.MediaHandler.registerDynamicPTsWithStream().983
PT overrides []
12:10:36.626 INFO: [5215] net.sf.fmj.media.Log.info()
Starting RTPSourceStream.
12:10:36.658 INFO: [5191]
org.jitsi.impl.neomedia.MediaStreamImpl.info() audio
codec/freq: GSM/8000 Hz
12:10:36.658 INFO: [5191]
org.jitsi.impl.neomedia.MediaStreamImpl.info() audio remote
IP/port: 10.215.147.112/19696
12:10:36.658 INFO: [5191] net.sf.fmj.media.Log.info()
Starting RTPSourceStream.
12:10:37.669 INFO: [5249]
org.jitsi.impl.neomedia.MediaStreamImpl.info()
Receive stream stats: discarded RTP packets: 7
Receive stream stats: decoded with FEC: 0
12:10:37.670 INFO: [5249] net.sf.fmj.media.Log.info()
Stopping RTPSourceStream.
12:10:37.672 INFO: [5249]
org.jitsi.impl.neomedia.MediaStreamImpl.info() rtpstat:call
stats for outgoing audio stream SSRC:-2021763546
rtpstat:bytes sent: 1650
rtpstat:RTP sent: 50
rtpstat:remote reported min interarrival jitter : -1
rtpstat:remote reported max interarrival jitter : 0
rtpstat:local collisions: 0
rtpstat:remote collisions: 0
rtpstat:RTCP sent: 0
rtpstat:transmit failed: 0
12:10:37.673 INFO: [5249]
org.jitsi.impl.neomedia.MediaStreamImpl.info() rtpstat:call
stats for incoming rtpmap:3 GSM/8000 stream SSRC:1809848788
rtpstat:packets received: 61
rtpstat:bytes received: 2745
rtpstat:packets lost: 0
rtpstat:min interarrival jitter : -1
rtpstat:max interarrival jitter : 0
rtpstat:RTCPs received: 0
rtpstat:bad RTCP packets: 0
rtpstat:bad RTP packets: 0
rtpstat:local collisions: 0
rtpstat:malformed BYEs: 0
rtpstat:malformed RRs: 0
rtpstat:malformed SDESs: 0
rtpstat:malformed SRs: 0
rtpstat:packets looped: 0
rtpstat:remote collisions: 0
rtpstat:SRRs received: 0
rtpstat:transmit failed: 0
rtpstat:unknown types: 0
12:10:37.673 INFO: [5249] net.sf.fmj.media.Log.info()
net.sf.fmj.media.rtp.RTPSourceStream Total packets added:
61
12:10:37.674 INFO: [5249] net.sf.fmj.media.Log.info()
net.sf.fmj.media.rtp.RTPSourceStream Times reset() called:
0
12:10:37.674 INFO: [5249] net.sf.fmj.media.Log.info()
net.sf.fmj.media.rtp.RTPSourceStream Times grow() called: 0
12:10:37.674 INFO: [5249] net.sf.fmj.media.Log.info()
net.sf.fmj.media.rtp.RTPSourceStream Times shrink() called:
0
12:10:37.674 INFO: [5249] net.sf.fmj.media.Log.info()
net.sf.fmj.media.rtp.RTPSourceStream Times read() while
empty:0
12:10:37.675 INFO: [5249] net.sf.fmj.media.Log.info()
net.sf.fmj.media.rtp.RTPSourceStream Packets dropped because
full: 7
12:10:37.675 INFO: [5249] net.sf.fmj.media.Log.info()
net.sf.fmj.media.rtp.RTPSourceStream Packets dropped while
shrinking: 0
12:10:37.675 INFO: [5249] net.sf.fmj.media.Log.info()
net.sf.fmj.media.rtp.RTPSourceStream Packets dropped because
they were late: 0
12:10:37.675 INFO: [5249] net.sf.fmj.media.Log.info()
net.sf.fmj.media.rtp.RTPSourceStream Packets dropped because
they were late by more than MAX_SIZE: 0
12:10:37.675 INFO: [5249] net.sf.fmj.media.Log.info()
net.sf.fmj.media.rtp.RTPSourceStream Packets dropped in
reset(): 0
12:10:37.676 INFO: [5249] net.sf.fmj.media.Log.info()
net.sf.fmj.media.rtp.RTPSourceStream Max size reached: 4
12:10:37.676 INFO: [5249] net.sf.fmj.media.Log.info()
net.sf.fmj.media.rtp.RTPSourceStream Adaptive jitter buffer
mode was enabled
12:10:37.676 INFO: [5249] net.sf.fmj.media.Log.info()
Stopping RTPSourceStream.
12:10:37.696 INFO: [5249] net.sf.fmj.media.Log.info()
Stopping RTPSourceStream.
12:10:37.698 INFO: [5238] net.sf.fmj.media.Log.info()
Stopping RTPSourceStream.
12:10:37.699 INFO: [5249] net.sf.fmj.media.Log.info()
Stopping RTPSourceStream.
12:23:30.723 SEVERE: [36]
impl.protocol.sip.CallPeerSipImpl.hangup().1049 Could not
determine call peer state!

Thanks,

Vieri

>