0

I have a MySQL 5.7.22 server that I'm having a problem enabling the bin log for. As far as I can tell from my reading, I have the proper configuration to enable bin logs, but they're never created anywhere on the server. My OS is Ubuntu 16.04.5 LTS with all patches up to date as of a few days ago.

Here is my configuration, comments stripped out:

[mysqld_safe]
socket      = /var/run/mysqld/mysqld.sock
nice        = 0

[mysqld]
user        = mysql
pid-file    = /var/run/mysqld/mysqld.pid
socket      = /var/run/mysqld/mysqld.sock
port        = 3306
basedir     = /usr
datadir     = /var/lib/mysql
tmpdir      = /tmp
lc-messages-dir = /usr/share/mysql
skip-external-locking
bind-address        = 0.0.0.0
key_buffer_size     = 16M
max_allowed_packet  = 16M
thread_stack        = 192K
thread_cache_size       = 8
myisam-recover-options  = BACKUP
query_cache_limit   = 1M
query_cache_size        = 16M
log_error = /var/log/mysql/error.log
server-id       = 1
log_bin         = /var/log/mysql/mysql-bin.log
expire_logs_days    = 10
max_binlog_size   = 100M
innodb_strict_mode = 0
innodb_log_file_size = 512M
innodb_log_buffer_size = 800M
innodb_file_format = Barracuda

Here is the folder where the logs should be written, included here to show (hopefully) correct permissions:

ll /var/log/mysql
total 116
drwxr-s---  2 mysql adm     4096 Jul 23 18:51 ./
drwxrwxr-x 24 root  syslog 12288 Jul 23 19:08 ../
-rw-r-----  1 mysql adm    14622 Jul 23 19:17 error.log
-rw-r-----  1 mysql adm       20 Jul 22 06:25 error.log.1.gz
-rw-r-----  1 mysql adm       20 Jul 21 06:25 error.log.2.gz
-rw-r-----  1 mysql adm       20 Jul 20 06:25 error.log.3.gz
-rw-r-----  1 mysql adm       20 Jul 19 06:25 error.log.4.gz
-rw-r-----  1 mysql adm       20 Jul 18 06:25 error.log.5.gz
-rw-r-----  1 mysql adm       20 Jul 17 06:25 error.log.6.gz
-rw-r-----  1 mysql adm       20 Jul 16 06:25 error.log.7.gz
-rw-r-----  1 mysql adm        0 Jul 23 06:25 general-query.log
-rw-r-----  1 mysql adm       20 Jul 22 06:25 general-query.log.1.gz
-rw-r-----  1 mysql adm       20 Jul 21 06:25 general-query.log.2.gz
-rw-r-----  1 mysql adm       20 Jul 20 06:25 general-query.log.3.gz
-rw-r-----  1 mysql adm       20 Jul 19 06:25 general-query.log.4.gz
-rw-r-----  1 mysql adm       20 Jul 18 06:25 general-query.log.5.gz
-rw-r-----  1 mysql adm       20 Jul 17 06:25 general-query.log.6.gz
-rw-r-----  1 mysql adm       20 Jul 16 06:25 general-query.log.7.gz
-rw-r-----  1 mysql adm        0 Jul 23 06:25 slow-query.log
-rw-r-----  1 mysql adm       20 Jul 22 06:25 slow-query.log.1.gz
-rw-r-----  1 mysql adm       20 Jul 21 06:25 slow-query.log.2.gz
-rw-r-----  1 mysql adm       20 Jul 20 06:25 slow-query.log.3.gz
-rw-r-----  1 mysql adm       20 Jul 19 06:25 slow-query.log.4.gz
-rw-r-----  1 mysql adm       20 Jul 18 06:25 slow-query.log.5.gz
-rw-r-----  1 mysql adm       20 Jul 17 06:25 slow-query.log.6.gz
-rw-r-----  1 mysql adm       20 Jul 16 06:25 slow-query.log.7.gz

You'll see that other logs from the config file have been properly written as of this morning (Jul 23 2018), so that seems like it would rule out permissions as a cause of this problem.

Lastly, I'm including syslog entries that appear when I restart MySQL. There's one line in particular that may or may not be related to this problem, so I wanted to include it.

Jul 23 20:12:40 servername systemd[1]: Starting MySQL Community Server...
Jul 23 20:12:40 servername kernel: [1554544.315682] audit: type=1400 audit(1532391160.325:191): apparmor="DENIED" operation="open" profile="/usr/sbin/mysqld" name="/proc/61396/status" pid=61396 comm="mysqld" requested_mask="r" denied_mask="r" fsuid=106 ouid=106
Jul 23 20:12:40 servername kernel: [1554544.320121] audit: type=1400 audit(1532391160.333:192): apparmor="DENIED" operation="open" profile="/usr/sbin/mysqld" name="/sys/devices/system/node/" pid=61396 comm="mysqld" requested_mask="r" denied_mask="r" fsuid=106 ouid=0
Jul 23 20:12:40 servername kernel: [1554544.323791] audit: type=1400 audit(1532391160.333:193): apparmor="DENIED" operation="open" profile="/usr/sbin/mysqld" name="/proc/61396/status" pid=61396 comm="mysqld" requested_mask="r" denied_mask="r" fsuid=106 ouid=106
Jul 23 20:12:40 servername kernel: [1554544.499446] audit: type=1400 audit(1532391160.509:194): apparmor="DENIED" operation="open" profile="/usr/sbin/mysqld" name="/proc/61411/status" pid=61411 comm="mysqld" requested_mask="r" denied_mask="r" fsuid=33 ouid=33
Jul 23 20:12:40 servername kernel: [1554544.504121] audit: type=1400 audit(1532391160.517:195): apparmor="DENIED" operation="open" profile="/usr/sbin/mysqld" name="/sys/devices/system/node/" pid=61411 comm="mysqld" requested_mask="r" denied_mask="r" fsuid=33 ouid=0
Jul 23 20:12:40 servername kernel: [1554544.504342] audit: type=1400 audit(1532391160.517:196): apparmor="DENIED" operation="open" profile="/usr/sbin/mysqld" name="/proc/61411/status" pid=61411 comm="mysqld" requested_mask="r" denied_mask="r" fsuid=33 ouid=33
Jul 23 20:12:40 servername mysqld[61396]: 2018-07-24T00:12:40.341787Z 0 [Warning] Changed limits: max_open_files: 1024 (requested 5000)
Jul 23 20:12:40 servername mysqld[61396]: 2018-07-24T00:12:40.341876Z 0 [Warning] Changed limits: table_open_cache: 431 (requested 2000)
Jul 23 20:12:40 servername mysqld[61396]: 2018-07-24T00:12:40.575763Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
Jul 23 20:12:40 servername mysqld[61396]: 2018-07-24T00:12:40.578797Z 0 [Note] /usr/sbin/mysqld (mysqld 5.7.22-0ubuntu0.16.04.1) starting as process 61396 ...
Jul 23 20:12:40 servername mysqld[61396]: 2018-07-24T00:12:40.585237Z 0 [Note] InnoDB: PUNCH HOLE support available
Jul 23 20:12:40 servername mysqld[61396]: 2018-07-24T00:12:40.585731Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
Jul 23 20:12:40 servername mysqld[61396]: 2018-07-24T00:12:40.586180Z 0 [Note] InnoDB: Uses event mutexes
Jul 23 20:12:40 servername mysqld[61396]: 2018-07-24T00:12:40.586199Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
Jul 23 20:12:40 servername mysqld[61396]: 2018-07-24T00:12:40.586216Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.8
Jul 23 20:12:40 servername mysqld[61396]: 2018-07-24T00:12:40.586223Z 0 [Note] InnoDB: Using Linux native AIO
Jul 23 20:12:40 servername mysqld[61396]: 2018-07-24T00:12:40.586668Z 0 [Note] InnoDB: Number of pools: 1
Jul 23 20:12:40 servername mysqld[61396]: 2018-07-24T00:12:40.586858Z 0 [Note] InnoDB: Using CPU crc32 instructions
Jul 23 20:12:40 servername mysqld[61396]: 2018-07-24T00:12:40.592103Z 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
Jul 23 20:12:40 servername mysqld[61396]: 2018-07-24T00:12:40.606427Z 0 [Note] InnoDB: Completed initialization of buffer pool
Jul 23 20:12:40 servername mysqld[61396]: 2018-07-24T00:12:40.610373Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
Jul 23 20:12:40 servername mysqld[61396]: 2018-07-24T00:12:40.674303Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
Jul 23 20:12:41 servername mysqld[61396]: 2018-07-24T00:12:41.074725Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
Jul 23 20:12:41 servername mysqld[61396]: 2018-07-24T00:12:41.075824Z 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
Jul 23 20:12:41 servername mysqld[61396]: 2018-07-24T00:12:41.103852Z 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
Jul 23 20:12:41 servername mysqld[61396]: 2018-07-24T00:12:41.106228Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
Jul 23 20:12:41 servername mysqld[61396]: 2018-07-24T00:12:41.106812Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
Jul 23 20:12:41 servername mysqld[61396]: 2018-07-24T00:12:41.107813Z 0 [Note] InnoDB: Waiting for purge to start
Jul 23 20:12:41 servername mysqld[61396]: 2018-07-24T00:12:41.158566Z 0 [Note] InnoDB: 5.7.22 started; log sequence number 9047719533
Jul 23 20:12:41 servername mysqld[61396]: 2018-07-24T00:12:41.158927Z 0 [Note] Plugin 'FEDERATED' is disabled.
Jul 23 20:12:41 servername mysqld[61396]: 2018-07-24T00:12:41.163763Z 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
Jul 23 20:12:41 servername mysqld[61396]: 2018-07-24T00:12:41.174954Z 0 [Warning] Failed to set up SSL because of the following SSL library error: SSL context is not usable without certificate and private key
Jul 23 20:12:41 servername mysqld[61396]: 2018-07-24T00:12:41.176327Z 0 [Note] Server hostname (bind-address): '*'; port: 3306
Jul 23 20:12:41 servername mysqld[61396]: 2018-07-24T00:12:41.176959Z 0 [Note] IPv6 is available.
Jul 23 20:12:41 servername mysqld[61396]: 2018-07-24T00:12:41.177504Z 0 [Note]   - '::' resolves to '::';
Jul 23 20:12:41 servername mysqld[61396]: 2018-07-24T00:12:41.178084Z 0 [Note] Server socket created on IP: '::'.
Jul 23 20:12:41 servername mysqld[61396]: 2018-07-24T00:12:41.297940Z 0 [Note] Event Scheduler: Loaded 0 events
Jul 23 20:12:41 servername mysqld[61396]: 2018-07-24T00:12:41.298812Z 0 [Note] /usr/sbin/mysqld: ready for connections.
Jul 23 20:12:41 servername mysqld[61396]: Version: '5.7.22-0ubuntu0.16.04.1'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  (Ubuntu)
=====>Jul 23 20:12:41 servername mysqld[61396]: 2018-07-24T00:12:41.351040Z 2  [Note] Access denied for user 'root'@'localhost' (using password: NO)
Jul 23 20:12:41 servername systemd[1]: Started MySQL Community Server.
Jul 23 20:12:41 servername mysqld[61396]: 2018-07-24T00:12:41.718190Z 0 [Note] InnoDB: Buffer pool(s) load completed at 180723 20:12:41

On the 41st line, indicated by the arrow, something is attempting to login as root without using a password. I have no idea what or why. As I said, it may be unrelated to my bin log issue.

Any help is greatly appreciated.

Added in response to Kernelv5's request below:

Here's the output from MySQL showing bin log status:

`mysql> show variables like "%log_bin%";
+---------------------------------+-------+
| Variable_name                   | Value |
+---------------------------------+-------+
| log_bin                         | OFF   |
| log_bin_basename                |       |
| log_bin_index                   |       |
| log_bin_trust_function_creators | OFF   |
| log_bin_use_v1_row_events       | OFF   |
| sql_log_bin                     | ON    |
+---------------------------------+-------+
6 rows in set (0.00 sec)`
0

Please share me your end output. Example below.

mysql> show variables like "%log_bin%";
+---------------------------------+--------------------------------+
| Variable_name                   | Value                          |
+---------------------------------+--------------------------------+
| log_bin                         | ON                             |
| log_bin_basename                | /var/lib/mysql/mysql-bin       |
| log_bin_index                   | /var/lib/mysql/mysql-bin.index |
| log_bin_trust_function_creators | OFF                            |
| log_bin_use_v1_row_events       | OFF                            |
| sql_log_bin                     | ON                             |
+---------------------------------+--------------------------------+
6 rows in set (0.00 sec)
3
  • I added the output you requested to the original question. – Aaron Adams Jul 25 '18 at 4:17
  • I don’t see any issue from your configuration, In this situation, you may give a common check. 1. Ensure it's reading you're my.cnf file mysqld --verbose --help | grep -A 1 "Default options" 2. Instead of log_bin use log-bin, some version has this issue. – Kernelv5 Jul 25 '18 at 10:14
  • Thanks for your help. I know mysqld is reading options from /etc/mysql/my.cnf, which has an include statement that picks up /etc/mysql/mysql.conf.d/mysqld.conf. If I were to change the path for the error logs, for example, that would be reflected in mysql> show variables like '%log%';. In other words, MySQL is correctly parsing configuration files. I also changed the line in my config to log-bin without any result. – Aaron Adams Jul 25 '18 at 12:47
0

I ended up having to remove and reinstall MySQL. I have no idea what caused this issue, but a clean install fixed it.

apt remove -y mysql-*
apt purge -y mysql-*
apt install -y mysql-server
mysql_secure_installation

During the purge, I believe, you'll be asked if you want to delete your databases in /var/lib/mysql. I said no, but I made a backup copy just in case. Then I changed the config to be identical to the one posted in the original question and it worked.

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.