Issue With Handling Of 480 DND
Hi List,
we’re calling a sip phone from our Asterisk Server, and try to add logic depending on the dialstatus
Stripped down example;
exten = 494XXXXXXXXX,n,Dial(SIP/4120089,15,w)
exten = 494XXXXXXXXX,n,Goto(98-${DIALSTATUS},1)
exten = 494XXXXXXXXX,n,Hangup()
….. exten = 98-BUSY,1,NoOp(Busy)
exten = 98-BUSY,n,ExecIf($[“${Voicemail}” =
“1”]?Playback(/home/4120/mitarbeiter/ab))
…. exten = 98-NOANSWER,1,NoOp(noanswer)
exten = 98-NOANSWER,n,ExecIf($[“${Voicemail}” =
“1”]?Playback(/home/4120/mitarbeiter/ab))
….
Íf the phone call times out, the call is sent to 98-NOANSWER and then answered as expected. If the User presses DND on his phone the call is sent to 98-BUSY which is identical but then the call is hung up. This behaviour is unexpected/unwanted.
We tried to figure out what the difference is and think it’s how Asterisk handles the “480 Do Not Disturb” from the phone
(xxx.xxx.xxx.xxx). It is passed to our main incoming server (zzz.zzz.zzz.zzz) as “181 call is being forwarded”. Is this a bug or a feature? 🙂 How could we handle this correctly?
SIP and Asterisk debug log below. Any help would be appreciated!
Markus
SIP:
#
U 2017/01/06 11:38:29.515836 xxx.xxx.xxx.xxx:45731 ->
yyy.yyy.yyy.yy:5060
SIP/2.0 480 Do Not Disturb. v: SIP/2.0/UDP yyy.yyy.yyy.yy:5060;branch=z9hG4bK749dbc68;rport=5060. f: “0160XXXXXXX”
.
#
U 2017/01/06 11:38:29.516045 yyy.yyy.yyy.yy:5060 ->
xxx.xxx.xxx.xxx:45731
ACK sip:4120089@192.168.178.70:45731;line=8lln9qsq SIP/2.0. Via: SIP/2.0/UDP yyy.yyy.yyy.yy:5060;branch=z9hG4bK749dbc68;rport. Max-Forwards: 70. From: “0160XXXXXXX”
.
#
U 2017/01/06 11:38:29.516166 yyy.yyy.yyy.yy:5060 -> zzz.zzz.zzz.zzz:5060
SIP/2.0 181 Call is being forwarded. Via: SIP/2.0/UDP
zzz.zzz.zzz.zzz;branch=z9hG4bK120a.dcdd311bf80a9536d4eec1ce380f66a7.0;received=zzz.zzz.zzz.zzz. Via: SIP/2.0/UDP 93.189.169.102:5060;branch=z9hG4bK4ec14865. Record-Route:
.
Asterisk Debug:
[Jan 6 11:38:29] VERBOSE[5383][C-000473c5] pbx.c: Executing
[494XXXXXXXXX@4120:7] Dial(“SIP/SER_IB-0004cd6d”, “SIP/4120089,15,w”) in new stack
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] chan_sip.c: Asked to create a SIP channel with formats: (alaw)
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] chan_sip.c: Allocating new SIP
dialog for 0dac947057f4ddc613b1391948770916@yyy.yyy.yyy.yy:5060 – INVITE
(No RTP)
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] rtp_engine.c: Using engine
‘asterisk’ for RTP instance ‘0x7fae14073678’
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] res_rtp_asterisk.c: Allocated port 14098 for RTP instance ‘0x7fae14073678’
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] rtp_engine.c: RTP instance
‘0x7fae14073678’ is setup and ready to go
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] acl.c: Not an IPv4 nor IPv6
address, cannot get port.
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] netsock2.c: Splitting ‘pbx6’
into…
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] netsock2.c: …host ‘pbx6’ and port ”.
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] res_rtp_asterisk.c: Setup RTCP
on RTP instance ‘0x7fae14073678’
[Jan 6 11:38:29] VERBOSE[5383][C-000473c5] netsock2.c: Using SIP RTP
TOS bits 184
[Jan 6 11:38:29] VERBOSE[5383][C-000473c5] netsock2.c: Using SIP RTP
CoS mark 5
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] chan_sip.c: Setting NAT on RTP
to On
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] acl.c: For destination
‘xxx.xxx.xxx.xxx’, our source address is ‘yyy.yyy.yyy.yy’.
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] chan_sip.c: Setting AST_TRANSPORT_UDP with address yyy.yyy.yyy.yy:5060
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] chan_sip.c: Setting NAT on RTP
to On
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] chan_sip.c: SIP call-id changed from ‘0dac947057f4ddc613b1391948770916@yyy.yyy.yyy.yy:5060’ to
‘7568eb9e7c148e535166a89702423c3e@yyy.yyy.yyy.yy:5060’
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] chan_sip.c: *** Our native formats are (alaw)
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] chan_sip.c: *** Joint capabilities are (alaw)
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] chan_sip.c: *** Our capabilities are (alaw|ulaw|gsm)
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] chan_sip.c: ***
AST_CODEC_CHOOSE formats are alaw
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] chan_sip.c: *** Our preferred formats from the incoming channel are (alaw)
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] chan_sip.c: This channel will not be able to handle video.
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] channel_internal_api.c:
Channel Call ID changing from [C-000473c5] to [C-000473c5]
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] chan_sip.c: Outgoing Call for
4120089
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] chan_sip.c: Updating call counter for outgoing call
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] chan_sip.c: ** Our capability:
(alaw|ulaw|gsm) Video flag: False Text flag: False
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] chan_sip.c: ** Our prefcodec:
(alaw)
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] chan_sip.c: — Done with adding codecs to SDP
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] chan_sip.c: Done building SDP. Settling with this capability: (alaw|ulaw|gsm)
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] chan_sip.c: Initializing initreq for method INVITE – callid
7568eb9e7c148e535166a89702423c3e@yyy.yyy.yyy.yy:5060
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] chan_sip.c: Trying to put
‘INVITE sip:’ onto UDP socket destined for xxx.xxx.xxx.xxx:45731
[Jan 6 11:38:29] VERBOSE[5383][C-000473c5] app_dial.c: Called SIP/4120089
[Jan 6 11:38:29] DEBUG[28758][C-000473c5] chan_sip.c: (Provisional)
Stopping retransmission (but retaining packet) on
‘7568eb9e7c148e535166a89702423c3e@yyy.yyy.yyy.yy:5060’ Request 102:
Found
[Jan 6 11:38:29] DEBUG[28758][C-000473c5] chan_sip.c: SIP response 100
to standard invite
[Jan 6 11:38:29] DEBUG[28758][C-000473c5] chan_sip.c: Acked pending invite 102
[Jan 6 11:38:29] DEBUG[28758][C-000473c5] chan_sip.c: Stopping retransmission on ‘7568eb9e7c148e535166a89702423c3e@yyy.yyy.yyy.yy:5060’
of Request 102: Match Found
[Jan 6 11:38:29] DEBUG[28758][C-000473c5] chan_sip.c: SIP response 480
to standard invite
[Jan 6 11:38:29] DEBUG[28758][C-000473c5] chan_sip.c: Trying to put
‘ACK sip:412’ onto UDP socket destined for xxx.xxx.xxx.xxx:45731
[Jan 6 11:38:29] VERBOSE[5383][C-000473c5] app_dial.c:
SIP/4120089-0004cd6e redirecting info has changed, passing it to SIP/SER_IB-0004cd6d
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] chan_sip.c: Trying to put
‘SIP/2.0 181’ onto UDP socket destined for zzz.zzz.zzz.zzz:5060
[Jan 6 11:38:29] VERBOSE[5383][C-000473c5] app_dial.c:
SIP/4120089-0004cd6e is busy
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] channel.c: Hanging up channel
‘SIP/4120089-0004cd6e’
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] chan_sip.c: Hangup call SIP/4120089-0004cd6e, SIP callid
7568eb9e7c148e535166a89702423c3e@yyy.yyy.yyy.yy:5060
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] chan_sip.c: Updating call counter for outgoing call
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] res_rtp_asterisk.c: Setting RTCP address on RTP instance ‘0x7fae14073678’
[Jan 6 11:38:29] VERBOSE[5383][C-000473c5] app_dial.c: Everyone is busy/congested at this time (1:1/0/0)
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] app_dial.c: Exiting with DIALSTATUS=BUSY.
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] pbx_variables.c: Result of
‘DIALSTATUS’ is ‘BUSY’
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] pbx.c: Launching ‘Goto’
[Jan 6 11:38:29] VERBOSE[5383][C-000473c5] pbx.c: Executing
[494XXXXXXXXX@4120:8] Goto(“SIP/SER_IB-0004cd6d”, “98-BUSY,1”) in new stack
[Jan 6 11:38:29] VERBOSE[5383][C-000473c5] pbx_builtins.c: Goto
(4120,98-BUSY,1)
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] pbx.c: Launching ‘NoOp’
[Jan 6 11:38:29] VERBOSE[5383][C-000473c5] pbx.c: Executing
[98-BUSY@4120:1] NoOp(“SIP/SER_IB-0004cd6d”, “Busy”) in new stack
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] pbx_variables.c: Result of
‘Voicemail’ is ‘1’
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] pbx_variables.c: Expression result is ‘1’
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] pbx.c: Launching ‘ExecIf’
[Jan 6 11:38:29] VERBOSE[5383][C-000473c5] pbx.c: Executing
[98-BUSY@4120:2] ExecIf(“SIP/SER_IB-0004cd6d”,
“1?Playback(/home/4120/mitarbeiter/ab)”) in new stack
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] chan_sip.c: SIP answering channel: SIP/SER_IB-0004cd6d
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] res_rtp_asterisk.c: Setting the marker bit due to a source update
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] chan_sip.c: ** Our capability:
(alaw|ulaw|gsm) Video flag: True Text flag: True
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] chan_sip.c: ** Our prefcodec:
(nothing)
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] chan_sip.c: — Done with adding codecs to SDP
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] chan_sip.c: Setting framing on incoming call: 0
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] chan_sip.c: Done building SDP. Settling with this capability: (alaw|ulaw|gsm)
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] chan_sip.c: Trying to put
‘SIP/2.0 200′ onto UDP socket destined for zzz.zzz.zzz.zzz:5060
[Jan 6 11:38:29] DEBUG[28758][C-000473c5] chan_sip.c: **** Received ACK
(6) – Command in SIP ACK
[Jan 6 11:38:29] DEBUG[28758][C-000473c5] chan_sip.c: Stopping retransmission on ’15f8ee0e657ba8687db29cff0093c95b@93.189.169.102:5060’
of Response 102: Match Found
[Jan 6 11:38:29] DEBUG[28758][C-000473c5] chan_sip.c: **** Received BYE
(8) – Command in SIP BYE
[Jan 6 11:38:29] DEBUG[28758][C-000473c5] netsock2.c: Splitting
‘zzz.zzz.zzz.zzz’ into…
[Jan 6 11:38:29] DEBUG[28758][C-000473c5] netsock2.c: …host
‘zzz.zzz.zzz.zzz’ and port ”.
[Jan 6 11:38:29] DEBUG[28758][C-000473c5] chan_sip.c: Setting SIP_ALREADYGONE on dialog
15f8ee0e657ba8687db29cff0093c95b@zzz.zzz.zzz.zzz:5060
[Jan 6 11:38:29] DEBUG[28758][C-000473c5] res_rtp_asterisk.c: Setting RTCP address on RTP instance ‘0x7fae95307ec8’
[Jan 6 11:38:29] DEBUG[28758][C-000473c5] chan_sip.c: Received bye, issuing owner hangup
[Jan 6 11:38:29] DEBUG[28758][C-000473c5] chan_sip.c: Trying to put
‘SIP/2.0 200’ onto UDP socket destined for zzz.zzz.zzz.zzz:5060
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] channel.c: Hangup of channel SIP/SER_IB-0004cd6d detected in answer routine
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] pbx.c: Spawn extension
(4120,98-BUSY,2) exited non-zero on ‘SIP/SER_IB-0004cd6d’
[Jan 6 11:38:29] VERBOSE[5383][C-000473c5] pbx.c: Spawn extension
(4120, 98-BUSY, 2) exited non-zero on ‘SIP/SER_IB-0004cd6d’
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] channel.c: Soft-Hanging (0x10)
up channel ‘SIP/SER_IB-0004cd6d’
[Jan 6 11:38:29] DEBUG[5383][C-000473c5] channel.c: Soft-Hanging (0x80)
up channel ‘SIP/SER_IB-0004cd6d’
—
3 thoughts on - Issue With Handling Of 480 DND
Nobody any idea?
It would be really helpful,
Markus
Am 06.01.2017 um 12:07 schrieb Markus Weiler:
—
Am 06.01.2017 um 12:07 schrieb Markus Weiler:
I *think* you can parse HANGUPCAUSE to catch that? But really not sure.
Here’s a snippet I stole from somewhere to do failover to a 2nd gateway:
exten =>
_something.,n,GotoIf($[“${DIALSTATUS}”=”CHANUNAVAIL”|”${DIALSTATUS}”=”CONGESTION”|”${HANGUPCAUSE}”=”34”]?failover)
Not really sure how or if that works, but googling Asterisk Hangupcause should get you started?
Good luck.
Response inline.
I believe that this is a consequence of the fact that when chan_sip receives a “480 Do Not Disturb” it also queues a redirecting_update frame on the channel. My guess is that the redirecting update is probably triggering the “181 Call is being forward as well”. If you add the ‘I’
flag to your dial, I believe it should suppress bridging of the redirection information and I would think that would also cause the 181 not to be sent. If it’s not that flag, I’d check the documentation for app_dial, as I’m pretty sure there’s a flag that should suppress that redirection from from being bridged to the calling channel.
Hope that helps.