Infrastructure at your Service

Elisa Usai

MySQL – Time mismatch between system and log files

I was working on MySQL upgrades to version 5.7 at a customer, when I found out that for my instance, time in the error log file didn’t correspond to local system time:

mysql@test1:/u01/app/mysql/admin/mysqld1/log/ [mysqld1] mysql -uroot -p
Enter password:
ERROR 1045 (28000): Access denied for user 'root'@'localhost' (using password: YES)

mysql@test1:/u01/app/mysql/admin/mysqld1/log/ [mysqld1] ls -ltr mysqld1.err
-rw-r-----. 1 mysql mysql 13323 Apr 12 10:54 mysqld1.err

mysql@test1:/u01/app/mysql/admin/mysqld1/log/ [mysqld1] tail -1 mysqld1.err
2018-04-12T08:54:55.300633Z 67 [Note] Access denied for user 'root'@'localhost' (using password: YES)

I performed the operation at 10h54 but in the error log file I saw 8h54.
I checked if there was a problem between system and instance time, but that was not the case:

mysql@test1:/u01/app/mysql/admin/mysqld1/log/ [mysqld1] date
Thu Apr 12 10:56:02 CEST 2018

mysqld1-(root@localhost) [(none)]> select now();
+---------------------+
| now()               |
+---------------------+
| 2018-04-12 10:56:35 |
+---------------------+
1 row in set (0.00 sec)

Actually, starting from version 5.7.2, there is a variable called log_timestamps which is set to UTC as default:

mysqld1-(root@localhost) [(none)]> select @@global.log_timestamps;
+-------------------------+
| @@global.log_timestamps |
+-------------------------+
| UTC                     |
+-------------------------+
1 row in set (0.00 sec)

I modified this variable from UTC to SYSTEM:

mysqld1-(root@localhost) [(none)]> set global log_timestamps='SYSTEM';
Query OK, 0 rows affected (0.00 sec)

mysqld1-(root@localhost) [(none)]> select @@global.log_timestamps;
+-------------------------+
| @@global.log_timestamps |
+-------------------------+
| SYSTEM                  |
+-------------------------+
1 row in set (0.00 sec)

and after that everything was OK, local system time was now aligned with timestamp time zone in MySQL log files:

mysql@test1:/u01/app/mysql/admin/mysqld1/log/ [mysqld1] mysql -uroot -p
Enter password:
ERROR 1045 (28000): Access denied for user 'root'@'localhost' (using password: YES)

mysql@test1:/u01/app/mysql/admin/mysqld1/log/ [mysqld1] ls -ltr mysqld1.err
-rw-r-----. 1 mysql mysql 13323 Apr 12 10:58 mysqld1.err

mysql@test1:/u01/app/mysql/admin/mysqld1/log/ [mysqld1] tail -1 mysqld1.err
2018-04-12T10:58:08.467615+01:00 69 [Note] Access denied for user 'root'@'localhost' (using password: YES)

Remember to set this variable also in the configuration file, to make this change persistent at reboot:

mysql@test1:/u01/app/mysql/admin/mysqld1/log/ [mysqld1] vi /etc/my.cnf

# 12042018 - dbi services - Timestamp time zone of log files from UTC (default) to SYSTEM
log_timestamps = SYSTEM
 

Leave a Reply

Elisa Usai
Elisa Usai