Page 2 - Intermittent can't connect to mysql socket

Oh, I know the error numbers and their meanings by heart

Kidding. Those are actually error numbers from the operating system, not MySQL (whose numbers tend to be >1000). I was looking at this list.

thanks for the link to the codes. That will come in very handy.

I just remembered (and re-tested using a dev server), that we have a Zabbix box that will alert me if mysql is not running, so mysql was still running during these episodes.

More info... There's nothing in the MySQL error log pointing to an issue during the episodes. Te episode yesterday was at 16:36, so I restarted MySQL. There was a second instance at 18:10. There are no entries in between:

130102 16:36:54 InnoDB: Starting shutdown...
130102 16:36:56 InnoDB: Shutdown completed; log sequence number 86958942
130102 16:36:56 [Note] /usr/sbin/mysqld: Shutdown complete
130102 16:36:56 [Note] Plugin 'FEDERATED' is disabled.
130102 16:36:56 InnoDB: The InnoDB memory heap is disabled
130102 16:36:56 InnoDB: Mutexes and rw_locks use GCC atomic builtins
130102 16:36:56 InnoDB: Compressed tables use zlib 1.2.3.4
130102 16:36:56 InnoDB: Initializing buffer pool, size = 16.0M
130102 16:36:56 InnoDB: Completed initialization of buffer pool
130102 16:36:56 InnoDB: highest supported file format is Barracuda.
130102 16:36:56 InnoDB: Waiting for the background threads to start
130102 16:36:57 InnoDB: 1.1.8 started; log sequence number 86958942
130102 16:36:57 [Note] Server hostname (bind-address): '0.0.0.0'; port: 3306
130102 16:36:57 [Note] - '0.0.0.0' resolves to '0.0.0.0';
130102 16:36:57 [Note] Server socket created on IP: '0.0.0.0'.
130102 16:36:57 [Note] Event Scheduler: Loaded 0 events
130102 16:36:57 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.5.28-0ubuntu0.12.04.3-log' socket: '/var/run/mysqld/mysqld.sock' port: 3306 (Ubuntu)
130102 16:37:52 [Note] Start binlog_dump to slave_server(2), pos(mysql-bin.001195, 1715160)
130102 18:10:44 [Note] /usr/sbin/mysqld: Normal shutdown
130102 18:10:44 [Note] Event Scheduler: Purging the queue. 0 events
130102 18:10:46 [Warning] /usr/sbin/mysqld: Forcing close of thread 8572 user: 'etherpad'
130102 18:10:46 [Warning] /usr/sbin/mysqld: Forcing close of thread 8571 user: 'etherpad'
130102 18:10:46 [Warning] /usr/sbin/mysqld: Forcing close of thread 8570 user: 'etherpad'
130102 18:10:46 [Warning] /usr/sbin/mysqld: Forcing close of thread 2612 user: 'openmeetings'
130102 18:10:46 [Warning] /usr/sbin/mysqld: Forcing close of thread 2611 user: 'openmeetings'
130102 18:10:46 InnoDB: Starting shutdown...
130102 18:10:47 InnoDB: Shutdown completed; log sequence number 86984114
130102 18:10:47 [Note] /usr/sbin/mysqld: Shutdown complete
130102 18:10:47 [Note] Plugin 'FEDERATED' is disabled.
130102 18:10:47 InnoDB: The InnoDB memory heap is disabled
130102 18:10:47 InnoDB: Mutexes and rw_locks use GCC atomic builtins
130102 18:10:47 InnoDB: Compressed tables use zlib 1.2.3.4
130102 18:10:47 InnoDB: Initializing buffer pool, size = 16.0M
130102 18:10:47 InnoDB: Completed initialization of buffer pool
130102 18:10:48 InnoDB: highest supported file format is Barracuda.
130102 18:10:48 InnoDB: Waiting for the background threads to start
130102 18:10:49 InnoDB: 1.1.8 started; log sequence number 86984114
130102 18:10:49 [Note] Server hostname (bind-address): '0.0.0.0'; port: 3306
130102 18:10:49 [Note] - '0.0.0.0' resolves to '0.0.0.0';
130102 18:10:49 [Note] Server socket created on IP: '0.0.0.0'.
130102 18:10:49 [Note] Event Scheduler: Loaded 0 events
130102 18:10:49 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.5.28-0ubuntu0.12.04.3-log' socket: '/var/run/mysqld/mysqld.sock' port: 3306 (Ubuntu)
130102 18:11:44 [Note] Start binlog_dump to slave_server(2), pos(mysql-bin.001196, 25606276)



For a first time, however, I did see a couple of entries in the error log when there wasn't an episode. These entries only appeared last night, though:

130102 18:31:46 [Warning] Aborted connection 2824 to db: 'openmeetings' user: 'openmeetings' host: 'localhost' (Got an error reading communication packets)
130102 18:31:46 [Warning] Aborted connection 2826 to db: 'openmeetings' user: 'openmeetings' host: 'localhost' (Got an error reading communication packets)
130103 1:10:03 [Warning] Aborted connection 163224 to db: 'openmeetings' user: 'openmeetings' host: 'localhost' (Got an error reading communication packets)
130103 1:10:03 [Warning] Aborted connection 14759 to db: 'openmeetings' user: 'openmeetings' host: 'localhost' (Got an error reading communication packets)

There were no entries last night other than those four.

I checked Zabbix for excess network traffic on that server that would represent a DDOS attack, but there was nothing out of the ordinary.

just for kicks, I enabled the general query log on that server. If this happens again, I'll look there for clues. A quick scan shows that most if not all connections get closed. I know the main part of the LMS code does close connections. Perhaps the ancillary bits that don't use the LMS connection code don't.

--UPDATE: some of the other bits were not explicitly closing the db connection. I fixed that.

well...the logging is working fine, but I didn't realize that you had to restart MySQL to get timestamps in the log. Too bad, too. The issue came up twice last night (1AM and 3:30 AM).

-- on closer inspection, the timestamps are in there. I just didn't see them.

well, it just happened again. The mysqld process was still running. The logs seem to indicate that it's just Apache/PHP that can't connect. I have OpenMeetings on the same server and, duyring the previous incident, OpenMeetings could connect fine, but Apache couldn't. This is shown by the fact that the only queries in the log for the period in question came from the OpenMeetings scheduler service. I stopped red5 (and thus OpenMeetings) earlier today, but the issue happened again just now. I though it may have been the OpenMeetings queries that were the culprit, as the were setting autocommit to 0 and back to 1. Apparently, it's something else. I didn't think to try swapping 127.0.0.1 for localhost. Not sure if it would make a difference, as the bind_address is commented out in my./cnf for replication purposes.

The 127.0.0.1 should force a connection over TCP instead of through the socket. If that works then it suggests there's something with the socket, otherwise something with PHP.

aha...I'll definitely give that a try.

Thanks again!

I've got a frequently called ajax script set to try localhost and then email me and try 127.0.0.1 if localhost won't connect. If 127.0.0.1 won't connect, I'll get a second email. We'll see what happens.

I do think it's an issue with the socket, given the errors. How could a socket go bad? Is it something that I'd need to refresh periodically?

turns out that it's more than likely break-in attempts. I installed Splunk to be able to look at the logs in a more manageable way and found entries like this in auth.log:

Jan 2 18:05:11 wgudev mysqld[26927]: refused connect from 218.2.75.154
Jan 2 18:06:11 mysqld[26927]: last message repeated 9 times
Jan 2 18:07:11 mysqld[26927]: last message repeated 11 times
Jan 2 18:08:11 mysqld[26927]: last message repeated 12 times
Jan 2 18:08:40 mysqld[26927]: last message repeated 6 times

I don't understand how the remote users are getting to the point where mysqld is denying them. My hosts.deny denies all to all and and hosts.allow only grants 4 IP addresses mysqld access. Any ideas?

Thanks again,
Mike

as it turns out, hosts.deny/allow only control access to services started buy inetd (on Ubuntu at least), so I have to use IPTABLES to block all and allow the specific IPs I want.

I moved this to the MySQL forum and then figured it out. It was hackers trying to connect to my db over port 306, which is open for the slave db to connect. I thought hosts.allow/deny controlled all access, but it's only those services started buy inetd. MySQL is not started by inetd, so I used IPTALES to allow the handful of IPs that need to connect to mysql and rejected the rest. Hope this summary will help someone else. Thanks to all who looked and responded.

Yep, with strict IPTABLES in place, no more entries in auth.log for hackers trying to get to the db.

Thanks for the help, requinix!

Mike