[Jan 13 12:35:10] VERBOSE[12712] pbx.c: -- Executing [123456789@from-internal:1] AGI("SIP/product-local-000065d0", "agi://127.0.0.1/product?stype=internal") in new stack [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> agi_request: agi://127.0.0.1/product?stype=internal [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> agi_channel: SIP/product-local-000065d0 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> agi_language: en [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> agi_type: SIP [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> agi_uniqueid: 1389645310.84728 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> agi_version: 1.8.22.0 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> agi_callerid: 987654321 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> agi_calleridname: unknown [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> agi_callingpres: 0 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> agi_callingani2: 0 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> agi_callington: 0 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> agi_callingtns: 0 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> agi_dnid: 123456789 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> agi_rdnis: unknown [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> agi_context: from-internal [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> agi_extension: 123456789 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> agi_priority: 1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> agi_enhanced: 0.0 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> agi_accountcode: [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> agi_threadid: 1097239440 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << VERBOSE "AGI starting at Mon Jan 13 12:35:10 2014 (1389645310)" 9 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE CHANNEL(language) "en" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << GET VARIABLE product-CALLID [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=0 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-CALLID "1389645310.84728" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << GET VARIABLE product-SCREEN [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=0 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << GET VARIABLE product-DIALPLAN [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=0 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << GET VARIABLE product-DIVERTED [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=0 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << GET VARIABLE product-DIVERSION [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=0 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-MUSIC "default" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE CHANNEL(musicclass) "default" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __TRANSFER_CONTEXT "from-internal" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE TIMEOUT(absolute) "28800" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << GET VARIABLE product-CUTOFF [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=0 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE TIMEOUT(absolute) "28800" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << GET VARIABLE SIP_HEADER(Call-ID) [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 (200600103-0-1465022714@64.136.xx.xx) [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << VERBOSE "SIP Call-ID is: 200600103-0-1465022714@64.136.xx.xx" 9 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << GET VARIABLE product-SCUSTOMER [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=0 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << GET VARIABLE SIP_HEADER(X-product-Source) [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 (64.136.174.30:5060) [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << GET VARIABLE product-PRESENTATION-INTERNAL [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=0 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << GET VARIABLE product-PRESENTATION-EXTERNAL [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=0 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << GET VARIABLE SIP_HEADER(X-product-External) [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 (yes) [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << GET VARIABLE product-TRANSFER-PHONE [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=0 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << GET VARIABLE product-ORIGINAL-STYPE [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=0 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-ORIGINAL-STYPE "external" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-ORIGINAL-SNUMBER "987654321" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << VERBOSE "Resolving type '', number '123456789', old '', forward 1 for channel SIP/product-local-000065d0" 5 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: > agi://127.0.0.1/product?stype=internal: Resolving type '', number '123456789', old '', forward 1 for channel SIP/product-local-000065d0 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-DIVERSION "123456789" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE CHANNEL(language) "en" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-MUSIC "78" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE CHANNEL(musicclass) "78" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << VERBOSE "Starting recording group '5' expires '1389731710' file '/var/lib/product/recordings/13/5/2014/01/13/record_138964531084728_12713'" 9 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << EXEC Monitor "gsm,/var/lib/product/recordings/13/5/2014/01/13/record_138964531084728_12713" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=0 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << VERBOSE "Resolving type 'huntgroup', number '20', old '', forward 2 for channel SIP/product-local-000065d0" 5 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: > agi://127.0.0.1/product?stype=internal: Resolving type 'huntgroup', number '20', old '', forward 2 for channel SIP/product-local-000065d0 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << GET VARIABLE product-QUEUE [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=0 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << GET VARIABLE SIP_HEADER(Call-ID) [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 (200600103-0-1465022714@64.136.xx.xx) [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << GET VARIABLE CALLERID(name) [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 () [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << VERBOSE "Writing entry to active table for 1389645310.84728, external:987654321 - huntgroup:20." 9 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE TIMEOUT(absolute) "28800" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-DCUSTOMER "13" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-DTYPE "huntgroup" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-DNUMBER "20" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __LIMIT_PLAYAUDIO_CALLER "no" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __LIMIT_PLAYAUDIO_CALLEE "yes" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE CALLERID(number) "987654321" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-TRANSFER-CUSTOMER "13" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-CALLERID-EXTERNAL "987654321" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-PRESENTATION-INTERNAL "1" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-PRESENTATION-EXTERNAL "1" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-CUTOFF "28800" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-CALLERID-EXTERNAL "987654321" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << EXEC Ringing "" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=0 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-SCUSTOMER "13" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-STYPE "huntgroup" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-SNUMBER "20" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-CTYPE-1 "phone" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-CNUMBER-1 "1930542" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-SCREEN-1 "0" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-SCUSTOMER "13" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-STYPE "huntgroup" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-SNUMBER "20" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-CTYPE-2 "phone" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-CNUMBER-2 "1930543" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-SCREEN-2 "0" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-SCUSTOMER "13" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-STYPE "huntgroup" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-SNUMBER "20" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-CTYPE-3 "phone" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-CNUMBER-3 "1930545" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-SCREEN-3 "0" [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:35:10] VERBOSE[12712] res_agi.c: AGI Rx << EXEC Dial "Local/1@product-call-exten/n&Local/2@product-call-exten/n&Local/3@product-call-exten/n,10,M(product-answered^0^1389645310.84728)oir" [Jan 13 12:35:16] VERBOSE[12712] app_dial.c: -- Local/3@product-call-exten-000071e7;1 answered SIP/product-local-000065d0 [Jan 13 12:47:52] VERBOSE[12712] chan_sip.c: == Redirecting 'SIP/product-local-000065d0' to fax extension due to CNG detection [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=-1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> HANGUP [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: -- AGI Script agi://127.0.0.1/product?stype=internal completed, returning 4 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> HANGUP [Jan 13 12:47:52] VERBOSE[12712] pbx.c: == Spawn extension (from-internal, fax, 1) exited non-zero on 'SIP/product-local-000065d0' [Jan 13 12:47:52] VERBOSE[12712] pbx.c: -- Executing [fax@from-internal:1] AGI("SIP/product-local-000065d0", "agi://127.0.0.1/product?stype=internal") in new stack [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> agi_request: agi://127.0.0.1/product?stype=internal [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> agi_channel: SIP/product-local-000065d0 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> agi_language: en [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> agi_type: SIP [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> agi_uniqueid: 1389645310.84728 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> agi_version: 1.8.22.0 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> agi_callerid: 987654321 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> agi_calleridname: unknown [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> agi_callingpres: 0 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> agi_callingani2: 0 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> agi_callington: 0 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> agi_callingtns: 0 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> agi_dnid: 123456789 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> agi_rdnis: unknown [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> agi_context: from-internal [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> agi_extension: fax [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> agi_priority: 1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> agi_enhanced: 0.0 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> agi_accountcode: [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> agi_threadid: 1097239440 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << VERBOSE "AGI starting at Mon Jan 13 12:47:52 2014 (1389646072)" 9 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE CHANNEL(language) "en" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << GET VARIABLE product-CALLID [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 (1389645310.84728) [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << GET VARIABLE product-SCREEN [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=0 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << GET VARIABLE product-DIALPLAN [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=0 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << GET VARIABLE product-DIVERTED [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=0 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << GET VARIABLE product-DIVERSION [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 (123456789) [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-MUSIC "default" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE CHANNEL(musicclass) "default" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __TRANSFER_CONTEXT "from-internal" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE TIMEOUT(absolute) "28800" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << GET VARIABLE product-CUTOFF [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 (28800) [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE TIMEOUT(absolute) "28800" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << GET VARIABLE SIP_HEADER(Call-ID) [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 (200600103-0-1465022714@64.136.xx.xx) [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << VERBOSE "SIP Call-ID is: 200600103-0-1465022714@64.136.xx.xx" 9 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << GET VARIABLE product-SCUSTOMER [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 (13) [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << GET VARIABLE SIP_HEADER(X-product-Source) [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 (64.136.174.30:5060) [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << GET VARIABLE product-PRESENTATION-INTERNAL [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 (1) [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << GET VARIABLE product-PRESENTATION-EXTERNAL [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 (1) [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << GET VARIABLE product-ORIGINAL-STYPE [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 (external) [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << GET VARIABLE product-ORIGINAL-STYPE [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 (external) [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << VERBOSE "Resolving type '', number '123456789', old '', forward 1 for channel SIP/product-local-000065d0" 5 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: > agi://127.0.0.1/product?stype=internal: Resolving type '', number '123456789', old '', forward 1 for channel SIP/product-local-000065d0 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-DIVERSION "123456789" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE CHANNEL(language) "en" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-MUSIC "78" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE CHANNEL(musicclass) "78" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << VERBOSE "Starting recording group '5' expires '1389732472' file '/var/lib/product/recordings/13/5/2014/01/13/record_138964531084728_12713'" 9 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << EXEC Monitor "gsm,/var/lib/product/recordings/13/5/2014/01/13/record_138964531084728_12713" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=0 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << VERBOSE "Resolving type 'huntgroup', number '20', old '', forward 2 for channel SIP/product-local-000065d0" 5 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: > agi://127.0.0.1/product?stype=internal: Resolving type 'huntgroup', number '20', old '', forward 2 for channel SIP/product-local-000065d0 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << GET VARIABLE product-QUEUE [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=0 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << GET VARIABLE SIP_HEADER(Call-ID) [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 (200600103-0-1465022714@64.136.xx.xx) [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << GET VARIABLE CALLERID(name) [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 () [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << VERBOSE "Writing entry to active table for 1389645310.84728, external:987654321 - huntgroup:20." 9 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE TIMEOUT(absolute) "28800" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-DCUSTOMER "13" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-DTYPE "huntgroup" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-DNUMBER "20" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __LIMIT_PLAYAUDIO_CALLER "no" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __LIMIT_PLAYAUDIO_CALLEE "yes" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE CALLERID(number) "987654321" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-TRANSFER-CUSTOMER "13" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-CALLERID-EXTERNAL "987654321" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-PRESENTATION-INTERNAL "1" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-PRESENTATION-EXTERNAL "1" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-CUTOFF "28800" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-CALLERID-EXTERNAL "987654321" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << EXEC Ringing "" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=0 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-SCUSTOMER "13" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-STYPE "huntgroup" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-SNUMBER "20" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-CTYPE-1 "phone" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-CNUMBER-1 "1930542" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-SCREEN-1 "0" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-SCUSTOMER "13" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-STYPE "huntgroup" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-SNUMBER "20" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-CTYPE-2 "phone" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-CNUMBER-2 "1930543" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-SCREEN-2 "0" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-SCUSTOMER "13" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-STYPE "huntgroup" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-SNUMBER "20" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-CTYPE-3 "phone" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-CNUMBER-3 "1930545" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << SET VARIABLE __product-SCREEN-3 "0" [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Tx >> 200 result=1 [Jan 13 12:47:52] VERBOSE[12712] res_agi.c: AGI Rx << EXEC Dial "Local/1@product-call-exten/n&Local/2@product-call-exten/n&Local/3@product-call-exten/n,10,M(product-answered^0^1389645310.84728)oir" [Jan 13 12:47:58] VERBOSE[12712] app_dial.c: -- Local/3@product-call-exten-00007822;1 answered SIP/product-local-000065d0