[MDEV-16827] UNIX_TIMESTAMP() not working properly during replication Created: 2018-07-25  Updated: 2018-08-03  Resolved: 2018-08-03

Status: Closed
Project: MariaDB Server
Component/s: Replication
Affects Version/s: 10.0.34-galera
Fix Version/s: N/A

Type: Bug Priority: Blocker
Reporter: Brian Kolaci Assignee: Unassigned
Resolution: Not a Bug Votes: 0
Labels: need_feedback
Environment:

Replicating from MySQL 5.0.75 to MariaDB 10.0.34

Linux diskstation2 3.10.102 #15266 SMP Mon Mar 26 15:08:11 CST 2018 x86_64 GNU/Linux synology_x86_1511+


 Description   

I've enabled replication on a Synology diskstation.
The slave has MariaDB 10.0.34. The master server is running MySQL 5.0.75.
I have other MySQL replication slaves running fine with MySQL 5.0.75.

Starting replication I get:

180725 10:52:58 [Note] Slave I/O thread: Start asynchronous replication to master 'repl@db1:3306' in log 'mysql-bin.001155' at position 132023098
 
180725 10:52:58 [Note] Slave SQL thread initialized, starting replication in log 'mysql-bin.001104' at position 146085705, relay log './backup-relay-bin.007368' position: 146085992
 
180725 10:52:58 [ERROR] Slave SQL: Error 'Column '_expire' cannot be null' on query. Default database: 'gp2'. Query: 'REPLACE INTO policyd.blacklist_sender (_blacklist, _description, _expire) VALUES ('%@001web.net', '# SA blacklist', UNIX_TIMESTAMP(NOW()+2000000))', Internal MariaDB error code: 1048
 
180725 10:52:58 [Warning] Slave: Incorrect datetime value: '20180532023001' Error_code: 1292
 
180725 10:52:58 [Warning] Slave: Column '_expire' cannot be null Error_code: 1048
 
180725 10:52:58 [Warning] Slave: Unknown error Error_code: 1105
 
180725 10:52:58 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'mysql-bin.001104' position 146085705
 
180725 10:52:58 [Note] Slave SQL thread exiting, replication stopped in log 'mysql-bin.001104' at position 146085705
 
180725 10:52:59 [Note] Slave I/O thread: connected to master 'repl@db1:3306',replication started in log 'mysql-bin.001155' at position 132023098

which indicates UNIX_TIMESTAMP(NOW()+2000000)) is returning NULL.

However, when I run in the client:

MariaDB [(none)]> select NOW(), NOW()+2000000, UNIX_TIMESTAMP(NOW()+2000000);
 
+---------------------+----------------+-------------------------------+
 
| NOW()               | NOW()+2000000  | UNIX_TIMESTAMP(NOW()+2000000) |
 
+---------------------+----------------+-------------------------------+
 
| 2018-07-25 11:28:24 | 20180727112824 |                    1532708904 |
 
+---------------------+----------------+-------------------------------+
 
1 row in set (0.00 sec)

I don't get NULL, I get an integer value, which is what the column is.
When I issue the exact SQL command as indicated in the error log, it succeeds:

MariaDB [policyd]> REPLACE INTO policyd.blacklist_sender (_blacklist, _description, _expire) VALUES ('%@001web.net', '# SA blacklist', UNIX_TIMESTAMP(NOW()+2000000));
 
Query OK, 2 rows affected (0.00 sec)



 Comments   
Comment by Elena Stepanova [ 2018-08-03 ]

UNIX_TIMESTAMP works as expected, you're getting NULL because of

Incorrect datetime value: '20180532023001'

which, indeed, is quite obviously incorrect. How you got May 32nd on the slave – that's the question.

Could you please quote the whole binlog event from the binary log (including variables which are set for the event)?

Comment by Brian Kolaci [ 2018-08-03 ]

Wow, I looked at this for quite awhile and didn't notice May 32nd. This software has been running in production for over 10 years, but didn't fail until Mariadb 10.0.

Looking at this I can definitely say its a bug in the policyd code, not the database code. Just amazing that its been working so long.

I'll close this and open a bug with them to fix the SQL code. It should be an easy fix. They should be using date math and not: UNIX_TIMESTAMP(NOW()+2000000) (which appears to try to add 2 days).

Comment by Brian Kolaci [ 2018-08-03 ]

Not sure how to close this. Thank you so much for pointing out something so obvious...

Generated at Thu Feb 08 08:31:51 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.