[asterisk-users] Issue with handling of 480 DND

Fri Jan 6 12:47:54 CST 2017

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'
>
>
>