Moderators: gerski, enjay, williamconley, Op3r, Staydog, gardo, mflorell, MJCoate, mcargile, Kumba, Michael_N
so it is! lol (you must have typed it too quickly because I read right past it).Is this not the build number in the footer? Version: 2.6-372a BUILD: 120713-2123
PierreDeux wrote:Same here, after yesterday's update to VERSION: 2.8-417a BUILD: 131019-0849 I'm having multiple records like this:
131104 16:59:43 [Warning] Aborted connection 1102 to db: 'asterisk' user: 'cron' host: '192.168.9.21' (Unknown error)
131104 16:59:45 [Warning] Aborted connection 1835 to db: 'asterisk' user: 'cron' host: '192.168.9.22' (Unknown error)
131104 16:59:47 [Warning] Aborted connection 3824 to db: 'asterisk' user: 'cron' host: '192.168.9.15' (Unknown error)
6 Asterisk servers, 1 web server and dedicated DB. It took us a while to find out that we are having 26k of ports with TIME_WAIT to DB. Around 100 agents logged in, nearly half dialing, 200-300 calls total, all that stuff is making 2.5-2.7k mysql requests per second.
After changing tcp_tw_recycle busy ports look like this:
voip13:~ # netstat -an | grep TIME_WAIT | grep 3306 | wc -l
84
voip13:~ # netstat -an | grep TIME_WAIT | grep 3306 | wc -l
104
voip13:~ # netstat -an | grep TIME_WAIT | grep 3306 | wc -l
174
Bump for a useful thread since it took use several hours of heavy debug to find the reason.
williamconley wrote:PierreDeux wrote:Same here, after yesterday's update to VERSION: 2.8-417a BUILD: 131019-0849 I'm having multiple records like this:
131104 16:59:43 [Warning] Aborted connection 1102 to db: 'asterisk' user: 'cron' host: '192.168.9.21' (Unknown error)
131104 16:59:45 [Warning] Aborted connection 1835 to db: 'asterisk' user: 'cron' host: '192.168.9.22' (Unknown error)
131104 16:59:47 [Warning] Aborted connection 3824 to db: 'asterisk' user: 'cron' host: '192.168.9.15' (Unknown error)
6 Asterisk servers, 1 web server and dedicated DB. It took us a while to find out that we are having 26k of ports with TIME_WAIT to DB. Around 100 agents logged in, nearly half dialing, 200-300 calls total, all that stuff is making 2.5-2.7k mysql requests per second.
After changing tcp_tw_recycle busy ports look like this:
voip13:~ # netstat -an | grep TIME_WAIT | grep 3306 | wc -l
84
voip13:~ # netstat -an | grep TIME_WAIT | grep 3306 | wc -l
104
voip13:~ # netstat -an | grep TIME_WAIT | grep 3306 | wc -l
174
Bump for a useful thread since it took use several hours of heavy debug to find the reason.
1) Welcome to the Party!
2) As you are obviously new here, I have some suggestions to help us all help you:
You should post your installation method (link to the instructions if they are online, the name of the .iso image of the install disks, and any actions performed outside the .iso install and/or any special actions taken during the install or configuration settings changed).
Similar to This:
Vicibox X.X from .iso | Vicidial X.X.X-XXX Build XXXXXX-XXXX | Asterisk X.X.X | Single Server | No Digium/Sangoma Hardware | No Extra Software After Installation | Intel DG35EC | Core2Quad Q6600
3) As you are dropping deep technical results without any background ... you may want to consider cluing us in on the effect this has on your system. Me, too, usually turns out to be not entirely true on forums. So quoting the actual error or condition is helpful before the "me, too".
4) As you have a large system, do you have the large system database configuration in place? (Kumba's install CD will enact large database settings upon request during database install ...)
[mysqld]
max_allowed_packet=128M
skip-name-resolve
log-warnings=2
table_cache = 20480
myisam_sort_buffer_size = 256M
default-storage-engine=MyISAM
skip-innodb
bulk_insert_buffer_size=256M
datadir=/data/mysql
socket=/data/mysql/mysql.sock
tmpdir=/home/tmp/
user=mysql
bind-address=192.168.9.253
max_connections=800
old_passwords=0
open_files_limit=64270
log-slow-queries = /var/log/mysql-slow-queries.log
long_query_time = 5
key_buffer_size = 41G
query_cache_size = 20G
thread_cache_size = 32
query_cache_limit = 64M
join_buffer_size = 32M
sort_buffer_size = 16M
read_rnd_buffer_size = 2M
max_heap_table_size=12G
tmp_table_size=256M
connect_timeout=60
wait_timeout=600
thread_concurrency=24
concurrent_insert=2
Same here, after yesterday's update to VERSION: 2.8-417a BUILD: 131019-0849 I'm having multiple records like this:
131104 16:59:43 [Warning] Aborted connection 1102 to db: 'asterisk' user: 'cron' host: '192.168.9.21' (Unknown error)
131104 16:59:45 [Warning] Aborted connection 1835 to db: 'asterisk' user: 'cron' host: '192.168.9.22' (Unknown error)
131104 16:59:47 [Warning] Aborted connection 3824 to db: 'asterisk' user: 'cron' host: '192.168.9.15' (Unknown error)
131104 16:59:45 [Warning] Aborted connection 1835 to db: 'asterisk' user: 'cron' host: '192.168.9.22' (Unknown error)
1. Amount of calls constantly varies no matter what dial method (adapt or ratio) is set or how many free agents there are. There can be 20 calls, than 100 calls, than back to 20 in one minute or even less. It's highly unstable.
2. When there are many calls waiting for agents (e.g. I've seen many times issues like 30 calls are waiting for 5-10 seconds while there are 40 free agents) I'm getting a lot of those aborts in DB logs. However most of those calls seem to connect to agents.
Unless these aborts are due to processes that abandoned the mysql thread and mysql responded by aborting the "already being ignored" thread. This is why i wanted to find the symptom and see if we can attack from that direction instead.I can't find anything about mysql errors in any logs on my web or dialers. Not in /var/log/astguiclient, no anywhere else. That's weird.
This does not tell me anything about your symptom. I doubt your problem is that you don't want this line to be in that file because it takes up too much room on the hard drive. I suspect you are talking about problems with the dialer (which you still haven't mentioned, but in your next post you are getting closer!)
1340666 Connect cron@192.168.9.15 as anonymous on asterisk
1340666 Query set autocommit=1
1340666 Query SELECT agi_output,local_gmt FROM servers where server_ip = 'X.X.X.X' (one of my IP addresses was here)
1340666 Query SELECT enable_queuemetrics_logging,queuemetrics_server_ip,queuemetrics_dbname,queuemetrics_login,queuemetrics_pass,queuemetrics_log_id,queuemetrics_eq_prepend,queuemetrics_pe_phone_append,did_agent_log,alt_log_server_ip,alt_log_dbname,alt_log_login,alt_log_pass,tables_use_alt_log_db,did_ra_extensions_enabled,queuemetrics_socket,queuemetrics_socket_url FROM system_settings
1340666 Query SELECT call_handle_method,agent_search_method,group_id,did_pattern,list_id,phone_code,campaign_id,user,user_unavailable_action,user_route_settings_ingroup,did_route,voicemail_ext,extension,exten_context,phone,server_ip FROM vicidial_inbound_dids where did_id = '126'
1340666 Query SELECT voicemail_dump_exten,ext_context,answer_transfer_agent,local_gmt,asterisk_version,max_vicidial_trunks FROM servers where server_ip = '68.233.253.217'
1340666 Query UPDATE vicidial_inbound_groups SET group_calldate='2013-11-07 08:48:38' where group_id='English'
1340666 Query SELECT call_time_id,after_hours_action,after_hours_message_filename,after_hours_exten,after_hours_voicemail,welcome_message_filename,moh_context,onhold_prompt_filename,prompt_interval,agent_alert_exten,agent_alert_delay,drop_call_seconds,drop_action,drop_exten,next_agent_call,voicemail_ext,queue_priority,drop_inbound_group,afterhours_xfer_group,play_place_in_line,play_estimate_hold_time,hold_time_option,hold_time_option_seconds,hold_time_option_exten,hold_time_option_voicemail,hold_time_option_xfer_group,hold_time_option_callback_filename,hold_time_option_callback_list_id,hold_recall_xfer_group,no_delay_call_route,play_welcome_message,no_agent_no_queue,no_agent_action,no_agent_action_value,extension_appended_cidname,uniqueid_status_display,uniqueid_status_prefix,hold_time_option_minimum,hold_time_option_press_filename,hold_time_option_callmenu,onhold_prompt_no_block,onhold_prompt_seconds,hold_time_option_no_block,hold_time_option_prompt_seconds,hold_time_second_option,hold_time_third_option,wait_hold_option_priority,wait_time_option,wait_time_second_option,wait_time_third_option,wait_time_option_seconds,wait_time_option_exten,wait_time_option_voicemail,wait_time_option_xfer_group,wait_time_option_callmenu,wait_time_option_callback_filename,wait_time_option_callback_list_id,wait_time_option_press_filename,wait_time_option_no_block,wait_time_option_prompt_seconds,active,calculate_estimated_hold_seconds,add_lead_url,eht_minimum_prompt_filename,eht_minimum_prompt_no_block,eht_minimum_prompt_seconds,on_hook_ring_time,ingroup_recording_override,ingroup_rec_filename,on_hook_cid,action_xfer_cid,drop_callmenu,after_hours_callmenu,max_calls_method,max_calls_count,max_calls_action FROM vicidial_inbound_groups where group_id = 'English'
1340666 Query SELECT ct_default_start,ct_default_stop,default_afterhours_filename_override ,ct_thursday_start,ct_thursday_stop,thursday_afterhours_filename_override ,ct_wednesday_start,ct_wednesday_stop,ct_holidays FROM vicidial_call_times where call_time_id = '24hours'
1340666 Query SELECT lead_id from vicidial_list where phone_number='4073017666' order by last_local_call_time desc limit 1
| interactive_timeout | 28800 |
| net_read_timeout | 60 |
| net_write_timeout | 120 |
| wait_timeout | 28800 |
The system that generates the amount of calls has very specific reasons for doing so. There is a constantly running script that monitors the system and makes the decisions of what should be dialed now. Access that script (it is one of the many screens available via "screen -list") and you can find out why this behavior occurs and trace that problem, likely to an unrelated process. Unrelated meaning "nothing to do with mysql having an error".
---------- ADAPT DEBUG
Campaign Debug: route72 - Route72 US 2013-11-07 10:59:13
Total leads in hopper right now: 1106
Adapt Debug: 2013-11-07 10:59:05
route72 hopper READY count: 1073
route72 agents LOGGED-IN count: 66
0 |route72|5|1073|9am-9pm|15|60|
TIME CALL CHECK: 13838396451383839941
CAMPAIGN DIFFERENTIAL: 66.2 23.1333333333333 (23.1333333333333 - 0)
CAMPAIGN ANSWERED STATUSES: route72|DROP,XDROP,CALLBK,CBHOLD,DEC,SALE,NI,NP,XFER,RQXFER,TIMEOT,AFTHRS,NANQUE,DropM,SALEFP,411,QCFAIL|
route72|1.20|2.47| |185 7491 2129| 0
LIVE CALLS: 102|SELECT count(*) from vicidial_auto_calls where campaign_id=route72
AGENT TIME STATS: 46021 511247 85401 89752|SELECT sum(pause_sec),sum(wait_sec),sum(talk_sec) - sum(dead_sec) as custtalk,sum(dispo_sec) + sum(dead_sec) as acw from vicidial_agent_log where event_time > 2013-11-07 00:00:01 and campaign_id=route72 and pause_sec < 65000 and wait_sec < 65000 and talk_sec < 65000 and dispo_sec < 65000 and dead_sec < 65000
AGENT CALLS: 5257|SELECT count(*) from vicidial_agent_log where event_time > 2013-11-07 00:00:01 and campaign_id=route72 and lead_id > 0
CAMPAIGN: route72 0
SETTINGS-
DIAL LEVEL: 2
DIAL METHOD: ADAPT_AVERAGE
AVAIL ONLY: N
DROP PERCENT: 48
MAX LEVEL: 2
SERVER TIME: 1059
LATE TARGET: 2100 (1041 left|1)
INTENSITY: 30
DLDIFF TARGET: 3
CURRENT STATS-
AVG AGENTS: 66.85
AGENTS: 66 ACTIVE: 48 CALC: 48 INCALL: 25 READY: 23
DL DIFFERENTIAL: 21.25 = (18.25 + 3)
DIAL LEVEL SUGGESTION-
PERCENT DIFF: 31.79
SUGGEST DL: 2.636 = (2 * (0.317875841436051 + 1) )
INTENSE DIFF: 41.32
INTENSE DL: 2.826 = (2 * (0.413238593866866 + 1) )
DIAL LEVEL OVER CAP! SETTING TO CAP: 2
DROP STATS-
TODAY DROPS: 7491 185 2.47%
ANSWER DROPS: 2129 8.69%
ONE HOUR DROPS: 4487/1229 52 1.16%
HALF HOUR DROPS: 2333/653 19 0.81%
FIVE MIN DROPS: 333/86 4 1.20%
ONE MIN DROPS: 36/6 2 5.56%
DIAL LEVEL UPDATED TO: 2 CONFIRM: 1
X.X.X.28 Debug: 2013-11-07 10:59:01
ROUTE72 X.X.X.28: agents: 4 (READY: 1) dial_level: 2 (1|0|1) 3
ROUTE72 X.X.X.28: Calls to place: 6 (8 - 2 [0 + 2|5|0]) 14
CAMPAIGN DIFFERENTIAL: 26.7 8.4 (8.5 - 0.1)
LOCAL TRUNK SHORTAGE: 0|0 (14 - 300)
X.X.X.30 Debug: 2013-11-07 10:59:01
ROUTE72 X.X.X.30: agents: 6 (READY: 1) dial_level: 2 (1|2|4) 3
ROUTE72 X.X.X.30: Calls to place: -12 (12 - 24 [0 + 24|5|0]) 34
CAMPAIGN DIFFERENTIAL: 23.2 6.15 (8 - 1.85)
LOCAL TRUNK SHORTAGE: 0|0 (22 - 300)
X.X.X.31 Debug: 2013-11-07 10:59:01
ROUTE72 X.X.X.31: agents: 7 (READY: 2) dial_level: 2 (2|2|0) 3
ROUTE72 X.X.X.31: Calls to place: 6 (14 - 8 [0 + 8|5|0]) 14
CAMPAIGN DIFFERENTIAL: 67.3 16.55 (18.9 - 2.35)
LOCAL TRUNK SHORTAGE: 0|0 (14 - 300)
X.X.X.32 Debug: 2013-11-07 10:59:01
ROUTE72 X.X.X.32: agents: 19 (READY: 7) dial_level: 2 (7|9|0) 3
ROUTE72 X.X.X.32: Calls to place: 4 (38 - 34 [0 + 34|5|0]) 38
CAMPAIGN DIFFERENTIAL: 67.25 16.3 (18.55 - 2.25)
LOCAL TRUNK SHORTAGE: 0|0 (38 - 300)
X.X.X.33 Debug: 2013-11-07 10:59:01
ROUTE72 X.X.X.33: agents: 3 (READY: 0) dial_level: 2 (0|0|1) 3
ROUTE72 X.X.X.33: Calls to place: 4 (6 - 2 [0 + 2|5|0]) 6
CAMPAIGN DIFFERENTIAL: 67.1 16.1 (18.75 - 2.65)
LOCAL TRUNK SHORTAGE: 0|0 (6 - 300)
X.X.X.34 Debug: 2013-11-07 10:59:01
ROUTE72 X.X.X.34: agents: 12 (READY: 6) dial_level: 2 (6|3|2) 3
ROUTE72 X.X.X.34: Calls to place: 17 (24 - 7 [0 + 7|4|0]) 26
CAMPAIGN DIFFERENTIAL: 66.85 18.25 (19.15 - 0.9)
LOCAL TRUNK SHORTAGE: 0|0 (26 - 300)
X.X.X.35 Debug: 2013-11-07 10:59:01
ROUTE72 X.X.X.35: agents: 12 (READY: 4) dial_level: 2 (4|5|0) 3
ROUTE72 X.X.X.35: Calls to place: 1 (24 - 23 [0 + 23|5|0]) 25
CAMPAIGN DIFFERENTIAL: 67.35 16.8 (18.55 - 1.75)
LOCAL TRUNK SHORTAGE: 0|0 (25 - 300)
Inbound Debug: English 2013-11-07 10:58:42
ANSWERED STATUSES: English|DROP,XDROP,CALLBK,CBHOLD,DEC,SALE,NI,NP,XFER,RQXFER,TIMEOT,AFTHRS,NANQUE,DropM,SALEFP,411,QCFAIL|
DAILY STATS|4|70|0|11 IN-GROUP: English CALLS: 1082 ANSWER: 1004 DROPS: 49
Stat1: 978 Stat2: 995 Hold: 4413.50|2019.75|833.00
And based on your comments, you are saying that these aborts happened in the stock vicidial mysql configuration as well? Or "it had problems" not specifically THIS problem?
Users browsing this forum: No registered users and 51 guests