[Jun 15 15:41:03] VERBOSE[15299] pbx.c: -- Executing [0123456789@from-external:1] Wait("DAHDI/i1/1234567890-b81", "1") in new stack [Jun 15 15:41:04] VERBOSE[15299] pbx.c: -- Executing [0123456789@from-external:2] AGI("DAHDI/i1/1234567890-b81", "agi://127.0.0.1/product?stype=external") in new stack [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> agi_network: yes [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> agi_network_script: product?stype=external [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> agi_request: agi://127.0.0.1/product?stype=external [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> agi_channel: DAHDI/i1/1234567890-b81 [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> agi_language: en [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> agi_type: DAHDI [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> agi_uniqueid: 1339810863.88476 [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> agi_version: 1.8.7.1 [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> agi_callerid: 1234567890 [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> agi_calleridname: WIRELESS CALLER [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> agi_callingpres: 3 [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> agi_callingani2: 0 [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> agi_callington: 33 [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> agi_callingtns: 0 [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> agi_dnid: 0123456789 [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> agi_rdnis: unknown [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> agi_context: from-external [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> agi_extension: 0123456789 [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> agi_priority: 2 [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> agi_enhanced: 0.0 [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> agi_accountcode: [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> agi_threadid: 1119542176 [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Rx << VERBOSE "AGI starting at Fri Jun 15 15:41:04 2012 (1339810864)" 9 [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: > agi://127.0.0.1/product?stype=external: AGI starting at Fri Jun 15 15:41:04 2012 (1339810864) [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=1 [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Rx << SET VARIABLE CHANNEL(language) "en" [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=1 [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Rx << GET VARIABLE product-CALLID [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=0 [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Rx << SET VARIABLE __product-CALLID "1339810863.88476" [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=1 [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Rx << GET VARIABLE product-SCREEN [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=0 [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Rx << GET VARIABLE product-DIVERTED [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=0 [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Rx << GET VARIABLE product-DIVERSION [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=0 [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Rx << SET VARIABLE __product-MUSIC "default" [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=1 [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Rx << SET VARIABLE CHANNEL(musicclass) "default" [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=1 [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Rx << SET VARIABLE __TRANSFER_CONTEXT "from-internal" [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=1 [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Rx << SET VARIABLE TIMEOUT(absolute) "86400" [Jun 15 15:41:04] VERBOSE[15299] func_timeout.c: Channel will hangup at 2012-06-16 15:41:04.968 HST. [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=1 [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Rx << GET VARIABLE product-CUTOFF [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=0 [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Rx << SET VARIABLE TIMEOUT(absolute) "86400" [Jun 15 15:41:04] VERBOSE[15299] func_timeout.c: Channel will hangup at 2012-06-16 15:41:04.968 HST. [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=1 [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Rx << GET VARIABLE product-SCUSTOMER [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=0 [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Rx << GET VARIABLE product-PRESENTATION-INTERNAL [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=0 [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Rx << GET VARIABLE product-PRESENTATION-EXTERNAL [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=0 [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Rx << GET VARIABLE CALLINGPRES [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=1 (3) [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Rx << GET VARIABLE product-TRANSFER-PHONE [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=0 [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Rx << VERBOSE "Resolving type '', number '0123456789', old '', forward 1 for channel DAHDI/i1/1234567890-b81" 5 [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: > agi://127.0.0.1/product?stype=external: Resolving type '', number '0123456789', old '', forward 1 for channel DAHDI/i1/1234567890-b81 [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=1 [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Rx << SET VARIABLE __product-DIVERSION "0123456789" [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=1 [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Rx << SET VARIABLE CHANNEL(language) "en" [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=1 [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Rx << VERBOSE "Resolving type 'mailbox', number '6226', old '', forward 2 for channel DAHDI/i1/1234567890-b81" 5 [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: > agi://127.0.0.1/product?stype=external: Resolving type 'mailbox', number '6226', old '', forward 2 for channel DAHDI/i1/1234567890-b81 [Jun 15 15:41:04] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=1 [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Rx << SET VARIABLE TIMEOUT(absolute) "86399" [Jun 15 15:41:05] VERBOSE[15299] func_timeout.c: Channel will hangup at 2012-06-16 15:41:04.003 HST. [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=1 [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Rx << VERBOSE "Writing entry to active table for 1339810863.88476, external:1234567890 - mailbox:6226." 9 [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: > agi://127.0.0.1/product?stype=external: Writing entry to active table for 1339810863.88476, external:1234567890 - mailbox:6226. [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=1 [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Rx << GET VARIABLE CALLERID(name) [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=1 (WIRELESS CALLER) [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Rx << SET VARIABLE TIMEOUT(absolute) "86399" [Jun 15 15:41:05] VERBOSE[15299] func_timeout.c: Channel will hangup at 2012-06-16 15:41:04.021 HST. [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=1 [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Rx << SET VARIABLE __product-MUSIC "slackkey" [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=1 [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Rx << SET VARIABLE CHANNEL(musicclass) "slackkey" [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=1 [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Rx << SET VARIABLE __product-DCUSTOMER "328" [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=1 [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Rx << SET VARIABLE __product-DTYPE "mailbox" [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=1 [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Rx << SET VARIABLE __product-DNUMBER "6226" [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=1 [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Rx << SET VARIABLE __LIMIT_PLAYAUDIO_CALLER "no" [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=1 [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Rx << SET VARIABLE __LIMIT_PLAYAUDIO_CALLEE "yes" [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=1 [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Rx << SET VARIABLE CALLERID(number) "1234567890" [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=1 [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Rx << SET VARIABLE __product-TRANSFER-CUSTOMER "328" [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=1 [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Rx << SET VARIABLE __product-PRESENTATION-INTERNAL "3" [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=1 [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Rx << SET VARIABLE __product-PRESENTATION-EXTERNAL "3" [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=1 [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Rx << SET VARIABLE __product-CUTOFF "86399" [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=1 [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Rx << SET VARIABLE __product-SCUSTOMER "328" [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=1 [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Rx << SET VARIABLE __product-STYPE "mailbox" [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=1 [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Rx << SET VARIABLE __product-SNUMBER "6226" [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=1 [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Rx << SET VARIABLE __product-CTYPE "ivr" [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=1 [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Rx << SET VARIABLE __product-CNUMBER "814" [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=1 [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Rx << SET VARIABLE __product-CALLERID "1234567890" [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=1 [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Rx << SET VARIABLE __product-EXIT-MAILBOX "" [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=1 [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Rx << SET CONTEXT product-mailbox-exit [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=0 [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Rx << SET PRIORITY 1 [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=0 [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Rx << GET VARIABLE DIALSTATUS [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=0 [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Rx << EXEC Answer "" [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: -- AGI Script Executing Application: (Answer) Options: () [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=0 [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: AGI Rx << EXEC Voicemail "6226@328,sg(3)u" [Jun 15 15:41:05] VERBOSE[15299] res_agi.c: -- AGI Script Executing Application: (Voicemail) Options: (6226@328,sg(3)u) [Jun 15 15:41:05] VERBOSE[15299] file.c: -- Playing '/var/spool/asterisk/voicemail/328/6226/temp.slin' (language 'en') [Jun 15 15:41:10] VERBOSE[15299] file.c: -- Playing 'beep.gsm' (language 'en') [Jun 15 15:41:11] VERBOSE[15299] app_voicemail.c: -- Recording the message [Jun 15 15:41:11] VERBOSE[15299] app.c: -- x=0, open writing: /var/spool/asterisk/voicemail/328/6226/tmp/cCg9v7 format: wav, 0x8e0d178 [Jun 15 15:41:21] VERBOSE[15299] app.c: -- User hung up [Jun 15 15:41:21] VERBOSE[15299] app_voicemail.c: -- Recording was 1 seconds long but needs to be at least 3 - abandoning [Jun 15 15:41:21] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=-1 [Jun 15 15:41:21] VERBOSE[15299] res_agi.c: -- AGI Script agi://127.0.0.1/product?stype=external completed, returning 4 [Jun 15 15:41:21] VERBOSE[15299] pbx.c: == Spawn extension (product-mailbox-exit, 0123456789, 0) exited non-zero on 'DAHDI/i1/1234567890-b81' [Jun 15 15:41:21] VERBOSE[15299] pbx.c: -- Executing [h@product-mailbox-exit:1] AGI("DAHDI/i1/1234567890-b81", "agi://127.0.0.1/end") in new stack [Jun 15 15:41:21] VERBOSE[15299] res_agi.c: AGI Tx >> agi_network: yes [Jun 15 15:41:21] VERBOSE[15299] res_agi.c: AGI Tx >> agi_network_script: end [Jun 15 15:41:21] VERBOSE[15299] res_agi.c: AGI Tx >> agi_request: agi://127.0.0.1/end [Jun 15 15:41:21] VERBOSE[15299] res_agi.c: AGI Tx >> agi_channel: DAHDI/i1/1234567890-b81 [Jun 15 15:41:21] VERBOSE[15299] res_agi.c: AGI Tx >> agi_language: en [Jun 15 15:41:21] VERBOSE[15299] res_agi.c: AGI Tx >> agi_type: DAHDI [Jun 15 15:41:21] VERBOSE[15299] res_agi.c: AGI Tx >> agi_uniqueid: 1339810863.88476 [Jun 15 15:41:21] VERBOSE[15299] res_agi.c: AGI Tx >> agi_version: 1.8.7.1 [Jun 15 15:41:21] VERBOSE[15299] res_agi.c: AGI Tx >> agi_callerid: 1234567890 [Jun 15 15:41:21] VERBOSE[15299] res_agi.c: AGI Tx >> agi_calleridname: WIRELESS CALLER [Jun 15 15:41:21] VERBOSE[15299] res_agi.c: AGI Tx >> agi_callingpres: 3 [Jun 15 15:41:21] VERBOSE[15299] res_agi.c: AGI Tx >> agi_callingani2: 0 [Jun 15 15:41:21] VERBOSE[15299] res_agi.c: AGI Tx >> agi_callington: 33 [Jun 15 15:41:21] VERBOSE[15299] res_agi.c: AGI Tx >> agi_callingtns: 0 [Jun 15 15:41:21] VERBOSE[15299] res_agi.c: AGI Tx >> agi_dnid: 0123456789 [Jun 15 15:41:21] VERBOSE[15299] res_agi.c: AGI Tx >> agi_rdnis: unknown [Jun 15 15:41:21] VERBOSE[15299] res_agi.c: AGI Tx >> agi_context: product-mailbox-exit [Jun 15 15:41:21] VERBOSE[15299] res_agi.c: AGI Tx >> agi_extension: h [Jun 15 15:41:21] VERBOSE[15299] res_agi.c: AGI Tx >> agi_priority: 1 [Jun 15 15:41:21] VERBOSE[15299] res_agi.c: AGI Tx >> agi_enhanced: 0.0 [Jun 15 15:41:21] VERBOSE[15299] res_agi.c: AGI Tx >> agi_accountcode: [Jun 15 15:41:21] VERBOSE[15299] res_agi.c: AGI Tx >> agi_threadid: 1119542176 [Jun 15 15:41:21] VERBOSE[15299] res_agi.c: AGI Tx >> [Jun 15 15:41:21] VERBOSE[15299] res_agi.c: AGI Rx << VERBOSE "AGI starting at Fri Jun 15 15:41:21 2012 (1339810881)" 9 [Jun 15 15:41:21] VERBOSE[15299] res_agi.c: > agi://127.0.0.1/end: AGI starting at Fri Jun 15 15:41:21 2012 (1339810881) [Jun 15 15:41:21] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=1 [Jun 15 15:41:21] VERBOSE[15299] res_agi.c: AGI Rx << SET VARIABLE CHANNEL(language) "en" [Jun 15 15:41:21] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=1 [Jun 15 15:41:21] VERBOSE[15299] res_agi.c: AGI Rx << GET VARIABLE product-CALLID [Jun 15 15:41:21] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=1 (1339810863.88476) [Jun 15 15:41:21] VERBOSE[15299] res_agi.c: AGI Rx << GET VARIABLE ANSWEREDTIME [Jun 15 15:41:21] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=0 [Jun 15 15:41:21] VERBOSE[15299] res_agi.c: AGI Rx << GET VARIABLE DIALSTATUS [Jun 15 15:41:21] VERBOSE[15299] res_agi.c: AGI Tx >> 200 result=0 [Jun 15 15:41:22] VERBOSE[15299] res_agi.c: -- AGI Script agi://127.0.0.1/end completed, returning 0 [Jun 15 15:41:22] DEBUG[15299] sig_pri.c: sig_pri_hangup 7 [Jun 15 15:41:22] DEBUG[15299] sig_pri.c: Not yet hungup... Calling hangup once with icause, and clearing call [Jun 15 15:41:22] VERBOSE[15299] chan_dahdi.c: -- Hungup 'DAHDI/i1/1234567890-b81'