voiceglue/voiceglue — Issue #2: possible bug
Author: JamesCordell
Created: 2011-11-30 15:19:08+00:00
State: open

Hi

I am using voiceglue .14 with asterisk 1.4.21.1 on centos 4. I have it palying back wav examples fine. It works intermittantly however. With full verbosity on I noticed this message appears when is does not work and no sound it heard and the line hangs up.

15:06:37:522 DBUG OPEN_VXI in-aster callid=[1] |1099069760|1|60001|testClient::ChannelThread|NULL result

Here is the complete out put. Once again, if i ring again it works this is approximately half the time it works.

15:06:27:879 DBUG PHONGLUE in-aster rcv mgr(::ASTMGR): "Event: Newchannel\r\nPrivilege: call,all\r\nTimestamp: 1322665587.862300\r\nChannel: SIP/ipbx.inetplc.org-08c9f880\r\nState: Down\r\nCallerIDNum: 25011013\r\nCallerIDName: 02033623013 - 25011013\r\nUniqueid: 1322665587.1\r\n\r\n"
15:06:27:921 DBUG PHONGLUE in-aster rcv mgr(::ASTMGR): "Event: Newstate\r\nPrivilege: call,all\r\nTimestamp: 1322665587.862494\r\nChannel: SIP/ipbx.inetplc.org-08c9f880\r\nState: Ring\r\nCallerID: 25011013\r\nCallerIDName: 02033623013 - 25011013\r\nUniqueid: 1322665587.1\r\n\r\n"
15:06:27:922 DBUG PHONGLUE in-aster rcv mgr(::ASTMGR): "Event: Newexten\r\nPrivilege: call,all\r\nTimestamp: 1322665587.904687\r\nChannel: SIP/ipbx.inetplc.org-08c9f880\r\nContext: from-internal\r\nExtension: 555\r\nPriority: 1\r\nApplication: Answer\r\nAppData: \r\nUniqueid: 1322665587.1\r\n\r\n"
15:06:27:923 DBUG PHONGLUE in-aster rcv mgr(::ASTMGR): "Event: Newstate\r\nPrivilege: call,all\r\nTimestamp: 1322665587.922374\r\nChannel: SIP/ipbx.inetplc.org-08c9f880\r\nState: Up\r\nCallerID: 25011013\r\nCallerIDName: 02033623013 - 25011013\r\nUniqueid: 1322665587.1\r\n\r\n"
15:06:28:120 DBUG PHONGLUE in-aster rcv mgr(::ASTMGR): "Event: Newexten\r\nPrivilege: call,all\r\nTimestamp: 1322665588.118637\r\nChannel: SIP/ipbx.inetplc.org-08c9f880\r\nContext: from-internal\r\nExtension: 555\r\nPriority: 2\r\nApplication: Set\r\nAppData: url_encoded=\"https%3a%2f%2fipswitch.inetplc.org%2ffeatures%2fvxml%2fexample5.vxml\"\r\nUniqueid: 1322665587.1\r\n\r\n"
15:06:28:120 DBUG PHONGLUE in-aster rcv mgr(::ASTMGR): "Event: Newexten\r\nPrivilege: call,all\r\nTimestamp: 1322665588.118723\r\nChannel: SIP/ipbx.inetplc.org-08c9f880\r\nContext: from-internal\r\nExtension: 555\r\nPriority: 3\r\nApplication: AGI\r\nAppData: agi://localhost:4574/url=https%3a%2f%2fipswitch.inetplc.org%2ffeatures%2fvxml%2fexample5.vxml\r\nUniqueid: 1322665587.1\r\n\r\n"
15:06:28:233 INFO PHONGLUE in-aster New AGI connection on fh = ::FASTAGI1
15:06:28:275 DBUG PHONGLUE in-aster rcv agi(::FASTAGI1): "agi_network: yes\n"
15:06:28:318 DBUG PHONGLUE in-aster ::FASTAGI1 initial data "agi_network" = "yes"
15:06:28:319 DBUG PHONGLUE in-aster rcv agi(::FASTAGI1): "agi_network_script: url=https%3a%2f%2fipswitch.inetplc.org%2ffeatures%2fvxml%2fexample5.vxml\n"
15:06:28:320 DBUG PHONGLUE in-aster ::FASTAGI1 initial data "agi_network_script" = "url=https%3a%2f%2fipswitch.inetplc.org%2ffeatures%2fvxml%2fexample5.vxml"
15:06:28:320 DBUG PHONGLUE in-aster rcv agi(::FASTAGI1): "agi_request: agi://localhost:4574/url=https%3a%2f%2fipswitch.inetplc.org%2ffeatures%2fvxml%2fexample5.vxml\n"
15:06:28:321 DBUG PHONGLUE in-aster ::FASTAGI1 initial data "agi_request" = "agi://localhost:4574/url=https%3a%2f%2fipswitch.inetplc.org%2ffeatures%2fvxml%2fexample5.vxml"
15:06:28:321 DBUG PHONGLUE in-aster rcv agi(::FASTAGI1): "agi_channel: SIP/ipbx.inetplc.org-08c9f880\n"
15:06:28:321 DBUG PHONGLUE in-aster ::FASTAGI1 initial data "agi_channel" = "SIP/ipbx.inetplc.org-08c9f880"
15:06:28:322 DBUG PHONGLUE in-aster rcv agi(::FASTAGI1): "agi_language: en\n"
15:06:28:322 DBUG PHONGLUE in-aster ::FASTAGI1 initial data "agi_language" = "en"
15:06:28:323 DBUG PHONGLUE in-aster rcv agi(::FASTAGI1): "agi_type: SIP\n"
15:06:28:323 DBUG PHONGLUE in-aster ::FASTAGI1 initial data "agi_type" = "SIP"
15:06:28:323 DBUG PHONGLUE in-aster rcv agi(::FASTAGI1): "agi_uniqueid: 1322665587.1\n"
15:06:28:325 DBUG PHONGLUE in-aster ::FASTAGI1 initial data "agi_uniqueid" = "1322665587.1"
15:06:28:325 DBUG PHONGLUE in-aster rcv agi(::FASTAGI1): "agi_callerid: 25011013\n"
15:06:28:325 DBUG PHONGLUE in-aster ::FASTAGI1 initial data "agi_callerid" = "25011013"
15:06:28:325 DBUG PHONGLUE in-aster rcv agi(::FASTAGI1): "agi_calleridname: 02033623013 - 25011013\n"
15:06:28:334 DBUG PHONGLUE in-aster ::FASTAGI1 initial data "agi_calleridname" = "02033623013 - 25011013"
15:06:28:335 DBUG PHONGLUE in-aster rcv agi(::FASTAGI1): "agi_callingpres: 0\n"
15:06:28:336 DBUG PHONGLUE in-aster ::FASTAGI1 initial data "agi_callingpres" = "0"
15:06:28:337 DBUG PHONGLUE in-aster rcv agi(::FASTAGI1): "agi_callingani2: 0\n"
15:06:28:337 DBUG PHONGLUE in-aster ::FASTAGI1 initial data "agi_callingani2" = "0"
15:06:28:338 DBUG PHONGLUE in-aster rcv agi(::FASTAGI1): "agi_callington: 0\n"
15:06:28:338 DBUG PHONGLUE in-aster ::FASTAGI1 initial data "agi_callington" = "0"
15:06:28:339 DBUG PHONGLUE in-aster rcv agi(::FASTAGI1): "agi_callingtns: 0\n"
15:06:28:339 DBUG PHONGLUE in-aster ::FASTAGI1 initial data "agi_callingtns" = "0"
15:06:28:339 DBUG PHONGLUE in-aster rcv agi(::FASTAGI1): "agi_dnid: 555\n"
15:06:28:340 DBUG PHONGLUE in-aster ::FASTAGI1 initial data "agi_dnid" = "555"
15:06:28:340 DBUG PHONGLUE in-aster rcv agi(::FASTAGI1): "agi_rdnis: unknown\n"
15:06:28:344 DBUG PHONGLUE in-aster ::FASTAGI1 initial data "agi_rdnis" = "unknown"
15:06:28:345 DBUG PHONGLUE in-aster rcv agi(::FASTAGI1): "agi_context: from-internal\n"
15:06:28:345 DBUG PHONGLUE in-aster ::FASTAGI1 initial data "agi_context" = "from-internal"
15:06:28:346 DBUG PHONGLUE in-aster rcv agi(::FASTAGI1): "agi_extension: 555\n"
15:06:28:346 DBUG PHONGLUE in-aster ::FASTAGI1 initial data "agi_extension" = "555"
15:06:28:346 DBUG PHONGLUE in-aster rcv agi(::FASTAGI1): "agi_priority: 3\n"
15:06:28:347 DBUG PHONGLUE in-aster ::FASTAGI1 initial data "agi_priority" = "3"
15:06:28:348 DBUG PHONGLUE in-aster rcv agi(::FASTAGI1): "agi_enhanced: 0.0\n"
15:06:28:348 DBUG PHONGLUE in-aster ::FASTAGI1 initial data "agi_enhanced" = "0.0"
15:06:28:349 DBUG PHONGLUE in-aster rcv agi(::FASTAGI1): "agi_accountcode: \n"
15:06:28:349 DBUG PHONGLUE in-aster ::FASTAGI1 initial data "agi_accountcode" = undef
15:06:28:349 DBUG PHONGLUE in-aster rcv agi(::FASTAGI1): "\n"
15:06:28:393 INFO PHONGLUE in-aster callid=[1] new incoming assigned to index 0 of 1: CT client on fh="::CTCLIENT1" at host=127.0.0.1 proto=SATC
15:06:28:500 DBUG PHONGLUE in-aster callid=[1] snd incoming callid=1 ani="25011013" dnis="555" arg="url=https%3a%2f%2fipswitch.inetplc.org%2ffeatures%2fvxml%2fexample5.vxml" to CT client on fh="::CTCLIENT1" at host=127.0.0.1 proto=SATC
15:06:28:501 DBUG PHONGLUE in-aster snd "incoming 1 25011013 555 \"url=https%3a%2f%2fipswitch.inetplc.org%2ffeatures%2fvxml%2fexample5.vxml\"\n" to ::CTCLIENT1
15:06:28:768 DBUG VOICEGLU in-aster rcv ctsrv: "incoming 1 25011013 555 \"url=https%3a%2f%2fipswitch.inetplc.org%2ffeatures%2fvxml%2fexample5.vxml\"\n"
15:06:28:769 DBUG VOICEGLU in-aster callid=[1] parsed incoming callid=1 ani="25011013" dnis="555" arg="url=https%3a%2f%2fipswitch.inetplc.org%2ffeatures%2fvxml%2fexample5.vxml"
15:06:29:113 NOTI VOICEGLU in-aster callid=[1] starting VXML interp on url="https://ipswitch.inetplc.org/features/vxml/example5.vxml" from ANI="25011013" for DNIS="555" javascript_init="connection.initargs = new Object();\n" perlfd=10 vxmlfd=11 =#[#= 1322665589.113 call start 1 =#]#=
15:06:29:225 DBUG OPEN_VXI in-aster callid=[1] SBinetChannel::SBinetChannel() constructed
15:06:29:288 DBUG OPEN_VXI in-aster callid=[1] Xerces-C new DocumentConverter 0x24e8b40
15:06:29:289 DBUG OPEN_VXI in-aster callid=[1] Xerces-C new XMLReaderFactory::createXMLReader 0x24e8c38
15:06:29:289 DBUG OPEN_VXI in-aster callid=[1] Xerces-C new DTDResolver 0x24f1d20
15:06:29:292 NOTI OPEN_VXI in-aster callid=[1] Channel 1: Starting VXML Call Processing
15:06:29:305 DBUG OPEN_VXI in-aster callid=[1] |1099069760|1|60001|testClient::ChannelThread|In a Call
15:06:29:310 DBUG OPEN_VXI in-aster callid=[1] SBinetChannel::setCookieJar() called
15:06:29:441 DBUG OPEN_VXI in-aster callid=[1] del VXMLDocumentRep (nil)
15:06:29:442 DBUG OPEN_VXI in-aster callid=[1] (Copy) Allocated http_get buffer 0x259a2b0 of size 4799
15:06:29:448 DBUG OPEN_VXI in-aster callid=[1] Released http_get buffer 0x259a2b0
15:06:29:449 DBUG OPEN_VXI in-aster callid=[1] JsiContext::Create() started
15:06:29:449 DBUG OPEN_VXI in-aster callid=[1] JS_NewContext()
15:06:29:481 DBUG OPEN_VXI in-aster callid=[1] JsiContext::Create(): JS_THREADSAFE set
15:06:29:482 DBUG OPEN_VXI in-aster callid=[1] JSDOMDocument::JSInit() started
15:06:29:482 DBUG OPEN_VXI in-aster callid=[1] JS_InitClass(JSDOMDocument) OK, do: InitNodeObject()
15:06:29:494 DBUG OPEN_VXI in-aster callid=[1] JsiContext::Create() finished
15:06:29:572 DBUG OPEN_VXI in-aster callid=[1] SBinetChannel::open(https://ipswitch.inetplc.org/features/vxml/example5.vxml) called with mode FILE and with properties: {inet.timeoutDownload=7000}
15:06:29:572 DBUG OPEN_VXI in-aster callid=[1] voiceglue_http_get called with method=GET url=https://ipswitch.inetplc.org/features/vxml/example5.vxml postdata="" (encoded from map: ) parsevxml=1
15:06:29:572 DBUG OPEN_VXI in-aster callid=[1] snd vg: HttpGet "GET" "https://ipswitch.inetplc.org/features/vxml/example5.vxml" "" 1
15:06:29:584 DBUG VOICEGLU in-aster callid=[1] rcv ovxi: "HttpGet \"GET\" \"https://ipswitch.inetplc.org/features/vxml/example5.vxml\" \"\" 1\n"
15:06:29:641 DBUG VOICEGLU in-aster callid=[1] made http cache request hcreq=[1000] for url=https://ipswitch.inetplc.org/features/vxml/example5.vxml as: req 1000 v /var/lib/asterisk/sounds/voiceglue/cookie/1 GET - url https://ipswitch.inetplc.org/features/vxml/example5.vxml
15:06:29:646 DBUG VOICEGLU in-aster snd "req 1000 v /var/lib/asterisk/sounds/voiceglue/cookie/1 GET - url https://ipswitch.inetplc.org/features/vxml/example5.vxml\n" to ::MAIN_TO_HC
15:06:29:722 DBUG HTTCACHE in-aster rcv main: "req 1000 v /var/lib/asterisk/sounds/voiceglue/cookie/1 GET - url https://ipswitch.inetplc.org/features/vxml/example5.vxml\n"
15:06:29:848 DBUG HTTCACHE in-aster hcreq=[1000] processing url request httpreq=https://ipswitch.inetplc.org/features/vxml/example5.vxml/?/: method=GET postdata= audio=0 parsevxml=1 hashname=0Y254YF40oDAIG3LoxcN1CPKRb8nSoNDB_example5.vxml host=ipswitch.inetplc.org maxage=7200 lang= cookie_file=/var/lib/asterisk/sounds/voiceglue/cookie/1 timeout=7 for https://ipswitch.inetplc.org/features/vxml/example5.vxml
15:06:29:889 DBUG HTTCACHE in-aster hcreq=[1000] started pid=616 as curl -k -m 7 -q -f -s -S --create-dirs -o /var/lib/asterisk/sounds/voiceglue/url/0Y254YF40oDAIG3LoxcN1CPKRb8nSoNDB_example5.vxml/req.tmp -b /var/lib/asterisk/sounds/voiceglue/cookie/1 -c /var/lib/asterisk/sounds/voiceglue/cookie/1 -D /var/lib/asterisk/sounds/voiceglue/url/0Y254YF40oDAIG3LoxcN1CPKRb8nSoNDB_example5.vxml/req.header --stderr /var/lib/asterisk/sounds/voiceglue/url/0Y254YF40oDAIG3LoxcN1CPKRb8nSoNDB_example5.vxml/req.err -b /var/lib/asterisk/sounds/voiceglue/cookie/1 https://ipswitch.inetplc.org/features/vxml/example5.vxml
15:06:33:318 DBUG PHONGLUE in-aster rcv mgr(::ASTMGR): "Event: Registry\r\nPrivilege: system,all\r\nTimestamp: 1322665593.317117\r\nChannelDriver: SIP\r\nDomain: 194.50.55.12\r\nStatus: Registered\r\n\r\n"
15:06:37:005 DBUG HTTCACHE in-aster pid=616 done on https://ipswitch.inetplc.org/features/vxml/example5.vxml
15:06:37:006 EROR HTTCACHE in-aster failed to retrieve URL https://ipswitch.inetplc.org/features/vxml/example5.vxml curl error: "curl: (6) name lookup timed out\n" on curl command: curl -k -m 7 https://ipswitch.inetplc.org/features/vxml/example5.vxml
15:06:37:006 DBUG HTTCACHE in-aster hcreq=[1000] failed, looking for fallback
15:06:37:006 DBUG HTTCACHE in-aster hcreq=[1000] no more fallbacks, returning failure (=-1)
15:06:37:006 DBUG HTTCACHE in-aster snd "done 1000 -1 - - - -\n" to ::HC_TO_MAIN
15:06:37:010 DBUG VOICEGLU in-aster rcv sc: "done 1000 -1 - - - -"
15:06:37:010 DBUG VOICEGLU in-aster callid=[1] snd 0 to VXML interpreter on fh="10" at host=localhost callid=[1]
15:06:37:010 DBUG VOICEGLU in-aster snd "0\n" to 10
15:06:37:011 DBUG OPEN_VXI in-aster callid=[1] rcv vg: 0
15:06:37:011 DBUG OPEN_VXI in-aster callid=[1] voiceglue_http_get returns 0
15:06:37:011 DBUG OPEN_VXI in-aster callid=[1] SBinetChannel::open() voiceglue_http_get(https://ipswitch.inetplc.org/features/vxml/example5.vxml) returns cachefile="0" content_type="" parse_tree_addr=
15:06:37:011 DBUG OPEN_VXI in-aster callid=[1] |1099069760|1|8000|com.vocalocity.vxi|DocumentParser::FetchBuffer - could not open URL: https://ipswitch.inetplc.org/features/vxml/example5.vxml
15:06:37:011 DBUG OPEN_VXI in-aster callid=[1] |1099069760|1|8000|com.vocalocity.vxi|DocumentParser::FetchDocument - exiting with error result 2
15:06:37:011 DBUG HTTCACHE in-aster Removing contentdir /var/lib/asterisk/sounds/voiceglue/url/0Y254YF40oDAIG3LoxcN1CPKRb8nSoNDB_example5.vxml
15:06:37:017 EROR OPEN_VXI in-aster callid=[1] |1099069760|1|CRITICAL|com.vocalocity.vxi|203|VXIinterpreterRun: Failed to open|URL=https://ipswitch.inetplc.org/features/vxml/example5.vxml
15:06:37:019 NOTI OPEN_VXI in-aster callid=[1] |1099069760|1|EVENT|2|content=Default error handler: error.badfetch , https://ipswitch.inetplc.org/features/vxml/example5.vxml
15:06:37:019 DBUG OPEN_VXI in-aster callid=[1] |1099069760|1|8001|com.vocalocity.vxi|Default error handler: error.badfetch , https://ipswitch.inetplc.org/features/vxml/example5.vxml
15:06:37:028 DBUG OPEN_VXI in-aster callid=[1] VXIpromptQueue called with spec= A serious error has occured. Exiting. , properties={audiofetchhint=prefetch bargein=true bargeintype=speech confidencelevel=0.5 datafetchhint=prefetch documentfetchhint=safe fetchaudiodelay=2s fetchaudiominimum=5s fetchtimeout=7s grammarfetchhint=prefetch inputmodes=dtmf voice maxnbest=1 objectfetchhint=prefetch scriptfetchhint=prefetch sensitivity=0.5 speedvsaccuracy=0.5 swirec_extra_nbest_keys= termchar=# termtimeout=0s universals=none}
15:06:37:028 DBUG OPEN_VXI in-aster callid=[1] VXIpromptQueue ( A serious error has occured. Exiting. )
15:06:37:028 DBUG OPEN_VXI in-aster callid=[1] snd vg: Queue "\n A serious error has occured. Exiting. " true
15:06:37:028 DBUG OPEN_VXI in-aster callid=[1] VXIpromptPlay()
15:06:37:028 DBUG OPEN_VXI in-aster callid=[1] snd vg: Play
15:06:37:028 DBUG VOICEGLU in-aster callid=[1] rcv ovxi: "Queue \"\\n A serious error has occured. Exiting. \" true\n"
15:06:37:310 DBUG VOICEGLU in-aster callid=[1] made http cache request hcreq=[1001] for bargein=1 play_queued index 0 as: req 1001 a:lang=en /var/lib/asterisk/sounds/voiceglue/cookie/1 get - tts A serious error has occured. Exiting.
15:06:37:310 DBUG VOICEGLU in-aster snd "req 1001 a:lang=en /var/lib/asterisk/sounds/voiceglue/cookie/1 get - tts A serious error has occured. Exiting.\n" to ::MAIN_TO_HC
15:06:37:312 DBUG HTTCACHE in-aster rcv main: "req 1001 a:lang=en /var/lib/asterisk/sounds/voiceglue/cookie/1 get - tts A serious error has occured. Exiting.\n"
15:06:37:312 DBUG HTTCACHE in-aster hcreq=[1001] processing tts request httpreq=A serious error has occured. Exiting. method=get postdata= audio=1 parsevxml=0 hashname=nKspH8NWoqCQHdnUbRbm-0c3qQUwqMXJ5_A_serious_error_has_occured___Ex host= maxage=7200 lang=en cookie_file=/var/lib/asterisk/sounds/voiceglue/cookie/1 timeout=7 for A serious error has occured. Exiting.
15:06:37:313 DBUG VOICEGLU in-aster callid=[1] rcv ovxi: "Play\n"
15:06:37:313 DBUG HTTCACHE in-aster hcreq=[1001] started pid=623 as voiceglue_tts_gen -t A serious error has occured. Exiting. /var/lib/asterisk/sounds/voiceglue/tts/nKspH8NWoqCQHdnUbRbm-0c3qQUwqMXJ5_A_serious_error_has_occured___Ex.wav en
15:06:37:314 DBUG VOICEGLU in-aster callid=[1] snd Played to VXML interpreter on fh="10" at host=localhost callid=[1]
15:06:37:314 DBUG VOICEGLU in-aster snd "Played\n" to 10
15:06:37:315 DBUG OPEN_VXI in-aster callid=[1] rcv vg: Played
15:06:37:315 DBUG OPEN_VXI in-aster callid=[1] VXIpromptWait()
15:06:37:315 DBUG OPEN_VXI in-aster callid=[1] snd vg: Wait
15:06:37:315 DBUG VOICEGLU in-aster callid=[1] rcv ovxi: "Wait\n"
15:06:37:318 DBUG VOICEGLU in-aster callid=[1] dpal(): do_prompt_and_listen() called
15:06:37:319 DBUG VOICEGLU in-aster callid=[1] dpal(): Checking for prompts
15:06:37:319 DBUG VOICEGLU in-aster callid=[1] dpal(): No prompts ready, waiting for more
15:06:37:515 DBUG VOICEGLU in-aster rcv sc: "done 1001 -1 - - - -"
15:06:37:515 DBUG VOICEGLU in-aster callid=[1] dpal(): do_prompt_and_listen() called
15:06:37:515 DBUG VOICEGLU in-aster callid=[1] dpal(): Checking for prompts
15:06:37:515 DBUG VOICEGLU in-aster callid=[1] dpal(): Done with prompts
15:06:37:515 DBUG VOICEGLU in-aster callid=[1] dpal(): Sending response to wait
15:06:37:515 DBUG VOICEGLU in-aster callid=[1] dpal() Data Cleared
15:06:37:515 DBUG VOICEGLU in-aster callid=[1] snd Waited to VXML interpreter on fh="10" at host=localhost callid=[1]
15:06:37:515 DBUG VOICEGLU in-aster snd "Waited\n" to 10
15:06:37:515 DBUG HTTCACHE in-aster pid=623 done on A serious error has occured. Exiting.
15:06:37:515 EROR HTTCACHE in-aster TTS genration of /var/lib/asterisk/sounds/voiceglue/tts/nKspH8NWoqCQHdnUbRbm-0c3qQUwqMXJ5_A_serious_error_has_occured___Ex.wav failed, file has bad stat: No such file or directory
15:06:37:515 DBUG HTTCACHE in-aster hcreq=[1001] failed, looking for fallback
15:06:37:515 DBUG HTTCACHE in-aster hcreq=[1001] no more fallbacks, returning failure (=-1)
15:06:37:515 DBUG HTTCACHE in-aster snd "done 1001 -1 - - - -\n" to ::HC_TO_MAIN
15:06:37:518 DBUG OPEN_VXI in-aster callid=[1] rcv vg: Waited
15:06:37:518 DBUG OPEN_VXI in-aster callid=[1] JS_DestroyContext()
15:06:37:518 DBUG OPEN_VXI in-aster callid=[1] VXIpromptPlay()
15:06:37:518 DBUG OPEN_VXI in-aster callid=[1] snd vg: Play
15:06:37:518 DBUG VOICEGLU in-aster callid=[1] rcv ovxi: "Play\n"
15:06:37:518 DBUG VOICEGLU in-aster callid=[1] snd Played to VXML interpreter on fh="10" at host=localhost callid=[1]
15:06:37:518 DBUG VOICEGLU in-aster snd "Played\n" to 10
15:06:37:518 DBUG OPEN_VXI in-aster callid=[1] rcv vg: Played
15:06:37:518 DBUG OPEN_VXI in-aster callid=[1] VXIpromptWait()
15:06:37:518 DBUG OPEN_VXI in-aster callid=[1] snd vg: Wait
15:06:37:518 DBUG VOICEGLU in-aster callid=[1] rcv ovxi: "Wait\n"
15:06:37:518 DBUG VOICEGLU in-aster callid=[1] snd Waited to VXML interpreter on fh="10" at host=localhost callid=[1]
15:06:37:518 DBUG VOICEGLU in-aster snd "Waited\n" to 10
15:06:37:518 DBUG OPEN_VXI in-aster callid=[1] rcv vg: Waited
15:06:37:522 DBUG OPEN_VXI in-aster callid=[1] |1099069760|1|60001|testClient::ChannelThread|NULL result
15:06:37:525 DBUG OPEN_VXI in-aster callid=[1] |1099069760|1|60001|testClient::ChannelThread|Call Terminated
15:06:37:525 NOTI OPEN_VXI in-aster callid=[1] Channel 1: Call Terminated
15:06:37:525 DBUG OPEN_VXI in-aster callid=[1] Xerces-C del DTDResolver 0x24f1d20
15:06:37:525 DBUG OPEN_VXI in-aster callid=[1] Xerces-C del XMLReaderFactory::createXMLReader 0x24e8c38
15:06:37:525 DBUG OPEN_VXI in-aster callid=[1] Xerces-C del DocumentConverter 0x24e8b40
15:06:37:525 DBUG OPEN_VXI in-aster callid=[1] |1099069760|-1|3000|SBinetDestroyResource|entering: 0x0x24f8020 (0x0x24faa80)
15:06:37:527 DBUG OPEN_VXI in-aster callid=[1] SBinetChannel::~SBinetChannel() destructed
15:06:37:527 DBUG OPEN_VXI in-aster callid=[1] SBinetChannel::closeHttpConnections() called
15:06:37:527 DBUG OPEN_VXI in-aster callid=[1] SBinetChannel::deleteAllCookies() called
15:06:37:527 DBUG OPEN_VXI in-aster callid=[1] |1099069760|-1|3000|SBinetDestroyResource|exiting, returned 0
15:06:37:527 DBUG OPEN_VXI in-aster callid=[1] snd vg:
15:06:37:527 DBUG VOICEGLU in-aster callid=[1] rcv ovxi: "\n"
15:06:37:527 NOTI VOICEGLU in-aster callid=[1] VXML interpreter thread exited =#[#= 1322665597.526 call end 1 =#]#=
15:06:37:527 DBUG VOICEGLU in-aster callid=[1] deallocating VXML thread
15:06:37:527 NOTI VOICEGLU in-aster callid=[1] releasing call because VXML interpreter exited
15:06:37:536 DBUG VOICEGLU in-aster callid=[1] snd release callid=1 to CT server on fh="::CTSRV" at host=localhost
15:06:37:537 DBUG VOICEGLU in-aster snd "release 1\n" to ::CTSRV
15:06:37:539 DBUG PHONGLUE in-aster rcv ct(::CTCLIENT1): "release 1\n"
15:06:37:565 DBUG PHONGLUE in-aster callid=[1] parsed release callid=1
15:06:37:598 INFO PHONGLUE in-aster AGI client filehandle "::FASTAGI1" stopped: release requested
15:06:37:614 DBUG PHONGLUE in-aster callid=[1] snd released callid=1 to CT client on fh="::CTCLIENT1" at host=127.0.0.1 proto=SATC
15:06:37:614 DBUG PHONGLUE in-aster snd "released 1\n" to ::CTCLIENT1
15:06:37:615 DBUG VOICEGLU in-aster rcv ctsrv: "released 1\n"
15:06:37:615 DBUG VOICEGLU in-aster callid=[1] parsed released callid=1
15:06:37:616 DBUG PHONGLUE in-aster rcv mgr(::ASTMGR): "Event: Newexten\r\nPrivilege: call,all\r\nTimestamp: 1322665597.580001\r\nChannel: SIP/ipbx.inetplc.org-08c9f880\r\nContext: from-internal\r\nExtension: 555\r\nPriority: 4\r\nApplication: Hangup\r\nAppData: \r\nUniqueid: 1322665587.1\r\n\r\n"
15:06:37:617 DBUG PHONGLUE in-aster rcv mgr(::ASTMGR): "Event: Newexten\r\nPrivilege: call,all\r\nTimestamp: 1322665597.580065\r\nChannel: SIP/ipbx.inetplc.org-08c9f880\r\nContext: from-internal\r\nExtension: h\r\nPriority: 1\r\nApplication: DeadAGI\r\nAppData: agi://127.0.0.1/end\r\nUniqueid: 1322665587.1\r\n\r\n"
15:06:38:071 DBUG PHONGLUE in-aster rcv mgr(::ASTMGR): "Event: Hangup\r\nPrivilege: call,all\r\nTimestamp: 1322665598.069868\r\nChannel: SIP/ipbx.inetplc.org-08c9f880\r\nUniqueid: 1322665587.1\r\nCause: 16\r\nCause-txt: Normal Clearing\r\n\r\n"