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'
Nobody any idea? It would be really helpful, Markus Am 06.01.2017 um 12:07 schrieb Markus Weiler:> 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' > > >
Am 06.01.2017 um 12:07 schrieb Markus Weiler:> Hi List, > > we're calling a sip phone from our Asterisk Server, and try to add logic > depending on the dialstatus > > 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). > > Is this a bug or a feature? :-) How could we handle this correctly?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. On Fri, Jan 6, 2017 at 12:47 PM, Markus Weiler <markus_weiler at mailworks.org> wrote:> Nobody any idea? > > It would be really helpful, > > Markus > > > > > Am 06.01.2017 um 12:07 schrieb Markus Weiler: > >> 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? >> >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. -- Matthew Fredrickson Digium, Inc. | Engineering Manager 445 Jan Davis Drive NW - Huntsville, AL 35806 - USA -------------- next part -------------- An HTML attachment was scrubbed... URL: <http://lists.digium.com/pipermail/asterisk-users/attachments/20170110/44ebb106/attachment.html>