[asterisk-bugs] [Asterisk 0011727]: Sending 503 after 100 trying and BYE message
noreply at bugs.digium.com
noreply at bugs.digium.com
Tue Jan 22 07:53:24 CST 2008
A NOTE has been added to this issue.
======================================================================
http://bugs.digium.com/view.php?id=11727
======================================================================
Reported By: gasparz
Assigned To:
======================================================================
Project: Asterisk
Issue ID: 11727
Category: Channels/chan_sip/General
Reproducibility: random
Severity: major
Priority: normal
Status: feedback
Asterisk Version: 1.4.13
SVN Branch (only for SVN checkouts, not tarball releases): N/A
SVN Revision (number only!):
Disclaimer on File?: N/A
Request Review:
======================================================================
Date Submitted: 01-10-2008 08:01 CST
Last Modified: 01-22-2008 07:53 CST
======================================================================
Summary: Sending 503 after 100 trying and BYE message
Description:
Asterisk sometimes sends 503 after it receives a 100 trying or a BYE
message. Perhaps after other messages but I can confirm only these 2.
Let's get down to the problems:
sending 503 after 100 trying
2008-01-08 09:00:14 INVITE sip:number at ip SIP/2.0. sending
2008-01-08 09:00:14 SIP/2.0 100 Trying. receiving
2008-01-08 09:00:14 SIP/2.0 503 Server error. sending
2008-01-08 09:00:15 INVITE sip:number at ip SIP/2.0. sending
2008-01-08 09:00:15 SIP/2.0 100 Trying. receiving
2008-01-08 09:00:15 SIP/2.0 503 Server error. sending
2008-01-08 09:00:16 INVITE sip:number at ip SIP/2.0. sending
2008-01-08 09:00:16 SIP/2.0 100 Trying. receiving
2008-01-08 09:00:16 SIP/2.0 503 Server error. sending
2008-01-08 09:00:18 INVITE sip:number at ip SIP/2.0. sending
2008-01-08 09:00:18 SIP/2.0 100 Trying. receiving
2008-01-08 09:00:18 SIP/2.0 183 Session Progress. receiving
2008-01-08 09:00:22 SIP/2.0 200 OK. sending
2008-01-08 09:00:22 ACK sip:number at ip:5060 SIP/2.0. receiving
2008-01-08 09:03:08 BYE sip:number at ip5060 SIP/2.0. sending
2008-01-08 09:03:08 SIP/2.0 200 OK. receiving
sending 503 after BYE
2008-01-09 06:02:55 INVITE sip:+number at ip:port SIP/2.0. receiving
2008-01-09 06:02:55 SIP/2.0 100 Trying. sending
2008-01-09 06:02:55 SIP/2.0 200 OK. sending
2008-01-09 06:02:55 ACK sip:+number at ip SIP/2.0. receiving
2008-01-09 06:05:18 BYE sip:+number at ip SIP/2.0. receiving
2008-01-09 06:05:18 SIP/2.0 503 Server error. sending
2008-01-09 06:08:44 BYE sip:+number at ip:port;transport=udp SIP/2.0.
2008-01-09 06:08:44 SIP/2.0 481 Call Leg/Transaction Does Not Exist.
I was also able to capture the cli output:
[Jan 9 06:05:18] ERROR[4667]: chan_sip.c:15304 sipsock_read: We could NOT
get the channel lock for SIP/ip-b7d0dce8!
[Jan 9 06:05:18] ERROR[4667]: chan_sip.c:15305 sipsock_read: SIP
transaction failed: call_id
the second case is the major issue because in our setup there is an
outbound call after the inbound. The hangup is on the inbound call and
asterisk does not "sense" this causing the outbound call to go until the
call times out (fortunatly we have a max_call duration)
To reproduce the issues is not easy, it doesn't happen for each call :(,
it depends on I don't know what.
The setup is something like (this is a simplified version because it's a
complicated ivr script):
exten _X.,1,answer
exten _X.,2,playback
exten _X.,3 dial <- during this dial we have the 503s but the dial is not
exiting
exten _X.,4,hangup
the 503 after 100 trying happens on the outbound leg, the 503 after bye on
the inbound leg (a bigger problem from our point of view).
It seems like a timeout when trying to aquire a lock to handle the
incomming packet. Because we send the 503 the party thinks we confirmed the
packet and does not resend it. Then for the invite we time out (asterisk is
not taking into account the 100 trying it received) and resend the invite
,this is why it isn't such a big issue.
For accurate packet capture I suggest a separate logging (ngrep, etheral
whatever) on a production type (high traffic) server and the problem will
occure sooner or later :)
======================================================================
----------------------------------------------------------------------
gasparz - 01-22-08 07:53
----------------------------------------------------------------------
just noticed another issue, and this is in 1.4.17
2008-01-20 15:25:54 ip2:55776 ip1:5060 INVITE sip:+number at ip1:5060
SIP/2.0.
2008-01-20 15:25:54 ip1:5060 ip2:5060 SIP/2.0 100 Trying.
2008-01-20 15:25:54 ip1:5060 ip2:5060 SIP/2.0 200 OK.
2008-01-20 15:25:54 ip2:55776 ip1:5060 ACK sip:+number at ip1 SIP/2.0.
2008-01-20 15:29:45 ip2:55776 ip1:5060 BYE sip:+number at ip1 SIP/2.0.
2008-01-20 15:29:45 ip1:5060 ip2:5060 SIP/2.0 503 Server error. CSeq: 2
BYE.
2008-01-20 15:30:01 ip1:5060 ip2:5060 BYE
sip:restricted at ip2:5060;transport=udp SIP/2.0. CSeq: 102 BYE.
2008-01-20 15:30:01 ip2:55776 ip1:5060 SIP/2.0 481 Call Leg/Transaction
Does Not Exist. CSeq: 102 BYE.
ip1 is asterisk 1.4.17
So when we received the bye we send 503 Server error. There are only 2
lines that send this in chan_sip.c:
15156-
15160
if (p->icseq && (p->icseq > seqno)) {
if (option_debug)
ast_log(LOG_DEBUG, "Ignoring too old SIP packet packet %d (expecting >=
%d)\n", seqno, p->icseq);
if (req->method != SIP_ACK)
transmit_response(p, "503 Server error", req); /* We must respond
according to RFC 3261 sec 12.2 */
but this is not the case for us, the bye cseq we receive is higher than
the invite by 1 so it's perfect.
and 15358- 15363
if (!lockretry) {
if (p->owner)
ast_log(LOG_ERROR, "We could NOT get the channel lock for %s! \n",
S_OR(p->owner->name, "- no channel name ??? - "));
ast_log(LOG_ERROR, "SIP transaction failed: %s \n", p->callid);
if (req.method != SIP_ACK)
transmit_response(p, "503 Server error", &req); /* We must respond
according to RFC 3261 sec 12.2 */
So it sounds like a lock error...
Unfortunatly I couldn't find a way to reproduce this and to get asterisk
cli information or run the core show locks :(
Issue History
Date Modified Username Field Change
======================================================================
01-22-08 07:53 gasparz Note Added: 0080995
======================================================================
More information about the asterisk-bugs
mailing list