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)`
Best Answer
Please share me your end output. Example below.