vicidial.org

Posted: **Tue May 03, 2011 2:56 am**

Gateway: Asterisk 1.2.30.2 vicidial 2.0.5-stable zaptel Digium TE122
Dialer: Asterisk 1.2.30.2 vicidial 2.2.1-stable
Between them, use IAX2 trunk.
extension.conf on Dialer server

Code: Select all: exten => _86ZXXXXXXX.,1,AGI(agi-NVA_recording.agi,BOTH------Y---N---Y) exten => _86ZXXXXXXX.,2,Dial(${HKZH3TRUNK}/${EXTEN},,tTor) exten => _86ZXXXXXXX.,3,Congestion exten => _86ZXXXXXXX.,4,Hangup

iax.conf on Dialer server

Code: Select all: register => hkzh3carrier:xxxxxx@192.168.1.39

extension.conf on Gateway server

Code: Select all: exten => _86ZXXXXXXX.,1,Set(PATH=/home/${STRFTIME(${EPOCH},,%Y-%m-%d)}) exten => _86ZXXXXXXX.,n,Set(FILENAME=${STRFTIME(${EPOCH},,%Y-%m-%d-%H%M%S)}--${CALLERID(num)}-${EXTEN}) exten => _86ZXXXXXXX.,n,Set(MONITOR_EXEC=/etc/asterisk/scripts/mce ${PATH} ${FILENAME}) exten => _86ZXXXXXXX.,n,Monitor(wav,${PATH}/${FILENAME},mb) exten => _86ZXXXXXXX.,n,Dial(ZAP/g1/0080${EXTEN},,tTm)

iax.conf on gateway server

Code: Select all: register => hkzh3carrier:xxxxxx@192.168.2.38 [hkzh3carrier] disallow=all allow=g729 allow=gsm allow=ulaw allow=ilbc type=friend username=hkzh3carrier secret=xxxxxx host=dynamic dtmfmode=rfc2833 context=default

/var/spool/crom/root

Code: Select all: 0,3,6,9,12,15,18,21,24,27,30,33,36,39,42,45,48,51,54,57 * * * * /usr/share/astguiclient/AST_CRON_audio_1_move_mix.pl

When dial out, about 2% call log is zero, but the call continue over 1 min at least.
When I set recording at gateway, it can get the right recording file.

Check log file on dialer, the -in and -out call log file is 11:47:36, and both size are 44Byte.

The message log on dialer,

Code: Select all: [May 3 11:47:36] -- Executing [1;36;40mAGI[0;37;40m("[1;35;40mSIP/6208-b7b9f4a0[0;37;40m", "[1;35;40magi-NVA_recording.agi|BOTH------Y---N---Y[0;37;40m") in new stack [May 3 11:47:36] -- Launched AGI Script /var/lib/asterisk/agi-bin/agi-NVA_recording.agi 2011-05-03 11:47:36|agi-NVA_recording.agi|Perl Environment Dump: 2011-05-03 11:47:36|agi-NVA_recording.agi|BOTH||N|Y| 2011-05-03 11:47:36|agi-NVA_recording.agi|request|agi-NVA_recording.agi 2011-05-03 11:47:36|agi-NVA_recording.agi|channel|SIP/6208-b7b9f4a0 2011-05-03 11:47:36|agi-NVA_recording.agi|language|en 2011-05-03 11:47:36|agi-NVA_recording.agi|type|SIP 2011-05-03 11:47:36|agi-NVA_recording.agi|uniqueid|1304394456.412 2011-05-03 11:47:36|agi-NVA_recording.agi|callerid|6208 2011-05-03 11:47:36|agi-NVA_recording.agi|calleridname|station 6208 2011-05-03 11:47:36|agi-NVA_recording.agi|callingpres|0 2011-05-03 11:47:36|agi-NVA_recording.agi|callingani2|0 2011-05-03 11:47:36|agi-NVA_recording.agi|callington|0 2011-05-03 11:47:36|agi-NVA_recording.agi|callingtns|0 2011-05-03 11:47:36|agi-NVA_recording.agi|dnid|8613594805280 2011-05-03 11:47:36|agi-NVA_recording.agi|rdnis|unknown 2011-05-03 11:47:36|agi-NVA_recording.agi|context|default 2011-05-03 11:47:36|agi-NVA_recording.agi|extension|8613594805280 2011-05-03 11:47:36|agi-NVA_recording.agi|priority|1 2011-05-03 11:47:36|agi-NVA_recording.agi|enhanced|0.0 2011-05-03 11:47:36|agi-NVA_recording.agi|accountcode| [May 3 11:47:36] -- AGI Script Executing Application: (Monitor) Options: (wav|/var/spool/asterisk/monitor/20110503-114736_6208_8613594805280) [May 3 11:47:36] -- AGI Script agi-NVA_recording.agi completed, returning 0 [May 3 11:47:36] -- Executing [1;36;40mDial[0;37;40m("[1;35;40mSIP/6208-b7b9f4a0[0;37;40m", "[1;35;40mIAX2/hkzh3carrier/8613594805280||tTor[0;37;40m") in new stack [May 3 11:47:36] -- Called hkzh3carrier/8613594805280 [May 3 11:47:36] -- Call accepted by 192.168.1.39 (format g729) [May 3 11:47:36] -- Format for call is g729 [May 3 11:47:36] -- IAX2/hkzh3carrier-13530 is making progress passing it to SIP/6208-b7b9f4a0 [May 3 11:47:36] -- IAX2/hkzh3carrier-13530 is proceeding passing it to SIP/6208-b7b9f4a0 [May 3 11:48:11] -- IAX2/hkzh3carrier-13530 answered SIP/6208-b7b9f4a0 [May 3 11:50:40] -- Hungup 'IAX2/hkzh3carrier-13530' [May 3 11:50:40] == Spawn extension (default, 8613594805280, 2) exited non-zero on 'SIP/6208-b7b9f4a0' [May 3 11:50:40] -- Executing [1;36;40mDeadAGI[0;37;40m("[1;35;40mSIP/6208-b7b9f4a0[0;37;40m", "[1;35;40magi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----184-----149[0;37;40m") in new stack [May 3 11:50:40] -- AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----184-----149 completed, returning 0

Posted: **Tue May 03, 2011 3:01 am**

The debug info on dialer server

Code: Select all: [May 3 11:47:36] DEBUG[2556]: Manager received command 'Command' [May 3 11:47:36] DEBUG[2413]: Setting NAT on RTP to 524288 [May 3 11:47:36] DEBUG[2413]: Stopping retransmission on '2d43baa1f8bd55a7@192.168.4.211' of Response 39542: Match Found [May 3 11:47:36] DEBUG[2413]: Setting NAT on RTP to 524288 [May 3 11:47:36] DEBUG[2413]: Checking SIP call limits for device 6208 [May 3 11:47:36] DEBUG[2413]: build_route: Contact hop: <sip:6208@192.168.4.211:5060;transport=udp> [May 3 11:47:36] DEBUG[2386]: Avoiding initial deadlock for 'SIP/6208-b7b9f4a0' [May 3 11:47:36] VERBOSE[30318]: [May 3 11:47:36] -- Executing AGI("SIP/6208-b7b9f4a0", "agi-NVA_recording.agi|BOTH------Y---N---Y") in new stack [May 3 11:47:36] VERBOSE[30318]: [May 3 11:47:36] -- Launched AGI Script /var/lib/asterisk/agi-bin/agi-NVA_recording.agi [May 3 11:47:36] VERBOSE[30318]: [May 3 11:47:36] -- AGI Script Executing Application: (Monitor) Options: (wav|/var/spool/asterisk/monitor/20110503-114736_6208_8613594805280) [May 3 11:47:36] VERBOSE[30318]: [May 3 11:47:36] -- AGI Script agi-NVA_recording.agi completed, returning 0 [May 3 11:47:36] VERBOSE[30318]: [May 3 11:47:36] -- Executing Dial("SIP/6208-b7b9f4a0", "IAX2/hkzh3carrier/8613594805280||tTor") in new stack [May 3 11:47:36] VERBOSE[30318]: [May 3 11:47:36] -- Called hkzh3carrier/8613594805280 [May 3 11:47:36] VERBOSE[2406]: [May 3 11:47:36] -- Call accepted by 192.168.1.39 (format g729) [May 3 11:47:36] VERBOSE[2406]: [May 3 11:47:36] -- Format for call is g729 [May 3 11:47:36] VERBOSE[30318]: [May 3 11:47:36] -- IAX2/hkzh3carrier-13530 is making progress passing it to SIP/6208-b7b9f4a0 [May 3 11:47:36] DEBUG[2406]: Ooh, voice format changed to 256 [May 3 11:47:36] VERBOSE[30318]: [May 3 11:47:36] -- IAX2/hkzh3carrier-13530 is proceeding passing it to SIP/6208-b7b9f4a0 [May 3 11:47:36] DEBUG[2556]: Manager received command 'Command' [May 3 11:47:44] DEBUG[2406]: Peer lastms 15, historicms 15, maxms 2000 [May 3 11:47:44] DEBUG[2406]: Peer lastms 5, historicms 5, maxms 2000 [May 3 11:47:44] DEBUG[2406]: Peer lastms 7, historicms 7, maxms 2000 [May 3 11:47:45] VERBOSE[2381]: [May 3 11:47:45] -- Remote UNIX connection [May 3 11:47:56] DEBUG[2406]: Immediately destroying 12993, having received hangup [May 3 11:47:56] DEBUG[30232]: Didn't get a frame from channel: IAX2/hkzh3carrier-12993 [May 3 11:47:56] DEBUG[30232]: Bridge stops bridging channels SIP/6203-b7b9b6f0 and IAX2/hkzh3carrier-12993 [May 3 11:47:56] DEBUG[30232]: We're hanging up IAX2/hkzh3carrier-12993 now... [May 3 11:47:56] DEBUG[30232]: Really destroying IAX2/hkzh3carrier-12993 now... [May 3 11:47:56] VERBOSE[30232]: [May 3 11:47:56] -- Hungup 'IAX2/hkzh3carrier-12993' [May 3 11:47:56] DEBUG[30232]: Exiting with DIALSTATUS=ANSWER. [May 3 11:47:56] VERBOSE[30232]: [May 3 11:47:56] == Spawn extension (default, 8613515779721, 2) exited non-zero on 'SIP/6203-b7b9b6f0' [May 3 11:47:56] VERBOSE[30232]: [May 3 11:47:56] -- Executing DeadAGI("SIP/6203-b7b9b6f0", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----57-----33") in new stack [May 3 11:47:56] VERBOSE[30232]: [May 3 11:47:56] -- AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----57-----33 completed, returning 0 [May 3 11:47:56] DEBUG[30232]: update_call_counter(6203) - decrement call limit counter [May 3 11:47:56] DEBUG[30232]: Function result is '"station 6203" <6203>' [May 3 11:47:56] DEBUG[30232]: Function result is '6203' [May 3 11:47:56] DEBUG[30232]: Function result is '8613515779721' [May 3 11:47:56] DEBUG[30232]: Function result is 'default' [May 3 11:47:56] DEBUG[30232]: Function result is 'SIP/6203-b7b9b6f0' [May 3 11:47:56] DEBUG[30232]: Function result is 'IAX2/hkzh3carrier-12993' [May 3 11:47:56] DEBUG[30232]: Function result is 'DeadAGI' [May 3 11:47:56] DEBUG[30232]: Function result is 'agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----' [May 3 11:47:56] DEBUG[30232]: Function result is '2011-05-03 11:46:59' [May 3 11:47:56] DEBUG[30232]: Function result is '2011-05-03 11:47:23' [May 3 11:47:56] DEBUG[30232]: Function result is '2011-05-03 11:47:56' [May 3 11:47:56] DEBUG[30232]: Function result is '57' [May 3 11:47:56] DEBUG[30232]: Function result is '33' [May 3 11:47:56] DEBUG[30232]: Function result is 'ANSWERED' [May 3 11:47:56] DEBUG[30232]: Function result is 'DOCUMENTATION' [May 3 11:47:56] DEBUG[30232]: Function result is '(null)' [May 3 11:47:56] DEBUG[30232]: Function result is '1304394419.410' [May 3 11:47:56] DEBUG[30232]: Function result is '(null)' [May 3 11:47:56] DEBUG[2413]: Stopping retransmission on 'NDMyNDgxMDdhYjZkZDc3MTE4OWY3OThkNDY3ZmIxMmI.' of Request 102: Match Found [May 3 11:47:58] DEBUG[2406]: Peer lastms 6, historicms 6, maxms 2000 [May 3 11:48:02] DEBUG[30396]: Manager received command 'Login' [May 3 11:48:02] VERBOSE[30396]: [May 3 11:48:02] == Parsing '/etc/asterisk/manager.conf': [May 3 11:48:02] VERBOSE[30396]: [May 3 11:48:02] == Parsing '/etc/asterisk/manager.conf': [May 3 11:48:02] Found [May 3 11:48:02] VERBOSE[30396]: [May 3 11:48:02] == Manager 'sendcron' logged on from 127.0.0.1 [May 3 11:48:02] DEBUG[30396]: Manager received command 'MailboxCount' [May 3 11:48:02] DEBUG[30396]: Manager received command 'Ping' [May 3 11:48:02] DEBUG[30398]: Manager received command 'Login' [May 3 11:48:02] VERBOSE[30398]: [May 3 11:48:02] == Parsing '/etc/asterisk/manager.conf': [May 3 11:48:02] VERBOSE[30398]: [May 3 11:48:02] == Parsing '/etc/asterisk/manager.conf': [May 3 11:48:02] Found [May 3 11:48:02] VERBOSE[30398]: [May 3 11:48:02] == Manager 'sendcron' logged on from 127.0.0.1 [May 3 11:48:02] DEBUG[30398]: Manager received command 'Command' [.....Same message.........] [May 3 11:48:07] DEBUG[30396]: Manager received command 'Ping' [May 3 11:48:07] DEBUG[30422]: Manager received command 'Login' [May 3 11:48:07] VERBOSE[30422]: [May 3 11:48:07] == Parsing '/etc/asterisk/manager.conf': [May 3 11:48:07] VERBOSE[30422]: [May 3 11:48:07] == Parsing '/etc/asterisk/manager.conf': [May 3 11:48:07] Found [May 3 11:48:07] VERBOSE[30422]: [May 3 11:48:07] == Manager 'sendcron' logged on from 127.0.0.1 [.....Same message.........] [May 3 11:48:09] DEBUG[30396]: Manager received command 'MailboxCount' [May 3 11:48:09] DEBUG[30396]: Manager received command 'Ping' [May 3 11:48:09] DEBUG[30396]: Manager received command 'MailboxCount' [May 3 11:48:09] DEBUG[30396]: Manager received command 'Ping' [May 3 11:48:10] DEBUG[30396]: Manager received command 'Logoff' [May 3 11:48:10] VERBOSE[30396]: [May 3 11:48:10] == Manager 'sendcron' logged off from 127.0.0.1 [May 3 11:48:11] DEBUG[2556]: Manager received command 'Command' [May 3 11:48:11] VERBOSE[30318]: [May 3 11:48:11] -- IAX2/hkzh3carrier-13530 answered SIP/6208-b7b9f4a0 [May 3 11:48:11] DEBUG[2413]: Stopping retransmission on '2d43baa1f8bd55a7@192.168.4.211' of Response 39543: Match Found [May 3 11:48:11] DEBUG[2556]: Manager received command 'Command' [.....Same message.........] [May 3 11:48:20] DEBUG[2556]: Manager received command 'Command' [May 3 11:48:21] DEBUG[2413]: Stopping retransmission on '61887a2f2e7885e43ea9d34f4de3c9fb@192.168.2.38' of Request 102: Match Found [May 3 11:48:21] DEBUG[2556]: Manager received command 'Command' [.....Same message.........] [May 3 11:48:29] DEBUG[2556]: Manager received command 'Command' [May 3 11:48:29] DEBUG[2413]: Auto destroying call 'YmUyZjhmMTZhMGZlZDM2ODdlNGM2NmZlZWRkZWI4Zjc.' [May 3 11:48:29] DEBUG[2556]: Manager received command 'Command' [.....Same message.........] [May 3 11:48:32] DEBUG[2556]: Manager received command 'Command' [May 3 11:48:32] DEBUG[2413]: Stopping retransmission on '2a4cf2fe155c099b301bfb4c0af549d9@192.168.2.38' of Request 102: Match Found [May 3 11:48:33] DEBUG[2556]: Manager received command 'Command' [.....Same message.........] [May 3 11:48:36] DEBUG[2556]: Manager received command 'Command' [May 3 11:48:37] DEBUG[2413]: Setting NAT on RTP to 524288 [May 3 11:48:37] DEBUG[2413]: Stopping retransmission on 'Yjk3ZDBjYWQ3ZTM3ZjAzYjc3N2NhYjM5OGUzNWY2MmQ.' of Response 1: Match Found [May 3 11:48:37] DEBUG[2413]: Setting NAT on RTP to 524288 [May 3 11:48:37] DEBUG[2413]: Checking SIP call limits for device 6203 [May 3 11:48:37] DEBUG[2413]: build_route: Contact hop: <sip:6203@192.168.4.232:55564> [May 3 11:48:37] DEBUG[2386]: Avoiding initial deadlock for 'SIP/6203-b7b9b6f0' [May 3 11:48:37] VERBOSE[30494]: [May 3 11:48:37] -- Executing AGI("SIP/6203-b7b9b6f0", "agi-NVA_recording.agi|BOTH------Y---N---Y") in new stack [May 3 11:48:37] VERBOSE[30494]: [May 3 11:48:37] -- Launched AGI Script /var/lib/asterisk/agi-bin/agi-NVA_recording.agi [May 3 11:48:37] VERBOSE[30494]: [May 3 11:48:37] -- AGI Script Executing Application: (Monitor) Options: (wav|/var/spool/asterisk/monitor/20110503-114837_6203_8613968931578) [May 3 11:48:37] DEBUG[2556]: Manager received command 'Command' [May 3 11:48:37] VERBOSE[30494]: [May 3 11:48:37] -- AGI Script agi-NVA_recording.agi completed, returning 0 [May 3 11:48:37] VERBOSE[30494]: [May 3 11:48:37] -- Executing Dial("SIP/6203-b7b9b6f0", "IAX2/hkzh3carrier/8613968931578||tTor") in new stack [May 3 11:48:37] VERBOSE[30494]: [May 3 11:48:37] -- Called hkzh3carrier/8613968931578 [May 3 11:48:37] VERBOSE[2406]: [May 3 11:48:37] -- Call accepted by 192.168.1.39 (format g729) [May 3 11:48:37] VERBOSE[2406]: [May 3 11:48:37] -- Format for call is g729 [May 3 11:48:37] VERBOSE[30494]: [May 3 11:48:37] -- IAX2/hkzh3carrier-4714 is making progress passing it to SIP/6203-b7b9b6f0 [May 3 11:48:37] DEBUG[2406]: Ooh, voice format changed to 256 [May 3 11:48:37] DEBUG[2413]: Auto destroying call 'Njg1ZjkzZjk0NjY3NGE4MzJkYzk2NmZmMTBlMDRiMTg.' [May 3 11:48:37] VERBOSE[30494]: [May 3 11:48:37] -- IAX2/hkzh3carrier-4714 is proceeding passing it to SIP/6203-b7b9b6f0 [May 3 11:48:37] DEBUG[2556]: Manager received command 'Command' [.....Same message.........] [May 3 11:48:43] DEBUG[2556]: Manager received command 'Command' [May 3 11:48:44] DEBUG[2406]: Peer lastms 16, historicms 16, maxms 2000 [May 3 11:48:44] DEBUG[2406]: Peer lastms 3, historicms 3, maxms 2000 [May 3 11:48:44] DEBUG[2406]: Peer lastms 4, historicms 4, maxms 2000 [May 3 11:48:44] DEBUG[2556]: Manager received command 'Command' [.....Same message.........] [May 3 11:48:52] DEBUG[2556]: Manager received command 'Command' [May 3 11:48:52] DEBUG[2406]: ##### Testing 127.0.0.1 with 0.0.0.0 [.....Same message.........] [May 3 11:48:52] DEBUG[2406]: ##### Testing 127.0.0.1 with 0.0.0.0 [May 3 11:48:53] DEBUG[2556]: Manager received command 'Command' [.....Same message.........] [May 3 11:48:56] DEBUG[2556]: Manager received command 'Command' [May 3 11:48:56] VERBOSE[30494]: [May 3 11:48:56] -- IAX2/hkzh3carrier-4714 answered SIP/6203-b7b9b6f0 [May 3 11:48:56] DEBUG[2413]: Stopping retransmission on 'Yjk3ZDBjYWQ3ZTM3ZjAzYjc3N2NhYjM5OGUzNWY2MmQ.' of Response 2: Match Found [May 3 11:48:56] DEBUG[2556]: Manager received command 'Command' [May 3 11:48:58] DEBUG[2406]: Peer lastms 6, historicms 6, maxms 2000 [May 3 11:48:58] DEBUG[2556]: Manager received command 'Command' [May 3 11:49:01] DEBUG[30553]: Manager received command 'Login' [May 3 11:49:01] VERBOSE[30553]: [May 3 11:49:01] == Parsing '/etc/asterisk/manager.conf': [May 3 11:49:01] VERBOSE[30553]: [May 3 11:49:01] == Parsing '/etc/asterisk/manager.conf': [May 3 11:49:01] Found [May 3 11:49:01] VERBOSE[30553]: [May 3 11:49:01] == Manager 'sendcron' logged on from 127.0.0.1 [May 3 11:49:01] DEBUG[30553]: Manager received command 'Command' [May 3 11:49:01] DEBUG[30553]: Manager received command 'Ping' [May 3 11:49:01] DEBUG[2556]: Manager received command 'Command' [May 3 11:49:01] DEBUG[30559]: Manager received command 'Login' [May 3 11:49:01] VERBOSE[30559]: [May 3 11:49:01] == Parsing '/etc/asterisk/manager.conf': [May 3 11:49:01] VERBOSE[30559]: [May 3 11:49:01] == Parsing '/etc/asterisk/manager.conf': [May 3 11:49:01] Found [May 3 11:49:01] VERBOSE[30559]: [May 3 11:49:01] == Manager 'sendcron' logged on from 127.0.0.1 [May 3 11:49:01] DEBUG[30559]: Manager received command 'MailboxCount' [May 3 11:49:01] DEBUG[30559]: Manager received command 'Ping' [May 3 11:49:01] DEBUG[30559]: Manager received command 'MailboxCount' [May 3 11:49:01] DEBUG[30559]: Manager received command 'Ping' [May 3 11:49:01] DEBUG[30553]: Manager received command 'Logoff' [May 3 11:49:01] VERBOSE[30553]: [May 3 11:49:01] == Manager 'sendcron' logged off from 127.0.0.1 [May 3 11:49:01] DEBUG[30559]: Manager received command 'MailboxCount' [May 3 11:49:01] DEBUG[30559]: Manager received command 'Ping' [May 3 11:49:01] DEBUG[30559]: Manager received command 'MailboxCount' [May 3 11:49:02] DEBUG[30559]: Manager received command 'Ping' [May 3 11:49:02] DEBUG[2406]: Peer lastms 20, historicms 20, maxms 2000 [May 3 11:49:02] DEBUG[2406]: Peer lastms 6, historicms 6, maxms 2000 [May 3 11:49:02] DEBUG[2406]: Peer lastms 9, historicms 9, maxms 2000 [May 3 11:49:02] DEBUG[30559]: Manager received command 'MailboxCount' [May 3 11:49:02] DEBUG[30559]: Manager received command 'Ping' [.....Same message.........] [May 3 11:49:03] DEBUG[30559]: Manager received command 'Ping' [May 3 11:49:03] DEBUG[2413]: Setting NAT on RTP to 524288 [May 3 11:49:03] DEBUG[2413]: Stopping retransmission on 'MTRiZGNhNmFlMTlmZDNhNDYxNzMzMmRlNjMyNzE5Zjc.' of Response 1: Match Found [May 3 11:49:03] DEBUG[2413]: Setting NAT on RTP to 524288 [May 3 11:49:03] DEBUG[2413]: Checking SIP call limits for device 6216 [May 3 11:49:03] DEBUG[2413]: build_route: Contact hop: <sip:6216@192.168.4.206:25822> [May 3 11:49:03] DEBUG[2386]: Avoiding initial deadlock for 'SIP/6216-b7bc9050' [May 3 11:49:03] VERBOSE[30562]: [May 3 11:49:03] -- Executing AGI("SIP/6216-b7bc9050", "agi-NVA_recording.agi|BOTH------Y---N---Y") in new stack [May 3 11:49:03] VERBOSE[30562]: [May 3 11:49:03] -- Launched AGI Script /var/lib/asterisk/agi-bin/agi-NVA_recording.agi [May 3 11:49:03] DEBUG[30559]: Manager received command 'MailboxCount' [May 3 11:49:03] DEBUG[30559]: Manager received command 'Ping' [May 3 11:49:03] VERBOSE[30562]: [May 3 11:49:03] -- AGI Script Executing Application: (Monitor) Options: (wav|/var/spool/asterisk/monitor/20110503-114903_6216_8613683375250) [May 3 11:49:03] VERBOSE[30562]: [May 3 11:49:03] -- AGI Script agi-NVA_recording.agi completed, returning 0 [May 3 11:49:03] VERBOSE[30562]: [May 3 11:49:03] -- Executing Dial("SIP/6216-b7bc9050", "IAX2/hkzh3carrier/8613683375250||tTor") in new stack [May 3 11:49:03] DEBUG[2386]: Avoiding initial deadlock for 'IAX2/hkzh3carrier-4590' [May 3 11:49:03] VERBOSE[30562]: [May 3 11:49:03] -- Called hkzh3carrier/8613683375250 [May 3 11:49:03] DEBUG[30559]: Manager received command 'MailboxCount' [May 3 11:49:03] DEBUG[30559]: Manager received command 'Ping' [May 3 11:49:03] VERBOSE[2406]: [May 3 11:49:03] -- Call accepted by 192.168.1.39 (format g729) [May 3 11:49:03] VERBOSE[2406]: [May 3 11:49:03] -- Format for call is g729 [May 3 11:49:03] VERBOSE[30562]: [May 3 11:49:03] -- IAX2/hkzh3carrier-4590 is making progress passing it to SIP/6216-b7bc9050 [May 3 11:49:03] DEBUG[30559]: Manager received command 'MailboxCount' [May 3 11:49:03] DEBUG[30559]: Manager received command 'Ping' [May 3 11:49:03] DEBUG[2406]: Ooh, voice format changed to 256 [May 3 11:49:03] DEBUG[30559]: Manager received command 'MailboxCount' [May 3 11:49:03] DEBUG[30559]: Manager received command 'Ping' [May 3 11:49:03] VERBOSE[30562]: [May 3 11:49:03] -- IAX2/hkzh3carrier-4590 is proceeding passing it to SIP/6216-b7bc9050 [May 3 11:49:03] DEBUG[30559]: Manager received command 'MailboxCount' [.....Same message.........] [May 3 11:49:06] DEBUG[30559]: Manager received command 'Ping' [May 3 11:49:06] DEBUG[30559]: Manager received command 'MailboxCount' [May 3 11:49:06] VERBOSE[30571]: [May 3 11:49:06] == Parsing '/etc/asterisk/manager.conf': [May 3 11:49:06] VERBOSE[30571]: [May 3 11:49:06] == Parsing '/etc/asterisk/manager.conf': [May 3 11:49:06] Found [May 3 11:49:06] VERBOSE[30571]: [May 3 11:49:06] == Manager 'sendcron' logged on from 127.0.0.1 [May 3 11:49:06] DEBUG[30571]: Manager received command 'Command' [May 3 11:49:06] DEBUG[30571]: Manager received command 'Logoff' [May 3 11:49:06] VERBOSE[30571]: [May 3 11:49:06] == Manager 'sendcron' logged off from 127.0.0.1 [May 3 11:49:06] DEBUG[30559]: Manager received command 'MailboxCount' [May 3 11:49:06] DEBUG[30559]: Manager received command 'Ping' [May 3 11:49:09] DEBUG[2556]: Manager received command 'Command' [May 3 11:49:09] DEBUG[2556]: Manager received command 'Command' [May 3 11:49:09] DEBUG[2406]: Peer lastms 2, historicms 2, maxms 2000 [May 3 11:49:09] DEBUG[2556]: Manager received command 'Command' [May 3 11:49:35] DEBUG[2556]: Manager received command 'Command' [May 3 11:49:36] DEBUG[2556]: Manager received command 'Command' [May 3 11:49:36] VERBOSE[30359]: [May 3 11:49:36] -- Remote UNIX connection disconnected [.....Same message.........] [May 3 11:49:42] DEBUG[2556]: Manager received command 'Command' [May 3 11:49:42] DEBUG[2406]: ##### Testing 127.0.0.1 with 0.0.0.0 [May 3 11:49:42] DEBUG[2406]: ##### Testing 127.0.0.1 with 0.0.0.0 [May 3 11:49:43] DEBUG[2556]: Manager received command 'Command' [May 3 11:49:44] DEBUG[2556]: Manager received command 'Command' [May 3 11:49:44] DEBUG[2406]: Peer lastms 16, historicms 16, maxms 2000 [May 3 11:49:44] DEBUG[2406]: Peer lastms 5, historicms 5, maxms 2000 [May 3 11:49:44] DEBUG[2406]: Peer lastms 4, historicms 4, maxms 2000 [May 3 11:49:44] DEBUG[2556]: Manager received command 'Command' [.....Same message.........] [May 3 11:49:52] DEBUG[2556]: Manager received command 'Command' [May 3 11:49:52] DEBUG[2413]: Setting NAT on RTP to 524288 [May 3 11:49:52] DEBUG[2413]: Stopping retransmission on '9ce6f1fe8fe0c218@192.168.4.199' of Response 29090: Match Found [May 3 11:49:52] DEBUG[2413]: Setting NAT on RTP to 524288 [May 3 11:49:52] DEBUG[2413]: Checking SIP call limits for device 6206 [May 3 11:49:52] DEBUG[2413]: build_route: Contact hop: <sip:6206@192.168.4.199:5060;transport=udp> [May 3 11:49:52] DEBUG[2386]: Avoiding initial deadlock for 'SIP/6206-b7bce9a0' [May 3 11:49:52] VERBOSE[30641]: [May 3 11:49:52] -- Executing AGI("SIP/6206-b7bce9a0", "agi-NVA_recording.agi|BOTH------Y---N---Y") in new stack [May 3 11:49:52] VERBOSE[30641]: [May 3 11:49:52] -- Launched AGI Script /var/lib/asterisk/agi-bin/agi-NVA_recording.agi [May 3 11:49:52] VERBOSE[30641]: [May 3 11:49:52] -- AGI Script Executing Application: (Monitor) Options: (wav|/var/spool/asterisk/monitor/20110503-114952_6206_23907433) [May 3 11:49:52] VERBOSE[30641]: [May 3 11:49:52] -- AGI Script agi-NVA_recording.agi completed, returning 0 [May 3 11:49:52] VERBOSE[30641]: [May 3 11:49:52] -- Executing Dial("SIP/6206-b7bce9a0", "IAX2/hkzh3carrier/23907433||tTor") in new stack [May 3 11:49:52] VERBOSE[30641]: [May 3 11:49:52] -- Called hkzh3carrier/23907433 [May 3 11:49:52] VERBOSE[2406]: [May 3 11:49:52] -- Call accepted by 192.168.1.39 (format g729) [May 3 11:49:52] VERBOSE[2406]: [May 3 11:49:52] -- Format for call is g729 [May 3 11:49:52] DEBUG[2406]: Ooh, voice format changed to 256 [May 3 11:49:52] VERBOSE[30641]: [May 3 11:49:52] -- IAX2/hkzh3carrier-2692 is proceeding passing it to SIP/6206-b7bce9a0 [May 3 11:49:52] DEBUG[2556]: Manager received command 'Command' [May 3 11:49:54] VERBOSE[30641]: [May 3 11:49:54] -- IAX2/hkzh3carrier-2692 is ringing [May 3 11:49:54] DEBUG[2556]: Manager received command 'Command' [May 3 11:49:56] VERBOSE[30641]: [May 3 11:49:56] -- IAX2/hkzh3carrier-2692 answered SIP/6206-b7bce9a0 [May 3 11:49:56] DEBUG[2413]: Stopping retransmission on '9ce6f1fe8fe0c218@192.168.4.199' of Response 29091: Match Found [May 3 11:49:56] DEBUG[2556]: Manager received command 'Command' [May 3 11:49:58] DEBUG[2406]: Peer lastms 6, historicms 6, maxms 2000 [May 3 11:49:58] DEBUG[2556]: Manager received command 'Command' [May 3 11:50:01] DEBUG[2556]: Manager received command 'Command' [May 3 11:50:01] DEBUG[30672]: Manager received command 'Login' [May 3 11:50:01] VERBOSE[30672]: [May 3 11:50:01] == Parsing '/etc/asterisk/manager.conf': [May 3 11:50:01] VERBOSE[30672]: [May 3 11:50:01] == Parsing '/etc/asterisk/manager.conf': [May 3 11:50:01] Found [May 3 11:50:01] VERBOSE[30672]: [May 3 11:50:01] == Manager 'sendcron' logged on from 127.0.0.1 [May 3 11:50:01] DEBUG[30672]: Manager received command 'Command' [May 3 11:50:01] DEBUG[30672]: Manager received command 'Ping' [May 3 11:50:01] DEBUG[30674]: Manager received command 'Login' [May 3 11:50:01] VERBOSE[30674]: [May 3 11:50:01] == Parsing '/etc/asterisk/manager.conf': [May 3 11:50:01] VERBOSE[30674]: [May 3 11:50:01] == Parsing '/etc/asterisk/manager.conf': [May 3 11:50:01] Found [May 3 11:50:01] VERBOSE[30674]: [May 3 11:50:01] == Manager 'sendcron' logged on from 127.0.0.1 [May 3 11:50:01] DEBUG[30674]: Manager received command 'MailboxCount' [May 3 11:50:01] DEBUG[30674]: Manager received command 'Ping' [May 3 11:50:01] DEBUG[30674]: Manager received command 'MailboxCount' [May 3 11:50:01] DEBUG[30674]: Manager received command 'Ping' [May 3 11:50:01] DEBUG[30672]: Manager received command 'Logoff' [May 3 11:50:01] VERBOSE[30672]: [May 3 11:50:01] == Manager 'sendcron' logged off from 127.0.0.1 [May 3 11:50:01] DEBUG[30674]: Manager received command 'MailboxCount' [May 3 11:50:01] DEBUG[30674]: Manager received command 'Ping' [.....Same message.........] [May 3 11:50:09] VERBOSE[30674]: [May 3 11:50:09] == Manager 'sendcron' logged off from 127.0.0.1 [May 3 11:50:09] DEBUG[2556]: Manager received command 'Command' [May 3 11:50:09] DEBUG[2406]: Peer lastms 2, historicms 2, maxms 2000 [May 3 11:50:10] DEBUG[2556]: Manager received command 'Command' [May 3 11:50:11] DEBUG[30562]: We're hanging up IAX2/hkzh3carrier-4590 now... [May 3 11:50:11] VERBOSE[30562]: [May 3 11:50:11] -- Hungup 'IAX2/hkzh3carrier-4590' [May 3 11:50:11] DEBUG[30562]: Exiting with DIALSTATUS=CANCEL. [May 3 11:50:11] VERBOSE[30562]: [May 3 11:50:11] == Spawn extension (default, 8613683375250, 2) exited non-zero on 'SIP/6216-b7bc9050' [May 3 11:50:11] VERBOSE[30562]: [May 3 11:50:11] -- Executing DeadAGI("SIP/6216-b7bc9050", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0-----CANCEL----------") in new stack [May 3 11:50:11] DEBUG[2413]: Stopping retransmission on 'MTRiZGNhNmFlMTlmZDNhNDYxNzMzMmRlNjMyNzE5Zjc.' of Response 2: Match Found [May 3 11:50:11] VERBOSE[30562]: [May 3 11:50:11] -- AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0-----CANCEL---------- completed, returning 0 [May 3 11:50:11] DEBUG[30562]: update_call_counter(6216) - decrement call limit counter [May 3 11:50:11] DEBUG[30562]: Function result is '"station 6216" <6216>' [May 3 11:50:11] DEBUG[30562]: Function result is '6216' [May 3 11:50:11] DEBUG[30562]: Function result is '8613683375250' [May 3 11:50:11] DEBUG[30562]: Function result is 'default' [May 3 11:50:11] DEBUG[30562]: Function result is 'SIP/6216-b7bc9050' [May 3 11:50:11] DEBUG[30562]: Function result is 'IAX2/hkzh3carrier-4590' [May 3 11:50:11] DEBUG[30562]: Function result is 'Dial' [May 3 11:50:11] DEBUG[30562]: Function result is 'IAX2/hkzh3carrier/8613683375250||tTor' [May 3 11:50:11] DEBUG[30562]: Function result is '2011-05-03 11:49:03' [May 3 11:50:11] DEBUG[30562]: Function result is '(null)' [May 3 11:50:11] DEBUG[30562]: Function result is '2011-05-03 11:50:11' [May 3 11:50:11] DEBUG[30562]: Function result is '68' [May 3 11:50:11] DEBUG[30562]: Function result is '0' [May 3 11:50:11] DEBUG[30562]: Function result is 'NO ANSWER' [May 3 11:50:11] DEBUG[30562]: Function result is 'DOCUMENTATION' [May 3 11:50:11] DEBUG[30562]: Function result is '(null)' [May 3 11:50:11] DEBUG[30562]: Function result is '1304394543.416' [May 3 11:50:11] DEBUG[30562]: Function result is '(null)' [May 3 11:50:11] DEBUG[2556]: Manager received command 'Command' [May 3 11:50:11] DEBUG[2556]: Manager received command 'Command' [May 3 11:50:12] DEBUG[2556]: Manager received command 'Command' [May 3 11:50:12] DEBUG[2413]: Setting NAT on RTP to 524288 [May 3 11:50:12] DEBUG[2413]: Stopping retransmission on '40820e4289b53ebc@192.168.4.223' of Response 39172: Match Found [May 3 11:50:12] DEBUG[2413]: Setting NAT on RTP to 524288 [May 3 11:50:12] DEBUG[2413]: Checking SIP call limits for device 6204 [May 3 11:50:12] DEBUG[2413]: build_route: Contact hop: <sip:6204@192.168.4.223:5060;transport=udp> [May 3 11:50:12] DEBUG[2386]: Avoiding initial deadlock for 'SIP/6204-b7bc9050' [May 3 11:50:12] VERBOSE[30698]: [May 3 11:50:12] -- Executing AGI("SIP/6204-b7bc9050", "agi-NVA_recording.agi|BOTH------Y---N---Y") in new stack [May 3 11:50:12] VERBOSE[30698]: [May 3 11:50:12] -- Launched AGI Script /var/lib/asterisk/agi-bin/agi-NVA_recording.agi [May 3 11:50:12] VERBOSE[30698]: [May 3 11:50:12] -- AGI Script Executing Application: (Monitor) Options: (wav|/var/spool/asterisk/monitor/20110503-115012_6204_86133068613309314868) [May 3 11:50:12] VERBOSE[30698]: [May 3 11:50:12] -- AGI Script agi-NVA_recording.agi completed, returning 0 [May 3 11:50:12] VERBOSE[30698]: [May 3 11:50:12] -- Executing Dial("SIP/6204-b7bc9050", "IAX2/hkzh3carrier/86133068613309314868||tTor") in new stack [May 3 11:50:12] VERBOSE[30698]: [May 3 11:50:12] -- Called hkzh3carrier/86133068613309314868 [May 3 11:50:12] VERBOSE[2406]: [May 3 11:50:12] -- Call accepted by 192.168.1.39 (format g729) [May 3 11:50:12] VERBOSE[2406]: [May 3 11:50:12] -- Format for call is g729 [May 3 11:50:12] VERBOSE[30698]: [May 3 11:50:12] -- IAX2/hkzh3carrier-12799 is making progress passing it to SIP/6204-b7bc9050 [May 3 11:50:12] DEBUG[2406]: Ooh, voice format changed to 256 [May 3 11:50:12] VERBOSE[30698]: [May 3 11:50:12] -- IAX2/hkzh3carrier-12799 is proceeding passing it to SIP/6204-b7bc9050 [May 3 11:50:12] DEBUG[2556]: Manager received command 'Command' [May 3 11:50:21] DEBUG[2556]: Manager received command 'Command' [May 3 11:50:21] DEBUG[2413]: Setting NAT on RTP to 524288 [May 3 11:50:21] DEBUG[2413]: Stopping retransmission on 'OTQwM2Q3ZTc4M2E0MTE4ZjZlNDRkNmI0NjcyNTJhZmE.' of Response 1: Match Found [May 3 11:50:21] DEBUG[2413]: Setting NAT on RTP to 524288 [May 3 11:50:21] DEBUG[2413]: Checking SIP call limits for device 6216 [May 3 11:50:21] DEBUG[2413]: build_route: Contact hop: <sip:6216@192.168.4.206:25822> [May 3 11:50:21] DEBUG[2386]: Avoiding initial deadlock for 'SIP/6216-b7bd88e8' [May 3 11:50:21] VERBOSE[30717]: [May 3 11:50:21] -- Executing AGI("SIP/6216-b7bd88e8", "agi-NVA_recording.agi|BOTH------Y---N---Y") in new stack [May 3 11:50:21] VERBOSE[30717]: [May 3 11:50:21] -- Launched AGI Script /var/lib/asterisk/agi-bin/agi-NVA_recording.agi [May 3 11:50:21] VERBOSE[30717]: [May 3 11:50:21] -- AGI Script Executing Application: (Monitor) Options: (wav|/var/spool/asterisk/monitor/20110503-115021_6216_8613501371418) [May 3 11:50:21] VERBOSE[30717]: [May 3 11:50:21] -- AGI Script agi-NVA_recording.agi completed, returning 0 [May 3 11:50:21] VERBOSE[30717]: [May 3 11:50:21] -- Executing Dial("SIP/6216-b7bd88e8", "IAX2/hkzh3carrier/8613501371418||tTor") in new stack [May 3 11:50:21] DEBUG[2386]: Avoiding initial deadlock for 'IAX2/hkzh3carrier-9779' [May 3 11:50:21] VERBOSE[30717]: [May 3 11:50:21] -- Called hkzh3carrier/8613501371418 [May 3 11:50:21] VERBOSE[2406]: [May 3 11:50:21] -- Call accepted by 192.168.1.39 (format g729) [May 3 11:50:21] VERBOSE[2406]: [May 3 11:50:21] -- Format for call is g729 [May 3 11:50:21] VERBOSE[30717]: [May 3 11:50:21] -- IAX2/hkzh3carrier-9779 is making progress passing it to SIP/6216-b7bd88e8 [May 3 11:50:21] DEBUG[2406]: Ooh, voice format changed to 256 [May 3 11:50:21] VERBOSE[30717]: [May 3 11:50:21] -- IAX2/hkzh3carrier-9779 is proceeding passing it to SIP/6216-b7bd88e8 [May 3 11:50:21] DEBUG[2556]: Manager received command 'Command' [.....Same message.........] [May 3 11:50:30] DEBUG[2556]: Manager received command 'Command' [May 3 11:50:30] VERBOSE[30698]: [May 3 11:50:30] -- IAX2/hkzh3carrier-12799 answered SIP/6204-b7bc9050 [May 3 11:50:30] DEBUG[2413]: Stopping retransmission on '40820e4289b53ebc@192.168.4.223' of Response 39173: Match Found [May 3 11:50:30] DEBUG[2556]: Manager received command 'Command' [May 3 11:50:40] DEBUG[2556]: Manager received command 'Command' [May 3 11:50:40] DEBUG[30641]: Didn't get a frame from channel: SIP/6206-b7bce9a0 [May 3 11:50:40] DEBUG[30641]: Bridge stops bridging channels SIP/6206-b7bce9a0 and IAX2/hkzh3carrier-2692 [May 3 11:50:40] DEBUG[30641]: We're hanging up IAX2/hkzh3carrier-2692 now... [May 3 11:50:40] VERBOSE[30641]: [May 3 11:50:40] -- Hungup 'IAX2/hkzh3carrier-2692' [May 3 11:50:40] DEBUG[30641]: Exiting with DIALSTATUS=ANSWER. [May 3 11:50:40] VERBOSE[30641]: [May 3 11:50:40] == Spawn extension (default, 23907433, 2) exited non-zero on 'SIP/6206-b7bce9a0' [May 3 11:50:40] VERBOSE[30641]: [May 3 11:50:40] -- Executing DeadAGI("SIP/6206-b7bce9a0", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----48-----44") in new stack [May 3 11:50:40] VERBOSE[30641]: [May 3 11:50:40] -- AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----48-----44 completed, returning 0 [May 3 11:50:40] DEBUG[30641]: update_call_counter(6206) - decrement call limit counter [May 3 11:50:40] DEBUG[30641]: Function result is '"station 6206" <6206>' [May 3 11:50:40] DEBUG[30641]: Function result is '6206' [May 3 11:50:40] DEBUG[30641]: Function result is '23907433' [May 3 11:50:40] DEBUG[30641]: Function result is 'default' [May 3 11:50:40] DEBUG[30641]: Function result is 'SIP/6206-b7bce9a0' [May 3 11:50:40] DEBUG[30641]: Function result is 'IAX2/hkzh3carrier-2692' [May 3 11:50:40] DEBUG[30641]: Function result is 'Dial' [May 3 11:50:40] DEBUG[30641]: Function result is 'IAX2/hkzh3carrier/23907433||tTor' [May 3 11:50:40] DEBUG[30641]: Function result is '2011-05-03 11:49:52' [May 3 11:50:40] DEBUG[30641]: Function result is '2011-05-03 11:49:56' [May 3 11:50:40] DEBUG[30641]: Function result is '2011-05-03 11:50:40' [May 3 11:50:40] DEBUG[30641]: Function result is '48' [May 3 11:50:40] DEBUG[30641]: Function result is '44' [May 3 11:50:40] DEBUG[30641]: Function result is 'ANSWERED' [May 3 11:50:40] DEBUG[30641]: Function result is 'DOCUMENTATION' [May 3 11:50:40] DEBUG[30641]: Function result is '(null)' [May 3 11:50:40] DEBUG[30641]: Function result is '1304394592.418' [May 3 11:50:40] DEBUG[30641]: Function result is '(null)' [May 3 11:50:40] DEBUG[2556]: Manager received command 'Command' [May 3 11:50:40] DEBUG[30318]: Didn't get a frame from channel: SIP/6208-b7b9f4a0 [May 3 11:50:40] DEBUG[30318]: Bridge stops bridging channels SIP/6208-b7b9f4a0 and IAX2/hkzh3carrier-13530 [May 3 11:50:40] DEBUG[30318]: We're hanging up IAX2/hkzh3carrier-13530 now... [May 3 11:50:40] VERBOSE[30318]: [May 3 11:50:40] -- Hungup 'IAX2/hkzh3carrier-13530' [May 3 11:50:40] DEBUG[30318]: Exiting with DIALSTATUS=ANSWER. [May 3 11:50:40] VERBOSE[30318]: [May 3 11:50:40] == Spawn extension (default, 8613594805280, 2) exited non-zero on 'SIP/6208-b7b9f4a0' [May 3 11:50:40] VERBOSE[30318]: [May 3 11:50:40] -- Executing DeadAGI("SIP/6208-b7b9f4a0", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----184-----149") in new stack [May 3 11:50:40] VERBOSE[30318]: [May 3 11:50:40] -- AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----184-----149 completed, returning 0 [May 3 11:50:40] DEBUG[30318]: update_call_counter(6208) - decrement call limit counter [May 3 11:50:40] DEBUG[30318]: Function result is '"station 6208" <6208>' [May 3 11:50:40] DEBUG[30318]: Function result is '6208' [May 3 11:50:40] DEBUG[30318]: Function result is '8613594805280' [May 3 11:50:40] DEBUG[30318]: Function result is 'default' [May 3 11:50:40] DEBUG[30318]: Function result is 'SIP/6208-b7b9f4a0' [May 3 11:50:40] DEBUG[30318]: Function result is 'IAX2/hkzh3carrier-13530' [May 3 11:50:40] DEBUG[30318]: Function result is 'Dial' [May 3 11:50:40] DEBUG[30318]: Function result is 'IAX2/hkzh3carrier/8613594805280||tTor' [May 3 11:50:40] DEBUG[30318]: Function result is '2011-05-03 11:47:36' [May 3 11:50:40] DEBUG[30318]: Function result is '2011-05-03 11:48:11' [May 3 11:50:40] DEBUG[30318]: Function result is '2011-05-03 11:50:40' [May 3 11:50:40] DEBUG[30318]: Function result is '184' [May 3 11:50:40] DEBUG[30318]: Function result is '149' [May 3 11:50:40] DEBUG[30318]: Function result is 'ANSWERED' [May 3 11:50:40] DEBUG[30318]: Function result is 'DOCUMENTATION' [May 3 11:50:40] DEBUG[30318]: Function result is '(null)' [May 3 11:50:40] DEBUG[30318]: Function result is '1304394456.412' [May 3 11:50:40] DEBUG[30318]: Function result is '(null)' [May 3 11:50:41] DEBUG[2556]: Manager received command 'Command' [May 3 11:50:44] DEBUG[2406]: Peer lastms 16, historicms 16, maxms 2000 [May 3 11:50:44] DEBUG[2406]: Peer lastms 5, historicms 5, maxms 2000 [May 3 11:50:44] DEBUG[2406]: Peer lastms 7, historicms 7, maxms 2000 [May 3 11:50:44] DEBUG[2556]: Manager received command 'Command' [May 3 11:50:46] DEBUG[2406]: Immediately destroying 4714, having received hangup [May 3 11:50:46] DEBUG[30494]: Didn't get a frame from channel: IAX2/hkzh3carrier-4714 [May 3 11:50:46] DEBUG[30494]: Bridge stops bridging channels SIP/6203-b7b9b6f0 and IAX2/hkzh3carrier-4714 [May 3 11:50:46] DEBUG[30494]: We're hanging up IAX2/hkzh3carrier-4714 now... [May 3 11:50:46] DEBUG[30494]: Really destroying IAX2/hkzh3carrier-4714 now... [May 3 11:50:46] VERBOSE[30494]: [May 3 11:50:46] -- Hungup 'IAX2/hkzh3carrier-4714' [May 3 11:50:46] DEBUG[30494]: Exiting with DIALSTATUS=ANSWER. [May 3 11:50:46] VERBOSE[30494]: [May 3 11:50:46] == Spawn extension (default, 8613968931578, 2) exited non-zero on 'SIP/6203-b7b9b6f0' [May 3 11:50:46] VERBOSE[30494]: [May 3 11:50:46] -- Executing DeadAGI("SIP/6203-b7b9b6f0", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----129-----110") in new stack [May 3 11:50:46] VERBOSE[30494]: [May 3 11:50:46] -- AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----129-----110 completed, returning 0 [May 3 11:50:46] DEBUG[30494]: update_call_counter(6203) - decrement call limit counter [May 3 11:50:46] DEBUG[30494]: Function result is '"station 6203" <6203>' [May 3 11:50:46] DEBUG[30494]: Function result is '6203' [May 3 11:50:46] DEBUG[30494]: Function result is '8613968931578' [May 3 11:50:46] DEBUG[30494]: Function result is 'default' [May 3 11:50:46] DEBUG[30494]: Function result is 'SIP/6203-b7b9b6f0' [May 3 11:50:46] DEBUG[30494]: Function result is 'IAX2/hkzh3carrier-4714' [May 3 11:50:46] DEBUG[30494]: Function result is 'DeadAGI' [May 3 11:50:46] DEBUG[30494]: Function result is 'agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----' [May 3 11:50:46] DEBUG[30494]: Function result is '2011-05-03 11:48:37' [May 3 11:50:46] DEBUG[30494]: Function result is '2011-05-03 11:48:56' [May 3 11:50:46] DEBUG[30494]: Function result is '2011-05-03 11:50:46' [May 3 11:50:46] DEBUG[30494]: Function result is '129' [May 3 11:50:46] DEBUG[30494]: Function result is '110' [May 3 11:50:46] DEBUG[30494]: Function result is 'ANSWERED' [May 3 11:50:46] DEBUG[30494]: Function result is 'DOCUMENTATION' [May 3 11:50:46] DEBUG[30494]: Function result is '(null)' [May 3 11:50:46] DEBUG[30494]: Function result is '1304394517.414' [May 3 11:50:46] DEBUG[30494]: Function result is '(null)' [May 3 11:50:46] DEBUG[2413]: Stopping retransmission on 'Yjk3ZDBjYWQ3ZTM3ZjAzYjc3N2NhYjM5OGUzNWY2MmQ.' of Request 102: Match Found [May 3 11:50:46] DEBUG[2556]: Manager received command 'Command' [May 3 11:50:58] DEBUG[2556]: Manager received command 'Command' [May 3 11:50:58] DEBUG[2406]: Peer lastms 6, historicms 6, maxms 2000 [May 3 11:51:01] DEBUG[2556]: Manager received command 'Command' [May 3 11:51:01] DEBUG[30717]: We're hanging up IAX2/hkzh3carrier-9779 now... [May 3 11:51:01] VERBOSE[30717]: [May 3 11:51:01] -- Hungup 'IAX2/hkzh3carrier-9779' [May 3 11:51:01] DEBUG[30717]: Exiting with DIALSTATUS=CANCEL. [May 3 11:51:01] VERBOSE[30717]: [May 3 11:51:01] == Spawn extension (default, 8613501371418, 2) exited non-zero on 'SIP/6216-b7bd88e8' [May 3 11:51:01] VERBOSE[30717]: [May 3 11:51:01] -- Executing DeadAGI("SIP/6216-b7bd88e8", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0-----CANCEL----------") in new stack [May 3 11:51:01] VERBOSE[30717]: [May 3 11:51:01] -- AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0-----CANCEL---------- completed, returning 0 [May 3 11:51:01] DEBUG[30717]: update_call_counter(6216) - decrement call limit counter [May 3 11:51:01] DEBUG[30717]: Function result is '"station 6216" <6216>' [May 3 11:51:01] DEBUG[30717]: Function result is '6216' [May 3 11:51:01] DEBUG[30717]: Function result is '8613501371418' [May 3 11:51:01] DEBUG[30717]: Function result is 'default' [May 3 11:51:01] DEBUG[30717]: Function result is 'SIP/6216-b7bd88e8' [May 3 11:51:01] DEBUG[30717]: Function result is 'IAX2/hkzh3carrier-9779' [May 3 11:51:01] DEBUG[30717]: Function result is 'Dial' [May 3 11:51:01] DEBUG[30717]: Function result is 'IAX2/hkzh3carrier/8613501371418||tTor' [May 3 11:51:01] DEBUG[30717]: Function result is '2011-05-03 11:50:21' [May 3 11:51:01] DEBUG[30717]: Function result is '(null)' [May 3 11:51:01] DEBUG[30717]: Function result is '2011-05-03 11:51:01' [May 3 11:51:01] DEBUG[30717]: Function result is '40' [May 3 11:51:01] DEBUG[30717]: Function result is '0' [May 3 11:51:01] DEBUG[30717]: Function result is 'NO ANSWER' [May 3 11:51:01] DEBUG[30717]: Function result is 'DOCUMENTATION' [May 3 11:51:01] DEBUG[30717]: Function result is '(null)' [May 3 11:51:01] DEBUG[30717]: Function result is '1304394621.422' [May 3 11:51:01] DEBUG[30717]: Function result is '(null)' [May 3 11:51:01] DEBUG[2413]: Stopping retransmission on 'OTQwM2Q3ZTc4M2E0MTE4ZjZlNDRkNmI0NjcyNTJhZmE.' of Response 2: Match Found [May 3 11:51:01] DEBUG[30804]: Manager received command 'Login' [May 3 11:51:01] VERBOSE[30804]: [May 3 11:51:01] == Parsing '/etc/asterisk/manager.conf': [May 3 11:51:01] VERBOSE[30804]: [May 3 11:51:01] == Parsing '/etc/asterisk/manager.conf': [May 3 11:51:01] Found [May 3 11:51:01] VERBOSE[30804]: [May 3 11:51:01] == Manager 'sendcron' logged on from 127.0.0.1 [May 3 11:51:01] DEBUG[30804]: Manager received command 'Command' [May 3 11:51:01] DEBUG[30804]: Manager received command 'Ping' [May 3 11:51:01] DEBUG[2556]: Manager received command 'Command' [May 3 11:51:01] DEBUG[30807]: Manager received command 'Login' [May 3 11:51:01] VERBOSE[30807]: [May 3 11:51:01] == Parsing '/etc/asterisk/manager.conf': [May 3 11:51:01] VERBOSE[30807]: [May 3 11:51:01] == Parsing '/etc/asterisk/manager.conf': [May 3 11:51:01] Found [May 3 11:51:01] VERBOSE[30807]: [May 3 11:51:01] == Manager 'sendcron' logged on from 127.0.0.1 [May 3 11:51:01] DEBUG[30807]: Manager received command 'MailboxCount' [May 3 11:51:01] DEBUG[30807]: Manager received command 'Ping' [May 3 11:51:01] DEBUG[30804]: Manager received command 'Logoff' [May 3 11:51:01] VERBOSE[30804]: [May 3 11:51:01] == Manager 'sendcron' logged off from 127.0.0.1 [May 3 11:51:01] DEBUG[30807]: Manager received command 'MailboxCount' [May 3 11:51:01] DEBUG[30807]: Manager received command 'Ping' [May 3 11:51:02] DEBUG[30807]: Manager received command 'Ping' [May 3 11:51:02] DEBUG[2406]: Peer lastms 2, historicms 2, maxms 2000 [May 3 11:51:02] DEBUG[2406]: Peer lastms 9, historicms 9, maxms 2000 [May 3 11:51:02] DEBUG[2406]: Peer lastms 10, historicms 10, maxms 2000 [May 3 11:51:02] DEBUG[30807]: Manager received command 'MailboxCount' [May 3 11:51:03] DEBUG[30807]: Manager received command 'MailboxCount' [May 3 11:51:03] DEBUG[30807]: Manager received command 'Ping' [May 3 11:51:03] DEBUG[2556]: Manager received command 'Command' [.....Same message.........] [May 3 11:51:25] DEBUG[2556]: Manager received command 'Command' [May 3 11:51:26] DEBUG[30698]: Didn't get a frame from channel: SIP/6204-b7bc9050 [May 3 11:51:26] DEBUG[30698]: Bridge stops bridging channels SIP/6204-b7bc9050 and IAX2/hkzh3carrier-12799 [May 3 11:51:26] DEBUG[30698]: We're hanging up IAX2/hkzh3carrier-12799 now... [May 3 11:51:26] VERBOSE[30698]: [May 3 11:51:26] -- Hungup 'IAX2/hkzh3carrier-12799' [May 3 11:51:26] DEBUG[30698]: Exiting with DIALSTATUS=ANSWER. [May 3 11:51:26] VERBOSE[30698]: [May 3 11:51:26] == Spawn extension (default, 86133068613309314868, 2) exited non-zero on 'SIP/6204-b7bc9050' [May 3 11:51:26] VERBOSE[30698]: [May 3 11:51:26] -- Executing DeadAGI("SIP/6204-b7bc9050", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----74-----56") in new stack [May 3 11:51:26] VERBOSE[30698]: [May 3 11:51:26] -- AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----74-----56 completed, returning 0 [May 3 11:51:26] DEBUG[30698]: update_call_counter(6204) - decrement call limit counter [May 3 11:51:26] DEBUG[30698]: Function result is '"station 6204" <6204>' [May 3 11:51:26] DEBUG[30698]: Function result is '6204' [May 3 11:51:26] DEBUG[30698]: Function result is '86133068613309314868' [May 3 11:51:26] DEBUG[30698]: Function result is 'default' [May 3 11:51:26] DEBUG[30698]: Function result is 'SIP/6204-b7bc9050' [May 3 11:51:26] DEBUG[30698]: Function result is 'IAX2/hkzh3carrier-12799' [May 3 11:51:26] DEBUG[30698]: Function result is 'Dial' [May 3 11:51:26] DEBUG[30698]: Function result is 'IAX2/hkzh3carrier/86133068613309314868||tTor' [May 3 11:51:26] DEBUG[30698]: Function result is '2011-05-03 11:50:12' [May 3 11:51:26] DEBUG[30698]: Function result is '2011-05-03 11:50:30' [May 3 11:51:26] DEBUG[30698]: Function result is '2011-05-03 11:51:26' [May 3 11:51:26] DEBUG[30698]: Function result is '74' [May 3 11:51:26] DEBUG[30698]: Function result is '56' [May 3 11:51:26] DEBUG[30698]: Function result is 'ANSWERED' [May 3 11:51:26] DEBUG[30698]: Function result is 'DOCUMENTATION' [May 3 11:51:26] DEBUG[30698]: Function result is '(null)' [May 3 11:51:26] DEBUG[30698]: Function result is '1304394612.420' [May 3 11:51:26] DEBUG[30698]: Function result is '(null)' [May 3 11:51:26] DEBUG[2556]: Manager received command 'Command'

Posted: **Tue May 03, 2011 4:25 am**

It seem when the IAX connection has not fully build, but the AST_CRON_audio_1_move_mix.pl run the convert job at that time, it detect the file size not increase with 5 sec and then move the recording file out the monitor folder, and not record the least voice content. But I not know how to make the IAX2 building immediately, not wait callee accept the call, but change the AST_CRON_audio_1_move_mix.pl sleep time to a larger time.

Code: Select all: ### Loop through files first to gather filesizes $i=0; foreach(@FILES) { $FILEsize1[$i] = 0; if ( (length($FILES[$i]) > 4) && (!-d "$dir1/$FILES[$i]") ) { $FILEsize1[$i] = (-s "$dir1/$FILES[$i]"); if ($DBX) {print "$FILES[$i] $FILEsize1[$i]\n";} } $i++; } sleep(5); ### Loop through files a second time to gather filesizes again 5 seconds later $i=0; foreach(@FILES) {

If anybody give a suggestion about this?

Posted: **Tue May 03, 2011 2:42 pm**

it's not 5 minutes. it's 5 seconds.

Code: Select all: sleep(5);

Posted: **Tue May 03, 2011 7:45 pm**

williamconley wrote:it's not 5 minutes. it's 5 seconds.

Code: Select all
sleep(5);

Yes, sir, type error.

, I have changed it to sleep(20), but it can only reduce the error ratio but not avoid such problem. If any suggestion about this?

Posted: **Tue May 03, 2011 8:55 pm**

There is the seem problem with campaign call. And the problem will be live if the call is not dial out directly, but dial via a geteway like IAX, SIP trunk.

Code: Select all: Dialer==>Dialer Server ===>IAX2/SIP trunk===> Gateway===>zap/dahdi===>PSTN===>Dialee

For the dialer server will connect to the gateway, then it will start the recording, but in fact gateway will build the connction after Dialee answer the call. The conver script will detect the call log file whether increase with a time, default is 5 sec. It will cause a lot of call will be covert before the Dialee answer the call. After he answer the call , the call log file will not include the talking content.

Not know dundi any help with this. But it seem duhdi cannot support vicidial campaign model.

If any boss can look into it and give a suggestion. Many thanks.

Posted: **Tue May 03, 2011 11:28 pm**

try a delay recording of 5 seconds. then the file should not be created until after the call is answered, and it should continually change size after it is answered.

Posted: **Fri May 06, 2011 1:07 am**

williamconley wrote:try a delay recording of 5 seconds. then the file should not be created until after the call is answered, and it should continually change size after it is answered.

Yes, it's work in campaign, many thanks, williamconley. But how to set when dial directly? I use

Code: Select all: exten => _86ZXXXXXXX.,1,AGI(agi-NVA_recording.agi,BOTH------Y---N---Y) exten => _86ZXXXXXXX.,2,Dial(${HKZH3TRUNK}/${EXTEN},,tTor) exten => _86ZXXXXXXX.,3,Congestion exten => _86ZXXXXXXX.,4,Hangup

to record.

Posted: **Sat May 07, 2011 12:20 am**

Since you begin recording before the dial command that's tough. LOL

Try the "G" option of the dial command instead.

Posted: **Sun May 08, 2011 10:58 pm**

williamconley wrote:Since you begin recording before the dial command that's tough. LOL

Try the "G" option of the dial command instead.

Thanks very much, I can only get the info about "G" is

Code: Select all: G(context^exten^pri) Drops both channels into the specified context, extension and priority when the call is answered.

, but no any more info, I have no idea of this, I try

Code: Select all: exten => _931626582,1,Dial(${HKZH3TRUNK}/${EXTEN},30,G(default^8169^1)) exten => _931626582,2,Congestion exten => _931626582,3,Hangup exten => 8169,1,Answer exten => 8169,2,AGI(agi-NVA_recording.agi,BOTH------Y---N---Y) exten => 8169,3,Hangup

It seem a wrong way.
Could you give more guide of this or some link about the point of "G"?
Another, if anyway let recording after communication building? I not find any about this too, include vicidial manual.
Many thanks.

Posted: **Mon May 09, 2011 8:40 am**

You'll need to work this without the vicidial manual. This is pure asterisk baby. LOL

vicidial.org

Issue about agi-NVA_recording recording, size is zero

Issue about agi-NVA_recording recording, size is zero