Directmedia=no not working with Callcentric


#1

I have been trying to debug an issue with routing a call to a group containing an internal Extension and an External Cellphone. This is simplified case of FollowMe, which I was trying to implement. I have been round-n-round on the “hang-up at 20 seconds” issue with the FreePBX forum and then with CallCentric support, but the most meaningful information seems to be that there are UPDATE sip packets in the trace which should not be there if directmedia=no were being honored.

The call progresses normally, with both destinations ringing, and when I answer the call on the internal extension, the call to the external cellphone is CANCELed, but there is a reINVITE and 2 UPDATE packets produced by asterisk at the same time as the CANCEL. Callcentric says this is not supposed to occur.

The UPDATE (two of them?) and two 100 Trying replies reoccur every 4 seconds until Callcentric eventually gives up and sends the 408 Request Timeout - which then terminates the connection between the incoming line and the internal extension.

How can I begin to debug this?

Is it correct that asterisk shouldn’t be sending UPDATE packets with directmedia=no?

Should the directmedia keyword be in sip_general_additional.conf (PEER Details for my Callcentric trunk) or sip_additional.conf (I have it in both)?

TIA

BTW, all other FreePBX, asterisk, Polycom IP321 functions I’ve tried work flawlessly.

Environment: FreePBX 2.9.0.7, Asterisk 1.8.6.0, Trunk provider CallCentric, Hardware ESXi 4.1 VM with 1 vCPU, 384 MB ram, behind NAT firewall with a Static public IP.


#2

I wasn’t aware that the way that Asterisk implemented direct media had changed. I would suspect if UPDATE is being used for that, it is being used by the other party.


#3

The UPDATEs come from asterisk and go to Callcentric. Callcentric says they shouldn’t be there. They certainly don’t fit with what I understand about direcmedia=no conversations.


#4

Can you do a “sip set debug on” in the Asterisk CLI, make the call and copy/paste the output here?


#5

I certainly can. I personally find tcpdump and wireshark to be easier to read, but at least this is a common format.

Call from external line to group containting 347 and 16785551212#
Part 1, thru the CANCEL of the external cellphone due to answering on the internal Extension 347

Call from external line to group containting 347 and 16785551212#

[2011-10-12 06:37:19] VERBOSE[5535] chan_sip.c: Reliably Transmitting (no NAT) to 172.30.0.193:5060:
OPTIONS sip:313@172.30.0.193 SIP/2.0
Via: SIP/2.0/UDP 172.30.0.190:5060;branch=z9hG4bK25293468
Max-Forwards: 70
From: "Unknown" <sip:Unknown@172.30.0.190>;tag=as22a22063
To: <sip:313@172.30.0.193>
Contact: <sip:Unknown@172.30.0.190:5060>
Call-ID: 115e731321b24ad05d43133a5e131e74@172.30.0.190:5060
CSeq: 102 OPTIONS
User-Agent: FPBX-2.9.0(1.8.6.0)
Date: Wed, 12 Oct 2011 10:37:19 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces
Content-Length: 0


---
[2011-10-12 06:37:19] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:172.30.0.193:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.30.0.190:5060;branch=z9hG4bK25293468
From: "Unknown" <sip:Unknown@172.30.0.190>;tag=as22a22063
To: "The Barkers" <sip:313@172.30.0.193>;tag=E8FA3731-897561F8
CSeq: 102 OPTIONS
Call-ID: 115e731321b24ad05d43133a5e131e74@172.30.0.190:5060
Contact: <sip:313@172.30.0.193>
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER
Supported: 100rel,replaces,100rel,timer,replaces,norefersub
User-Agent: PolycomSoundPointIP-SPIP_331-UA/3.3.2.0413
Accept-Language: en
Accept: application/sdp,text/plain,message/sipfrag,application/dialog-info+xml
Accept-Encoding: identity
Content-Length: 0

<------------->
[2011-10-12 06:37:19] VERBOSE[5535] chan_sip.c: --- (14 headers 0 lines) ---
[2011-10-12 06:37:19] VERBOSE[5535] chan_sip.c: Really destroying SIP dialog '115e731321b24ad05d43133a5e131e74@172.30.0.190:5060' Method: OPTIONS
[2011-10-12 06:37:20] VERBOSE[5535] chan_sip.c: Really destroying SIP dialog '480d6eb374f4562a698fe82e448bcb4e@127.0.0.1' Method: REGISTER
[2011-10-12 06:37:22] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:204.11.192.31:5060 --->
INVITE sip:17775551212@69.172.20.234:5060 SIP/2.0
v: SIP/2.0/UDP 204.11.192.31:5060;branch=z9hG4bK-706ce4f428db2d11a607bf72a893bed8
f: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
t: <sip:14044786561@ss.callcentric.com>
i: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 1 INVITE
Max-Forwards: 13
m: <sip:6779c9c129c0c5f45206c7ba6a46e4ed@204.11.192.31:5060;transport=udp>
Diversion: <sip:6785134504@64.35.56.125:5060>;privacy=off;screen=no; reason=unconditional; counter=1
Diversion: <sip:6785134504@64.35.56.125:5060>;privacy=off;screen=no; reason=unconditional; counter=1
Supported: timer
c: application/sdp
l: 317

v=0
o=NexTone-MSW 25150 17702 IN IP4 204.11.192.31
s=sip call
c=IN IP4 204.11.192.31
t=0 0
m=audio 49212 RTP/AVP 0 18 101
a=maxptime:20
a=sendrecv
a=fmtp:101 0-15
a=rtpmap:101 telephone-event/8000
a=fmtp:18 annexb=no
a=rtpmap:18 G729/8000
a=rtpmap:0 PCMU/8000
a=silenceSupp:off - - - -
a=setup:actpass
<------------->
[2011-10-12 06:37:22] VERBOSE[5535] chan_sip.c: --- (13 headers 15 lines) ---
[2011-10-12 06:37:22] VERBOSE[5535] chan_sip.c: Sending to 204.11.192.31:5060 (NAT)
[2011-10-12 06:37:22] VERBOSE[5535] chan_sip.c: Using INVITE request as basis request - 13593669-3527404641-844036@msw1.telengy.net
[2011-10-12 06:37:22] VERBOSE[5535] chan_sip.c: No matching peer for '16785134505' from '204.11.192.31:5060'
[2011-10-12 06:37:22] VERBOSE[5535] netsock2.c:   == Using SIP RTP TOS bits 184
[2011-10-12 06:37:22] VERBOSE[5535] netsock2.c:   == Using SIP RTP CoS mark 5
[2011-10-12 06:37:22] VERBOSE[5535] chan_sip.c: Found RTP audio format 0
[2011-10-12 06:37:22] VERBOSE[5535] chan_sip.c: Found RTP audio format 18
[2011-10-12 06:37:22] VERBOSE[5535] chan_sip.c: Found RTP audio format 101
[2011-10-12 06:37:22] VERBOSE[5535] chan_sip.c: Found audio description format telephone-event for ID 101
[2011-10-12 06:37:22] VERBOSE[5535] chan_sip.c: Found audio description format G729 for ID 18
[2011-10-12 06:37:22] VERBOSE[5535] chan_sip.c: Found audio description format PCMU for ID 0
[2011-10-12 06:37:22] VERBOSE[5535] chan_sip.c: Capabilities: us - 0xe (gsm|ulaw|alaw), peer - audio=0x104 (ulaw|g729)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x4 (ulaw)
[2011-10-12 06:37:22] VERBOSE[5535] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|)
[2011-10-12 06:37:22] VERBOSE[5535] chan_sip.c: Peer audio RTP is at port 204.11.192.31:49212
[2011-10-12 06:37:22] VERBOSE[5535] chan_sip.c: Looking for 17775551212 in from-sip-external-custom (domain 69.172.20.234:5060)
[2011-10-12 06:37:22] VERBOSE[5535] chan_sip.c: list_route: hop: <sip:6779c9c129c0c5f45206c7ba6a46e4ed@204.11.192.31:5060;transport=udp>
[2011-10-12 06:37:22] VERBOSE[5535] chan_sip.c: RDNIS for this call is 6785134504 (reason unconditional)
[2011-10-12 06:37:22] VERBOSE[5535] chan_sip.c:
<--- Transmitting (NAT) to 204.11.192.31:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 204.11.192.31:5060;branch=z9hG4bK-706ce4f428db2d11a607bf72a893bed8;received=204.11.192.31;rport=5060
From: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
To: <sip:14044786561@ss.callcentric.com>
Call-ID: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 1 INVITE
Server: FPBX-2.9.0(1.8.6.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces
Contact: <sip:17775551212@69.172.20.234:5060>
Content-Length: 0


<------------>
[2011-10-12 06:37:22] VERBOSE[29000] pbx.c:     -- Executing [17775551212@from-sip-external-custom:1] NoOp("SIP/66.193.176.35-0000000d", "Received incoming SIP connection from unknown peer to 17775551212") in new stack
[2011-10-12 06:37:22] VERBOSE[29000] pbx.c:     -- Executing [17775551212@from-sip-external-custom:2] Set("SIP/66.193.176.35-0000000d", "DID=17775551212") in new stack
[2011-10-12 06:37:22] VERBOSE[29000] pbx.c:     -- Executing [17775551212@from-sip-external-custom:3] Goto("SIP/66.193.176.35-0000000d", "s,1") in new stack
[2011-10-12 06:37:22] VERBOSE[29000] pbx.c:     -- Goto (from-sip-external-custom,s,1)
[2011-10-12 06:37:22] VERBOSE[29000] pbx.c:     -- Executing [s@from-sip-external-custom:1] GotoIf("SIP/66.193.176.35-0000000d", "0?from-sip-external,17775551212,1") in new stack
[2011-10-12 06:37:22] VERBOSE[29000] pbx.c:     -- Executing [s@from-sip-external-custom:2] Set("SIP/66.193.176.35-0000000d", "MYVAR=14044786561@ss.callcentric.com>") in new stack
[2011-10-12 06:37:22] VERBOSE[29000] pbx.c:     -- Executing [s@from-sip-external-custom:3] Set("SIP/66.193.176.35-0000000d", "DID=14044786561") in new stack
[2011-10-12 06:37:22] VERBOSE[29000] pbx.c:     -- Executing [s@from-sip-external-custom:4] Goto("SIP/66.193.176.35-0000000d", "from-pstn,14044786561,1") in new stack
[2011-10-12 06:37:22] VERBOSE[29000] pbx.c:     -- Goto (from-pstn,14044786561,1)
[2011-10-12 06:37:22] VERBOSE[29000] pbx.c:     -- Executing [14044786561@from-pstn:1] Set("SIP/66.193.176.35-0000000d", "__FROM_DID=14044786561") in new stack
[2011-10-12 06:37:22] VERBOSE[29000] pbx.c:     -- Executing [14044786561@from-pstn:2] Gosub("SIP/66.193.176.35-0000000d", "app-blacklist-check,s,1") in new stack
[2011-10-12 06:37:22] VERBOSE[29000] pbx.c:     -- Executing [s@app-blacklist-check:1] GotoIf("SIP/66.193.176.35-0000000d", "0?blacklisted") in new stack
[2011-10-12 06:37:22] VERBOSE[29000] pbx.c:     -- Executing [s@app-blacklist-check:2] Set("SIP/66.193.176.35-0000000d", "CALLED_BLACKLIST=1") in new stack
[2011-10-12 06:37:22] VERBOSE[29000] pbx.c:     -- Executing [s@app-blacklist-check:3] Return("SIP/66.193.176.35-0000000d", "") in new stack
[2011-10-12 06:37:22] VERBOSE[29000] pbx.c:     -- Executing [14044786561@from-pstn:3] Gosub("SIP/66.193.176.35-0000000d", "cidlookup,cidlookup_1,1") in new stack
[2011-10-12 06:37:22] VERBOSE[29000] pbx.c:     -- Executing [cidlookup_1@cidlookup:1] ExecIf("SIP/66.193.176.35-0000000d", "1?Set(CALLERID(name)=Old Office)") in new stack
[2011-10-12 06:37:22] VERBOSE[29000] pbx.c:     -- Executing [cidlookup_1@cidlookup:2] Return("SIP/66.193.176.35-0000000d", "") in new stack
[2011-10-12 06:37:22] VERBOSE[29000] pbx.c:     -- Executing [14044786561@from-pstn:4] ExecIf("SIP/66.193.176.35-0000000d", "0 ?Set(CALLERID(name)=16785134505)") in new stack
[2011-10-12 06:37:22] VERBOSE[29000] pbx.c:     -- Executing [14044786561@from-pstn:5] Set("SIP/66.193.176.35-0000000d", "__CALLINGPRES_SV=allowed_not_screened") in new stack
[2011-10-12 06:37:22] VERBOSE[29000] pbx.c:     -- Executing [14044786561@from-pstn:6] Set("SIP/66.193.176.35-0000000d", "CALLERPRES()=allowed_not_screened") in new stack
[2011-10-12 06:37:22] VERBOSE[29000] pbx.c:     -- Executing [14044786561@from-pstn:7] Goto("SIP/66.193.176.35-0000000d", "timeconditions,1,1") in new stack
[2011-10-12 06:37:22] VERBOSE[29000] pbx.c:     -- Goto (timeconditions,1,1)
[2011-10-12 06:37:22] VERBOSE[29000] pbx.c:     -- Executing [1@timeconditions:1] GotoIfTime("SIP/66.193.176.35-0000000d", "08:00-19:00,mon-fri,*,*?truestate") in new stack
[2011-10-12 06:37:22] VERBOSE[29000] pbx.c:     -- Executing [1@timeconditions:2] GotoIf("SIP/66.193.176.35-0000000d", "0?truegoto") in new stack
[2011-10-12 06:37:22] VERBOSE[29000] pbx.c:     -- Executing [1@timeconditions:3] ExecIf("SIP/66.193.176.35-0000000d", "0?Set(DB(TC/1)=)") in new stack
[2011-10-12 06:37:22] VERBOSE[29000] pbx.c:     -- Executing [1@timeconditions:4] GotoIf("SIP/66.193.176.35-0000000d", "1?ivr-4,s,1") in new stack
[2011-10-12 06:37:22] VERBOSE[29000] pbx.c:     -- Goto (ivr-4,s,1)
[2011-10-12 06:37:22] VERBOSE[29000] pbx.c:     -- Executing [s@ivr-4:1] Set("SIP/66.193.176.35-0000000d", "MSG=custom/Greeting") in new stack
[2011-10-12 06:37:22] VERBOSE[29000] pbx.c:     -- Executing [s@ivr-4:2] Set("SIP/66.193.176.35-0000000d", "LOOPCOUNT=0") in new stack
[2011-10-12 06:37:22] VERBOSE[29000] pbx.c:     -- Executing [s@ivr-4:3] Set("SIP/66.193.176.35-0000000d", "__DIR-CONTEXT=") in new stack
[2011-10-12 06:37:22] VERBOSE[29000] pbx.c:     -- Executing [s@ivr-4:4] Set("SIP/66.193.176.35-0000000d", "_IVR_CONTEXT_ivr-4=") in new stack
[2011-10-12 06:37:22] VERBOSE[29000] pbx.c:     -- Executing [s@ivr-4:5] Set("SIP/66.193.176.35-0000000d", "_IVR_CONTEXT=ivr-4") in new stack
[2011-10-12 06:37:22] VERBOSE[29000] pbx.c:     -- Executing [s@ivr-4:6] GotoIf("SIP/66.193.176.35-0000000d", "0?begin") in new stack
[2011-10-12 06:37:22] VERBOSE[29000] pbx.c:     -- Executing [s@ivr-4:7] Answer("SIP/66.193.176.35-0000000d", "") in new stack
[2011-10-12 06:37:22] VERBOSE[29000] chan_sip.c: Audio is at 5060
[2011-10-12 06:37:22] VERBOSE[29000] chan_sip.c: Adding codec 0x4 (ulaw) to SDP
[2011-10-12 06:37:22] VERBOSE[29000] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP
[2011-10-12 06:37:22] VERBOSE[29000] chan_sip.c:
<--- Reliably Transmitting (NAT) to 204.11.192.31:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 204.11.192.31:5060;branch=z9hG4bK-706ce4f428db2d11a607bf72a893bed8;received=204.11.192.31;rport=5060
From: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
To: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
Call-ID: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 1 INVITE
Server: FPBX-2.9.0(1.8.6.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces
Contact: <sip:17775551212@69.172.20.234:5060>
Content-Type: application/sdp
Content-Length: 238

v=0
o=root 1840618489 1840618489 IN IP4 69.172.20.234
s=Asterisk PBX 1.8.6.0
c=IN IP4 69.172.20.234
t=0 0
m=audio 10440 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

<------------>
[2011-10-12 06:37:22] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:204.11.192.31:5060 --->
ACK sip:17775551212@69.172.20.234:5060 SIP/2.0
v: SIP/2.0/UDP 204.11.192.31:5060;branch=z9hG4bK-25c5575800cd7abae07cfeeee64fb7df
f: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
t: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
i: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 1 ACK
Max-Forwards: 13
m: <sip:282495408f61519f1809b7fcaebd5f18@204.11.192.31:5060;transport=udp>
l: 0

<------------->
[2011-10-12 06:37:22] VERBOSE[5535] chan_sip.c: --- (9 headers 0 lines) ---
[2011-10-12 06:37:22] VERBOSE[29000] pbx.c:     -- Executing [s@ivr-4:8] Wait("SIP/66.193.176.35-0000000d", "1") in new stack
[2011-10-12 06:37:23] VERBOSE[29000] pbx.c:     -- Executing [s@ivr-4:9] Set("SIP/66.193.176.35-0000000d", "TIMEOUT(digit)=3") in new stack
[2011-10-12 06:37:23] VERBOSE[29000] func_timeout.c:     -- Digit timeout set to 3.000
[2011-10-12 06:37:23] VERBOSE[29000] pbx.c:     -- Executing [s@ivr-4:10] Set("SIP/66.193.176.35-0000000d", "TIMEOUT(response)=10") in new stack
[2011-10-12 06:37:23] VERBOSE[29000] func_timeout.c:     -- Response timeout set to 10.000
[2011-10-12 06:37:23] VERBOSE[29000] pbx.c:     -- Executing [s@ivr-4:11] Set("SIP/66.193.176.35-0000000d", "__IVR_RETVM=") in new stack
[2011-10-12 06:37:23] VERBOSE[29000] pbx.c:     -- Executing [s@ivr-4:12] ExecIf("SIP/66.193.176.35-0000000d", "1?Background(custom/Greeting)") in new stack
[2011-10-12 06:37:23] DEBUG[29000] format_wav.c: Skipping unknown block 'LIST'
[2011-10-12 06:37:23] VERBOSE[29000] file.c:     -- <SIP/66.193.176.35-0000000d> Playing 'custom/Greeting.slin' (language 'en')
[2011-10-12 06:37:24] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:172.30.0.199:5060 --->

<------------->
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:   == CDR updated on SIP/66.193.176.35-0000000d
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [*812@ivr-4:1] Macro("SIP/66.193.176.35-0000000d", "blkvm-clr,") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [s@macro-blkvm-clr:1] Set("SIP/66.193.176.35-0000000d", "SHARED(BLKVM,)=") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [s@macro-blkvm-clr:2] Set("SIP/66.193.176.35-0000000d", "GOSUB_RETVAL=") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [s@macro-blkvm-clr:3] MacroExit("SIP/66.193.176.35-0000000d", "") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [*812@ivr-4:2] Set("SIP/66.193.176.35-0000000d", "__NODEST=") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [*812@ivr-4:3] Goto("SIP/66.193.176.35-0000000d", "ext-group,647,1") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Goto (ext-group,647,1)
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [647@ext-group:1] Macro("SIP/66.193.176.35-0000000d", "user-callerid,") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [s@macro-user-callerid:1] Set("SIP/66.193.176.35-0000000d", "AMPUSER=16785134505") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [s@macro-user-callerid:2] GotoIf("SIP/66.193.176.35-0000000d", "0?report") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [s@macro-user-callerid:3] ExecIf("SIP/66.193.176.35-0000000d", "1?Set(REALCALLERIDNUM=16785134505)") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [s@macro-user-callerid:4] Set("SIP/66.193.176.35-0000000d", "AMPUSER=") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [s@macro-user-callerid:5] Set("SIP/66.193.176.35-0000000d", "AMPUSERCIDNAME=") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [s@macro-user-callerid:6] GotoIf("SIP/66.193.176.35-0000000d", "1?report") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Goto (macro-user-callerid,s,13)
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [s@macro-user-callerid:13] GotoIf("SIP/66.193.176.35-0000000d", "0?continue") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [s@macro-user-callerid:14] Set("SIP/66.193.176.35-0000000d", "__TTL=64") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [s@macro-user-callerid:15] GotoIf("SIP/66.193.176.35-0000000d", "1?continue") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Goto (macro-user-callerid,s,26)
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [s@macro-user-callerid:26] Set("SIP/66.193.176.35-0000000d", "CALLERID(number)=16785134505") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [s@macro-user-callerid:27] Set("SIP/66.193.176.35-0000000d", "CALLERID(name)=Old Office") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [s@macro-user-callerid:28] Set("SIP/66.193.176.35-0000000d", "CHANNEL(language)=en") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [647@ext-group:2] Macro("SIP/66.193.176.35-0000000d", "blkvm-setifempty,") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [s@macro-blkvm-setifempty:1] GotoIf("SIP/66.193.176.35-0000000d", "1?init") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Goto (macro-blkvm-setifempty,s,4)
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [s@macro-blkvm-setifempty:4] Set("SIP/66.193.176.35-0000000d", "__BLKVM_CHANNEL=SIP/66.193.176.35-0000000d") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [s@macro-blkvm-setifempty:5] Set("SIP/66.193.176.35-0000000d", "SHARED(BLKVM,SIP/66.193.176.35-0000000d)=TRUE") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [s@macro-blkvm-setifempty:6] Set("SIP/66.193.176.35-0000000d", "GOSUB_RETVAL=TRUE") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [s@macro-blkvm-setifempty:7] MacroExit("SIP/66.193.176.35-0000000d", "") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [647@ext-group:3] GotoIf("SIP/66.193.176.35-0000000d", "1?skipov") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Goto (ext-group,647,6)
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [647@ext-group:6] Set("SIP/66.193.176.35-0000000d", "RRNODEST=") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [647@ext-group:7] Set("SIP/66.193.176.35-0000000d", "__NODEST=647") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [647@ext-group:8] GosubIf("SIP/66.193.176.35-0000000d", "0?sub-rgsetcid,s,1") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [647@ext-group:9] Set("SIP/66.193.176.35-0000000d", "RecordMethod=Group") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [647@ext-group:10] Macro("SIP/66.193.176.35-0000000d", "record-enable,347-6785551212#,Group") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [s@macro-record-enable:1] GotoIf("SIP/66.193.176.35-0000000d", "1?check") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Goto (macro-record-enable,s,4)
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [s@macro-record-enable:4] ExecIf("SIP/66.193.176.35-0000000d", "0?MacroExit()") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [s@macro-record-enable:5] GotoIf("SIP/66.193.176.35-0000000d", "1?Group:OUT") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Goto (macro-record-enable,s,6)
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [s@macro-record-enable:6] Set("SIP/66.193.176.35-0000000d", "LOOPCNT=2") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [s@macro-record-enable:7] Set("SIP/66.193.176.35-0000000d", "ITER=1") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [s@macro-record-enable:8] GotoIf("SIP/66.193.176.35-0000000d", "1?continue") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Goto (macro-record-enable,s,12)
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [s@macro-record-enable:12] Set("SIP/66.193.176.35-0000000d", "ITER=2") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [s@macro-record-enable:13] GotoIf("SIP/66.193.176.35-0000000d", "1?begin") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Goto (macro-record-enable,s,8)
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [s@macro-record-enable:8] GotoIf("SIP/66.193.176.35-0000000d", "1?continue") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Goto (macro-record-enable,s,12)
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [s@macro-record-enable:12] Set("SIP/66.193.176.35-0000000d", "ITER=3") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [s@macro-record-enable:13] GotoIf("SIP/66.193.176.35-0000000d", "0?begin") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [s@macro-record-enable:14] GotoIf("SIP/66.193.176.35-0000000d", "0?IN") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [s@macro-record-enable:15] ExecIf("SIP/66.193.176.35-0000000d", "1?MacroExit()") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [647@ext-group:11] Set("SIP/66.193.176.35-0000000d", "RingGroupMethod=ringall-prim") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [647@ext-group:12] Macro("SIP/66.193.176.35-0000000d", "dial,20,m(default)t,347-6785551212#") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [s@macro-dial:1] GotoIf("SIP/66.193.176.35-0000000d", "1?dial") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Goto (macro-dial,s,3)
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [s@macro-dial:3] AGI("SIP/66.193.176.35-0000000d", "dialparties.agi") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] res_agi.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
[2011-10-12 06:37:26] VERBOSE[29000] res_agi.c:  dialparties.agi: Starting New Dialparties.agi
[2011-10-12 06:37:26] VERBOSE[29000] res_agi.c:  dialparties.agi: Caller ID name is 'Old Office' number is '16785134505'
[2011-10-12 06:37:26] VERBOSE[29000] res_agi.c:  dialparties.agi: Methodology of ring is  'ringall-prim'
[2011-10-12 06:37:26] VERBOSE[29000] res_agi.c:     -- dialparties.agi: Added extension 347 to extension map
[2011-10-12 06:37:26] VERBOSE[29000] res_agi.c:     -- dialparties.agi: Added extension 6785551212# to extension map
[2011-10-12 06:37:26] VERBOSE[29000] res_agi.c:     -- dialparties.agi: Extension 347 cf is disabled
[2011-10-12 06:37:26] VERBOSE[29000] res_agi.c:     -- dialparties.agi: Extension 6785551212# cf is disabled
[2011-10-12 06:37:26] VERBOSE[29000] res_agi.c:     -- dialparties.agi: Extension 347 do not disturb is disabled
[2011-10-12 06:37:26] VERBOSE[29000] res_agi.c:  dialparties.agi: EXTENSION_STATE: 0 (NOT_INUSE)
[2011-10-12 06:37:26] VERBOSE[29000] res_agi.c:  dialparties.agi: Extension 347 has ExtensionState: 0
[2011-10-12 06:37:26] VERBOSE[29000] res_agi.c:     -- dialparties.agi: dbset CALLTRACE/347 to 16785134505
[2011-10-12 06:37:26] VERBOSE[29000] res_agi.c:     -- dialparties.agi: Filtered ARG3: 347-6785551212
[2011-10-12 06:37:26] VERBOSE[29000] res_agi.c:     -- <SIP/66.193.176.35-0000000d>AGI Script dialparties.agi completed, returning 0
[2011-10-12 06:37:26] VERBOSE[29000] pbx.c:     -- Executing [s@macro-dial:7] Dial("SIP/66.193.176.35-0000000d", "SIP/347&Local/6785551212@from-internal/n,20,m(default)tM(auto-blkvm)") in new stack
[2011-10-12 06:37:26] VERBOSE[29000] netsock2.c:   == Using SIP RTP TOS bits 184
[2011-10-12 06:37:26] VERBOSE[29000] netsock2.c:   == Using SIP RTP CoS mark 5
[2011-10-12 06:37:26] VERBOSE[29000] chan_sip.c: Audio is at 5060
[2011-10-12 06:37:26] VERBOSE[29000] chan_sip.c: Adding codec 0x4 (ulaw) to SDP
[2011-10-12 06:37:26] VERBOSE[29000] chan_sip.c: Adding codec 0x8 (alaw) to SDP
[2011-10-12 06:37:26] VERBOSE[29000] chan_sip.c: Adding codec 0x2 (gsm) to SDP
[2011-10-12 06:37:26] VERBOSE[29000] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP
[2011-10-12 06:37:26] VERBOSE[29000] chan_sip.c: Reliably Transmitting (no NAT) to 172.30.0.191:5060:
INVITE sip:347@172.30.0.191 SIP/2.0
Via: SIP/2.0/UDP 172.30.0.190:5060;branch=z9hG4bK3785076b
Max-Forwards: 70
From: "Old Office" <sip:16785134505@172.30.0.190>;tag=as3043f72e
To: <sip:347@172.30.0.191>
Contact: <sip:16785134505@172.30.0.190:5060>
Call-ID: 62d6d0d027e34b756140de1a7df49869@172.30.0.190:5060
CSeq: 102 INVITE
User-Agent: FPBX-2.9.0(1.8.6.0)
Date: Wed, 12 Oct 2011 10:37:26 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces
Diversion: <sip:6785134504@172.30.0.190>;reason=unconditional
Content-Type: application/sdp
Content-Length: 283

v=0
o=root 2021443383 2021443383 IN IP4 172.30.0.190
s=Asterisk PBX 1.8.6.0
c=IN IP4 172.30.0.190
t=0 0
m=audio 10506 RTP/AVP 0 8 3 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

---
[2011-10-12 06:37:26] VERBOSE[29000] app_dial.c:     -- Called SIP/347
[2011-10-12 06:37:26] VERBOSE[29000] app_dial.c:     -- Called Local/6785551212@from-internal/n
[2011-10-12 06:37:26] VERBOSE[29000] res_musiconhold.c:     -- Started music on hold, class 'default', on SIP/66.193.176.35-0000000d
[2011-10-12 06:37:26] VERBOSE[29000] app_dial.c:     -- SIP/347-0000000e connected line has changed. Saving it until answer for SIP/66.193.176.35-0000000d
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [6785551212@from-internal:1] Macro("Local/6785551212@from-internal-b723;2", "user-callerid,LIMIT,") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-user-callerid:1] Set("Local/6785551212@from-internal-b723;2", "AMPUSER=16785134505") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-user-callerid:2] GotoIf("Local/6785551212@from-internal-b723;2", "1?report") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Goto (macro-user-callerid,s,13)
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-user-callerid:13] GotoIf("Local/6785551212@from-internal-b723;2", "1?continue") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Goto (macro-user-callerid,s,26)
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-user-callerid:26] Set("Local/6785551212@from-internal-b723;2", "CALLERID(number)=16785134505") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-user-callerid:27] Set("Local/6785551212@from-internal-b723;2", "CALLERID(name)=Old Office") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-user-callerid:28] Set("Local/6785551212@from-internal-b723;2", "CHANNEL(language)=en") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [6785551212@from-internal:2] Set("Local/6785551212@from-internal-b723;2", "MOHCLASS=default") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [6785551212@from-internal:3] Set("Local/6785551212@from-internal-b723;2", "_NODEST=") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [6785551212@from-internal:4] Macro("Local/6785551212@from-internal-b723;2", "record-enable,16785134505,OUT,") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-record-enable:1] GotoIf("Local/6785551212@from-internal-b723;2", "1?check") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Goto (macro-record-enable,s,4)
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-record-enable:4] ExecIf("Local/6785551212@from-internal-b723;2", "0?MacroExit()") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-record-enable:5] GotoIf("Local/6785551212@from-internal-b723;2", "0?Group:OUT") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Goto (macro-record-enable,s,14)
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-record-enable:14] GotoIf("Local/6785551212@from-internal-b723;2", "0?IN") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-record-enable:15] ExecIf("Local/6785551212@from-internal-b723;2", "1?MacroExit()") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [6785551212@from-internal:5] Macro("Local/6785551212@from-internal-b723;2", "dialout-trunk,2,16785551212,") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-dialout-trunk:1] Set("Local/6785551212@from-internal-b723;2", "DIAL_TRUNK=2") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-dialout-trunk:2] GosubIf("Local/6785551212@from-internal-b723;2", "0?sub-pincheck,s,1") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-dialout-trunk:3] GotoIf("Local/6785551212@from-internal-b723;2", "0?disabletrunk,1") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-dialout-trunk:4] Set("Local/6785551212@from-internal-b723;2", "DIAL_NUMBER=16785551212") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-dialout-trunk:5] Set("Local/6785551212@from-internal-b723;2", "DIAL_TRUNK_OPTIONS=tr") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-dialout-trunk:6] Set("Local/6785551212@from-internal-b723;2", "OUTBOUND_GROUP=OUT_2") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-dialout-trunk:7] GotoIf("Local/6785551212@from-internal-b723;2", "1?nomax") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Goto (macro-dialout-trunk,s,9)
[2011-10-12 06:37:26] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:172.30.0.191:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 172.30.0.190:5060;branch=z9hG4bK3785076b
From: "Old Office" <sip:16785134505@172.30.0.190>;tag=as3043f72e
To: "Dan Barker" <sip:347@172.30.0.191>;tag=3D7AD09D-15288712
CSeq: 102 INVITE
Call-ID: 62d6d0d027e34b756140de1a7df49869@172.30.0.190:5060
Contact: <sip:347@172.30.0.191>
User-Agent: PolycomSoundPointIP-SPIP_331-UA/3.3.2.0413
Accept-Language: en
Content-Length: 0

<------------->
[2011-10-12 06:37:26] VERBOSE[5535] chan_sip.c: --- (10 headers 0 lines) ---
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-dialout-trunk:9] GotoIf("Local/6785551212@from-internal-b723;2", "0?skipoutcid") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-dialout-trunk:10] Set("Local/6785551212@from-internal-b723;2", "DIAL_TRUNK_OPTIONS=") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-dialout-trunk:11] Macro("Local/6785551212@from-internal-b723;2", "outbound-callerid,2") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-outbound-callerid:1] ExecIf("Local/6785551212@from-internal-b723;2", "1?Set(CALLERPRES()=allowed_not_screened)") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-outbound-callerid:2] ExecIf("Local/6785551212@from-internal-b723;2", "1?Set(REALCALLERIDNUM=16785134505)") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-outbound-callerid:3] GotoIf("Local/6785551212@from-internal-b723;2", "0?normcid") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-outbound-callerid:4] Set("Local/6785551212@from-internal-b723;2", "USEROUTCID=16785134505") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-outbound-callerid:5] GotoIf("Local/6785551212@from-internal-b723;2", "1?bypass") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Goto (macro-outbound-callerid,s,7)
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-outbound-callerid:7] Set("Local/6785551212@from-internal-b723;2", "EMERGENCYCID=") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-outbound-callerid:8] Set("Local/6785551212@from-internal-b723;2", "TRUNKOUTCID=16785134504") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-outbound-callerid:9] GotoIf("Local/6785551212@from-internal-b723;2", "1?trunkcid") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Goto (macro-outbound-callerid,s,12)
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-outbound-callerid:12] ExecIf("Local/6785551212@from-internal-b723;2", "1?Set(CALLERID(all)=16785134504)") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-outbound-callerid:13] ExecIf("Local/6785551212@from-internal-b723;2", "1?Set(CALLERID(all)=16785134505)") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-outbound-callerid:14] ExecIf("Local/6785551212@from-internal-b723;2", "0?Set(CALLERID(all)=)") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-outbound-callerid:15] ExecIf("Local/6785551212@from-internal-b723;2", "0?Set(CALLERPRES()=prohib_passed_screen)") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-dialout-trunk:12] GosubIf("Local/6785551212@from-internal-b723;2", "1?sub-flp-2,s,1") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@sub-flp-2:1] ExecIf("Local/6785551212@from-internal-b723;2", "0?Set(TARGET_FLP_2=116785551212)") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@sub-flp-2:2] GotoIf("Local/6785551212@from-internal-b723;2", "0?match") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@sub-flp-2:3] ExecIf("Local/6785551212@from-internal-b723;2", "1?Return()") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-dialout-trunk:13] Set("Local/6785551212@from-internal-b723;2", "OUTNUM=16785551212") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-dialout-trunk:14] Set("Local/6785551212@from-internal-b723;2", "custom=SIP/callcentric") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-dialout-trunk:15] ExecIf("Local/6785551212@from-internal-b723;2", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default))") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-dialout-trunk:16] ExecIf("Local/6785551212@from-internal-b723;2", "0?Set(DIAL_TRUNK_OPTIONS=M(confirm))") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-dialout-trunk:17] Macro("Local/6785551212@from-internal-b723;2", "dialout-trunk-predial-hook,") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("Local/6785551212@from-internal-b723;2", "") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-dialout-trunk:18] GotoIf("Local/6785551212@from-internal-b723;2", "0?bypass,1") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-dialout-trunk:19] GotoIf("Local/6785551212@from-internal-b723;2", "0?customtrunk") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] pbx.c:     -- Executing [s@macro-dialout-trunk:20] Dial("Local/6785551212@from-internal-b723;2", "SIP/callcentric/16785551212,300,") in new stack
[2011-10-12 06:37:26] VERBOSE[29015] netsock2.c:   == Using SIP RTP TOS bits 184
[2011-10-12 06:37:26] VERBOSE[29015] netsock2.c:   == Using SIP RTP CoS mark 5
[2011-10-12 06:37:26] VERBOSE[29015] chan_sip.c: Audio is at 5060
[2011-10-12 06:37:26] VERBOSE[29015] chan_sip.c: Adding codec 0x4 (ulaw) to SDP
[2011-10-12 06:37:26] VERBOSE[29015] chan_sip.c: Adding codec 0x8 (alaw) to SDP
[2011-10-12 06:37:26] VERBOSE[29015] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP
[2011-10-12 06:37:26] VERBOSE[29015] chan_sip.c: Reliably Transmitting (NAT) to 204.11.192.34:5080:
INVITE sip:16785551212@callcentric.com SIP/2.0
Via: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK6d013d77;rport
Max-Forwards: 70
From: "16785134505" <sip:17775551212@callcentric.com>;tag=as579afb7c
To: <sip:16785551212@callcentric.com>
Contact: <sip:17775551212@69.172.20.234:5060>
Call-ID: 2ac2b48d3f114706355f320f25ea785c@callcentric.com
CSeq: 102 INVITE
User-Agent: FPBX-2.9.0(1.8.6.0)
Date: Wed, 12 Oct 2011 10:37:26 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces
Remote-Party-ID: "16785134505" <sip:16785134505@callcentric.com>;party=calling;privacy=off;screen=no
Diversion: <sip:6785134504@69.172.20.234>;reason=unconditional
Content-Type: application/sdp
Content-Length: 260

v=0
o=root 863134914 863134914 IN IP4 69.172.20.234
s=Asterisk PBX 1.8.6.0
c=IN IP4 69.172.20.234
t=0 0
m=audio 10526 RTP/AVP 0 8 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

---
[2011-10-12 06:37:26] VERBOSE[29015] app_dial.c:     -- Called SIP/callcentric/16785551212
[2011-10-12 06:37:26] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:172.30.0.191:5060 --->
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 172.30.0.190:5060;branch=z9hG4bK3785076b
From: "Old Office" <sip:16785134505@172.30.0.190>;tag=as3043f72e
To: "Dan Barker" <sip:347@172.30.0.191>;tag=3D7AD09D-15288712
CSeq: 102 INVITE
Call-ID: 62d6d0d027e34b756140de1a7df49869@172.30.0.190:5060
Contact: <sip:347@172.30.0.191>
User-Agent: PolycomSoundPointIP-SPIP_331-UA/3.3.2.0413
Allow-Events: talk,hold,conference
Accept-Language: en
Content-Length: 0

<------------->
[2011-10-12 06:37:26] VERBOSE[5535] chan_sip.c: --- (11 headers 0 lines) ---
[2011-10-12 06:37:26] VERBOSE[29000] app_dial.c:     -- SIP/347-0000000e is ringing
[2011-10-12 06:37:26] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:204.11.192.34:5080 --->
SIP/2.0 407 Proxy Authentication Required
v: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK6d013d77;rport=5060
f: "16785134505" <sip:17775551212@callcentric.com>;tag=as579afb7c
t: <sip:16785551212@callcentric.com>
i: 2ac2b48d3f114706355f320f25ea785c@callcentric.com
CSeq: 102 INVITE
Proxy-Authenticate: Digest realm="callcentric.com", domain="sip:callcentric.com", nonce="962890843ed7dda95e719c3961c2b204", opaque="", stale=TRUE, algorithm=MD5
l: 0

<------------->
[2011-10-12 06:37:26] VERBOSE[5535] chan_sip.c: --- (8 headers 0 lines) ---
[2011-10-12 06:37:26] VERBOSE[5535] chan_sip.c: Transmitting (NAT) to 204.11.192.34:5080:
ACK sip:16785551212@callcentric.com SIP/2.0
Via: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK6d013d77;rport
Max-Forwards: 70
From: "16785134505" <sip:17775551212@callcentric.com>;tag=as579afb7c
To: <sip:16785551212@callcentric.com>
Contact: <sip:17775551212@69.172.20.234:5060>
Call-ID: 2ac2b48d3f114706355f320f25ea785c@callcentric.com
CSeq: 102 ACK
User-Agent: FPBX-2.9.0(1.8.6.0)
Content-Length: 0


---
[2011-10-12 06:37:26] VERBOSE[5535] chan_sip.c: Audio is at 5060
[2011-10-12 06:37:26] VERBOSE[5535] chan_sip.c: Adding codec 0x4 (ulaw) to SDP
[2011-10-12 06:37:26] VERBOSE[5535] chan_sip.c: Adding codec 0x8 (alaw) to SDP
[2011-10-12 06:37:26] VERBOSE[5535] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP
[2011-10-12 06:37:26] VERBOSE[5535] chan_sip.c: Reliably Transmitting (NAT) to 204.11.192.34:5080:
INVITE sip:16785551212@callcentric.com SIP/2.0
Via: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK3851b9e2;rport
Max-Forwards: 70
From: "16785134505" <sip:17775551212@callcentric.com>;tag=as579afb7c
To: <sip:16785551212@callcentric.com>
Contact: <sip:17775551212@69.172.20.234:5060>
Call-ID: 2ac2b48d3f114706355f320f25ea785c@callcentric.com
CSeq: 103 INVITE
User-Agent: FPBX-2.9.0(1.8.6.0)
Proxy-Authorization: Digest username="17775551212", realm="callcentric.com", algorithm=MD5, uri="sip:sip:callcentric.com", nonce="962890843ed7dda95e719c3961c2b204", response="45b59a6035ac0d7d168a0ecfdd69b4b2"
Date: Wed, 12 Oct 2011 10:37:26 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces
Remote-Party-ID: "16785134505" <sip:16785134505@callcentric.com>;party=calling;privacy=off;screen=no
Diversion: <sip:6785134504@69.172.20.234>;reason=unconditional
Content-Type: application/sdp
Content-Length: 260

v=0
o=root 863134914 863134915 IN IP4 69.172.20.234
s=Asterisk PBX 1.8.6.0
c=IN IP4 69.172.20.234
t=0 0
m=audio 10526 RTP/AVP 0 8 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

---
[2011-10-12 06:37:26] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:204.11.192.34:5080 --->
SIP/2.0 100 Trying
v: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK3851b9e2;rport=5060
f: "16785134505" <sip:17775551212@callcentric.com>;tag=as579afb7c
t: <sip:16785551212@callcentric.com>
i: 2ac2b48d3f114706355f320f25ea785c@callcentric.com
CSeq: 103 INVITE
l: 0

<------------->
[2011-10-12 06:37:26] VERBOSE[5535] chan_sip.c: --- (7 headers 0 lines) ---
[2011-10-12 06:37:26] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:204.11.192.34:5080 --->
SIP/2.0 100 Trying
v: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK3851b9e2;rport=5060
f: "16785134505" <sip:17775551212@callcentric.com>;tag=as579afb7c
t: <sip:16785551212@callcentric.com>
i: 2ac2b48d3f114706355f320f25ea785c@callcentric.com
CSeq: 103 INVITE
l: 0

<------------->
[2011-10-12 06:37:26] VERBOSE[5535] chan_sip.c: --- (7 headers 0 lines) ---
[2011-10-12 06:37:28] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:204.11.192.34:5080 --->
SIP/2.0 183 Session Progress
v: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK3851b9e2;rport=5060
f: "16785134505" <sip:17775551212@callcentric.com>;tag=as579afb7c
t: <sip:16785551212@callcentric.com>;tag=3527404648-143775
i: 2ac2b48d3f114706355f320f25ea785c@callcentric.com
CSeq: 103 INVITE
m: <sip:1ad5f411e1498eb403a36721f9812f3d@204.11.192.34:5080;transport=udp>
c: application/sdp
l: 266

v=0
o=NexTone-MSW 16554 8393 IN IP4 204.11.192.34
s=sip call
c=IN IP4 204.11.192.34
t=0 0
m=audio 63030 RTP/AVP 0 101
a=ptime:20
a=sendrecv
a=fmtp:101 0-15
a=rtpmap:101 telephone-event/8000
a=rtpmap:0 PCMU/8000
a=silenceSupp:off - - - -
a=setup:actpass
<------------->
[2011-10-12 06:37:28] VERBOSE[5535] chan_sip.c: --- (9 headers 13 lines) ---
[2011-10-12 06:37:28] VERBOSE[5535] chan_sip.c: Found RTP audio format 0
[2011-10-12 06:37:28] VERBOSE[5535] chan_sip.c: Found RTP audio format 101
[2011-10-12 06:37:28] VERBOSE[5535] chan_sip.c: Found audio description format telephone-event for ID 101
[2011-10-12 06:37:28] VERBOSE[5535] chan_sip.c: Found audio description format PCMU for ID 0
[2011-10-12 06:37:28] VERBOSE[5535] chan_sip.c: Capabilities: us - 0xc (ulaw|alaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x4 (ulaw)
[2011-10-12 06:37:28] VERBOSE[5535] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|)
[2011-10-12 06:37:28] VERBOSE[5535] chan_sip.c: Peer audio RTP is at port 204.11.192.34:63030
[2011-10-12 06:37:28] VERBOSE[29015] app_dial.c:     -- SIP/callcentric-0000000f is making progress passing it to Local/6785551212@from-internal-b723;2
[2011-10-12 06:37:28] VERBOSE[29000] app_dial.c:     -- Local/6785551212@from-internal-b723;1 is making progress passing it to SIP/66.193.176.35-0000000d
[2011-10-12 06:37:28] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:204.11.192.34:5080 --->
SIP/2.0 183 Session Progress
v: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK3851b9e2;rport=5060
f: "16785134505" <sip:17775551212@callcentric.com>;tag=as579afb7c
t: <sip:16785551212@callcentric.com>;tag=3527404648-143775
i: 2ac2b48d3f114706355f320f25ea785c@callcentric.com
CSeq: 103 INVITE
m: <sip:1ad5f411e1498eb403a36721f9812f3d@204.11.192.34:5080;transport=udp>
c: application/sdp
l: 266

v=0
o=NexTone-MSW 16554 8393 IN IP4 204.11.192.34
s=sip call
c=IN IP4 204.11.192.34
t=0 0
m=audio 63030 RTP/AVP 0 101
a=ptime:20
a=sendrecv
a=fmtp:101 0-15
a=rtpmap:101 telephone-event/8000
a=rtpmap:0 PCMU/8000
a=silenceSupp:off - - - -
a=setup:actpass
<------------->
[2011-10-12 06:37:28] VERBOSE[5535] chan_sip.c: --- (9 headers 13 lines) ---
[2011-10-12 06:37:28] VERBOSE[29015] app_dial.c:     -- SIP/callcentric-0000000f is making progress passing it to Local/6785551212@from-internal-b723;2
[2011-10-12 06:37:28] VERBOSE[29000] app_dial.c:     -- Local/6785551212@from-internal-b723;1 is making progress passing it to SIP/66.193.176.35-0000000d
[2011-10-12 06:37:29] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:204.11.192.34:5080 --->
SIP/2.0 183 Session Progress
v: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK3851b9e2;rport=5060
f: "16785134505" <sip:17775551212@callcentric.com>;tag=as579afb7c
t: <sip:16785551212@callcentric.com>;tag=3527404648-143775
i: 2ac2b48d3f114706355f320f25ea785c@callcentric.com
CSeq: 103 INVITE
m: <sip:1ad5f411e1498eb403a36721f9812f3d@204.11.192.34:5080;transport=udp>
c: application/sdp
l: 266

v=0
o=NexTone-MSW 16554 8393 IN IP4 204.11.192.34
s=sip call
c=IN IP4 204.11.192.34
t=0 0
m=audio 63030 RTP/AVP 0 101
a=ptime:20
a=sendrecv
a=fmtp:101 0-15
a=rtpmap:101 telephone-event/8000
a=rtpmap:0 PCMU/8000
a=silenceSupp:off - - - -
a=setup:actpass
<------------->
[2011-10-12 06:37:29] VERBOSE[5535] chan_sip.c: --- (9 headers 13 lines) ---
[2011-10-12 06:37:29] VERBOSE[29015] app_dial.c:     -- SIP/callcentric-0000000f is making progress passing it to Local/6785551212@from-internal-b723;2
[2011-10-12 06:37:29] VERBOSE[29000] app_dial.c:     -- Local/6785551212@from-internal-b723;1 is making progress passing it to SIP/66.193.176.35-0000000d
[2011-10-12 06:37:31] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:204.11.192.34:5080 --->
SIP/2.0 183 Session Progress
v: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK3851b9e2;rport=5060
f: "16785134505" <sip:17775551212@callcentric.com>;tag=as579afb7c
t: <sip:16785551212@callcentric.com>;tag=3527404648-143775
i: 2ac2b48d3f114706355f320f25ea785c@callcentric.com
CSeq: 103 INVITE
m: <sip:1ad5f411e1498eb403a36721f9812f3d@204.11.192.34:5080;transport=udp>
c: application/sdp
l: 266

v=0
o=NexTone-MSW 16554 8393 IN IP4 204.11.192.34
s=sip call
c=IN IP4 204.11.192.34
t=0 0
m=audio 63030 RTP/AVP 0 101
a=ptime:20
a=sendrecv
a=fmtp:101 0-15
a=rtpmap:101 telephone-event/8000
a=rtpmap:0 PCMU/8000
a=silenceSupp:off - - - -
a=setup:actpass
<------------->
[2011-10-12 06:37:31] VERBOSE[5535] chan_sip.c: --- (9 headers 13 lines) ---
[2011-10-12 06:37:31] VERBOSE[29015] app_dial.c:     -- SIP/callcentric-0000000f is making progress passing it to Local/6785551212@from-internal-b723;2
[2011-10-12 06:37:31] VERBOSE[29000] app_dial.c:     -- Local/6785551212@from-internal-b723;1 is making progress passing it to SIP/66.193.176.35-0000000d
[2011-10-12 06:37:33] NOTICE[5535] chan_sip.c:    -- Re-registration for  17775551212@callcentric.com
[2011-10-12 06:37:33] VERBOSE[5535] chan_sip.c: REGISTER 11 headers, 0 lines
[2011-10-12 06:37:33] VERBOSE[5535] chan_sip.c: Reliably Transmitting (NAT) to 204.11.192.35:5060:
REGISTER sip:callcentric.com SIP/2.0
Via: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK7bcf52ef;rport
Max-Forwards: 70
From: <sip:17775551212@callcentric.com>;tag=as3802eb7a
To: <sip:17775551212@callcentric.com>
Call-ID: 480d6eb374f4562a698fe82e448bcb4e@127.0.0.1
CSeq: 2002 REGISTER
User-Agent: FPBX-2.9.0(1.8.6.0)
Authorization: Digest username="17775551212", realm="callcentric.com", algorithm=MD5, uri="sip:sip:callcentric.com", nonce="e227ed2c09f6ad0480baae3047eee67c", response="ead67f63db6d1a60243714cf6edcc2d3"
Expires: 120
Contact: <sip:17775551212@69.172.20.234:5060>
Content-Length: 0


---
[2011-10-12 06:37:33] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:204.11.192.35:5060 --->
SIP/2.0 407 Proxy Authentication Required
v: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK7bcf52ef;rport=5060
f: <sip:17775551212@callcentric.com>;tag=as3802eb7a
t: <sip:17775551212@callcentric.com>
i: 480d6eb374f4562a698fe82e448bcb4e@127.0.0.1
CSeq: 2002 REGISTER
Proxy-Authenticate: Digest realm="callcentric.com", domain="sip:callcentric.com", nonce="50c6963777c622494fc4e74ac95cfe54", opaque="", stale=TRUE, algorithm=MD5
l: 0

<------------->
[2011-10-12 06:37:33] VERBOSE[5535] chan_sip.c: --- (8 headers 0 lines) ---
[2011-10-12 06:37:33] VERBOSE[5535] chan_sip.c: Responding to challenge, registration to domain/host name callcentric.com
[2011-10-12 06:37:33] VERBOSE[5535] chan_sip.c: REGISTER 11 headers, 0 lines
[2011-10-12 06:37:33] VERBOSE[5535] chan_sip.c: Reliably Transmitting (NAT) to 204.11.192.35:5060:
REGISTER sip:callcentric.com SIP/2.0
Via: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK10dcab14;rport
Max-Forwards: 70
From: <sip:17775551212@callcentric.com>;tag=as323ee8c6
To: <sip:17775551212@callcentric.com>
Call-ID: 480d6eb374f4562a698fe82e448bcb4e@127.0.0.1
CSeq: 2003 REGISTER
User-Agent: FPBX-2.9.0(1.8.6.0)
Proxy-Authorization: Digest username="17775551212", realm="callcentric.com", algorithm=MD5, uri="sip:sip:callcentric.com", nonce="50c6963777c622494fc4e74ac95cfe54", response="5ead3324ddf573136cc23ce9198538d7"
Expires: 120
Contact: <sip:17775551212@69.172.20.234:5060>
Content-Length: 0


---
[2011-10-12 06:37:33] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:204.11.192.35:5060 --->
SIP/2.0 200 Ok
v: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK10dcab14;rport=5060
f: <sip:17775551212@callcentric.com>;tag=as323ee8c6
t: <sip:17775551212@callcentric.com>
i: 480d6eb374f4562a698fe82e448bcb4e@127.0.0.1
CSeq: 2003 REGISTER
m: <sip:17775551212@69.172.20.234:5060>;expires=60
l: 0

<------------->
[2011-10-12 06:37:33] VERBOSE[5535] chan_sip.c: --- (8 headers 0 lines) ---
[2011-10-12 06:37:33] VERBOSE[5535] chan_sip.c: Scheduling destruction of SIP dialog '480d6eb374f4562a698fe82e448bcb4e@127.0.0.1' in 32000 ms (Method: REGISTER)
[2011-10-12 06:37:33] NOTICE[5535] chan_sip.c: Outbound Registration: Expiry for callcentric.com is 60 sec (Scheduling reregistration in 45 s)
[2011-10-12 06:37:33] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:204.11.192.35:5060 --->
NOTIFY sip:17775551212@69.172.20.234:5060 SIP/2.0
v: SIP/2.0/UDP 204.11.192.35:5060;branch=z9hG4bK-a38715a2e55eadcddee8f417ef6a090d
f: <sip:17775551212@callcentric.com:5062>
t: <sip:17775551212@callcentric.com>
i: e7087689aa235954c8f2744248fbfa4f-10ff552959baef9333dfb3afa5d028a0@callcentric.com
CSeq: 1 NOTIFY
Max-Forwards: 15
m: <sip:f32371f2cea2add28a46a403d3b58674@204.11.192.35:5060;transport=udp>
Event: message-summary
c: application/simple-message-summary
l: 138

Messages-Waiting: no
Message-Account: sip:17775551212@callcentric.com
Voice-Message: 0/0 (0/0)
Fax-Message: 0/0 (0/0)
None: 0/0 (0/0)
<------------->
[2011-10-12 06:37:33] VERBOSE[5535] chan_sip.c: --- (11 headers 5 lines) ---
[2011-10-12 06:37:35] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:172.30.0.191:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.30.0.190:5060;branch=z9hG4bK3785076b
From: "Old Office" <sip:16785134505@172.30.0.190>;tag=as3043f72e
To: "Dan Barker" <sip:347@172.30.0.191>;tag=3D7AD09D-15288712
CSeq: 102 INVITE
Call-ID: 62d6d0d027e34b756140de1a7df49869@172.30.0.190:5060
Contact: <sip:347@172.30.0.191>
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER
Supported: 100rel,replaces
User-Agent: PolycomSoundPointIP-SPIP_331-UA/3.3.2.0413
Accept-Language: en
Content-Type: application/sdp
Content-Length: 211

v=0
o=- 1318415851 1318415851 IN IP4 172.30.0.191
s=Polycom IP Phone
c=IN IP4 172.30.0.191
t=0 0
a=sendrecv
m=audio 2236 RTP/AVP 0 127
a=sendrecv
a=rtpmap:0 PCMU/8000
a=rtpmap:127 telephone-event/8000
<------------->
[2011-10-12 06:37:35] VERBOSE[5535] chan_sip.c: --- (13 headers 10 lines) ---
[2011-10-12 06:37:35] VERBOSE[5535] chan_sip.c: Found RTP audio format 0
[2011-10-12 06:37:35] VERBOSE[5535] chan_sip.c: Found RTP audio format 127
[2011-10-12 06:37:35] VERBOSE[5535] chan_sip.c: Found audio description format PCMU for ID 0
[2011-10-12 06:37:35] VERBOSE[5535] chan_sip.c: Found audio description format telephone-event for ID 127
[2011-10-12 06:37:35] VERBOSE[5535] chan_sip.c: Capabilities: us - 0xe (gsm|ulaw|alaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x4 (ulaw)
[2011-10-12 06:37:35] VERBOSE[5535] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|)
[2011-10-12 06:37:35] VERBOSE[5535] chan_sip.c: Peer audio RTP is at port 172.30.0.191:2236
[2011-10-12 06:37:35] VERBOSE[5535] chan_sip.c: list_route: hop: <sip:347@172.30.0.191>
[2011-10-12 06:37:35] VERBOSE[5535] chan_sip.c: set_destination: Parsing <sip:347@172.30.0.191> for address/port to send to
[2011-10-12 06:37:35] VERBOSE[5535] chan_sip.c: set_destination: set destination to 172.30.0.191:5060
[2011-10-12 06:37:35] VERBOSE[5535] chan_sip.c: Transmitting (no NAT) to 172.30.0.191:5060:
ACK sip:347@172.30.0.191 SIP/2.0
Via: SIP/2.0/UDP 172.30.0.190:5060;branch=z9hG4bK002843da
Max-Forwards: 70
From: "Old Office" <sip:16785134505@172.30.0.190>;tag=as3043f72e
To: <sip:347@172.30.0.191>;tag=3D7AD09D-15288712
Contact: <sip:16785134505@172.30.0.190:5060>
Call-ID: 62d6d0d027e34b756140de1a7df49869@172.30.0.190:5060
CSeq: 102 ACK
User-Agent: FPBX-2.9.0(1.8.6.0)
Content-Length: 0


---
[2011-10-12 06:37:35] VERBOSE[29000] app_dial.c:     -- SIP/347-0000000e connected line has changed. Saving it until answer for SIP/66.193.176.35-0000000d
[2011-10-12 06:37:35] VERBOSE[29000] app_dial.c:     -- SIP/347-0000000e answered SIP/66.193.176.35-0000000d
[2011-10-12 06:37:35] VERBOSE[29000] chan_sip.c: set_destination: Parsing <sip:6779c9c129c0c5f45206c7ba6a46e4ed@204.11.192.31:5060;transport=udp> for address/port to send to
[2011-10-12 06:37:35] VERBOSE[29000] chan_sip.c: set_destination: set destination to 204.11.192.31:5060
[2011-10-12 06:37:35] VERBOSE[29000] chan_sip.c: Audio is at 5060
[2011-10-12 06:37:35] VERBOSE[29000] chan_sip.c: Adding codec 0x4 (ulaw) to SDP
[2011-10-12 06:37:35] VERBOSE[29000] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP
[2011-10-12 06:37:35] VERBOSE[29000] chan_sip.c: Reliably Transmitting (NAT) to 204.11.192.31:5060:
INVITE sip:6779c9c129c0c5f45206c7ba6a46e4ed@204.11.192.31:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK27fb9062;rport
Max-Forwards: 70
From: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
To: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
Contact: <sip:17775551212@69.172.20.234:5060>
Call-ID: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 102 INVITE
User-Agent: FPBX-2.9.0(1.8.6.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces
Remote-Party-ID: "device" <sip:347@66.193.176.35>;party=called;privacy=off;screen=no
Content-Type: application/sdp
Content-Length: 238

v=0
o=root 1840618489 1840618490 IN IP4 69.172.20.234
s=Asterisk PBX 1.8.6.0
c=IN IP4 69.172.20.234
t=0 0
m=audio 10440 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

---
[2011-10-12 06:37:35] VERBOSE[29015] chan_sip.c: Scheduling destruction of SIP dialog '2ac2b48d3f114706355f320f25ea785c@callcentric.com' in 32000 ms (Method: INVITE)
[2011-10-12 06:37:35] VERBOSE[29015] chan_sip.c: Reliably Transmitting (NAT) to 204.11.192.34:5080:
CANCEL sip:16785551212@callcentric.com SIP/2.0
Via: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK3851b9e2;rport
Max-Forwards: 70
From: "16785134505" <sip:17775551212@callcentric.com>;tag=as579afb7c
To: <sip:16785551212@callcentric.com>
Call-ID: 2ac2b48d3f114706355f320f25ea785c@callcentric.com
CSeq: 103 CANCEL
User-Agent: FPBX-2.9.0(1.8.6.0)
Content-Length: 0


---

#6

Part 2, Cancel packet (duplicated) forward.

[2011-10-12 06:37:35] VERBOSE[29015] chan_sip.c: Scheduling destruction of SIP dialog '2ac2b48d3f114706355f320f25ea785c@callcentric.com' in 32000 ms (Method: INVITE)
[2011-10-12 06:37:35] VERBOSE[29015] chan_sip.c: Reliably Transmitting (NAT) to 204.11.192.34:5080:
CANCEL sip:16785551212@callcentric.com SIP/2.0
Via: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK3851b9e2;rport
Max-Forwards: 70
From: "16785134505" <sip:17775551212@callcentric.com>;tag=as579afb7c
To: <sip:16785551212@callcentric.com>
Call-ID: 2ac2b48d3f114706355f320f25ea785c@callcentric.com
CSeq: 103 CANCEL
User-Agent: FPBX-2.9.0(1.8.6.0)
Content-Length: 0


---
[2011-10-12 06:37:35] VERBOSE[29015] chan_sip.c: Scheduling destruction of SIP dialog '2ac2b48d3f114706355f320f25ea785c@callcentric.com' in 32000 ms (Method: INVITE)
[2011-10-12 06:37:35] VERBOSE[29015] app_macro.c:   == Spawn extension (macro-dialout-trunk, s, 20) exited non-zero on 'Local/6785551212@from-internal-b723;2' in macro 'dialout-trunk'
[2011-10-12 06:37:35] VERBOSE[29015] pbx.c:   == Spawn extension (from-internal, 6785551212, 5) exited non-zero on 'Local/6785551212@from-internal-b723;2'
[2011-10-12 06:37:35] VERBOSE[29015] pbx.c:     -- Executing [h@from-internal:1] Hangup("Local/6785551212@from-internal-b723;2", "") in new stack
[2011-10-12 06:37:35] VERBOSE[29015] pbx.c:   == Spawn extension (from-internal, h, 1) exited non-zero on 'Local/6785551212@from-internal-b723;2'
[2011-10-12 06:37:35] VERBOSE[29000] pbx.c:     -- Executing [s@macro-auto-blkvm:1] Set("SIP/347-0000000e", "__MACRO_RESULT=") in new stack
[2011-10-12 06:37:35] VERBOSE[29000] pbx.c:     -- Executing [s@macro-auto-blkvm:2] Macro("SIP/347-0000000e", "blkvm-clr,") in new stack
[2011-10-12 06:37:35] VERBOSE[29000] pbx.c:     -- Executing [s@macro-blkvm-clr:1] Set("SIP/347-0000000e", "SHARED(BLKVM,SIP/66.193.176.35-0000000d)=") in new stack
[2011-10-12 06:37:35] VERBOSE[29000] pbx.c:     -- Executing [s@macro-blkvm-clr:2] Set("SIP/347-0000000e", "GOSUB_RETVAL=") in new stack
[2011-10-12 06:37:35] VERBOSE[29000] pbx.c:     -- Executing [s@macro-blkvm-clr:3] MacroExit("SIP/347-0000000e", "") in new stack
[2011-10-12 06:37:35] VERBOSE[29000] pbx.c:     -- Executing [s@macro-auto-blkvm:3] Set("SIP/347-0000000e", "MASTER_CHANNEL(CONNECTEDLINE(num))=347") in new stack
[2011-10-12 06:37:35] VERBOSE[29000] chan_sip.c: set_destination: Parsing <sip:6779c9c129c0c5f45206c7ba6a46e4ed@204.11.192.31:5060;transport=udp> for address/port to send to
[2011-10-12 06:37:35] VERBOSE[29000] chan_sip.c: set_destination: set destination to 204.11.192.31:5060
[2011-10-12 06:37:35] VERBOSE[29000] chan_sip.c: Reliably Transmitting (NAT) to 204.11.192.31:5060:
UPDATE sip:6779c9c129c0c5f45206c7ba6a46e4ed@204.11.192.31:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK1bb5e73b;rport
Max-Forwards: 70
From: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
To: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
Contact: <sip:17775551212@69.172.20.234:5060>
Call-ID: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 103 UPDATE
User-Agent: FPBX-2.9.0(1.8.6.0)
Remote-Party-ID: "device" <sip:347@66.193.176.35>;party=calling;privacy=off;screen=no
X-Asterisk-rpid-update: Yes
Content-Length: 0


---
[2011-10-12 06:37:35] VERBOSE[29000] pbx.c:     -- Executing [s@macro-auto-blkvm:4] Set("SIP/347-0000000e", "MASTER_CHANNEL(CONNECTEDLINE(name))=Dan Barker") in new stack
[2011-10-12 06:37:35] VERBOSE[29000] chan_sip.c: set_destination: Parsing <sip:6779c9c129c0c5f45206c7ba6a46e4ed@204.11.192.31:5060;transport=udp> for address/port to send to
[2011-10-12 06:37:35] VERBOSE[29000] chan_sip.c: set_destination: set destination to 204.11.192.31:5060
[2011-10-12 06:37:35] VERBOSE[29000] chan_sip.c: Reliably Transmitting (NAT) to 204.11.192.31:5060:
UPDATE sip:6779c9c129c0c5f45206c7ba6a46e4ed@204.11.192.31:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK126d3160;rport
Max-Forwards: 70
From: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
To: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
Contact: <sip:17775551212@69.172.20.234:5060>
Call-ID: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 104 UPDATE
User-Agent: FPBX-2.9.0(1.8.6.0)
Remote-Party-ID: "Dan Barker" <sip:347@66.193.176.35>;party=calling;privacy=off;screen=no
X-Asterisk-rpid-update: Yes
Content-Length: 0


---
[2011-10-12 06:37:35] VERBOSE[29000] res_musiconhold.c:     -- Stopped music on hold on SIP/66.193.176.35-0000000d
[2011-10-12 06:37:35] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:204.11.192.34:5080 --->
SIP/2.0 200 OK
v: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK3851b9e2;rport=5060
f: "16785134505" <sip:17775551212@callcentric.com>;tag=as579afb7c
t: <sip:16785551212@callcentric.com>
i: 2ac2b48d3f114706355f320f25ea785c@callcentric.com
CSeq: 103 CANCEL
l: 0

<------------->
[2011-10-12 06:37:35] VERBOSE[5535] chan_sip.c: --- (7 headers 0 lines) ---
[2011-10-12 06:37:35] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:204.11.192.34:5080 --->
SIP/2.0 487 Request Terminated
v: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK3851b9e2;rport=5060
f: "16785134505" <sip:17775551212@callcentric.com>;tag=as579afb7c
t: <sip:16785551212@callcentric.com>;tag=3527404648-143775
i: 2ac2b48d3f114706355f320f25ea785c@callcentric.com
CSeq: 103 INVITE
m: <sip:1ad5f411e1498eb403a36721f9812f3d@204.11.192.34:5080;transport=udp>
l: 0

<------------->
[2011-10-12 06:37:35] VERBOSE[5535] chan_sip.c: --- (8 headers 0 lines) ---
[2011-10-12 06:37:35] VERBOSE[5535] chan_sip.c: Transmitting (NAT) to 204.11.192.34:5080:
ACK sip:16785551212@callcentric.com SIP/2.0
Via: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK3851b9e2;rport
Max-Forwards: 70
From: "16785134505" <sip:17775551212@callcentric.com>;tag=as579afb7c
To: <sip:16785551212@callcentric.com>;tag=3527404648-143775
Contact: <sip:17775551212@69.172.20.234:5060>
Call-ID: 2ac2b48d3f114706355f320f25ea785c@callcentric.com
CSeq: 103 ACK
User-Agent: FPBX-2.9.0(1.8.6.0)
Content-Length: 0


---
[2011-10-12 06:37:35] VERBOSE[5535] chan_sip.c: Really destroying SIP dialog '2ac2b48d3f114706355f320f25ea785c@callcentric.com' Method: INVITE
[2011-10-12 06:37:35] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:204.11.192.31:5060 --->
SIP/2.0 100 Trying
v: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK27fb9062;rport=5060
f: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
t: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
i: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 102 INVITE
l: 0

<------------->
[2011-10-12 06:37:35] VERBOSE[5535] chan_sip.c: --- (7 headers 0 lines) ---
[2011-10-12 06:37:35] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:204.11.192.31:5060 --->
SIP/2.0 100 Trying
v: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK1bb5e73b;rport=5060
f: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
t: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
i: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 103 UPDATE
l: 0

<------------->
[2011-10-12 06:37:35] VERBOSE[5535] chan_sip.c: --- (7 headers 0 lines) ---
[2011-10-12 06:37:35] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:204.11.192.31:5060 --->
SIP/2.0 100 Trying
v: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK126d3160;rport=5060
f: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
t: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
i: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 104 UPDATE
l: 0

<------------->
[2011-10-12 06:37:35] VERBOSE[5535] chan_sip.c: --- (7 headers 0 lines) ---
[2011-10-12 06:37:35] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:204.11.192.31:5060 --->
SIP/2.0 200 OK
v: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK27fb9062;rport=5060
f: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
t: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
i: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 102 INVITE
m: <sip:930baa9071a6e8971677a71d0c66e8ae@204.11.192.31:5060;transport=udp>
c: application/sdp
l: 317

v=0
o=NexTone-MSW 25150 17702 IN IP4 204.11.192.31
s=sip call
c=IN IP4 204.11.192.31
t=0 0
m=audio 49212 RTP/AVP 0 18 101
a=maxptime:20
a=sendrecv
a=fmtp:101 0-15
a=rtpmap:101 telephone-event/8000
a=fmtp:18 annexb=no
a=rtpmap:18 G729/8000
a=rtpmap:0 PCMU/8000
a=silenceSupp:off - - - -
a=setup:actpass
<------------->
[2011-10-12 06:37:35] VERBOSE[5535] chan_sip.c: --- (9 headers 15 lines) ---
[2011-10-12 06:37:35] VERBOSE[5535] chan_sip.c: set_destination: Parsing <sip:6779c9c129c0c5f45206c7ba6a46e4ed@204.11.192.31:5060;transport=udp> for address/port to send to
[2011-10-12 06:37:35] VERBOSE[5535] chan_sip.c: set_destination: set destination to 204.11.192.31:5060
[2011-10-12 06:37:35] VERBOSE[5535] chan_sip.c: Transmitting (NAT) to 204.11.192.31:5060:
ACK sip:6779c9c129c0c5f45206c7ba6a46e4ed@204.11.192.31:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK572b8ab9;rport
Max-Forwards: 70
From: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
To: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
Contact: <sip:17775551212@69.172.20.234:5060>
Call-ID: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 102 ACK
User-Agent: FPBX-2.9.0(1.8.6.0)
Content-Length: 0


---
[2011-10-12 06:37:35] VERBOSE[5535] chan_sip.c: Retransmitting #1 (NAT) to 204.11.192.31:5060:
UPDATE sip:6779c9c129c0c5f45206c7ba6a46e4ed@204.11.192.31:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK1bb5e73b;rport
Max-Forwards: 70
From: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
To: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
Contact: <sip:17775551212@69.172.20.234:5060>
Call-ID: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 103 UPDATE
User-Agent: FPBX-2.9.0(1.8.6.0)
Remote-Party-ID: "device" <sip:347@66.193.176.35>;party=calling;privacy=off;screen=no
X-Asterisk-rpid-update: Yes
Content-Length: 0


---
[2011-10-12 06:37:35] VERBOSE[5535] chan_sip.c: Retransmitting #1 (NAT) to 204.11.192.31:5060:
UPDATE sip:6779c9c129c0c5f45206c7ba6a46e4ed@204.11.192.31:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK126d3160;rport
Max-Forwards: 70
From: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
To: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
Contact: <sip:17775551212@69.172.20.234:5060>
Call-ID: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 104 UPDATE
User-Agent: FPBX-2.9.0(1.8.6.0)
Remote-Party-ID: "Dan Barker" <sip:347@66.193.176.35>;party=calling;privacy=off;screen=no
X-Asterisk-rpid-update: Yes
Content-Length: 0


---
[2011-10-12 06:37:35] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:204.11.192.31:5060 --->
SIP/2.0 100 Trying
v: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK1bb5e73b;rport=5060
f: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
t: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
i: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 103 UPDATE
l: 0

<------------->
[2011-10-12 06:37:35] VERBOSE[5535] chan_sip.c: --- (7 headers 0 lines) ---
[2011-10-12 06:37:35] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:204.11.192.31:5060 --->
SIP/2.0 100 Trying
v: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK126d3160;rport=5060
f: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
t: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
i: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 104 UPDATE
l: 0

<------------->
[2011-10-12 06:37:35] VERBOSE[5535] chan_sip.c: --- (7 headers 0 lines) ---
[2011-10-12 06:37:36] VERBOSE[5535] chan_sip.c: Retransmitting #2 (NAT) to 204.11.192.31:5060:
UPDATE sip:6779c9c129c0c5f45206c7ba6a46e4ed@204.11.192.31:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK1bb5e73b;rport
Max-Forwards: 70
From: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
To: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
Contact: <sip:17775551212@69.172.20.234:5060>
Call-ID: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 103 UPDATE
User-Agent: FPBX-2.9.0(1.8.6.0)
Remote-Party-ID: "device" <sip:347@66.193.176.35>;party=calling;privacy=off;screen=no
X-Asterisk-rpid-update: Yes
Content-Length: 0


---
[2011-10-12 06:37:36] VERBOSE[5535] chan_sip.c: Retransmitting #2 (NAT) to 204.11.192.31:5060:
UPDATE sip:6779c9c129c0c5f45206c7ba6a46e4ed@204.11.192.31:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK126d3160;rport
Max-Forwards: 70
From: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
To: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
Contact: <sip:17775551212@69.172.20.234:5060>
Call-ID: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 104 UPDATE
User-Agent: FPBX-2.9.0(1.8.6.0)
Remote-Party-ID: "Dan Barker" <sip:347@66.193.176.35>;party=calling;privacy=off;screen=no
X-Asterisk-rpid-update: Yes
Content-Length: 0


---
[2011-10-12 06:37:36] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:204.11.192.31:5060 --->
SIP/2.0 100 Trying
v: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK1bb5e73b;rport=5060
f: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
t: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
i: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 103 UPDATE
l: 0

<------------->
[2011-10-12 06:37:36] VERBOSE[5535] chan_sip.c: --- (7 headers 0 lines) ---
[2011-10-12 06:37:36] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:204.11.192.31:5060 --->
SIP/2.0 100 Trying
v: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK126d3160;rport=5060
f: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
t: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
i: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 104 UPDATE
l: 0

<------------->
[2011-10-12 06:37:36] VERBOSE[5535] chan_sip.c: --- (7 headers 0 lines) ---
[2011-10-12 06:37:36] VERBOSE[5535] chan_sip.c: Reliably Transmitting (no NAT) to 172.30.0.191:5060:
OPTIONS sip:347@172.30.0.191 SIP/2.0
Via: SIP/2.0/UDP 172.30.0.190:5060;branch=z9hG4bK60034b07
Max-Forwards: 70
From: "Unknown" <sip:Unknown@172.30.0.190>;tag=as1ff0fd6d
To: <sip:347@172.30.0.191>
Contact: <sip:Unknown@172.30.0.190:5060>
Call-ID: 4718e1cd6b45e65b699e64f302712fda@172.30.0.190:5060
CSeq: 102 OPTIONS
User-Agent: FPBX-2.9.0(1.8.6.0)
Date: Wed, 12 Oct 2011 10:37:36 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces
Content-Length: 0


---
[2011-10-12 06:37:36] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:172.30.0.191:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.30.0.190:5060;branch=z9hG4bK60034b07
From: "Unknown" <sip:Unknown@172.30.0.190>;tag=as1ff0fd6d
To: "Dan Barker" <sip:347@172.30.0.191>;tag=4F124D50-345FDE79
CSeq: 102 OPTIONS
Call-ID: 4718e1cd6b45e65b699e64f302712fda@172.30.0.190:5060
Contact: <sip:347@172.30.0.191>
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER
Supported: 100rel,replaces,100rel,timer,replaces,norefersub
User-Agent: PolycomSoundPointIP-SPIP_331-UA/3.3.2.0413
Accept-Language: en
Accept: application/sdp,text/plain,message/sipfrag,application/dialog-info+xml
Accept-Encoding: identity
Content-Length: 0

<------------->
[2011-10-12 06:37:36] VERBOSE[5535] chan_sip.c: --- (14 headers 0 lines) ---
[2011-10-12 06:37:36] VERBOSE[5535] chan_sip.c: Really destroying SIP dialog '4718e1cd6b45e65b699e64f302712fda@172.30.0.190:5060' Method: OPTIONS
[2011-10-12 06:37:38] VERBOSE[5535] chan_sip.c: Retransmitting #3 (NAT) to 204.11.192.31:5060:
UPDATE sip:6779c9c129c0c5f45206c7ba6a46e4ed@204.11.192.31:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK1bb5e73b;rport
Max-Forwards: 70
From: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
To: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
Contact: <sip:17775551212@69.172.20.234:5060>
Call-ID: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 103 UPDATE
User-Agent: FPBX-2.9.0(1.8.6.0)
Remote-Party-ID: "device" <sip:347@66.193.176.35>;party=calling;privacy=off;screen=no
X-Asterisk-rpid-update: Yes
Content-Length: 0


---
[2011-10-12 06:37:38] VERBOSE[5535] chan_sip.c: Retransmitting #3 (NAT) to 204.11.192.31:5060:
UPDATE sip:6779c9c129c0c5f45206c7ba6a46e4ed@204.11.192.31:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK126d3160;rport
Max-Forwards: 70
From: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
To: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
Contact: <sip:17775551212@69.172.20.234:5060>
Call-ID: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 104 UPDATE
User-Agent: FPBX-2.9.0(1.8.6.0)
Remote-Party-ID: "Dan Barker" <sip:347@66.193.176.35>;party=calling;privacy=off;screen=no
X-Asterisk-rpid-update: Yes
Content-Length: 0


---
[2011-10-12 06:37:38] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:204.11.192.31:5060 --->
SIP/2.0 100 Trying
v: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK1bb5e73b;rport=5060
f: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
t: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
i: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 103 UPDATE
l: 0

<------------->
[2011-10-12 06:37:38] VERBOSE[5535] chan_sip.c: --- (7 headers 0 lines) ---
[2011-10-12 06:37:38] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:204.11.192.31:5060 --->
SIP/2.0 100 Trying
v: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK126d3160;rport=5060
f: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
t: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
i: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 104 UPDATE
l: 0

<------------->
[2011-10-12 06:37:38] VERBOSE[5535] chan_sip.c: --- (7 headers 0 lines) ---
[2011-10-12 06:37:39] VERBOSE[5535] chan_sip.c: Reliably Transmitting (no NAT) to 172.30.0.192:5060:
OPTIONS sip:348@172.30.0.192 SIP/2.0
Via: SIP/2.0/UDP 172.30.0.190:5060;branch=z9hG4bK31886226
Max-Forwards: 70
From: "Unknown" <sip:Unknown@172.30.0.190>;tag=as55cb5f4e
To: <sip:348@172.30.0.192>
Contact: <sip:Unknown@172.30.0.190:5060>
Call-ID: 4b0f1e2669525b6a765d378e3a6f162e@172.30.0.190:5060
CSeq: 102 OPTIONS
User-Agent: FPBX-2.9.0(1.8.6.0)
Date: Wed, 12 Oct 2011 10:37:39 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces
Content-Length: 0


---
[2011-10-12 06:37:39] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:172.30.0.192:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.30.0.190:5060;branch=z9hG4bK31886226
From: "Unknown" <sip:Unknown@172.30.0.190>;tag=as55cb5f4e
To: "Pam Barker" <sip:348@172.30.0.192>;tag=6E81BA18-B7DAC427
CSeq: 102 OPTIONS
Call-ID: 4b0f1e2669525b6a765d378e3a6f162e@172.30.0.190:5060
Contact: <sip:348@172.30.0.192>
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER
Supported: 100rel,replaces,100rel,timer,replaces,norefersub
User-Agent: PolycomSoundPointIP-SPIP_331-UA/3.3.2.0413
Accept-Language: en
Accept: application/sdp,text/plain,message/sipfrag,application/dialog-info+xml
Accept-Encoding: identity
Content-Length: 0

<------------->
[2011-10-12 06:37:39] VERBOSE[5535] chan_sip.c: --- (14 headers 0 lines) ---
[2011-10-12 06:37:39] VERBOSE[5535] chan_sip.c: Really destroying SIP dialog '4b0f1e2669525b6a765d378e3a6f162e@172.30.0.190:5060' Method: OPTIONS
[2011-10-12 06:37:42] VERBOSE[5535] chan_sip.c: Retransmitting #4 (NAT) to 204.11.192.31:5060:
UPDATE sip:6779c9c129c0c5f45206c7ba6a46e4ed@204.11.192.31:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK1bb5e73b;rport
Max-Forwards: 70
From: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
To: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
Contact: <sip:17775551212@69.172.20.234:5060>
Call-ID: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 103 UPDATE
User-Agent: FPBX-2.9.0(1.8.6.0)
Remote-Party-ID: "device" <sip:347@66.193.176.35>;party=calling;privacy=off;screen=no
X-Asterisk-rpid-update: Yes
Content-Length: 0


---
[2011-10-12 06:37:42] VERBOSE[5535] chan_sip.c: Retransmitting #4 (NAT) to 204.11.192.31:5060:
UPDATE sip:6779c9c129c0c5f45206c7ba6a46e4ed@204.11.192.31:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK126d3160;rport
Max-Forwards: 70
From: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
To: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
Contact: <sip:17775551212@69.172.20.234:5060>
Call-ID: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 104 UPDATE
User-Agent: FPBX-2.9.0(1.8.6.0)
Remote-Party-ID: "Dan Barker" <sip:347@66.193.176.35>;party=calling;privacy=off;screen=no
X-Asterisk-rpid-update: Yes
Content-Length: 0


---
[2011-10-12 06:37:42] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:204.11.192.31:5060 --->
SIP/2.0 100 Trying
v: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK1bb5e73b;rport=5060
f: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
t: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
i: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 103 UPDATE
l: 0

<------------->
[2011-10-12 06:37:42] VERBOSE[5535] chan_sip.c: --- (7 headers 0 lines) ---
[2011-10-12 06:37:42] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:204.11.192.31:5060 --->
SIP/2.0 100 Trying
v: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK126d3160;rport=5060
f: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
t: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
i: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 104 UPDATE
l: 0

<------------->
[2011-10-12 06:37:42] VERBOSE[5535] chan_sip.c: --- (7 headers 0 lines) ---
[2011-10-12 06:37:44] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:172.30.0.199:5060 --->

<------------->
[2011-10-12 06:37:46] VERBOSE[5535] chan_sip.c: Reliably Transmitting (no NAT) to 172.30.0.199:5060:
OPTIONS sip:314@172.30.0.199 SIP/2.0
Via: SIP/2.0/UDP 172.30.0.190:5060;branch=z9hG4bK5dec812e
Max-Forwards: 70
From: "Unknown" <sip:Unknown@172.30.0.190>;tag=as2b8fb4c2
To: <sip:314@172.30.0.199>
Contact: <sip:Unknown@172.30.0.190:5060>
Call-ID: 7489034e3403e4af3679bf7a253ad7a4@172.30.0.190:5060
CSeq: 102 OPTIONS
User-Agent: FPBX-2.9.0(1.8.6.0)
Date: Wed, 12 Oct 2011 10:37:46 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces
Content-Length: 0


---
[2011-10-12 06:37:46] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:172.30.0.199:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.30.0.190:5060;branch=z9hG4bK5dec812e
From: "Unknown" <sip:Unknown@172.30.0.190>;tag=as2b8fb4c2
To: <sip:314@172.30.0.199>;tag=4acea7ce923ff83e
Call-ID: 7489034e3403e4af3679bf7a253ad7a4@172.30.0.190:5060
CSeq: 102 OPTIONS
User-Agent: Grandstream HT287 1.1.0.42 DevId 000b82334478
Contact: <sip:314@172.30.0.199>
Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE
Supported: replaces, timer
Content-Length: 0

<------------->
[2011-10-12 06:37:46] VERBOSE[5535] chan_sip.c: --- (11 headers 0 lines) ---
[2011-10-12 06:37:46] VERBOSE[5535] chan_sip.c: Really destroying SIP dialog '7489034e3403e4af3679bf7a253ad7a4@172.30.0.190:5060' Method: OPTIONS
[2011-10-12 06:37:46] VERBOSE[5535] chan_sip.c: Retransmitting #5 (NAT) to 204.11.192.31:5060:
UPDATE sip:6779c9c129c0c5f45206c7ba6a46e4ed@204.11.192.31:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK1bb5e73b;rport
Max-Forwards: 70
From: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
To: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
Contact: <sip:17775551212@69.172.20.234:5060>
Call-ID: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 103 UPDATE
User-Agent: FPBX-2.9.0(1.8.6.0)
Remote-Party-ID: "device" <sip:347@66.193.176.35>;party=calling;privacy=off;screen=no
X-Asterisk-rpid-update: Yes
Content-Length: 0


---
[2011-10-12 06:37:46] VERBOSE[5535] chan_sip.c: Retransmitting #5 (NAT) to 204.11.192.31:5060:
UPDATE sip:6779c9c129c0c5f45206c7ba6a46e4ed@204.11.192.31:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK126d3160;rport
Max-Forwards: 70
From: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
To: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
Contact: <sip:17775551212@69.172.20.234:5060>
Call-ID: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 104 UPDATE
User-Agent: FPBX-2.9.0(1.8.6.0)
Remote-Party-ID: "Dan Barker" <sip:347@66.193.176.35>;party=calling;privacy=off;screen=no
X-Asterisk-rpid-update: Yes
Content-Length: 0


---
[2011-10-12 06:37:46] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:204.11.192.31:5060 --->
SIP/2.0 100 Trying
v: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK1bb5e73b;rport=5060
f: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
t: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
i: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 103 UPDATE
l: 0

<------------->
[2011-10-12 06:37:46] VERBOSE[5535] chan_sip.c: --- (7 headers 0 lines) ---
[2011-10-12 06:37:46] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:204.11.192.31:5060 --->
SIP/2.0 100 Trying
v: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK126d3160;rport=5060
f: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
t: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
i: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 104 UPDATE
l: 0

<------------->
[2011-10-12 06:37:46] VERBOSE[5535] chan_sip.c: --- (7 headers 0 lines) ---
[2011-10-12 06:37:50] VERBOSE[5535] chan_sip.c: Retransmitting #6 (NAT) to 204.11.192.31:5060:
UPDATE sip:6779c9c129c0c5f45206c7ba6a46e4ed@204.11.192.31:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK1bb5e73b;rport
Max-Forwards: 70
From: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
To: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
Contact: <sip:17775551212@69.172.20.234:5060>
Call-ID: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 103 UPDATE
User-Agent: FPBX-2.9.0(1.8.6.0)
Remote-Party-ID: "device" <sip:347@66.193.176.35>;party=calling;privacy=off;screen=no
X-Asterisk-rpid-update: Yes
Content-Length: 0


---
[2011-10-12 06:37:50] VERBOSE[5535] chan_sip.c: Retransmitting #6 (NAT) to 204.11.192.31:5060:
UPDATE sip:6779c9c129c0c5f45206c7ba6a46e4ed@204.11.192.31:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK126d3160;rport
Max-Forwards: 70
From: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
To: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
Contact: <sip:17775551212@69.172.20.234:5060>
Call-ID: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 104 UPDATE
User-Agent: FPBX-2.9.0(1.8.6.0)
Remote-Party-ID: "Dan Barker" <sip:347@66.193.176.35>;party=calling;privacy=off;screen=no
X-Asterisk-rpid-update: Yes
Content-Length: 0


---
[2011-10-12 06:37:50] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:204.11.192.31:5060 --->
SIP/2.0 100 Trying
v: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK1bb5e73b;rport=5060
f: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
t: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
i: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 103 UPDATE
l: 0

<------------->
[2011-10-12 06:37:50] VERBOSE[5535] chan_sip.c: --- (7 headers 0 lines) ---
[2011-10-12 06:37:50] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:204.11.192.31:5060 --->
SIP/2.0 100 Trying
v: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK126d3160;rport=5060
f: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
t: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
i: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 104 UPDATE
l: 0

<------------->
[2011-10-12 06:37:50] VERBOSE[5535] chan_sip.c: --- (7 headers 0 lines) ---
[2011-10-12 06:37:54] VERBOSE[5535] chan_sip.c: Retransmitting #7 (NAT) to 204.11.192.31:5060:
UPDATE sip:6779c9c129c0c5f45206c7ba6a46e4ed@204.11.192.31:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK1bb5e73b;rport
Max-Forwards: 70
From: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
To: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
Contact: <sip:17775551212@69.172.20.234:5060>
Call-ID: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 103 UPDATE
User-Agent: FPBX-2.9.0(1.8.6.0)
Remote-Party-ID: "device" <sip:347@66.193.176.35>;party=calling;privacy=off;screen=no
X-Asterisk-rpid-update: Yes
Content-Length: 0


---
[2011-10-12 06:37:54] VERBOSE[5535] chan_sip.c: Retransmitting #7 (NAT) to 204.11.192.31:5060:
UPDATE sip:6779c9c129c0c5f45206c7ba6a46e4ed@204.11.192.31:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK126d3160;rport
Max-Forwards: 70
From: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
To: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
Contact: <sip:17775551212@69.172.20.234:5060>
Call-ID: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 104 UPDATE
User-Agent: FPBX-2.9.0(1.8.6.0)
Remote-Party-ID: "Dan Barker" <sip:347@66.193.176.35>;party=calling;privacy=off;screen=no
X-Asterisk-rpid-update: Yes
Content-Length: 0


---
[2011-10-12 06:37:54] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:204.11.192.31:5060 --->
SIP/2.0 100 Trying
v: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK1bb5e73b;rport=5060
f: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
t: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
i: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 103 UPDATE
l: 0

<------------->
[2011-10-12 06:37:54] VERBOSE[5535] chan_sip.c: --- (7 headers 0 lines) ---
[2011-10-12 06:37:54] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:204.11.192.31:5060 --->
SIP/2.0 100 Trying
v: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK126d3160;rport=5060
f: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
t: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
i: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 104 UPDATE
l: 0

<------------->
[2011-10-12 06:37:54] VERBOSE[5535] chan_sip.c: --- (7 headers 0 lines) ---
[2011-10-12 06:37:55] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:204.11.192.31:5060 --->
SIP/2.0 408 Request Timeout
v: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK1bb5e73b;rport=5060
f: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
t: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
i: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 103 UPDATE
l: 0

<------------->
[2011-10-12 06:37:55] VERBOSE[5535] chan_sip.c: --- (7 headers 0 lines) ---
[2011-10-12 06:37:55] VERBOSE[29000] pbx.c:     -- Executing [h@macro-dial:1] Macro("SIP/66.193.176.35-0000000d", "hangupcall") in new stack
[2011-10-12 06:37:55] VERBOSE[29000] pbx.c:     -- Executing [s@macro-hangupcall:1] GotoIf("SIP/66.193.176.35-0000000d", "1?theend") in new stack
[2011-10-12 06:37:55] VERBOSE[29000] pbx.c:     -- Goto (macro-hangupcall,s,3)
[2011-10-12 06:37:55] VERBOSE[29000] pbx.c:     -- Executing [s@macro-hangupcall:3] Hangup("SIP/66.193.176.35-0000000d", "") in new stack
[2011-10-12 06:37:55] VERBOSE[29000] app_macro.c:   == Spawn extension (macro-hangupcall, s, 3) exited non-zero on 'SIP/66.193.176.35-0000000d' in macro 'hangupcall'
[2011-10-12 06:37:55] VERBOSE[29000] features.c:   == Spawn extension (macro-dial, h, 1) exited non-zero on 'SIP/66.193.176.35-0000000d'
[2011-10-12 06:37:55] VERBOSE[29000] chan_sip.c: Scheduling destruction of SIP dialog '62d6d0d027e34b756140de1a7df49869@172.30.0.190:5060' in 6400 ms (Method: INVITE)
[2011-10-12 06:37:55] VERBOSE[29000] chan_sip.c: set_destination: Parsing <sip:347@172.30.0.191> for address/port to send to
[2011-10-12 06:37:55] VERBOSE[29000] chan_sip.c: set_destination: set destination to 172.30.0.191:5060
[2011-10-12 06:37:55] VERBOSE[29000] chan_sip.c: Reliably Transmitting (no NAT) to 172.30.0.191:5060:
BYE sip:347@172.30.0.191 SIP/2.0
Via: SIP/2.0/UDP 172.30.0.190:5060;branch=z9hG4bK31c0731e
Max-Forwards: 70
From: "Old Office" <sip:16785134505@172.30.0.190>;tag=as3043f72e
To: <sip:347@172.30.0.191>;tag=3D7AD09D-15288712
Call-ID: 62d6d0d027e34b756140de1a7df49869@172.30.0.190:5060
CSeq: 103 BYE
User-Agent: FPBX-2.9.0(1.8.6.0)
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16
Content-Length: 0


---
[2011-10-12 06:37:55] VERBOSE[29000] app_macro.c:   == Spawn extension (macro-dial, s, 7) exited non-zero on 'SIP/66.193.176.35-0000000d' in macro 'dial'
[2011-10-12 06:37:55] VERBOSE[29000] pbx.c:   == Spawn extension (ext-group, 647, 12) exited non-zero on 'SIP/66.193.176.35-0000000d'
[2011-10-12 06:37:55] VERBOSE[29000] chan_sip.c: Scheduling destruction of SIP dialog '13593669-3527404641-844036@msw1.telengy.net' in 32000 ms (Method: ACK)
[2011-10-12 06:37:55] VERBOSE[29000] chan_sip.c: set_destination: Parsing <sip:6779c9c129c0c5f45206c7ba6a46e4ed@204.11.192.31:5060;transport=udp> for address/port to send to
[2011-10-12 06:37:55] VERBOSE[29000] chan_sip.c: set_destination: set destination to 204.11.192.31:5060
[2011-10-12 06:37:55] VERBOSE[29000] chan_sip.c: Reliably Transmitting (NAT) to 204.11.192.31:5060:
BYE sip:6779c9c129c0c5f45206c7ba6a46e4ed@204.11.192.31:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK33982cea;rport
Max-Forwards: 70
From: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
To: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
Call-ID: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 105 BYE
User-Agent: FPBX-2.9.0(1.8.6.0)
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16
Content-Length: 0


---
[2011-10-12 06:37:55] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:204.11.192.31:5060 --->
SIP/2.0 408 Request Timeout
v: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK126d3160;rport=5060
f: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
t: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
i: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 104 UPDATE
l: 0

<------------->
[2011-10-12 06:37:55] VERBOSE[5535] chan_sip.c: --- (7 headers 0 lines) ---
[2011-10-12 06:37:55] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:172.30.0.191:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.30.0.190:5060;branch=z9hG4bK31c0731e
From: "Old Office" <sip:16785134505@172.30.0.190>;tag=as3043f72e
To: "Dan Barker" <sip:347@172.30.0.191>;tag=3D7AD09D-15288712
CSeq: 103 BYE
Call-ID: 62d6d0d027e34b756140de1a7df49869@172.30.0.190:5060
Contact: <sip:347@172.30.0.191>
User-Agent: PolycomSoundPointIP-SPIP_331-UA/3.3.2.0413
Accept-Language: en
Content-Length: 0

<------------->
[2011-10-12 06:37:55] VERBOSE[5535] chan_sip.c: --- (10 headers 0 lines) ---
[2011-10-12 06:37:55] VERBOSE[5535] chan_sip.c: Really destroying SIP dialog '62d6d0d027e34b756140de1a7df49869@172.30.0.190:5060' Method: INVITE
[2011-10-12 06:37:55] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:204.11.192.31:5060 --->
SIP/2.0 100 Trying
v: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK33982cea;rport=5060
f: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
t: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
i: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 105 BYE
l: 0

<------------->
[2011-10-12 06:37:55] VERBOSE[5535] chan_sip.c: --- (7 headers 0 lines) ---
[2011-10-12 06:37:55] VERBOSE[5535] chan_sip.c:
<--- SIP read from UDP:204.11.192.31:5060 --->
SIP/2.0 200 OK
v: SIP/2.0/UDP 69.172.20.234:5060;branch=z9hG4bK33982cea;rport=5060
f: <sip:14044786561@ss.callcentric.com>;tag=as56a848f6
t: <sip:16785134505@66.193.176.35>;tag=3527404641-844072
i: 13593669-3527404641-844036@msw1.telengy.net
CSeq: 105 BYE
l: 0

<------------->
[2011-10-12 06:37:55] VERBOSE[5535] chan_sip.c: --- (7 headers 0 lines) ---
[2011-10-12 06:37:55] VERBOSE[5535] chan_sip.c: Really destroying SIP dialog '13593669-3527404641-844036@msw1.telengy.net' Method: ACK

#7

The UPDATE has no SDP, so it nothing to do with directmedia.

It is actually the result of your dialplan trying to update the connected line information that would display on the phone. If you don’t want the UPDATE, don’t use this feature.


#8

I’m not certain to what feature you may be referring, but that’s beside the point. I (a noob) saw the UPDATEs and didn’t understand them and mentioned them in my post. However, the “SIP/2.0 408 Request Timeout” terminates the call and is unwanted. Do you know why Callcentric sent that packet?


#9

So, I added rpid_update=no to sip_conf, and the symptom didn’t change. I then removed sendrpid=yes and it fixed the problem! Thanks for the hint! However, I really do need the sendrpid, otherwise I can’t control which DID number is shown on outsider’s phones. So, it’s back to Callcentric support with the new information.

Really big thanks for pointing out that I requested the UPDATEs.


#10

To stop the UPDATEs you need to remove this (and all similar) lines from the dialplan:

[2011-10-12 06:37:35] VERBOSE[29000] pbx.c: – Executing [s@macro-auto-blkvm:3] Set(“SIP/3470000000e”, “MASTER_CHANNEL(CONNECTEDLINE(num))=347”) in new stack

There may be a sip.conf option that makes it ineffective, but it is new to 1.8 and I only have 1.6 to play with.

The 408 appears to be the result of Callcentric having a bug in their handling of UPDATE methods.


#11

Moved to “rpid_update=no not working” thread.