[Home]

Summary:ASTERISK-13909: 1 in 3 incoming zap PRI calls do no hear audio (are not bridged) when call is answered with agi script
Reporter:David Brillert (aragon)Labels:
Date Opened:2009-04-07 08:12:56Date Closed:2009-10-21 10:05:00
Priority:MajorRegression?Yes
Status:Closed/CompleteComponents:Resources/res_agi
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:Incoming zap PRI call answers with DNIS and agi script
Some calls are answered properly with audio (bridged)
Sometimes caller hears no audio (not bridged)
Roughly 1 in 3 callers hears no audio.
No relation found to specific B channel

I'm opening as major because lots of calls are not being bridged.

Started with Asterisk 1.4.20 problem still in 1.4.24.1

zaptel-1.4.12
asterisk-1.4.24.1

The last line in the CLI keeps repeating until the caller hangs up

[Apr 6 19:35:18] NOTICE[26970]: utils.c:938 ast_carefulwrite: Timed out trying to write
[Apr 6 19:35:18] NOTICE[26970]: utils.c:938 ast_carefulwrite: Timed out trying to write

or

[Apr 6 22:37:10] DEBUG[20731]: chan_sip.c:2226 __sip_ack: Stopping retransmission on '7cd1530c5be721a24327004c5d520b3e@10.0.50.254' of Request 102: Match Found
[Apr 6 22:37:10] DEBUG[20731]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS

****** ADDITIONAL INFORMATION ******

Here is the CLI of a bad call with agi debug, verbose 3, debug enabled

[Apr 6 22:37:05] DEBUG[20754]: manager.c:2184 process_message: Manager received command 'Command'
[Apr 6 22:37:05] DEBUG[20754]: manager.c:2184 process_message: Manager received command 'Command'
[Apr 6 22:37:05] DEBUG[20754]: db.c:198 ast_db_get: Unable to find key '2835' in family 'agent/channel'
[Apr 6 22:37:05] DEBUG[20754]: manager.c:2184 process_message: Manager received command 'Command'
[Apr 6 22:37:05] DEBUG[20754]: db.c:198 ast_db_get: Unable to find key '2321' in family 'agent/channel'
[Apr 6 22:37:05] DEBUG[20731]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Apr 6 22:37:05] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.115 with 192.168.0.0
[Apr 6 22:37:05] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.115 with 10.0.0.0
[Apr 6 22:37:05] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.115 with 172.16.0.0
[Apr 6 22:37:05] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.115 with 169.254.0.0
[Apr 6 22:37:05] DEBUG[20731]: chan_sip.c:2226 __sip_ack: Stopping retransmission on '1aed46113a11522027712d7169efd663@10.0.50.254' of Request 102: Match Found
[Apr 6 22:37:05] DEBUG[20731]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Apr 6 22:37:05] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.102 with 192.168.0.0
[Apr 6 22:37:05] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.102 with 10.0.0.0
[Apr 6 22:37:05] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.102 with 172.16.0.0
[Apr 6 22:37:05] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.102 with 169.254.0.0
[Apr 6 22:37:05] DEBUG[20754]: manager.c:2184 process_message: Manager received command 'Command'
[Apr 6 22:37:05] DEBUG[20754]: db.c:198 ast_db_get: Unable to find key '3281' in family 'agent/channel'
[Apr 6 22:37:05] DEBUG[20731]: chan_sip.c:2226 __sip_ack: Stopping retransmission on '35ef63655ede050c3159818e2856207f@10.0.50.254' of Request 102: Match Found
[Apr 6 22:37:05] DEBUG[20754]: manager.c:2184 process_message: Manager received command 'Command'
[Apr 6 22:37:05] DEBUG[20754]: db.c:198 ast_db_get: Unable to find key '2451' in family 'agent/channel'
[Apr 6 22:37:06] DEBUG[20754]: manager.c:2184 process_message: Manager received command 'Command'
[Apr 6 22:37:06] DEBUG[20754]: db.c:198 ast_db_get: Unable to find key '2351' in family 'agent/channel'
[Apr 6 22:37:06] DEBUG[20731]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Apr 6 22:37:06] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.1.24 with 192.168.0.0
[Apr 6 22:37:06] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.1.24 with 10.0.0.0
[Apr 6 22:37:06] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.1.24 with 172.16.0.0
[Apr 6 22:37:06] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.1.24 with 169.254.0.0
 -- Accepting call from '5555551234' to '2247' on channel 0/6, span 2
[Apr 6 22:37:06] DEBUG[20725]: chan_dahdi.c:1780 dahdi_enable_ec: Enabled echo cancellation on channel 30
[Apr 6 22:37:06] DEBUG[13056]: pbx.c:1843 pbx_extension_helper: Launching 'Answer'
 -- Executing [2247@zap-incoming:1] Answer("Zap/30-1", "") in new stack
[Apr 6 22:37:06] DEBUG[13056]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/30
[Apr 6 22:37:06] DEBUG[20703]: channel.c:1103 channel_find_locked: Avoiding initial deadlock for channel '0x9028028'
[Apr 6 22:37:06] DEBUG[20703]: channel.c:1103 channel_find_locked: Avoiding initial deadlock for channel '0x9028028'
[Apr 6 22:37:06] DEBUG[20703]: channel.c:1103 channel_find_locked: Avoiding initial deadlock for channel '0x9028028'
[Apr 6 22:37:06] DEBUG[20703]: channel.c:1103 channel_find_locked: Avoiding initial deadlock for channel '0x9028028'
[Apr 6 22:37:06] DEBUG[20703]: channel.c:1103 channel_find_locked: Avoiding initial deadlock for channel '0x9028028'
[Apr 6 22:37:06] DEBUG[13056]: chan_dahdi.c:5462 dahdi_indicate: Requested indication -1 on channel Zap/30-1
[Apr 6 22:37:06] DEBUG[13056]: pbx.c:1843 pbx_extension_helper: Launching 'Set'
 -- Executing [2247@zap-incoming:2] Set("Zap/30-1", "CHANNEL(musicclass)=default") in new stack
[Apr 6 22:37:06] DEBUG[20703]: devicestate.c:287 do_state_change: Changing state for Zap/30 - state 2 (In use)
[Apr 6 22:37:06] DEBUG[20729]: app_queue.c:676 handle_statechange: Device 'Zap/30' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Apr 6 22:37:06] DEBUG[13056]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is '5555551234'
[Apr 6 22:37:06] DEBUG[13056]: pbx.c:1692 pbx_substitute_variables_helper_full: Function result is 'Some Caller'
[Apr 6 22:37:06] DEBUG[13056]: pbx.c:1843 pbx_extension_helper: Launching 'NoOp'
 -- Executing [2247@zap-incoming:3] NoOp("Zap/30-1", ""INCOMING CALL FROM CALLER ID: 5555551234 (Some Caller)"") in new stack
[Apr 6 22:37:06] DEBUG[13056]: pbx.c:1843 pbx_extension_helper: Launching 'Set'
 -- Executing [2247@zap-incoming:4] Set("Zap/30-1", "__INCOMING_DNIS=2247") in new stack
[Apr 6 22:37:06] DEBUG[13056]: pbx.c:1843 pbx_extension_helper: Launching 'Set'
 -- Executing [2247@zap-incoming:5] Set("Zap/30-1", "CALLERID(dnid)=2247") in new stack
[Apr 6 22:37:06] DEBUG[13056]: pbx.c:1843 pbx_extension_helper: Launching 'Set'
 -- Executing [2247@zap-incoming:6] Set("Zap/30-1", "CDR(userfield)=2247") in new stack
[Apr 6 22:37:06] DEBUG[13056]: pbx.c:1843 pbx_extension_helper: Launching 'Goto'
 -- Executing [2247@zap-incoming:7] Goto("Zap/30-1", "10") in new stack
 -- Goto (zap-incoming,2247,10)
[Apr 6 22:37:06] DEBUG[20754]: manager.c:2184 process_message: Manager received command 'Command'
[Apr 6 22:37:06] DEBUG[20754]: db.c:198 ast_db_get: Unable to find key '2331' in family 'agent/channel'
[Apr 6 22:37:06] DEBUG[13056]: pbx.c:1843 pbx_extension_helper: Launching 'AGI'
 -- Executing [2247@zap-incoming:10] AGI("Zap/30-1", "/var/www/scopserv/telephony/scripts/agi/fixcidname.php") in new stack
 -- Launched AGI Script /var/www/scopserv/telephony/scripts/agi/fixcidname.php
AGI Tx >> agi_request: /var/www/scopserv/telephony/scripts/agi/fixcidname.php
AGI Tx >> agi_channel: Zap/30-1
[Apr 6 22:37:06] DEBUG[20731]: chan_sip.c:2226 __sip_ack: Stopping retransmission on '368b99c9030444316c5894a527798f7e@10.0.50.254' of Request 102: Match Found
[Apr 6 22:37:06] NOTICE[13056]: utils.c:938 ast_carefulwrite: Timed out trying to write
AGI Tx >> agi_language: en
[Apr 6 22:37:06] DEBUG[20754]: manager.c:2184 process_message: Manager received command 'Command'
[Apr 6 22:37:06] DEBUG[20754]: db.c:198 ast_db_get: Unable to find key '3001' in family 'agent/channel'
[Apr 6 22:37:06] NOTICE[13056]: utils.c:938 ast_carefulwrite: Timed out trying to write
AGI Tx >> agi_type: Zap
[Apr 6 22:37:06] DEBUG[20731]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Apr 6 22:37:06] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.1.24 with 192.168.0.0
[Apr 6 22:37:06] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.1.24 with 10.0.0.0
[Apr 6 22:37:06] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.1.24 with 172.16.0.0
[Apr 6 22:37:06] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.1.24 with 169.254.0.0
[Apr 6 22:37:06] DEBUG[20754]: manager.c:2184 process_message: Manager received command 'Command'
[Apr 6 22:37:06] DEBUG[20754]: db.c:198 ast_db_get: Unable to find key '2231' in family 'agent/channel'
[Apr 6 22:37:06] DEBUG[20731]: chan_sip.c:2226 __sip_ack: Stopping retransmission on '07ea6f383ee8c8251cfa69203c40991a@10.0.50.254' of Request 102: Match Found
[Apr 6 22:37:06] NOTICE[13056]: utils.c:938 ast_carefulwrite: Timed out trying to write
AGI Tx >> agi_uniqueid: 1239071826.14
[Apr 6 22:37:06] DEBUG[20754]: manager.c:2184 process_message: Manager received command 'Command'
[Apr 6 22:37:06] DEBUG[20754]: db.c:198 ast_db_get: Unable to find key '2861' in family 'agent/channel'
[Apr 6 22:37:06] NOTICE[13056]: utils.c:938 ast_carefulwrite: Timed out trying to write
AGI Tx >> agi_callerid: 5555551234
[Apr 6 22:37:06] DEBUG[20754]: manager.c:2184 process_message: Manager received command 'Command'
[Apr 6 22:37:06] DEBUG[20754]: db.c:198 ast_db_get: Unable to find key '2711' in family 'agent/channel'
[Apr 6 22:37:06] DEBUG[20731]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Apr 6 22:37:06] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.194 with 192.168.0.0
[Apr 6 22:37:06] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.194 with 10.0.0.0
[Apr 6 22:37:06] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.194 with 172.16.0.0
[Apr 6 22:37:06] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.194 with 169.254.0.0
[Apr 6 22:37:06] NOTICE[13056]: utils.c:938 ast_carefulwrite: Timed out trying to write
AGI Tx >> agi_calleridname: Some Caller
[Apr 6 22:37:06] DEBUG[20731]: chan_sip.c:2226 __sip_ack: Stopping retransmission on '2f486b301caf023b0bdb720d25875426@10.0.50.254' of Request 102: Match Found
[Apr 6 22:37:06] DEBUG[20731]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Apr 6 22:37:06] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.129 with 192.168.0.0
[Apr 6 22:37:06] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.129 with 10.0.0.0
[Apr 6 22:37:06] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.129 with 172.16.0.0
[Apr 6 22:37:06] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.129 with 169.254.0.0
[Apr 6 22:37:06] DEBUG[20754]: manager.c:2184 process_message: Manager received command 'Command'
[Apr 6 22:37:06] DEBUG[20754]: db.c:198 ast_db_get: Unable to find key '2431' in family 'agent/channel'
[Apr 6 22:37:06] NOTICE[13056]: utils.c:938 ast_carefulwrite: Timed out trying to write
AGI Tx >> agi_callingpres: 0
[Apr 6 22:37:06] DEBUG[20731]: chan_sip.c:2226 __sip_ack: Stopping retransmission on '33aacb9b7d8e31c37612bf7b59e6e735@10.0.50.254' of Request 102: Match Found
[Apr 6 22:37:06] DEBUG[20731]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Apr 6 22:37:06] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.101 with 192.168.0.0
[Apr 6 22:37:06] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.101 with 10.0.0.0
[Apr 6 22:37:06] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.101 with 172.16.0.0
[Apr 6 22:37:06] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.101 with 169.254.0.0
[Apr 6 22:37:06] DEBUG[20754]: manager.c:2184 process_message: Manager received command 'Command'
[Apr 6 22:37:06] DEBUG[20754]: db.c:198 ast_db_get: Unable to find key '2401' in family 'agent/channel'
[Apr 6 22:37:06] NOTICE[13056]: utils.c:938 ast_carefulwrite: Timed out trying to write
AGI Tx >> agi_callingani2: 0
[Apr 6 22:37:06] DEBUG[20731]: chan_sip.c:2226 __sip_ack: Stopping retransmission on '249a48cb730221a7616f325c7376844a@10.0.50.254' of Request 102: Match Found
[Apr 6 22:37:06] DEBUG[20731]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Apr 6 22:37:06] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.136 with 192.168.0.0
[Apr 6 22:37:06] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.136 with 10.0.0.0
[Apr 6 22:37:06] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.136 with 172.16.0.0
[Apr 6 22:37:06] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.136 with 169.254.0.0
[Apr 6 22:37:07] DEBUG[20754]: manager.c:2184 process_message: Manager received command 'Command'
[Apr 6 22:37:07] DEBUG[20754]: db.c:198 ast_db_get: Unable to find key '2761' in family 'agent/channel'
[Apr 6 22:37:07] NOTICE[13056]: utils.c:938 ast_carefulwrite: Timed out trying to write
AGI Tx >> agi_callington: 33
[Apr 6 22:37:07] DEBUG[20731]: chan_sip.c:2226 __sip_ack: Stopping retransmission on '57de75297a7e277039d537ba01f41a51@10.0.50.254' of Request 102: Match Found
[Apr 6 22:37:07] DEBUG[20731]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Apr 6 22:37:07] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.150 with 192.168.0.0
[Apr 6 22:37:07] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.150 with 10.0.0.0
[Apr 6 22:37:07] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.150 with 172.16.0.0
[Apr 6 22:37:07] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.150 with 169.254.0.0
[Apr 6 22:37:07] NOTICE[13056]: utils.c:938 ast_carefulwrite: Timed out trying to write
AGI Tx >> agi_callingtns: 0
[Apr 6 22:37:07] DEBUG[20731]: chan_sip.c:2226 __sip_ack: Stopping retransmission on '736dae7e481b883361fcb7f2576141ce@10.0.50.254' of Request 102: Match Found
[Apr 6 22:37:07] DEBUG[20731]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Apr 6 22:37:07] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.149 with 192.168.0.0
[Apr 6 22:37:07] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.149 with 10.0.0.0
[Apr 6 22:37:07] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.149 with 172.16.0.0
[Apr 6 22:37:07] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.149 with 169.254.0.0
[Apr 6 22:37:07] NOTICE[13056]: utils.c:938 ast_carefulwrite: Timed out trying to write
AGI Tx >> agi_dnid: 2247
[Apr 6 22:37:07] DEBUG[20731]: chan_sip.c:2226 __sip_ack: Stopping retransmission on '0d0edb5a38214dc07fa33b781195cd9d@10.0.50.254' of Request 102: Match Found
[Apr 6 22:37:07] DEBUG[20731]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Apr 6 22:37:07] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.168 with 192.168.0.0
[Apr 6 22:37:07] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.168 with 10.0.0.0
[Apr 6 22:37:07] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.168 with 172.16.0.0
[Apr 6 22:37:07] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.168 with 169.254.0.0
[Apr 6 22:37:07] NOTICE[13056]: utils.c:938 ast_carefulwrite: Timed out trying to write
AGI Tx >> agi_rdnis: unknown
[Apr 6 22:37:07] DEBUG[20731]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Apr 6 22:37:07] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.135 with 192.168.0.0
[Apr 6 22:37:07] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.135 with 10.0.0.0
[Apr 6 22:37:07] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.135 with 172.16.0.0
[Apr 6 22:37:07] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.135 with 169.254.0.0
[Apr 6 22:37:07] DEBUG[20731]: chan_sip.c:2226 __sip_ack: Stopping retransmission on '508efb8b1e167ea95226b8b84b192375@10.0.50.254' of Request 102: Match Found
[Apr 6 22:37:07] DEBUG[20731]: chan_sip.c:2226 __sip_ack: Stopping retransmission on '74e40f04697770e54cba61645d431bad@10.0.50.254' of Request 102: Match Found
[Apr 6 22:37:07] NOTICE[13056]: utils.c:938 ast_carefulwrite: Timed out trying to write
AGI Tx >> agi_context: zap-incoming
[Apr 6 22:37:07] DEBUG[20731]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Apr 6 22:37:07] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.161 with 192.168.0.0
[Apr 6 22:37:07] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.161 with 10.0.0.0
[Apr 6 22:37:07] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.161 with 172.16.0.0
[Apr 6 22:37:07] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.161 with 169.254.0.0
[Apr 6 22:37:07] NOTICE[13056]: utils.c:938 ast_carefulwrite: Timed out trying to write
AGI Tx >> agi_extension: 2247
[Apr 6 22:37:07] DEBUG[20731]: chan_sip.c:2226 __sip_ack: Stopping retransmission on '2f0b93bf1caea11f16ba12655c52ee21@10.0.50.254' of Request 102: Match Found
[Apr 6 22:37:07] DEBUG[20731]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Apr 6 22:37:07] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.120 with 192.168.0.0
[Apr 6 22:37:07] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.120 with 10.0.0.0
[Apr 6 22:37:07] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.120 with 172.16.0.0
[Apr 6 22:37:07] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.120 with 169.254.0.0
[Apr 6 22:37:07] DEBUG[20773]: manager.c:2184 process_message: Manager received command 'Command'
[Apr 6 22:37:07] DEBUG[20773]: manager.c:2184 process_message: Manager received command 'Command'
[Apr 6 22:37:07] NOTICE[13056]: utils.c:938 ast_carefulwrite: Timed out trying to write
AGI Tx >> agi_priority: 10
[Apr 6 22:37:07] DEBUG[20773]: manager.c:2184 process_message: Manager received command 'Command'
[Apr 6 22:37:07] DEBUG[20731]: chan_sip.c:2226 __sip_ack: Stopping retransmission on '20e23d4129a8b645386dbc18515cbf74@10.0.50.254' of Request 102: Match Found
[Apr 6 22:37:07] DEBUG[20731]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Apr 6 22:37:07] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.144 with 192.168.0.0
[Apr 6 22:37:07] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.144 with 10.0.0.0
[Apr 6 22:37:07] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.144 with 172.16.0.0
[Apr 6 22:37:07] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.144 with 169.254.0.0
[Apr 6 22:37:07] NOTICE[13056]: utils.c:938 ast_carefulwrite: Timed out trying to write
AGI Tx >> agi_enhanced: 0.0
[Apr 6 22:37:07] DEBUG[20731]: chan_sip.c:2226 __sip_ack: Stopping retransmission on '74768bc87359003435060fb92271bbb8@10.0.50.254' of Request 102: Match Found
[Apr 6 22:37:07] DEBUG[20731]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Apr 6 22:37:07] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.139 with 192.168.0.0
[Apr 6 22:37:07] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.139 with 10.0.0.0
[Apr 6 22:37:07] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.139 with 172.16.0.0
[Apr 6 22:37:07] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.139 with 169.254.0.0
[Apr 6 22:37:07] NOTICE[13056]: utils.c:938 ast_carefulwrite: Timed out trying to write
AGI Tx >> agi_accountcode: _NONE_
[Apr 6 22:37:07] DEBUG[20731]: chan_sip.c:2226 __sip_ack: Stopping retransmission on '5f68bc005348cccf2b2bf2ff6dde4f14@10.0.50.254' of Request 102: Match Found
[Apr 6 22:37:07] DEBUG[20731]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Apr 6 22:37:07] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.186 with 192.168.0.0
[Apr 6 22:37:07] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.186 with 10.0.0.0
[Apr 6 22:37:07] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.186 with 172.16.0.0
[Apr 6 22:37:07] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.186 with 169.254.0.0
[Apr 6 22:37:07] DEBUG[20731]: chan_sip.c:2226 __sip_ack: Stopping retransmission on '19a97d3a5af593326be16ebb2a638aba@10.0.50.254' of Request 102: Match Found
[Apr 6 22:37:07] NOTICE[13056]: utils.c:938 ast_carefulwrite: Timed out trying to write
AGI Tx >>
[Apr 6 22:37:07] DEBUG[20731]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Apr 6 22:37:07] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.145 with 192.168.0.0
[Apr 6 22:37:07] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.145 with 10.0.0.0
[Apr 6 22:37:07] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.145 with 172.16.0.0
[Apr 6 22:37:07] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.145 with 169.254.0.0
[Apr 6 22:37:08] NOTICE[13056]: utils.c:938 ast_carefulwrite: Timed out trying to write
[Apr 6 22:37:08] DEBUG[20731]: chan_sip.c:2226 __sip_ack: Stopping retransmission on '0db1b95b292f81cd1dd53d1525b43d53@10.0.50.254' of Request 102: Match Found
[Apr 6 22:37:08] DEBUG[20731]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Apr 6 22:37:08] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.157 with 192.168.0.0
[Apr 6 22:37:08] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.157 with 10.0.0.0
[Apr 6 22:37:08] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.157 with 172.16.0.0
[Apr 6 22:37:08] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.157 with 169.254.0.0
[Apr 6 22:37:08] DEBUG[20731]: chan_sip.c:2226 __sip_ack: Stopping retransmission on '23e38d5e6997e6294e9d0d0231d106f6@10.0.50.254' of Request 102: Match Found
[Apr 6 22:37:08] DEBUG[20731]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Apr 6 22:37:08] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.193 with 192.168.0.0
[Apr 6 22:37:08] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.193 with 10.0.0.0
[Apr 6 22:37:08] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.193 with 172.16.0.0
[Apr 6 22:37:08] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.193 with 169.254.0.0
[Apr 6 22:37:08] DEBUG[20731]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Apr 6 22:37:08] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.154 with 192.168.0.0
[Apr 6 22:37:08] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.154 with 10.0.0.0
[Apr 6 22:37:08] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.154 with 172.16.0.0
[Apr 6 22:37:08] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.154 with 169.254.0.0
[Apr 6 22:37:08] DEBUG[20731]: chan_sip.c:2226 __sip_ack: Stopping retransmission on '078496947eed026852ecb4660687f0bd@10.0.50.254' of Request 102: Match Found
[Apr 6 22:37:08] DEBUG[20731]: chan_sip.c:2226 __sip_ack: Stopping retransmission on '1089895a1ffbe6d3245955455c8a9cd7@10.0.50.254' of Request 102: Match Found
[Apr 6 22:37:08] DEBUG[20731]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Apr 6 22:37:08] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.159 with 192.168.0.0
[Apr 6 22:37:08] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.159 with 10.0.0.0
[Apr 6 22:37:08] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.159 with 172.16.0.0
[Apr 6 22:37:08] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.159 with 169.254.0.0
[Apr 6 22:37:08] DEBUG[20731]: chan_sip.c:2226 __sip_ack: Stopping retransmission on '6356f804246a0f0467fa59214ab6d895@10.0.50.254' of Request 102: Match Found
[Apr 6 22:37:08] DEBUG[20731]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Apr 6 22:37:08] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.115 with 192.168.0.0
[Apr 6 22:37:08] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.115 with 10.0.0.0
[Apr 6 22:37:08] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.115 with 172.16.0.0
[Apr 6 22:37:08] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.115 with 169.254.0.0
[Apr 6 22:37:08] DEBUG[20731]: chan_sip.c:2226 __sip_ack: Stopping retransmission on '0cac26862ac11c34703248735a8ddd05@10.0.50.254' of Request 102: Match Found
[Apr 6 22:37:08] DEBUG[20731]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Apr 6 22:37:08] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.155 with 192.168.0.0
[Apr 6 22:37:08] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.155 with 10.0.0.0
[Apr 6 22:37:08] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.155 with 172.16.0.0
[Apr 6 22:37:08] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.155 with 169.254.0.0
[Apr 6 22:37:08] DEBUG[20731]: chan_sip.c:2226 __sip_ack: Stopping retransmission on '68b0f45250eea44c20500fb849d7583c@10.0.50.254' of Request 102: Match Found
[Apr 6 22:37:08] DEBUG[20731]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Apr 6 22:37:08] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.103 with 192.168.0.0
[Apr 6 22:37:08] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.103 with 10.0.0.0
[Apr 6 22:37:08] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.103 with 172.16.0.0
[Apr 6 22:37:08] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.103 with 169.254.0.0
[Apr 6 22:37:08] DEBUG[20731]: chan_sip.c:2226 __sip_ack: Stopping retransmission on '496c4f840df9a5173d21be715162c302@10.0.50.254' of Request 102: Match Found
[Apr 6 22:37:08] DEBUG[20731]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Apr 6 22:37:08] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.102 with 192.168.0.0
[Apr 6 22:37:08] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.102 with 10.0.0.0
[Apr 6 22:37:08] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.102 with 172.16.0.0
[Apr 6 22:37:08] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.102 with 169.254.0.0
[Apr 6 22:37:09] DEBUG[20731]: chan_sip.c:2226 __sip_ack: Stopping retransmission on '6c6b7f8c7282cba16b97218a1fc4097c@10.0.50.254' of Request 102: Match Found
[Apr 6 22:37:09] DEBUG[20731]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Apr 6 22:37:09] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.134 with 192.168.0.0
[Apr 6 22:37:09] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.134 with 10.0.0.0
[Apr 6 22:37:09] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.134 with 172.16.0.0
[Apr 6 22:37:09] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.134 with 169.254.0.0
[Apr 6 22:37:09] DEBUG[20731]: chan_sip.c:2226 __sip_ack: Stopping retransmission on '0f51e6f274dc0d9a7074996d3a3cd82b@10.0.50.254' of Request 102: Match Found
[Apr 6 22:37:09] DEBUG[20731]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Apr 6 22:37:09] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.175 with 192.168.0.0
[Apr 6 22:37:09] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.175 with 10.0.0.0
[Apr 6 22:37:09] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.175 with 172.16.0.0
[Apr 6 22:37:09] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.175 with 169.254.0.0
[Apr 6 22:37:09] DEBUG[20731]: chan_sip.c:2226 __sip_ack: Stopping retransmission on '431386101b8e857e525ca75005946a2f@10.0.50.254' of Request 102: Match Found
[Apr 6 22:37:09] DEBUG[20731]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Apr 6 22:37:09] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.169 with 192.168.0.0
[Apr 6 22:37:09] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.169 with 10.0.0.0
[Apr 6 22:37:09] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.169 with 172.16.0.0
[Apr 6 22:37:09] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.169 with 169.254.0.0
[Apr 6 22:37:09] DEBUG[20731]: chan_sip.c:2226 __sip_ack: Stopping retransmission on '7dab51c05d91eb2637b54ff0758cf104@10.0.50.254' of Request 102: Match Found
[Apr 6 22:37:09] DEBUG[20731]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Apr 6 22:37:09] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.108 with 192.168.0.0
[Apr 6 22:37:09] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.108 with 10.0.0.0
[Apr 6 22:37:09] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.108 with 172.16.0.0
[Apr 6 22:37:09] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.108 with 169.254.0.0
[Apr 6 22:37:09] DEBUG[20731]: chan_sip.c:2226 __sip_ack: Stopping retransmission on '6bb6595f1aaa09955dc5a58451b7ce4b@10.0.50.254' of Request 102: Match Found
[Apr 6 22:37:09] DEBUG[20731]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Apr 6 22:37:09] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.140 with 192.168.0.0
[Apr 6 22:37:09] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.140 with 10.0.0.0
[Apr 6 22:37:09] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.140 with 172.16.0.0
[Apr 6 22:37:09] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.140 with 169.254.0.0
[Apr 6 22:37:09] DEBUG[20731]: chan_sip.c:2226 __sip_ack: Stopping retransmission on '3324e5dc37b6d05f105a1fa466b789f1@10.0.50.254' of Request 102: Match Found
[Apr 6 22:37:09] DEBUG[20731]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Apr 6 22:37:09] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.165 with 192.168.0.0
[Apr 6 22:37:09] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.165 with 10.0.0.0
[Apr 6 22:37:09] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.165 with 172.16.0.0
[Apr 6 22:37:09] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.165 with 169.254.0.0
[Apr 6 22:37:09] DEBUG[20731]: chan_sip.c:2226 __sip_ack: Stopping retransmission on '6a6a82cb5b70be34122fb75202006e59@10.0.50.254' of Request 102: Match Found
[Apr 6 22:37:09] DEBUG[20731]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Apr 6 22:37:09] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.178 with 192.168.0.0
[Apr 6 22:37:09] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.178 with 10.0.0.0
[Apr 6 22:37:09] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.178 with 172.16.0.0
[Apr 6 22:37:09] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.178 with 169.254.0.0
[Apr 6 22:37:09] DEBUG[20731]: chan_sip.c:2226 __sip_ack: Stopping retransmission on '3e6fa61c1047ab69592399d86c4c3e39@10.0.50.254' of Request 102: Match Found
[Apr 6 22:37:09] DEBUG[20731]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Apr 6 22:37:09] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.184 with 192.168.0.0
[Apr 6 22:37:09] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.184 with 10.0.0.0
[Apr 6 22:37:09] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.184 with 172.16.0.0
[Apr 6 22:37:09] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.184 with 169.254.0.0
[Apr 6 22:37:09] DEBUG[20731]: chan_sip.c:2226 __sip_ack: Stopping retransmission on '2037efc1279476944a6297466397e508@10.0.50.254' of Request 102: Match Found
[Apr 6 22:37:09] DEBUG[20731]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Apr 6 22:37:09] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.160 with 192.168.0.0
[Apr 6 22:37:09] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.160 with 10.0.0.0
[Apr 6 22:37:09] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.160 with 172.16.0.0
[Apr 6 22:37:09] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.160 with 169.254.0.0
[Apr 6 22:37:09] DEBUG[20731]: chan_sip.c:2226 __sip_ack: Stopping retransmission on '45c7fd88299b2d4e096655310e58f6fe@10.0.50.254' of Request 102: Match Found
[Apr 6 22:37:09] DEBUG[20731]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Apr 6 22:37:09] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.126 with 192.168.0.0
[Apr 6 22:37:09] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.126 with 10.0.0.0
[Apr 6 22:37:09] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.126 with 172.16.0.0
[Apr 6 22:37:09] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.126 with 169.254.0.0
[Apr 6 22:37:10] DEBUG[20731]: chan_sip.c:2226 __sip_ack: Stopping retransmission on '6034663c6d6efc8c5a0fe83f0faf0f7e@10.0.50.254' of Request 102: Match Found
[Apr 6 22:37:10] DEBUG[20731]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Apr 6 22:37:10] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.190 with 192.168.0.0
[Apr 6 22:37:10] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.190 with 10.0.0.0
[Apr 6 22:37:10] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.190 with 172.16.0.0
[Apr 6 22:37:10] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.190 with 169.254.0.0
[Apr 6 22:37:10] DEBUG[20731]: chan_sip.c:2226 __sip_ack: Stopping retransmission on '5be025af4f1cf10d5663946c70a11233@10.0.50.254' of Request 102: Match Found
[Apr 6 22:37:10] DEBUG[20731]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Apr 6 22:37:10] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.141 with 192.168.0.0
[Apr 6 22:37:10] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.141 with 10.0.0.0
[Apr 6 22:37:10] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.141 with 172.16.0.0
[Apr 6 22:37:10] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.141 with 169.254.0.0
[Apr 6 22:37:10] DEBUG[20731]: chan_sip.c:2226 __sip_ack: Stopping retransmission on '610fe2a940f8d5ab0f53d6b06c1ccc8b@10.0.50.254' of Request 102: Match Found
[Apr 6 22:37:10] DEBUG[20731]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Apr 6 22:37:10] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.158 with 192.168.0.0
[Apr 6 22:37:10] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.158 with 10.0.0.0
[Apr 6 22:37:10] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.158 with 172.16.0.0
[Apr 6 22:37:10] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.158 with 169.254.0.0
[Apr 6 22:37:10] DEBUG[20731]: chan_sip.c:2226 __sip_ack: Stopping retransmission on '46a75f773b94eb011c7abbe00dc2e11a@10.0.50.254' of Request 102: Match Found
[Apr 6 22:37:10] DEBUG[20731]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Apr 6 22:37:10] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.188 with 192.168.0.0
[Apr 6 22:37:10] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.188 with 10.0.0.0
[Apr 6 22:37:10] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.188 with 172.16.0.0
[Apr 6 22:37:10] DEBUG[20731]: acl.c:378 ast_apply_ha: ##### Testing 10.0.50.188 with 169.254.0.0
[Apr 6 22:37:10] DEBUG[20731]: chan_sip.c:2226 __sip_ack: Stopping retransmission on '7cd1530c5be721a24327004c5d520b3e@10.0.50.254' of Request 102: Match Found
[Apr 6 22:37:10] DEBUG[20731]: chan_sip.c:4653 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS
Comments:By: Joel Vandal (jvandal) 2009-04-07 09:34:24

Not fully sure, but maybe related to r165796 ? I have same problems on multiple server causing issues with AGI scripts (ex. cannot get result of a GET VARIABLE XYZ)

-------------------------------------------------------------------------
r165796 | russell | 2008-12-18 16:39:25 -0500 (Thu, 18 Dec 2008) | 11 lines

Make ast_carefulwrite() be more careful.

This patch handles some additional cases that could result in partial writes
to the file description.  This was done to address complaints about partial
writes on AMI.

(issue ASTERISK-12767) (more changes needed to address potential problems in 1.6)
Reported by: srt
Tested by: russell
Review: http://reviewboard.digium.com/r/99/
By: David Brillert (aragon) 2009-04-07 09:39:51

I had to downgrade the customer to 1.4.21 to remove the errors and restore some normal service.
I have to get them to 1.4.24 to get parking and transfers working properly, and to use official state_interface backport

Heeeellllpppp!!


By: David Brillert (aragon) 2009-04-07 09:58:30

At least downgrading to 1.4.21 proves that this is an issue with Asterisk and not agi script...

I think jvandal maybe correct in his analysis of root cause.
The workaround to increase the writetimeout I think means the caller is never bridged...

0013546: Partial writes on Manager API
Description Sometimes writing manager events with ast_carefulwrite in manager.c only results in a partial write i.e. not all data is written to the socket. There is no check for this and no code to send the missing data. As a workaround increasing the writetimeout in manager.conf mitigates this issue.
See http://jira.reucon.org/browse/AJ-174?focusedCommentId=10522#action_10522 [^] for details.
By: David Brillert (aragon) 2009-04-07 10:17:36

The call center is closed after 5PM EST
I can test patches after business hours and I am very anxious to get this problem fixed; now if only someone could diagnose problem (with my debug info) and provide patch...

I have no knowledge of C or programming skills
By: David Brillert (aragon) 2009-04-07 13:00:28

Also I should mention that the incoming calls are configured to reach an IVR menu and not another technology.
Sometimes I hear the IVR announcment but too often I hear dead silence.

Most calls experience some random delay before hearing the IVR menu prompt...
Once incoming test call remained dead silent for 5 minutes (until I got bored and hung up)!

asterisk 1.4.24.1


By: Joel Vandal (jvandal) 2009-04-07 13:58:04

If this can help, I'm trying to do some analysis...

The error occur when the AGI do a: 'AGI Tx >> ... ', if I look on res/res_agi.c, it call the ast_carefulwrite function, maybe the timeout of 100ms is too short ?

if (agidebug)
       ast_verbose("AGI Tx >> %s", stuff); /* \n provided by caller */
res = ast_carefulwrite(fd, stuff, strlen(stuff), 100);
By: Joel Vandal (jvandal) 2009-04-08 10:30:51

On res/res_agi.c, If I change 100 to 500ms by example, the problem look fixed and AGI work as expected :

From:
res = ast_carefulwrite(fd, stuff, strlen(stuff), 100);

To:
res = ast_carefulwrite(fd, stuff, strlen(stuff), 500);

To be honest, I'm not sure if this is the good approach but look to fix the problem. I highly appreciate if an admin can tell us if we are looking on the 'good' direction ?
By: David Brillert (aragon) 2009-04-08 18:41:09

Tried the change jvandal suggested

From:
res = ast_carefulwrite(fd, stuff, strlen(stuff), 100);

To:
res = ast_carefulwrite(fd, stuff, strlen(stuff), 500);

No noticeable improvement, still getting no RTP

[Apr  8 19:40:05] NOTICE[17000]: utils.c:938 ast_carefulwrite: Timed out trying to write
[Apr  8 19:40:06] NOTICE[17000]: utils.c:938 ast_carefulwrite: Timed out trying to write
[Apr  8 19:40:06] NOTICE[17000]: utils.c:938 ast_carefulwrite: Timed out trying to write
[Apr  8 19:40:07] NOTICE[17000]: utils.c:938 ast_carefulwrite: Timed out trying to write
[Apr  8 19:40:07] NOTICE[17000]: utils.c:938 ast_carefulwrite: Timed out trying to write
[Apr  8 19:40:08] NOTICE[17000]: utils.c:938 ast_carefulwrite: Timed out trying to write
[Apr  8 19:40:08] NOTICE[17000]: utils.c:938 ast_carefulwrite: Timed out trying to write
[Apr  8 19:40:09] NOTICE[17000]: utils.c:938 ast_carefulwrite: Timed out trying to write
[Apr  8 19:40:09] NOTICE[17000]: utils.c:938 ast_carefulwrite: Timed out trying to write
[Apr  8 19:40:10] NOTICE[17000]: utils.c:938 ast_carefulwrite: Timed out trying to write
[Apr  8 19:40:10] NOTICE[17000]: utils.c:938 ast_carefulwrite: Timed out trying to write
[Apr  8 19:40:11] NOTICE[17000]: utils.c:938 ast_carefulwrite: Timed out trying to write
[Apr  8 19:40:11] NOTICE[17000]: utils.c:938 ast_carefulwrite: Timed out trying to write
[Apr  8 19:40:12] NOTICE[17000]: utils.c:938 ast_carefulwrite: Timed out trying to write
By: Joel Vandal (jvandal) 2009-04-08 23:40:56

ok, I have made some test with aragon, change 100ms to 500ms doesn't help.

We have revert r165796 on 1.4.24.1 in order to have working AGI, all work as expected on multiple server now.
By: D KULL (kulldominique) 2009-04-22 11:43:18

I can confirm this bug, but it only seems to appear on VIA ITX platforms. Not sure if this is hardware related though.

AGI Tx >> agi_channel: SIP/5006-08852460
[Apr 22 12:35:21] NOTICE[29774]: utils.c:938 ast_carefulwrite: Timed out trying to write
AGI Tx >> agi_language: en
AGI Tx >> agi_type: SIP
AGI Tx >> agi_uniqueid: 1240418121.240
AGI Tx >> agi_callerid: 5006
AGI Tx >> agi_calleridname: Marc Rich
AGI Tx >> agi_callingpres: 0
AGI Tx >> agi_callingani2: 0
AGI Tx >> agi_callington: 0
AGI Tx >> agi_callingtns: 0
AGI Tx >> agi_dnid: *12
AGI Tx >> agi_rdnis: unknown
AGI Tx >> agi_context: inside
AGI Tx >> agi_extension: *12
AGI Tx >> agi_priority: 1
AGI Tx >> agi_enhanced: 0.0
AGI Tx >> agi_accountcode: 5006@default

this AGI code worked fine on 1.4.21
By: David Brillert (aragon) 2009-04-22 12:08:36

Thanks for confirming but this is not hardware related.
My chipset is Intel
It is a software regression
We have revert r165796 on 1.4.24.1 in order to have working AGI, all work as expected on multiple server now.
By: David Brillert (aragon) 2009-04-27 12:13:04

I think this issue is related to http://bugs.digium.com/view.php?id=14723
Except that reverting r165796 fixed this site and I have not tested patch from 14723
By: David Brillert (aragon) 2009-04-27 12:30:45

I revisited the logs from the site that was fixed by reverting r165796 and I am still seeing errors related to bug report 14723

[Apr 27 10:50:35] NOTICE[8690] chan_local.c: No such extension/context @customer-local while calling Local channel
[Apr 27 10:51:18] WARNING[16768] app_queue.c: Unable to join queue 'queuename'
[Apr 27 10:51:35] ERROR[22930] channel.c: ast_read() called with no recorded file descriptor.
[Apr 27 10:51:43] WARNING[12959] file.c: Failed to write frame

This means that the IVR problem was fixed by reverting r165796 but queues are still missing calls


By: David Brillert (aragon) 2009-07-29 15:42:57

Reverting 165796 fixed part of the issue as stated but queues are no longer missing calls with asterisk 1.4.24.1

I am tempted to test 1.4.26 with 165796 re-instated to see if the problem was fixed in 1.4.26 but I won't be able to do this for several weeks.

Edit: I originally stated this problem still existed in 1.4.24.1 however now this is not the case.  I just witnessed the same error message in the CLI in real time and I was able to see that no agent was logged to queue.
Therefore reverting 165796 DID fix the problem and I should re-test with 1.4.26 and with 165796 re-instated.


By: David Brillert (aragon) 2009-08-12 14:54:07

I no longer see error using revision 211806
[Apr 6 19:35:18] NOTICE[26970]: utils.c:938 ast_carefulwrite: Timed out trying to write

I can no longer reproduce using SVN therefore this ticket can be closed
By: David Brillert (aragon) 2009-09-02 12:59:46

Please close ticket
By: Leif Madsen (lmadsen) 2009-09-08 14:17:10

Closed per the reporter as this appears to be resolved in later revisions. Thanks for reporting back!