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