[Home]

Summary:ASTERISK-11197: Sending 503 after 100 trying and BYE message
Reporter:Gaspar Zoltan (gasparz)Labels:
Date Opened:2008-01-10 08:01:13.000-0600Date Closed:2011-06-07 14:02:45
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Channels/chan_sip/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
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@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@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@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@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@ip:5060 SIP/2.0. receiving
2008-01-08 09:03:08 BYE sip:number@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@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@ip SIP/2.0. receiving
2008-01-09 06:05:18 BYE sip:+number@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@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 :)
Comments:By: Joshua C. Colp (jcolp) 2008-01-10 09:18:40.000-0600

1. Please try the latest version of 1.4
2. If still an issue attach a core show locks, this CLI command can be enabled in menuselect by turning on DEBUG_THREADS in Compiler Flags. There have been fixes to it though in the latest versions, so you really need to use the latest.
By: Gaspar Zoltan (gasparz) 2008-01-22 02:04:44.000-0600

Hi,

Upgraded to 1.4.17 and the problem stopped.

Thanks
By: Gaspar Zoltan (gasparz) 2008-01-22 07:53:24.000-0600

just noticed another issue, and this is in 1.4.17

2008-01-20 15:25:54 ip2:55776 ip1:5060 INVITE sip:+number@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@ip1 SIP/2.0.
2008-01-20 15:29:45 ip2:55776 ip1:5060 BYE sip:+number@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@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 :(
By: Olle Johansson (oej) 2008-01-22 08:46:18.000-0600

We always need a SIP debug from asterisk... Please consult the bug guidelines.
By: Olle Johansson (oej) 2008-01-22 08:50:54.000-0600

Without any SIP debug I can't find out the reason for the 503. The SIP communication seems very valid. YOu need to find out more information from Asterisk and help us with a log file that explains the 503.
By: Olle Johansson (oej) 2008-02-03 04:45:29.000-0600

Any updates? Still need a debug...
By: jmls (jmls) 2008-02-17 13:03:05.000-0600

please reopen if you manage to get the debug that was requested