TRUNK Dial failed due to CHANUNAVAIL

Discussion in 'General' started by eijob, Mar 9, 2011.

  1. eijob

    Joined:
    Jul 29, 2010
    Messages:
    43
    Likes Received:
    0
    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
     
  2. dicko

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

    rasterisk -x 'show g729'

    from each box, at the time the calls fail.
     
  3. eijob

    Joined:
    Jul 29, 2010
    Messages:
    43
    Likes Received:
    0
    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
     
  4. dicko

    Joined:
    Oct 24, 2008
    Messages:
    4,099
    Likes Received:
    0
    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
     
  5. eijob

    Joined:
    Jul 29, 2010
    Messages:
    43
    Likes Received:
    0
    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
     
  6. dicko

    Joined:
    Oct 24, 2008
    Messages:
    4,099
    Likes Received:
    0
    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
     
  7. eijob

    Joined:
    Jul 29, 2010
    Messages:
    43
    Likes Received:
    0
    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.
     
  8. dicko

    Joined:
    Oct 24, 2008
    Messages:
    4,099
    Likes Received:
    0
    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,
     
  9. eijob

    Joined:
    Jul 29, 2010
    Messages:
    43
    Likes Received:
    0
    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.
     
  10. dicko

    Joined:
    Oct 24, 2008
    Messages:
    4,099
    Likes Received:
    0
    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.
     
  11. eijob

    Joined:
    Jul 29, 2010
    Messages:
    43
    Likes Received:
    0
    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'
     
  12. dicko

    Joined:
    Oct 24, 2008
    Messages:
    4,099
    Likes Received:
    0
    .
    .

    [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>'
     
  13. eijob

    Joined:
    Jul 29, 2010
    Messages:
    43
    Likes Received:
    0
    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
     
  14. eijob

    Joined:
    Jul 29, 2010
    Messages:
    43
    Likes Received:
    0
    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
     
  15. dicko

    Joined:
    Oct 24, 2008
    Messages:
    4,099
    Likes Received:
    0
    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?
     
  16. eijob

    Joined:
    Jul 29, 2010
    Messages:
    43
    Likes Received:
    0
    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
     
  17. eijob

    Joined:
    Jul 29, 2010
    Messages:
    43
    Likes Received:
    0
    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
     
  18. eijob

    Joined:
    Jul 29, 2010
    Messages:
    43
    Likes Received:
    0
    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
     
  19. dicko

    Joined:
    Oct 24, 2008
    Messages:
    4,099
    Likes Received:
    0
    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.
     
  20. eijob

    Joined:
    Jul 29, 2010
    Messages:
    43
    Likes Received:
    0
    Hi Dicko,

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

    Thank you very much.
     

Share This Page