[Home]

Summary:ASTERISK-21662: Res_odbc keeps losing connection to MySQL
Reporter:Duane Larson (osiris123d)Labels:
Date Opened:2013-04-20 13:28:23Date Closed:2013-04-23 09:19:21
Priority:MajorRegression?
Status:Closed/CompleteComponents:Resources/res_odbc
Versions:11.3.0 Frequency of
Occurrence
Related
Issues:
Environment:Debian 6.0Attachments:( 0) odbc.ini.txt
( 1) res_odbc.txt
Description:For some reason my ODBC connection to my MySQL server keeps losing its connection.  Because of this calls might be delayed until Asterisk re-establishes the connection.

I have posted this before in the forum and never got an answer.

http://forums.asterisk.org/viewtopic.php?p=170284

Here are the errors I see

{noformat}
[Apr 19 15:05:18] WARNING[7380][C-00000003] res_odbc.c: SetConnectAttr (Txn isolation) returned an error: HY000: [MySQL][ODBC 5.1 Driver]MySQL server has gone away
[Apr 19 15:05:18] WARNING[7380][C-00000003] res_odbc.c: SQL Execute returned an error -1: 08S01: [MySQL][ODBC 5.1 Driver][mysqld-5.1.42]MySQL server has gone away (65)
[Apr 19 15:05:18] WARNING[7380][C-00000003] res_odbc.c: SQL Execute error -1! Verifying connection to asterisk [MySQL-asterisk]...
[Apr 19 15:05:18] WARNING[7380][C-00000003] res_odbc.c: Connection is down attempting to reconnect...
[Apr 19 15:05:23] NOTICE[7380][C-00000003] res_odbc.c: Connecting asterisk
[Apr 19 15:05:23] NOTICE[7380][C-00000003] res_odbc.c: res_odbc: Connected to asterisk [MySQL-asterisk]
[Apr 19 15:05:23] WARNING[7380][C-00000003] res_odbc.c: SQL Execute returned an error -1: 42S22: [MySQL][ODBC 5.1 Driver][mysqld-5.1.42]Unknown column 'callbackextension' in 'where clause' (91)
[Apr 19 15:05:23] WARNING[7380][C-00000003] res_odbc.c: SQL Execute error -1! Verifying connection to asterisk [MySQL-asterisk]...
[Apr 19 15:05:23] WARNING[7380][C-00000003] res_odbc.c: Connection is down attempting to reconnect...
[Apr 19 15:05:28] NOTICE[7380][C-00000003] res_odbc.c: Connecting asterisk
[Apr 19 15:05:28] NOTICE[7380][C-00000003] res_odbc.c: res_odbc: Connected to asterisk [MySQL-asterisk]
[Apr 19 15:05:28] WARNING[7380][C-00000003] res_odbc.c: SQL Execute returned an error -1: 42S22: [MySQL][ODBC 5.1 Driver][mysqld-5.1.42]Unknown column 'callbackextension' in 'where clause' (91)
[Apr 19 15:05:28] WARNING[7380][C-00000003] res_odbc.c: SQL Execute error -1! Verifying connection to asterisk [MySQL-asterisk]...
[Apr 19 15:05:28] WARNING[7380][C-00000003] res_odbc.c: Connection is down attempting to reconnect...
[Apr 19 15:05:33] NOTICE[7380][C-00000003] res_odbc.c: Connecting asterisk
[Apr 19 15:05:33] NOTICE[7380][C-00000003] res_odbc.c: res_odbc: Connected to asterisk [MySQL-asterisk]
[Apr 20 13:24:25] WARNING[7380][C-00000004] res_odbc.c: SetConnectAttr (Txn isolation) returned an error: HY000: [MySQL][ODBC 5.1 Driver]MySQL server has gone away
[Apr 20 13:24:25] WARNING[7380][C-00000004] res_odbc.c: SQL Execute returned an error -1: 08S01: [MySQL][ODBC 5.1 Driver][mysqld-5.1.42]MySQL server has gone away (65)
[Apr 20 13:24:25] WARNING[7380][C-00000004] res_odbc.c: SQL Execute error -1! Verifying connection to asterisk [MySQL-asterisk]...
[Apr 20 13:24:25] WARNING[7380][C-00000004] res_odbc.c: Connection is down attempting to reconnect...
[Apr 20 13:24:30] NOTICE[7380][C-00000004] res_odbc.c: Connecting asterisk
[Apr 20 13:24:30] NOTICE[7380][C-00000004] res_odbc.c: res_odbc: Connected to asterisk [MySQL-asterisk]
{noformat}
Comments:By: Michael L. Young (elguero) 2013-04-20 16:38:40.053-0500

Duane, I would suggest that you fix your database table for sip peers.

{quote}
[Apr 19 15:05:28] WARNING[7380][C-00000003] res_odbc.c: SQL Execute returned an error -1: 42S22: [MySQL][ODBC 5.1 Driver][mysqld-5.1.42]Unknown column 'callbackextension' in 'where clause' (91)
{quote}
By: Duane Larson (osiris123d) 2013-04-21 13:12:07.144-0500

Fixed that issue but I still see the same issue.
{noformat}
[Apr 21 13:09:30] WARNING[24159][C-00000001] res_odbc.c: SetConnectAttr (Txn isolation) returned an error: HY000: [MySQL][ODBC 5.1 Driver]MySQL server has gone away
[Apr 21 13:09:30] WARNING[24159][C-00000001] res_odbc.c: SQL Execute returned an error -1: 08S01: [MySQL][ODBC 5.1 Driver][mysqld-5.1.42]MySQL server has gone away (65)
[Apr 21 13:09:30] WARNING[24159][C-00000001] res_odbc.c: SQL Execute error -1! Verifying connection to asterisk [MySQL-asterisk]...
[Apr 21 13:09:30] WARNING[24159][C-00000001] res_odbc.c: Connection is down attempting to reconnect...
[Apr 21 13:09:35] NOTICE[24159][C-00000001] res_odbc.c: Connecting asterisk
{noformat}

I would think that many people would have this same issue if the connection to the mysql database doesn't always stay connecected 24/7.

{noformat}
mysql> desc sipusers;
+-------------------+--------------+------+-----+---------+-------+
| Field             | Type         | Null | Key | Default | Extra |
+-------------------+--------------+------+-----+---------+-------+
| name              | char(64)     | NO   |     |         |       |
| defaultuser       | char(64)     | NO   |     |         |       |
| type              | varchar(6)   | NO   |     |         |       |
| secret            | char(25)     | NO   |     |         |       |
| host              | char(64)     | NO   |     |         |       |
| callerid          | char(64)     | NO   |     |         |       |
| context           | char(64)     | NO   |     |         |       |
| mailbox           | varchar(129) | NO   |     |         |       |
| subscribemwi      | varchar(2)   | NO   |     |         |       |
| regexten          | char(64)     | YES  |     | NULL    |       |
| nat               | varchar(7)   | NO   |     |         |       |
| fromuser          | char(64)     | NO   |     |         |       |
| authuser          | binary(0)    | YES  |     | NULL    |       |
| fromdomain        | char(64)     | NO   |     |         |       |
| mohinterpret      | char(64)     | NO   |     |         |       |
| mohsuggest        | char(64)     | NO   |     |         |       |
| insecure          | binary(0)    | YES  |     | NULL    |       |
| dtmfmode          | varchar(7)   | NO   |     |         |       |
| directmedia       | varchar(2)   | NO   |     |         |       |
| directrtpsetup    | varchar(3)   | NO   |     |         |       |
| disallow          | varchar(3)   | NO   |     |         |       |
| allow             | varchar(14)  | NO   |     |         |       |
| defaultip         | char(64)     | NO   |     |         |       |
| ipaddr            | char(64)     | NO   |     |         |       |
| port              | varchar(4)   | NO   |     |         |       |
| callbackextension | binary(0)    | YES  |     | NULL    |       |
| callcounter       | varchar(3)   | NO   |     |         |       |
| busylevel         | varchar(1)   | NO   |     |         |       |
| regseconds        | binary(0)    | YES  |     | NULL    |       |
+-------------------+--------------+------+-----+---------+-------+
29 rows in set (0.01 sec)
{noformat}

By: Dare Awktane (awktane) 2013-04-21 23:52:26.569-0500

We do not use sip users table but we do have most of the other tables in a mysql database which we connect through odbc. I checked a number of our log files for the past few days and we do not see this issue. I have seen disconnects in the past but it happens very rarely and it is almost always explainable (mysql server restart,etc). Out of curiosity would you mind posting both your /etc/asterisk/res_odbc.conf and your /etc/odbc.ini file (with any passwords,etc blanked out as necessary)? How busy is the database? How busy is the asterisk server? Does this happen during points of particularly high or low traffic? Any other information you can give us that might help narrow this down would be excellent. Without being able to reproduce it or some information that gives a direction it's almost impossible to help.
By: Michael L. Young (elguero) 2013-04-22 00:03:51.468-0500

Like Dare mentioned in his comment, you need to find out what is causing you to lose the connection.  That is something that should not be happening at all unless you are doing maintenance or something.  Otherwise, you should not be losing the connection.

What we actually need to help troubleshoot is a debug log.  Please follow this guide on how to get a complete debug for us:  https://wiki.asterisk.org/wiki/display/AST/Collecting+Debug+Information

Based on the snippet that you posted, it would like like Asterisk lost the connection to the database server and then was trying to reconnect but your snippet doesn't show if it succeeded or not.  A debug log would be very helpful.

By: Duane Larson (osiris123d) 2013-04-22 21:48:01.357-0500

I have uploaded the res_odbc and odbc.ini files.  These asterisk servers are not busy at all.  I have an OpenSIPS proxy server that sits in front of my Asterisk servers and it never loses its connection but maybe that is because OpenSIPS is never really idle when it comes to reading or writing to the database maybe?  I also have an OpenXCAP server that doesn't lose connectivity.  When I do a "show processlist;" within mysql I see that all my connections are good and persistent except for the mysql ones.  If I use the res_config_mysql module I don't lose my connection but I do run into a different issue for which I currently have a different trouble ticket open.  ASTERISK-21387

So if I use res_config_mysql my connectivity to the database is fine until I run into my deadlock issue.  I set my logging to debug and I only got this

[Apr 22 21:46:17] WARNING[24159][C-00000006] res_odbc.c: SetConnectAttr (Txn isolation) returned an error: HY000: [MySQL][ODBC 5.1 Driver]MySQL server has gone away
[Apr 22 21:46:17] WARNING[24159][C-00000006] res_odbc.c: SQL Execute returned an error -1: 08S01: [MySQL][ODBC 5.1 Driver][mysqld-5.1.42]MySQL server has gone away (65)
[Apr 22 21:46:17] WARNING[24159][C-00000006] res_odbc.c: SQL Execute error -1! Verifying connection to asterisk [MySQL-asterisk]...
[Apr 22 21:46:17] WARNING[24159][C-00000006] res_odbc.c: Connection is down attempting to reconnect...
[Apr 22 21:46:22] NOTICE[24159][C-00000006] res_odbc.c: Connecting asterisk
[Apr 22 21:46:22] NOTICE[24159][C-00000006] res_odbc.c: res_odbc: Connected to asterisk [MySQL-asterisk]
By: Dare Awktane (awktane) 2013-04-22 23:48:08.205-0500

Hmm very interesting. We have pretty much the same setup and we're not seeing the same issue. We get a sip connection by our sip proxy to make sure we're up. The extensions table is also realtime odbc and therefore I can see in the mysql show processlist that the connection time is reset to 0 occasionally by this process. I took a machine effectively offline by firewalling it from its trunk for about an hour and the connection maintained. When I dropped the firewall rule and allowed the call through to it I did not see a notice about reconnecting when a call came in.

Things I would try for fun:
1. Perhaps obvious but should be mentioned nonetheless - check to make sure you don't have a wait_timeout specified in the mysql server's my.cnf and also check the mysql error log for anything of interest. You could from the mysql cli ask for show variables like "%_timeout". Our wait_timeout is the mysql default which is 28800. A long time to go without any traffic.
2. Check the results of odbc show from the asterisk cli - does it think it's connected? Does this change?
3. Connection pooling - Likely of no use. Would still cause a delay because it still has to do the same steps if it loses a connection. Maybe worth a shot though nonetheless? Add a limit=5 under the database context and see what happens?

That's all I have. Hopefully someone with more knowledge than I comes along with a brilliant idea for you if those don't help.
By: Duane Larson (osiris123d) 2013-04-23 08:47:40.352-0500

MediaServer02*CLI> odbc show

ODBC DSN Settings
-----------------

 Name:   asterisk
 DSN:    MySQL-asterisk
   Last connection attempt: 1969-12-31 18:00:00
 Pooled: No
 Connected: Yes

[Apr 23 08:40:04] WARNING[12253]: res_odbc.c:761 ast_odbc_sanity_check: Connection is down attempting to reconnect...
[Apr 23 08:40:09] NOTICE[12253]: res_odbc.c:1527 odbc_obj_connect: Connecting asterisk
[Apr 23 08:40:10] NOTICE[12253]: res_odbc.c:1559 odbc_obj_connect: res_odbc: Connected to asterisk [MySQL-asterisk]


And here is what I saw in my debug logs

[Apr 23 08:40:04] WARNING[12253] res_odbc.c: Connection is down attempting to reconnect...
[Apr 23 08:40:09] DEBUG[12253] res_odbc.c: Disconnected 0 from asterisk [MySQL-asterisk]
[Apr 23 08:40:09] DEBUG[12253] res_odbc.c: Database handle 0x7fa184899eb0 deallocated
[Apr 23 08:40:09] NOTICE[12253] res_odbc.c: Connecting asterisk
[Apr 23 08:40:10] NOTICE[12253] res_odbc.c: res_odbc: Connected to asterisk [MySQL-asterisk]


I am using a hosted Database from http://xeround.com and I don't think I can change the wait_timeout variable in mysql via my.cnf.  The default value is
mysql> SHOW VARIABLES LIKE 'wait_timeout';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| wait_timeout  | 100   |
+---------------+-------+
1 row in set (0.00 sec)


I just added limit=5 just to see what happens.




By: Michael L. Young (elguero) 2013-04-23 09:18:22.100-0500

So, if I am understanding the debug snippet that you posted, it does look like Asterisk is working properly and reconnecting after it loses its connection.

I am not seeing that there is a bug in Asterisk.  It would appear that you would benefit from raising your issue on the asterisk-users mailing list (http://www.asterisk.org/community/discuss), since that would have a greater reach than perhaps the forum.  You need to be specific and mention that you are using a hosted database provider and that Asterisk is losing the connection to the hosted db to see if anyone has any suggestions on how to setup ODBC better to handle this setup.  Otherwise, I dont' think there is much more you can do with Asterisk since it relies on the odbc driver and its ability to be connected to the database server.

Therefore, I am going to close this out as not being a bug.  If you can gather some more evidence that shows this is a bug in Asterisk, then we can look at re-opening this issue.  You can contact any bug marshal (perhaps in IRC in #asterisk-bugs) who can do so.

Thanks
By: Duane Larson (osiris123d) 2013-04-23 10:05:18.750-0500

Thanks Michael.  I thought it just seemed odd that I would have this issue with odbc but not with res_config_mysql.  The database does reconnect on its own but there is a 1 or 2 second delay that is noticed by the callers.
By: Dare Awktane (awktane) 2013-04-23 13:18:28.224-0500

Agreed. Talk to you on asterisk-users! http://lists.digium.com/mailman/listinfo/asterisk-users