Duplicated MySQL RDS 5.7 error.log entries in CloudWatch

Hi! Thanks for reaching out.

With the information available here, I'd be interested to learn a few more details:

1. How are the logs being retrieved from CloudWatch? Directly in the log stream within the console, or by another method such as a GetLogEvents, FilterLogEvents, or possibly a Logs Insights query?

2. MySQL error log files are rotated every hour with the hour each file is generated appended to the file name in UTC. In this case, I note that the log file is appended with the date 2021-12-26.0 while the log entry timestamp is denoted as 2021-12-25T23:15:10.131859Z. Was this log entry also written in the error/mysql-error.log.2021-12-25.23 file as well, leading to the duplicate entries being seen in CloudWatch?

These details may help determine if the same log entry was written twice by RDS to two files between rotations, or if this may be a quirk with retrieving log entries from CloudWatch Logs.

Overall, it may be best to open a case with the RDS team via the case management system in order to work directly with an engineer to determine if error logs are being written as expected to the RDS error log files.

Overview of MySQL database logs - MySQL error logs - https://docs.aws.amazon.com/AmazonRDS/latest/UserGuide/USER_LogAccess.MySQL.LogFileSize.html#USER_LogAccess.MySQL.Errorlog

Hi Justin,

1. How are the logs being retrieved from CloudWatch? Directly in the log stream within the console,...

I am looking at the logs directly in the log stream within the console.

2. ...Was this log entry also written in the error/mysql-error.log.2021-12-25.23 file as well, leading to the duplicate entries being seen in CloudWatch?

No duplication observed in the mysql-error.log files. There were only two logs for 2021-12-26

error/mysql-error-running.log.2021-12-26.21	Sun Dec 26 2021 15:00:00 GMT-0500 177 B
error/mysql-error-running.log.2021-12-26.0	Sat Dec 25 2021 18:20:00 GMT-0500	2.7 kB

and five logs for 2021-12-25

error/mysql-error-running.log.2021-12-25.20	Sat Dec 25 2021 14:25:00 GMT-0500	177 B
error/mysql-error-running.log.2021-12-25.13	Sat Dec 25 2021 07:30:00 GMT-0500	528 B
error/mysql-error-running.log.2021-12-25.7	Sat Dec 25 2021 01:35:00 GMT-0500	494 B
error/mysql-error-running.log.2021-12-25.6	Sat Dec 25 2021 00:55:00 GMT-0500	516 B
error/mysql-error-running.log.2021-12-25.5	Fri Dec 24 2021 23:30:00 GMT-0500	13.3 kB

These details may help determine if the same log entry was written twice by RDS to two files between rotations, or if this may be a quirk with retrieving log entries from CloudWatch Logs.

I found one other case of duplication of the deadlock error.log entries in the CloudWatch Logs. Filtering for deadlock in the log stream within the console for the past two months shows repeated timestamps that happen on 2021-11-10:

2021-11-10T23:15:27.926126Z 200840 [Note] InnoDB: Transactions deadlock detected, dumping detailed information.
2021-11-10T23:15:27.926462Z 200906 [Note] InnoDB: Transactions deadlock detected, dumping detailed information.

repeated subsequently as

2021-11-10T23:15:27.926126Z 200840 [Note] InnoDB: Transactions deadlock detected, dumping detailed information.
2021-11-10T23:15:27.926462Z 200906 [Note] InnoDB: Transactions deadlock detected, dumping detailed information.

As on 2021-12-25, these duplicates happen at the last UTC hour of 2021-11-10. Other filtered out deadlock records were not duplicated.