Bug #1372501 “INSERT with NOW() gives incorrect timestamp” : Bugs : Percona Server moved to https://jira.percona.com/projects/PS

Revision history for this message

Valerii Kravchuk (valerii-kravchuk) wrote on 2014-09-22:

#1

Thank you for the problem report. Please, share the exact C code that is used to connect to MySQL server in your application.

Had you tried to run the same application over Percona Server (not Percona XtraDB Cluster) or upstream MySQL Server 5.6.20?

Changed in percona-server:
status:	New → Incomplete

Valerii Kravchuk (valerii-kravchuk) on 2014-09-23

Changed in percona-xtradb-cluster:
status:	New → Incomplete

Revision history for this message

Bram Matthys (syzop) wrote on 2014-09-23:

#2

I'm afraid I can't share the source of the C program. But.. it can't be the C program right? As the query is sent as "NOW()" over the wire? Or?

The issue happened only once so far, so I don't really have more details than what I already shared. Don't know it can be reproduced on official mysqld, and don't know if it happens in a non-cluster environment.

If you feel this makes the bug report kinda worthless, then feel free to close the issue. I just wanted to report it right away, see if anyone else has seen this before, it's very weird after all.

Thanks for your time.

Revision history for this message

Launchpad Janitor (janitor) wrote on 2014-11-23:

#3

[Expired for Percona XtraDB Cluster because there has been no activity for 60 days.]

Changed in percona-xtradb-cluster:
status:	Incomplete → Expired

Revision history for this message

Launchpad Janitor (janitor) wrote on 2014-11-23:

#4

[Expired for Percona Server because there has been no activity for 60 days.]

Changed in percona-server:
status:	Incomplete → Expired

Revision history for this message

Jose Cavieres (jcavieres) wrote on 2015-05-12:

#5

We are seing the same problem a few times a week in our "MariaDB Galera Cluster 10.0.17" in two different tables.
The only thing both of them have in common is that there's a TRIGGER associated with INSERTs in them.

Don't hesitate to ask any file o log required to solve the problem.

Revision history for this message

Valerii Kravchuk (valerii-kravchuk) wrote on 2015-05-12:

#6

So, Jose, can you provide any repeatable test case that demonstrates the problem in a clean environment?

Changed in percona-xtradb-cluster:
status:	Expired → New
status:	New → Incomplete

Revision history for this message

Jose Cavieres (jcavieres) wrote on 2015-05-14:

#7

Download full text (5.0 KiB)

Valerii, we are trying to create the test case, but the incorrect timestamp problem only happens once every few days in a heavy load system.
In the meantime, we have some more information :

1) The affected table is the only one in the schema with a trigger defined for it:

CREATE TABLE `estadisticos_ws` (
  `id` bigint(20) NOT NULL AUTO_INCREMENT,
  `tx` char(20) NOT NULL,
  `msisdn` bigint(20) NOT NULL,
  `nodo` smallint(6) NOT NULL,
  `stamp` timestamp NOT NULL DEFAULT '0000-00-00 00:00:00',
  `duracion` smallint(6) NOT NULL,
  `error` int(11) NOT NULL,
  `wsid` smallint(6) NOT NULL DEFAULT '0',
  PRIMARY KEY (`id`,`stamp`),
  KEY `msisdn` (`msisdn`),
  KEY `stamp` (`stamp`)
) ENGINE=InnoDB AUTO_INCREMENT=4546612238 DEFAULT CHARSET=latin1
/*!50100 PARTITION BY RANGE ( UNIX_TIMESTAMP( stamp ))
(PARTITION p1428465600 VALUES LESS THAN (1428465600) ENGINE = InnoDB,
PARTITION p1429070400 VALUES LESS THAN (1429070400) ENGINE = InnoDB,
PARTITION p1429675200 VALUES LESS THAN (1429675200) ENGINE = InnoDB,
PARTITION p1430280000 VALUES LESS THAN (1430280000) ENGINE = InnoDB,
PARTITION p1430884800 VALUES LESS THAN (1430884800) ENGINE = InnoDB,
PARTITION p1431489600 VALUES LESS THAN (1431489600) ENGINE = InnoDB,
PARTITION p1432094400 VALUES LESS THAN (1432094400) ENGINE = InnoDB)

show triggers\G
*************************** 1. row ***************************
             Trigger: estadisticos_ws_trg
               Event: INSERT
               Table: estadisticos_ws
           Statement: BEGIN
    INSERT INTO contadores_ws ( `nodo`, `stamp`, `wsid`, `error`, `contador` ) VALUES ( NEW.nodo, STR_TO_DATE( DATE_FORMAT( NEW.stamp, "%Y/%m/%d %H:%i:00" ), "%Y/%m/%d %H:%i:%s" ) , NEW.wsid, NEW.error, 1 ) ON DUPLICATE KEY UPDATE contador = contador + 1, stamp = VALUES( stamp );
    INSERT INTO estadisticos_ws_sec ( wsid, stamp, valor ) VALUES (new.wsid, new.stamp, 1) ON DUPLICATE KEY UPDATE valor=valor+1;
END
              Timing: AFTER
             Created: NULL
            sql_mode:
             Definer: root@localhost
character_set_client: latin1
collation_connection: latin1_swedish_ci
  Database Collation: latin1_swedish_ci

CREATE TABLE `contadores_ws` (
  `nodo` smallint(6) NOT NULL,
  `stamp` timestamp NOT NULL DEFAULT '0000-00-00 00:00:00',
  `error` int(11) NOT NULL,
  `contador` int(11) NOT NULL,
  `wsid` smallint(6) NOT NULL DEFAULT '0',
  PRIMARY KEY (`nodo`,`stamp`,`wsid`,`error`),
  KEY `stamp` (`stamp`,`nodo`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1

2) The only querys sent to that table have the structure:

SELECT id into @a FROM servicios where nombre IN ('WS_ValidaEstado', 'unknown') ORDER BY id DESC LIMIT 1;INSERT INTO estadisticos_ws ( tx, msisdn, nodo, stamp, duracion, wsid, error ) VALUES ('0xc70748a05bb2', 56988659040,47, now(), 1, @a, 0);

3) If the certification errors are logged and before the problem happens, the following is logged for EVERY such query in the galera node receiving the query (we are sure the query is received only once):

150513 20:49:31 [Note] WSREP: cluster conflict due to certification failure for threads:
150513 20:49:31 [Note] WSREP: Victim thread:
THD: 2450210, mode: local, state: executing, conflict...

Valerii, we are trying to create the test case, but the incorrect timestamp problem only happens once every few days in a heavy load system. 
In the meantime, we have some more information :

1) The affected table is the only one in the schema with a trigger defined for it:

CREATE TABLE `estadisticos_ws` (
  `id` bigint(20) NOT NULL AUTO_INCREMENT,
  `tx` char(20) NOT NULL,
  `msisdn` bigint(20) NOT NULL,
  `nodo` smallint(6) NOT NULL,
  `stamp` timestamp NOT NULL DEFAULT '0000-00-00 00:00:00',
  `duracion` smallint(6) NOT NULL,
  `error` int(11) NOT NULL,
  `wsid` smallint(6) NOT NULL DEFAULT '0',
  PRIMARY KEY (`id`,`stamp`),
  KEY `msisdn` (`msisdn`),
  KEY `stamp` (`stamp`)
) ENGINE=InnoDB AUTO_INCREMENT=4546612238 DEFAULT CHARSET=latin1
/*!50100 PARTITION BY RANGE ( UNIX_TIMESTAMP( stamp ))
(PARTITION p1428465600 VALUES LESS THAN (1428465600) ENGINE = InnoDB,
 PARTITION p1429070400 VALUES LESS THAN (1429070400) ENGINE = InnoDB,
 PARTITION p1429675200 VALUES LESS THAN (1429675200) ENGINE = InnoDB,
 PARTITION p1430280000 VALUES LESS THAN (1430280000) ENGINE = InnoDB,
 PARTITION p1430884800 VALUES LESS THAN (1430884800) ENGINE = InnoDB,
 PARTITION p1431489600 VALUES LESS THAN (1431489600) ENGINE = InnoDB,
 PARTITION p1432094400 VALUES LESS THAN (1432094400) ENGINE = InnoDB)

show triggers\G
*************************** 1. row ***************************
             Trigger: estadisticos_ws_trg
               Event: INSERT
               Table: estadisticos_ws
           Statement: BEGIN
    INSERT INTO contadores_ws ( `nodo`, `stamp`, `wsid`, `error`, `contador` ) VALUES ( NEW.nodo,  STR_TO_DATE( DATE_FORMAT( NEW.stamp, "%Y/%m/%d %H:%i:00" ), "%Y/%m/%d %H:%i:%s" ) , NEW.wsid, NEW.error, 1 ) ON DUPLICATE KEY UPDATE contador = contador + 1, stamp = VALUES( stamp );
    INSERT INTO estadisticos_ws_sec ( wsid, stamp, valor ) VALUES (new.wsid, new.stamp, 1) ON DUPLICATE KEY UPDATE valor=valor+1;
END
              Timing: AFTER
             Created: NULL
            sql_mode: 
             Definer: root@localhost
character_set_client: latin1
collation_connection: latin1_swedish_ci
  Database Collation: latin1_swedish_ci

CREATE TABLE `contadores_ws` (
  `nodo` smallint(6) NOT NULL,
  `stamp` timestamp NOT NULL DEFAULT '0000-00-00 00:00:00',
  `error` int(11) NOT NULL,
  `contador` int(11) NOT NULL,
  `wsid` smallint(6) NOT NULL DEFAULT '0',
  PRIMARY KEY (`nodo`,`stamp`,`wsid`,`error`),
  KEY `stamp` (`stamp`,`nodo`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1

2) The only querys sent to that table have the structure:

SELECT id into @a FROM servicios where nombre IN ('WS_ValidaEstado', 'unknown') ORDER BY id DESC LIMIT 1;INSERT INTO estadisticos_ws ( tx, msisdn, nodo, stamp, duracion, wsid, error ) VALUES ('0xc70748a05bb2', 56988659040,47, now(), 1, @a, 0);

3) If the certification errors are logged and before the problem happens, the following is logged for EVERY such query in the galera node receiving the query (we are sure the query is received only once):

150513 20:49:31 [Note] WSREP: cluster conflict due to certification failure for threads:
150513 20:49:31 [Note] WSREP: Victim thread: 
   THD: 2450210, mode: local, state: executing, conflict: cert failure, seqno: 48653922
   SQL: INSERT INTO estadisticos_ws ( tx, msisdn, nodo, stamp, duracion, wsid, error ) VALUES ('0xdd0702c6b758', 56953876137,47, now(), 48, @a, 0)

*** Priority TRANSACTION:
TRANSACTION 100254405, ACTIVE 0 sec starting index read
mysql tables in use 20, locked 20
2 lock struct(s), heap size 360, 0 row lock(s), undo log entries 1
MySQL thread id 7, OS thread handle 0x7f0cec92b700, query id 108515295 Update_rows_log_event::find_row(48653921)

*** Victim TRANSACTION:
TRANSACTION 100254404, ACTIVE 0 sec rollback
mysql tables in use 20, locked 20
ROLLING BACK 5 lock struct(s), heap size 1184, 2 row lock(s)
MySQL thread id 2450210, OS thread handle 0x7f0b8abb6700, query id 108515290 192.168.111.58 ws_user query end
INSERT INTO estadisticos_ws ( tx, msisdn, nodo, stamp, duracion, wsid, error ) VALUES ('0xdd0702c6b758', 56953876137,47, now(), 48, @a, 0)
*** WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 11 page no 165638 n bits 168 index `PRIMARY` of table `WSDB`.`contadores_ws` trx table locks 3 total table locks 2  trx id 100254404 lock_mode X locks rec but not gap lock hold time 0 wait time before grant 0 
150513 20:49:31 [Note] WSREP: cluster conflict due to high priority abort for threads:
150513 20:49:31 [Note] WSREP: Winning thread: 
   THD: 7, mode: applier, state: executing, conflict: no conflict, seqno: 48653921
   SQL: (null)
150513 20:49:31 [Note] WSREP: Victim thread: 
   THD: 2450210, mode: local, state: executing, conflict: cert failure, seqno: -1
   SQL: INSERT INTO estadisticos_ws ( tx, msisdn, nodo, stamp, duracion, wsid, error ) VALUES ('0xdd0702c6b758', 56953876137,47, now(), 48, @a, 0)

4) After the problem happens nothing else is logged until the client application is restarted

The certification error in 3) shouldn't happen, so we believe is related to the fixed timestamp problem

Valerii Kravchuk (valerii-kravchuk) on 2015-05-14

Changed in percona-xtradb-cluster:
status:	Incomplete → New
Changed in percona-server:
status:	Expired → New

Revision history for this message

Muhammad Irfan (muhammad-irfan) wrote on 2015-05-19:

#8

Can you please provide my.cnf file from one of the cluster node. Also provide output of

mysql> SHOW GLOBAL VARIABLES LIKE '%version%';

Changed in percona-xtradb-cluster:
status:	New → Incomplete

Revision history for this message

Jose Cavieres (jcavieres) wrote on 2015-05-19:

#9

Download full text (5.5 KiB)

[root@basedatos-d ~]# more /etc/my.cnf
[MYSQLD]
user=mysql
basedir=/usr/
datadir=/Data/mysql
tmpdir=/Data/mysql/tmp
socket=/var/lib/mysql/mysql.sock
pid_file=mysqld.pid
port=3306
log_error=/var/log/mysqld.log
log_warnings=2
#log_output=FILE
### INNODB OPTIONS
innodb_buffer_pool_size=5000M
innodb_flush_log_at_trx_commit=2
innodb_file_per_table=1
innodb_data_file_path = ibdata1:100M:autoextend
## You may want to tune the below depending on number of cores and disk sub
innodb_read_io_threads=4
innodb_write_io_threads=4
innodb_io_capacity=200
innodb_doublewrite=1
innodb_log_file_size=512M
innodb_log_buffer_size=64M
innodb_buffer_pool_instances=4
innodb_log_files_in_group=2
innodb_thread_concurrency=64
#innodb_file_format=barracuda
innodb_flush_method = O_DIRECT
innodb_autoinc_lock_mode=2
## avoid statistics update when doing e.g show tables
innodb_stats_on_metadata=0
default_storage_engine=innodb
# CHARACTER SET
#collation_server = utf8_unicode_ci
#init_connect='SET NAMES utf8'
#character_set_server = utf8
event_scheduler=ON
# REPLICATION SPECIFIC
#server_id must be unique across all mysql servers participating in replication.
#server_id=SERVERID
binlog_format=ROW
#log_slave_updates=1
#log_bin=binlog
#relay_log=relay-bin
#expire_logs_days=7
#gtid_mode=ON
#enforce_gtid_consistency=1
# OTHER THINGS, BUFFERS ETC
key_buffer_size = 24M
tmp_table_size = 64M
max_heap_table_size = 64M
max_allowed_packet = 512M
#sort_buffer_size = 256K
#read_buffer_size = 256K
#read_rnd_buffer_size = 512K
#myisam_sort_buffer_size = 8M
skip_name_resolve
memlock=0
sysdate_is_now=1
max_connections=700
max_user_connections=350
thread_cache_size=512
query_cache_type = 0
query_cache_size = 0
table_open_cache=1024
lower_case_table_names=0
# 5.6 backwards compatibility
explicit_defaults_for_timestamp=1
##
## WSREP options
##
# Full path to wsrep provider library or 'none'
wsrep_provider=/usr/lib64/galera/libgalera_smm.so
wsrep_node_address=192.168.111.55
# Provider specific configuration options
wsrep_provider_options="gcache.size=8192M; gmcast.segment=0"
# Logical cluster name. Should be the same for all nodes.
wsrep_cluster_name="my_wsrep_cluster"
# Group communication system handle
wsrep_cluster_address=gcomm://192.168.111.55,192.168.111.56,192.168.111.57
# Human_readable node name (non-unique). Hostname by default.
wsrep_node_name=192.168.111.55
# Address for incoming client connec...

[root@basedatos-d ~]# more /etc/my.cnf
[MYSQLD]
user=mysql
basedir=/usr/
datadir=/Data/mysql
tmpdir=/Data/mysql/tmp
socket=/var/lib/mysql/mysql.sock
pid_file=mysqld.pid
port=3306
log_error=/var/log/mysqld.log
log_warnings=2
#log_output=FILE
### INNODB OPTIONS 
innodb_buffer_pool_size=5000M
innodb_flush_log_at_trx_commit=2
innodb_file_per_table=1
innodb_data_file_path = ibdata1:100M:autoextend
## You may want to tune the below depending on number of cores and disk sub
innodb_read_io_threads=4
innodb_write_io_threads=4
innodb_io_capacity=200
innodb_doublewrite=1
innodb_log_file_size=512M
innodb_log_buffer_size=64M
innodb_buffer_pool_instances=4
innodb_log_files_in_group=2
innodb_thread_concurrency=64
#innodb_file_format=barracuda
innodb_flush_method = O_DIRECT
innodb_autoinc_lock_mode=2
## avoid statistics update when doing e.g show tables
innodb_stats_on_metadata=0
default_storage_engine=innodb
# CHARACTER SET
#collation_server = utf8_unicode_ci
#init_connect='SET NAMES utf8'
#character_set_server = utf8
event_scheduler=ON
# REPLICATION SPECIFIC
#server_id must be unique across all mysql servers participating in replication.
#server_id=SERVERID
binlog_format=ROW
#log_slave_updates=1
#log_bin=binlog
#relay_log=relay-bin
#expire_logs_days=7
#gtid_mode=ON
#enforce_gtid_consistency=1
# OTHER THINGS, BUFFERS ETC
key_buffer_size = 24M
tmp_table_size = 64M
max_heap_table_size = 64M
max_allowed_packet = 512M
#sort_buffer_size = 256K
#read_buffer_size = 256K
#read_rnd_buffer_size = 512K
#myisam_sort_buffer_size = 8M
skip_name_resolve
memlock=0
sysdate_is_now=1
max_connections=700
max_user_connections=350
thread_cache_size=512
query_cache_type = 0
query_cache_size = 0
table_open_cache=1024
lower_case_table_names=0
# 5.6 backwards compatibility
explicit_defaults_for_timestamp=1
##
## WSREP options
##
# Full path to wsrep provider library or 'none'
wsrep_provider=/usr/lib64/galera/libgalera_smm.so
wsrep_node_address=192.168.111.55
# Provider specific configuration options
wsrep_provider_options="gcache.size=8192M; gmcast.segment=0"
# Logical cluster name. Should be the same for all nodes.
wsrep_cluster_name="my_wsrep_cluster"
# Group communication system handle
wsrep_cluster_address=gcomm://192.168.111.55,192.168.111.56,192.168.111.57
# Human_readable node name (non-unique). Hostname by default.
wsrep_node_name=192.168.111.55
# Address for incoming client connections. Autodetect by default.
#wsrep_node_incoming_address=
# How many threads will process writesets from other nodes
wsrep_slave_threads=8
# DBUG options for wsrep provider
#wsrep_dbug_option
# Generate fake primary keys for non-PK tables (required for multi-master
# and parallel applying operation)
wsrep_certify_nonPK=1
# Location of the directory with data files. Needed for non-mysqldump
# state snapshot transfers. Defaults to mysql_real_data_home.
#wsrep_data_home_dir=
# Maximum number of rows in write set
wsrep_max_ws_rows=131072
# Maximum size of write set
wsrep_max_ws_size=1073741824
# to enable debug level logging, set this to 1
wsrep_debug=0
# convert locking sessions into transactions
wsrep_convert_LOCK_to_trx=0
# how many times to retry deadlocked autocommits
wsrep_retry_autocommit=1
# change auto_increment_increment and auto_increment_offset automatically
wsrep_auto_increment_control=1
# replicate myisam
wsrep_replicate_myisam=1
# retry autoinc insert, which failed for duplicate key error
wsrep_drupal_282555_workaround=0
# enable "strictly synchronous" semantics for read operations
wsrep_causal_reads=0
# Command to call when node status or cluster membership changes.
# Will be passed all or some of the following options:
# --status  - new status of this node
# --uuid    - UUID of the cluster
# --primary - whether the component is primary or not ("yes"/"no")
# --members - comma-separated list of members
# --index   - index of this node in the list
#wsrep_notify_cmd=
##
## WSREP State Transfer options
##
# State Snapshot Transfer method
# ClusterControl currently DOES NOT support wsrep_sst_method=mysqldump
wsrep_sst_method=xtrabackup-v2
# Address on THIS node to receive SST at. DON'T SET IT TO DONOR ADDRESS!!!
# (SST method dependent. Defaults to the first IP of the first interface)
#wsrep_sst_receive_address=
# SST authentication string. This will be used to send SST to joining nodes.
# Depends on SST method. For mysqldump method it is root:<root password>
wsrep_sst_auth=root:pp3zwc02
# Desired SST donor name.
#wsrep_sst_donor=
# Protocol version to use
# wsrep_protocol_version=
[MYSQL]
socket=/var/lib/mysql/mysql.sock
#default_character_set=utf8
[client]
socket=/var/lib/mysql/mysql.sock
#default_character_set=utf8
[mysqldump]
max_allowed_packet = 512M
socket=/var/lib/mysql/mysql.sock
#default_character_set=utf8
[MYSQLD_SAFE]
pid_file=mysqld.pid
log_error=/var/log/mysqld.log
basedir=/usr/
datadir=/Data/mysql

Valerii Kravchuk (valerii-kravchuk) on 2015-05-19

Changed in percona-xtradb-cluster:
status:	Incomplete → New

Revision history for this message

Muhammad Irfan (muhammad-irfan) wrote on 2015-05-21:

#10

I replicated by using provided table definitions, trigger and my.cnf. I tried with 3 node cluster and all machines running NTP and time is synchronized on all nodes. I noticed stamp value for TIMESTAMP column inserted properly on my test case on all nodes of the cluster.

[root@centos1 ~]# mysqlslap --concurrency=500 --iterations=100 --no-drop --create-schema=test --query="INSERT INTO estadisticos_ws ( tx, msisdn, nodo, stamp, duracion, wsid, error ) VALUES ('0xc70748a05bb2', 56988659040,47, now(), 1, 2, 0);" --verbose

MariaDB [test]> SELECT * FROM estadisticos_ws;
+------------+----------------+-------------+------+---------------------+----------+-------+------+
| id | tx | msisdn | nodo | stamp | duracion | error | wsid |
+------------+----------------+-------------+------+---------------------+----------+-------+------+
| 4546612239 | 0xc70748a05bb2 | 56988659040 | 47 | 2015-05-21 05:53:08 | 1 | 0 | 2 |
| 4546612242 | 0xc70748a05bb2 | 56988659040 | 47 | 2015-05-21 05:53:08 | 1 | 0 | 2 |
| 4546612245 | 0xc70748a05bb2 | 56988659040 | 47 | 2015-05-21 05:53:08 | 1 | 0 | 2 |
| 4546612248 | 0xc70748a05bb2 | 56988659040 | 47 | 2015-05-21 05:53:08 | 1 | 0 | 2 |
| 4546612251 | 0xc70748a05bb2 | 56988659040 | 47 | 2015-05-21 05:53:08 | 1 | 0 | 2 |
| 4546612254 | 0xc70748a05bb2 | 56988659040 | 47 | 2015-05-21 05:53:08 | 1 | 0 | 2 |
| 4546612257 | 0xc70748a05bb2 | 56988659040 | 47 | 2015-05-21 05:53:08 | 1 | 0 | 2 |
| 4546612260 | 0xc70748a05bb2 | 56988659040 | 47 | 2015-05-21 05:53:08 | 1 | 0 | 2 |
| 4546612263 | 0xc70748a05bb2 | 56988659040 | 47 | 2015-05-21 05:53:08 | 1 | 0 | 2 |
| 4546612266 | 0xc70748a05bb2 | 56988659040 | 47 | 2015-05-21 05:53:08 | 1 | 0 | 2 |
+------------+----------------+-------------+------+---------------------+----------+-------+------+

We would need repeatable test case to try to reproduce it.

I replicated by using provided table definitions, trigger and my.cnf. I tried with 3 node cluster and all machines running NTP and time is synchronized on all nodes. I noticed stamp value for TIMESTAMP column inserted properly on my test case on all nodes of the cluster.

[root@centos1 ~]# mysqlslap  --concurrency=500 --iterations=100 --no-drop --create-schema=test --query="INSERT INTO estadisticos_ws ( tx, msisdn, nodo, stamp, duracion, wsid, error ) VALUES ('0xc70748a05bb2', 56988659040,47, now(), 1, 2, 0);" --verbose

MariaDB [test]> SELECT * FROM estadisticos_ws;
+------------+----------------+-------------+------+---------------------+----------+-------+------+
| id         | tx             | msisdn      | nodo | stamp               | duracion | error | wsid |
+------------+----------------+-------------+------+---------------------+----------+-------+------+
| 4546612239 | 0xc70748a05bb2 | 56988659040 |   47 | 2015-05-21 05:53:08 |        1 |     0 |    2 |
| 4546612242 | 0xc70748a05bb2 | 56988659040 |   47 | 2015-05-21 05:53:08 |        1 |     0 |    2 |
| 4546612245 | 0xc70748a05bb2 | 56988659040 |   47 | 2015-05-21 05:53:08 |        1 |     0 |    2 |
| 4546612248 | 0xc70748a05bb2 | 56988659040 |   47 | 2015-05-21 05:53:08 |        1 |     0 |    2 |
| 4546612251 | 0xc70748a05bb2 | 56988659040 |   47 | 2015-05-21 05:53:08 |        1 |     0 |    2 |
| 4546612254 | 0xc70748a05bb2 | 56988659040 |   47 | 2015-05-21 05:53:08 |        1 |     0 |    2 |
| 4546612257 | 0xc70748a05bb2 | 56988659040 |   47 | 2015-05-21 05:53:08 |        1 |     0 |    2 |
| 4546612260 | 0xc70748a05bb2 | 56988659040 |   47 | 2015-05-21 05:53:08 |        1 |     0 |    2 |
| 4546612263 | 0xc70748a05bb2 | 56988659040 |   47 | 2015-05-21 05:53:08 |        1 |     0 |    2 |
| 4546612266 | 0xc70748a05bb2 | 56988659040 |   47 | 2015-05-21 05:53:08 |        1 |     0 |    2 |
+------------+----------------+-------------+------+---------------------+----------+-------+------+

We would need repeatable test case to try to reproduce it.

Changed in percona-xtradb-cluster:
status:	New → Incomplete

markus_albe (markus-albe) on 2016-02-13

tags:

added: i65455

Revision history for this message

Jervin R (revin) wrote on 2016-02-17:

#11

Bram, Jose - any chance you were using persistent/pooled connections?

Revision history for this message

Jose Cavieres (jcavieres) wrote on 2016-02-18: Re: [Bug 1372501] Re: INSERT with NOW() gives incorrect timestamp

#12

Yes/Yes to your questions
El 17 feb. 2016 8:50 PM, "Jervin R" <email address hidden> escribió:

> Bram, Jose - any chance you were using persistent/pooled connections?
>
> --
> You received this bug notification because you are subscribed to a
> duplicate bug report (1453964).
> https://bugs.launchpad.net/bugs/1372501
>
> Title:
> INSERT with NOW() gives incorrect timestamp
>
> Status in Percona Server:
> New
> Status in Percona XtraDB Cluster:
> Incomplete
>
> Bug description:
> Had a very strange issue today.
>
> From a C program (using libmysqlclient) I am executing queries like
> INSERT INTO ... (t, ..) VALUES (NOW(), ...)
> And similarly UPDATE .... WHERE ..=NOW()
>
> For the past 12 hours or so all NOW() statements resulted in a
> TIMESTAMP of '2014-09-22 05:17:03' in the database fields.
>
> Yeah... "huh!?"... like after that time the time stood still...
>
> Just to be clear: the machine is running NTP and I checked the date
> manually, it's perfectly synchronized.
>
> Presumably NOW() is not expanded on the client-side right? So my
> libmysqlclient application can't be blamed, correct?
> Must be the SQL server / Percona then?
>
> I restarted the client application - which closed the connection to
> the SQL server and reinitiated it - and the bug disappeared... or at
> least for now.
>
> Using ubuntu:
> i percona-xtrabackup 2.2.3-4982-1.trusty
> amd64 Open source backup tool for InnoDB and XtraDB
> ii percona-xtradb-cluster-56 5.6.20-25.7-886.trusty
> amd64 Percona XtraDB Cluster with Galera
> ii percona-xtradb-cluster-client-5.6 5.6.20-25.7-886.trusty
> amd64 Percona XtraDB Cluster database client binaries
> ii percona-xtradb-cluster-common-5.6 5.6.20-25.7-886.trusty
> amd64 Percona XtraDB Cluster database common files (e.g.
> /etc/mysql/my.cnf)
> ii percona-xtradb-cluster-galera-3 3.7.3256.trusty
> amd64 Metapackage for latest version of galera3.
> ii percona-xtradb-cluster-galera-3.x 3.7.3256.trusty
> amd64 Galera components of Percona XtraDB Cluster
> ii percona-xtradb-cluster-server-5.6 5.6.20-25.7-886.trusty
> amd64 Percona XtraDB Cluster database server binaries
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/percona-server/+bug/1372501/+subscriptions
>

Yes/Yes to your questions
El 17 feb. 2016 8:50 PM, "Jervin R" <1372501@bugs.launchpad.net> escribió:

> Bram, Jose - any chance you were using persistent/pooled connections?
>
> --
> You received this bug notification because you are subscribed to a
> duplicate bug report (1453964).
> https://bugs.launchpad.net/bugs/1372501
>
> Title:
>   INSERT with  NOW() gives incorrect timestamp
>
> Status in Percona Server:
>   New
> Status in Percona XtraDB Cluster:
>   Incomplete
>
> Bug description:
>   Had a very strange issue today.
>
>   From a C program (using libmysqlclient) I am executing queries like
> INSERT INTO ... (t, ..) VALUES (NOW(), ...)
>   And similarly UPDATE .... WHERE ..=NOW()
>
>   For the past 12 hours or so all NOW() statements resulted in a
>   TIMESTAMP of '2014-09-22 05:17:03' in the database fields.
>
>   Yeah... "huh!?"... like after that time the time stood still...
>
>   Just to be clear: the machine is running NTP and I checked the date
>   manually, it's perfectly synchronized.
>
>   Presumably NOW() is not expanded on the client-side right? So my
> libmysqlclient application can't be blamed, correct?
>   Must be the SQL server / Percona then?
>
>   I restarted the client application - which closed the connection to
>   the SQL server and reinitiated it - and the bug disappeared... or at
>   least for now.
>
>   Using ubuntu:
>   i  percona-xtrabackup                2.2.3-4982-1.trusty
>  amd64        Open source backup tool for InnoDB and XtraDB
>   ii  percona-xtradb-cluster-56         5.6.20-25.7-886.trusty
> amd64        Percona XtraDB Cluster with Galera
>   ii  percona-xtradb-cluster-client-5.6 5.6.20-25.7-886.trusty
> amd64        Percona XtraDB Cluster database client binaries
>   ii  percona-xtradb-cluster-common-5.6 5.6.20-25.7-886.trusty
> amd64        Percona XtraDB Cluster database common files (e.g.
> /etc/mysql/my.cnf)
>   ii  percona-xtradb-cluster-galera-3   3.7.3256.trusty
>  amd64        Metapackage for latest version of galera3.
>   ii  percona-xtradb-cluster-galera-3.x 3.7.3256.trusty
>  amd64        Galera components of Percona XtraDB Cluster
>   ii  percona-xtradb-cluster-server-5.6 5.6.20-25.7-886.trusty
> amd64        Percona XtraDB Cluster database server binaries
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/percona-server/+bug/1372501/+subscriptions
>

Revision history for this message

Bram Matthys (syzop) wrote on 2016-02-18:

#13

Yes, the (TCP/IP) socket was often connected for days, sometimes even weeks.

Revision history for this message

Jervin R (revin) wrote on 2016-02-18:

#14

Jose, Bram - gotcha - I am trying to reproduce this using some simple scripts. It seems MGC 10.0.21 and PXC 5.6.22 are the highest versions affected - anyone running higher? Aside from Java, anyone using PHP or something else for the persistent connections?

Revision history for this message

Jose Cavieres (jcavieres) wrote on 2016-02-19:

#15

Se use the C connector.

JCS
El 18 feb. 2016 7:01 AM, "Jervin R" <email address hidden> escribió:

> Jose, Bram - gotcha - I am trying to reproduce this using some simple
> scripts. It seems MGC 10.0.21 and PXC 5.6.22 are the highest versions
> affected - anyone running higher? Aside from Java, anyone using PHP or
> something else for the persistent connections?
>
> --
> You received this bug notification because you are subscribed to a
> duplicate bug report (1453964).
> https://bugs.launchpad.net/bugs/1372501
>
> Title:
> INSERT with NOW() gives incorrect timestamp
>
> Status in Percona Server:
> New
> Status in Percona XtraDB Cluster:
> Incomplete
>
> Bug description:
> Had a very strange issue today.
>
> From a C program (using libmysqlclient) I am executing queries like
> INSERT INTO ... (t, ..) VALUES (NOW(), ...)
> And similarly UPDATE .... WHERE ..=NOW()
>
> For the past 12 hours or so all NOW() statements resulted in a
> TIMESTAMP of '2014-09-22 05:17:03' in the database fields.
>
> Yeah... "huh!?"... like after that time the time stood still...
>
> Just to be clear: the machine is running NTP and I checked the date
> manually, it's perfectly synchronized.
>
> Presumably NOW() is not expanded on the client-side right? So my
> libmysqlclient application can't be blamed, correct?
> Must be the SQL server / Percona then?
>
> I restarted the client application - which closed the connection to
> the SQL server and reinitiated it - and the bug disappeared... or at
> least for now.
>
> Using ubuntu:
> i percona-xtrabackup 2.2.3-4982-1.trusty
> amd64 Open source backup tool for InnoDB and XtraDB
> ii percona-xtradb-cluster-56 5.6.20-25.7-886.trusty
> amd64 Percona XtraDB Cluster with Galera
> ii percona-xtradb-cluster-client-5.6 5.6.20-25.7-886.trusty
> amd64 Percona XtraDB Cluster database client binaries
> ii percona-xtradb-cluster-common-5.6 5.6.20-25.7-886.trusty
> amd64 Percona XtraDB Cluster database common files (e.g.
> /etc/mysql/my.cnf)
> ii percona-xtradb-cluster-galera-3 3.7.3256.trusty
> amd64 Metapackage for latest version of galera3.
> ii percona-xtradb-cluster-galera-3.x 3.7.3256.trusty
> amd64 Galera components of Percona XtraDB Cluster
> ii percona-xtradb-cluster-server-5.6 5.6.20-25.7-886.trusty
> amd64 Percona XtraDB Cluster database server binaries
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/percona-server/+bug/1372501/+subscriptions
>

Se use the C connector.

JCS
El 18 feb. 2016 7:01 AM, "Jervin R" <1372501@bugs.launchpad.net> escribió:

> Jose, Bram - gotcha - I am trying to reproduce this using some simple
> scripts. It seems MGC 10.0.21 and PXC 5.6.22 are the highest versions
> affected - anyone running higher? Aside from Java, anyone using PHP or
> something else for the persistent connections?
>
> --
> You received this bug notification because you are subscribed to a
> duplicate bug report (1453964).
> https://bugs.launchpad.net/bugs/1372501
>
> Title:
>   INSERT with  NOW() gives incorrect timestamp
>
> Status in Percona Server:
>   New
> Status in Percona XtraDB Cluster:
>   Incomplete
>
> Bug description:
>   Had a very strange issue today.
>
>   From a C program (using libmysqlclient) I am executing queries like
> INSERT INTO ... (t, ..) VALUES (NOW(), ...)
>   And similarly UPDATE .... WHERE ..=NOW()
>
>   For the past 12 hours or so all NOW() statements resulted in a
>   TIMESTAMP of '2014-09-22 05:17:03' in the database fields.
>
>   Yeah... "huh!?"... like after that time the time stood still...
>
>   Just to be clear: the machine is running NTP and I checked the date
>   manually, it's perfectly synchronized.
>
>   Presumably NOW() is not expanded on the client-side right? So my
> libmysqlclient application can't be blamed, correct?
>   Must be the SQL server / Percona then?
>
>   I restarted the client application - which closed the connection to
>   the SQL server and reinitiated it - and the bug disappeared... or at
>   least for now.
>
>   Using ubuntu:
>   i  percona-xtrabackup                2.2.3-4982-1.trusty
>  amd64        Open source backup tool for InnoDB and XtraDB
>   ii  percona-xtradb-cluster-56         5.6.20-25.7-886.trusty
> amd64        Percona XtraDB Cluster with Galera
>   ii  percona-xtradb-cluster-client-5.6 5.6.20-25.7-886.trusty
> amd64        Percona XtraDB Cluster database client binaries
>   ii  percona-xtradb-cluster-common-5.6 5.6.20-25.7-886.trusty
> amd64        Percona XtraDB Cluster database common files (e.g.
> /etc/mysql/my.cnf)
>   ii  percona-xtradb-cluster-galera-3   3.7.3256.trusty
>  amd64        Metapackage for latest version of galera3.
>   ii  percona-xtradb-cluster-galera-3.x 3.7.3256.trusty
>  amd64        Galera components of Percona XtraDB Cluster
>   ii  percona-xtradb-cluster-server-5.6 5.6.20-25.7-886.trusty
> amd64        Percona XtraDB Cluster database server binaries
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/percona-server/+bug/1372501/+subscriptions
>

Revision history for this message

Shahriyar Rzayev (rzayev-sehriyar) wrote on 2018-01-18:

#16

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PXC-1741

Revision history for this message

Shahriyar Rzayev (rzayev-sehriyar) wrote on 2018-01-25:

#17

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-3181

Affects		Status	Importance	Assigned to	Milestone
	Percona Server moved to https://jira.percona.com/projects/PS	New	Undecided	Unassigned
	Percona XtraDB Cluster moved to https://jira.percona.com/projects/PXC	Incomplete	Undecided	Unassigned

Percona Server moved to https://jira.percona.com/projects/PS

INSERT with NOW() gives incorrect timestamp

Bug Description

Duplicates of this bug

Other bug subscribers

Remote bug watches