[Home]

Summary:ASTERISK-20124: chan_sip retransmit timeout causes a AST_CAUSE_PROTOCOL_ERROR, translates to 603 Declined
Reporter:Walter Doekes (wdoekes)Labels:
Date Opened:2012-07-12 08:32:32Date Closed:2012-08-29 12:07:07
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Channels/chan_sip/General
Versions:1.8.14.0 Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) asterisk-20124_patch.diff
Description:When chan_sip.c does a {{ast_queue_hangup_with_cause(channel, AST_CAUSE_PROTOCOL_ERROR);}} the cause code AST_CAUSE_PROTOCOL_ERROR gets translated to "603 Declined" because AST_CAUSE_PROTOCOL_ERROR is not found in {{cause2sip}}.

{{ast_queue_hangup_with_cause(channel, AST_CAUSE_PROTOCOL_ERROR);}} is called from {{__sip_autodestruct()}}, {{handle_request_bye()}} on rare occasions, and (relevant in my case) from the {{retrans_pkt()}} retransmit handler on timeout.

For the timeout, I'd expect a 408 or something. Especially when I pass the ${HANGUPCAUSE} to an A-leg.

The translation to 603 happens here:
{noformat}

                               if (p->hangupcause && (res = hangup_cause2sip(p->hangupcause)))
                                       transmit_response_reliable(p, res, &p->initreq);
                               else
                                       transmit_response_reliable(p, "603 Declined", &p->initreq);
{noformat}
Comments:By: Jonathan Rose (jrose) 2012-08-23 11:58:14.114-0500

Based on how you are describing the problem, I think this is the appropriate response. Please confirm that this patch changes the behavior to match your expectations.
By: Walter Doekes (wdoekes) 2012-08-24 04:59:58.069-0500

Ok. This report could've used a bit of clarification. Let's add some:

{noformat}
sip.conf:

[general]
timert1=100 ; speed up test a bit

[somepeer]
type=peer
host=127.0.0.1
port=5063 ; we're not listening here

extensions.conf:

[default]
exten => somepeer,1,Dial(SIP/somepeer)
         same => n,NoOp(hangupcause=${HANGUPCAUSE})
;          same => n,Hangup(${HANGUPCAUSE})
{noformat}

Calling 'somepeer' yields this:

{noformat}
   -- Executing [somepeer@default:2] NoOp("SIP/127.0.1.1-00000000", "hangupcause=111") in new stack
   -- Auto fallthrough, channel 'SIP/127.0.1.1-00000000' status is 'CHANUNAVAIL'
[Aug 24 11:36:32] DEBUG[32623]: chan_sip.c:3420 __sip_xmit: Trying to put 'SIP/2.0 503' onto UDP socket destined for 127.0.0.1:5061
{noformat}

Now I add the hangup:

{noformat}
   -- Executing [somepeer@default:2] NoOp("SIP/127.0.1.1-00000000", "hangupcause=111") in new stack
[Aug 24 11:38:22] DEBUG[32682]: chan_sip.c:27488 sip_devicestate: Checking device state for peer somepeer
[Aug 24 11:38:22] DEBUG[32720]: pbx.c:3381 ast_str_retrieve_variable: Result of 'HANGUPCAUSE' is '111'
[Aug 24 11:38:22] DEBUG[32720]: pbx.c:4372 pbx_extension_helper: Launching 'Hangup'
[Aug 24 11:38:22] DEBUG[32682]: devicestate.c:456 do_state_change: Changing state for SIP/somepeer - state 1 (Not in use)
[Aug 24 11:38:22] DEBUG[32682]: devicestate.c:436 devstate_event: device 'SIP/somepeer' state '1'
   -- Executing [somepeer@default:3] Hangup("SIP/127.0.1.1-00000000", "111") in new stack
[Aug 24 11:38:22] DEBUG[32720]: pbx.c:5207 __ast_pbx_run: Spawn extension (default,somepeer,3) exited non-zero on 'SIP/127.0.1.1-00000000'
 == Spawn extension (default, somepeer, 3) exited non-zero on 'SIP/127.0.1.1-00000000'
...
[Aug 24 11:38:22] DEBUG[32720]: chan_sip.c:3420 __sip_xmit: Trying to put 'SIP/2.0 603' onto UDP socket destined for 127.0.0.1:5061
{noformat}

Funny enough, when I started testing this today -- before applying any patch, with ~10.6 -- I got HANGUPCAUSE=18 earlier, but now I cannot reproduce.

This:

{noformat}
[Aug 24 11:15:36] WARNING[31988]: chan_sip.c:3715 retrans_pkt: Retransmission timeout reached on transmission 073c84767b3559a1263abc565c7f660b@127.0.0.1:5060 for seqno 102 (Critical Request) -- See https://wiki.asterisk.org/wiki/display/AST/SIP+Retransmissions
Packet timed out after 32000ms with no response
[Aug 24 11:15:36] WARNING[31988]: chan_sip.c:3744 retrans_pkt: Hanging up call 073c84767b3559a1263abc565c7f660b@127.0.0.1:5060 - no reply to our critical packet (see https://wiki.asterisk.org/wiki/display/AST/SIP+Retransmissions).
[Aug 24 11:15:36] DEBUG[31988]: chan_sip.c:3108 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 073c84767b3559a1263abc565c7f660b@127.0.0.1:5060
   -- SIP/somepeer-00000001 is circuit-busy
[Aug 24 11:15:36] DEBUG[32030]: channel.c:2876 ast_hangup: Hanging up channel 'SIP/somepeer-00000001'
[Aug 24 11:15:36] DEBUG[32030]: chan_sip.c:6385 sip_hangup: Hanging up zombie call. Be scared.
[Aug 24 11:15:36] DEBUG[32030]: chan_sip.c:6406 sip_hangup: Hanging up channel in state Down (not UP)
[Aug 24 11:15:36] DEBUG[32030]: res_rtp_asterisk.c:2564 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x212b7c8'
 == Everyone is busy/congested at this time (1:0/1/0)
[Aug 24 11:15:36] DEBUG[32030]: app_dial.c:3023 dial_exec_full: Exiting with DIALSTATUS=CONGESTION.
[Aug 24 11:15:36] DEBUG[32030]: pbx.c:3381 ast_str_retrieve_variable: Result of 'HANGUPCAUSE' is '18'
{noformat}

Instead of this:

{noformat}

[Aug 24 11:40:48] WARNING[32753]: chan_sip.c:3715 retrans_pkt: Retransmission timeout reached on transmission 3b0d93bd29a942d13718ea203a41342b@127.0.0.1:5060 for seqno 102 (Critical Request) -- See https://wiki.asterisk.org/wiki/display/AST/SIP+Retransmissions
Packet timed out after 6400ms with no response
[Aug 24 11:40:48] WARNING[32753]: chan_sip.c:3744 retrans_pkt: Hanging up call 3b0d93bd29a942d13718ea203a41342b@127.0.0.1:5060 - no reply to our critical packet (see https://wiki.asterisk.org/wiki/display/AST/SIP+Retransmissions).
[Aug 24 11:40:48] DEBUG[32753]: chan_sip.c:3108 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 3b0d93bd29a942d13718ea203a41342b@127.0.0.1:5060
[Aug 24 11:40:48] DEBUG[315]: channel.c:2876 ast_hangup: Hanging up channel 'SIP/somepeer-00000001'
[Aug 24 11:40:48] DEBUG[315]: chan_sip.c:6385 sip_hangup: Hanging up zombie call. Be scared.
[Aug 24 11:40:48] DEBUG[315]: chan_sip.c:6406 sip_hangup: Hanging up channel in state Down (not UP)
[Aug 24 11:40:48] DEBUG[315]: res_rtp_asterisk.c:2564 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x11e5e88'
 == Everyone is busy/congested at this time (1:0/0/1)
[Aug 24 11:40:48] DEBUG[315]: app_dial.c:3023 dial_exec_full: Exiting with DIALSTATUS=CHANUNAVAIL.
[Aug 24 11:40:48] DEBUG[32742]: devicestate.c:338 _ast_device_state: No provider found, checking channel drivers for SIP - somepeer
[Aug 24 11:40:48] DEBUG[32742]: chan_sip.c:27488 sip_devicestate: Checking device state for peer somepeer
[Aug 24 11:40:48] DEBUG[32742]: devicestate.c:456 do_state_change: Changing state for SIP/somepeer - state 1 (Not in use)
[Aug 24 11:40:48] DEBUG[315]: pbx.c:3381 ast_str_retrieve_variable: Result of 'HANGUPCAUSE' is '111'
{noformat}

But, since I cannot reproduce that, we'll ignore that bit.

In any case: yes, your patch fixes so it returns a nice 408 when the invite times out.

[x] Ship it!