UCP log MySQL server has gone away code 2006 error

duli · June 7, 2020, 2:57am

Hello, community.

FreePBX 15.0.16.53
Asterisk 16.9.0

I´m getting endless MySQL server connection errors in /var/log/asterisk/ucp_err.log:

2020-06-03 07:44 -03:00: { Error: MySQL server has gone away code: 2006 }
2020-06-03 07:44 -03:00: There was an error with MySQL Connection
2020-06-03 15:44 -03:00: { Error: MySQL server has gone away code: 2006 }
2020-06-03 15:44 -03:00: There was an error with MySQL Connection
2020-06-03 23:44 -03:00: { Error: MySQL server has gone away code: 2006 }
2020-06-03 23:44 -03:00: There was an error with MySQL Connection
2020-06-04 07:44 -03:00: { Error: MySQL server has gone away code: 2006 }
2020-06-04 07:44 -03:00: There was an error with MySQL Connection
2020-06-04 15:44 -03:00: { Error: MySQL server has gone away code: 2006 }
2020-06-04 15:44 -03:00: There was an error with MySQL Connection
2020-06-04 23:44 -03:00: { Error: MySQL server has gone away code: 2006 }
2020-06-04 23:44 -03:00: There was an error with MySQL Connection
2020-06-05 07:44 -03:00: { Error: MySQL server has gone away code: 2006 }
2020-06-05 07:44 -03:00: There was an error with MySQL Connection
2020-06-05 15:44 -03:00: { Error: MySQL server has gone away code: 2006 }
2020-06-05 15:44 -03:00: There was an error with MySQL Connection
2020-06-05 23:44 -03:00: { Error: MySQL server has gone away code: 2006 }
2020-06-05 23:44 -03:00: There was an error with MySQL Connection
2020-06-06 07:44 -03:00: { Error: MySQL server has gone away code: 2006 }
2020-06-06 07:44 -03:00: There was an error with MySQL Connection
2020-06-06 15:44 -03:00: { Error: MySQL server has gone away code: 2006 }
2020-06-06 15:44 -03:00: There was an error with MySQL Connection
2020-06-06 23:44 -03:00: { Error: MySQL server has gone away code: 2006 }
2020-06-06 23:44 -03:00: There was an error with MySQL Connection

But UCP and the system in general seems to be working just fine.

How can I further debug this?

Thank you.

dicko · June 7, 2020, 3:17am

Step 1) from a shell

systemctl status mariadb

duli · June 7, 2020, 3:10pm

Hello, dicko:

[root@freepbx ~]# systemctl status mariadb
● mariadb.service - MariaDB database server
   Loaded: loaded (/usr/lib/systemd/system/mariadb.service; enabled; vendor preset: disabled)
   Active: active (running) since Fri 2020-02-28 08:55:41 -03; 3 months 8 days ago
 Main PID: 1614 (mysqld_safe)
   CGroup: /system.slice/mariadb.service
           ├─1614 /bin/sh /usr/bin/mysqld_safe --basedir=/usr
           └─1776 /usr/libexec/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib64/...

Warning: Journal has been rotated since unit was started. Log output is incomplete or unavailable.

I´m pretty sure the database service is working ok. I can update settings in the admin panel and overall the system works just fine.

Under /var/log/mariadb I have only one log file:

[root@freepbx mariadb]# tail -n20 mariadb.log
200228  8:54:48  InnoDB: Shutdown completed; log sequence number 485785776182
200228  8:54:48 [Note] /usr/libexec/mysqld: Shutdown complete

200228 08:54:49 mysqld_safe mysqld from pid file /var/run/mariadb/mariadb.pid ended
200228 08:55:35 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
200228  8:55:36 [Note] /usr/libexec/mysqld (mysqld 5.5.60-MariaDB) starting as process 1776 ...
200228  8:55:37 InnoDB: The InnoDB memory heap is disabled
200228  8:55:37 InnoDB: Mutexes and rw_locks use GCC atomic builtins
200228  8:55:37 InnoDB: Compressed tables use zlib 1.2.7
200228  8:55:37 InnoDB: Using Linux native AIO
200228  8:55:37 InnoDB: Initializing buffer pool, size = 128.0M
200228  8:55:37 InnoDB: Completed initialization of buffer pool
200228  8:55:37 InnoDB: highest supported file format is Barracuda.
200228  8:55:39  InnoDB: Waiting for the background threads to start
200228  8:55:40 Percona XtraDB (http://www.percona.com) 5.5.59-MariaDB-38.11 started; log sequence number 485785776182
200228  8:55:40 [Note] Plugin 'FEEDBACK' is disabled.
200228  8:55:40 [Note] Server socket created on IP: '0.0.0.0'.
200228  8:55:41 [Note] Event Scheduler: Loaded 0 events
200228  8:55:41 [Note] /usr/libexec/mysqld: ready for connections.
Version: '5.5.60-MariaDB'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MariaDB Server

It appears some cron job related to UCP is running always at 07:44 and 23:44 and at those times the error messages pop up.

Thanks a lot.

dicko · June 7, 2020, 3:45pm

Step 2

crontab -l -u asterisk
crontab -l -u root

duli · June 7, 2020, 4:25pm

[root@freepbx ~]# crontab -l -u asterisk
@daily  [ -e /var/www/html/admin/modules/sysadmin/bin/check_portal.php ] && /var/www/html/admin/modules/sysadmin/bin/check_portal.php >/dev/null 2>&1
@daily  [ -x /var/lib/asterisk/agi-bin/ddns_client.php ] && /var/lib/asterisk/agi-bin/ddns_client.php >/dev/null 2>&1
@hourly  [ -x /var/lib/asterisk/bin/storage.php ] && /var/lib/asterisk/bin/storage.php >/dev/null 2>&1
*/15 * * * * [ -e /etc/asterisk/firewall.enabled ] && touch /var/spool/asterisk/incron/firewall.firewall
0 12 1 * * /usr/sbin/fwconsole backup --backup=50e127b6-6e88-4f4c-adff-f25bf4e371eb > /dev/null 2>&1
0 22 * * * /usr/sbin/fwconsole backup --backup=adf7f10b-bd1c-41ae-b6ac-1c8ca0c5b75d > /dev/null 2>&1
58 1 * * * /usr/sbin/fwconsole certificates --updateall -q 2>&1 >/dev/null
* 0 * * * /usr/sbin/fwconsole util cleanplaybackcache -q
59 5 * * 6 [ -e /usr/sbin/fwconsole ] && /usr/sbin/fwconsole ma listonline --sendemail -q > /dev/null 2>&1
59 6 * * 6 [ -e /usr/sbin/fwconsole ] && /usr/sbin/fwconsole sys listonline --sendemail -q > /dev/null 2>&1
* * * * * [ -e /usr/sbin/fwconsole ] && sleep $((RANDOM\%30)) && /usr/sbin/fwconsole job --run --quiet 2>&1 > /dev/null
[root@freepbx ~]# crontab -l -u root

[root@freepbx ~]#

dicko · June 7, 2020, 4:30pm

As you can see it’s neither root nor asterisk running that process, please expand on why you mention 7:44 and 23:44

duli · June 7, 2020, 5:13pm

Sorry, actually, it´s 07:44, 15:44 and 23:44, as it appears in the ucp_err.log:

2020-06-01 15:44 -03:00: There was an error with MySQL Connection
2020-06-01 23:44 -03:00: { Error: MySQL server has gone away code: 2006 }
2020-06-01 23:44 -03:00: There was an error with MySQL Connection
2020-06-02 07:44 -03:00: { Error: MySQL server has gone away code: 2006 }
2020-06-02 07:44 -03:00: There was an error with MySQL Connection
2020-06-02 15:44 -03:00: { Error: MySQL server has gone away code: 2006 }
2020-06-02 15:44 -03:00: There was an error with MySQL Connection
2020-06-02 23:44 -03:00: { Error: MySQL server has gone away code: 2006 }
2020-06-02 23:44 -03:00: There was an error with MySQL Connection
2020-06-03 07:44 -03:00: { Error: MySQL server has gone away code: 2006 }
2020-06-03 07:44 -03:00: There was an error with MySQL Connection
2020-06-03 15:44 -03:00: { Error: MySQL server has gone away code: 2006 }
2020-06-03 15:44 -03:00: There was an error with MySQL Connection
2020-06-03 23:44 -03:00: { Error: MySQL server has gone away code: 2006 }
2020-06-03 23:44 -03:00: There was an error with MySQL Connection
2020-06-04 07:44 -03:00: { Error: MySQL server has gone away code: 2006 }
2020-06-04 07:44 -03:00: There was an error with MySQL Connection
2020-06-04 15:44 -03:00: { Error: MySQL server has gone away code: 2006 }
2020-06-04 15:44 -03:00: There was an error with MySQL Connection
2020-06-04 23:44 -03:00: { Error: MySQL server has gone away code: 2006 }
2020-06-04 23:44 -03:00: There was an error with MySQL Connection
2020-06-05 07:44 -03:00: { Error: MySQL server has gone away code: 2006 }
2020-06-05 07:44 -03:00: There was an error with MySQL Connection
2020-06-05 15:44 -03:00: { Error: MySQL server has gone away code: 2006 }
2020-06-05 15:44 -03:00: There was an error with MySQL Connection
2020-06-05 23:44 -03:00: { Error: MySQL server has gone away code: 2006 }
2020-06-05 23:44 -03:00: There was an error with MySQL Connection
2020-06-06 07:44 -03:00: { Error: MySQL server has gone away code: 2006 }
2020-06-06 07:44 -03:00: There was an error with MySQL Connection
2020-06-06 15:44 -03:00: { Error: MySQL server has gone away code: 2006 }
2020-06-06 15:44 -03:00: There was an error with MySQL Connection
2020-06-06 23:44 -03:00: { Error: MySQL server has gone away code: 2006 }
2020-06-06 23:44 -03:00: There was an error with MySQL Connection
2020-06-07 07:44 -03:00: { Error: MySQL server has gone away code: 2006 }
2020-06-07 07:44 -03:00: There was an error with MySQL Connection

I´m not sure it´s a cronjob, but it does not appear to be caused by user interaction, due to the precision of minutes and hours it is repeated.

dicko · June 7, 2020, 11:08pm

No, sorry, nothing more from me, just a guess

what does

node -v

return ?

duli · June 8, 2020, 11:39pm

It´s:

[root@freepbx ~]# node -v
v8.11.3

The messages keep comming:

2020-06-08 03:13 -03:00: { Error: MySQL server has gone away code: 2006 }
2020-06-08 03:13 -03:00: There was an error with MySQL Connection
2020-06-08 11:13 -03:00: { Error: MySQL server has gone away code: 2006 }
2020-06-08 11:13 -03:00: There was an error with MySQL Connection
2020-06-08 19:13 -03:00: { Error: MySQL server has gone away code: 2006 }
2020-06-08 19:13 -03:00: There was an error with MySQL Connection

And now I just realized they appear on a nother box as well.

2020-06-08 03:42 -03:00: { Error: MySQL server has gone away code: 2006 }
2020-06-08 03:42 -03:00: There was an error with MySQL Connection
2020-06-08 11:52 -03:00: { Error: MySQL server has gone away code: 2006 }
2020-06-08 11:52 -03:00: There was an error with MySQL Connection
2020-06-08 20:01 -03:00: { Error: MySQL server has gone away code: 2006 }
2020-06-08 20:01 -03:00: There was an error with MySQL Connection

I guess I should open a bug ticket. I can´t think of anything else for these weird log messages.

Thank you.

cynjut · June 9, 2020, 1:39pm

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

This is MySQL’s answer to your request. They have a couple of suggestions. Can you see if you can try these and check to see if it fixes the problem?

duli · June 10, 2020, 1:06am

Hello, @cynjut. Thanks for the input.

I´ve installed a fresh SNG7-FPBX-64bit-2002-2 on a VM and after a day powered on, I got the same messages in the log:

2020-06-09 07:40 +00:00: { Error: MySQL server has gone away code: 2006 }
There was an error with MySQL Connection
2020-06-09 15:40 +00:00: { Error: MySQL server has gone away code: 2006 }
There was an error with MySQL Connection
2020-06-09 23:40 +00:00: { Error: MySQL server has gone away code: 2006 }
There was an error with MySQL Connection

Looking at the documentation you posted, indeed it appears to be the server closing the connection after eight hours of nothing happening:

By default, the server closes the connection after eight hours if nothing has happened. You can change the time limit by setting the wait_timeout variable when you start mysqld . See Section 5.1.8, “Server System Variables”.

That´s why I guess each log message is yielded every eight hours.

And yes, the wait_time variable is set to eight hours in the machine (28800 seconds):

[root@freepbx ~]# mysqladmin variables | grep -i wait_timeout
| innodb_lock_wait_timeout                          | 50                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                  |
| lock_wait_timeout                                 | 31536000                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                            |
| wait_timeout                                      | 28800                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                               |

The server has been up without any crash:

[root@freepbx ~]# mysqladmin version
mysqladmin  Ver 9.0 Distrib 5.5.60-MariaDB, for Linux on x86_64
Copyright (c) 2000, 2018, Oracle, MariaDB Corporation Ab and others.

Server version          5.5.60-MariaDB
Protocol version        10
Connection              Localhost via UNIX socket
UNIX socket             /var/lib/mysql/mysql.sock
Uptime:                 1 day 1 hour 21 min 3 sec

So I guess it really is a matter of the connection getting automatically closed due to no queries being made.

The solution proposed by the documentation is “to issue the query again for the client to do an automatic reconnection.”

But I don´t know which client is making the connection in the first place. What UCP script is making a connection?

Do you think increasing the wait_time variable would be the right away of getting rid of these error messages on a low usage system?

Thanks!

duli · June 13, 2020, 3:57pm

I´ve created an issue on bug tracker.

system · July 14, 2020, 3:57pm

This topic was automatically closed 31 days after the last reply. New replies are no longer allowed.