Dial Command and Timeout

Netzilla · June 10, 2010, 11:39pm

When we use the Dial command from our Dialplan, it does not seem to matter what we set our timeout value to, it always rings for a maximum of 30 seconds. We’re making sure to dial a number that does not have voicemail or the like. Here is the command we are currently using:

Dial(SIP/912345678900@nisc,60)

We’ve also tried setting the timeout to 0, which according to the documentation we’ve read, should cause the line to ring indefinitely.

Dial(SIP/912345678900@nisc,0)

However, this is the output we get from the CLI:

-- Executing [dial@outdial:1] Set("Local/dial@outdial-e774;2", "GROUP()=outboundgroup") in new stack
    -- Executing [dial@outdial:2] NoOp("Local/dial@outdial-e774;2", "Num Outbound Calls = 1") in new stack
    -- Executing [dial@outdial:3] Set("Local/dial@outdial-e774;2", "GLOBAL(OUT_COUNT)=1") in new stack
  == Setting global variable 'OUT_COUNT' to '1'
    -- Executing [dial@outdial:4] GotoIf("Local/dial@outdial-e774;2", "0?outlimit,1") in new stack
    -- Executing [dial@outdial:5] NoOp("Local/dial@outdial-e774;2", "Dial String = SIP/912345678900@nisc") in new stack
    -- Executing [dial@outdial:6] NoOp("Local/dial@outdial-e774;2", "Dial Timeout = 0") in new stack
    -- Executing [dial@outdial:7] Dial("Local/dial@outdial-e774;2", "SIP/912345678900@nisc,0") in new stack
  == Using SIP RTP CoS mark 5
    -- Called 912345678900@nisc
[Jun 10 17:50:02] WARNING[24409]: app_dial.c:1641 dial_exec_full: Invalid timeout specified: '0'. Setting timeout to infinite
    -- SIP/nisc-00000002 is ringing
  == Spawn extension (outdial, dial, 7) exited non-zero on 'Local/dial@outdial-e774;2'

There is roughly 30 seconds between the execution of the Dial command and the final line quoted above.

Here is the contents of our sip.conf file:

[general]
;allowoverlap=no
bindport=5060
bindaddr=0.0.0.0
srvlookup=yes
'nat=no
'qualify=no

[test1_sip]
type=friend
context=users
host=dynamic

[test2_sip]
type=friend
context=users
host=dynamic

[test3_sip]
type=friend
context=users
host=dynamic

[test4_sip]
type=friend
context=users
host=dynamic

Anyone have any thoughts on this? Thanks in advance.

david55 · June 11, 2010, 11:44am

Please provide a sip debug trace of the actual SIP dialogue.

Netzilla · June 11, 2010, 2:20pm

Here’s our sip debug:

5001ivr1*CLI> sip set debug on
SIP Debugging enabled
    -- Executing [dial@outdial:1] Set("Local/dial@outdial-37fa;2", "GROUP()=outboundgroup") in new stack
    -- Executing [dial@outdial:2] NoOp("Local/dial@outdial-37fa;2", "Num Outbound Calls = 1") in new stack
    -- Executing [dial@outdial:3] Set("Local/dial@outdial-37fa;2", "GLOBAL(OUT_COUNT)=1") in new stack
  == Setting global variable 'OUT_COUNT' to '1'
    -- Executing [dial@outdial:4] GotoIf("Local/dial@outdial-37fa;2", "0?outlimit,1") in new stack
    -- Executing [dial@outdial:5] NoOp("Local/dial@outdial-37fa;2", "Dial String = SIP/911234567890@nisc") in new stack
    -- Executing [dial@outdial:6] NoOp("Local/dial@outdial-37fa;2", "Dial Timeout = 45") in new stack
    -- Executing [dial@outdial:7] Dial("Local/dial@outdial-37fa;2", "SIP/911234567890@nisc,45") in new stack
  == Using SIP RTP CoS mark 5
Audio is at 10.45.1.13 port 11498
Adding codec 0x2 (gsm) to SDP
Adding codec 0x4 (ulaw) to SDP
Adding codec 0x8 (alaw) to SDP
Adding non-codec 0x1 (telephone-event) to SDP
Reliably Transmitting (no NAT) to 1.1.1.1:5060:
INVITE sip:911234567890@1.1.1.1 SIP/2.0
Via: SIP/2.0/UDP 2.2.2.2:5060;branch=z9hG4bK27cfd865;rport
Max-Forwards: 70
From: "asterisk" <sip:asterisk@2.2.2.2>;tag=as3c82eccf
To: <sip:911234567890@1.1.1.1>
Contact: <sip:asterisk@2.2.2.2>
Call-ID: 4a8515494d1fd44f328b1b2e0a203d3b@2.2.2.2
CSeq: 102 INVITE
User-Agent: Asterisk PBX 1.6.1.14
Date: Fri, 11 Jun 2010 14:05:47 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces, timer
Content-Type: application/sdp
Content-Length: 305

v=0
o=root 559615843 559615843 IN IP4 2.2.2.2
s=Asterisk PBX 1.6.1.14
c=IN IP4 2.2.2.2
t=0 0
m=audio 11498 RTP/AVP 3 0 8 101
a=rtpmap:3 GSM/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

---
    -- Called 911234567890@nisc
45001ivr1*CLI> 
<--- SIP read from UDP://1.1.1.1:5060 --->
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 2.2.2.2:5060;branch=z9hG4bK27cfd865;rport=5060
Contact: <sip:911234567890@1.1.1.1>
To: <sip:911234567890@1.1.1.1>;tag=3f27b94a
From: "asterisk"<sip:asterisk@2.2.2.2>;tag=as3c82eccf
Call-ID: 4a8515494d1fd44f328b1b2e0a203d3b@2.2.2.2
CSeq: 102 INVITE
User-Agent: Zoiper rev.6751
Content-Length: 0


<------------->
--- (9 headers 0 lines) ---
    -- SIP/nisc-00000004 is ringing
45001ivr1*CLI> 
<--- SIP read from UDP://1.1.1.1:5060 --->



<------------->
Scheduling destruction of SIP dialog '4a8515494d1fd44f328b1b2e0a203d3b@2.2.2.2' in 32000 ms (Method: INVITE)
Reliably Transmitting (no NAT) to 1.1.1.1:5060:
CANCEL sip:911234567890@1.1.1.1 SIP/2.0
Via: SIP/2.0/UDP 2.2.2.2:5060;branch=z9hG4bK27cfd865;rport
Max-Forwards: 70
From: "asterisk" <sip:asterisk@2.2.2.2>;tag=as3c82eccf
To: <sip:911234567890@1.1.1.1>
Call-ID: 4a8515494d1fd44f328b1b2e0a203d3b@2.2.2.2
CSeq: 102 CANCEL
User-Agent: Asterisk PBX 1.6.1.14
Content-Length: 0


---
Scheduling destruction of SIP dialog '4a8515494d1fd44f328b1b2e0a203d3b@2.2.2.2' in 32000 ms (Method: INVITE)
  == Spawn extension (outdial, dial, 7) exited non-zero on 'Local/dial@outdial-37fa;2'
45001ivr1*CLI> 
<--- SIP read from UDP://1.1.1.1:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 2.2.2.2:5060;branch=z9hG4bK27cfd865;rport=5060
Contact: <sip:911234567890@1.1.1.1>
To: <sip:911234567890@1.1.1.1>;tag=3f27b94a
From: "asterisk"<sip:asterisk@2.2.2.2>;tag=as3c82eccf
Call-ID: 4a8515494d1fd44f328b1b2e0a203d3b@2.2.2.2
CSeq: 102 CANCEL
User-Agent: Zoiper rev.6751
Content-Length: 0


<------------->
--- (9 headers 0 lines) ---
45001ivr1*CLI> 
<--- SIP read from UDP://1.1.1.1:5060 --->
SIP/2.0 487 Request Terminated
Via: SIP/2.0/UDP 2.2.2.2:5060;branch=z9hG4bK27cfd865;rport=5060
To: <sip:911234567890@1.1.1.1>;tag=3f27b94a
From: "asterisk"<sip:asterisk@2.2.2.2>;tag=as3c82eccf
Call-ID: 4a8515494d1fd44f328b1b2e0a203d3b@2.2.2.2
CSeq: 102 INVITE
User-Agent: Zoiper rev.6751
Content-Length: 0


<------------->
--- (8 headers 0 lines) ---
Transmitting (no NAT) to 1.1.1.1:5060:
ACK sip:911234567890@1.1.1.1 SIP/2.0
ia: SIP/2.0/UDP 2.2.2.2:5060;branch=z9hG4bK27cfd865;rport
Max-Forwards: 70
From: "asterisk" <sip:asterisk@2.2.2.2>;tag=as3c82eccf
To: <sip:911234567890@1.1.1.1>;tag=3f27b94a
Contact: <sip:asterisk@2.2.2.2>
Call-ID: 4a8515494d1fd44f328b1b2e0a203d3b@2.2.2.2
CSeq: 102 ACK
User-Agent: Asterisk PBX 1.6.1.14
Content-Length: 0


---
Really destroying SIP dialog '4a8515494d1fd44f328b1b2e0a203d3b@2.2.2.2' Method: INVITE
45001ivr1*CLI>

david55 · June 11, 2010, 2:34pm

Asterisk initiated the disconnect. What’s the incoming technology? Could it be timing out after 30 seconds with no intermediate responses.

You may have to turn up the debugging level to find out why. It shouldn’t be doing anything before three minutes, unless the caller goes away.

david55 · June 11, 2010, 2:44pm

Actually, could you provide the logs from the log file. You may have to uncomment full in logger.conf.

The Scheduling line seems to be in the wrong order with respect to the Ringing one, and I’d like to see if the Ringing came back very fast. You may have uncovered a race condition.

Are you using a recent supported version, or a recent trunk version?

Netzilla · June 11, 2010, 3:10pm

We’re using Asterisk 1.6.1.14-1 and Libpri 1.4.10.2-1

Here’s one of our calls with full logging turned on:

[Jun 11 10:02:19] VERBOSE[31518] logger.c:  Asterisk Queue Logger restarted
[Jun 11 10:02:24] VERBOSE[31518] asterisk.c:     -- Remote UNIX connection disconnected
[Jun 11 10:02:30] NOTICE[27120] chan_sip.c:    -- Registration for 'ivueivrtest@1.1.1.1' timed out, trying again (Attempt #3364)
[Jun 11 10:02:45] VERBOSE[31584] pbx.c:     -- Executing [dial@outdial:1] ^[[1;36;40mNoOp^[[0;37;40m("^[[1;35;40mLocal/dial@outdial-0664;2^[[0;37;40m", "^[[$
[Jun 11 10:02:45] VERBOSE[31584] pbx.c:     -- Executing [dial@outdial:2] ^[[1;36;40mNoOp^[[0;37;40m("^[[1;35;40mLocal/dial@outdial-0664;2^[[0;37;40m", "^[[$
[Jun 11 10:02:45] VERBOSE[31584] pbx.c:     -- Executing [dial@outdial:3] ^[[1;36;40mDial^[[0;37;40m("^[[1;35;40mLocal/dial@outdial-0664;2^[[0;37;40m", "^[[$
[Jun 11 10:02:45] VERBOSE[31584] netsock.c:   == Using SIP RTP CoS mark 5
[Jun 11 10:02:45] VERBOSE[31584] app_dial.c:     -- Called 911234567890@ss_polycom
[Jun 11 10:02:45] VERBOSE[31584] app_dial.c:     -- SIP/ss_polycom-006ec7f8 is ringing
[Jun 11 10:02:50] NOTICE[27120] chan_sip.c:    -- Registration for 'ivueivrtest@1.1.1.1' timed out, trying again (Attempt #3365)
[Jun 11 10:03:10] NOTICE[27120] chan_sip.c:    -- Registration for 'ivueivrtest@1.1.1.1' timed out, trying again (Attempt #3366)
[Jun 11 10:03:15] VERBOSE[31584] pbx.c:   == Spawn extension (outdial, dial, 3) exited non-zero on 'Local/dial@outdial-0664;2'

david55 · June 11, 2010, 3:13pm

Sorry. You need SIP debugging as well. What I’m looking for is the time delay between the INVITE and the 180 Ringing.

Netzilla · June 11, 2010, 3:32pm

Here’s the full log with SIP debugging on:

[Jun 11 10:21:52] VERBOSE[1994] config.c:   == Parsing '/etc/asterisk/logger.conf': [Jun 11 10:21:52] VERBOSE[1994] config.c:   == Found
[Jun 11 10:21:52] VERBOSE[1994] logger.c:  Asterisk Event Logger restarted
[Jun 11 10:21:52] VERBOSE[1994] logger.c:  Asterisk Queue Logger restarted
[Jun 11 10:21:52] VERBOSE[27120] chan_sip.c: 
<--- SIP read from UDP://1.1.1.1:5061 --->



<------------->
[Jun 11 10:21:55] VERBOSE[27120] chan_sip.c: 
<--- SIP read from UDP://2.2.2.2:5060 --->



<------------->
[Jun 11 10:22:00] VERBOSE[27120] chan_sip.c: 
<--- SIP read from UDP://3.3.3.3:5061 --->



<------------->
[Jun 11 10:22:15] VERBOSE[27120] chan_sip.c: 
<--- SIP read from UDP://4.4.4.4:5060 --->
REGISTER sip:10.27.1.75 SIP/2.0
Via: SIP/2.0/UDP 4.4.4.4:5060;branch=z9hG4bK7e2d39b5;rport
Max-Forwards: 70
From: <sip:vmivr1@10.27.1.75>;tag=as0d912321
To: <sip:vmivr1@10.27.1.75>
Call-ID: 23734a0b1d01899f53d1bfe02541d418@4.4.4.4
CSeq: 122 REGISTER
User-Agent: Asterisk PBX 1.6.1.13
Authorization: Digest username="vmivr1", realm="asterisk", algorithm=MD5, uri="sip:5.5.5.5", nonce="7bcf11af", response="46d3f7b52af692f7a7121f962844b7c3"
Expires: 120
Contact: <sip:s@4.4.4.4>
Content-Length: 0


<------------->
[Jun 11 10:22:15] VERBOSE[27120] chan_sip.c: --- (12 headers 0 lines) ---
[Jun 11 10:22:15] VERBOSE[27120] chan_sip.c: Sending to 4.4.4.4 : 5060 (NAT)
[Jun 11 10:22:15] VERBOSE[27120] chan_sip.c: 
<--- Transmitting (no NAT) to 4.4.4.4:5060 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 4.4.4.4:5060;branch=z9hG4bK7e2d39b5;received=4.4.4.4;rport=5060
From: <sip:vmivr1@5.5.5.5>;tag=as0d912321
To: <sip:vmivr1@5.5.5.5>;tag=as1bbaa248
Call-ID: 23734a0b1d01899f53d1bfe02541d418@4.4.4.4
CSeq: 122 REGISTER
Server: Asterisk PBX 1.6.1.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="2dc09c8b"
Content-Length: 0


<------------>
[Jun 11 10:22:15] VERBOSE[27120] chan_sip.c: Scheduling destruction of SIP dialog '23734a0b1d01899f53d1bfe02541d418@4.4.4.4' in 32000 ms (Method: REGISTER)
[Jun 11 10:22:15] VERBOSE[27120] chan_sip.c: 
<--- SIP read from UDP://4.4.4.4:5060 --->
REGISTER sip:5.5.5.5 SIP/2.0
Via: SIP/2.0/UDP 4.4.4.4:5060;branch=z9hG4bK6d191d37;rport
Max-Forwards: 70
From: <sip:vmivr1@5.5.5.5>;tag=as68b0de77
To: <sip:vmivr1@5.5.5.5>
Call-ID: 23734a0b1d01899f53d1bfe02541d418@4.4.4.4
CSeq: 123 REGISTER
User-Agent: Asterisk PBX 1.6.1.13
Authorization: Digest username="vmivr1", realm="asterisk", algorithm=MD5, uri="sip:5.5.5.5", nonce="2dc09c8b", response="765d92f5b971866b2721afc19ad09094"
Expires: 120
Contact: <sip:s@4.4.4.4>
Content-Length: 0


<------------->
[Jun 11 10:22:15] VERBOSE[27120] chan_sip.c: --- (12 headers 0 lines) ---
[Jun 11 10:22:15] VERBOSE[27120] chan_sip.c: Sending to 4.4.4.4 : 5060 (NAT)
[Jun 11 10:22:16] VERBOSE[27120] chan_sip.c: 
<--- Transmitting (no NAT) to 4.4.4.4:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 4.4.4.4:5060;branch=z9hG4bK6d191d37;received=4.4.4.4;rport=5060
From: <sip:vmivr1@5.5.5.5>;tag=as68b0de77
To: <sip:vmivr1@5.5.5.5>;tag=as1bbaa248
Call-ID: 23734a0b1d01899f53d1bfe02541d418@4.4.4.4
CSeq: 123 REGISTER
Server: Asterisk PBX 1.6.1.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces, timer
Expires: 120
Contact: <sip:s@4.4.4.4>;expires=120
Date: Fri, 11 Jun 2010 15:22:16 GMT
Content-Length: 0


<------------>
[Jun 11 10:22:16] VERBOSE[27120] chan_sip.c: Scheduling destruction of SIP dialog '23734a0b1d01899f53d1bfe02541d418@4.4.4.4' in 32000 ms (Method: REGISTER)
[Jun 11 10:22:17] NOTICE[27120] chan_sip.c:    -- Re-registration for  ivueivrtest@4.4.4.4
[Jun 11 10:22:17] VERBOSE[27120] chan_sip.c: REGISTER 12 headers, 0 lines
[Jun 11 10:22:17] VERBOSE[27120] chan_sip.c: Reliably Transmitting (no NAT) to 4.4.4.4:5060:
REGISTER sip:4.4.4.4 SIP/2.0
Via: SIP/2.0/UDP 5.5.5.5:5060;branch=z9hG4bK0002c705;rport
Max-Forwards: 70
From: <sip:ivueivrtest@4.4.4.4>;tag=as01f3c5f1
To: <sip:ivueivrtest@4.4.4.4>
Call-ID: 305c177e6b74185a0000df994156d553@5.5.5.5
CSeq: 15210 REGISTER
User-Agent: Asterisk PBX 1.6.1.1
Authorization: Digest username="ivueivrtest", realm="asterisk", algorithm=MD5, uri="sip:4.4.4.4", nonce="0dac0b1a", response="3b06572e85ded47fdb3fe097ead29a30"
Expires: 120
Contact: <sip:s@5.5.5.5>
Content-Length: 0


---
[Jun 11 10:22:17] VERBOSE[27120] chan_sip.c: 
<--- SIP read from UDP://4.4.4.4:5060 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 5.5.5.5:5060;branch=z9hG4bK0002c705;received=5.5.5.5;rport=5060
From: <sip:ivueivrtest@4.4.4.4>;tag=as01f3c5f1
To: <sip:ivueivrtest@4.4.4.4>;tag=as34dd910e
Call-ID: 305c177e6b74185a0000df994156d553@5.5.5.5
CSeq: 15210 REGISTER
Server: Asterisk PBX 1.6.1.13
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="419e2192"
Content-Length: 0


<------------->
[Jun 11 10:22:17] VERBOSE[27120] chan_sip.c: --- (11 headers 0 lines) ---
[Jun 11 10:22:17] VERBOSE[27120] chan_sip.c: Responding to challenge, registration to domain/host name 4.4.4.4
[Jun 11 10:22:17] VERBOSE[27120] chan_sip.c: REGISTER 12 headers, 0 lines
[Jun 11 10:22:17] VERBOSE[27120] chan_sip.c: Reliably Transmitting (no NAT) to 4.4.4.4:5060:
REGISTER sip:4.4.4.4 SIP/2.0
Via: SIP/2.0/UDP 5.5.5.5:5060;branch=z9hG4bK05612e8d;rport
Max-Forwards: 70
From: <sip:ivueivrtest@4.4.4.4>;tag=as219dc0ae
To: <sip:ivueivrtest@4.4.4.4>
Call-ID: 305c177e6b74185a0000df994156d553@5.5.5.5
CSeq: 15211 REGISTER
User-Agent: Asterisk PBX 1.6.1.1
Authorization: Digest username="ivueivrtest", realm="asterisk", algorithm=MD5, uri="sip:4.4.4.4", nonce="419e2192", response="56e21029e8dec396c008ba356b90b100"
Expires: 120
Contact: <sip:s@5.5.5.5>
Content-Length: 0


---
[Jun 11 10:22:17] VERBOSE[27120] chan_sip.c: 
<--- SIP read from UDP://4.4.4.4:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 5.5.5.5:5060;branch=z9hG4bK05612e8d;received=5.5.5.5;rport=5060
From: <sip:ivueivrtest@4.4.4.4>;tag=as219dc0ae
To: <sip:ivueivrtest@4.4.4.4>;tag=as34dd910e
Call-ID: 305c177e6b74185a0000df994156d553@5.5.5.5
CSeq: 15211 REGISTER
Server: Asterisk PBX 1.6.1.13
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces, timer
Expires: 120
Contact: <sip:s@5.5.5.5>;expires=120
Date: Fri, 11 Jun 2010 15:22:30 GMT
Content-Length: 0


<------------->
[Jun 11 10:22:17] VERBOSE[27120] chan_sip.c: --- (13 headers 0 lines) ---
[Jun 11 10:22:17] VERBOSE[27120] chan_sip.c: Scheduling destruction of SIP dialog '305c177e6b74185a0000df994156d553@5.5.5.5' in 32000 ms (Method: REGISTER)
[Jun 11 10:22:17] NOTICE[27120] chan_sip.c: Outbound Registration: Expiry for 4.4.4.4 is 120 sec (Scheduling reregistration in 105 s)
[Jun 11 10:22:22] VERBOSE[27120] chan_sip.c: 
<--- SIP read from UDP://1.1.1.1:5061 --->



<------------->
[Jun 11 10:22:25] VERBOSE[27120] chan_sip.c: 
<--- SIP read from UDP://2.2.2.2:5060 --->



<------------->
[Jun 11 10:22:30] VERBOSE[27120] chan_sip.c: 
<--- SIP read from UDP://3.3.3.3:5061 --->



<------------->
[Jun 11 10:22:47] VERBOSE[2208] pbx.c:     -- Executing [dial@outdial:1] e[1;36;40mSete[0;37;40m("e[1;35;40mLocal/dial@outdial-458c;2e[0;37;40m", "e[1;35;40mTIMEOUT(response)=3e[0;37;40m") in new stack
[Jun 11 10:22:47] VERBOSE[2208] func_timeout.c:     -- Response timeout set to 3.000
[Jun 11 10:22:47] VERBOSE[2208] pbx.c:     -- Executing [dial@outdial:2] e[1;36;40mNoOpe[0;37;40m("e[1;35;40mLocal/dial@outdial-458c;2e[0;37;40m", "e[1;35;40mDial String = SIP/911234567890@ss_polycome[0;37;40m") in new stack
[Jun 11 10:22:47] VERBOSE[2208] pbx.c:     -- Executing [dial@outdial:3] e[1;36;40mNoOpe[0;37;40m("e[1;35;40mLocal/dial@outdial-458c;2e[0;37;40m", "e[1;35;40mDial Timeout = 60e[0;37;40m") in new stack
[Jun 11 10:22:47] VERBOSE[2208] pbx.c:     -- Executing [dial@outdial:4] e[1;36;40mDiale[0;37;40m("e[1;35;40mLocal/dial@outdial-458c;2e[0;37;40m", "e[1;35;40mSIP/911234567890@ss_polycom, 60e[0;37;40m") in new stack
[Jun 11 10:22:47] VERBOSE[2208] netsock.c:   == Using SIP RTP CoS mark 5
[Jun 11 10:22:47] VERBOSE[2208] chan_sip.c: Audio is at 5.5.5.5 port 18000
[Jun 11 10:22:47] VERBOSE[2208] chan_sip.c: Adding codec 0x2 (gsm) to SDP
[Jun 11 10:22:47] VERBOSE[2208] chan_sip.c: Adding codec 0x4 (ulaw) to SDP
[Jun 11 10:22:47] VERBOSE[2208] chan_sip.c: Adding codec 0x8 (alaw) to SDP
[Jun 11 10:22:47] VERBOSE[2208] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP
[Jun 11 10:22:47] VERBOSE[2208] chan_sip.c: Reliably Transmitting (no NAT) to 10.27.5.61:5060:
INVITE sip:911234567890@6.6.6.6 SIP/2.0
Via: SIP/2.0/UDP 5.5.5.5:5060;branch=z9hG4bK5fe07b48;rport
Max-Forwards: 70
From: "8669991234" <sip:8669991234@5.5.5.5>;tag=as52703764
To: <sip:911234567890@6.6.6.6>
Contact: <sip:8669991234@5.5.5.5>
Call-ID: 60c3333b4908bed858500ef21ccb612b@5.5.5.5
CSeq: 102 INVITE
User-Agent: Asterisk PBX 1.6.1.1
Date: Fri, 11 Jun 2010 15:22:47 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces, timer
Content-Type: application/sdp
Content-Length: 304

v=0
o=root 282487424 282487424 IN IP4 5.5.5.5
s=Asterisk PBX 1.6.1.1
c=IN IP4 5.5.5.5
t=0 0
m=audio 18000 RTP/AVP 3 0 8 101
a=rtpmap:3 GSM/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

---
[Jun 11 10:22:47] VERBOSE[2208] app_dial.c:     -- Called 911234567890@ss_polycom
[Jun 11 10:22:47] VERBOSE[27120] chan_sip.c: 
<--- SIP read from UDP://6.6.6.6:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 5.5.5.5:5060;branch=z9hG4bK5fe07b48;rport
From: "8669991234" <sip:8669991234@5.5.5.5>;tag=as52703764
To: <sip:911234567890@6.6.6.6>;tag=DC719A44-A658C6D9
CSeq: 102 INVITE
Call-ID: 60c3333b4908bed858500ef21ccb612b@5.5.5.5
Contact: <sip:ss_polycom@6.6.6.6>
User-Agent: PolycomSoundPointIP-SPIP_330-UA/2.1.2.0049
Content-Length: 0


<------------->
[Jun 11 10:22:47] VERBOSE[27120] chan_sip.c: --- (9 headers 0 lines) ---
[Jun 11 10:22:47] VERBOSE[27120] chan_sip.c: 
<--- SIP read from UDP://6.6.6.6:5060 --->
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 5.5.5.5:5060;branch=z9hG4bK5fe07b48;rport
From: "8669991234" <sip:8669991234@5.5.5.5>;tag=as52703764
To: <sip:911234567890@6.6.6.6>;tag=DC719A44-A658C6D9
CSeq: 102 INVITE
Call-ID: 60c3333b4908bed858500ef21ccb612b@5.5.5.5
Contact: <sip:ss_polycom@6.6.6.6>
User-Agent: PolycomSoundPointIP-SPIP_330-UA/2.1.2.0049
Allow-Events: talk,hold,conference
Content-Length: 0


<------------->
[Jun 11 10:22:47] VERBOSE[27120] chan_sip.c: --- (10 headers 0 lines) ---
[Jun 11 10:22:47] VERBOSE[2208] app_dial.c:     -- SIP/ss_polycom-aacc20b8 is ringing
[Jun 11 10:22:48] VERBOSE[27120] chan_sip.c: Really destroying SIP dialog '23734a0b1d01899f53d1bfe02541d418@4.4.4.4' Method: REGISTER
[Jun 11 10:22:49] VERBOSE[27120] chan_sip.c: Really destroying SIP dialog '305c177e6b74185a0000df994156d553@5.5.5.5' Method: REGISTER
[Jun 11 10:22:52] VERBOSE[27120] chan_sip.c: 
<--- SIP read from UDP://1.1.1.1:5061 --->



<------------->
[Jun 11 10:22:55] VERBOSE[27120] chan_sip.c: 
<--- SIP read from UDP://2.2.2.2:5060 --->



<------------->
[Jun 11 10:23:00] VERBOSE[27120] chan_sip.c: 
<--- SIP read from UDP://3.3.3.3:5061 --->



<------------->
[Jun 11 10:23:17] VERBOSE[2208] chan_sip.c: Scheduling destruction of SIP dialog '60c3333b4908bed858500ef21ccb612b@5.5.5.5' in 32000 ms (Method: INVITE)
[Jun 11 10:23:17] VERBOSE[2208] chan_sip.c: Reliably Transmitting (no NAT) to 6.6.6.6:5060:
CANCEL sip:911234567890@6.6.6.6 SIP/2.0
Via: SIP/2.0/UDP 5.5.5.5:5060;branch=z9hG4bK5fe07b48;rport
Max-Forwards: 70
From: "8669991234" <sip:8669991234@5.5.5.5>;tag=as52703764
To: <sip:911234567890@6.6.6.6>
Call-ID: 60c3333b4908bed858500ef21ccb612b@5.5.5.5
CSeq: 102 CANCEL
User-Agent: Asterisk PBX 1.6.1.1
Content-Length: 0


---
[Jun 11 10:23:17] VERBOSE[2208] chan_sip.c: Scheduling destruction of SIP dialog '60c3333b4908bed858500ef21ccb612b@5.5.5.5' in 32000 ms (Method: INVITE)
[Jun 11 10:23:17] VERBOSE[2208] pbx.c:   == Spawn extension (outdial, dial, 4) exited non-zero on 'Local/dial@outdial-458c;2'
[Jun 11 10:23:17] VERBOSE[27120] chan_sip.c: 
<--- SIP read from UDP://6.6.6.6:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 5.5.5.5:5060;branch=z9hG4bK5fe07b48;rport
From: "8669991234" <sip:8669991234@5.5.5.5>;tag=as52703764
To: <sip:911234567890@6.6.6.6>
CSeq: 102 CANCEL
Call-ID: 60c3333b4908bed858500ef21ccb612b@5.5.5.5
Contact: <sip:ss_polycom@6.6.6.6>
User-Agent: PolycomSoundPointIP-SPIP_330-UA/2.1.2.0049
Content-Length: 0


<------------->
[Jun 11 10:23:17] VERBOSE[27120] chan_sip.c: --- (9 headers 0 lines) ---
[Jun 11 10:23:17] VERBOSE[27120] chan_sip.c: 
<--- SIP read from UDP://6.6.6.6:5060 --->
SIP/2.0 487 Request Cancelled
Via: SIP/2.0/UDP 5.5.5.5:5060;branch=z9hG4bK5fe07b48;rport
From: "8669991234" <sip:8669991234@5.5.5.5>;tag=as52703764
To: <sip:911234567890@6.6.6.6>;tag=DC719A44-A658C6D9
CSeq: 102 INVITE
Call-ID: 60c3333b4908bed858500ef21ccb612b@5.5.5.5
Contact: <sip:ss_polycom@6.6.6.6>
User-Agent: PolycomSoundPointIP-SPIP_330-UA/2.1.2.0049
Content-Length: 0


<------------->
[Jun 11 10:23:17] VERBOSE[27120] chan_sip.c: --- (9 headers 0 lines) ---
[Jun 11 10:23:17] VERBOSE[27120] chan_sip.c: Transmitting (no NAT) to 6.6.6.6:5060:
ACK sip:911234567890@6.6.6.6 SIP/2.0
Via: SIP/2.0/UDP 5.5.5.5:5060;branch=z9hG4bK5fe07b48;rport
Max-Forwards: 70
From: "8669991234" <sip:8669991234@5.5.5.5>;tag=as52703764
To: <sip:911234567890@6.6.6.6>;tag=DC719A44-A658C6D9
Contact: <sip:8669991234@5.5.5.5>
Call-ID: 60c3333b4908bed858500ef21ccb612b@5.5.5.5
CSeq: 102 ACK
User-Agent: Asterisk PBX 1.6.1.1
Content-Length: 0


---
[Jun 11 10:23:17] VERBOSE[27120] chan_sip.c: Really destroying SIP dialog '60c3333b4908bed858500ef21ccb612b@5.5.5.5' Method: INVITE
[Jun 11 10:23:22] VERBOSE[27120] chan_sip.c: 
<--- SIP read from UDP://1.1.1.1:5061 --->



<------------->
[Jun 11 10:23:25] VERBOSE[27120] chan_sip.c: 
<--- SIP read from UDP://2.2.2.2:5060 --->



<------------->
[Jun 11 10:23:30] VERBOSE[27120] chan_sip.c: 
<--- SIP read from UDP://3.3.3.3:5061 --->



<------------->
[Jun 11 10:23:46] VERBOSE[1994] asterisk.c:     -- Remote UNIX connection disconnected
[Jun 11 10:23:52] VERBOSE[27120] chan_sip.c: 
<--- SIP read from UDP://1.1.1.1:5061 --->



<------------->
[Jun 11 10:23:55] VERBOSE[27120] chan_sip.c: 
<--- SIP read from UDP://2.2.2.2:5060 --->



<------------->
[Jun 11 10:24:00] VERBOSE[27120] chan_sip.c: 
<--- SIP read from UDP://3.3.3.3:5061 --->



<------------->
[Jun 11 10:24:02] NOTICE[27120] chan_sip.c:    -- Re-registration for  ivueivrtest@4.4.4.4
[Jun 11 10:24:02] VERBOSE[27120] chan_sip.c: REGISTER 12 headers, 0 lines
[Jun 11 10:24:02] VERBOSE[27120] chan_sip.c: Reliably Transmitting (no NAT) to 4.4.4.4:5060:
REGISTER sip:4.4.4.4 SIP/2.0
Via: SIP/2.0/UDP 5.5.5.5:5060;branch=z9hG4bK567c87cd;rport
Max-Forwards: 70
From: <sip:ivueivrtest@4.4.4.4>;tag=as761102d6
To: <sip:ivueivrtest@4.4.4.4>
Call-ID: 305c177e6b74185a0000df994156d553@5.5.5.5
CSeq: 15212 REGISTER
User-Agent: Asterisk PBX 1.6.1.1
Authorization: Digest username="ivueivrtest", realm="asterisk", algorithm=MD5, uri="sip:4.4.4.4", nonce="419e2192", response="56e21029e8dec396c008ba356b90b100"
Expires: 120
Contact: <sip:s@5.5.5.5>
Content-Length: 0


---
[Jun 11 10:24:02] VERBOSE[27120] chan_sip.c: 
<--- SIP read from UDP://4.4.4.4:5060 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 5.5.5.5:5060;branch=z9hG4bK567c87cd;received=5.5.5.5;rport=5060
From: <sip:ivueivrtest@4.4.4.4>;tag=as761102d6
To: <sip:ivueivrtest@4.4.4.4>;tag=as6d368817
Call-ID: 305c177e6b74185a0000df994156d553@5.5.5.5
CSeq: 15212 REGISTER
Server: Asterisk PBX 1.6.1.13
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="319cf1cb"
Content-Length: 0


<------------->
[Jun 11 10:24:02] VERBOSE[27120] chan_sip.c: --- (11 headers 0 lines) ---
[Jun 11 10:24:02] VERBOSE[27120] chan_sip.c: Responding to challenge, registration to domain/host name 4.4.4.4
[Jun 11 10:24:02] VERBOSE[27120] chan_sip.c: REGISTER 12 headers, 0 lines
[Jun 11 10:24:02] VERBOSE[27120] chan_sip.c: Reliably Transmitting (no NAT) to 4.4.4.4:5060:
REGISTER sip:4.4.4.4 SIP/2.0
Via: SIP/2.0/UDP 5.5.5.5:5060;branch=z9hG4bK029d1d4a;rport
Max-Forwards: 70
From: <sip:ivueivrtest@4.4.4.4>;tag=as1e81c663
To: <sip:ivueivrtest@4.4.4.4>
Call-ID: 305c177e6b74185a0000df994156d553@5.5.5.5
CSeq: 15213 REGISTER
User-Agent: Asterisk PBX 1.6.1.1
Authorization: Digest username="ivueivrtest", realm="asterisk", algorithm=MD5, uri="sip:4.4.4.4", nonce="319cf1cb", response="deaf5b89ad97f5ded3f7794f5d5d4c53"
Expires: 120
Contact: <sip:s@5.5.5.5>
Content-Length: 0


---
[Jun 11 10:24:02] VERBOSE[27120] chan_sip.c: 
<--- SIP read from UDP://4.4.4.4:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 5.5.5.5:5060;branch=z9hG4bK029d1d4a;received=5.5.5.5;rport=5060
From: <sip:ivueivrtest@4.4.4.4>;tag=as1e81c663
To: <sip:ivueivrtest@4.4.4.4>;tag=as6d368817
Call-ID: 305c177e6b74185a0000df994156d553@5.5.5.5
CSeq: 15213 REGISTER
Server: Asterisk PBX 1.6.1.13
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces, timer
Expires: 120
Contact: <sip:s@5.5.5.5>;expires=120
Date: Fri, 11 Jun 2010 15:24:02 GMT
Content-Length: 0


<------------->
[Jun 11 10:24:02] VERBOSE[27120] chan_sip.c: --- (13 headers 0 lines) ---
[Jun 11 10:24:02] VERBOSE[27120] chan_sip.c: Scheduling destruction of SIP dialog '305c177e6b74185a0000df994156d553@5.5.5.5' in 32000 ms (Method: REGISTER)
[Jun 11 10:24:02] NOTICE[27120] chan_sip.c: Outbound Registration: Expiry for 4.4.4.4 is 120 sec (Scheduling reregistration in 105 s)
[Jun 11 10:24:14] VERBOSE[27120] chan_sip.c: 
<--- SIP read from UDP://4.4.4.4:5060 --->
REGISTER sip:5.5.5.5 SIP/2.0
Via: SIP/2.0/UDP 4.4.4.4:5060;branch=z9hG4bK56dcd210;rport
Max-Forwards: 70
From: <sip:vmivr1@5.5.5.5>;tag=as60e5a124
To: <sip:vmivr1@5.5.5.5>
Call-ID: 23734a0b1d01899f53d1bfe02541d418@4.4.4.4
CSeq: 124 REGISTER
User-Agent: Asterisk PBX 1.6.1.13
Authorization: Digest username="vmivr1", realm="asterisk", algorithm=MD5, uri="sip:5.5.5.5", nonce="2dc09c8b", response="765d92f5b971866b2721afc19ad09094"
Expires: 120
Contact: <sip:s@4.4.4.4>
Content-Length: 0


<------------->
[Jun 11 10:24:14] VERBOSE[27120] chan_sip.c: --- (12 headers 0 lines) ---
[Jun 11 10:24:14] VERBOSE[27120] chan_sip.c: Sending to 4.4.4.4 : 5060 (NAT)
[Jun 11 10:24:14] VERBOSE[27120] chan_sip.c: 
<--- Transmitting (no NAT) to 4.4.4.4:5060 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 4.4.4.4:5060;branch=z9hG4bK56dcd210;received=4.4.4.4;rport=5060
From: <sip:vmivr1@5.5.5.5>;tag=as60e5a124
To: <sip:vmivr1@5.5.5.5>;tag=as506407db
Call-ID: 23734a0b1d01899f53d1bfe02541d418@4.4.4.4
CSeq: 124 REGISTER
Server: Asterisk PBX 1.6.1.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="4c060eec"
Content-Length: 0


<------------>
[Jun 11 10:24:14] VERBOSE[27120] chan_sip.c: Scheduling destruction of SIP dialog '23734a0b1d01899f53d1bfe02541d418@4.4.4.4' in 32000 ms (Method: REGISTER)
[Jun 11 10:24:14] VERBOSE[27120] chan_sip.c: 
<--- SIP read from UDP://4.4.4.4:5060 --->
REGISTER sip:5.5.5.5 SIP/2.0
Via: SIP/2.0/UDP 4.4.4.4:5060;branch=z9hG4bK4db81d77;rport
Max-Forwards: 70
From: <sip:vmivr1@5.5.5.5>;tag=as12914b9f
To: <sip:vmivr1@5.5.5.5>
Call-ID: 23734a0b1d01899f53d1bfe02541d418@4.4.4.4
CSeq: 125 REGISTER
User-Agent: Asterisk PBX 1.6.1.13
Authorization: Digest username="vmivr1", realm="asterisk", algorithm=MD5, uri="sip:5.5.5.5", nonce="4c060eec", response="069bbf2620d0adab4974053f85a05984"
Expires: 120
Contact: <sip:s@4.4.4.4>
Content-Length: 0


<------------->
[Jun 11 10:24:14] VERBOSE[27120] chan_sip.c: --- (12 headers 0 lines) ---
[Jun 11 10:24:14] VERBOSE[27120] chan_sip.c: Sending to 4.4.4.4 : 5060 (NAT)
[Jun 11 10:24:14] VERBOSE[27120] chan_sip.c: 
<--- Transmitting (no NAT) to 4.4.4.4:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 4.4.4.4:5060;branch=z9hG4bK4db81d77;received=4.4.4.4;rport=5060
From: <sip:vmivr1@5.5.5.5>;tag=as12914b9f
To: <sip:vmivr1@5.5.5.5>;tag=as506407db
Call-ID: 23734a0b1d01899f53d1bfe02541d418@4.4.4.4
CSeq: 125 REGISTER
Server: Asterisk PBX 1.6.1.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces, timer
Expires: 120
Contact: <sip:s@4.4.4.4>;expires=120
Date: Fri, 11 Jun 2010 15:24:14 GMT
Content-Length: 0


<------------>
[Jun 11 10:24:14] VERBOSE[27120] chan_sip.c: Scheduling destruction of SIP dialog '23734a0b1d01899f53d1bfe02541d418@4.4.4.4' in 32000 ms (Method: REGISTER)
[Jun 11 10:24:22] VERBOSE[27120] chan_sip.c: 
<--- SIP read from UDP://1.1.1.1:5061 --->



<------------->
[Jun 11 10:24:25] VERBOSE[27120] chan_sip.c: 
<--- SIP read from UDP://2.2.2.2:5060 --->



<------------->
[Jun 11 10:24:30] VERBOSE[27120] chan_sip.c: 
<--- SIP read from UDP://3.3.3.3:5061 --->



<------------->
[Jun 11 10:24:34] VERBOSE[27120] chan_sip.c: Really destroying SIP dialog '305c177e6b74185a0000df994156d553@5.5.5.5' Method: REGISTER

david55 · June 11, 2010, 3:44pm

I normally have

dateformat=%F %T.%3q ; with milliseconds

in logger.conf.

However the Scheduling is associated with the CANCEL, not the INVITE, so that theory doesn’t work. You will need to turn up the debugging, and/or debug the incoming channel, to work out why Asterisk is abandoning the call.