[Home]

Summary:ASTERISK-28956: res_odbc: ODBC connection does not always reconnect
Reporter:Luke Escude (lukeescude)Labels:
Date Opened:2020-06-20 09:32:38Date Closed:2020-06-30 04:01:59
Priority:MajorRegression?
Status:Closed/CompleteComponents:CDR/cdr_adaptive_odbc
Versions:16.8.0 Frequency of
Occurrence
Related
Issues:
Environment:CentOS 7 x64Attachments:
Description:So I am not too sure how to diagnose this one, but I've seen it happen too many times to not report it.

Environment: Our Asterisk instances use an ODBC connection for CDR (adaptive_odbc) as well as an ODBC connection for Voicemail. The DSNs for each of these is separate, since they point to separate MySQL servers.

Failure Scenario: A SQL server goes down for some X minutes. During those X minutes, all Asterisk instances that are supposed to connect to that particular one are aware of the issue, and odbc show will indicate as such. This is expected behavior, and happens for both the Voicemail ODBC and the CDR ODBC connection.

Recovery Scenario: When a Voicemail SQL server comes back up, ALL Asterisk instances see it and reconnect. This is expected. However, when the CDR SQL server comes back up, only a majority of Asterisk instances reconnect. The remaining ones will say 1 out of 1 (meaning ODBC is connected) but will not log CDR at all until performing a module reload res_adaptive_odbc command. Some of them will still say 0 out of 1, indicating the connection is indeed dead, but they never attempt to reconnect.

While the issue is happening, are there any other useful commands I can run to assist it diagnosing this? I don't want to have to restart asterisk since obviously that will fix it.

Comments:By: Asterisk Team (asteriskteam) 2020-06-20 09:32:40.411-0500

Thanks for creating a report! The issue has entered the triage process. That means the issue will wait in this status until a Bug Marshal has an opportunity to review the issue. Once the issue has been reviewed you will receive comments regarding the next steps towards resolution.

A good first step is for you to review the [Asterisk Issue Guidelines|https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines] if you haven't already. The guidelines detail what is expected from an Asterisk issue report.

Then, if you are submitting a patch, please review the [Patch Contribution Process|https://wiki.asterisk.org/wiki/display/AST/Patch+Contribution+Process].

Please note that once your issue enters an open state it has been accepted. As Asterisk is an open source project there is no guarantee or timeframe on when your issue will be looked into. If you need expedient resolution you will need to find and pay a suitable developer. Asking for an update on your issue will not yield any progress on it and will not result in a response. All updates are posted to the issue when they occur.
By: Kevin Harwell (kharwell) 2020-06-22 11:56:55.612-0500

In Asterisk you could try to enable debugging level 3 on the relevant modules to see if it turns anything up. Please post the logs after an occurrence:
{noformat}
*CLI> core set debug 3 res_odbc.so
{noformat}
{noformat}
core set debug 3 cdr
{noformat}
I'd also suggest you enable tracing logging in ODBC itself. Note, however this could potentially create large log files. You should be able to do this by modifying your [odbcinst.ini file|http://www.unixodbc.org/odbcinst.html]. For example:
{quote}
[MySQL-test]
Trace               = Yes
TraceFile           = sql.log
{quote}
By: Luke Escude (lukeescude) 2020-06-29 11:40:23.227-0500

Hello,

Well it appears this happens to the Voicemail ODBC connection as well... The only output I get is the following:

Jun 29 16:34:03] DEBUG[20439]: res_odbc.c:974 _ast_odbc_request_obj2: Reusing ODBC handle 0x7fe9d8000c60 from class 'sql'
[Jun 29 16:34:03] DEBUG[20439]: res_odbc.c:817 ast_odbc_release_obj: Releasing ODBC handle 0x7fe9d8000c60 into pool
[Jun 29 16:34:03] DEBUG[20439]: res_odbc.c:974 _ast_odbc_request_obj2: Reusing ODBC handle 0x7fe9d8000c60 from class 'sql'
[Jun 29 16:34:03] DEBUG[20439]: res_odbc.c:817 ast_odbc_release_obj: Releasing ODBC handle 0x7fe9d8000c60 into pool
[Jun 29 16:34:03] DEBUG[20439]: res_odbc.c:974 _ast_odbc_request_obj2: Reusing ODBC handle 0x7fe9d8000c60 from class 'sql'
[Jun 29 16:34:04] DEBUG[20439]: res_odbc.c:817 ast_odbc_release_obj: Releasing ODBC handle 0x7fe9d8000c60 into pool
[Jun 29 16:34:04] DEBUG[20439]: res_odbc.c:974 _ast_odbc_request_obj2: Reusing ODBC handle 0x7fe9d8000c60 from class 'sql'
[Jun 29 16:34:04] DEBUG[20439]: res_odbc.c:817 ast_odbc_release_obj: Releasing ODBC handle 0x7fe9d8000c60 into pool
[Jun 29 16:34:04] DEBUG[20439]: res_odbc.c:974 _ast_odbc_request_obj2: Reusing ODBC handle 0x7fe9d8000c60 from class 'sql'
[Jun 29 16:34:04] DEBUG[20439]: res_odbc.c:817 ast_odbc_release_obj: Releasing ODBC handle 0x7fe9d8000c60 into pool
[Jun 29 16:34:04] DEBUG[20439]: res_odbc.c:974 _ast_odbc_request_obj2: Reusing ODBC handle 0x7fe9d8000c60 from class 'sql'
[Jun 29 16:34:04] DEBUG[20439]: res_odbc.c:817 ast_odbc_release_obj: Releasing ODBC handle 0x7fe9d8000c60 into pool
[Jun 29 16:34:04] DEBUG[20439]: res_odbc.c:974 _ast_odbc_request_obj2: Reusing ODBC handle 0x7fe9d8000c60 from class 'sql'
[Jun 29 16:34:04] DEBUG[20439]: res_odbc.c:817 ast_odbc_release_obj: Releasing ODBC handle 0x7fe9d8000c60 into pool


Could there be an error in how I have odbc.ini set up:

[sql]
Driver=MySQL
Driver64=MySQL
Server=SERVERADDR
UserName=USER
Password=PASSWORD
readtimeout=1
Database=DB

[vmsql]
Driver=MySQL
Driver64=MySQL
Server=SERVERADDR
UserName=USER
Password=PASSWORD
readtimeout=1
Database=DB

I think "readtimeout" helps with preventing dial plan from hanging if the SQL connection is down.

res_odbc.conf:

[sql]
enabled => yes
dsn => sql
username => USER
password => PASSWORD
pre-connect => yes
connect_timeout => 1

[vmodbc]
enabled => yes
dsn => vmsql
username => USER
password => PASSWORD
pre-connect => yes
connect_timeout => 1

Here I believe connect_timeout should allow the connection to continue re-attempting if it ever goes down.
By: Luke Escude (lukeescude) 2020-06-29 11:46:35.499-0500

Okay so, today's case may not have been ODBC...
[Jun 29 16:43:20] WARNING[20911][C-0000001c]: app.c:2212 ast_lock_path_lockfile: Failed to lock path '/var/spool/asterisk/voicemail/voicemail/103/Old': File exists
[Jun 29 16:43:20] ERROR[20911][C-0000001c]: app_voicemail.c:9225 open_mailbox: Could not open mailbox /var/spool/asterisk/voicemail/voicemail/103/Old:  mailbox is locked

Removed the lockfile and that fixed it.
By: Joshua C. Colp (jcolp) 2020-06-29 11:54:04.707-0500

Nothing stands out in your configuration or the debug. Did you enable MySQL tracing like [~kharwell] mentioned?

As well the connection timeout is passed into UnixODBC, so I believe it ultimately depends on how exactly the underlying UnixODBC and connector deal with it. We're also dependent on the connector itself for connecting. Our usage of UnixODBC itself is fairly simple in that regards, it does the bulk of the work. What connector are you using?
By: Luke Escude (lukeescude) 2020-06-29 12:01:13.158-0500

I haven't yet... If your implementation of unixODBC is fairly simple, then I'm wondering if it's the version of unixODBC that automatically ships with CentOS 7.

This appears to be what was compiled:

mysql-connector-odbc.x86_64                   5.2.5-8.el7               @base
By: Luke Escude (lukeescude) 2020-06-29 12:04:27.122-0500

I'm wondering if it would be better to use MariaDB's implementation: https://mariadb.com/kb/en/about-mariadb-connector-odbc/

Since our system uses MariaDB as the SQL servers.
By: Joshua C. Colp (jcolp) 2020-06-29 12:06:05.550-0500

I've seen numerous issues with the MySQL connector. Crashes, sockets getting hung/blocked. People have had considerably better luck with the MariaDB connector instead. In fact, I updated the guide online[1] to use the MariaDB one instead with a recommendation not to use the MySQL connector.

[1] https://wiki.asterisk.org/wiki/display/AST/Getting+Asterisk+Connected+to+MySQL+via+ODBC
By: Luke Escude (lukeescude) 2020-06-29 12:09:00.195-0500

Yep you certainly did. I didn't think to check the documentation, since we had implemented the ODBC stuff a couple years ago and I assumed it probably hadn't changed much.

Let's go ahead and consider this issue resolved, unless you guys want to keep it open and want to have me verify that using the MariaDB connector indeed resolves it.

Your call - by the way I highly appreciate the assistance.
By: Joshua C. Colp (jcolp) 2020-06-29 12:27:53.217-0500

I'll suspend this for now. If things continue even after switching, you can comment and it will reopen.
By: Luke Escude (lukeescude) 2020-06-29 15:24:09.379-0500

Joshua, is there a way to disable the lockfile the voicemail spool folders? Since it's using ODBC, I don't think it's really necessary to have that.

Apparently if the SQL server goes down for a bit during a voicemail transaction, the lockfile will remain, preventing further access until I manually remove it.

I'm thinking about creating a cronjob every morning at 3am to wipe out all lockfiles in voicemail but this might do more harm than good.
By: Asterisk Team (asteriskteam) 2020-06-29 15:24:10.124-0500

This issue has been reopened as a result of your commenting on it as the reporter. It will be triaged once again as applicable.
By: Joshua C. Colp (jcolp) 2020-06-30 04:01:59.080-0500

There is no ability to disable lock files. It's built into the way that app_voicemail is written.