Sip Calls being disconnected after exactly 1 minute in external IVR

I am trying to troubleshoot a problem where all the calls made to certain 1800 numbers (with IVRs get disconnected after EXACTLY one minute when listening to the prompts.

This happens in at least two freepbx systems that I have installed using PBXinaflash.

I have polycom phones, and here is a copy of the log when this happens: the extension is 114, the external number is the 1800 below… I had PRI debug and sip debug enabled for this log file.

The call started on [Jun 5 13:34:44] and got misteriously disconnected on [Jun 5 13:35:44]

There are at least 5 other 1800 numbers with IVRs that give me the same scenario.

PLEASE HEEEELP!

---- start ----

[Jun 5 13:33:38] VERBOSE[2207] logger.c: Asterisk Event Logger restarted
[Jun 5 13:33:38] VERBOSE[2207] logger.c: Asterisk Queue Logger restarted
[Jun 5 13:34:23] DEBUG[21708] chan_sip.c: Adding subscription for mailbox notification - peer 107 Mailbox 107@default
[Jun 5 13:34:24] DEBUG[21708] chan_sip.c: Adding subscription for mailbox notification - peer 116 Mailbox 116@device
[Jun 5 13:34:39] DEBUG[21708] chan_sip.c: Adding subscription for mailbox notification - peer 109 Mailbox 109@default
[Jun 5 13:34:44] VERBOSE[21708] logger.c:
<— SIP read from 192.168.10.139:5060 —>
INVITE sip:[email protected]:5060;user=phone SIP/2.0

Via: SIP/2.0/UDP 192.168.10.139;branch=z9hG4bK45df262755990942

From: “Flores” sip:[email protected];tag=CE60922E-9020E389

To: sip:[email protected];user=phone

CSeq: 1 INVITE

Call-ID: [email protected]

Contact: sip:[email protected]

Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER

User-Agent: PolycomSoundPointIP-SPIP_430-UA/3.1.2.0392

Accept-Language: en

Supported: 100rel,replaces

Allow-Events: talk,hold,conference

Max-Forwards: 70

Content-Type: application/sdp

Content-Length: 274

v=0

o=- 1244209843 1244209843 IN IP4 192.168.10.139

s=Polycom IP Phone

c=IN IP4 192.168.10.139

t=0 0

a=sendrecv

m=audio 2244 RTP/AVP 0 8 18 101

a=rtpmap:0 PCMU/8000

a=rtpmap:8 PCMA/8000

a=rtpmap:18 G729/8000

a=fmtp:18 annexb=no

a=rtpmap:101 telephone-event/8000

<------------->
[Jun 5 13:34:44] VERBOSE[21708] logger.c: — (15 headers 12 lines) —
[Jun 5 13:34:44] VERBOSE[21708] logger.c: Sending to 192.168.10.139 : 5060 (no NAT)
[Jun 5 13:34:44] VERBOSE[21708] logger.c: Using INVITE request as basis request - [email protected]
[Jun 5 13:34:44] VERBOSE[21708] logger.c:
<— Reliably Transmitting (NAT) to 192.168.10.139:5060 —>
SIP/2.0 407 Proxy Authentication Required

Via: SIP/2.0/UDP 192.168.10.139;branch=z9hG4bK45df262755990942;received=192.168.10.139

From: “Flores” sip:[email protected];tag=CE60922E-9020E389

To: sip:[email protected];user=phone;tag=as666c48c8

Call-ID: [email protected]

CSeq: 1 INVITE

User-Agent: Asterisk PBX

Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY

Supported: replaces

Proxy-Authenticate: Digest algorithm=MD5, realm=“asterisk”, nonce=“624c7fd5”

Content-Length: 0

<------------>
[Jun 5 13:34:44] VERBOSE[21708] logger.c: Scheduling destruction of SIP dialog ‘[email protected]’ in 32000 ms (Method: INVITE)
[Jun 5 13:34:44] VERBOSE[21708] logger.c: Found user ‘114’
[Jun 5 13:34:44] VERBOSE[21708] logger.c:
<— SIP read from 192.168.10.139:5060 —>
ACK sip:[email protected]:5060 SIP/2.0

Via: SIP/2.0/UDP 192.168.10.139;branch=z9hG4bK45df262755990942

From: “Flores” sip:[email protected];tag=CE60922E-9020E389

To: sip:[email protected];user=phone;tag=as666c48c8

CSeq: 1 ACK

Call-ID: [email protected]

Contact: sip:[email protected]

Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER

User-Agent: PolycomSoundPointIP-SPIP_430-UA/3.1.2.0392

Accept-Language: en

Max-Forwards: 70

Content-Length: 0

<------------->
[Jun 5 13:34:44] VERBOSE[21708] logger.c: — (12 headers 0 lines) —
[Jun 5 13:34:44] VERBOSE[21708] logger.c:
<— SIP read from 192.168.10.139:5060 —>
INVITE sip:[email protected]:5060;user=phone SIP/2.0

Via: SIP/2.0/UDP 192.168.10.139;branch=z9hG4bK910f8e242FEA41FF

From: “Flores” sip:[email protected];tag=CE60922E-9020E389

To: sip:[email protected];user=phone

CSeq: 2 INVITE

Call-ID: [email protected]

Contact: sip:[email protected]

Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER

User-Agent: PolycomSoundPointIP-SPIP_430-UA/3.1.2.0392

Accept-Language: en

Supported: 100rel,replaces

Allow-Events: talk,hold,conference

Proxy-Authorization: Digest username=“114”, realm=“asterisk”, nonce=“624c7fd5”, uri=“sip:[email protected]:5060;user=phone”, response=“cc3ef298472ef401d65d432106d33ad6”, algorithm=MD5

Max-Forwards: 70

Content-Type: application/sdp

Content-Length: 274

v=0

o=- 1244209843 1244209843 IN IP4 192.168.10.139

s=Polycom IP Phone

c=IN IP4 192.168.10.139

t=0 0

a=sendrecv

m=audio 2244 RTP/AVP 0 8 18 101

a=rtpmap:0 PCMU/8000

a=rtpmap:8 PCMA/8000

a=rtpmap:18 G729/8000

a=fmtp:18 annexb=no

a=rtpmap:101 telephone-event/8000

<------------->
[Jun 5 13:34:44] VERBOSE[21708] logger.c: — (16 headers 12 lines) —
[Jun 5 13:34:44] VERBOSE[21708] logger.c: Sending to 192.168.10.139 : 5060 (NAT)
[Jun 5 13:34:44] VERBOSE[21708] logger.c: Using INVITE request as basis request - [email protected]
[Jun 5 13:34:44] VERBOSE[21708] logger.c: Found user ‘114’
[Jun 5 13:34:44] VERBOSE[21708] logger.c: Found RTP audio format 0
[Jun 5 13:34:44] VERBOSE[21708] logger.c: Found RTP audio format 8
[Jun 5 13:34:44] VERBOSE[21708] logger.c: Found RTP audio format 18
[Jun 5 13:34:44] VERBOSE[21708] logger.c: Found RTP audio format 101
[Jun 5 13:34:44] VERBOSE[21708] logger.c: Peer audio RTP is at port 192.168.10.139:2244
[Jun 5 13:34:44] VERBOSE[21708] logger.c: Found audio description format PCMU for ID 0
[Jun 5 13:34:44] VERBOSE[21708] logger.c: Found audio description format PCMA for ID 8
[Jun 5 13:34:44] VERBOSE[21708] logger.c: Found audio description format G729 for ID 18
[Jun 5 13:34:44] VERBOSE[21708] logger.c: Found audio description format telephone-event for ID 101
[Jun 5 13:34:44] VERBOSE[21708] logger.c: Capabilities: us - 0xc (ulaw|alaw), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing), combined - 0xc (ulaw|alaw)
[Jun 5 13:34:44] VERBOSE[21708] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event)
[Jun 5 13:34:44] VERBOSE[21708] logger.c: Peer audio RTP is at port 192.168.10.139:2244
[Jun 5 13:34:44] VERBOSE[21708] logger.c: Looking for 18009376824 in from-internal (domain 192.168.10.20)
[Jun 5 13:34:44] VERBOSE[21708] logger.c: list_route: hop: sip:[email protected]
[Jun 5 13:34:44] VERBOSE[21708] logger.c:
<— Transmitting (NAT) to 192.168.10.139:5060 —>
SIP/2.0 100 Trying

Via: SIP/2.0/UDP 192.168.10.139;branch=z9hG4bK910f8e242FEA41FF;received=192.168.10.139

From: “Flores” sip:[email protected];tag=CE60922E-9020E389

To: sip:[email protected];user=phone

Call-ID: [email protected]

CSeq: 2 INVITE

User-Agent: Asterisk PBX

Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY

Supported: replaces

Contact: sip:[email protected]

Content-Length: 0

<------------>
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [18009376824@from-internal:1] Set(“SIP/114-096d7478”, “EMERGENCYROUTE=YES”) in new stack
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [18009376824@from-internal:2] Macro(“SIP/114-096d7478”, “user-callerid|SKIPTTL|”) in new stack
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-user-callerid:1] Set(“SIP/114-096d7478”, “AMPUSER=114”) in new stack
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Executed application: Set
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-user-callerid:2] GotoIf(“SIP/114-096d7478”, “0?report”) in new stack
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Executed application: GotoIf
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-user-callerid:3] ExecIf(“SIP/114-096d7478”, “1|Set|REALCALLERIDNUM=114”) in new stack
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Executed application: ExecIf
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-user-callerid:4] Set(“SIP/114-096d7478”, “AMPUSER=114”) in new stack
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Executed application: Set
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-user-callerid:5] Set(“SIP/114-096d7478”, “AMPUSERCIDNAME=Gary Flores”) in new stack
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Executed application: Set
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-user-callerid:6] GotoIf(“SIP/114-096d7478”, “0?report”) in new stack
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Executed application: GotoIf
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-user-callerid:7] Set(“SIP/114-096d7478”, “AMPUSERCID=114”) in new stack
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Executed application: Set
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-user-callerid:8] Set(“SIP/114-096d7478”, “CALLERID(all)=“Gary Flores” <114>”) in new stack
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Executed application: Set
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-user-callerid:9] Set(“SIP/114-096d7478”, “REALCALLERIDNUM=114”) in new stack
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Executed application: Set
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-user-callerid:10] ExecIf(“SIP/114-096d7478”, “0|Set|CHANNEL(language)=”) in new stack
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Executed application: ExecIf
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-user-callerid:11] GotoIf(“SIP/114-096d7478”, “1?continue”) in new stack
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Goto (macro-user-callerid,s,20)
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Executed application: GotoIf
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-user-callerid:20] NoOp(“SIP/114-096d7478”, “Using CallerID “Gary Flores” <114>”) in new stack
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Executed application: Noop
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [18009376824@from-internal:3] Set(“SIP/114-096d7478”, “_NODEST=”) in new stack
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [18009376824@from-internal:4] Macro(“SIP/114-096d7478”, “record-enable|114|OUT|”) in new stack
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-record-enable:1] GotoIf(“SIP/114-096d7478”, “1?check”) in new stack
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Goto (macro-record-enable,s,4)
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Executed application: GotoIf
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-record-enable:4] AGI(“SIP/114-096d7478”, “recordingcheck|20090605-133444|1244234084.1870”) in new stack
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
[Jun 5 13:34:44] VERBOSE[2210] logger.c: recordingcheck|20090605-133444|1244234084.1870: Outbound recording not enabled
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – AGI Script recordingcheck completed, returning 0
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Executed application: AGI
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-record-enable:5] MacroExit(“SIP/114-096d7478”, “”) in new stack
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [18009376824@from-internal:5] Macro(“SIP/114-096d7478”, “dialout-trunk|1|18009376824||”) in new stack
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-dialout-trunk:1] Set(“SIP/114-096d7478”, “DIAL_TRUNK=1”) in new stack
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Executed application: Set
[Jun 5 13:34:44] DEBUG[2210] func_db.c: DB: AMPUSER/114/pinless not found in database.
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-dialout-trunk:2] GosubIf(“SIP/114-096d7478”, “0?sub-pincheck|s|1”) in new stack
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Executed application: GosubIf
[Jun 5 13:34:44] DEBUG[2210] func_db.c: DB: AMPUSER/114/pinless not found in database.
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-dialout-trunk:3] GotoIf(“SIP/114-096d7478”, “0?disabletrunk|1”) in new stack
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Executed application: GotoIf
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-dialout-trunk:4] Set(“SIP/114-096d7478”, “DIAL_NUMBER=18009376824”) in new stack
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Executed application: Set
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-dialout-trunk:5] Set(“SIP/114-096d7478”, “DIAL_TRUNK_OPTIONS=trw”) in new stack
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Executed application: Set
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-dialout-trunk:6] Set(“SIP/114-096d7478”, “OUTBOUND_GROUP=OUT_1”) in new stack
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Executed application: Set
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-dialout-trunk:7] GotoIf(“SIP/114-096d7478”, “1?nomax”) in new stack
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Goto (macro-dialout-trunk,s,9)
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Executed application: GotoIf
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-dialout-trunk:9] GotoIf(“SIP/114-096d7478”, “0?skipoutcid”) in new stack
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Executed application: GotoIf
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-dialout-trunk:10] Set(“SIP/114-096d7478”, “DIAL_TRUNK_OPTIONS=TW”) in new stack
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Executed application: Set
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-dialout-trunk:11] Macro(“SIP/114-096d7478”, “outbound-callerid|1”) in new stack
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-outbound-callerid:1] ExecIf(“SIP/114-096d7478”, “0|SetCallerPres|”) in new stack
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Executed application: ExecIf
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-outbound-callerid:2] ExecIf(“SIP/114-096d7478”, “0|Set|REALCALLERIDNUM=114”) in new stack
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Executed application: ExecIf
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-outbound-callerid:3] GotoIf(“SIP/114-096d7478”, “1?normcid”) in new stack
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Goto (macro-outbound-callerid,s,6)
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Executed application: GotoIf
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-outbound-callerid:6] Set(“SIP/114-096d7478”, “USEROUTCID=”) in new stack
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Executed application: Set
[Jun 5 13:34:44] DEBUG[2210] func_db.c: DB: DEVICE/114/emergency_cid not found in database.
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-outbound-callerid:7] Set(“SIP/114-096d7478”, “EMERGENCYCID=”) in new stack
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Executed application: Set
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-outbound-callerid:8] Set(“SIP/114-096d7478”, “TRUNKOUTCID=6024540471”) in new stack
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Executed application: Set
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-outbound-callerid:9] GotoIf(“SIP/114-096d7478”, “1?trunkcid”) in new stack
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Goto (macro-outbound-callerid,s,12)
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Executed application: GotoIf
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-outbound-callerid:12] ExecIf(“SIP/114-096d7478”, “1|Set|CALLERID(all)=6024540471”) in new stack
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Executed application: ExecIf
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Last app: Set|CALLERID(all)=6024540471
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-outbound-callerid:13] ExecIf(“SIP/114-096d7478”, “0|Set|CALLERID(all)=”) in new stack
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Executed application: ExecIf
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-outbound-callerid:14] ExecIf(“SIP/114-096d7478”, “0|SetCallerPres|prohib_passed_screen”) in new stack
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Executed application: ExecIf
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Executed application: Macro
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-dialout-trunk:12] ExecIf(“SIP/114-096d7478”, “1|AGI|fixlocalprefix”) in new stack
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Launched AGI Script /var/lib/asterisk/agi-bin/fixlocalprefix
[Jun 5 13:34:44] VERBOSE[2210] logger.c: == fixlocalprefix: Dialpattern 1NXXNXXXXXX matched. 18009376824 -> 18009376824
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – AGI Script fixlocalprefix completed, returning 0
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Executed application: ExecIf
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Last app: AGI|fixlocalprefix
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-dialout-trunk:13] Set(“SIP/114-096d7478”, “OUTNUM=18009376824”) in new stack
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Executed application: Set
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-dialout-trunk:14] Set(“SIP/114-096d7478”, “custom=ZAP/g0”) in new stack
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Executed application: Set
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-dialout-trunk:15] ExecIf(“SIP/114-096d7478”, “0|Set|DIAL_TRUNK_OPTIONS=M(setmusic^)TW”) in new stack
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Executed application: ExecIf
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-dialout-trunk:16] Macro(“SIP/114-096d7478”, “dialout-trunk-predial-hook|”) in new stack
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit(“SIP/114-096d7478”, “”) in new stack
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Executed application: Macro
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-dialout-trunk:17] GotoIf(“SIP/114-096d7478”, “0?bypass|1”) in new stack
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Executed application: GotoIf
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-dialout-trunk:18] GotoIf(“SIP/114-096d7478”, “0?customtrunk”) in new stack
[Jun 5 13:34:44] DEBUG[2210] app_macro.c: Executed application: GotoIf
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Executing [s@macro-dialout-trunk:19] Dial(“SIP/114-096d7478”, “ZAP/g0/18009376824|300|TW”) in new stack
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Making new call for cr 33101
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Requested transfer capability: 0x00 - SPEECH
[Jun 5 13:34:44] VERBOSE[2210] logger.c: > Protocol Discriminator: Q.931 (8) len=47
[Jun 5 13:34:44] VERBOSE[2210] logger.c: > Call Ref: len= 2 (reference 333/0x14D) (Originator)
[Jun 5 13:34:44] VERBOSE[2210] logger.c: > Message type: SETUP (5)
[Jun 5 13:34:44] VERBOSE[2210] logger.c: > [04 03 80 90 a2]
[Jun 5 13:34:44] VERBOSE[2210] logger.c: > Bearer Capability (len= 5) [ Ext: 1 Q.931 Std: 0 Info transfer capability: Speech (0)
[Jun 5 13:34:44] VERBOSE[2210] logger.c: > Ext: 1 Trans mode/rate: 64kbps, circuit-mode (16)
[Jun 5 13:34:44] VERBOSE[2210] logger.c: > User information layer 1: u-Law (34)
[Jun 5 13:34:44] VERBOSE[2210] logger.c: > [18 03 a9 83 81]
[Jun 5 13:34:44] VERBOSE[2210] logger.c: > Channel ID (len= 5) [ Ext: 1 IntID: Implicit PRI Spare: 0 Exclusive Dchan: 0
[Jun 5 13:34:44] VERBOSE[2210] logger.c: > ChanSel: As indicated in following octets
[Jun 5 13:34:44] VERBOSE[2210] logger.c: > Ext: 1 Coding: 0 Number Specified Channel Type: 3
[Jun 5 13:34:44] VERBOSE[2210] logger.c: > Ext: 1 Channel: 1 ]
[Jun 5 13:34:44] VERBOSE[2210] logger.c: > [1e 02 80 83]
[Jun 5 13:34:44] VERBOSE[2210] logger.c: > Progress Indicator (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) 0: 0 Location: User (0)
[Jun 5 13:34:44] VERBOSE[2210] logger.c: > Ext: 1 Progress Description: Calling equipment is non-ISDN. (3) ]
[Jun 5 13:34:44] VERBOSE[2210] logger.c: > [6c 0c 21 80 36 30 32 34 35 34 30 34 37 31]
[Jun 5 13:34:44] VERBOSE[2210] logger.c: > Calling Number (len=14) [ Ext: 0 TON: National Number (2) NPI: ISDN/Telephony Numbering Plan (E.164/E.163) (1)
[Jun 5 13:34:44] VERBOSE[2210] logger.c: > Presentation: Presentation permitted, user number not screened (0) ‘6024540471’ ]
[Jun 5 13:34:44] VERBOSE[2210] logger.c: > [70 0c a1 31 38 30 30 39 33 37 36 38 32 34]
[Jun 5 13:34:44] VERBOSE[2210] logger.c: > Called Number (len=14) [ Ext: 1 TON: National Number (2) NPI: ISDN/Telephony Numbering Plan (E.164/E.163) (1) ‘18009376824’ ]
[Jun 5 13:34:44] VERBOSE[2210] logger.c: q931.c:3128 q931_setup: call 33101 on channel 1 enters state 1 (Call Initiated)
[Jun 5 13:34:44] VERBOSE[2210] logger.c: – Called g0/18009376824
[Jun 5 13:34:44] VERBOSE[2210] logger.c: Audio is at 192.168.10.20 port 11690
[Jun 5 13:34:44] VERBOSE[2210] logger.c: Adding codec 0x4 (ulaw) to SDP
[Jun 5 13:34:44] VERBOSE[2210] logger.c: Adding codec 0x8 (alaw) to SDP
[Jun 5 13:34:44] VERBOSE[2210] logger.c: Adding non-codec 0x1 (telephone-event) to SDP
[Jun 5 13:34:44] VERBOSE[2210] logger.c:
<— Transmitting (NAT) to 192.168.10.139:5060 —>
SIP/2.0 183 Session Progress

Via: SIP/2.0/UDP 192.168.10.139;branch=z9hG4bK910f8e242FEA41FF;received=192.168.10.139

From: “Flores” sip:[email protected];tag=CE60922E-9020E389

To: sip:[email protected];user=phone;tag=as6ac11206

Call-ID: [email protected]

CSeq: 2 INVITE

User-Agent: Asterisk PBX

Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY

Supported: replaces

Contact: sip:[email protected]

Content-Type: application/sdp

Content-Length: 266

v=0

o=root 21701 21701 IN IP4 192.168.10.20

s=session

c=IN IP4 192.168.10.20

t=0 0

m=audio 11690 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=silenceSupp:off - - - -

a=ptime:20

a=sendrecv

<------------>
[Jun 5 13:34:45] VERBOSE[21711] logger.c: < Protocol Discriminator: Q.931 (8) len=10
[Jun 5 13:34:45] VERBOSE[21711] logger.c: < Call Ref: len= 2 (reference 333/0x14D) (Terminator)
[Jun 5 13:34:45] VERBOSE[21711] logger.c: < Message type: CALL PROCEEDING (2)
[Jun 5 13:34:45] VERBOSE[21711] logger.c: < [18 03 a9 83 81]
[Jun 5 13:34:45] VERBOSE[21711] logger.c: < Channel ID (len= 5) [ Ext: 1 IntID: Implicit PRI Spare: 0 Exclusive Dchan: 0
[Jun 5 13:34:45] VERBOSE[21711] logger.c: < ChanSel: As indicated in following octets
[Jun 5 13:34:45] VERBOSE[21711] logger.c: < Ext: 1 Coding: 0 Number Specified Channel Type: 3
[Jun 5 13:34:45] VERBOSE[21711] logger.c: < Ext: 1 Channel: 1 ]
[Jun 5 13:34:45] VERBOSE[21711] logger.c: – Processing IE 24 (cs0, Channel Identification)
[Jun 5 13:34:45] VERBOSE[21711] logger.c: q931.c:3677 q931_receive: call 33101 on channel 1 enters state 3 (Outgoing call Proceeding)
[Jun 5 13:34:45] DEBUG[21711] chan_zap.c: Queuing frame from PRI_EVENT_PROCEEDING on channel 0/1 span 1
[Jun 5 13:34:45] VERBOSE[2210] logger.c: – Zap/1-1 is proceeding passing it to SIP/114-096d7478
[Jun 5 13:34:45] VERBOSE[21711] logger.c: < Protocol Discriminator: Q.931 (8) len=13
[Jun 5 13:34:45] VERBOSE[21711] logger.c: < Call Ref: len= 2 (reference 333/0x14D) (Terminator)
[Jun 5 13:34:45] VERBOSE[21711] logger.c: < Message type: PROGRESS (3)
[Jun 5 13:34:45] VERBOSE[21711] logger.c: < [08 02 82 ff]
[Jun 5 13:34:45] VERBOSE[21711] logger.c: < Cause (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) Spare: 0 Location: Public network serving the local user (2)
[Jun 5 13:34:45] VERBOSE[21711] logger.c: < Ext: 1 Cause: Interworking, unspecified (127), class = Interworking (7) ]
[Jun 5 13:34:45] VERBOSE[21711] logger.c: < [1e 02 82 81]
[Jun 5 13:34:45] VERBOSE[21711] logger.c: < Progress Indicator (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) 0: 0 Location: Public network serving the local user (2)
[Jun 5 13:34:45] VERBOSE[21711] logger.c: < Ext: 1 Progress Description: Call is not end-to-end ISDN; further call progress information may be available inband. (1) ]
[Jun 5 13:34:45] VERBOSE[21711] logger.c: – Processing IE 8 (cs0, Cause)
[Jun 5 13:34:45] VERBOSE[21711] logger.c: – Processing IE 30 (cs0, Progress Indicator)
[Jun 5 13:34:45] VERBOSE[21711] logger.c: – PROGRESS with cause code 127 received
[Jun 5 13:34:45] DEBUG[21711] chan_zap.c: Queuing frame from PRI_EVENT_PROGRESS on channel 0/1 span 1
[Jun 5 13:34:45] VERBOSE[2210] logger.c: – Zap/1-1 is making progress passing it to SIP/114-096d7478
[Jun 5 13:34:48] DEBUG[21708] chan_sip.c: Adding subscription for mailbox notification - peer 108 Mailbox 108@default
[Jun 5 13:34:53] DEBUG[21708] chan_sip.c: Adding subscription for mailbox notification - peer 107 Mailbox 107@default
[Jun 5 13:34:54] DEBUG[21708] chan_sip.c: Adding subscription for mailbox notification - peer 116 Mailbox 116@device
[Jun 5 13:34:56] VERBOSE[21708] logger.c: Reliably Transmitting (NAT) to 192.168.10.139:5060:
OPTIONS sip:[email protected] SIP/2.0

Via: SIP/2.0/UDP 192.168.10.20:5060;branch=z9hG4bK39081262;rport

From: “Unknown” sip:[email protected];tag=as05bc4fa3

To: sip:[email protected]

Contact: sip:[email protected]

Call-ID: [email protected]

CSeq: 102 OPTIONS

User-Agent: Asterisk PBX

Max-Forwards: 70

Date: Fri, 05 Jun 2009 20:34:56 GMT

Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY

Supported: replaces

Content-Length: 0


[Jun 5 13:34:56] VERBOSE[21708] logger.c:
<— SIP read from 192.168.10.139:5060 —>
SIP/2.0 200 OK

Via: SIP/2.0/UDP 192.168.10.20:5060;branch=z9hG4bK39081262;rport

From: “Unknown” sip:[email protected];tag=as05bc4fa3

To: sip:[email protected];tag=D99B2DEB-316B6006

CSeq: 102 OPTIONS

Call-ID: [email protected]

Contact: sip:[email protected]

Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER

User-Agent: PolycomSoundPointIP-SPIP_430-UA/3.1.2.0392

Accept-Language: en

Accept: application/sdp,text/plain,message/sipfrag,application/dialog-info+xml

Accept-Encoding: identity

Supported: 100rel,timer,replaces

Content-Length: 0

<------------->
[Jun 5 13:34:56] VERBOSE[21708] logger.c: — (14 headers 0 lines) —
[Jun 5 13:34:56] VERBOSE[21708] logger.c: Really destroying SIP dialog ‘[email protected]’ Method: OPTIONS
[Jun 5 13:35:07] VERBOSE[2338] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [Jun 5 13:35:07] VERBOSE[2338] logger.c: Found
[Jun 5 13:35:07] VERBOSE[2338] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [Jun 5 13:35:07] VERBOSE[2338] logger.c: Found
[Jun 5 13:35:07] VERBOSE[2338] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [Jun 5 13:35:07] VERBOSE[2338] logger.c: Found
[Jun 5 13:35:07] VERBOSE[2338] logger.c: == Manager ‘phpagi’ logged on from 127.0.0.1
[Jun 5 13:35:07] VERBOSE[2338] logger.c: == Manager ‘phpagi’ logged off from 127.0.0.1
[Jun 5 13:35:08] VERBOSE[2377] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [Jun 5 13:35:08] VERBOSE[2377] logger.c: Found
[Jun 5 13:35:08] VERBOSE[2377] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [Jun 5 13:35:08] VERBOSE[2377] logger.c: Found
[Jun 5 13:35:08] VERBOSE[2377] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [Jun 5 13:35:08] VERBOSE[2377] logger.c: Found
[Jun 5 13:35:08] VERBOSE[2377] logger.c: == Manager ‘phpagi’ logged on from 127.0.0.1
[Jun 5 13:35:08] VERBOSE[2377] logger.c: == Manager ‘phpagi’ logged off from 127.0.0.1
[Jun 5 13:35:09] VERBOSE[2453] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [Jun 5 13:35:09] VERBOSE[2453] logger.c: Found
[Jun 5 13:35:09] VERBOSE[2453] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [Jun 5 13:35:09] VERBOSE[2453] logger.c: Found
[Jun 5 13:35:09] VERBOSE[2453] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [Jun 5 13:35:09] VERBOSE[2453] logger.c: Found
[Jun 5 13:35:09] VERBOSE[2453] logger.c: == Manager ‘phpagi’ logged on from 127.0.0.1
[Jun 5 13:35:09] VERBOSE[2453] logger.c: == Manager ‘phpagi’ logged off from 127.0.0.1
[Jun 5 13:35:09] DEBUG[21708] chan_sip.c: Adding subscription for mailbox notification - peer 109 Mailbox 109@default
[Jun 5 13:35:10] VERBOSE[2458] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [Jun 5 13:35:10] VERBOSE[2458] logger.c: Found
[Jun 5 13:35:10] VERBOSE[2458] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [Jun 5 13:35:10] VERBOSE[2458] logger.c: Found
[Jun 5 13:35:10] VERBOSE[2458] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [Jun 5 13:35:10] VERBOSE[2458] logger.c: Found
[Jun 5 13:35:10] VERBOSE[2458] logger.c: == Manager ‘phpagi’ logged on from 127.0.0.1
[Jun 5 13:35:10] VERBOSE[2458] logger.c: == Manager ‘phpagi’ logged off from 127.0.0.1
[Jun 5 13:35:10] VERBOSE[2460] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [Jun 5 13:35:10] VERBOSE[2460] logger.c: Found
[Jun 5 13:35:10] VERBOSE[2460] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [Jun 5 13:35:10] VERBOSE[2460] logger.c: Found
[Jun 5 13:35:10] VERBOSE[2460] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [Jun 5 13:35:10] VERBOSE[2460] logger.c: Found
[Jun 5 13:35:10] VERBOSE[2460] logger.c: == Manager ‘phpagi’ logged on from 127.0.0.1
[Jun 5 13:35:10] VERBOSE[2460] logger.c: == Manager ‘phpagi’ logged off from 127.0.0.1
[Jun 5 13:35:11] VERBOSE[2468] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [Jun 5 13:35:11] VERBOSE[2468] logger.c: Found
[Jun 5 13:35:11] VERBOSE[2468] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [Jun 5 13:35:11] VERBOSE[2468] logger.c: Found
[Jun 5 13:35:11] VERBOSE[2468] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [Jun 5 13:35:11] VERBOSE[2468] logger.c: Found
[Jun 5 13:35:11] VERBOSE[2468] logger.c: == Manager ‘phpagi’ logged on from 127.0.0.1
[Jun 5 13:35:11] VERBOSE[2468] logger.c: == Manager ‘phpagi’ logged off from 127.0.0.1
[Jun 5 13:35:11] VERBOSE[2477] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [Jun 5 13:35:11] VERBOSE[2477] logger.c: Found
[Jun 5 13:35:11] VERBOSE[2477] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [Jun 5 13:35:11] VERBOSE[2477] logger.c: Found
[Jun 5 13:35:11] VERBOSE[2477] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [Jun 5 13:35:11] VERBOSE[2477] logger.c: Found
[Jun 5 13:35:11] VERBOSE[2477] logger.c: == Manager ‘phpagi’ logged on from 127.0.0.1
[Jun 5 13:35:11] VERBOSE[2477] logger.c: == Manager ‘phpagi’ logged off from 127.0.0.1
[Jun 5 13:35:11] VERBOSE[2479] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [Jun 5 13:35:11] VERBOSE[2479] logger.c: Found
[Jun 5 13:35:11] VERBOSE[2479] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [Jun 5 13:35:11] VERBOSE[2479] logger.c: Found
[Jun 5 13:35:11] VERBOSE[2479] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [Jun 5 13:35:11] VERBOSE[2479] logger.c: Found
[Jun 5 13:35:11] VERBOSE[2479] logger.c: == Manager ‘phpagi’ logged on from 127.0.0.1
[Jun 5 13:35:11] VERBOSE[2479] logger.c: == Manager ‘phpagi’ logged off from 127.0.0.1
[Jun 5 13:35:11] VERBOSE[2481] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [Jun 5 13:35:11] VERBOSE[2481] logger.c: Found
[Jun 5 13:35:11] VERBOSE[2481] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [Jun 5 13:35:11] VERBOSE[2481] logger.c: Found
[Jun 5 13:35:11] VERBOSE[2481] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [Jun 5 13:35:11] VERBOSE[2481] logger.c: Found
[Jun 5 13:35:11] VERBOSE[2481] logger.c: == Manager ‘phpagi’ logged on from 127.0.0.1
[Jun 5 13:35:11] VERBOSE[2481] logger.c: == Manager ‘phpagi’ logged off from 127.0.0.1
[Jun 5 13:35:12] VERBOSE[2490] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [Jun 5 13:35:12] VERBOSE[2490] logger.c: Found
[Jun 5 13:35:12] VERBOSE[2490] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [Jun 5 13:35:12] VERBOSE[2490] logger.c: Found
[Jun 5 13:35:12] VERBOSE[2490] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [Jun 5 13:35:12] VERBOSE[2490] logger.c: Found
[Jun 5 13:35:12] VERBOSE[2490] logger.c: == Manager ‘phpagi’ logged on from 127.0.0.1
[Jun 5 13:35:12] VERBOSE[2490] logger.c: == Manager ‘phpagi’ logged off from 127.0.0.1
[Jun 5 13:35:13] VERBOSE[2515] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [Jun 5 13:35:13] VERBOSE[2515] logger.c: Found
[Jun 5 13:35:13] VERBOSE[2515] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [Jun 5 13:35:13] VERBOSE[2515] logger.c: Found
[Jun 5 13:35:13] VERBOSE[2515] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [Jun 5 13:35:13] VERBOSE[2515] logger.c: Found
[Jun 5 13:35:13] VERBOSE[2515] logger.c: == Manager ‘phpagi’ logged on from 127.0.0.1
[Jun 5 13:35:13] VERBOSE[2515] logger.c: == Manager ‘phpagi’ logged off from 127.0.0.1
[Jun 5 13:35:18] DEBUG[21708] chan_sip.c: Adding subscription for mailbox notification - peer 108 Mailbox 108@default
[Jun 5 13:35:23] DEBUG[21708] chan_sip.c: Adding subscription for mailbox notification - peer 107 Mailbox 107@default
[Jun 5 13:35:24] DEBUG[21708] chan_sip.c: Adding subscription for mailbox notification - peer 116 Mailbox 116@device
[Jun 5 13:35:39] DEBUG[21708] chan_sip.c: Adding subscription for mailbox notification - peer 109 Mailbox 109@default
[Jun 5 13:35:44] VERBOSE[21708] logger.c:
<— SIP read from 192.168.10.139:5060 —>
CANCEL sip:[email protected]:5060;user=phone SIP/2.0

Via: SIP/2.0/UDP 192.168.10.139;branch=z9hG4bK910f8e242FEA41FF

From: “Flores” sip:[email protected];tag=CE60922E-9020E389

To: sip:[email protected];user=phone

CSeq: 2 CANCEL

Call-ID: [email protected]

Contact: sip:[email protected]

User-Agent: PolycomSoundPointIP-SPIP_430-UA/3.1.2.0392

Proxy-Authorization: Digest username=“114”, realm=“asterisk”, nonce=“624c7fd5”, uri=“sip:[email protected]:5060;user=phone”, response=“d1356f443a1336db065fb0564160d9a0”, algorithm=MD5

Max-Forwards: 70

Content-Length: 0

<------------->
[Jun 5 13:35:44] VERBOSE[21708] logger.c: — (11 headers 0 lines) —
[Jun 5 13:35:44] VERBOSE[21708] logger.c: Sending to 192.168.10.139 : 5060 (NAT)
[Jun 5 13:35:44] VERBOSE[21708] logger.c:
<— Reliably Transmitting (NAT) to 192.168.10.139:5060 —>
SIP/2.0 487 Request Terminated

Via: SIP/2.0/UDP 192.168.10.139;branch=z9hG4bK910f8e242FEA41FF;received=192.168.10.139

From: “Flores” sip:[email protected];tag=CE60922E-9020E389

To: sip:[email protected];user=phone;tag=as6ac11206

Call-ID: [email protected]

CSeq: 2 INVITE

User-Agent: Asterisk PBX

Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY

Supported: replaces

Content-Length: 0

<------------>
[Jun 5 13:35:44] VERBOSE[21708] logger.c:
<— Transmitting (NAT) to 192.168.10.139:5060 —>
SIP/2.0 200 OK

Via: SIP/2.0/UDP 192.168.10.139;branch=z9hG4bK910f8e242FEA41FF;received=192.168.10.139

From: “Flores” sip:[email protected];tag=CE60922E-9020E389

To: sip:[email protected];user=phone;tag=as6ac11206

Call-ID: [email protected]

CSeq: 2 CANCEL

User-Agent: Asterisk PBX

Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY

Supported: replaces

Contact: sip:[email protected]

Content-Length: 0

<------------>
[Jun 5 13:35:44] DEBUG[2210] chan_zap.c: Set option AUDIO MODE, value: ON(1) on Zap/1-1
[Jun 5 13:35:44] DEBUG[2210] chan_zap.c: Not yet hungup… Calling hangup once with icause, and clearing call
[Jun 5 13:35:44] VERBOSE[2210] logger.c: NEW_HANGUP DEBUG: Calling q931_hangup, ourstate Outgoing call Proceeding, peerstate Incoming Call Proceeding
[Jun 5 13:35:44] VERBOSE[2210] logger.c: q931.c:3009 q931_disconnect: call 33101 on channel 1 enters state 11 (Disconnect Request)
[Jun 5 13:35:44] VERBOSE[2210] logger.c: > Protocol Discriminator: Q.931 (8) len=9
[Jun 5 13:35:44] VERBOSE[2210] logger.c: > Call Ref: len= 2 (reference 333/0x14D) (Originator)
[Jun 5 13:35:44] VERBOSE[2210] logger.c: > Message type: DISCONNECT (69)
[Jun 5 13:35:44] VERBOSE[2210] logger.c: > [08 02 81 90]
[Jun 5 13:35:44] VERBOSE[2210] logger.c: > Cause (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) Spare: 0 Location: Private network serving the local user (1)
[Jun 5 13:35:44] VERBOSE[2210] logger.c: > Ext: 1 Cause: Normal Clearing (16), class = Normal Event (1) ]
[Jun 5 13:35:44] DEBUG[2210] chan_zap.c: Set option AUDIO MODE, value: OFF(0) on Zap/1-1
[Jun 5 13:35:44] VERBOSE[2210] logger.c: – Hungup ‘Zap/1-1’
[Jun 5 13:35:44] VERBOSE[2210] logger.c: == Spawn extension (macro-dialout-trunk, s, 19) exited non-zero on ‘SIP/114-096d7478’ in macro ‘dialout-trunk’
[Jun 5 13:35:44] VERBOSE[2210] logger.c: == Spawn extension (macro-dialout-trunk, s, 19) exited non-zero on ‘SIP/114-096d7478’
[Jun 5 13:35:44] VERBOSE[2210] logger.c: – Executing [h@macro-dialout-trunk:1] Macro(“SIP/114-096d7478”, “hangupcall|”) in new stack
[Jun 5 13:35:44] VERBOSE[2210] logger.c: – Executing [s@macro-hangupcall:1] ResetCDR(“SIP/114-096d7478”, “vw”) in new stack
[Jun 5 13:35:44] DEBUG[2210] app_macro.c: Executed application: ResetCDR
[Jun 5 13:35:44] VERBOSE[2210] logger.c: – Executing [s@macro-hangupcall:2] NoCDR(“SIP/114-096d7478”, “”) in new stack
[Jun 5 13:35:44] DEBUG[2210] app_macro.c: Executed application: NoCDR
[Jun 5 13:35:44] VERBOSE[2210] logger.c: – Executing [s@macro-hangupcall:3] GotoIf(“SIP/114-096d7478”, “1?skiprg”) in new stack
[Jun 5 13:35:44] VERBOSE[2210] logger.c: – Goto (macro-hangupcall,s,6)
[Jun 5 13:35:44] DEBUG[2210] app_macro.c: Executed application: GotoIf
[Jun 5 13:35:44] VERBOSE[2210] logger.c: – Executing [s@macro-hangupcall:6] GotoIf(“SIP/114-096d7478”, “1?skipblkvm”) in new stack
[Jun 5 13:35:44] VERBOSE[2210] logger.c: – Goto (macro-hangupcall,s,9)
[Jun 5 13:35:44] DEBUG[2210] app_macro.c: Executed application: GotoIf
[Jun 5 13:35:44] VERBOSE[2210] logger.c: – Executing [s@macro-hangupcall:9] GotoIf(“SIP/114-096d7478”, “1?theend”) in new stack
[Jun 5 13:35:44] VERBOSE[2210] logger.c: – Goto (macro-hangupcall,s,11)
[Jun 5 13:35:44] DEBUG[2210] app_macro.c: Executed application: GotoIf
[Jun 5 13:35:44] VERBOSE[2210] logger.c: – Executing [s@macro-hangupcall:11] Hangup(“SIP/114-096d7478”, “”) in new stack
[Jun 5 13:35:44] VERBOSE[2210] logger.c: == Spawn extension (macro-hangupcall, s, 11) exited non-zero on ‘SIP/114-096d7478’ in macro ‘hangupcall’
[Jun 5 13:35:44] VERBOSE[2210] logger.c: == Spawn extension (macro-hangupcall, s, 11) exited non-zero on ‘SIP/114-096d7478’
[Jun 5 13:35:44] VERBOSE[21708] logger.c:
<— SIP read from 192.168.10.139:5060 —>
ACK sip:[email protected] SIP/2.0

Via: SIP/2.0/UDP 192.168.10.139;branch=z9hG4bK910f8e242FEA41FF

From: “Flores” sip:[email protected];tag=CE60922E-9020E389

To: sip:[email protected];user=phone;tag=as6ac11206

CSeq: 2 ACK

Call-ID: [email protected]

Contact: sip:[email protected]

Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER

User-Agent: PolycomSoundPointIP-SPIP_430-UA/3.1.2.0392

Accept-Language: en

Max-Forwards: 70

Content-Length: 0

<------------->
[Jun 5 13:35:44] VERBOSE[21708] logger.c: — (12 headers 0 lines) —
[Jun 5 13:35:44] VERBOSE[21708] logger.c: Really destroying SIP dialog ‘[email protected]’ Method: ACK
[Jun 5 13:35:44] VERBOSE[21711] logger.c: < Protocol Discriminator: Q.931 (8) len=5
[Jun 5 13:35:44] VERBOSE[21711] logger.c: < Call Ref: len= 2 (reference 333/0x14D) (Terminator)
[Jun 5 13:35:44] VERBOSE[21711] logger.c: < Message type: RELEASE (77)
[Jun 5 13:35:44] VERBOSE[21711] logger.c: q931.c:3795 q931_receive: call 33101 on channel 1 enters state 0 (Null)
[Jun 5 13:35:44] VERBOSE[21711] logger.c: NEW_HANGUP DEBUG: Calling q931_hangup, ourstate Null, peerstate Release Request
[Jun 5 13:35:44] VERBOSE[21711] logger.c: > Protocol Discriminator: Q.931 (8) len=9
[Jun 5 13:35:44] VERBOSE[21711] logger.c: > Call Ref: len= 2 (reference 333/0x14D) (Originator)
[Jun 5 13:35:44] VERBOSE[21711] logger.c: > Message type: RELEASE COMPLETE (90)
[Jun 5 13:35:44] VERBOSE[21711] logger.c: > [08 02 81 90]
[Jun 5 13:35:44] VERBOSE[21711] logger.c: > Cause (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) Spare: 0 Location: Private network serving the local user (1)
[Jun 5 13:35:44] VERBOSE[21711] logger.c: > Ext: 1 Cause: Normal Clearing (16), class = Normal Event (1) ]
[Jun 5 13:35:44] VERBOSE[21711] logger.c: NEW_HANGUP DEBUG: Calling q931_hangup, ourstate Null, peerstate Null
[Jun 5 13:35:44] VERBOSE[21711] logger.c: NEW_HANGUP DEBUG: Destroying the call, ourstate Null, peerstate Null
[Jun 5 13:35:48] DEBUG[21708] chan_sip.c: Adding subscription for mailbox notification - peer 108 Mailbox 108@default
[Jun 5 13:35:53] DEBUG[21708] chan_sip.c: Adding subscription for mailbox notification - peer 107 Mailbox 107@default
[Jun 5 13:35:54] DEBUG[21708] chan_sip.c: Adding subscription for mailbox notification - peer 116 Mailbox 116@device
[Jun 5 13:35:56] VERBOSE[21708] logger.c: Reliably Transmitting (NAT) to 192.168.10.139:5060:
OPTIONS sip:[email protected] SIP/2.0

Via: SIP/2.0/UDP 192.168.10.20:5060;branch=z9hG4bK1da1ec7a;rport

From: “Unknown” sip:[email protected];tag=as501023fe

To: sip:[email protected]

Contact: sip:[email protected]

Call-ID: [email protected]

CSeq: 102 OPTIONS

User-Agent: Asterisk PBX

Max-Forwards: 70

Date: Fri, 05 Jun 2009 20:35:56 GMT

Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY

Supported: replaces

Content-Length: 0


[Jun 5 13:35:56] VERBOSE[21708] logger.c:
<— SIP read from 192.168.10.139:5060 —>
SIP/2.0 200 OK

Via: SIP/2.0/UDP 192.168.10.20:5060;branch=z9hG4bK1da1ec7a;rport

From: “Unknown” sip:[email protected];tag=as501023fe

To: sip:[email protected];tag=9386A4F2-E08A854D

CSeq: 102 OPTIONS

Call-ID: [email protected]

Contact: sip:[email protected]

Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER

User-Agent: PolycomSoundPointIP-SPIP_430-UA/3.1.2.0392

Accept-Language: en

Accept: application/sdp,text/plain,message/sipfrag,application/dialog-info+xml

Accept-Encoding: identity

Supported: 100rel,timer,replaces

Content-Length: 0

<------------->
[Jun 5 13:35:56] VERBOSE[21708] logger.c: — (14 headers 0 lines) —
[Jun 5 13:35:56] VERBOSE[21708] logger.c: Really destroying SIP dialog ‘[email protected]’ Method: OPTIONS

---- end ----

Didn’t have time to scan but I think I can tell you exactly what is happening.

You are calling these 800 numbers through some sort of digital trunk. It may be a PRI, SIP or IAX trunk. When your reach the external IVR, it has not actually answered the call but starts interacting with you.

This is called early media and is often used by very large customer service centers like Airlines and similar. They will often do this in the ‘pre-routing’ phase of their IVR until you have answered a few questions and they can direct you to the proper queue.

The polycom phones have a setting that will cancel a call if not answered and their default setting is exactly 1 minute. I don’t recall what the setting is called, you will have to look it up. What is happening, from a SIP signaling perspective, is that the Polycom is passing the early media to you so you hear the IVR, however from a signaling perspective, the phone still thinks it is ringing and after the 1 minute default setting, it hangs up on you.

You need to change this default to a higher value, like maybe 5 minutes. You can confirm that your issue is with the early media by doing the following. Go into the General Settings tab. Put the option r in the Asterisk Outbound Dial command options box. And then submit and apply your configuration settings. (And hopefully when you do this it warns you that you SHOULD NOT add the r setting). Now make the call again, this time you should hear the phone ring and not hear the IVR. That is because Asterisk will send you ringing tones until the call is answered.

NOW - GO BACK AND CHANGE IT BACK by taking out the r because you do NOT want to leave that there, or your users will tell you they can’t ever reach these numbers…

After I tried everything, I realized that the Polycom phone was not “picking up” the call, because it was not showing the time meter in the screen. Then I pick up the phone and didn’t dial anything to see if there was a default idle timeout. There was. Then I dial my home phone, that has no VM so it will ring forever, so I tested and at exactly 1 minute it hang up by itself.
The light bulb broke! and I called Polycom.

They refused to check my log files, and they were going to troubleshot with the configuration files, so at the end I asked them if there where a way to disable timeout, and they gave me the following info:

call.ringBackTimeOut

“Time in seconds to allow an outgoing call to
remain in the ringback state before dropping the
call, 0=infinite.”

They say that is in A-64 in their admin guide. At that point I just tested it and it worked, so I didn’t care to look at their admin guide again.

I changed it and they are still looking at the issue thinking that is Polycom’s fault. I am going to close the ticket and give them your information. Thanks Philippe