[asterisk-users] SIP 603 response when call is not answered

Wed Aug 17 15:00:17 CDT 2016

On Wed, Aug 17, 2016 at 8:29 AM, Hooman Fazaeli <hoomanfazaeli at gmail.com> wrote:
> On 2016-08-16 12:10, Joris Engbers wrote:
>>
>> Hooman Fazaeli writes:
>>
>>> Hi
>>>
>>> I have noticed that asterisk returns 'SIP 603' when the called party does
>>> not answer.
>>>
>>> My test setup is simple: two SIP phones (extensions: 100 and 111)
>>> registered to an Asterisk 1.8.30.0 gateway.The Dial timeout is 30
>>> seconds.
>>> When 100 calls 111 and after 30 seconds, asterisk sends a CANCEL request
>>> to
>>> 111 (expected) and a '603 Decline' response to 100 (unexpected &
>>> misleading).
>>> It seems to me that a'480 Temporarily unavailable' response is more
>>> suitable in this situation.
>>>
>>> Is this a normal behavior of asterisk or a bug?
>>>
>>> Thanks.
>>
>> That sounds like you are not doing a Hangup().
>>
>> What is the dialplan that you are using?
>>
>
> Hangup() is there. The dial plan is:
>
> (I set dial timeout to 10s to speed up tests)
>
> [phone-100]
> exten => 111,1,Dial(SIP/111,10,tTo)
> exten => 111,n,Hangup()
>
> [phone-111]
> exten => 100,1,Dial(SIP/100,10,tTo)
> exten => 100,n,Hangup()
>
> As can be seen in below log messages, asterisk correctly sets DIALSTATUS to
> NOANSWER (line 7).
> Line 18 shows that the hangupcause value has been set to 16
> (AST_CAUSE_NORMAL_CLEARING) which
> asterisk complains has no SIP equivalent and falls back to 603. The problem
> seems to be
> that hangupcause is set incorrectly in the first place.
>
> ...
> <Dial() times out>
> ...
> 1 VERBOSE[-1]: app_dial.c:1633 in wait_for_answer:     -- Nobody picked up
> in 10000 ms
> 2 DEBUG[-1]: channel.c:2884 in ast_hangup: Hanging up channel
> 'SIP/111-00000003'
> 3 DEBUG[-1]: chan_sip.c:6553 in sip_hangup: Hangup call SIP/111-00000003,
> SIP callid 1a8ef4ce3f4d8a513de4639916c28b15 at 192.168.1.17:5060
> 4 DEBUG[-1]: chan_sip.c:6169 in update_call_counter: Updating call counter
> for outgoing call
> 5 DEBUG[-1]: chan_sip.c:6572 in sip_hangup: Hanging up channel in state
> Ringing (not UP)
> ...
> 6 DEBUG[-1]: chan_sip.c:3554 in __sip_xmit: Trying to put 'CANCEL sip:' onto
> UDP socket destined for 192.168.1.200:5062
> 7 DEBUG[-1]: app_dial.c:3033 in dial_exec_full: Exiting with
> DIALSTATUS=NOANSWER.
> 8 DEBUG[-1]: pbx.c:4720 in pbx_extension_helper: Launching 'Hangup'
> 9 VERBOSE[-1]: pbx.c:4728 in pbx_extension_helper:     -- Executing
> [111 at phone-100:2] Hangup("SIP/100-00000002", "") in new stack
> 10 DEBUG[-1]: pbx.c:5544 in __ast_pbx_run: Spawn extension (phone-100,111,2)
> exited non-zero on 'SIP/100-00000002'
> 11 VERBOSE[-1]: pbx.c:5545 in __ast_pbx_run:   == Spawn extension
> (SIP-PHONE-35145790056fd369709fb2, 111, 2) exited non-zero on
> 'SIP/100-00000002'
> 12 DEBUG[-1]: channel.c:2735 in ast_softhangup_nolock: Soft-Hanging up
> channel 'SIP/100-00000002'
> 13 DEBUG[-1]: channel.c:2884 in ast_hangup: Hanging up channel
> 'SIP/100-00000002'
> 14 DEBUG[-1]: chan_sip.c:6553 in sip_hangup: Hangup call SIP/100-00000002,
> SIP callid 9eda334cf9584d408ccd6e14eae7143a
> 15 DEBUG[-1]: chan_sip.c:6169 in update_call_counter: Updating call counter
> for incoming call
> 16 DEBUG[-1]: chan_sip.c:6572 in sip_hangup: Hanging up channel in state
> Ring (not UP)
> 17 DEBUG[-1]: res_rtp_asterisk.c:2604 in ast_rtp_remote_address_set: Setting
> RTCP address on RTP instance '0x29dbf01c'
> 18 DEBUG[-1]: chan_sip.c:6484 in hangup_cause2sip: AST hangup cause 16 (no
> match found in SIP)
> 19 DEBUG[-1]: chan_sip.c:3554 in __sip_xmit: Trying to put 'SIP/2.0 603'
> onto UDP socket destined for 192.168.1.30:52628
> 20 ...
> 21 DEBUG[-1]: devicestate.c:344 in _ast_device_state: No provider found,
> checking channel drivers for SIP - 111
> 22 DEBUG[-1]: chan_sip.c:27264 in sip_devicestate: Checking device state for
> peer 111
> 23 DEBUG[-1]: devicestate.c:467 in do_state_change: Changing state for
> SIP/111 - state 1 (Not in use)
> 24 DEBUG[-1]: devicestate.c:442 in devstate_event: device 'SIP/111' state
> '1'
> 25 DEBUG[-1]: devicestate.c:344 in _ast_device_state: No provider found,
> checking channel drivers for SIP - 111
> 26 DEBUG[-1]: chan_sip.c:27264 in sip_devicestate: Checking device state for
> peer 111
> 27 DEBUG[-1]: devicestate.c:467 in do_state_change: Changing state for
> SIP/111 - state 1 (Not in use)
> 28 DEBUG[-1]: devicestate.c:442 in devstate_event: device 'SIP/111' state
> '1'
> 29 DEBUG[-1]: devicestate.c:344 in _ast_device_state: No provider found,
> checking channel drivers for SIP - 100
> 30 DEBUG[-1]: chan_sip.c:27264 in sip_devicestate: Checking device state for
> peer 100
> 31 DEBUG[-1]: devicestate.c:467 in do_state_change: Changing state for
> SIP/100 - state 5 (Unavailable)
> 32 DEBUG[-1]: devicestate.c:442 in devstate_event: device 'SIP/100' state
> '5'
> 33 DEBUG[-1]: chan_sip.c:8436 in find_call: = Looking for  Call ID:
> 9eda334cf9584d408ccd6e14eae7143a (Checking From) --From tag
> 48505f8775334f429a54d48d5b095543 --To-tag as2ad3ad05
> 34 DEBUG[-1]: chan_sip.c:25954 in handle_incoming: **** Received ACK (6) -
> Command in SIP ACK
> 35 DEBUG[-1]: chan_sip.c:4238 in __sip_ack: Stopping retransmission on
> '9eda334cf9584d408ccd6e14eae7143a' of Response 21834: Match Found
> 36 DEBUG[-1]: chan_sip.c:8436 in find_call: = Looking for  Call ID:
> 1a8ef4ce3f4d8a513de4639916c28b15 at 192.168.1.17:5060 (Checking To) --From tag
> as212fb4c7 --To-tag 479449046
> 37 DEBUG[-1]: chan_sip.c:4200 in __sip_ack: Acked pending invite 102
> 38 DEBUG[-1]: chan_sip.c:4238 in __sip_ack: Stopping retransmission on
> '1a8ef4ce3f4d8a513de4639916c28b15 at 192.168.1.17:5060' of Request 102: Match
> Found
> 39 DEBUG[-1]: devicestate.c:344 in _ast_device_state: No provider found,
> checking channel drivers for SIP - 100
> 40 DEBUG[-1]: chan_sip.c:27264 in sip_devicestate: Checking device state for
> peer 100
> 41 DEBUG[-1]: devicestate.c:467 in do_state_change: Changing state for
> SIP/100 - state 5 (Unavailable)
> 42 DEBUG[-1]: devicestate.c:442 in devstate_event: device 'SIP/100' state
> '5'
> 43 DEBUG[-1]: chan_sip.c:8436 in find_call: = Looking for  Call ID:
> 1a8ef4ce3f4d8a513de4639916c28b15 at 192.168.1.17:5060 (Checking To) --From tag
> as212fb4c7 --To-tag 479449046
> 44 DEBUG[-1]: chan_sip.c:4238 in __sip_ack: Stopping retransmission on
> '1a8ef4ce3f4d8a513de4639916c28b15 at 192.168.1.17:5060' of Request 102: Match
> Found
> 45 DEBUG[-1]: chan_sip.c:20747 in handle_response_invite: SIP response 487
> to standard invite
> 46 DEBUG[-1]: chan_sip.c:3554 in __sip_xmit: Trying to put 'ACK sip:111'
> onto UDP socket destined for 192.168.1.200:5062
> 47 DEBUG[-1]: chan_sip.c:6169 in update_call_counter: Updating call counter
> for outgoing call
> 48 DEBUG[-1]: devicestate.c:344 in _ast_device_state: No provider found,
> checking channel drivers for SIP - 111
> 49 DEBUG[-1]: chan_sip.c:27264 in sip_devicestate: Checking device state for
> peer 111
> 50 DEBUG[-1]: devicestate.c:467 in do_state_change: Changing state for
> SIP/111 - state 1 (Not in use)
> 51 DEBUG[-1]: devicestate.c:442 in devstate_event: device 'SIP/111' state
> '1'
>

While it's a bit harsh, there's nothing inherently wrong with
returning a 603 in this case - so I wouldn't say it's a bug. Asterisk
has decided that since it tried everything it could about the
extension, the person at the other end must not want the call, and
hence opts for the global 6xx response as opposed to a 4xx response.

If you want to return something else, then you can provide a cause
code to the Hangup application that maps to the SIP response you'd
like to return. A mapping table exists on the wiki here:

https://wiki.asterisk.org/wiki/display/AST/Hangup+Cause+Mappings

In your case, providing a 19 to the Hangup dialplan application should
convert that to a SIP cause of 480.

-- 
Matthew Jordan
Digium, Inc. | CTO
445 Jan Davis Drive NW - Huntsville, AL 35806 - USA
Check us out at: http://digium.com & http://asterisk.org