Inbound issues with multiple servers

[brown078]

Hello all,
We are transitioning servers to a multi server setup in an office that handles inbound calls.

We have three servers all with synchronized time.

ASTERISK VERSION: Asterisk 1.2.31.1
VICIDIAL VERSION: 2.0.5

When we receive an inbound call to a server, it seems to run "allInbound.agi" multiple (6) times. The first call goes through and multiple "LIVE" calls from the same inbound number are queued up, causing the entire call to hang up.

CLI OUT:
== Parsing '/etc/asterisk/manager.conf': Found
== Manager 'sendcron' logged on from 127.0.0.1
== Parsing '/etc/asterisk/manager.conf': Found
== Manager 'sendcron' logged on from 127.0.0.1
== Manager 'sendcron' logged off from 127.0.0.1
== Manager 'sendcron' logged off from 127.0.0.1
-- Executing Ringing("SIP/5060-b7039b78", "") in new stack
-- Executing Wait("SIP/5060-b7039b78", "4") in new stack
-- Executing AGI("SIP/5060-b7034638", "agi-VDAD_ALL_inbound.agi|CID-----LB-----LOANMODIN-----8888972733-----Closer-----park----------999-----1") in new stack
-- Launched AGI Script /var/lib/asterisk/agi-bin/agi-VDAD_ALL_inbound.agi
-- Executing Ringing("SIP/5060-b7049270", "") in new stack
-- Executing Wait("SIP/5060-b7049270", "4") in new stack
== Parsing '/etc/asterisk/manager.conf': Found
== Manager 'sendcron' logged on from 127.0.0.1
== Manager 'sendcron' logged off from 127.0.0.1
-- Executing AGI("SIP/5060-b7039b78", "agi-VDAD_ALL_inbound.agi|CID-----LB-----LOANMODIN-----8888972733-----Closer-----park----------999-----1") in new stack
-- Launched AGI Script /var/lib/asterisk/agi-bin/agi-VDAD_ALL_inbound.agi
-- Started music on hold, class 'default', on SIP/5060-b702f0f8
May 4 16:31:09 WARNING[25763]: file.c:517 ast_openstream_full: File /var/lib/asterisk/mohmp3/fpm-world-mix does not exist in any format
May 4 16:31:09 WARNING[25763]: res_musiconhold.c:232 ast_moh_files_next: Unable to open file '/var/lib/asterisk/mohmp3/fpm-world-mix': No such file or directory
-- Stopped music on hold on SIP/5060-b702f0f8
-- Executing Ringing("SIP/5060-b704e7b0", "") in new stack
-- Executing Wait("SIP/5060-b704e7b0", "4") in new stack
-- Executing AGI("SIP/5060-b7049270", "agi-VDAD_ALL_inbound.agi|CID-----LB-----LOANMODIN-----8888972733-----Closer-----park----------999-----1") in new stack
-- Launched AGI Script /var/lib/asterisk/agi-bin/agi-VDAD_ALL_inbound.agi
-- Started music on hold, class 'default', on SIP/5060-b7018160
May 4 16:31:12 WARNING[25325]: file.c:517 ast_openstream_full: File /var/lib/asterisk/mohmp3/LICENSE does not exist in any format
May 4 16:31:12 WARNING[25325]: res_musiconhold.c:232 ast_moh_files_next: Unable to open file '/var/lib/asterisk/mohmp3/LICENSE': No such file or directory
-- Stopped music on hold on SIP/5060-b7018160
-- Started music on hold, class 'default', on SIP/5060-b7034638
May 4 16:31:13 WARNING[25768]: file.c:517 ast_openstream_full: File /var/lib/asterisk/mohmp3/fpm-world-mix does not exist in any format
May 4 16:31:13 WARNING[25768]: res_musiconhold.c:232 ast_moh_files_next: Unable to open file '/var/lib/asterisk/mohmp3/fpm-world-mix': No such file or directory
-- Stopped music on hold on SIP/5060-b7034638
-- Executing Ringing("SIP/5060-b703f0b8", "") in new stack
-- Executing Wait("SIP/5060-b703f0b8", "4") in new stack
-- Executing AGI("SIP/5060-b704e7b0", "agi-VDAD_ALL_inbound.agi|CID-----LB-----LOANMODIN-----8888972733-----Closer-----park----------999-----1") in new stack
-- Launched AGI Script /var/lib/asterisk/agi-bin/agi-VDAD_ALL_inbound.agi
-- Started music on hold, class 'default', on SIP/5060-b7003ae0
May 4 16:31:15 WARNING[25330]: file.c:517 ast_openstream_full: File /var/lib/asterisk/mohmp3/LICENSE does not exist in any format
May 4 16:31:15 WARNING[25330]: res_musiconhold.c:232 ast_moh_files_next: Unable to open file '/var/lib/asterisk/mohmp3/LICENSE': No such file or directory
-- Stopped music on hold on SIP/5060-b7003ae0
-- Started music on hold, class 'default', on SIP/5060-b7039b78
May 4 16:31:16 WARNING[25797]: file.c:517 ast_openstream_full: File /var/lib/asterisk/mohmp3/fpm-world-mix does not exist in any format
May 4 16:31:16 WARNING[25797]: res_musiconhold.c:232 ast_moh_files_next: Unable to open file '/var/lib/asterisk/mohmp3/fpm-world-mix': No such file or directory
-- Stopped music on hold on SIP/5060-b7039b78
-- Executing AGI("SIP/5060-b703f0b8", "agi-VDAD_ALL_inbound.agi|CID-----LB-----LOANMODIN-----8888972733-----Closer-----park----------999-----1") in new stack
-- Launched AGI Script /var/lib/asterisk/agi-bin/agi-VDAD_ALL_inbound.agi
-- Started music on hold, class 'default', on SIP/5060-b7013aa8

CORRESPONDING FastAGI log info:
2009-05-04 17:12:19|VDfastAGI|call_log|VD hangup: no VDAC record found: 1241482309.93 9166018190
2009-05-04 17:12:19|VDfastAGI|begin|+++++++++++++++++ FastAGI Start ++++++++++++++++++++++++++++++++++++++++
2009-05-04 17:12:19|VDfastAGI|begin|Perl Environment Dump:
2009-05-04 17:12:19|VDfastAGI|begin|0|--debug
2009-05-04 17:12:19|VDfastAGI|begin|URL HVcauses: |PRI|NODEBUG|16|NOANSWER|||
2009-05-04 17:12:19|VDfastAGI|begin|AGI Environment Dump:
2009-05-04 17:12:19|VDfastAGI|begin| -- accountcode =
2009-05-04 17:12:19|VDfastAGI|begin| -- callerid = 9166018190
2009-05-04 17:12:19|VDfastAGI|begin| -- calleridname = Brown Daman
2009-05-04 17:12:19|VDfastAGI|begin| -- callingani2 = 0
2009-05-04 17:12:19|VDfastAGI|begin| -- callingpres = 0
2009-05-04 17:12:19|VDfastAGI|begin| -- callingtns = 0
2009-05-04 17:12:19|VDfastAGI|begin| -- callington = 0
2009-05-04 17:12:19|VDfastAGI|begin| -- channel = SIP/5060-09cec7d0
2009-05-04 17:12:19|VDfastAGI|begin| -- context = default
2009-05-04 17:12:19|VDfastAGI|begin| -- dnid = 8888972733
2009-05-04 17:12:19|VDfastAGI|begin| -- enhanced = 0.0
2009-05-04 17:12:19|VDfastAGI|begin| -- extension = h
2009-05-04 17:12:19|VDfastAGI|begin| -- language = en
2009-05-04 17:12:19|VDfastAGI|begin| -- network = yes
2009-05-04 17:12:19|VDfastAGI|begin| -- network_script = call_log--HVcauses--PRI-----NODEBUG-----16-----NOANSWER----------
2009-05-04 17:12:19|VDfastAGI|begin| -- priority = 1
2009-05-04 17:12:19|VDfastAGI|begin| -- rdnis = unknown
2009-05-04 17:12:19|VDfastAGI|begin| -- request = agi://127.0.0.1:4577/call_log--HVcauses ... ----------
2009-05-04 17:12:19|VDfastAGI|begin| -- type = SIP
2009-05-04 17:12:19|VDfastAGI|begin| -- uniqueid = 1241482315.96
2009-05-04 17:12:19|VDfastAGI|begin|AGI Variables: |1241482315.96|SIP/5060-09cec7d0|h|SIP|9166018190|
2009-05-04 17:12:19|VDfastAGI|call_log|Process to run: |agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----NOANSWER----------|call_log|END|
2009-05-04 17:12:19|VDfastAGI|call_log||CALL HUNG UP|
2009-05-04 17:12:19|VDfastAGI|call_log|URL HVcauses: |PRI|NODEBUG|16|NOANSWER|||
2009-05-04 17:12:19|VDfastAGI|call_log||DELETE from live_inbound where uniqueid='1241482315.96' and server_ip='8.12.160.115'|
2009-05-04 17:12:19|VDfastAGI|call_log|+++++ CALL LOG HUNGUP: |1241482315.96|SIP/5060-09cec7d0|h|2009-05-04 17:12:19|min: |
2009-05-04 17:12:19|VDfastAGI|call_log|DEBUG: NODEBUG
2009-05-04 17:12:19|VDfastAGI|call_log|VD_hangup : 9166018190 SIP/5060-09cec7d0 1 0
2009-05-04 17:12:19|VDfastAGI|call_log||SELECT lead_id,callerid,campaign_id,alt_dial,stage,UNIX_TIMESTAMP(call_time),uniqueid,status FROM vicidial_auto_calls where uniqueid = '1241482315.96' or callerid = '9166018190' limit 1;|
2009-05-04 17:12:19|VDfastAGI|call_log|VD hangup: no VDAC record found: 1241482315.96 9166018190
2009-05-04 17:12:22|VDfastAGI|begin|+++++++++++++++++ FastAGI Start ++++++++++++++++++++++++++++++++++++++++
2009-05-04 17:12:22|VDfastAGI|begin|Perl Environment Dump:
2009-05-04 17:12:22|VDfastAGI|begin|0|--debug
2009-05-04 17:12:22|VDfastAGI|begin|URL HVcauses: |PRI|NODEBUG|16|NOANSWER|||
2009-05-04 17:12:22|VDfastAGI|begin|AGI Environment Dump:
2009-05-04 17:12:22|VDfastAGI|begin| -- accountcode =
2009-05-04 17:12:22|VDfastAGI|begin| -- callerid = 9166018190
2009-05-04 17:12:22|VDfastAGI|begin| -- calleridname = Brown Daman
2009-05-04 17:12:22|VDfastAGI|begin| -- callingani2 = 0
2009-05-04 17:12:22|VDfastAGI|begin| -- callingpres = 0
2009-05-04 17:12:22|VDfastAGI|begin| -- callingtns = 0
2009-05-04 17:12:22|VDfastAGI|begin| -- callington = 0
2009-05-04 17:12:22|VDfastAGI|begin| -- channel = SIP/5060-09cf8e30
2009-05-04 17:12:22|VDfastAGI|begin| -- context = default
2009-05-04 17:12:22|VDfastAGI|begin| -- dnid = 8888972733
2009-05-04 17:12:22|VDfastAGI|begin| -- enhanced = 0.0
2009-05-04 17:12:22|VDfastAGI|begin| -- extension = h
2009-05-04 17:12:22|VDfastAGI|begin| -- language = en
2009-05-04 17:12:22|VDfastAGI|begin| -- network = yes
2009-05-04 17:12:22|VDfastAGI|begin| -- network_script = call_log--HVcauses--PRI-----NODEBUG-----16-----NOANSWER----------
2009-05-04 17:12:22|VDfastAGI|begin| -- priority = 1
2009-05-04 17:12:22|VDfastAGI|begin| -- rdnis = unknown
2009-05-04 17:12:22|VDfastAGI|begin| -- request = agi://127.0.0.1:4577/call_log--HVcauses ... ----------
2009-05-04 17:12:22|VDfastAGI|begin| -- type = SIP
2009-05-04 17:12:22|VDfastAGI|begin| -- uniqueid = 1241482318.98
2009-05-04 17:12:22|VDfastAGI|begin|AGI Variables: |1241482318.98|SIP/5060-09cf8e30|h|SIP|9166018190|
2009-05-04 17:12:22|VDfastAGI|call_log|Process to run: |agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----NOANSWER----------|call_log|END|
2009-05-04 17:12:22|VDfastAGI|call_log||CALL HUNG UP|
2009-05-04 17:12:22|VDfastAGI|call_log|URL HVcauses: |PRI|NODEBUG|16|NOANSWER|||
2009-05-04 17:12:22|VDfastAGI|call_log||DELETE from live_inbound where uniqueid='1241482318.98' and server_ip='8.12.160.115'|
2009-05-04 17:12:22|VDfastAGI|call_log|+++++ CALL LOG HUNGUP: |1241482318.98|SIP/5060-09cf8e30|h|2009-05-04 17:12:22|min: |
2009-05-04 17:12:22|VDfastAGI|call_log|DEBUG: NODEBUG
2009-05-04 17:12:22|VDfastAGI|call_log|VD_hangup : 9166018190 SIP/5060-09cf8e30 1 0
2009-05-04 17:12:22|VDfastAGI|call_log||SELECT lead_id,callerid,campaign_id,alt_dial,stage,UNIX_TIMESTAMP(call_time),uniqueid,status FROM vicidial_auto_calls where uniqueid = '1241482318.98' or callerid = '9166018190' limit 1;|
2009-05-04 17:12:22|VDfastAGI|call_log|VD hangup: no VDAC record found: 1241482318.98 9166018190
2009-05-04 17:12:25|VDfastAGI|begin|+++++++++++++++++ FastAGI Start ++++++++++++++++++++++++++++++++++++++++
2009-05-04 17:12:25|VDfastAGI|begin|Perl Environment Dump:
2009-05-04 17:12:25|VDfastAGI|begin|0|--debug
2009-05-04 17:12:25|VDfastAGI|begin|URL HVcauses: |PRI|NODEBUG|16|NOANSWER|||
2009-05-04 17:12:25|VDfastAGI|begin|AGI Environment Dump:
2009-05-04 17:12:25|VDfastAGI|begin| -- accountcode =
2009-05-04 17:12:25|VDfastAGI|begin| -- callerid = 9166018190
2009-05-04 17:12:25|VDfastAGI|begin| -- calleridname = Brown Daman
2009-05-04 17:12:25|VDfastAGI|begin| -- callingani2 = 0
2009-05-04 17:12:25|VDfastAGI|begin| -- callingpres = 0
2009-05-04 17:12:25|VDfastAGI|begin| -- callingtns = 0
2009-05-04 17:12:25|VDfastAGI|begin| -- callington = 0
2009-05-04 17:12:25|VDfastAGI|begin| -- channel = SIP/5060-09d03458
2009-05-04 17:12:25|VDfastAGI|begin| -- context = default
2009-05-04 17:12:25|VDfastAGI|begin| -- dnid = 8888972733
2009-05-04 17:12:25|VDfastAGI|begin| -- enhanced = 0.0
2009-05-04 17:12:25|VDfastAGI|begin| -- extension = h
2009-05-04 17:12:25|VDfastAGI|begin| -- language = en
2009-05-04 17:12:25|VDfastAGI|begin| -- network = yes
2009-05-04 17:12:25|VDfastAGI|begin| -- network_script = call_log--HVcauses--PRI-----NODEBUG-----16-----NOANSWER----------
2009-05-04 17:12:25|VDfastAGI|begin| -- priority = 1
2009-05-04 17:12:25|VDfastAGI|begin| -- rdnis = unknown
2009-05-04 17:12:25|VDfastAGI|begin| -- request = agi://127.0.0.1:4577/call_log--HVcauses ... ----------
2009-05-04 17:12:25|VDfastAGI|begin| -- type = SIP
2009-05-04 17:12:25|VDfastAGI|begin| -- uniqueid = 1241482321.100
2009-05-04 17:12:25|VDfastAGI|begin|AGI Variables: |1241482321.100|SIP/5060-09d03458|h|SIP|9166018190|
2009-05-04 17:12:25|VDfastAGI|call_log|Process to run: |agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----NOANSWER----------|call_log|END|
2009-05-04 17:12:25|VDfastAGI|call_log||CALL HUNG UP|
2009-05-04 17:12:25|VDfastAGI|call_log|URL HVcauses: |PRI|NODEBUG|16|NOANSWER|||
2009-05-04 17:12:25|VDfastAGI|call_log||DELETE from live_inbound where uniqueid='1241482321.100' and server_ip='8.12.160.115'|
2009-05-04 17:12:25|VDfastAGI|call_log|+++++ CALL LOG HUNGUP: |1241482321.100|SIP/5060-09d03458|h|2009-05-04 17:12:25|min: |
2009-05-04 17:12:25|VDfastAGI|call_log|DEBUG: NODEBUG
2009-05-04 17:12:25|VDfastAGI|call_log|VD_hangup : 9166018190 SIP/5060-09d03458 1 0
2009-05-04 17:12:25|VDfastAGI|call_log||SELECT lead_id,callerid,campaign_id,alt_dial,stage,UNIX_TIMESTAMP(call_time),uniqueid,status FROM vicidial_auto_calls where uniqueid = '1241482321.100' or callerid = '9166018190' limit 1;|
2009-05-04 17:12:25|VDfastAGI|call_log|VD hangup: no VDAC record found: 1241482321.100 9166018190
2009-05-04 17:12:28|VDfastAGI|begin|+++++++++++++++++ FastAGI Start ++++++++++++++++++++++++++++++++++++++++
2009-05-04 17:12:28|VDfastAGI|begin|Perl Environment Dump:
2009-05-04 17:12:28|VDfastAGI|begin|0|--debug
2009-05-04 17:12:28|VDfastAGI|begin|URL HVcauses: |PRI|NODEBUG|16|ANSWER|26|20|
2009-05-04 17:12:28|VDfastAGI|begin|AGI Environment Dump:
2009-05-04 17:12:28|VDfastAGI|begin| -- accountcode =
2009-05-04 17:12:28|VDfastAGI|begin| -- callerid = 9166018190
2009-05-04 17:12:28|VDfastAGI|begin| -- calleridname = Brown Daman
2009-05-04 17:12:28|VDfastAGI|begin| -- callingani2 = 0
2009-05-04 17:12:28|VDfastAGI|begin| -- callingpres = 0
2009-05-04 17:12:28|VDfastAGI|begin| -- callingtns = 0
2009-05-04 17:12:28|VDfastAGI|begin| -- callington = 0
2009-05-04 17:12:28|VDfastAGI|begin| -- channel = SIP/5060-09d0da80
2009-05-04 17:12:28|VDfastAGI|begin| -- context = default
2009-05-04 17:12:28|VDfastAGI|begin| -- dnid = 8888972733
2009-05-04 17:12:28|VDfastAGI|begin| -- enhanced = 0.0
2009-05-04 17:12:28|VDfastAGI|begin| -- extension = h
2009-05-04 17:12:28|VDfastAGI|begin| -- language = en
2009-05-04 17:12:28|VDfastAGI|begin| -- network = yes
2009-05-04 17:12:28|VDfastAGI|begin| -- network_script = call_log--HVcauses--PRI-----NODEBUG-----16-----NOANSWER----------
2009-05-04 17:12:28|VDfastAGI|begin| -- priority = 1
2009-05-04 17:12:28|VDfastAGI|begin| -- rdnis = unknown
2009-05-04 17:12:28|VDfastAGI|begin| -- request = agi://127.0.0.1:4577/call_log--HVcauses ... ----------
2009-05-04 17:12:28|VDfastAGI|begin| -- type = SIP
2009-05-04 17:12:28|VDfastAGI|begin| -- uniqueid = 1241482324.102
2009-05-04 17:12:28|VDfastAGI|begin|AGI Variables: |1241482324.102|SIP/5060-09d0da80|h|SIP|9166018190|
2009-05-04 17:12:28|VDfastAGI|call_log|Process to run: |agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----NOANSWER----------|call_log|END|
2009-05-04 17:12:28|VDfastAGI|call_log||CALL HUNG UP|
2009-05-04 17:12:28|VDfastAGI|call_log|URL HVcauses: |PRI|NODEBUG|16|NOANSWER|||
2009-05-04 17:12:28|VDfastAGI|call_log||DELETE from live_inbound where uniqueid='1241482324.102' and server_ip='8.12.160.115'|
2009-05-04 17:12:28|VDfastAGI|call_log|+++++ CALL LOG HUNGUP: |1241482324.102|SIP/5060-09d0da80|h|2009-05-04 17:12:28|min: |
2009-05-04 17:12:28|VDfastAGI|call_log|DEBUG: NODEBUG
2009-05-04 17:12:28|VDfastAGI|call_log|VD_hangup : 9166018190 SIP/5060-09d0da80 1 0
2009-05-04 17:12:28|VDfastAGI|call_log||SELECT lead_id,callerid,campaign_id,alt_dial,stage,UNIX_TIMESTAMP(call_time),uniqueid,status FROM vicidial_auto_calls where uniqueid = '1241482324.102' or callerid = '9166018190' limit 1;|
2009-05-04 17:12:28|VDfastAGI|call_log|VD hangup: no VDAC record found: 1241482324.102 9166018190


Has anyone experienced this in the new version before? Let me know if there is any other info I can give.

THANKS!!!!

[mflorell]

Looks like something is wrong with your music on hold, you might want to fix that first then see if the issue still exists.