TRUNK Dial failed due to CHANUNAVAIL

eijob

Joined
Jul 29, 2010
Messages
43
Likes
0
Points
0
#1
Hi Everyone,

I need help :)

I have two elastix 1.6-12 phone servers (USPBX and PHPBX) communicating thru IAX.
And intermittently calls are not passing thru the IAX trunk and gives me "TRUNK Dial failed due to CHANUNAVAIL (hangupcause: 0) - failing through to other trunks") in new stack

The configs from /etc/asterisk/iax_additional.conf in USPBX
[phpbx01]
disallow=all
username=phpbx01
type=peer
secret=AAA
qualify=yes
host=10.32.XX.XX
context=from-internal
trunk=no (I have tried this with 'yes' including the PHPBX trunk and still experiencing the issue)
allow=g729

[uspbx01]
disallow=all
type=user
secret=AAA
host=10.32.XX.XX
context=from-internal
allow=g729

iax_additional.conf in PHPBX
[phpbx01]
disallow=all
type=user
secret=AAA
host=10.2.XX.XX
context=from-internal
allow=g729

[uspbx01]
disallow=all
username=uspbx01
type=peer
secret=yellow47
qualify=yes
host=10.2.XX.XX
context=from-internal
trunk=no
allow=g729





-- Executing [s-CHANUNAVAIL@macro-dialout-trunk:3] NoOp("SIP/7038-b417d0d0", "TRUNK Dial failed due to CHANUNAVAIL (hangupcause: 0) - failing through to other trunks") in new stack

Below is a transcript from the CLI. I called from extension 7038 (USPBX) to 3224 (PHPBX)

-- Executing [3224@from-internal:1] Set("SIP/7038-b417d0d0", "INTRACOMPANYROUTE=YES") in new stack
-- Executing [3224@from-internal:2] Macro("SIP/7038-b417d0d0", "user-callerid|SKIPTTL|") in new stack
-- Executing [s@macro-user-callerid:1] Set("SIP/7038-b417d0d0", "AMPUSER=7038") in new stack
-- Executing [s@macro-user-callerid:2] GotoIf("SIP/7038-b417d0d0", "0?report") in new stack
-- Executing [s@macro-user-callerid:3] ExecIf("SIP/7038-b417d0d0", "1|Set|REALCALLERIDNUM=7038") in new stack
-- Executing [s@macro-user-callerid:4] Set("SIP/7038-b417d0d0", "AMPUSER=7038") in new stack
-- Executing [s@macro-user-callerid:5] Set("SIP/7038-b417d0d0", "AMPUSERCIDNAME=IT Test") in new stack
-- Executing [s@macro-user-callerid:6] GotoIf("SIP/7038-b417d0d0", "0?report") in new stack
-- Executing [s@macro-user-callerid:7] Set("SIP/7038-b417d0d0", "AMPUSERCID=7038") in new stack
-- Executing [s@macro-user-callerid:8] Set("SIP/7038-b417d0d0", "CALLERID(all)="IT Test" <7038>") in new stack
-- Executing [s@macro-user-callerid:9] ExecIf("SIP/7038-b417d0d0", "0|Set|CHANNEL(language)=") in new stack
-- Executing [s@macro-user-callerid:10] GotoIf("SIP/7038-b417d0d0", "1?continue") in new stack
-- Goto (macro-user-callerid,s,19)
-- Executing [s@macro-user-callerid:19] NoOp("SIP/7038-b417d0d0", "Using CallerID "IT Test" <7038>") in new stack
-- Executing [3224@from-internal:3] Set("SIP/7038-b417d0d0", "_NODEST=") in new stack
-- Executing [3224@from-internal:4] Macro("SIP/7038-b417d0d0", "record-enable|7038|OUT|") in new stack
-- Executing [s@macro-record-enable:1] GotoIf("SIP/7038-b417d0d0", "1?check") in new stack
-- Goto (macro-record-enable,s,4)
-- Executing [s@macro-record-enable:4] AGI("SIP/7038-b417d0d0", "recordingcheck|20110308-183511|1299638111.23323") in new stack
-- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
recordingcheck|20110308-183511|1299638111.23323: Outbound recording enabled.
recordingcheck|20110308-183511|1299638111.23323: CALLFILENAME=OUT7038-20110308-183511-1299638111.23323
-- AGI Script recordingcheck completed, returning 0
-- Executing [s@macro-record-enable:999] MixMonitor("SIP/7038-b417d0d0", "OUT7038-20110308-183511-1299638111.23323.gsm||") in new stack
== Begin MixMonitor Recording SIP/7038-b417d0d0
-- Executing [3224@from-internal:5] Macro("SIP/7038-b417d0d0", "dialout-trunk|2|3224||") in new stack
-- Executing [s@macro-dialout-trunk:1] Set("SIP/7038-b417d0d0", "DIAL_TRUNK=2") in new stack
-- Executing [s@macro-dialout-trunk:2] GosubIf("SIP/7038-b417d0d0", "0?sub-pincheck|s|1") in new stack
-- Executing [s@macro-dialout-trunk:3] GotoIf("SIP/7038-b417d0d0", "0?disabletrunk|1") in new stack
-- Executing [s@macro-dialout-trunk:4] Set("SIP/7038-b417d0d0", "DIAL_NUMBER=3224") in new stack
-- Executing [s@macro-dialout-trunk:5] Set("SIP/7038-b417d0d0", "DIAL_TRUNK_OPTIONS=tr") in new stack
-- Executing [s@macro-dialout-trunk:6] Set("SIP/7038-b417d0d0", "OUTBOUND_GROUP=OUT_2") in new stack
-- Executing [s@macro-dialout-trunk:7] GotoIf("SIP/7038-b417d0d0", "1?nomax") in new stack
-- Goto (macro-dialout-trunk,s,9)
-- Executing [s@macro-dialout-trunk:9] GotoIf("SIP/7038-b417d0d0", "1?skipoutcid") in new stack
-- Goto (macro-dialout-trunk,s,12)
-- Executing [s@macro-dialout-trunk:12] ExecIf("SIP/7038-b417d0d0", "0|AGI|fixlocalprefix") in new stack
-- Executing [s@macro-dialout-trunk:13] Set("SIP/7038-b417d0d0", "OUTNUM=3224") in new stack
-- Executing [s@macro-dialout-trunk:14] Set("SIP/7038-b417d0d0", "custom=IAX2/phpbx01") in new stack
-- Executing [s@macro-dialout-trunk:15] ExecIf("SIP/7038-b417d0d0", "0|Set|DIAL_TRUNK_OPTIONS=M(setmusic^)tr") in new stack
-- Executing [s@macro-dialout-trunk:16] Macro("SIP/7038-b417d0d0", "dialout-trunk-predial-hook|") in new stack
-- Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("SIP/7038-b417d0d0", "") in new stack
-- Executing [s@macro-dialout-trunk:17] GotoIf("SIP/7038-b417d0d0", "0?bypass|1") in new stack
-- Executing [s@macro-dialout-trunk:18] GotoIf("SIP/7038-b417d0d0", "0?customtrunk") in new stack
-- Executing [s@macro-dialout-trunk:19] Dial("SIP/7038-b417d0d0", "IAX2/phpbx01/3224|300|tr") in new stack
-- Called phpbx01/3224
== Parsing '/etc/asterisk/manager.conf': Found
== Parsing '/etc/asterisk/manager_additional.conf': Found
== Parsing '/etc/asterisk/manager_custom.conf': Found
== Manager 'admin' logged on from 127.0.0.1
== Manager 'admin' logged off from 127.0.0.1
== Parsing '/etc/asterisk/manager.conf': Found
== Parsing '/etc/asterisk/manager_additional.conf': Found
== Parsing '/etc/asterisk/manager_custom.conf': Found
== Manager 'admin' logged on from 127.0.0.1
== Manager 'admin' logged off from 127.0.0.1
== Parsing '/etc/asterisk/manager.conf': Found
== Parsing '/etc/asterisk/manager_additional.conf': Found
== Parsing '/etc/asterisk/manager_custom.conf': Found
== Manager 'admin' logged on from 127.0.0.1
== Manager 'admin' logged off from 127.0.0.1
-- Hungup 'IAX2/phpbx01-240'
== Everyone is busy/congested at this time (1:0/0/1)
-- Executing [s@macro-dialout-trunk:20] Goto("SIP/7038-b417d0d0", "s-CHANUNAVAIL|1") in new stack
-- Goto (macro-dialout-trunk,s-CHANUNAVAIL,1)
-- Executing [s-CHANUNAVAIL@macro-dialout-trunk:1] GotoIf("SIP/7038-b417d0d0", "1?noreport") in new stack
-- Goto (macro-dialout-trunk,s-CHANUNAVAIL,3)
-- Executing [s-CHANUNAVAIL@macro-dialout-trunk:3] NoOp("SIP/7038-b417d0d0", "TRUNK Dial failed due to CHANUNAVAIL (hangupcause: 0) - failing through to other trunks") in new stack
-- Executing [3224@from-internal:6] Macro("SIP/7038-b417d0d0", "outisbusy|") in new stack
-- Executing [s@macro-outisbusy:1] GotoIf("SIP/7038-b417d0d0", "0?emergency|1") in new stack
-- Executing [s@macro-outisbusy:2] GotoIf("SIP/7038-b417d0d0", "1?intracompany|1") in new stack
-- Goto (macro-outisbusy,intracompany,1)
-- Executing [intracompany@macro-outisbusy:1] Playback("SIP/7038-b417d0d0", "all-circuits-busy-now&pls-try-call-later| noanswer") in new stack
-- <SIP/7038-b417d0d0> Playing 'all-circuits-busy-now' (language 'en')
== Spawn extension (macro-outisbusy, intracompany, 1) exited non-zero on 'SIP/7038-b417d0d0' in macro 'outisbusy'
== Spawn extension (from-internal, 3224, 6) exited non-zero on 'SIP/7038-b417d0d0'
-- Executing [h@from-internal:1] Macro("SIP/7038-b417d0d0", "hangupcall") in new stack
-- Executing [s@macro-hangupcall:1] GotoIf("SIP/7038-b417d0d0", "1?skiprg") in new stack
-- Goto (macro-hangupcall,s,4)
-- Executing [s@macro-hangupcall:4] GotoIf("SIP/7038-b417d0d0", "1?skipblkvm") in new stack
-- Goto (macro-hangupcall,s,7)
-- Executing [s@macro-hangupcall:7] GotoIf("SIP/7038-b417d0d0", "1?theend") in new stack
-- Goto (macro-hangupcall,s,9)
-- Executing [s@macro-hangupcall:9] Hangup("SIP/7038-b417d0d0", "") in new stack
== Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/7038-b417d0d0' in macro 'hangupcall'
== Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/7038-b417d0d0'
== MixMonitor close filestream

Thanks
Eijob
 

dicko

Joined
Oct 24, 2008
Messages
4,099
Likes
0
Points
0
#2
please post the output of:

rasterisk -x 'show g729'

from each box, at the time the calls fail.
 

eijob

Joined
Jul 29, 2010
Messages
43
Likes
0
Points
0
#3
Hi Dicko,

uspbx01*CLI> g729 show version
Digium G.729A Module Version 1.4_3.1.5 (optimized for generic_64)

uspbx01*CLI> g729 show licenses
0/0 encoders/decoders of 64 licensed channels are currently in use


phpbx01*CLI> g729 show version
Digium G.729A Module Version 1.4_3.1.5 (optimized for generic_64)

phpbx01*CLI> g729 show licenses
0/0 encoders/decoders of 60 licensed channels are currently in use


This happens even though its the only call.

Thanks in advance
 

dicko

Joined
Oct 24, 2008
Messages
4,099
Likes
0
Points
0
#4
try adding g711 to your allowed codecs list. (ulaw or alaw as appropriate, maybe both) to reduce the possibility that the codecs are not negotiating successfully.

add

rasterisk -x 'iax2 show peers'

from each to make sure they can see each other. If still a problem

rasterisk -x 'iax2 set debug on'

and watch the issue of:

tailf /var/log/asterisk/full
 

eijob

Joined
Jul 29, 2010
Messages
43
Likes
0
Points
0
#5
Hi Dicko,


uspbx01*CLI> iax2 show peers
Name/Username Host Mask Port Status
phpbx01/phpbx01 10.32.1.24 (S) 255.255.255.255 4569 (T) OK (189 ms)
1 iax2 peers [1 online, 0 offline, 0 unmonitored]

phpbx01*CLI> iax2 show peers
Name/Username Host Mask Port Status
uspbx01/uspbx01 10.2.1.15 (S) 255.255.255.255 4569 (T) OK (183 ms)
1 iax2 peers [1 online, 0 offline, 0 unmonitored]

Do you think the g729 is the culprit? How can I fix the negotiation?

Here is the snip from /var/log/asterisk/full of the call above


[Mar 8 18:35:07] VERBOSE[15681] logger.c: == Manager 'admin' logged off from 127.0.0.1
[Mar 8 18:35:08] NOTICE[4826] chan_sip.c: Received SIP subscribe for peer without mailbox: (null)
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Executing [3224@from-internal:1] Set("SIP/7038-b417d0d0", "INTRACOMPANYROUTE=YES") in new stack
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Executing [3224@from-internal:2] Macro("SIP/7038-b417d0d0", "user-callerid|SKIPTTL|") in new stack
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Executing [s@macro-user-callerid:1] Set("SIP/7038-b417d0d0", "AMPUSER=7038") in new stack
[Mar 8 18:35:11] DEBUG[15689] app_macro.c: Executed application: Set
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Executing [s@macro-user-callerid:2] GotoIf("SIP/7038-b417d0d0", "0?report") in new stack
[Mar 8 18:35:11] DEBUG[15689] app_macro.c: Executed application: GotoIf
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Executing [s@macro-user-callerid:3] ExecIf("SIP/7038-b417d0d0", "1|Set|REALCALLERIDNUM=7038") in new stac
k
[Mar 8 18:35:11] DEBUG[15689] app_macro.c: Executed application: ExecIf
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Executing [s@macro-user-callerid:4] Set("SIP/7038-b417d0d0", "AMPUSER=7038") in new stack
[Mar 8 18:35:11] DEBUG[15689] app_macro.c: Executed application: Set
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Executing [s@macro-user-callerid:5] Set("SIP/7038-b417d0d0", "AMPUSERCIDNAME=IT Test") in new stack
[Mar 8 18:35:11] DEBUG[15689] app_macro.c: Executed application: Set
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Executing [s@macro-user-callerid:6] GotoIf("SIP/7038-b417d0d0", "0?report") in new stack
[Mar 8 18:35:11] DEBUG[15689] app_macro.c: Executed application: GotoIf
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Executing [s@macro-user-callerid:7] Set("SIP/7038-b417d0d0", "AMPUSERCID=7038") in new stack
[Mar 8 18:35:11] DEBUG[15689] app_macro.c: Executed application: Set
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Executing [s@macro-user-callerid:8] Set("SIP/7038-b417d0d0", "CALLERID(all)="IT Test" <7038>") in new sta
ck
[Mar 8 18:35:11] DEBUG[15689] app_macro.c: Executed application: Set
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Executing [s@macro-user-callerid:9] ExecIf("SIP/7038-b417d0d0", "0|Set|CHANNEL(language)=") in new stack
[Mar 8 18:35:11] DEBUG[15689] app_macro.c: Executed application: ExecIf
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Executing [s@macro-user-callerid:10] GotoIf("SIP/7038-b417d0d0", "1?continue") in new stack
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Goto (macro-user-callerid,s,19)
[Mar 8 18:35:11] DEBUG[15689] app_macro.c: Executed application: GotoIf
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Executing [s@macro-user-callerid:19] NoOp("SIP/7038-b417d0d0", "Using CallerID "IT Test" <7038>") in new
stack
[Mar 8 18:35:11] DEBUG[15689] app_macro.c: Executed application: Noop
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Executing [3224@from-internal:3] Set("SIP/7038-b417d0d0", "_NODEST=") in new stack
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Executing [3224@from-internal:4] Macro("SIP/7038-b417d0d0", "record-enable|7038|OUT|") in new stack
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Executing [s@macro-record-enable:1] GotoIf("SIP/7038-b417d0d0", "1?check") in new stack
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Goto (macro-record-enable,s,4)
[Mar 8 18:35:11] DEBUG[15689] app_macro.c: Executed application: GotoIf
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Executing [s@macro-record-enable:4] AGI("SIP/7038-b417d0d0", "recordingcheck|20110308-183511|1299638111.2
3323") in new stack
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
[Mar 8 18:35:11] VERBOSE[15689] logger.c: recordingcheck|20110308-183511|1299638111.23323: Outbound recording enabled.
[Mar 8 18:35:11] VERBOSE[15689] logger.c: recordingcheck|20110308-183511|1299638111.23323: CALLFILENAME=OUT7038-20110308-183511-1299638111.23323
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- AGI Script recordingcheck completed, returning 0
[Mar 8 18:35:11] DEBUG[15689] app_macro.c: Executed application: AGI
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Executing [s@macro-record-enable:999] MixMonitor("SIP/7038-b417d0d0", "OUT7038-20110308-183511-1299638111
.23323.gsm||") in new stack
[Mar 8 18:35:11] DEBUG[15689] app_macro.c: Executed application: MixMonitor
[Mar 8 18:35:11] VERBOSE[15691] logger.c: == Begin MixMonitor Recording SIP/7038-b417d0d0
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Executing [3224@from-internal:5] Macro("SIP/7038-b417d0d0", "dialout-trunk|2|3224||") in new stack
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Executing [s@macro-dialout-trunk:1] Set("SIP/7038-b417d0d0", "DIAL_TRUNK=2") in new stack
[Mar 8 18:35:11] DEBUG[15689] app_macro.c: Executed application: Set
[Mar 8 18:35:11] DEBUG[15689] func_db.c: DB: AMPUSER/7038/pinless not found in database.
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Executing [s@macro-dialout-trunk:2] GosubIf("SIP/7038-b417d0d0", "0?sub-pincheck|s|1") in new stack
[Mar 8 18:35:11] DEBUG[15689] app_macro.c: Executed application: GosubIf
[Mar 8 18:35:11] DEBUG[15689] func_db.c: DB: AMPUSER/7038/pinless not found in database.
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Executing [s@macro-dialout-trunk:3] GotoIf("SIP/7038-b417d0d0", "0?disabletrunk|1") in new stack
[Mar 8 18:35:11] DEBUG[15689] app_macro.c: Executed application: GotoIf
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Executing [s@macro-dialout-trunk:4] Set("SIP/7038-b417d0d0", "DIAL_NUMBER=3224") in new stack
[Mar 8 18:35:11] DEBUG[15689] app_macro.c: Executed application: Set
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Executing [s@macro-dialout-trunk:5] Set("SIP/7038-b417d0d0", "DIAL_TRUNK_OPTIONS=tr") in new stack
[Mar 8 18:35:11] DEBUG[15689] app_macro.c: Executed application: Set
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Executing [s@macro-dialout-trunk:6] Set("SIP/7038-b417d0d0", "OUTBOUND_GROUP=OUT_2") in new stack
[Mar 8 18:35:11] DEBUG[15689] app_macro.c: Executed application: Set
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Executing [s@macro-dialout-trunk:7] GotoIf("SIP/7038-b417d0d0", "1?nomax") in new stack
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Goto (macro-dialout-trunk,s,9)
[Mar 8 18:35:11] DEBUG[15689] app_macro.c: Executed application: GotoIf
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Executing [s@macro-dialout-trunk:9] GotoIf("SIP/7038-b417d0d0", "1?skipoutcid") in new stack
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Goto (macro-dialout-trunk,s,12)
[Mar 8 18:35:11] DEBUG[15689] app_macro.c: Executed application: GotoIf
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Executing [s@macro-dialout-trunk:12] ExecIf("SIP/7038-b417d0d0", "0|AGI|fixlocalprefix") in new stack
[Mar 8 18:35:11] DEBUG[15689] app_macro.c: Executed application: ExecIf
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Executing [s@macro-dialout-trunk:13] Set("SIP/7038-b417d0d0", "OUTNUM=3224") in new stack
[Mar 8 18:35:11] DEBUG[15689] app_macro.c: Executed application: Set
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Executing [s@macro-dialout-trunk:14] Set("SIP/7038-b417d0d0", "custom=IAX2/phpbx01") in new stack
[Mar 8 18:35:11] DEBUG[15689] app_macro.c: Executed application: Set
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Executing [s@macro-dialout-trunk:15] ExecIf("SIP/7038-b417d0d0", "0|Set|DIAL_TRUNK_OPTIONS=M(setmusic^)tr
") in new stack
[Mar 8 18:35:11] DEBUG[15689] app_macro.c: Executed application: ExecIf

[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Executing [s@macro-dialout-trunk:16] Macro("SIP/7038-b417d0d0", "dialout-trunk-predial-hook|") in new sta
ck
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("SIP/7038-b417d0d0", "") in new stack
[Mar 8 18:35:11] DEBUG[15689] app_macro.c: Executed application: Macro
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Executing [s@macro-dialout-trunk:17] GotoIf("SIP/7038-b417d0d0", "0?bypass|1") in new stack
[Mar 8 18:35:11] DEBUG[15689] app_macro.c: Executed application: GotoIf
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Executing [s@macro-dialout-trunk:18] GotoIf("SIP/7038-b417d0d0", "0?customtrunk") in new stack
[Mar 8 18:35:11] DEBUG[15689] app_macro.c: Executed application: GotoIf
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Executing [s@macro-dialout-trunk:19] Dial("SIP/7038-b417d0d0", "IAX2/phpbx01/3224|300|tr") in new stack
[Mar 8 18:35:11] NOTICE[15689] app_dial.c: Hey! chan SIP/7038-b417d0d0's context='macro-dialout-trunk', and exten='s'
[Mar 8 18:35:11] DEBUG[15689] chan_iax2.c: prepending 100 to prefs
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Called phpbx01/3224
[Mar 8 18:35:13] VERBOSE[15692] logger.c: == Parsing '/etc/asterisk/manager.conf': [Mar 8 18:35:13] VERBOSE[15692] logger.c: Found
[Mar 8 18:35:13] VERBOSE[15692] logger.c: == Parsing '/etc/asterisk/manager_additional.conf': [Mar 8 18:35:13] VERBOSE[15692] logger.c: Found
[Mar 8 18:35:13] VERBOSE[15692] logger.c: == Parsing '/etc/asterisk/manager_custom.conf': [Mar 8 18:35:13] VERBOSE[15692] logger.c: Found
[Mar 8 18:35:13] WARNING[15692] config.c: Unknown directive '#permit=192.168.1.0/255.255.255.0' at line 18 of /etc/asterisk/manager_custom.conf
[Mar 8 18:35:13] VERBOSE[15692] logger.c: == Manager 'admin' logged on from 127.0.0.1
[Mar 8 18:35:14] VERBOSE[15692] logger.c: == Manager 'admin' logged off from 127.0.0.1
[Mar 8 18:35:18] VERBOSE[15700] logger.c: == Parsing '/etc/asterisk/manager.conf': [Mar 8 18:35:18] VERBOSE[15700] logger.c: Found
[Mar 8 18:35:18] VERBOSE[15700] logger.c: == Parsing '/etc/asterisk/manager_additional.conf': [Mar 8 18:35:18] VERBOSE[15700] logger.c: Found
[Mar 8 18:35:18] VERBOSE[15700] logger.c: == Parsing '/etc/asterisk/manager_custom.conf': [Mar 8 18:35:18] VERBOSE[15700] logger.c: Found
[Mar 8 18:35:18] WARNING[15700] config.c: Unknown directive '#permit=192.168.1.0/255.255.255.0' at line 18 of /etc/asterisk/manager_custom.conf
[Mar 8 18:35:18] VERBOSE[15700] logger.c: == Manager 'admin' logged on from 127.0.0.1
[Mar 8 18:35:19] VERBOSE[15700] logger.c: == Manager 'admin' logged off from 127.0.0.1
[Mar 8 18:35:20] VERBOSE[15703] logger.c: == Parsing '/etc/asterisk/manager.conf': [Mar 8 18:35:20] VERBOSE[15703] logger.c: Found
[Mar 8 18:35:20] VERBOSE[15703] logger.c: == Parsing '/etc/asterisk/manager_additional.conf': [Mar 8 18:35:20] VERBOSE[15703] logger.c: Found
[Mar 8 18:35:20] VERBOSE[15703] logger.c: == Parsing '/etc/asterisk/manager_custom.conf': [Mar 8 18:35:20] VERBOSE[15703] logger.c: Found
[Mar 8 18:35:20] WARNING[15703] config.c: Unknown directive '#permit=192.168.1.0/255.255.255.0' at line 18 of /etc/asterisk/manager_custom.conf
[Mar 8 18:35:20] VERBOSE[15703] logger.c: == Manager 'admin' logged on from 127.0.0.1
[Mar 8 18:35:21] VERBOSE[15703] logger.c: == Manager 'admin' logged off from 127.0.0.1
[Mar 8 18:35:21] VERBOSE[15689] logger.c: -- Hungup 'IAX2/phpbx01-240'
[Mar 8 18:35:21] VERBOSE[15689] logger.c: == Everyone is busy/congested at this time (1:0/0/1)
[Mar 8 18:35:21] DEBUG[15689] app_macro.c: Executed application: Dial
[Mar 8 18:35:21] VERBOSE[15689] logger.c: -- Executing [s@macro-dialout-trunk:20] Goto("SIP/7038-b417d0d0", "s-CHANUNAVAIL|1") in new stack
[Mar 8 18:35:21] VERBOSE[15689] logger.c: -- Goto (macro-dialout-trunk,s-CHANUNAVAIL,1)
[Mar 8 18:35:21] DEBUG[15689] app_macro.c: Executed application: Goto
[Mar 8 18:35:21] VERBOSE[15689] logger.c: -- Executing [s-CHANUNAVAIL@macro-dialout-trunk:1] GotoIf("SIP/7038-b417d0d0", "1?noreport") in new stack
[Mar 8 18:35:21] VERBOSE[15689] logger.c: -- Goto (macro-dialout-trunk,s-CHANUNAVAIL,3)
[Mar 8 18:35:21] DEBUG[15689] app_macro.c: Executed application: GotoIf
[Mar 8 18:35:21] VERBOSE[15689] logger.c: -- Executing [s-CHANUNAVAIL@macro-dialout-trunk:3] NoOp("SIP/7038-b417d0d0", "TRUNK Dial failed due to CHANU
NAVAIL (hangupcause: 0) - failing through to other trunks") in new stack
[Mar 8 18:35:21] DEBUG[15689] app_macro.c: Executed application: Noop
[Mar 8 18:35:21] VERBOSE[15689] logger.c: -- Executing [3224@from-internal:6] Macro("SIP/7038-b417d0d0", "outisbusy|") in new stack
[Mar 8 18:35:21] VERBOSE[15689] logger.c: -- Executing [s@macro-outisbusy:1] GotoIf("SIP/7038-b417d0d0", "0?emergency|1") in new stack
[Mar 8 18:35:21] DEBUG[15689] app_macro.c: Executed application: GotoIf
[Mar 8 18:35:21] VERBOSE[15689] logger.c: -- Executing [s@macro-outisbusy:2] GotoIf("SIP/7038-b417d0d0", "1?intracompany|1") in new stack
[Mar 8 18:35:21] VERBOSE[15689] logger.c: -- Goto (macro-outisbusy,intracompany,1)
[Mar 8 18:35:21] DEBUG[15689] app_macro.c: Executed application: GotoIf
[Mar 8 18:35:21] VERBOSE[15689] logger.c: -- Executing [intracompany@macro-outisbusy:1] Playback("SIP/7038-b417d0d0", "all-circuits-busy-now&pls-try-c
all-later| noanswer") in new stack
[Mar 8 18:35:21] VERBOSE[15689] logger.c: -- <SIP/7038-b417d0d0> Playing 'all-circuits-busy-now' (language 'en')
[Mar 8 18:35:22] VERBOSE[15689] logger.c: == Spawn extension (macro-outisbusy, intracompany, 1) exited non-zero on 'SIP/7038-b417d0d0' in macro 'outisbu
sy'
[Mar 8 18:35:22] VERBOSE[15689] logger.c: == Spawn extension (from-internal, 3224, 6) exited non-zero on 'SIP/7038-b417d0d0'
[Mar 8 18:35:22] VERBOSE[15689] logger.c: -- Executing [h@from-internal:1] Macro("SIP/7038-b417d0d0", "hangupcall") in new stack
[Mar 8 18:35:22] VERBOSE[15689] logger.c: -- Executing [s@macro-hangupcall:1] GotoIf("SIP/7038-b417d0d0", "1?skiprg") in new stack
[Mar 8 18:35:22] VERBOSE[15689] logger.c: -- Goto (macro-hangupcall,s,4)
[Mar 8 18:35:22] DEBUG[15689] app_macro.c: Executed application: GotoIf
[Mar 8 18:35:22] VERBOSE[15689] logger.c: -- Executing [s@macro-hangupcall:4] GotoIf("SIP/7038-b417d0d0", "1?skipblkvm") in new stack
[Mar 8 18:35:22] VERBOSE[15689] logger.c: -- Goto (macro-hangupcall,s,7)
[Mar 8 18:35:22] DEBUG[15689] app_macro.c: Executed application: GotoIf
[Mar 8 18:35:22] VERBOSE[15689] logger.c: -- Executing [s@macro-hangupcall:7] GotoIf("SIP/7038-b417d0d0", "1?theend") in new stack
[Mar 8 18:35:22] VERBOSE[15689] logger.c: -- Goto (macro-hangupcall,s,9)
[Mar 8 18:35:22] DEBUG[15689] app_macro.c: Executed application: GotoIf
[Mar 8 18:35:22] VERBOSE[15689] logger.c: -- Executing [s@macro-hangupcall:9] Hangup("SIP/7038-b417d0d0", "") in new stack
[Mar 8 18:35:22] VERBOSE[15689] logger.c: == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/7038-b417d0d0' in macro 'hangupcall'
[Mar 8 18:35:22] VERBOSE[15689] logger.c: == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/7038-b417d0d0'
[Mar 8 18:35:22] VERBOSE[15691] logger.c: == MixMonitor close filestream
[Mar 8 18:35:22] VERBOSE[15691] logger.c: == End MixMonitor Recording SIP/7038-b417d0d0
 

dicko

Joined
Oct 24, 2008
Messages
4,099
Likes
0
Points
0
#6
I doubt that g729 is the problem, did you try g711 as a fall back? I don't really know why the trunk is failing as you say it is an intermittent problem. Hence to IAX2 debug, if you updated Asterisk you might need to do the calltoken security update, you seem to have a well built network so allow 10.0.0.0/8 not as often suggested 0.0.0.0/0
 

eijob

Joined
Jul 29, 2010
Messages
43
Likes
0
Points
0
#7
This afternoon we did add the allow=g729&ulaw on both servers, and we still saw it doing the congestion.

Do you think doing a yum update is a good idea? or can you suggest a better way to do it?

Thanks so much for your help on this.
 

dicko

Joined
Oct 24, 2008
Messages
4,099
Likes
0
Points
0
#8
Did it work before?, if it did, I suggest you carefully explore any changes you made after that was the case. The IAX2 debugging will surely expose the problem,
 

eijob

Joined
Jul 29, 2010
Messages
43
Likes
0
Points
0
#9
Yes the PBX is working and there are time the congestions happen

Sometimes when we are running on a lot of simultaneous channels and the one I posted a while ago, that was the only call using the server.
 

dicko

Joined
Oct 24, 2008
Messages
4,099
Likes
0
Points
0
#10
Everything seems normal but the extension phpbx01/3224 reported busy, try calling an endpoint that can't be perhaps ? you also need to look at the phpbx01 log at 18:35 or so (or whatever time it is in PH :) ) to see what it has to say in those 10 seconds.

.
.
[Mar 8 18:35:11] VERBOSE[15689] logger.c: -- Called phpbx01/3224
[Mar 8 18:35:13] VERBOSE[15692] logger.c: == Parsing '/etc/asterisk/manager.conf': [Mar 8 18:35:13] VERBOSE[15692] logger.c: Found
[Mar 8 18:35:13] VERBOSE[15692] logger.c: == Parsing '/etc/asterisk/manager_additional.conf': [Mar 8 18:35:13] VERBOSE[15692] logger.c: Found
[Mar 8 18:35:13] VERBOSE[15692] logger.c: == Parsing '/etc/asterisk/manager_custom.conf': [Mar 8 18:35:13] VERBOSE[15692] logger.c: Found
[Mar 8 18:35:13] WARNING[15692] config.c: Unknown directive '#permit=192.168.1.0/255.255.255.0' at line 18 of /etc/asterisk/manager_custom.conf
[Mar 8 18:35:13] VERBOSE[15692] logger.c: == Manager 'admin' logged on from 127.0.0.1
[Mar 8 18:35:14] VERBOSE[15692] logger.c: == Manager 'admin' logged off from 127.0.0.1
[Mar 8 18:35:18] VERBOSE[15700] logger.c: == Parsing '/etc/asterisk/manager.conf': [Mar 8 18:35:18] VERBOSE[15700] logger.c: Found
[Mar 8 18:35:18] VERBOSE[15700] logger.c: == Parsing '/etc/asterisk/manager_additional.conf': [Mar 8 18:35:18] VERBOSE[15700] logger.c: Found
[Mar 8 18:35:18] VERBOSE[15700] logger.c: == Parsing '/etc/asterisk/manager_custom.conf': [Mar 8 18:35:18] VERBOSE[15700] logger.c: Found
[Mar 8 18:35:18] WARNING[15700] config.c: Unknown directive '#permit=192.168.1.0/255.255.255.0' at line 18 of /etc/asterisk/manager_custom.conf
[Mar 8 18:35:18] VERBOSE[15700] logger.c: == Manager 'admin' logged on from 127.0.0.1
[Mar 8 18:35:19] VERBOSE[15700] logger.c: == Manager 'admin' logged off from 127.0.0.1
[Mar 8 18:35:20] VERBOSE[15703] logger.c: == Parsing '/etc/asterisk/manager.conf': [Mar 8 18:35:20] VERBOSE[15703] logger.c: Found
[Mar 8 18:35:20] VERBOSE[15703] logger.c: == Parsing '/etc/asterisk/manager_additional.conf': [Mar 8 18:35:20] VERBOSE[15703] logger.c: Found
[Mar 8 18:35:20] VERBOSE[15703] logger.c: == Parsing '/etc/asterisk/manager_custom.conf': [Mar 8 18:35:20] VERBOSE[15703] logger.c: Found
[Mar 8 18:35:20] WARNING[15703] config.c: Unknown directive '#permit=192.168.1.0/255.255.255.0' at line 18 of /etc/asterisk/manager_custom.conf
[Mar 8 18:35:20] VERBOSE[15703] logger.c: == Manager 'admin' logged on from 127.0.0.1
[Mar 8 18:35:21] VERBOSE[15703] logger.c: == Manager 'admin' logged off from 127.0.0.1
[Mar 8 18:35:21] VERBOSE[15689] logger.c: -- Hungup 'IAX2/phpbx01-240'
[Mar 8 18:35:21] VERBOSE[15689] logger.c: == Everyone is busy/congested at this time (1:0/0/1)
.
.
.

(you should filter the call leg for clarity with in this case:

grep 15689 /var/log/asterisk/full

to save my eyesight next time :) )


p.s.
If your servers are "across time zones" then maybe edit /etc/asterisk/logger.conf with regard to:


http://www.voip-info.org/wiki/index.php ... ogger.conf

with specific regard to strftime %+ and TZ (use UST ? )usage, if you get that right you can blend both end's logs and sort numerically by time to get a more synchronous view of WTF is happening.
 

eijob

Joined
Jul 29, 2010
Messages
43
Likes
0
Points
0
#11
Hi Dicko,

I followed your advice this is from a grep export. :)

I see this in the USPBX /var/log/full it happened again. and I dont see a trace of that call in PHPBX.
I wonder right after called is hungup already.

Any ideas?

Thanks

[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Called phpbx01/3279
[Mar 8 20:53:25] VERBOSE[4768] logger.c: -- Hungup 'IAX2/phpbx01-16384'


Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Executing [3279@from-internal:1] Set("SIP/7039-b8146ae0", "INTRACOMPANYROUTE=YES") in new stack
[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Executing [3279@from-internal:2] Macro("SIP/7039-b8146ae0", "user-callerid|SKIPTTL|") in new stack
[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Executing [s@macro-user-callerid:1] Set("SIP/7039-b8146ae0", "AMPUSER=7039") in new stack
[Mar 8 20:53:15] DEBUG[4768] app_macro.c: Executed application: Set
[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Executing [s@macro-user-callerid:2] GotoIf("SIP/7039-b8146ae0", "0?report") in new stack
[Mar 8 20:53:15] DEBUG[4768] app_macro.c: Executed application: GotoIf
[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Executing [s@macro-user-callerid:3] ExecIf("SIP/7039-b8146ae0", "1|Set|REALCALLERIDNUM=7039") in new stack
[Mar 8 20:53:15] DEBUG[4768] app_macro.c: Executed application: ExecIf
[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Executing [s@macro-user-callerid:4] Set("SIP/7039-b8146ae0", "AMPUSER=7039") in new stack
[Mar 8 20:53:15] DEBUG[4768] app_macro.c: Executed application: Set
[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Executing [s@macro-user-callerid:5] Set("SIP/7039-b8146ae0", "AMPUSERCIDNAME=7039") in new stack
[Mar 8 20:53:15] DEBUG[4768] app_macro.c: Executed application: Set
[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Executing [s@macro-user-callerid:6] GotoIf("SIP/7039-b8146ae0", "0?report") in new stack
[Mar 8 20:53:15] DEBUG[4768] app_macro.c: Executed application: GotoIf
[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Executing [s@macro-user-callerid:7] Set("SIP/7039-b8146ae0", "AMPUSERCID=7039") in new stack
[Mar 8 20:53:15] DEBUG[4768] app_macro.c: Executed application: Set
[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Executing [s@macro-user-callerid:8] Set("SIP/7039-b8146ae0", "CALLERID(all)="7039" <7039>") in new stack
[Mar 8 20:53:15] DEBUG[4768] app_macro.c: Executed application: Set
[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Executing [s@macro-user-callerid:9] ExecIf("SIP/7039-b8146ae0", "0|Set|CHANNEL(language)=") in new stack
[Mar 8 20:53:15] DEBUG[4768] app_macro.c: Executed application: ExecIf
[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Executing [s@macro-user-callerid:10] GotoIf("SIP/7039-b8146ae0", "1?continue") in new stack
[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Goto (macro-user-callerid,s,19)
[Mar 8 20:53:15] DEBUG[4768] app_macro.c: Executed application: GotoIf
[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Executing [s@macro-user-callerid:19] NoOp("SIP/7039-b8146ae0", "Using CallerID "7039" <7039>") in new stack
[Mar 8 20:53:15] DEBUG[4768] app_macro.c: Executed application: Noop
[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Executing [3279@from-internal:3] Set("SIP/7039-b8146ae0", "_NODEST=") in new stack
[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Executing [3279@from-internal:4] Macro("SIP/7039-b8146ae0", "record-enable|7039|OUT|") in new stack
[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Executing [s@macro-record-enable:1] GotoIf("SIP/7039-b8146ae0", "1?check") in new stack
[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Goto (macro-record-enable,s,4)
[Mar 8 20:53:15] DEBUG[4768] app_macro.c: Executed application: GotoIf
[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Executing [s@macro-record-enable:4] AGI("SIP/7039-b8146ae0", "recordingcheck|20110308-205315|1299646395.97") in new stack
[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
[Mar 8 20:53:15] VERBOSE[4768] logger.c: recordingcheck|20110308-205315|1299646395.97: Outbound recording not enabled
[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- AGI Script recordingcheck completed, returning 0
[Mar 8 20:53:15] DEBUG[4768] app_macro.c: Executed application: AGI
[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Executing [s@macro-record-enable:5] MacroExit("SIP/7039-b8146ae0", "") in new stack
[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Executing [3279@from-internal:5] Macro("SIP/7039-b8146ae0", "dialout-trunk|2|3279||") in new stack
[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Executing [s@macro-dialout-trunk:1] Set("SIP/7039-b8146ae0", "DIAL_TRUNK=2") in new stack
[Mar 8 20:53:15] DEBUG[4768] app_macro.c: Executed application: Set
[Mar 8 20:53:15] DEBUG[4768] func_db.c: DB: AMPUSER/7039/pinless not found in database.
[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Executing [s@macro-dialout-trunk:2] GosubIf("SIP/7039-b8146ae0", "0?sub-pincheck|s|1") in new stack
[Mar 8 20:53:15] DEBUG[4768] app_macro.c: Executed application: GosubIf
[Mar 8 20:53:15] DEBUG[4768] func_db.c: DB: AMPUSER/7039/pinless not found in database.
[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Executing [s@macro-dialout-trunk:3] GotoIf("SIP/7039-b8146ae0", "0?disabletrunk|1") in new stack
[Mar 8 20:53:15] DEBUG[4768] app_macro.c: Executed application: GotoIf
[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Executing [s@macro-dialout-trunk:4] Set("SIP/7039-b8146ae0", "DIAL_NUMBER=3279") in new stack
[Mar 8 20:53:15] DEBUG[4768] app_macro.c: Executed application: Set
[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Executing [s@macro-dialout-trunk:5] Set("SIP/7039-b8146ae0", "DIAL_TRUNK_OPTIONS=tr") in new stack
[Mar 8 20:53:15] DEBUG[4768] app_macro.c: Executed application: Set
[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Executing [s@macro-dialout-trunk:6] Set("SIP/7039-b8146ae0", "OUTBOUND_GROUP=OUT_2") in new stack
[Mar 8 20:53:15] DEBUG[4768] app_macro.c: Executed application: Set
[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Executing [s@macro-dialout-trunk:7] GotoIf("SIP/7039-b8146ae0", "1?nomax") in new stack
[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Goto (macro-dialout-trunk,s,9)
[Mar 8 20:53:15] DEBUG[4768] app_macro.c: Executed application: GotoIf
[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Executing [s@macro-dialout-trunk:9] GotoIf("SIP/7039-b8146ae0", "1?skipoutcid") in new stack
[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Goto (macro-dialout-trunk,s,12)
[Mar 8 20:53:15] DEBUG[4768] app_macro.c: Executed application: GotoIf
[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Executing [s@macro-dialout-trunk:12] ExecIf("SIP/7039-b8146ae0", "0|AGI|fixlocalprefix") in new stack
[Mar 8 20:53:15] DEBUG[4768] app_macro.c: Executed application: ExecIf
[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Executing [s@macro-dialout-trunk:13] Set("SIP/7039-b8146ae0", "OUTNUM=3279") in new stack
[Mar 8 20:53:15] DEBUG[4768] app_macro.c: Executed application: Set
[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Executing [s@macro-dialout-trunk:14] Set("SIP/7039-b8146ae0", "custom=IAX2/phpbx01") in new stack
[Mar 8 20:53:15] DEBUG[4768] app_macro.c: Executed application: Set
[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Executing [s@macro-dialout-trunk:15] ExecIf("SIP/7039-b8146ae0", "0|Set|DIAL_TRUNK_OPTIONS=M(setmusic^)tr") in new stack
[Mar 8 20:53:15] DEBUG[4768] app_macro.c: Executed application: ExecIf
[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Executing [s@macro-dialout-trunk:16] Macro("SIP/7039-b8146ae0", "dialout-trunk-predial-hook|") in new stack
[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("SIP/7039-b8146ae0", "") in new stack
[Mar 8 20:53:15] DEBUG[4768] app_macro.c: Executed application: Macro
[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Executing [s@macro-dialout-trunk:17] GotoIf("SIP/7039-b8146ae0", "0?bypass|1") in new stack
[Mar 8 20:53:15] DEBUG[4768] app_macro.c: Executed application: GotoIf
[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Executing [s@macro-dialout-trunk:18] GotoIf("SIP/7039-b8146ae0", "0?customtrunk") in new stack
[Mar 8 20:53:15] DEBUG[4768] app_macro.c: Executed application: GotoIf
[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Executing [s@macro-dialout-trunk:19] Dial("SIP/7039-b8146ae0", "IAX2/phpbx01/3279|300|tr") in new stack
[Mar 8 20:53:15] NOTICE[4768] app_dial.c: Hey! chan SIP/7039-b8146ae0's context='macro-dialout-trunk', and exten='s'
[Mar 8 20:53:15] DEBUG[4768] chan_iax2.c: prepending 100 to prefs
[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Called phpbx01/3279
[Mar 8 20:53:25] VERBOSE[4768] logger.c: -- Hungup 'IAX2/phpbx01-16384'
[Mar 8 20:53:25] VERBOSE[4768] logger.c: == Everyone is busy/congested at this time (1:0/0/1)
[Mar 8 20:53:25] DEBUG[4768] app_macro.c: Executed application: Dial
[Mar 8 20:53:25] VERBOSE[4768] logger.c: -- Executing [s@macro-dialout-trunk:20] Goto("SIP/7039-b8146ae0", "s-CHANUNAVAIL|1") in new stack
[Mar 8 20:53:25] VERBOSE[4768] logger.c: -- Goto (macro-dialout-trunk,s-CHANUNAVAIL,1)
[Mar 8 20:53:25] DEBUG[4768] app_macro.c: Executed application: Goto
[Mar 8 20:53:25] VERBOSE[4768] logger.c: -- Executing [s-CHANUNAVAIL@macro-dialout-trunk:1] GotoIf("SIP/7039-b8146ae0", "1?noreport") in new stack
[Mar 8 20:53:25] VERBOSE[4768] logger.c: -- Goto (macro-dialout-trunk,s-CHANUNAVAIL,3)
[Mar 8 20:53:25] DEBUG[4768] app_macro.c: Executed application: GotoIf
[Mar 8 20:53:25] VERBOSE[4768] logger.c: -- Executing [s-CHANUNAVAIL@macro-dialout-trunk:3] NoOp("SIP/7039-b8146ae0", "TRUNK Dial failed due to CHANUNAVAIL (hangupcause: 0) - failing through to other trunks") in new stack
[Mar 8 20:53:25] DEBUG[4768] app_macro.c: Executed application: Noop
[Mar 8 20:53:25] VERBOSE[4768] logger.c: -- Executing [3279@from-internal:6] Macro("SIP/7039-b8146ae0", "outisbusy|") in new stack
[Mar 8 20:53:25] VERBOSE[4768] logger.c: -- Executing [s@macro-outisbusy:1] GotoIf("SIP/7039-b8146ae0", "0?emergency|1") in new stack
[Mar 8 20:53:25] DEBUG[4768] app_macro.c: Executed application: GotoIf
[Mar 8 20:53:25] VERBOSE[4768] logger.c: -- Executing [s@macro-outisbusy:2] GotoIf("SIP/7039-b8146ae0", "1?intracompany|1") in new stack
[Mar 8 20:53:25] VERBOSE[4768] logger.c: -- Goto (macro-outisbusy,intracompany,1)
[Mar 8 20:53:25] DEBUG[4768] app_macro.c: Executed application: GotoIf
[Mar 8 20:53:25] VERBOSE[4768] logger.c: -- Executing [intracompany@macro-outisbusy:1] Playback("SIP/7039-b8146ae0", "all-circuits-busy-now&pls-try-call-later| noanswer") in new stack
[Mar 8 20:53:25] VERBOSE[4768] logger.c: -- <SIP/7039-b8146ae0> Playing 'all-circuits-busy-now' (language 'en')
[Mar 8 20:53:27] VERBOSE[4768] logger.c: -- <SIP/7039-b8146ae0> Playing 'pls-try-call-later' (language 'en')
[Mar 8 20:53:27] VERBOSE[4768] logger.c: == Spawn extension (macro-outisbusy, intracompany, 1) exited non-zero on 'SIP/7039-b8146ae0' in macro 'outisbusy'
[Mar 8 20:53:27] VERBOSE[4768] logger.c: == Spawn extension (from-internal, 3279, 6) exited non-zero on 'SIP/7039-b8146ae0'
[Mar 8 20:53:27] VERBOSE[4768] logger.c: -- Executing [h@from-internal:1] Macro("SIP/7039-b8146ae0", "hangupcall") in new stack
[Mar 8 20:53:27] VERBOSE[4768] logger.c: -- Executing [s@macro-hangupcall:1] GotoIf("SIP/7039-b8146ae0", "1?skiprg") in new stack
[Mar 8 20:53:27] VERBOSE[4768] logger.c: -- Goto (macro-hangupcall,s,4)
[Mar 8 20:53:27] DEBUG[4768] app_macro.c: Executed application: GotoIf
[Mar 8 20:53:27] VERBOSE[4768] logger.c: -- Executing [s@macro-hangupcall:4] GotoIf("SIP/7039-b8146ae0", "1?skipblkvm") in new stack
[Mar 8 20:53:27] VERBOSE[4768] logger.c: -- Goto (macro-hangupcall,s,7)
[Mar 8 20:53:27] DEBUG[4768] app_macro.c: Executed application: GotoIf
[Mar 8 20:53:27] VERBOSE[4768] logger.c: -- Executing [s@macro-hangupcall:7] GotoIf("SIP/7039-b8146ae0", "1?theend") in new stack
[Mar 8 20:53:27] VERBOSE[4768] logger.c: -- Goto (macro-hangupcall,s,9)
[Mar 8 20:53:27] DEBUG[4768] app_macro.c: Executed application: GotoIf
[Mar 8 20:53:27] VERBOSE[4768] logger.c: -- Executing [s@macro-hangupcall:9] Hangup("SIP/7039-b8146ae0", "") in new stack
[Mar 8 20:53:27] VERBOSE[4768] logger.c: == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/7039-b8146ae0' in macro 'hangupcall'
[Mar 8 20:53:27] VERBOSE[4768] logger.c: == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/7039-b8146ae0'
 

dicko

Joined
Oct 24, 2008
Messages
4,099
Likes
0
Points
0
#12
.
.

[Mar 8 20:53:15] VERBOSE[4768] logger.c: -- Called phpbx01/3279
[Mar 8 20:53:25] VERBOSE[4768] logger.c: -- Hungup 'IAX2/phpbx01-16384'
.
.
the exact part of asterik/full on the far end between those times ?

Did you ever try the IAX2 debug thingy (on both ends) ?

p.s.

rasterisk -x 'core set verbose <n>'
rasterisk -x 'core set debug <n>'
 

eijob

Joined
Jul 29, 2010
Messages
43
Likes
0
Points
0
#13
yup, i got this log from /var/log/asterisk/full and I did not see the call in PHPBX01. which is really weird.

Im testing our numbers now. and will paste if i see something odd on the log again. or if it fails again.

Thanks for your help
 

eijob

Joined
Jul 29, 2010
Messages
43
Likes
0
Points
0
#14
Hi Dicko,

It happened again in USPBX, i was calling the number from my cellphone, the call should have went to USPBX01 then PHPBX01 for the extension. Here is the log from /var/log/asterisk/full. This time I did not see anything from /var/log/asterisk/full of PHPBX

And at the bottom is from a PHPBX extension calling me to my mobile

Thanks


[Mar 8 23:18:38] VERBOSE[4696] logger.c: -- Executing [2356@from-internal:1] Set("SIP/Wiline-b02151d0", "INTRACOMPANYROUTE=YES") in new stack
[Mar 8 23:18:38] VERBOSE[4696] logger.c: -- Executing [2356@from-internal:2] Macro("SIP/Wiline-b02151d0", "user-callerid|SKIPTTL|") in new stack
[Mar 8 23:18:38] VERBOSE[4696] logger.c: -- Executing [s@macro-user-callerid:1] Set("SIP/Wiline-b02151d0", "AMPUSER=6502748970") in new stack
[Mar 8 23:18:38] DEBUG[4696] app_macro.c: Executed application: Set
[Mar 8 23:18:38] VERBOSE[4696] logger.c: -- Executing [s@macro-user-callerid:2] GotoIf("SIP/Wiline-b02151d0", "0?report") in new stack
[Mar 8 23:18:38] DEBUG[4696] app_macro.c: Executed application: GotoIf
[Mar 8 23:18:38] VERBOSE[4696] logger.c: -- Executing [s@macro-user-callerid:3] ExecIf("SIP/Wiline-b02151d0", "1|Set|REALCALLERIDNUM=6502748970") in new stack
[Mar 8 23:18:38] DEBUG[4696] app_macro.c: Executed application: ExecIf
[Mar 8 23:18:38] DEBUG[4696] func_db.c: DB: DEVICE/6502748970/user not found in database.
[Mar 8 23:18:38] VERBOSE[4696] logger.c: -- Executing [s@macro-user-callerid:4] Set("SIP/Wiline-b02151d0", "AMPUSER=") in new stack
[Mar 8 23:18:38] DEBUG[4696] app_macro.c: Executed application: Set
[Mar 8 23:18:38] DEBUG[4696] func_db.c: DB: AMPUSER//cidname not found in database.
[Mar 8 23:18:38] VERBOSE[4696] logger.c: -- Executing [s@macro-user-callerid:5] Set("SIP/Wiline-b02151d0", "AMPUSERCIDNAME=") in new stack
[Mar 8 23:18:38] DEBUG[4696] app_macro.c: Executed application: Set
[Mar 8 23:18:38] VERBOSE[4696] logger.c: -- Executing [s@macro-user-callerid:6] GotoIf("SIP/Wiline-b02151d0", "1?report") in new stack
[Mar 8 23:18:38] VERBOSE[4696] logger.c: -- Goto (macro-user-callerid,s,10)
[Mar 8 23:18:38] DEBUG[4696] app_macro.c: Executed application: GotoIf
[Mar 8 23:18:38] VERBOSE[4696] logger.c: -- Executing [s@macro-user-callerid:10] GotoIf("SIP/Wiline-b02151d0", "1?continue") in new stack
[Mar 8 23:18:38] VERBOSE[4696] logger.c: -- Goto (macro-user-callerid,s,19)
[Mar 8 23:18:38] DEBUG[4696] app_macro.c: Executed application: GotoIf
[Mar 8 23:18:38] VERBOSE[4696] logger.c: -- Executing [s@macro-user-callerid:19] NoOp("SIP/Wiline-b02151d0", "Using CallerID "6502748970" <6502748970>") in new stack
[Mar 8 23:18:38] DEBUG[4696] app_macro.c: Executed application: Noop
[Mar 8 23:18:38] VERBOSE[4696] logger.c: -- Executing [2356@from-internal:3] Set("SIP/Wiline-b02151d0", "_NODEST=") in new stack
[Mar 8 23:18:38] VERBOSE[4696] logger.c: -- Executing [2356@from-internal:4] Macro("SIP/Wiline-b02151d0", "record-enable||OUT|") in new stack
[Mar 8 23:18:38] VERBOSE[4696] logger.c: -- Executing [s@macro-record-enable:1] GotoIf("SIP/Wiline-b02151d0", "1?check") in new stack
[Mar 8 23:18:38] VERBOSE[4696] logger.c: -- Goto (macro-record-enable,s,4)
[Mar 8 23:18:38] DEBUG[4696] app_macro.c: Executed application: GotoIf
[Mar 8 23:18:38] VERBOSE[4696] logger.c: -- Executing [s@macro-record-enable:4] AGI("SIP/Wiline-b02151d0", "recordingcheck|20110308-231838|1299655118.91") in new stack
[Mar 8 23:18:38] VERBOSE[4696] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
[Mar 8 23:18:38] VERBOSE[4696] logger.c: recordingcheck|20110308-231838|1299655118.91: No AMPUSER db entry for . Not recording
[Mar 8 23:18:38] VERBOSE[4696] logger.c: -- AGI Script recordingcheck completed, returning 0
[Mar 8 23:18:38] DEBUG[4696] app_macro.c: Executed application: AGI
[Mar 8 23:18:38] VERBOSE[4696] logger.c: -- Executing [s@macro-record-enable:5] MacroExit("SIP/Wiline-b02151d0", "") in new stack
[Mar 8 23:18:38] VERBOSE[4696] logger.c: -- Executing [2356@from-internal:5] Macro("SIP/Wiline-b02151d0", "dialout-trunk|2|2356||") in new stack
[Mar 8 23:18:38] VERBOSE[4696] logger.c: -- Executing [s@macro-dialout-trunk:1] Set("SIP/Wiline-b02151d0", "DIAL_TRUNK=2") in new stack
[Mar 8 23:18:38] DEBUG[4696] app_macro.c: Executed application: Set
[Mar 8 23:18:38] DEBUG[4696] func_db.c: DB: AMPUSER//pinless not found in database.
[Mar 8 23:18:38] VERBOSE[4696] logger.c: -- Executing [s@macro-dialout-trunk:2] GosubIf("SIP/Wiline-b02151d0", "0?sub-pincheck|s|1") in new stack
[Mar 8 23:18:38] DEBUG[4696] app_macro.c: Executed application: GosubIf
[Mar 8 23:18:38] DEBUG[4696] func_db.c: DB: AMPUSER//pinless not found in database.
[Mar 8 23:18:38] VERBOSE[4696] logger.c: -- Executing [s@macro-dialout-trunk:3] GotoIf("SIP/Wiline-b02151d0", "0?disabletrunk|1") in new stack
[Mar 8 23:18:38] DEBUG[4696] app_macro.c: Executed application: GotoIf
[Mar 8 23:18:38] VERBOSE[4696] logger.c: -- Executing [s@macro-dialout-trunk:4] Set("SIP/Wiline-b02151d0", "DIAL_NUMBER=2356") in new stack
[Mar 8 23:18:38] DEBUG[4696] app_macro.c: Executed application: Set
[Mar 8 23:18:38] VERBOSE[4696] logger.c: -- Executing [s@macro-dialout-trunk:5] Set("SIP/Wiline-b02151d0", "DIAL_TRUNK_OPTIONS=tr") in new stack
[Mar 8 23:18:38] DEBUG[4696] app_macro.c: Executed application: Set
[Mar 8 23:18:38] VERBOSE[4696] logger.c: -- Executing [s@macro-dialout-trunk:6] Set("SIP/Wiline-b02151d0", "OUTBOUND_GROUP=OUT_2") in new stack
[Mar 8 23:18:38] DEBUG[4696] app_macro.c: Executed application: Set
[Mar 8 23:18:38] VERBOSE[4696] logger.c: -- Executing [s@macro-dialout-trunk:7] GotoIf("SIP/Wiline-b02151d0", "1?nomax") in new stack
[Mar 8 23:18:38] VERBOSE[4696] logger.c: -- Goto (macro-dialout-trunk,s,9)
[Mar 8 23:18:38] DEBUG[4696] app_macro.c: Executed application: GotoIf
[Mar 8 23:18:38] VERBOSE[4696] logger.c: -- Executing [s@macro-dialout-trunk:9] GotoIf("SIP/Wiline-b02151d0", "1?skipoutcid") in new stack
[Mar 8 23:18:38] VERBOSE[4696] logger.c: -- Goto (macro-dialout-trunk,s,12)
[Mar 8 23:18:38] DEBUG[4696] app_macro.c: Executed application: GotoIf
[Mar 8 23:18:38] VERBOSE[4696] logger.c: -- Executing [s@macro-dialout-trunk:12] ExecIf("SIP/Wiline-b02151d0", "0|AGI|fixlocalprefix") in new stack
[Mar 8 23:18:38] DEBUG[4696] app_macro.c: Executed application: ExecIf
[Mar 8 23:18:38] VERBOSE[4696] logger.c: -- Executing [s@macro-dialout-trunk:13] Set("SIP/Wiline-b02151d0", "OUTNUM=2356") in new stack
[Mar 8 23:18:38] DEBUG[4696] app_macro.c: Executed application: Set
[Mar 8 23:18:38] VERBOSE[4696] logger.c: -- Executing [s@macro-dialout-trunk:14] Set("SIP/Wiline-b02151d0", "custom=IAX2/phpbx01") in new stack
[Mar 8 23:18:38] DEBUG[4696] app_macro.c: Executed application: Set
[Mar 8 23:18:38] VERBOSE[4696] logger.c: -- Executing [s@macro-dialout-trunk:15] ExecIf("SIP/Wiline-b02151d0", "0|Set|DIAL_TRUNK_OPTIONS=M(setmusic^)tr") in new stack
[Mar 8 23:18:38] DEBUG[4696] app_macro.c: Executed application: ExecIf
[Mar 8 23:18:38] VERBOSE[4696] logger.c: -- Executing [s@macro-dialout-trunk:16] Macro("SIP/Wiline-b02151d0", "dialout-trunk-predial-hook|") in new stack
[Mar 8 23:18:38] VERBOSE[4696] logger.c: -- Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("SIP/Wiline-b02151d0", "") in new stack
[Mar 8 23:18:38] DEBUG[4696] app_macro.c: Executed application: Macro
[Mar 8 23:18:38] VERBOSE[4696] logger.c: -- Executing [s@macro-dialout-trunk:17] GotoIf("SIP/Wiline-b02151d0", "0?bypass|1") in new stack
[Mar 8 23:18:38] DEBUG[4696] app_macro.c: Executed application: GotoIf
[Mar 8 23:18:38] VERBOSE[4696] logger.c: -- Executing [s@macro-dialout-trunk:18] GotoIf("SIP/Wiline-b02151d0", "0?customtrunk") in new stack
[Mar 8 23:18:38] DEBUG[4696] app_macro.c: Executed application: GotoIf
[Mar 8 23:18:38] VERBOSE[4696] logger.c: -- Executing [s@macro-dialout-trunk:19] Dial("SIP/Wiline-b02151d0", "IAX2/phpbx01/2356|300|tr") in new stack
[Mar 8 23:18:38] NOTICE[4696] app_dial.c: Hey! chan SIP/Wiline-b02151d0's context='macro-dialout-trunk', and exten='s'
[Mar 8 23:18:38] DEBUG[4696] chan_iax2.c: prepending 100 to prefs
[Mar 8 23:18:38] VERBOSE[4696] logger.c: -- Called phpbx01/2356
[Mar 8 23:18:48] VERBOSE[4696] logger.c: -- Hungup 'IAX2/phpbx01-16384'
[Mar 8 23:18:48] VERBOSE[4696] logger.c: == Everyone is busy/congested at this time (1:0/0/1)
[Mar 8 23:18:48] DEBUG[4696] app_macro.c: Executed application: Dial
[Mar 8 23:18:48] VERBOSE[4696] logger.c: -- Executing [s@macro-dialout-trunk:20] Goto("SIP/Wiline-b02151d0", "s-CHANUNAVAIL|1") in new stack
[Mar 8 23:18:48] VERBOSE[4696] logger.c: -- Goto (macro-dialout-trunk,s-CHANUNAVAIL,1)
[Mar 8 23:18:48] DEBUG[4696] app_macro.c: Executed application: Goto
[Mar 8 23:18:48] VERBOSE[4696] logger.c: -- Executing [s-CHANUNAVAIL@macro-dialout-trunk:1] GotoIf("SIP/Wiline-b02151d0", "1?noreport") in new stack
[Mar 8 23:18:48] VERBOSE[4696] logger.c: -- Goto (macro-dialout-trunk,s-CHANUNAVAIL,3)
[Mar 8 23:18:48] DEBUG[4696] app_macro.c: Executed application: GotoIf
[Mar 8 23:18:48] VERBOSE[4696] logger.c: -- Executing [s-CHANUNAVAIL@macro-dialout-trunk:3] NoOp("SIP/Wiline-b02151d0", "TRUNK Dial failed due to CHANUNAVAIL (hangupcause: 0) - failing through to other trunks") in new stack
[Mar 8 23:18:48] DEBUG[4696] app_macro.c: Executed application: Noop
[Mar 8 23:18:48] VERBOSE[4696] logger.c: -- Executing [2356@from-internal:6] Macro("SIP/Wiline-b02151d0", "outisbusy|") in new stack
[Mar 8 23:18:48] VERBOSE[4696] logger.c: -- Executing [s@macro-outisbusy:1] GotoIf("SIP/Wiline-b02151d0", "0?emergency|1") in new stack
[Mar 8 23:18:48] DEBUG[4696] app_macro.c: Executed application: GotoIf
[Mar 8 23:18:48] VERBOSE[4696] logger.c: -- Executing [s@macro-outisbusy:2] GotoIf("SIP/Wiline-b02151d0", "1?intracompany|1") in new stack
[Mar 8 23:18:48] VERBOSE[4696] logger.c: -- Goto (macro-outisbusy,intracompany,1)
[Mar 8 23:18:48] DEBUG[4696] app_macro.c: Executed application: GotoIf
[Mar 8 23:18:48] VERBOSE[4696] logger.c: -- Executing [intracompany@macro-outisbusy:1] Playback("SIP/Wiline-b02151d0", "all-circuits-busy-now&pls-try-call-later| noanswer") in new stack
[Mar 8 23:18:48] VERBOSE[4696] logger.c: -- <SIP/Wiline-b02151d0> Playing 'all-circuits-busy-now' (language 'en')
[Mar 8 23:18:50] VERBOSE[4696] logger.c: -- <SIP/Wiline-b02151d0> Playing 'pls-try-call-later' (language 'en')
[Mar 8 23:18:52] DEBUG[4696] app_macro.c: Executed application: Playback
[Mar 8 23:18:52] VERBOSE[4696] logger.c: -- Executing [intracompany@macro-outisbusy:2] Congestion("SIP/Wiline-b02151d0", "20") in new stack
[Mar 8 23:18:52] VERBOSE[4696] logger.c: == Spawn extension (macro-outisbusy, intracompany, 2) exited non-zero on 'SIP/Wiline-b02151d0' in macro 'outisbusy'
[Mar 8 23:18:52] VERBOSE[4696] logger.c: == Spawn extension (from-internal, 2356, 6) exited non-zero on 'SIP/Wiline-b02151d0'
[Mar 8 23:18:52] VERBOSE[4696] logger.c: -- Executing [h@from-internal:1] Macro("SIP/Wiline-b02151d0", "hangupcall") in new stack
[Mar 8 23:18:52] VERBOSE[4696] logger.c: -- Executing [s@macro-hangupcall:1] GotoIf("SIP/Wiline-b02151d0", "1?skiprg") in new stack
[Mar 8 23:18:52] VERBOSE[4696] logger.c: -- Goto (macro-hangupcall,s,4)
[Mar 8 23:18:52] DEBUG[4696] app_macro.c: Executed application: GotoIf
[Mar 8 23:18:52] VERBOSE[4696] logger.c: -- Executing [s@macro-hangupcall:4] GotoIf("SIP/Wiline-b02151d0", "1?skipblkvm") in new stack
[Mar 8 23:18:52] VERBOSE[4696] logger.c: -- Goto (macro-hangupcall,s,7)
[Mar 8 23:18:52] DEBUG[4696] app_macro.c: Executed application: GotoIf
[Mar 8 23:18:52] VERBOSE[4696] logger.c: -- Executing [s@macro-hangupcall:7] GotoIf("SIP/Wiline-b02151d0", "1?theend") in new stack
[Mar 8 23:18:52] VERBOSE[4696] logger.c: -- Goto (macro-hangupcall,s,9)
[Mar 8 23:18:52] DEBUG[4696] app_macro.c: Executed application: GotoIf
[Mar 8 23:18:52] VERBOSE[4696] logger.c: -- Executing [s@macro-hangupcall:9] Hangup("SIP/Wiline-b02151d0", "") in new stack
[Mar 8 23:18:52] VERBOSE[4696] logger.c: == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/Wiline-b02151d0' in macro 'hangupcall'
[Mar 8 23:18:52] VERBOSE[4696] logger.c: == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/Wiline-b02151d0'
[root@uspbx01 ~]#





And this error is from an extension in PHPBX01 calling my mobile.


[Mar 8 23:26:18] VERBOSE[4194] logger.c: -- Hungup 'IAX2/uspbx01-16384'
[Mar 8 23:26:18] VERBOSE[4194] logger.c: == Everyone is busy/congested at this time (1:0/0/1)
[Mar 8 23:26:18] DEBUG[4194] app_macro.c: Executed application: Dial
[Mar 8 23:26:18] VERBOSE[4194] logger.c: -- Executing [s@macro-dialout-trunk:20] Goto("SIP/3382-b82b26d0", "s-CHANUNAVAIL|1") in new stack
[Mar 8 23:26:18] VERBOSE[4194] logger.c: -- Goto (macro-dialout-trunk,s-CHANUNAVAIL,1)
[Mar 8 23:26:18] DEBUG[4194] app_macro.c: Executed application: Goto
[Mar 8 23:26:18] VERBOSE[4194] logger.c: -- Executing [s-CHANUNAVAIL@macro-dialout-trunk:1] GotoIf("SIP/3382-b82b26d0", "1?noreport") in new stack
[Mar 8 23:26:18] VERBOSE[4194] logger.c: -- Goto (macro-dialout-trunk,s-CHANUNAVAIL,3)
[Mar 8 23:26:18] DEBUG[4194] app_macro.c: Executed application: GotoIf
[Mar 8 23:26:18] VERBOSE[4194] logger.c: -- Executing [s-CHANUNAVAIL@macro-dialout-trunk:3] NoOp("SIP/3382-b82b26d0", "TRUNK Dial failed due to CHANUNAVAIL (hangupcause: 0) - failing through to other trunks") in new stack
[Mar 8 23:26:18] DEBUG[4194] app_macro.c: Executed application: Noop
[Mar 8 23:26:18] VERBOSE[4194] logger.c: -- Executing [6502748970@from-internal:6] Macro("SIP/3382-b82b26d0", "outisbusy|") in new stack
[Mar 8 23:26:18] VERBOSE[4194] logger.c: -- Executing [s@macro-outisbusy:1] GotoIf("SIP/3382-b82b26d0", "0?emergency|1") in new stack
[Mar 8 23:26:18] DEBUG[4194] app_macro.c: Executed application: GotoIf
[Mar 8 23:26:18] VERBOSE[4194] logger.c: -- Executing [s@macro-outisbusy:2] GotoIf("SIP/3382-b82b26d0", "1?intracompany|1") in new stack
[Mar 8 23:26:18] VERBOSE[4194] logger.c: -- Goto (macro-outisbusy,intracompany,1)
[Mar 8 23:26:18] DEBUG[4194] app_macro.c: Executed application: GotoIf
[Mar 8 23:26:18] VERBOSE[4194] logger.c: -- Executing [intracompany@macro-outisbusy:1] Playback("SIP/3382-b82b26d0", "all-circuits-busy-now&pls-try-call-later| noanswer") in new stack
[Mar 8 23:26:18] VERBOSE[4194] logger.c: -- <SIP/3382-b82b26d0> Playing 'all-circuits-busy-now' (language 'en')
[Mar 8 23:26:20] VERBOSE[4194] logger.c: -- <SIP/3382-b82b26d0> Playing 'pls-try-call-later' (language 'en')
[Mar 8 23:26:22] DEBUG[4194] app_macro.c: Executed application: Playback
[Mar 8 23:26:22] VERBOSE[4194] logger.c: -- Executing [intracompany@macro-outisbusy:2] Congestion("SIP/3382-b82b26d0", "20") in new stack
[Mar 8 23:26:22] VERBOSE[4194] logger.c: == Spawn extension (macro-outisbusy, intracompany, 2) exited non-zero on 'SIP/3382-b82b26d0' in macro 'outisbusy'
[Mar 8 23:26:22] VERBOSE[4194] logger.c: == Spawn extension (from-internal, 6502748970, 6) exited non-zero on 'SIP/3382-b82b26d0'
[Mar 8 23:26:22] VERBOSE[4194] logger.c: -- Executing [h@from-internal:1] Macro("SIP/3382-b82b26d0", "hangupcall") in new stack
[Mar 8 23:26:22] VERBOSE[4194] logger.c: -- Executing [s@macro-hangupcall:1] GotoIf("SIP/3382-b82b26d0", "1?skiprg") in new stack
[Mar 8 23:26:22] VERBOSE[4194] logger.c: -- Goto (macro-hangupcall,s,4)
[Mar 8 23:26:22] DEBUG[4194] app_macro.c: Executed application: GotoIf
[Mar 8 23:26:22] VERBOSE[4194] logger.c: -- Executing [s@macro-hangupcall:4] GotoIf("SIP/3382-b82b26d0", "1?skipblkvm") in new stack
[Mar 8 23:26:22] VERBOSE[4194] logger.c: -- Goto (macro-hangupcall,s,7)
[Mar 8 23:26:22] DEBUG[4194] app_macro.c: Executed application: GotoIf
[Mar 8 23:26:22] VERBOSE[4194] logger.c: -- Executing [s@macro-hangupcall:7] GotoIf("SIP/3382-b82b26d0", "1?theend") in new stack
[Mar 8 23:26:22] VERBOSE[4194] logger.c: -- Goto (macro-hangupcall,s,9)
[Mar 8 23:26:22] DEBUG[4194] app_macro.c: Executed application: GotoIf
[Mar 8 23:26:22] VERBOSE[4194] logger.c: -- Executing [s@macro-hangupcall:9] Hangup("SIP/3382-b82b26d0", "") in new stack
[Mar 8 23:26:22] VERBOSE[4194] logger.c: == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/3382-b82b26d0' in macro 'hangupcall'
[Mar 8 23:26:22] VERBOSE[4194] logger.c: == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/3382-b82b26d0'
[Mar 8 23:26:22] VERBOSE[4196] logger.c: == MixMonitor close filestream
[Mar 8 23:26:22] VERBOSE[4196] logger.c: == End MixMonitor Recording SIP/3382-b82b26d0
 

dicko

Joined
Oct 24, 2008
Messages
4,099
Likes
0
Points
0
#15
Same thing . . .
.
.
[Mar 8 23:18:38] VERBOSE[4696] logger.c: -- Called phpbx01/2356
[Mar 8 23:18:48] VERBOSE[4696] logger.c: -- Hungup 'IAX2/phpbx01-16384'
.
.

gotta get out your IAX2 debugger . . . . it's all about those ten seconds, no?
 

eijob

Joined
Jul 29, 2010
Messages
43
Likes
0
Points
0
#16
Hi Dicko,

im calling an extension in manila from my US cellphone.

My call only got through to USPBX01, below is the log. I did not see any in PHPBX01.

Thanks



[Mar 9 01:32:38] DEBUG[5869] pbx.c: Launching 'Set'
[Mar 9 01:32:38] VERBOSE[5869] logger.c: -- Executing [3494@from-internal:1] Set("SIP/Wiline-c8002660", "INTRACOMPANYROUTE=YES") in new stack
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Launching 'Macro'
[Mar 9 01:32:38] VERBOSE[5869] logger.c: -- Executing [3494@from-internal:2] Macro("SIP/Wiline-c8002660", "user-callerid|SKIPTTL|") in new stack
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Expression result is '1'
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Function result is '6502748970'
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Function result is '6502748970'
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Launching 'Set'
[Mar 9 01:32:38] VERBOSE[5869] logger.c: -- Executing [s@macro-user-callerid:1] Set("SIP/Wiline-c8002660", "AMPUSER=6502748970") in new stack
[Mar 9 01:32:38] DEBUG[5869] app_macro.c: Executed application: Set
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Expression result is '0'
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Launching 'GotoIf'
[Mar 9 01:32:38] VERBOSE[5869] logger.c: -- Executing [s@macro-user-callerid:2] GotoIf("SIP/Wiline-c8002660", "0?report") in new stack
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Not taking any branch
[Mar 9 01:32:38] DEBUG[5869] app_macro.c: Executed application: GotoIf
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Expression result is '1'
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Function result is '6502748970'
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Launching 'ExecIf'
[Mar 9 01:32:38] VERBOSE[5869] logger.c: -- Executing [s@macro-user-callerid:3] ExecIf("SIP/Wiline-c8002660", "1|Set|REALCALLERIDNUM=6502748970") in new stack
[Mar 9 01:32:38] DEBUG[5869] app_macro.c: Executed application: ExecIf
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Expression result is '0'
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Function result is '6502748970'
[Mar 9 01:32:38] DEBUG[5869] db.c: Unable to find key '6502748970/user' in family 'DEVICE'
[Mar 9 01:32:38] DEBUG[5869] func_db.c: DB: DEVICE/6502748970/user not found in database.
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Function result is ''
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Launching 'Set'
[Mar 9 01:32:38] VERBOSE[5869] logger.c: -- Executing [s@macro-user-callerid:4] Set("SIP/Wiline-c8002660", "AMPUSER=") in new stack
[Mar 9 01:32:38] DEBUG[5869] app_macro.c: Executed application: Set
[Mar 9 01:32:38] DEBUG[5869] db.c: Unable to find key '/cidname' in family 'AMPUSER'
[Mar 9 01:32:38] DEBUG[5869] func_db.c: DB: AMPUSER//cidname not found in database.
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Function result is ''
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Launching 'Set'
[Mar 9 01:32:38] VERBOSE[5869] logger.c: -- Executing [s@macro-user-callerid:5] Set("SIP/Wiline-c8002660", "AMPUSERCIDNAME=") in new stack
[Mar 9 01:32:38] DEBUG[5869] app_macro.c: Executed application: Set
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Expression result is '1'
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Launching 'GotoIf'
[Mar 9 01:32:38] VERBOSE[5869] logger.c: -- Executing [s@macro-user-callerid:6] GotoIf("SIP/Wiline-c8002660", "1?report") in new stack
[Mar 9 01:32:38] VERBOSE[5869] logger.c: -- Goto (macro-user-callerid,s,10)
[Mar 9 01:32:38] DEBUG[5869] app_macro.c: Executed application: GotoIf
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Expression result is '1'
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Launching 'GotoIf'
[Mar 9 01:32:38] VERBOSE[5869] logger.c: -- Executing [s@macro-user-callerid:10] GotoIf("SIP/Wiline-c8002660", "1?continue") in new stack
[Mar 9 01:32:38] VERBOSE[5869] logger.c: -- Goto (macro-user-callerid,s,19)
[Mar 9 01:32:38] DEBUG[5869] app_macro.c: Executed application: GotoIf
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Function result is '"6502748970" <6502748970>'
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Launching 'NoOp'
[Mar 9 01:32:38] VERBOSE[5869] logger.c: -- Executing [s@macro-user-callerid:19] NoOp("SIP/Wiline-c8002660", "Using CallerID "6502748970" <6502748970>") in new stack
[Mar 9 01:32:38] DEBUG[5869] app_macro.c: Executed application: Noop
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Launching 'Set'
[Mar 9 01:32:38] VERBOSE[5869] logger.c: -- Executing [3494@from-internal:3] Set("SIP/Wiline-c8002660", "_NODEST=") in new stack
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Launching 'Macro'
[Mar 9 01:32:38] VERBOSE[5869] logger.c: -- Executing [3494@from-internal:4] Macro("SIP/Wiline-c8002660", "record-enable||OUT|") in new stack
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Expression result is '1'
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Launching 'GotoIf'
[Mar 9 01:32:38] VERBOSE[5869] logger.c: -- Executing [s@macro-record-enable:1] GotoIf("SIP/Wiline-c8002660", "1?check") in new stack
[Mar 9 01:32:38] VERBOSE[5869] logger.c: -- Goto (macro-record-enable,s,4)
[Mar 9 01:32:38] DEBUG[5869] app_macro.c: Executed application: GotoIf
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Function result is '20110309-013238'
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Launching 'AGI'
[Mar 9 01:32:38] VERBOSE[5869] logger.c: -- Executing [s@macro-record-enable:4] AGI("SIP/Wiline-c8002660", "recordingcheck|20110309-013238|1299663158.410") in new stack
[Mar 9 01:32:38] VERBOSE[5869] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
[Mar 9 01:32:38] DEBUG[5869] db.c: Unable to find key '/recording' in family 'AMPUSER'
[Mar 9 01:32:38] VERBOSE[5869] logger.c: recordingcheck|20110309-013238|1299663158.410: No AMPUSER db entry for . Not recording
[Mar 9 01:32:38] VERBOSE[5869] logger.c: -- AGI Script recordingcheck completed, returning 0
[Mar 9 01:32:38] DEBUG[5869] app_macro.c: Executed application: AGI
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Launching 'MacroExit'
[Mar 9 01:32:38] VERBOSE[5869] logger.c: -- Executing [s@macro-record-enable:5] MacroExit("SIP/Wiline-c8002660", "") in new stack
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Launching 'Macro'
[Mar 9 01:32:38] VERBOSE[5869] logger.c: -- Executing [3494@from-internal:5] Macro("SIP/Wiline-c8002660", "dialout-trunk|2|3494||") in new stack
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Launching 'Set'
[Mar 9 01:32:38] VERBOSE[5869] logger.c: -- Executing [s@macro-dialout-trunk:1] Set("SIP/Wiline-c8002660", "DIAL_TRUNK=2") in new stack
[Mar 9 01:32:38] DEBUG[5869] app_macro.c: Executed application: Set
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Expression result is '0'
[Mar 9 01:32:38] DEBUG[5869] db.c: Unable to find key '/pinless' in family 'AMPUSER'
[Mar 9 01:32:38] DEBUG[5869] func_db.c: DB: AMPUSER//pinless not found in database.
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Function result is ''
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Expression result is '1'
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Expression result is '0'
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Launching 'GosubIf'
[Mar 9 01:32:38] VERBOSE[5869] logger.c: -- Executing [s@macro-dialout-trunk:2] GosubIf("SIP/Wiline-c8002660", "0?sub-pincheck|s|1") in new stack
[Mar 9 01:32:38] DEBUG[5869] app_macro.c: Executed application: GosubIf
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Expression result is '0'
[Mar 9 01:32:38] DEBUG[5869] db.c: Unable to find key '/pinless' in family 'AMPUSER'
[Mar 9 01:32:38] DEBUG[5869] func_db.c: DB: AMPUSER//pinless not found in database.
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Function result is ''
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Expression result is '1'
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Expression result is '0'
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Expression result is '0'
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Launching 'GotoIf'
[Mar 9 01:32:38] VERBOSE[5869] logger.c: -- Executing [s@macro-dialout-trunk:3] GotoIf("SIP/Wiline-c8002660", "0?disabletrunk|1") in new stack
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Not taking any branch
[Mar 9 01:32:38] DEBUG[5869] app_macro.c: Executed application: GotoIf
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Launching 'Set'
[Mar 9 01:32:38] VERBOSE[5869] logger.c: -- Executing [s@macro-dialout-trunk:4] Set("SIP/Wiline-c8002660", "DIAL_NUMBER=3494") in new stack
[Mar 9 01:32:38] DEBUG[5869] app_macro.c: Executed application: Set
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Launching 'Set'
[Mar 9 01:32:38] VERBOSE[5869] logger.c: -- Executing [s@macro-dialout-trunk:5] Set("SIP/Wiline-c8002660", "DIAL_TRUNK_OPTIONS=tr") in new stack
[Mar 9 01:32:38] DEBUG[5869] app_macro.c: Executed application: Set
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Launching 'Set'
[Mar 9 01:32:38] VERBOSE[5869] logger.c: -- Executing [s@macro-dialout-trunk:6] Set("SIP/Wiline-c8002660", "OUTBOUND_GROUP=OUT_2") in new stack
[Mar 9 01:32:38] DEBUG[5869] app_macro.c: Executed application: Set
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Expression result is '1'
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Launching 'GotoIf'
[Mar 9 01:32:38] VERBOSE[5869] logger.c: -- Executing [s@macro-dialout-trunk:7] GotoIf("SIP/Wiline-c8002660", "1?nomax") in new stack
[Mar 9 01:32:38] VERBOSE[5869] logger.c: -- Goto (macro-dialout-trunk,s,9)
[Mar 9 01:32:38] DEBUG[5869] app_macro.c: Executed application: GotoIf
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Expression result is '1'
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Launching 'GotoIf'
[Mar 9 01:32:38] VERBOSE[5869] logger.c: -- Executing [s@macro-dialout-trunk:9] GotoIf("SIP/Wiline-c8002660", "1?skipoutcid") in new stack
[Mar 9 01:32:38] VERBOSE[5869] logger.c: -- Goto (macro-dialout-trunk,s,12)
[Mar 9 01:32:38] DEBUG[5869] app_macro.c: Executed application: GotoIf
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Expression result is '0'
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Launching 'ExecIf'
[Mar 9 01:32:38] VERBOSE[5869] logger.c: -- Executing [s@macro-dialout-trunk:12] ExecIf("SIP/Wiline-c8002660", "0|AGI|fixlocalprefix") in new stack
[Mar 9 01:32:38] DEBUG[5869] app_macro.c: Executed application: ExecIf
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Expression result is '0'
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Launching 'Set'
[Mar 9 01:32:38] VERBOSE[5869] logger.c: -- Executing [s@macro-dialout-trunk:13] Set("SIP/Wiline-c8002660", "OUTNUM=3494") in new stack
[Mar 9 01:32:38] DEBUG[5869] app_macro.c: Executed application: Set
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Function result is 'IAX2/phpbx01'
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Launching 'Set'
[Mar 9 01:32:38] VERBOSE[5869] logger.c: -- Executing [s@macro-dialout-trunk:14] Set("SIP/Wiline-c8002660", "custom=IAX2/phpbx01") in new stack
[Mar 9 01:32:38] DEBUG[5869] app_macro.c: Executed application: Set
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Expression result is '1'
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Expression result is '0'
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Expression result is '0'
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Launching 'ExecIf'
[Mar 9 01:32:38] VERBOSE[5869] logger.c: -- Executing [s@macro-dialout-trunk:15] ExecIf("SIP/Wiline-c8002660", "0|Set|DIAL_TRUNK_OPTIONS=M(setmusic^)tr") in new stack
[Mar 9 01:32:38] DEBUG[5869] app_macro.c: Executed application: ExecIf
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Expression result is '1'
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Expression result is '0'
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Expression result is '0'
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Launching 'Macro'
[Mar 9 01:32:38] VERBOSE[5869] logger.c: -- Executing [s@macro-dialout-trunk:16] Macro("SIP/Wiline-c8002660", "dialout-trunk-predial-hook|") in new stack
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Launching 'MacroExit'
[Mar 9 01:32:38] VERBOSE[5869] logger.c: -- Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("SIP/Wiline-c8002660", "") in new stack
[Mar 9 01:32:38] DEBUG[5869] app_macro.c: Executed application: Macro
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Expression result is '0'
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Launching 'GotoIf'
[Mar 9 01:32:38] VERBOSE[5869] logger.c: -- Executing [s@macro-dialout-trunk:17] GotoIf("SIP/Wiline-c8002660", "0?bypass|1") in new stack
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Not taking any branch
[Mar 9 01:32:38] DEBUG[5869] app_macro.c: Executed application: GotoIf
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Expression result is '0'
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Launching 'GotoIf'
[Mar 9 01:32:38] VERBOSE[5869] logger.c: -- Executing [s@macro-dialout-trunk:18] GotoIf("SIP/Wiline-c8002660", "0?customtrunk") in new stack
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Not taking any branch
[Mar 9 01:32:38] DEBUG[5869] app_macro.c: Executed application: GotoIf
[Mar 9 01:32:38] DEBUG[5869] pbx.c: Launching 'Dial'
[Mar 9 01:32:38] VERBOSE[5869] logger.c: -- Executing [s@macro-dialout-trunk:19] Dial("SIP/Wiline-c8002660", "IAX2/phpbx01/3494|300|tr") in new stack
[Mar 9 01:32:38] NOTICE[5869] app_dial.c: Hey! chan SIP/Wiline-c8002660's context='macro-dialout-trunk', and exten='s'
[Mar 9 01:32:38] DEBUG[5869] chan_iax2.c: Made call 6919 into trunk call 16385
[Mar 9 01:32:38] DEBUG[5869] rtp.c: Channel 'IAX2/phpbx01-16385' has no RTP, not doing anything
[Mar 9 01:32:38] DEBUG[5869] channel.c: Not copying variable DIALEDTIME.
[Mar 9 01:32:38] DEBUG[5869] channel.c: Not copying variable ANSWEREDTIME.
[Mar 9 01:32:38] DEBUG[5869] channel.c: Not copying variable DIALEDPEERNAME.
[Mar 9 01:32:38] DEBUG[5869] channel.c: Not copying variable DIALEDPEERNUMBER.
[Mar 9 01:32:38] DEBUG[5869] channel.c: Not copying variable DIALSTATUS.
[Mar 9 01:32:38] DEBUG[5869] channel.c: Not copying variable MACRO_DEPTH.
[Mar 9 01:32:38] DEBUG[5869] channel.c: Not copying variable MACRO_PRIORITY.
[Mar 9 01:32:38] DEBUG[5869] channel.c: Not copying variable MACRO_CONTEXT.
[Mar 9 01:32:38] DEBUG[5869] channel.c: Not copying variable MACRO_EXTEN.
[Mar 9 01:32:38] DEBUG[5869] channel.c: Not copying variable ARG1.
[Mar 9 01:32:38] DEBUG[5869] channel.c: Not copying variable custom.
[Mar 9 01:32:38] DEBUG[5869] channel.c: Not copying variable OUTNUM.
[Mar 9 01:32:38] DEBUG[5869] channel.c: Not copying variable OUTBOUND_GROUP.
[Mar 9 01:32:38] DEBUG[5869] channel.c: Not copying variable DIAL_TRUNK_OPTIONS.
[Mar 9 01:32:38] DEBUG[5869] channel.c: Not copying variable DIAL_NUMBER.
[Mar 9 01:32:38] DEBUG[5869] channel.c: Not copying variable DIAL_TRUNK.
[Mar 9 01:32:38] DEBUG[5869] channel.c: Not copying variable ARG4.
[Mar 9 01:32:38] DEBUG[5869] channel.c: Not copying variable ARG3.
[Mar 9 01:32:38] DEBUG[5869] channel.c: Not copying variable ARG2.
[Mar 9 01:32:38] DEBUG[5869] channel.c: Not copying variable AGISTATUS.
[Mar 9 01:32:38] DEBUG[5869] channel.c: Copying soft-transferable variable NODEST.
[Mar 9 01:32:38] DEBUG[5869] channel.c: Not copying variable AMPUSERCIDNAME.
[Mar 9 01:32:38] DEBUG[5869] channel.c: Not copying variable AMPUSER.
[Mar 9 01:32:38] DEBUG[5869] channel.c: Not copying variable REALCALLERIDNUM.
[Mar 9 01:32:38] DEBUG[5869] channel.c: Not copying variable INTRACOMPANYROUTE.
[Mar 9 01:32:38] DEBUG[5869] channel.c: Not copying variable SIPCALLID.
[Mar 9 01:32:38] DEBUG[5869] channel.c: Not copying variable SIPUSERAGENT.
[Mar 9 01:32:38] DEBUG[5869] channel.c: Not copying variable SIPDOMAIN.
[Mar 9 01:32:38] DEBUG[5869] channel.c: Not copying variable SIPURI.
[Mar 9 01:32:38] DEBUG[5869] chan_iax2.c: prepending 100 to prefs
[Mar 9 01:32:38] DEBUG[5869] devicestate.c: Notification of state change to be queued on device/channel IAX2/phpbx01
[Mar 9 01:32:38] VERBOSE[5869] logger.c: -- Called phpbx01/3494
[Mar 9 01:32:49] DEBUG[5869] channel.c: Hanging up channel 'IAX2/phpbx01-16385'
[Mar 9 01:32:49] DEBUG[5869] chan_iax2.c: We're hanging up IAX2/phpbx01-16385 now...
[Mar 9 01:32:49] VERBOSE[5869] logger.c: -- Hungup 'IAX2/phpbx01-16385'
[Mar 9 01:32:49] DEBUG[5869] devicestate.c: Notification of state change to be queued on device/channel IAX2/phpbx01
[Mar 9 01:32:49] VERBOSE[5869] logger.c: == Everyone is busy/congested at this time (1:0/0/1)
[Mar 9 01:32:49] DEBUG[5869] rtp.c: Channel '<unspecified>' has no RTP, not doing anything
[Mar 9 01:32:49] DEBUG[5869] app_dial.c: Exiting with DIALSTATUS=CHANUNAVAIL.
[Mar 9 01:32:49] DEBUG[5869] app_macro.c: Executed application: Dial
[Mar 9 01:32:49] DEBUG[5869] pbx.c: Launching 'Goto'
[Mar 9 01:32:49] VERBOSE[5869] logger.c: -- Executing [s@macro-dialout-trunk:20] Goto("SIP/Wiline-c8002660", "s-CHANUNAVAIL|1") in new stack
[Mar 9 01:32:49] VERBOSE[5869] logger.c: -- Goto (macro-dialout-trunk,s-CHANUNAVAIL,1)
[Mar 9 01:32:49] DEBUG[5869] app_macro.c: Executed application: Goto
[Mar 9 01:32:49] DEBUG[5869] pbx.c: Expression result is '1'
[Mar 9 01:32:49] DEBUG[5869] pbx.c: Launching 'GotoIf'
[Mar 9 01:32:49] VERBOSE[5869] logger.c: -- Executing [s-CHANUNAVAIL@macro-dialout-trunk:1] GotoIf("SIP/Wiline-c8002660", "1?noreport") in new stack
[Mar 9 01:32:49] VERBOSE[5869] logger.c: -- Goto (macro-dialout-trunk,s-CHANUNAVAIL,3)
[Mar 9 01:32:49] DEBUG[5869] app_macro.c: Executed application: GotoIf
[Mar 9 01:32:49] DEBUG[5869] pbx.c: Launching 'NoOp'
[Mar 9 01:32:49] VERBOSE[5869] logger.c: -- Executing [s-CHANUNAVAIL@macro-dialout-trunk:3] NoOp("SIP/Wiline-c8002660", "TRUNK Dial failed due to CHANUNAVAIL (hangupcause: 0) - failing through to other trunks") in new stack
[Mar 9 01:32:49] DEBUG[5869] app_macro.c: Executed application: Noop
[Mar 9 01:32:49] DEBUG[5869] pbx.c: Launching 'Macro'
[Mar 9 01:32:49] VERBOSE[5869] logger.c: -- Executing [3494@from-internal:6] Macro("SIP/Wiline-c8002660", "outisbusy|") in new stack
[Mar 9 01:32:49] DEBUG[5869] pbx.c: Expression result is '0'
[Mar 9 01:32:49] DEBUG[5869] pbx.c: Launching 'GotoIf'
[Mar 9 01:32:49] VERBOSE[5869] logger.c: -- Executing [s@macro-outisbusy:1] GotoIf("SIP/Wiline-c8002660", "0?emergency|1") in new stack
[Mar 9 01:32:49] DEBUG[5869] pbx.c: Not taking any branch
[Mar 9 01:32:49] DEBUG[5869] app_macro.c: Executed application: GotoIf
[Mar 9 01:32:49] DEBUG[5869] pbx.c: Expression result is '1'
[Mar 9 01:32:49] DEBUG[5869] pbx.c: Launching 'GotoIf'
[Mar 9 01:32:49] VERBOSE[5869] logger.c: -- Executing [s@macro-outisbusy:2] GotoIf("SIP/Wiline-c8002660", "1?intracompany|1") in new stack
[Mar 9 01:32:49] VERBOSE[5869] logger.c: -- Goto (macro-outisbusy,intracompany,1)
[Mar 9 01:32:49] DEBUG[5869] app_macro.c: Executed application: GotoIf
[Mar 9 01:32:49] DEBUG[5869] pbx.c: Launching 'Playback'
[Mar 9 01:32:49] VERBOSE[5869] logger.c: -- Executing [intracompany@macro-outisbusy:1] Playback("SIP/Wiline-c8002660", "all-circuits-busy-now&pls-try-call-later| noanswer") in new stack
[Mar 9 01:32:49] DEBUG[5869] channel.c: Set channel SIP/Wiline-c8002660 to write format gsm
[Mar 9 01:32:49] DEBUG[5869] chan_sip.c: Setting framing from config on incoming call
[Mar 9 01:32:49] DEBUG[5869] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True
[Mar 9 01:32:49] DEBUG[5869] chan_sip.c: ** Our prefcodec: 0x0 (nothing)
[Mar 9 01:32:49] DEBUG[5869] chan_sip.c: -- Done with adding codecs to SDP
[Mar 9 01:32:49] DEBUG[5869] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25)
[Mar 9 01:32:49] DEBUG[5869] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Mar 9 01:32:49] DEBUG[5869] channel.c: Scheduling timer at 160 sample intervals
[Mar 9 01:32:49] VERBOSE[5869] logger.c: -- <SIP/Wiline-c8002660> Playing 'all-circuits-busy-now' (language 'en')
[Mar 9 01:32:49] DEBUG[5869] rtp.c: Ooh, format changed from unknown to ulaw
[Mar 9 01:32:49] DEBUG[5869] rtp.c: Created smoother: format: 4 ms: 20 len: 160
[Mar 9 01:32:50] DEBUG[5869] channel.c: Scheduling timer at 0 sample intervals
[Mar 9 01:32:50] DEBUG[5869] channel.c: Scheduling timer at 0 sample intervals
[Mar 9 01:32:50] DEBUG[5869] channel.c: Set channel SIP/Wiline-c8002660 to write format ulaw
[Mar 9 01:32:50] DEBUG[5869] channel.c: Set channel SIP/Wiline-c8002660 to write format gsm
[Mar 9 01:32:50] DEBUG[5869] channel.c: Scheduling timer at 160 sample intervals
[Mar 9 01:32:50] VERBOSE[5869] logger.c: -- <SIP/Wiline-c8002660> Playing 'pls-try-call-later' (language 'en')
[Mar 9 01:32:53] DEBUG[5869] channel.c: Scheduling timer at 0 sample intervals
[Mar 9 01:32:53] DEBUG[5869] channel.c: Scheduling timer at 0 sample intervals
[Mar 9 01:32:53] DEBUG[5869] channel.c: Set channel SIP/Wiline-c8002660 to write format ulaw
[Mar 9 01:32:53] DEBUG[5869] app_macro.c: Executed application: Playback
[Mar 9 01:32:53] DEBUG[5869] pbx.c: Launching 'Congestion'
[Mar 9 01:32:53] VERBOSE[5869] logger.c: -- Executing [intracompany@macro-outisbusy:2] Congestion("SIP/Wiline-c8002660", "20") in new stack
[Mar 9 01:32:53] DEBUG[5869] chan_sip.c: Setting SIP_ALREADYGONE on dialog 5d8e9a9a00f41bd07a77395f308b23e6@67.207.102.185
[Mar 9 01:32:53] DEBUG[5869] channel.c: Soft-Hanging up channel 'SIP/Wiline-c8002660'
[Mar 9 01:32:53] DEBUG[5869] devicestate.c: Notification of state change to be queued on device/channel SIP/Wiline
[Mar 9 01:32:53] DEBUG[5869] app_macro.c: Spawn extension (macro-outisbusy,intracompany,2) exited non-zero on 'SIP/Wiline-c8002660' in macro 'outisbusy'
[Mar 9 01:32:53] DEBUG[5869] pbx.c: Spawn extension (from-internal,3494,6) exited non-zero on 'SIP/Wiline-c8002660'
[Mar 9 01:32:53] VERBOSE[5869] logger.c: == Spawn extension (from-internal, 3494, 6) exited non-zero on 'SIP/Wiline-c8002660'
[Mar 9 01:32:53] DEBUG[5869] channel.c: Soft-Hanging up channel 'SIP/Wiline-c8002660'
[Mar 9 01:32:53] DEBUG[5869] pbx.c: Launching 'Macro'
[Mar 9 01:32:53] VERBOSE[5869] logger.c: -- Executing [h@from-internal:1] Macro("SIP/Wiline-c8002660", "hangupcall") in new stack
[Mar 9 01:32:53] DEBUG[5869] pbx.c: Expression result is '1'
[Mar 9 01:32:53] DEBUG[5869] pbx.c: Launching 'GotoIf'
[Mar 9 01:32:53] VERBOSE[5869] logger.c: -- Executing [s@macro-hangupcall:1] GotoIf("SIP/Wiline-c8002660", "1?skiprg") in new stack
[Mar 9 01:32:53] VERBOSE[5869] logger.c: -- Goto (macro-hangupcall,s,4)
[Mar 9 01:32:53] DEBUG[5869] app_macro.c: Executed application: GotoIf
[Mar 9 01:32:53] DEBUG[5869] pbx.c: Expression result is '1'
[Mar 9 01:32:53] DEBUG[5869] pbx.c: Launching 'GotoIf'
[Mar 9 01:32:53] VERBOSE[5869] logger.c: -- Executing [s@macro-hangupcall:4] GotoIf("SIP/Wiline-c8002660", "1?skipblkvm") in new stack
[Mar 9 01:32:53] VERBOSE[5869] logger.c: -- Goto (macro-hangupcall,s,7)
[Mar 9 01:32:53] DEBUG[5869] app_macro.c: Executed application: GotoIf
[Mar 9 01:32:53] DEBUG[5869] pbx.c: Expression result is '1'
[Mar 9 01:32:53] DEBUG[5869] pbx.c: Launching 'GotoIf'
[Mar 9 01:32:53] VERBOSE[5869] logger.c: -- Executing [s@macro-hangupcall:7] GotoIf("SIP/Wiline-c8002660", "1?theend") in new stack
[Mar 9 01:32:53] VERBOSE[5869] logger.c: -- Goto (macro-hangupcall,s,9)
[Mar 9 01:32:53] DEBUG[5869] app_macro.c: Executed application: GotoIf
[Mar 9 01:32:53] DEBUG[5869] pbx.c: Launching 'Hangup'
[Mar 9 01:32:53] VERBOSE[5869] logger.c: -- Executing [s@macro-hangupcall:9] Hangup("SIP/Wiline-c8002660", "") in new stack
[Mar 9 01:32:53] DEBUG[5869] app_macro.c: Spawn extension (macro-hangupcall,s,9) exited non-zero on 'SIP/Wiline-c8002660' in macro 'hangupcall'
[Mar 9 01:32:53] DEBUG[5869] pbx.c: Spawn extension (from-internal,h,1) exited non-zero on 'SIP/Wiline-c8002660'
[Mar 9 01:32:53] VERBOSE[5869] logger.c: == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/Wiline-c8002660'
[Mar 9 01:32:53] DEBUG[5869] channel.c: Hanging up channel 'SIP/Wiline-c8002660'
[Mar 9 01:32:53] DEBUG[5869] chan_sip.c: Hangup call SIP/Wiline-c8002660, SIP callid 5d8e9a9a00f41bd07a77395f308b23e6@67.207.102.185)
[Mar 9 01:32:53] DEBUG[5869] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
[Mar 9 01:32:53] DEBUG[5869] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield) VALUES ('2011-03-09 01:32:38','\"6502748970\" <6502748970>','6502748970','3494','from-internal', 'SIP/Wiline-c8002660','IAX2/phpbx01-16385','Congestion','20',15,0,'NO ANSWER',3,'','1299663158.410','')
[Mar 9 01:32:53] DEBUG[5869] devicestate.c: Notification of state change to be queued on device/channel SIP/Wiline
 

eijob

Joined
Jul 29, 2010
Messages
43
Likes
0
Points
0
#17
Hi Dicko,

This one is the reverse, from an extension in PHPBX01 to my cellphone.

Thank you very much for your patience with me.

[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'Set'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [6502748970@from-internal:1] Set("SIP/3493-0d9b4ee0", "INTRACOMPANYROUTE=YES") in new stack
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'Macro'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [6502748970@from-internal:2] Macro("SIP/3493-0d9b4ee0", "user-callerid|SKIPTTL|") in new stack
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '1'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Function result is '3493'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Function result is '3493'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'Set'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-user-callerid:1] Set("SIP/3493-0d9b4ee0", "AMPUSER=3493") in new stack
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: Set
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '0'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'GotoIf'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-user-callerid:2] GotoIf("SIP/3493-0d9b4ee0", "0?report") in new stack
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Not taking any branch
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: GotoIf
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '1'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Function result is '3493'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'ExecIf'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-user-callerid:3] ExecIf("SIP/3493-0d9b4ee0", "1|Set|REALCALLERIDNUM=3493") in new stack
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: ExecIf
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '0'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Function result is '3493'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Function result is '3493'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'Set'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-user-callerid:4] Set("SIP/3493-0d9b4ee0", "AMPUSER=3493") in new stack
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: Set
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Function result is 'Frank B'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'Set'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-user-callerid:5] Set("SIP/3493-0d9b4ee0", "AMPUSERCIDNAME=Frank B") in new stack
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: Set
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '0'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'GotoIf'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-user-callerid:6] GotoIf("SIP/3493-0d9b4ee0", "0?report") in new stack
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Not taking any branch
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: GotoIf
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Function result is '1'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '1'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Function result is '3493'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'Set'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-user-callerid:7] Set("SIP/3493-0d9b4ee0", "AMPUSERCID=3493") in new stack
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: Set
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'Set'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-user-callerid:8] Set("SIP/3493-0d9b4ee0", "CALLERID(all)="Frank B" <3493>") in new stack
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: Set
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Function result is ''
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '0'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Function result is ''
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'ExecIf'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-user-callerid:9] ExecIf("SIP/3493-0d9b4ee0", "0|Set|CHANNEL(language)=") in new stack
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: ExecIf
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Function result is ''
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '0'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Function result is ''
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '1'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'GotoIf'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-user-callerid:10] GotoIf("SIP/3493-0d9b4ee0", "1?continue") in new stack
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Goto (macro-user-callerid,s,19)
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: GotoIf
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Function result is '3493'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'Set'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-user-callerid:19] Set("SIP/3493-0d9b4ee0", "CALLERID(number)=3493") in new stack
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: Set
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Function result is 'Frank B'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'Set'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-user-callerid:20] Set("SIP/3493-0d9b4ee0", "CALLERID(name)=Frank B") in new stack
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: Set
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Function result is '"Frank B" <3493>'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'NoOp'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-user-callerid:21] NoOp("SIP/3493-0d9b4ee0", "Using CallerID "Frank B" <3493>") in new stack
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: Noop
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'Set'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [6502748970@from-internal:3] Set("SIP/3493-0d9b4ee0", "_NODEST=") in new stack
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'Macro'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [6502748970@from-internal:4] Macro("SIP/3493-0d9b4ee0", "record-enable|3493|OUT|") in new stack
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '1'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'GotoIf'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-record-enable:1] GotoIf("SIP/3493-0d9b4ee0", "1?check") in new stack
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Goto (macro-record-enable,s,4)
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: GotoIf
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Function result is '20110309-014314'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'AGI'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-record-enable:4] AGI("SIP/3493-0d9b4ee0", "recordingcheck|20110309-014314|1299663794.496") in new stack
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
[Mar 9 01:43:14] VERBOSE[6418] logger.c: recordingcheck|20110309-014314|1299663794.496: Outbound recording enabled.
[Mar 9 01:43:14] VERBOSE[6418] logger.c: recordingcheck|20110309-014314|1299663794.496: CALLFILENAME=OUT3493-20110309-014314-1299663794.496
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- AGI Script recordingcheck completed, returning 0
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: AGI
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'MixMonitor'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-record-enable:999] MixMonitor("SIP/3493-0d9b4ee0", "OUT3493-20110309-014314-1299663794.496.gsm||") in new stack
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: MixMonitor
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'Macro'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [6502748970@from-internal:5] Macro("SIP/3493-0d9b4ee0", "dialout-trunk|2|6502748970||") in new stack
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'Set'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-dialout-trunk:1] Set("SIP/3493-0d9b4ee0", "DIAL_TRUNK=2") in new stack
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: Set
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '0'
[Mar 9 01:43:14] DEBUG[6418] db.c: Unable to find key '3493/pinless' in family 'AMPUSER'
[Mar 9 01:43:14] DEBUG[6418] func_db.c: DB: AMPUSER/3493/pinless not found in database.
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Function result is ''
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '1'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '0'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'GosubIf'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-dialout-trunk:2] GosubIf("SIP/3493-0d9b4ee0", "0?sub-pincheck|s|1") in new stack
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: GosubIf
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '0'
[Mar 9 01:43:14] DEBUG[6418] db.c: Unable to find key '3493/pinless' in family 'AMPUSER'
[Mar 9 01:43:14] DEBUG[6418] func_db.c: DB: AMPUSER/3493/pinless not found in database.
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Function result is ''
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '1'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '0'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '0'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'GotoIf'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-dialout-trunk:3] GotoIf("SIP/3493-0d9b4ee0", "0?disabletrunk|1") in new stack
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Not taking any branch
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: GotoIf
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'Set'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-dialout-trunk:4] Set("SIP/3493-0d9b4ee0", "DIAL_NUMBER=6502748970") in new stack
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: Set
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'Set'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-dialout-trunk:5] Set("SIP/3493-0d9b4ee0", "DIAL_TRUNK_OPTIONS=tr") in new stack
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: Set
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'Set'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-dialout-trunk:6] Set("SIP/3493-0d9b4ee0", "OUTBOUND_GROUP=OUT_2") in new stack
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: Set
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '1'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'GotoIf'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-dialout-trunk:7] GotoIf("SIP/3493-0d9b4ee0", "1?nomax") in new stack
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Goto (macro-dialout-trunk,s,9)
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: GotoIf
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '1'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'GotoIf'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-dialout-trunk:9] GotoIf("SIP/3493-0d9b4ee0", "1?skipoutcid") in new stack
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Goto (macro-dialout-trunk,s,12)
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: GotoIf
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '0'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'ExecIf'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-dialout-trunk:12] ExecIf("SIP/3493-0d9b4ee0", "0|AGI|fixlocalprefix") in new stack
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: ExecIf
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '0'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'Set'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-dialout-trunk:13] Set("SIP/3493-0d9b4ee0", "OUTNUM=6502748970") in new stack
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: Set
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Function result is 'IAX2/uspbx01'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'Set'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-dialout-trunk:14] Set("SIP/3493-0d9b4ee0", "custom=IAX2/uspbx01") in new stack
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: Set
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '1'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '0'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '0'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'ExecIf'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-dialout-trunk:15] ExecIf("SIP/3493-0d9b4ee0", "0|Set|DIAL_TRUNK_OPTIONS=M(setmusic^)tr") in new stack
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: ExecIf
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '1'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '0'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '0'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'Macro'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-dialout-trunk:16] Macro("SIP/3493-0d9b4ee0", "dialout-trunk-predial-hook|") in new stack
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'MacroExit'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("SIP/3493-0d9b4ee0", "") in new stack
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: Macro
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '0'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'GotoIf'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-dialout-trunk:17] GotoIf("SIP/3493-0d9b4ee0", "0?bypass|1") in new stack
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Not taking any branch
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: GotoIf
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '0'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'GotoIf'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-dialout-trunk:18] GotoIf("SIP/3493-0d9b4ee0", "0?customtrunk") in new stack
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Not taking any branch
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: GotoIf
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'Dial'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-dialout-trunk:19] Dial("SIP/3493-0d9b4ee0", "IAX2/uspbx01/6502748970|300|tr") in new stack
[Mar 9 01:43:14] NOTICE[6418] app_dial.c: Hey! chan SIP/3493-0d9b4ee0's context='macro-dialout-trunk', and exten='s'
[Mar 9 01:43:14] DEBUG[6418] chan_iax2.c: Made call 2666 into trunk call 16384
[Mar 9 01:43:14] DEBUG[6418] rtp.c: Channel 'IAX2/uspbx01-16384' has no RTP, not doing anything
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable DIALEDTIME.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable ANSWEREDTIME.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable DIALEDPEERNAME.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable DIALEDPEERNUMBER.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable DIALSTATUS.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable MACRO_DEPTH.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable MACRO_PRIORITY.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable MACRO_CONTEXT.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable MACRO_EXTEN.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable ARG1.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable custom.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable OUTNUM.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable OUTBOUND_GROUP.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable DIAL_TRUNK_OPTIONS.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable DIAL_NUMBER.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable DIAL_TRUNK.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable ARG4.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable ARG3.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable ARG2.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable MIXMONITOR_FILENAME.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable AGISTATUS.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable CALLFILENAME.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Copying soft-transferable variable NODEST.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable DB_RESULT.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable AMPUSERCID.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable AMPUSERCIDNAME.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable AMPUSER.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable REALCALLERIDNUM.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable INTRACOMPANYROUTE.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable SIPCALLID.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable SIPUSERAGENT.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable SIPDOMAIN.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable SIPURI.
[Mar 9 01:43:14] DEBUG[6418] chan_iax2.c: prepending 100 to prefs
[Mar 9 01:43:14] DEBUG[6418] devicestate.c: Notification of state change to be queued on device/channel IAX2/uspbx01
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Called uspbx01/6502748970
[Mar 9 01:43:25] DEBUG[6418] channel.c: Hanging up channel 'IAX2/uspbx01-16384'
[Mar 9 01:43:25] DEBUG[6418] chan_iax2.c: We're hanging up IAX2/uspbx01-16384 now...
[Mar 9 01:43:25] VERBOSE[6418] logger.c: -- Hungup 'IAX2/uspbx01-16384'
[Mar 9 01:43:25] DEBUG[6418] devicestate.c: Notification of state change to be queued on device/channel IAX2/uspbx01
[Mar 9 01:43:25] VERBOSE[6418] logger.c: == Everyone is busy/congested at this time (1:0/0/1)
[Mar 9 01:43:25] DEBUG[6418] rtp.c: Channel '<unspecified>' has no RTP, not doing anything
[Mar 9 01:43:25] DEBUG[6418] app_dial.c: Exiting with DIALSTATUS=CHANUNAVAIL.
[Mar 9 01:43:25] DEBUG[6418] app_macro.c: Executed application: Dial
[Mar 9 01:43:25] DEBUG[6418] pbx.c: Launching 'Goto'
[Mar 9 01:43:25] VERBOSE[6418] logger.c: -- Executing [s@macro-dialout-trunk:20] Goto("SIP/3493-0d9b4ee0", "s-CHANUNAVAIL|1") in new stack
[Mar 9 01:43:25] VERBOSE[6418] logger.c: -- Goto (macro-dialout-trunk,s-CHANUNAVAIL,1)
[Mar 9 01:43:25] DEBUG[6418] app_macro.c: Executed application: Goto
[Mar 9 01:43:25] DEBUG[6418] pbx.c: Expression result is '1'
[Mar 9 01:43:25] DEBUG[6418] pbx.c: Launching 'GotoIf'
[Mar 9 01:43:25] VERBOSE[6418] logger.c: -- Executing [s-CHANUNAVAIL@macro-dialout-trunk:1] GotoIf("SIP/3493-0d9b4ee0", "1?noreport") in new stack
[Mar 9 01:43:25] VERBOSE[6418] logger.c: -- Goto (macro-dialout-trunk,s-CHANUNAVAIL,3)
[Mar 9 01:43:25] DEBUG[6418] app_macro.c: Executed application: GotoIf
[Mar 9 01:43:25] DEBUG[6418] pbx.c: Launching 'NoOp'
[Mar 9 01:43:25] VERBOSE[6418] logger.c: -- Executing [s-CHANUNAVAIL@macro-dialout-trunk:3] NoOp("SIP/3493-0d9b4ee0", "TRUNK Dial failed due to CHANUNAVAIL (hangupcause: 0) - failing through to other trunks") in new stack
[Mar 9 01:43:25] DEBUG[6418] app_macro.c: Executed application: Noop
[Mar 9 01:43:25] DEBUG[6418] pbx.c: Launching 'Macro'
[Mar 9 01:43:25] VERBOSE[6418] logger.c: -- Executing [6502748970@from-internal:6] Macro("SIP/3493-0d9b4ee0", "outisbusy|") in new stack
[Mar 9 01:43:25] DEBUG[6418] pbx.c: Expression result is '0'
[Mar 9 01:43:25] DEBUG[6418] pbx.c: Launching 'GotoIf'
[Mar 9 01:43:25] VERBOSE[6418] logger.c: -- Executing [s@macro-outisbusy:1] GotoIf("SIP/3493-0d9b4ee0", "0?emergency|1") in new stack
[Mar 9 01:43:25] DEBUG[6418] pbx.c: Not taking any branch
[Mar 9 01:43:25] DEBUG[6418] app_macro.c: Executed application: GotoIf
[Mar 9 01:43:25] DEBUG[6418] pbx.c: Expression result is '1'
[Mar 9 01:43:25] DEBUG[6418] pbx.c: Launching 'GotoIf'
[Mar 9 01:43:25] VERBOSE[6418] logger.c: -- Executing [s@macro-outisbusy:2] GotoIf("SIP/3493-0d9b4ee0", "1?intracompany|1") in new stack
[Mar 9 01:43:25] VERBOSE[6418] logger.c: -- Goto (macro-outisbusy,intracompany,1)
[Mar 9 01:43:25] DEBUG[6418] app_macro.c: Executed application: GotoIf
[Mar 9 01:43:25] DEBUG[6418] pbx.c: Launching 'Playback'
[Mar 9 01:43:25] VERBOSE[6418] logger.c: -- Executing [intracompany@macro-outisbusy:1] Playback("SIP/3493-0d9b4ee0", "all-circuits-busy-now&pls-try-call-later| noanswer") in new stack
[Mar 9 01:43:25] DEBUG[6418] channel.c: Set channel SIP/3493-0d9b4ee0 to write format gsm
[Mar 9 01:43:25] DEBUG[6418] chan_sip.c: Setting framing from config on incoming call
[Mar 9 01:43:25] DEBUG[6418] chan_sip.c: ** Our capability: 0xc (ulaw|alaw) Video flag: True
[Mar 9 01:43:25] DEBUG[6418] chan_sip.c: ** Our prefcodec: 0x0 (nothing)
[Mar 9 01:43:25] DEBUG[6418] chan_sip.c: -- Done with adding codecs to SDP
[Mar 9 01:43:25] DEBUG[6418] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23)
[Mar 9 01:43:25] DEBUG[6418] chan_sip.c: Done building SDP. Settling with this capability: 0xc (ulaw|alaw)
[Mar 9 01:43:25] DEBUG[6418] channel.c: Scheduling timer at 160 sample intervals
[Mar 9 01:43:25] VERBOSE[6418] logger.c: -- <SIP/3493-0d9b4ee0> Playing 'all-circuits-busy-now' (language 'en')
[Mar 9 01:43:25] DEBUG[6418] rtp.c: Ooh, format changed from unknown to ulaw
[Mar 9 01:43:25] DEBUG[6418] rtp.c: Created smoother: format: 4 ms: 20 len: 160
[Mar 9 01:43:25] DEBUG[6418] rtp.c: Got RTCP report of 88 bytes
[Mar 9 01:43:26] DEBUG[6418] channel.c: Scheduling timer at 0 sample intervals
[Mar 9 01:43:26] DEBUG[6418] channel.c: Scheduling timer at 0 sample intervals
[Mar 9 01:43:26] DEBUG[6418] channel.c: Set channel SIP/3493-0d9b4ee0 to write format ulaw
[Mar 9 01:43:26] DEBUG[6418] channel.c: Set channel SIP/3493-0d9b4ee0 to write format gsm
[Mar 9 01:43:26] DEBUG[6418] channel.c: Scheduling timer at 160 sample intervals
[Mar 9 01:43:26] VERBOSE[6418] logger.c: -- <SIP/3493-0d9b4ee0> Playing 'pls-try-call-later' (language 'en')
[Mar 9 01:43:29] DEBUG[6418] channel.c: Scheduling timer at 0 sample intervals
[Mar 9 01:43:29] DEBUG[6418] channel.c: Scheduling timer at 0 sample intervals
[Mar 9 01:43:29] DEBUG[6418] channel.c: Set channel SIP/3493-0d9b4ee0 to write format ulaw
[Mar 9 01:43:29] DEBUG[6418] app_macro.c: Executed application: Playback
[Mar 9 01:43:29] DEBUG[6418] pbx.c: Launching 'Congestion'
[Mar 9 01:43:29] VERBOSE[6418] logger.c: -- Executing [intracompany@macro-outisbusy:2] Congestion("SIP/3493-0d9b4ee0", "20") in new stack
[Mar 9 01:43:29] DEBUG[6418] chan_sip.c: Setting SIP_ALREADYGONE on dialog d29f112e-7e966148-66859ad5@10.32.7.245
[Mar 9 01:43:29] DEBUG[6418] channel.c: Soft-Hanging up channel 'SIP/3493-0d9b4ee0'
[Mar 9 01:43:29] DEBUG[6418] devicestate.c: Notification of state change to be queued on device/channel SIP/3493
[Mar 9 01:43:29] DEBUG[6418] app_macro.c: Spawn extension (macro-outisbusy,intracompany,2) exited non-zero on 'SIP/3493-0d9b4ee0' in macro 'outisbusy'
[Mar 9 01:43:29] DEBUG[6418] pbx.c: Spawn extension (from-internal,6502748970,6) exited non-zero on 'SIP/3493-0d9b4ee0'
[Mar 9 01:43:29] VERBOSE[6418] logger.c: == Spawn extension (from-internal, 6502748970, 6) exited non-zero on 'SIP/3493-0d9b4ee0'
[Mar 9 01:43:29] DEBUG[6418] channel.c: Soft-Hanging up channel 'SIP/3493-0d9b4ee0'
[Mar 9 01:43:29] DEBUG[6418] pbx.c: Launching 'Macro'
[Mar 9 01:43:29] VERBOSE[6418] logger.c: -- Executing [h@from-internal:1] Macro("SIP/3493-0d9b4ee0", "hangupcall") in new stack
[Mar 9 01:43:29] DEBUG[6418] pbx.c: Expression result is '1'
[Mar 9 01:43:29] DEBUG[6418] pbx.c: Launching 'GotoIf'
[Mar 9 01:43:29] VERBOSE[6418] logger.c: -- Executing [s@macro-hangupcall:1] GotoIf("SIP/3493-0d9b4ee0", "1?skiprg") in new stack
[Mar 9 01:43:29] VERBOSE[6418] logger.c: -- Goto (macro-hangupcall,s,4)
[Mar 9 01:43:29] DEBUG[6418] app_macro.c: Executed application: GotoIf
[Mar 9 01:43:29] DEBUG[6418] pbx.c: Expression result is '1'
[Mar 9 01:43:29] DEBUG[6418] pbx.c: Launching 'GotoIf'
[Mar 9 01:43:29] VERBOSE[6418] logger.c: -- Executing [s@macro-hangupcall:4] GotoIf("SIP/3493-0d9b4ee0", "1?skipblkvm") in new stack
[Mar 9 01:43:29] VERBOSE[6418] logger.c: -- Goto (macro-hangupcall,s,7)
[Mar 9 01:43:29] DEBUG[6418] app_macro.c: Executed application: GotoIf
[Mar 9 01:43:29] DEBUG[6418] pbx.c: Expression result is '1'
[Mar 9 01:43:29] DEBUG[6418] pbx.c: Launching 'GotoIf'
[Mar 9 01:43:29] VERBOSE[6418] logger.c: -- Executing [s@macro-hangupcall:7] GotoIf("SIP/3493-0d9b4ee0", "1?theend") in new stack
[Mar 9 01:43:29] VERBOSE[6418] logger.c: -- Goto (macro-hangupcall,s,9)
[Mar 9 01:43:29] DEBUG[6418] app_macro.c: Executed application: GotoIf
[Mar 9 01:43:29] DEBUG[6418] pbx.c: Launching 'Hangup'
[Mar 9 01:43:29] VERBOSE[6418] logger.c: -- Executing [s@macro-hangupcall:9] Hangup("SIP/3493-0d9b4ee0", "") in new stack
[Mar 9 01:43:29] DEBUG[6418] app_macro.c: Spawn extension (macro-hangupcall,s,9) exited non-zero on 'SIP/3493-0d9b4ee0' in macro 'hangupcall'
[Mar 9 01:43:29] DEBUG[6418] pbx.c: Spawn extension (from-internal,h,1) exited non-zero on 'SIP/3493-0d9b4ee0'
[Mar 9 01:43:29] VERBOSE[6418] logger.c: == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/3493-0d9b4ee0'
[Mar 9 01:43:29] DEBUG[6418] channel.c: Hanging up channel 'SIP/3493-0d9b4ee0'
[Mar 9 01:43:29] DEBUG[6418] chan_sip.c: Hangup call SIP/3493-0d9b4ee0, SIP callid d29f112e-7e966148-66859ad5@10.32.7.245)
[Mar 9 01:43:29] DEBUG[6418] chan_sip.c: Updating call counter for incoming call
[Mar 9 01:43:29] DEBUG[6418] chan_sip.c: Call from peer '3493' removed from call limit 50
[Mar 9 01:43:29] DEBUG[6418] devicestate.c: Notification of state change to be queued on device/channel SIP/3493
[Mar 9 01:43:29] DEBUG[6418] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
[Mar 9 01:43:29] DEBUG[6418] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield) VALUES ('2011-03-09 01:43:14','\"Frank B\" <3493>','3493','6502748970','from-internal', 'SIP/3493-0d9b4ee0','IAX2/uspbx01-16384','Congestion','20',15,0,'NO ANSWER',3,'','1299663794.496','')
[Mar 9 01:43:29] DEBUG[6418] devicestate.c: Notification of state change to be queued on device/channel SIP/3493
 

eijob

Joined
Jul 29, 2010
Messages
43
Likes
0
Points
0
#18
Hi Dicko,

This one is the reverse, from an extension in PHPBX01 to my cellphone.

Thank you very much for your patience with me.

[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'Set'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [6502748970@from-internal:1] Set("SIP/3493-0d9b4ee0", "INTRACOMPANYROUTE=YES") in new stack
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'Macro'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [6502748970@from-internal:2] Macro("SIP/3493-0d9b4ee0", "user-callerid|SKIPTTL|") in new stack
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '1'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Function result is '3493'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Function result is '3493'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'Set'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-user-callerid:1] Set("SIP/3493-0d9b4ee0", "AMPUSER=3493") in new stack
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: Set
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '0'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'GotoIf'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-user-callerid:2] GotoIf("SIP/3493-0d9b4ee0", "0?report") in new stack
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Not taking any branch
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: GotoIf
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '1'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Function result is '3493'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'ExecIf'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-user-callerid:3] ExecIf("SIP/3493-0d9b4ee0", "1|Set|REALCALLERIDNUM=3493") in new stack
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: ExecIf
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '0'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Function result is '3493'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Function result is '3493'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'Set'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-user-callerid:4] Set("SIP/3493-0d9b4ee0", "AMPUSER=3493") in new stack
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: Set
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Function result is 'Frank B'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'Set'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-user-callerid:5] Set("SIP/3493-0d9b4ee0", "AMPUSERCIDNAME=Frank B") in new stack
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: Set
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '0'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'GotoIf'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-user-callerid:6] GotoIf("SIP/3493-0d9b4ee0", "0?report") in new stack
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Not taking any branch
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: GotoIf
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Function result is '1'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '1'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Function result is '3493'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'Set'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-user-callerid:7] Set("SIP/3493-0d9b4ee0", "AMPUSERCID=3493") in new stack
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: Set
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'Set'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-user-callerid:8] Set("SIP/3493-0d9b4ee0", "CALLERID(all)="Frank B" <3493>") in new stack
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: Set
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Function result is ''
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '0'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Function result is ''
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'ExecIf'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-user-callerid:9] ExecIf("SIP/3493-0d9b4ee0", "0|Set|CHANNEL(language)=") in new stack
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: ExecIf
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Function result is ''
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '0'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Function result is ''
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '1'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'GotoIf'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-user-callerid:10] GotoIf("SIP/3493-0d9b4ee0", "1?continue") in new stack
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Goto (macro-user-callerid,s,19)
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: GotoIf
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Function result is '3493'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'Set'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-user-callerid:19] Set("SIP/3493-0d9b4ee0", "CALLERID(number)=3493") in new stack
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: Set
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Function result is 'Frank B'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'Set'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-user-callerid:20] Set("SIP/3493-0d9b4ee0", "CALLERID(name)=Frank B") in new stack
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: Set
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Function result is '"Frank B" <3493>'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'NoOp'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-user-callerid:21] NoOp("SIP/3493-0d9b4ee0", "Using CallerID "Frank B" <3493>") in new stack
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: Noop
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'Set'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [6502748970@from-internal:3] Set("SIP/3493-0d9b4ee0", "_NODEST=") in new stack
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'Macro'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [6502748970@from-internal:4] Macro("SIP/3493-0d9b4ee0", "record-enable|3493|OUT|") in new stack
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '1'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'GotoIf'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-record-enable:1] GotoIf("SIP/3493-0d9b4ee0", "1?check") in new stack
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Goto (macro-record-enable,s,4)
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: GotoIf
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Function result is '20110309-014314'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'AGI'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-record-enable:4] AGI("SIP/3493-0d9b4ee0", "recordingcheck|20110309-014314|1299663794.496") in new stack
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
[Mar 9 01:43:14] VERBOSE[6418] logger.c: recordingcheck|20110309-014314|1299663794.496: Outbound recording enabled.
[Mar 9 01:43:14] VERBOSE[6418] logger.c: recordingcheck|20110309-014314|1299663794.496: CALLFILENAME=OUT3493-20110309-014314-1299663794.496
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- AGI Script recordingcheck completed, returning 0
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: AGI
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'MixMonitor'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-record-enable:999] MixMonitor("SIP/3493-0d9b4ee0", "OUT3493-20110309-014314-1299663794.496.gsm||") in new stack
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: MixMonitor
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'Macro'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [6502748970@from-internal:5] Macro("SIP/3493-0d9b4ee0", "dialout-trunk|2|6502748970||") in new stack
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'Set'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-dialout-trunk:1] Set("SIP/3493-0d9b4ee0", "DIAL_TRUNK=2") in new stack
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: Set
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '0'
[Mar 9 01:43:14] DEBUG[6418] db.c: Unable to find key '3493/pinless' in family 'AMPUSER'
[Mar 9 01:43:14] DEBUG[6418] func_db.c: DB: AMPUSER/3493/pinless not found in database.
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Function result is ''
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '1'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '0'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'GosubIf'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-dialout-trunk:2] GosubIf("SIP/3493-0d9b4ee0", "0?sub-pincheck|s|1") in new stack
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: GosubIf
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '0'
[Mar 9 01:43:14] DEBUG[6418] db.c: Unable to find key '3493/pinless' in family 'AMPUSER'
[Mar 9 01:43:14] DEBUG[6418] func_db.c: DB: AMPUSER/3493/pinless not found in database.
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Function result is ''
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '1'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '0'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '0'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'GotoIf'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-dialout-trunk:3] GotoIf("SIP/3493-0d9b4ee0", "0?disabletrunk|1") in new stack
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Not taking any branch
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: GotoIf
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'Set'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-dialout-trunk:4] Set("SIP/3493-0d9b4ee0", "DIAL_NUMBER=6502748970") in new stack
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: Set
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'Set'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-dialout-trunk:5] Set("SIP/3493-0d9b4ee0", "DIAL_TRUNK_OPTIONS=tr") in new stack
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: Set
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'Set'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-dialout-trunk:6] Set("SIP/3493-0d9b4ee0", "OUTBOUND_GROUP=OUT_2") in new stack
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: Set
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '1'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'GotoIf'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-dialout-trunk:7] GotoIf("SIP/3493-0d9b4ee0", "1?nomax") in new stack
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Goto (macro-dialout-trunk,s,9)
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: GotoIf
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '1'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'GotoIf'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-dialout-trunk:9] GotoIf("SIP/3493-0d9b4ee0", "1?skipoutcid") in new stack
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Goto (macro-dialout-trunk,s,12)
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: GotoIf
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '0'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'ExecIf'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-dialout-trunk:12] ExecIf("SIP/3493-0d9b4ee0", "0|AGI|fixlocalprefix") in new stack
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: ExecIf
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '0'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'Set'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-dialout-trunk:13] Set("SIP/3493-0d9b4ee0", "OUTNUM=6502748970") in new stack
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: Set
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Function result is 'IAX2/uspbx01'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'Set'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-dialout-trunk:14] Set("SIP/3493-0d9b4ee0", "custom=IAX2/uspbx01") in new stack
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: Set
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '1'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '0'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '0'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'ExecIf'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-dialout-trunk:15] ExecIf("SIP/3493-0d9b4ee0", "0|Set|DIAL_TRUNK_OPTIONS=M(setmusic^)tr") in new stack
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: ExecIf
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '1'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '0'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '0'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'Macro'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-dialout-trunk:16] Macro("SIP/3493-0d9b4ee0", "dialout-trunk-predial-hook|") in new stack
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'MacroExit'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("SIP/3493-0d9b4ee0", "") in new stack
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: Macro
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '0'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'GotoIf'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-dialout-trunk:17] GotoIf("SIP/3493-0d9b4ee0", "0?bypass|1") in new stack
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Not taking any branch
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: GotoIf
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Expression result is '0'
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'GotoIf'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-dialout-trunk:18] GotoIf("SIP/3493-0d9b4ee0", "0?customtrunk") in new stack
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Not taking any branch
[Mar 9 01:43:14] DEBUG[6418] app_macro.c: Executed application: GotoIf
[Mar 9 01:43:14] DEBUG[6418] pbx.c: Launching 'Dial'
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Executing [s@macro-dialout-trunk:19] Dial("SIP/3493-0d9b4ee0", "IAX2/uspbx01/6502748970|300|tr") in new stack
[Mar 9 01:43:14] NOTICE[6418] app_dial.c: Hey! chan SIP/3493-0d9b4ee0's context='macro-dialout-trunk', and exten='s'
[Mar 9 01:43:14] DEBUG[6418] chan_iax2.c: Made call 2666 into trunk call 16384
[Mar 9 01:43:14] DEBUG[6418] rtp.c: Channel 'IAX2/uspbx01-16384' has no RTP, not doing anything
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable DIALEDTIME.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable ANSWEREDTIME.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable DIALEDPEERNAME.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable DIALEDPEERNUMBER.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable DIALSTATUS.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable MACRO_DEPTH.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable MACRO_PRIORITY.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable MACRO_CONTEXT.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable MACRO_EXTEN.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable ARG1.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable custom.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable OUTNUM.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable OUTBOUND_GROUP.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable DIAL_TRUNK_OPTIONS.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable DIAL_NUMBER.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable DIAL_TRUNK.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable ARG4.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable ARG3.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable ARG2.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable MIXMONITOR_FILENAME.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable AGISTATUS.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable CALLFILENAME.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Copying soft-transferable variable NODEST.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable DB_RESULT.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable AMPUSERCID.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable AMPUSERCIDNAME.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable AMPUSER.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable REALCALLERIDNUM.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable INTRACOMPANYROUTE.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable SIPCALLID.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable SIPUSERAGENT.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable SIPDOMAIN.
[Mar 9 01:43:14] DEBUG[6418] channel.c: Not copying variable SIPURI.
[Mar 9 01:43:14] DEBUG[6418] chan_iax2.c: prepending 100 to prefs
[Mar 9 01:43:14] DEBUG[6418] devicestate.c: Notification of state change to be queued on device/channel IAX2/uspbx01
[Mar 9 01:43:14] VERBOSE[6418] logger.c: -- Called uspbx01/6502748970
[Mar 9 01:43:25] DEBUG[6418] channel.c: Hanging up channel 'IAX2/uspbx01-16384'
[Mar 9 01:43:25] DEBUG[6418] chan_iax2.c: We're hanging up IAX2/uspbx01-16384 now...
[Mar 9 01:43:25] VERBOSE[6418] logger.c: -- Hungup 'IAX2/uspbx01-16384'
[Mar 9 01:43:25] DEBUG[6418] devicestate.c: Notification of state change to be queued on device/channel IAX2/uspbx01
[Mar 9 01:43:25] VERBOSE[6418] logger.c: == Everyone is busy/congested at this time (1:0/0/1)
[Mar 9 01:43:25] DEBUG[6418] rtp.c: Channel '<unspecified>' has no RTP, not doing anything
[Mar 9 01:43:25] DEBUG[6418] app_dial.c: Exiting with DIALSTATUS=CHANUNAVAIL.
[Mar 9 01:43:25] DEBUG[6418] app_macro.c: Executed application: Dial
[Mar 9 01:43:25] DEBUG[6418] pbx.c: Launching 'Goto'
[Mar 9 01:43:25] VERBOSE[6418] logger.c: -- Executing [s@macro-dialout-trunk:20] Goto("SIP/3493-0d9b4ee0", "s-CHANUNAVAIL|1") in new stack
[Mar 9 01:43:25] VERBOSE[6418] logger.c: -- Goto (macro-dialout-trunk,s-CHANUNAVAIL,1)
[Mar 9 01:43:25] DEBUG[6418] app_macro.c: Executed application: Goto
[Mar 9 01:43:25] DEBUG[6418] pbx.c: Expression result is '1'
[Mar 9 01:43:25] DEBUG[6418] pbx.c: Launching 'GotoIf'
[Mar 9 01:43:25] VERBOSE[6418] logger.c: -- Executing [s-CHANUNAVAIL@macro-dialout-trunk:1] GotoIf("SIP/3493-0d9b4ee0", "1?noreport") in new stack
[Mar 9 01:43:25] VERBOSE[6418] logger.c: -- Goto (macro-dialout-trunk,s-CHANUNAVAIL,3)
[Mar 9 01:43:25] DEBUG[6418] app_macro.c: Executed application: GotoIf
[Mar 9 01:43:25] DEBUG[6418] pbx.c: Launching 'NoOp'
[Mar 9 01:43:25] VERBOSE[6418] logger.c: -- Executing [s-CHANUNAVAIL@macro-dialout-trunk:3] NoOp("SIP/3493-0d9b4ee0", "TRUNK Dial failed due to CHANUNAVAIL (hangupcause: 0) - failing through to other trunks") in new stack
[Mar 9 01:43:25] DEBUG[6418] app_macro.c: Executed application: Noop
[Mar 9 01:43:25] DEBUG[6418] pbx.c: Launching 'Macro'
[Mar 9 01:43:25] VERBOSE[6418] logger.c: -- Executing [6502748970@from-internal:6] Macro("SIP/3493-0d9b4ee0", "outisbusy|") in new stack
[Mar 9 01:43:25] DEBUG[6418] pbx.c: Expression result is '0'
[Mar 9 01:43:25] DEBUG[6418] pbx.c: Launching 'GotoIf'
[Mar 9 01:43:25] VERBOSE[6418] logger.c: -- Executing [s@macro-outisbusy:1] GotoIf("SIP/3493-0d9b4ee0", "0?emergency|1") in new stack
[Mar 9 01:43:25] DEBUG[6418] pbx.c: Not taking any branch
[Mar 9 01:43:25] DEBUG[6418] app_macro.c: Executed application: GotoIf
[Mar 9 01:43:25] DEBUG[6418] pbx.c: Expression result is '1'
[Mar 9 01:43:25] DEBUG[6418] pbx.c: Launching 'GotoIf'
[Mar 9 01:43:25] VERBOSE[6418] logger.c: -- Executing [s@macro-outisbusy:2] GotoIf("SIP/3493-0d9b4ee0", "1?intracompany|1") in new stack
[Mar 9 01:43:25] VERBOSE[6418] logger.c: -- Goto (macro-outisbusy,intracompany,1)
[Mar 9 01:43:25] DEBUG[6418] app_macro.c: Executed application: GotoIf
[Mar 9 01:43:25] DEBUG[6418] pbx.c: Launching 'Playback'
[Mar 9 01:43:25] VERBOSE[6418] logger.c: -- Executing [intracompany@macro-outisbusy:1] Playback("SIP/3493-0d9b4ee0", "all-circuits-busy-now&pls-try-call-later| noanswer") in new stack
[Mar 9 01:43:25] DEBUG[6418] channel.c: Set channel SIP/3493-0d9b4ee0 to write format gsm
[Mar 9 01:43:25] DEBUG[6418] chan_sip.c: Setting framing from config on incoming call
[Mar 9 01:43:25] DEBUG[6418] chan_sip.c: ** Our capability: 0xc (ulaw|alaw) Video flag: True
[Mar 9 01:43:25] DEBUG[6418] chan_sip.c: ** Our prefcodec: 0x0 (nothing)
[Mar 9 01:43:25] DEBUG[6418] chan_sip.c: -- Done with adding codecs to SDP
[Mar 9 01:43:25] DEBUG[6418] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23)
[Mar 9 01:43:25] DEBUG[6418] chan_sip.c: Done building SDP. Settling with this capability: 0xc (ulaw|alaw)
[Mar 9 01:43:25] DEBUG[6418] channel.c: Scheduling timer at 160 sample intervals
[Mar 9 01:43:25] VERBOSE[6418] logger.c: -- <SIP/3493-0d9b4ee0> Playing 'all-circuits-busy-now' (language 'en')
[Mar 9 01:43:25] DEBUG[6418] rtp.c: Ooh, format changed from unknown to ulaw
[Mar 9 01:43:25] DEBUG[6418] rtp.c: Created smoother: format: 4 ms: 20 len: 160
[Mar 9 01:43:25] DEBUG[6418] rtp.c: Got RTCP report of 88 bytes
[Mar 9 01:43:26] DEBUG[6418] channel.c: Scheduling timer at 0 sample intervals
[Mar 9 01:43:26] DEBUG[6418] channel.c: Scheduling timer at 0 sample intervals
[Mar 9 01:43:26] DEBUG[6418] channel.c: Set channel SIP/3493-0d9b4ee0 to write format ulaw
[Mar 9 01:43:26] DEBUG[6418] channel.c: Set channel SIP/3493-0d9b4ee0 to write format gsm
[Mar 9 01:43:26] DEBUG[6418] channel.c: Scheduling timer at 160 sample intervals
[Mar 9 01:43:26] VERBOSE[6418] logger.c: -- <SIP/3493-0d9b4ee0> Playing 'pls-try-call-later' (language 'en')
[Mar 9 01:43:29] DEBUG[6418] channel.c: Scheduling timer at 0 sample intervals
[Mar 9 01:43:29] DEBUG[6418] channel.c: Scheduling timer at 0 sample intervals
[Mar 9 01:43:29] DEBUG[6418] channel.c: Set channel SIP/3493-0d9b4ee0 to write format ulaw
[Mar 9 01:43:29] DEBUG[6418] app_macro.c: Executed application: Playback
[Mar 9 01:43:29] DEBUG[6418] pbx.c: Launching 'Congestion'
[Mar 9 01:43:29] VERBOSE[6418] logger.c: -- Executing [intracompany@macro-outisbusy:2] Congestion("SIP/3493-0d9b4ee0", "20") in new stack
[Mar 9 01:43:29] DEBUG[6418] chan_sip.c: Setting SIP_ALREADYGONE on dialog d29f112e-7e966148-66859ad5@10.32.7.245
[Mar 9 01:43:29] DEBUG[6418] channel.c: Soft-Hanging up channel 'SIP/3493-0d9b4ee0'
[Mar 9 01:43:29] DEBUG[6418] devicestate.c: Notification of state change to be queued on device/channel SIP/3493
[Mar 9 01:43:29] DEBUG[6418] app_macro.c: Spawn extension (macro-outisbusy,intracompany,2) exited non-zero on 'SIP/3493-0d9b4ee0' in macro 'outisbusy'
[Mar 9 01:43:29] DEBUG[6418] pbx.c: Spawn extension (from-internal,6502748970,6) exited non-zero on 'SIP/3493-0d9b4ee0'
[Mar 9 01:43:29] VERBOSE[6418] logger.c: == Spawn extension (from-internal, 6502748970, 6) exited non-zero on 'SIP/3493-0d9b4ee0'
[Mar 9 01:43:29] DEBUG[6418] channel.c: Soft-Hanging up channel 'SIP/3493-0d9b4ee0'
[Mar 9 01:43:29] DEBUG[6418] pbx.c: Launching 'Macro'
[Mar 9 01:43:29] VERBOSE[6418] logger.c: -- Executing [h@from-internal:1] Macro("SIP/3493-0d9b4ee0", "hangupcall") in new stack
[Mar 9 01:43:29] DEBUG[6418] pbx.c: Expression result is '1'
[Mar 9 01:43:29] DEBUG[6418] pbx.c: Launching 'GotoIf'
[Mar 9 01:43:29] VERBOSE[6418] logger.c: -- Executing [s@macro-hangupcall:1] GotoIf("SIP/3493-0d9b4ee0", "1?skiprg") in new stack
[Mar 9 01:43:29] VERBOSE[6418] logger.c: -- Goto (macro-hangupcall,s,4)
[Mar 9 01:43:29] DEBUG[6418] app_macro.c: Executed application: GotoIf
[Mar 9 01:43:29] DEBUG[6418] pbx.c: Expression result is '1'
[Mar 9 01:43:29] DEBUG[6418] pbx.c: Launching 'GotoIf'
[Mar 9 01:43:29] VERBOSE[6418] logger.c: -- Executing [s@macro-hangupcall:4] GotoIf("SIP/3493-0d9b4ee0", "1?skipblkvm") in new stack
[Mar 9 01:43:29] VERBOSE[6418] logger.c: -- Goto (macro-hangupcall,s,7)
[Mar 9 01:43:29] DEBUG[6418] app_macro.c: Executed application: GotoIf
[Mar 9 01:43:29] DEBUG[6418] pbx.c: Expression result is '1'
[Mar 9 01:43:29] DEBUG[6418] pbx.c: Launching 'GotoIf'
[Mar 9 01:43:29] VERBOSE[6418] logger.c: -- Executing [s@macro-hangupcall:7] GotoIf("SIP/3493-0d9b4ee0", "1?theend") in new stack
[Mar 9 01:43:29] VERBOSE[6418] logger.c: -- Goto (macro-hangupcall,s,9)
[Mar 9 01:43:29] DEBUG[6418] app_macro.c: Executed application: GotoIf
[Mar 9 01:43:29] DEBUG[6418] pbx.c: Launching 'Hangup'
[Mar 9 01:43:29] VERBOSE[6418] logger.c: -- Executing [s@macro-hangupcall:9] Hangup("SIP/3493-0d9b4ee0", "") in new stack
[Mar 9 01:43:29] DEBUG[6418] app_macro.c: Spawn extension (macro-hangupcall,s,9) exited non-zero on 'SIP/3493-0d9b4ee0' in macro 'hangupcall'
[Mar 9 01:43:29] DEBUG[6418] pbx.c: Spawn extension (from-internal,h,1) exited non-zero on 'SIP/3493-0d9b4ee0'
[Mar 9 01:43:29] VERBOSE[6418] logger.c: == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/3493-0d9b4ee0'
[Mar 9 01:43:29] DEBUG[6418] channel.c: Hanging up channel 'SIP/3493-0d9b4ee0'
[Mar 9 01:43:29] DEBUG[6418] chan_sip.c: Hangup call SIP/3493-0d9b4ee0, SIP callid d29f112e-7e966148-66859ad5@10.32.7.245)
[Mar 9 01:43:29] DEBUG[6418] chan_sip.c: Updating call counter for incoming call
[Mar 9 01:43:29] DEBUG[6418] chan_sip.c: Call from peer '3493' removed from call limit 50
[Mar 9 01:43:29] DEBUG[6418] devicestate.c: Notification of state change to be queued on device/channel SIP/3493
[Mar 9 01:43:29] DEBUG[6418] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
[Mar 9 01:43:29] DEBUG[6418] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield) VALUES ('2011-03-09 01:43:14','\"Frank B\" <3493>','3493','6502748970','from-internal', 'SIP/3493-0d9b4ee0','IAX2/uspbx01-16384','Congestion','20',15,0,'NO ANSWER',3,'','1299663794.496','')
[Mar 9 01:43:29] DEBUG[6418] devicestate.c: Notification of state change to be queued on device/channel SIP/3493
 

dicko

Joined
Oct 24, 2008
Messages
4,099
Likes
0
Points
0
#19
They all show that 10 second of nothing, previously I seggesed

.
.
rasterisk -x 'iax2 show peers'

from each to make sure they can see each other. If still a problem

rasterisk -x 'iax2 set debug on'

and watch the issue of:

tailf /var/log/asterisk/full
.
.

that is what you need to watch on both ends in that ten seconds, all the rest of your posts are spurious as they are in essence all the same.
 

eijob

Joined
Jul 29, 2010
Messages
43
Likes
0
Points
0
#20
Hi Dicko,

I just completed our office move. Ill try to query my logs again this week.

Thank you very much.
 

Members online

No members online now.

Latest posts

Forum statistics

Threads
30,902
Messages
130,887
Members
17,566
Latest member
Fpino
Top