[Home]

Summary:ASTERISK-20037: func_odbc timeout quite long when connection drops during query - possibly need to expose query timeout attribute to make it configurable
Reporter:Steven Wheeler (swheeler)Labels:
Date Opened:2012-06-22 13:48:58Date Closed:
Priority:MajorRegression?
Status:Open/NewComponents:Functions/func_odbc Resources/res_odbc
Versions:1.8.9.3 13.18.4 Frequency of
Occurrence
Related
Issues:
Environment:Asterisk 1.8.9.2 CentOS 5.5 Final MyODBC 5.1.9Attachments:( 0) buglog.log
Description:When using UnixODBC to connect Asterisk to a MySQL database server we are encountering issues when the database goes down.  We have designed the system with a redundant database server, but Asterisk locks up when the primary database goes into a hung state where it neither accepts or rejects the connections.  We simulate this condition using this iptables rule on the Asterisk server: -A OUTPUT -d x.x.x.x -j DROP.  We have setup connection timeouts which work well if the connections are not established when the primary database server goes down, but it doesn't look like Asterisk implements any sort of query timeout.

Am I missing something or is this a known issue with Asterisk?
Comments:By: Rusty Newton (rnewton) 2012-06-27 18:10:27.414-0500

Regardless of your configuration, Asterisk really shouldn't lock up. Does it crash completely, or does the process just stop responding?

Please review: https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines

Then provide debug using the general instructions here: https://wiki.asterisk.org/wiki/display/AST/Collecting+Debug+Information

Essentially we'll need a full log with VERBOSE and DEBUG of at least level 5 covering the time before and up to the point of the process locking up.

Please attach any debug in *attached* compressed archive or text file format.
By: Steven Wheeler (swheeler) 2012-06-28 09:02:34.806-0500

The problem appears to be twofold.

1) Asterisk does not implement a query timeout which means that when we execute a query on an established connection to a hung database it waits 18 1/2 minutes before timing out.

2) unixODBC v2.3.0 had a threading issue which caused all queries to block until this 18 minute timeout was reached.

We have fixed the second issue by upgrading to v2.3.1, but we are still having issues with the first call hanging rather than timing out and continuing.  Is there any way to set a query timeout for res_odbc connections?  Even if it is just a global value it would be better than the current timeout.
By: Steven Davis (davissteve80) 2012-06-28 12:35:33.617-0500

I'm not sure if this is directly related. But with 1.8.13.0, we're trying to formalize our realtime database failover.

We don't seem to see the results that we'd expect from negative_connection_cache even entering the logic of the failover.

We have res_odbc configured with two explicit DSN for a `configuration.local` and a `configuration.remote` that point to two seperate MySQL servers. We simulate a failure by simply stopping the mysql service on one of the severs, in this case the server coresponding to configuration.local. When we do so, our func_odbc entries and our extconfig.conf settings seem to process properly, but all of the calls seem to at least try the now dead configuration.lcoal, before trying configuration.remote.

In our testing we have negative_connection_cache set to 300 (but there seems to be no change regardless of setting, as high as 1800)

Here is a log snippet (debug =5) :

Jun 28 11:36:41 opbld08 asterisk[28950]: WARNING[20076]: res_config_odbc.c:83 in custom_prepare: SQL Alloc Handle failed!
Jun 28 11:36:41 opbld08 asterisk[28950]: WARNING[20076]: res_odbc.c:758 in ast_odbc_sanity_check: Connection is down attempting to reconnect...
Jun 28 11:36:41 opbld08 asterisk[28950]: NOTICE[20076]: res_odbc.c:1527 in odbc_obj_connect: Connecting configuration.local
Jun 28 11:36:41 opbld08 asterisk[28950]: WARNING[20076]: res_odbc.c:1552 in odbc_obj_connect: res_odbc: Error SQLConnect=-1 errno=2013 [unixODBC][MySQL][ODBC 3.51 Driver]Lost connection to MySQL server at 'reading initial communicatio
Jun 28 11:36:41 opbld08 asterisk[28950]: WARNING[20076]: res_config_odbc.c:83 in custom_prepare: SQL Alloc Handle failed!
Jun 28 11:36:41 opbld08 asterisk[28950]: DEBUG[20076]: res_odbc.c:1050 in odbc_release_obj2: odbc_release_obj2(0x1ed70910) called (obj->txf = (nil))
Jun 28 11:36:41 opbld08 asterisk[28950]: DEBUG[20076]: res_config_odbc.c:87 in custom_prepare: Skip: 0; SQL: SELECT * FROM queues WHERE name LIKE ? ORDER BY name
Jun 28 11:36:41 opbld08 asterisk[28950]: DEBUG[20076]: res_config_odbc.c:103 in custom_prepare: Parameter 1 ('name LIKE') = '%'
Jun 28 11:36:41 opbld08 asterisk[28950]: DEBUG[20076]: res_odbc.c:1050 in odbc_release_obj2: odbc_release_obj2(0x1ee36a80) called (obj->txf = (nil))
Jun 28 11:36:41 opbld08 asterisk[28950]: WARNING[20076]: res_config_odbc.c:83 in custom_prepare: SQL Alloc Handle failed!
Jun 28 11:36:41 opbld08 asterisk[28950]: WARNING[20076]: res_odbc.c:758 in ast_odbc_sanity_check: Connection is down attempting to reconnect...
Jun 28 11:36:41 opbld08 asterisk[28950]: NOTICE[20076]: res_odbc.c:1527 in odbc_obj_connect: Connecting configuration.local
Jun 28 11:36:41 opbld08 asterisk[28950]: WARNING[20076]: res_odbc.c:1552 in odbc_obj_connect: res_odbc: Error SQLConnect=-1 errno=2013 [unixODBC][MySQL][ODBC 3.51 Driver]Lost connection to MySQL server at 'reading initial communicatio
Jun 28 11:36:41 opbld08 asterisk[28950]: WARNING[20076]: res_config_odbc.c:83 in custom_prepare: SQL Alloc Handle failed!
Jun 28 11:36:41 opbld08 asterisk[28950]: DEBUG[20076]: res_odbc.c:1050 in odbc_release_obj2: odbc_release_obj2(0x1ed70910) called (obj->txf = (nil))
Jun 28 11:36:41 opbld08 asterisk[28950]: DEBUG[20076]: res_config_odbc.c:87 in custom_prepare: Skip: 0; SQL: SELECT * FROM queues WHERE name = ?
Jun 28 11:36:41 opbld08 asterisk[28950]: DEBUG[20076]: res_config_odbc.c:103 in custom_prepare: Parameter 1 ('name') = 'XXXX-QUEUE-NAME-XXXX'
Jun 28 11:36:41 opbld08 asterisk[28950]: DEBUG[20076]: res_odbc.c:1050 in odbc_release_obj2: odbc_release_obj2(0x1ee36a80) called (obj->txf = (nil))
Jun 28 11:36:41 opbld08 asterisk[28950]: WARNING[20076]: res_config_odbc.c:83 in custom_prepare: SQL Alloc Handle failed!
Jun 28 11:36:41 opbld08 asterisk[28950]: WARNING[20076]: res_odbc.c:758 in ast_odbc_sanity_check: Connection is down attempting to reconnect...
Jun 28 11:36:41 opbld08 asterisk[28950]: NOTICE[20076]: res_odbc.c:1527 in odbc_obj_connect: Connecting configuration.local
Jun 28 11:36:41 opbld08 asterisk[28950]: WARNING[20076]: res_odbc.c:1552 in odbc_obj_connect: res_odbc: Error SQLConnect=-1 errno=2013 [unixODBC][MySQL][ODBC 3.51 Driver]Lost connection to MySQL server at 'reading initial communicatio
Jun 28 11:36:41 opbld08 asterisk[28950]: WARNING[20076]: res_config_odbc.c:83 in custom_prepare: SQL Alloc Handle failed!

This repeats for any func_odbc call or queue status update or really anything that would access odbc (we're not sending CDR/CEL/Queue_log to these DSNs)...

As soon as I restart the MySQL service:

Jun 28 11:36:52 opbld08 asterisk[28950]: WARNING[28965]: res_config_odbc.c:83 in custom_prepare: SQL Alloc Handle failed!
Jun 28 11:36:52 opbld08 asterisk[28950]: WARNING[28965]: res_odbc.c:758 in ast_odbc_sanity_check: Connection is down attempting to reconnect...
Jun 28 11:36:52 opbld08 asterisk[28950]: NOTICE[28965]: res_odbc.c:1527 in odbc_obj_connect: Connecting configuration.local
Jun 28 11:36:52 opbld08 asterisk[28950]: NOTICE[28965]: res_odbc.c:1559 in odbc_obj_connect: res_odbc: Connected to configuration.local [local.asterisk.config]





By: Rusty Newton (rnewton) 2012-06-28 16:41:41.695-0500

Not much we can do without the debug requested.

Steven Wheeler,

I'm told we don't set SQL_ATTR_QUERY_TIMEOUT when performing an SQLExecute and that doing so would likely be a new feature requiring some sweeping changes.

In the description of this issue you describe asterisk locking up and in your comment you describe a " first call hanging rather than timing out and continuing. "

After the unixODBC upgrade, does Asterisk continue to lock up, or does only a individual call (channel?) hang? Can you please provide debug requested above, attached to the issue. If Asterisk is not hard locking at the end of the debug, then point out a timestamp or location in the debug log where the call hanging occurs.
By: Steven Wheeler (swheeler) 2012-06-28 17:22:34.191-0500

The requested debug output.  Notable timestamps are:
17:01:28 - the call to func_odbc hangs
17:02:28 - the phone gives up and ends the call
17:18:53 - the func_odbc call finally returns with the error: Lost connection to MySQL server during query
By: Steven Wheeler (swheeler) 2012-06-28 17:23:27.734-0500

I have attached the requested output.  Note asterisk does not lock up entirely after upgrading unixODBC.  Only the call that tried to connect to the database locks up.
By: Rusty Newton (rnewton) 2012-07-02 14:21:31.709-0500

We can't determine that this behavior is unexpected, but it certainly isn't optimal. Acknowledged and also moved into the core queue as an improvement to expose the query timeout attribute and make it configurable.
By: Steven Wheeler (swheeler) 2012-07-03 12:01:27.745-0500

Thank you, I look forward to being able to configure this.
By: Martin Tomec (matesstar) 2015-05-13 06:24:46.953-0500

I am not sure if this is related, but I submited patch to ASTERISK-22708. If you set negative_connection_cache, asterisk should not connect to dead DB for specified amount of time.