BUG SQL errors after FreePBX 2.11 upgrade

[mcbsys]

Upgraded FreePBX from 2.10 to 2.11 over the weekend. Everything seems to be working fine but once a day, I'm getting a series of messages in the log complaining about a SQL error:

[2014-03-04 05:28:31] VERBOSE[1955] netsock2.c:  == Using SIP RTP TOS bits 184
[2014-03-04 05:28:31] VERBOSE[1955] netsock2.c:  == Using SIP RTP CoS mark 5
[2014-03-04 05:28:31] WARNING[1924] res_odbc.c: SetConnectAttr (Txn isolation) returned an error: HY000: [MySQL][ODBC 5.1 Driver]MySQL server has gone away
[2014-03-04 05:28:31] WARNING[1924] res_odbc.c: SQL Execute returned an error -1: 08S01: [MySQL][ODBC 5.1 Driver][mysqld-5.1.61]MySQL server has gone away (65)
[2014-03-04 05:28:31] WARNING[1924] res_odbc.c: SQL Execute error -1! Verifying connection to asteriskcdrdb [MySQL-asteriskcdrdb]...
[2014-03-04 05:28:31] WARNING[1924] res_odbc.c: Connection is down attempting to reconnect...
[2014-03-04 05:28:31] VERBOSE[31850] pbx.c:    -- Executing [8885551212@from-trunk:1] NoOp("SIP/losangeles2.voip.ms-00000010", "Catch-All DID Match - Found 8885551212 - You probably want a DID for this.") in new stack
[2014-03-04 05:28:31] DEBUG[1924] res_odbc.c: Disconnected 0 from asteriskcdrdb [MySQL-asteriskcdrdb]
[2014-03-04 05:28:31] DEBUG[1924] res_odbc.c: Database handle 0xb7402b28 deallocated
[2014-03-04 05:28:31] NOTICE[1924] res_odbc.c: Connecting asteriskcdrdb

I haven't figured out yet what is even triggering this daily re-connection. What is in asteriskcdrdb? Do I have a misconfiguration?

 

[wardmundy]

Please open a ticket on the FreePBX site. They've moved their CDR stuff away from MySQL if I'm not mistaken.

 

[mcbsys]

Ah, I remember now: CDR = Call Detail Records. The CDR report looks fine.

This FreePBX thread is reporting a CDR issue (which I don't seem to have) but his log also shows the SQL disconnect.

Is this normal with FreePBX 2.11?

Here are my other config details:

│ PIAF Installed Version = 2.0.6.2 under *HARDWARE* │
│ FreePBX Version = 2.11.0.24 │
│ Running Asterisk Version = 1.8.11-cert2 │
│ Asterisk Source Version = 1.8.11-cert2 │
│ Dahdi Source Version = 2.6.1+2.6.1 │
│ Libpri Source Version = 1.4.12 │
│ Operating System = CentOS release 6.2 (Final) │
│ Kernel Version = 2.6.32-220.17.1.el6.i686 - 32 Bit │

 

[mcbsys]

Okay I've posted to the FreeBPX forum:

freepbx.org/forum/general-help/sql-errors-after-freepbx-211-upgrade

http://community.freepbx.org/t/sql-errors-after-freepbx-2-11-upgrade/21216/14

 

[wardmundy]

Thanks, lgaetz. Incredible PBX systems have ODBC configured but it may not work as is. Will someone please try it. We're still unpacking boxes.

ODBC wasn't enabled by default with stock PIAF systems. We will push it out ASAP.

The safest setup should probably look like this:

[MySQL-asteriskcdrdb]
Description    = asteriskcdrdb MySQL ODBC
Driver          = MySQL
Socket          = /var/lib/mysql/mysql.sock
Server          = localhost
User            = asteriskuser
Password        = amp109
Port            = 3306
Database        = asteriskcdrdb
Option          = 3

Complete ODBC setup tutorial is available on Nerd Vittles.

 

[mcbsys]

lgaetz, re. your proposed odbc.ini, probably the Description should indicate that it is for connecting to "asteriskcdrdb', not 'asterisk'. More importantly, I'm confused about the password line:

• The odbc.ini in my PiaF Brown install (which already had ODBC configured) uses "passw0rd", which is not the asteriskcdrdb password.
• tm1000 at the FreePBX forum says it needs to be "amp109", which is the asteriskcdrdb password.
• Your example doesn't include password at all?

The other thing I don't get is why my CDR reports are working (with current data) if ODBC is a problem. I can even see in the log that it connects to asteriskcdrdb after the initial failed attempt:

[2014-03-10 09:04:21] VERBOSE[1955] netsock2.c:  == Using SIP RTP TOS bits 184
[2014-03-10 09:04:21] VERBOSE[1955] netsock2.c:  == Using SIP RTP CoS mark 5
[2014-03-10 09:04:21] WARNING[1924] res_odbc.c: SetConnectAttr (Txn isolation) returned an error: HY000: [MySQL][ODBC 5.1 Driver]MySQL server has gone away
[2014-03-10 09:04:21] WARNING[1924] res_odbc.c: SQL Execute returned an error -1: 08S01: [MySQL][ODBC 5.1 Driver][mysqld-5.1.61]MySQL server has gone away (65)
[2014-03-10 09:04:21] WARNING[1924] res_odbc.c: SQL Execute error -1! Verifying connection to asteriskcdrdb [MySQL-asteriskcdrdb]...
[2014-03-10 09:04:21] WARNING[1924] res_odbc.c: Connection is down attempting to reconnect...
[2014-03-10 09:04:21] DEBUG[1924] res_odbc.c: Disconnected 0 from asteriskcdrdb [MySQL-asteriskcdrdb]
[2014-03-10 09:04:21] DEBUG[1924] res_odbc.c: Database handle 0xb74147d8 deallocated
[2014-03-10 09:04:21] NOTICE[1924] res_odbc.c: Connecting asteriskcdrdb
[2014-03-10 09:04:21] VERBOSE[25682] pbx.c:    -- Executing [*97@from-internal:1] Answer("SIP/101-00000066", "") in new stack
[2014-03-10 09:04:21] NOTICE[1924] res_odbc.c: res_odbc: Connected to asteriskcdrdb [MySQL-asteriskcdrdb]

 

[mcbsys]

Oops I just noticed why the passwords differ. My PiaF Brown has this section in etc/odbc.ini:

[MySQL-asteriskcdrdb]
Description    = asteriskcdrdb MySQL ODBC
Driver          = MySQL
Socket          = /var/lib/mysql/mysql.sock
Server          = localhost
User            = root
Password        = passw0rd
Database        = asteriskcdrdb
Option          = 3

"passw0rd" is correct for user "root". However if it wants to connect with user "asteriskuser", the password is "amp109".

So my config actually has a working section, which makes me wonder whether the "MySQL server has gone away" warnings really have anything to do with the ODBC configuration. Maybe it's normal for it to "lose" the connection after a period of inactivity, then have to re-connect?

 

[mcbsys]

But if you click one of the uniqueid links in the 'system' column, you will get a blank screen.

When I click on an event in the CDR report, I get a full list of events (CHAN_START, ANSWER, BRIDGE_START, etc.).

So with your config, FreePBX attempts to connect using asteriskuser which understandably fails, and then attempts to connect with the root user defined in odbc.ini which succeeds.

I can connect manually (using isql) as root/passw0rd or asteriskuser/amp109. So both users are defined. According to res_odbc_additional.conf, it should supply both the user and password (asteriskuser/amp109).

etc/asterisk/res_odbc_additional.conf

[asteriskcdrdb]
enabled=>yes
dsn=>MySQL-asteriskcdrdb
pooling=>no
limit=>1
pre-connect=>yes
username=>asteriskuser
password=>amp109

Looking at my log, I don't think it is falling back to the odbc.ini user/password. It's just complaining that it got disconnected, then it's reconnecting, probably using the definition in res_odbc_additional.conf.

I think this has now diverged into two issues:

1. Some PiaF systems do not have ODBC configured. That will need to be added. I would go with Andrew's and lgaetz's suggestion to omit the user and password from odbc.ini and let res_odbc_additional.conf supply them. Specifying user/passoword in multiple places leads to confusion about which one is being used.

2. FreePBX sometimes loses its ODBC connection to asteriskcdrdb and needs to reconnect. This is the issue I'm seeing. Still unclear is whether this is "normal" and I should just ignore the daily warnings.

 

[mcbsys]

lgaetz, I appreciate the interaction; it's helped me understand what is (and isn't) happening. I think I triggered this whole tangent by not noticing the "Connected to asteriskcdrdb [MySQL-asteriskcdrdb]" line that probably followed the first log I posted, which would have clarified that my ODBC has been working all along. I'll be interested if you see the disconnects--so far I haven't found any documentation on whether ODBC connections time out by design. Maybe the 3am backup disconnects the database? It does seem that the re-connection happens once each day, the first time a user makes a call.

 

[Trimline2]

I see the same issue every morning. As soon as the first call is made, there is no longer an error. This occurs on two new systems that were recently installed.

[2014-09-19 04:40:30] VERBOSE[14436] asterisk.c:     -- Remote UNIX connection disconnected
[2014-09-19 07:26:55] VERBOSE[2188][C-00000071] netsock2.c:   == Using SIP RTP TOS bits 184
[2014-09-19 07:26:55] VERBOSE[2188][C-00000071] netsock2.c:   == Using SIP RTP CoS mark 5
[2014-09-19 07:26:55] WARNING[1900] res_odbc.c: SetConnectAttr (Txn isolation) returned an error: HY000: [MySQL][ODBC 5.1 Driver]MySQL server has gone away
[2014-09-19 07:26:55] VERBOSE[18151][C-00000071] pbx.c:     -- Executing [XXXX@from-internal:1] NoOp("SIP/479701-000000f4" in new stack
[2014-09-19 07:26:55] WARNING[1900] res_odbc.c: SQL Execute returned an error -1: 08S01: [MySQL][ODBC 5.1 Driver][mysqld-5.1.73]MySQL server has gone away (6
5)
[2014-09-19 07:26:55] WARNING[1900] res_odbc.c: SQL Execute error -1! Verifying connection to asteriskcdrdb [MySQL-asteriskcdrdb]...
[2014-09-19 07:26:55] WARNING[1900] res_odbc.c: Connection is down attempting to reconnect...
[2014-09-19 07:26:55] NOTICE[1900] res_odbc.c: Connecting asteriskcdrdb

 

[netintegrity]

Just adding this post for others that may be concerned about this issue....

https://dev.mysql.com/doc/refman/5.0/en/gone-away.html

It appears after 8 hours of no operation, the database connection times out (by design). Once the first call (mentioned by Trimline2) comes in it forces a reconnect. No call is lost....just these log entries that most of us have not seen before the chaneover to ODBC....

 

[mcbsys]

netintegrity, thanks for that confirmation and the link to the MySQL article.

I'm going to try adding a wait_timeout in /etc/my.cnf set to 7 days to see if it suppresses those annoying daily messages:

wait_timeout=604800

wait_timeout documentation: https://dev.mysql.com/doc/refman/5.0/en/server-system-variables.html#sysvar_wait_timeout

 

[mcbsys]

I can confirm that increasing the MySQL wait_timeout as described in my previous post does in fact eliminate the daily "MySQL server has gone away" messages. This makes my daily logwatch email easier to read.