[asterisk-users] Issue with handling of 480 DND

Fri Jan 6 05:07:25 CST 2017

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" <sip:0160XXXXXXX at yyy.yyy.yyy.yy>;tag=as4ef364e1.
t: <sip:4120089 at 192.168.178.70:45731;line=8lln9qsq>;tag=0380h4r478.
i: 7568eb9e7c148e535166a89702423c3e at yyy.yyy.yyy.yy:5060.
CSeq: 102 INVITE.
User-Agent: snom760/8.7.5.13.
m: <sip:4120089 at 192.168.178.70:45731;line=8lln9qsq>;reg-id=1.
l: 0.
.

#
U 2017/01/06 11:38:29.516045 yyy.yyy.yyy.yy:5060 ->
xxx.xxx.xxx.xxx:45731
ACK sip:4120089 at 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" <sip:0160XXXXXXX at yyy.yyy.yyy.yy>;tag=as4ef364e1.
To: <sip:4120089 at 192.168.178.70:45731;line=8lln9qsq>;tag=0380h4r478.
Contact: <sip:0160XXXXXXX at yyy.yyy.yyy.yy:5060>.
Call-ID: 7568eb9e7c148e535166a89702423c3e at yyy.yyy.yyy.yy:5060.
CSeq: 102 ACK.
User-Agent: Asterisk PBX 13.12.1.
Content-Length: 0.
.

#
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: <sip:zzz.zzz.zzz.zzz;lr=on;ftag=as47cd4bd4>.
From: "49160XXXXXXX" <sip:49160XXXXXXX at 93.189.169.102>;tag=as47cd4bd4.
To: <sip:494XXXXXXXXX at zzz.zzz.zzz.zzz>;tag=as0823beee.
Call-ID: 15f8ee0e657ba8687db29cff0093c95b at 93.189.169.102:5060.
CSeq: 102 INVITE.
Server: Asterisk PBX 13.12.1.
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY,
INFO, PUBLISH, MESSAGE.
Supported: replaces, timer.
Session-Expires: 1800;refresher=uas.
Contact: <sip:494XXXXXXXXX at yyy.yyy.yyy.yy:5060>.
Content-Length: 0.
.

Asterisk Debug:

[Jan  6 11:38:29] VERBOSE[5383][C-000473c5] pbx.c: Executing
[494XXXXXXXXX at 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 at 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 at yyy.yyy.yyy.yy:5060' to
'7568eb9e7c148e535166a89702423c3e at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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'