wsrep patch 23.5 for MySQL 5.5.23 released

[Alexey Yurchenko]

This an important security bugfix release which also adds a number of experimental features.

Bugfixes:
- merged with upstream MySQL 5.5.23 (security bugs fixed in 5.5.22 and 5.5.23)
- IO cache was not reset on trx cleanup if the writeset was empty
- ALTER TABLE RENAME and row deletion could conflict on slave
- slave applier can fail for exceeded max_allowed_packet size
- clustered index not included in key set
- locking session can deadlock multi-master

New experimental features:
- Runtime consistency check support (to be integrated with Percona tools)
- Hard crash recovery support (global transaction ID can be recovered by running 'mysqld --wsrep-recover')
- MyISAM storage engine support (non-deterministic functions unsupported), disabled by default, use wsrep_replicate_myisam to enable
- Solaris 11 x86 build support (see http://www.codership.com/wiki/doku.php?id=compile_galera)

[federated_life]

Hi Alex,

Is there more documentation on 'Runtime consistency check support.' ?

thanks

[seppo....@codership.com]

This is just a preparation to make it possible to run consistency
checks like pt-table-checksum in Galera cluster.

Specifically, it runs INSERT..SELECT statement, having a magic comment
/*! 99997 */ synchronized in all cluster nodes. Percona is working to
make use of this in pt-table-checksum tool.

-seppo

Quoting federated_life <m...@zinctech.com>:

> Hi Alex,
>
> Is there more documentation on 'Runtime consistency check support.' ?
>
> thanks
>
> On Tuesday, April 24, 2012 7:19:27 AM UTC-4, Alexey Yurchenko wrote:
>>
>> This an important security bugfix release which also adds a number of
>> experimental features.
>>
>> Bugfixes:
>> - merged with upstream MySQL 5.5.23 (security bugs fixed in 5.5.22 and
>> 5.5.23)
>> - IO cache was not reset on trx cleanup if the writeset was empty
>> - ALTER TABLE RENAME and row deletion could conflict on slave
>> - slave applier can fail for exceeded max_allowed_packet size
>> - clustered index not included in key set
>> - locking session can deadlock multi-master
>>

>> New *experimental* features:

[Alex Yurchenko]

In other words, if you patch pt-table-checksum to add /*! 99997 */ to
its INSERT...SELECT statement, it should work in Galera cluster the way
it works with native master-slave replication.

Regards,
Alex

--
Alexey Yurchenko,
Codership Oy, www.codership.com
Skype: alexey.yurchenko, Phone: +358-400-516-011

[王耿亮]

Hi Alex,
I got a question about runtime consistency check support.
The tool pt-checksum-table works on original galera cluster,just
running the tool on one node and the checksum query will be replicated
cluster wide -to verify that, use "wsrep_on=0;query;wsrep=1" to
produce data inconsistency, execute the tool, you can see difference
between this_crc and master_crc.
The data of all nodes should be consistent when checksum query
executed if we use strict total order committing.
With the new fix and patch on checksum tool, the checksum query is
executed only on local node instead of replicated to cluster wide. So
does it mean that the checksum tool should be run on every node? If
there are writes on nodes, the timing and order of checksum query
might be different.

On Apr 25, 6:43 am, Alex Yurchenko <alexey.yurche...@codership.com>
wrote:

> In other words, if you patch pt-table-checksum to add /*! 99997 */ to
> its INSERT...SELECT statement, it should work in Galera cluster the way
> it works with native master-slave replication.
>
> Regards,
> Alex
>

[Laurent MINOST]

Hi,

I've just tested the new release of mysql-wsrep and installed it on one of my nodes to test it, so I've shutdown the node then move the symbolic link to the new mysql-wsrep folder.
After restart, my mysql-error.log is populated with a lot of warning which were not present before :

120504 11:01:01 [Warning] WSREP: empty rbr buffer, query: UPDATE `instance` SET `instance_name` = 'Nagios Cygnus' WHERE `instance_id` = '1' LIMIT 1, affected rows: 1

120504 11:01:01 [Warning] WSREP: empty rbr buffer, query: UPDATE `instance` SET `log_flag` = '175' WHERE `instance_id` = '1', affected rows: 1

120504 11:01:33 [Warning] WSREP: empty rbr buffer, query: UPDATE `metrics` SET `warn` = '3000.000000', `crit` = '5000.000000' , `min` = '0.000000'  WHERE `metric_id` = '1', affected rows: 1

120504 11:01:33 [Warning] WSREP: empty rbr buffer, query: UPDATE `metrics` SET `warn` = '80', `crit` = '100' , `min` = '0'  WHERE `metric_id` = '2', affected rows: 1

120504 11:01:33 [Warning] WSREP: empty rbr buffer, query: UPDATE `metrics` SET `warn` = '32843', `crit` = '34668' , `min` = '0' , `max` = '36493'  WHERE `metric_id` = '29', affected rows: 1

120504 11:01:33 [Warning] WSREP: empty rbr buffer, query: UPDATE `metrics` SET `warn` = '68572', `crit` = '72382' , `min` = '0' , `max` = '76192'  WHERE `metric_id` = '81', affected rows: 1

I tried to find the cause of this but find only this change which is maybe related ? : http://bazaar.launchpad.net/~codership/codership-mysql/wsrep-5.5/revision/3736

What are these informations displayed for please ? Are they here only for information purpose ? Do I need to modify the configuration to avoid having these lines logged or to modify the cluster behaviour ?

Thanks by advance.
Regards,

Laurent

[seppo....@codership.com]

Hi,

You are pointing to correct LP change set. This warning was added as a
"double check", to catch potential replication issues up-front.
However, the condition has turned out to be too loose, it can fire
also if update matched some rows but the update was not "effective"
(old value was same as the new value).

Condition for the warning will be fixed, tracked by:
https://bugs.launchpad.net/codership-mysql/+bug/994494

Thanks for reporting this, Seppo

Quoting Laurent MINOST <lol...@gmail.com>:

> Hi,
>
> I've just tested the new release of mysql-wsrep and installed it on one of
> my nodes to test it, so I've shutdown the node then move the symbolic link
> to the new mysql-wsrep folder.
> After restart, my mysql-error.log is populated with a lot of warning which
> were not present before :
>

>> New *experimental* features:

[Laurent MINOST]

Hi Seppo,

Ok, thanks for your answer, so I can safely ignore these warnings for the moment ?

Regards,

Laurent

[Seppo Jaakola]

Yes, you can ignore these warnings, for the time being. Sorry about
flooding your log file :(
We have a fix under testing now. I believe we will publish new release
quite soon, Galera 2.1 is maturing and close to be released as well.

-seppo

On 4 touko, 16:46, Laurent MINOST <lolo...@gmail.com> wrote:
> Hi Seppo,
>
> Ok, thanks for your answer, so I can safely ignore these warnings for the
> moment ?
>
> Regards,
>
> Laurent
>
> Le vendredi 4 mai 2012 11:58:35 UTC+2, Seppo Jaakola a écrit :
>
>
>
>
>
>
>
>
>
> > Hi,
>
> > You are pointing to correct LP change set. This warning was added as a
> > "double check", to catch potential replication issues up-front.
> > However, the condition has turned out to be too loose, it can fire
> > also if update matched some rows but the update was not "effective"
> > (old value was same as the new value).
>
> > Condition for the warning will be fixed, tracked by:
> >https://bugs.launchpad.net/codership-mysql/+bug/994494
>
> > Thanks for reporting this, Seppo
>

> >http://bazaar.launchpad.net/~codership/codership-mysql/wsrep-5.5/revi...

[Seppo Jaakola]

I must take back my earlier statement here, there is after all
something fishy with these warnings you are seeing.

I first was able to reproduce these warnings but now it turned out
that my test setup was not valid. I now tested with proper setup and
several scenarios, but cannot see such warnings, so we'd better
investigate this in more detail. To begin with:
1. Do you have any of following configurations:
wsrep_on=OFF
sql_log_bin=OFF
binlog_do_db or binlog_ignore_db defined
2. Are instance and metrics tables of InnoDB engine?
3. Does application use ROLLBACK TO SAVEPOINT commands?

If you don't mind sending metrics and instance table definitions to me
(seppo....@codership.com), I could try to reproduce with same
tables.

-seppo

[Laurent MINOST]

Hi Seppo,

Thanks for your follow !

I've checked value of each parameter and below are the results :

mysql> show variables like '%wsrep_on%';

+---------------+-------+

| Variable_name | Value |

+---------------+-------+

| wsrep_on      | ON    |

+---------------+-------+

1 row in set (0.00 sec)

mysql> show variables like '%sql_log_bin%';

+---------------+-------+

| Variable_name | Value |

+---------------+-------+

| sql_log_bin   | ON    |

+---------------+-------+

1 row in set (0.00 sec)

[root@cygnus MAISON logs]# grep -i binlog_do_db /etc/my-galera.cnf

[root@cygnus MAISON logs]# grep -i binlog_ignore_db /etc/my-galera.cnf

[root@cygnus MAISON logs]# grep -i binlog /etc/my-galera.cnf

sync_binlog             = 1

binlog_format           = ROW

For the second point, I've checked and the 'instance' and 'metrics' table are using InnoDB engine type. To keep you up to date, this application is an Open Source one named Centreon, it's a monitoring solution that is combined with Nagios and provide a more usable frontend to manage Nagios configuration and parameters.

About your third question, I really do not have any idea on how this application is working internally, is there any advise/information that you can provide me to check/verify if the application is using this behaviour please ?

For the metrics and instance tables dump, you will find it in attachment.

By the way I have also seen the same type of Warning message for another table named settings :

120509 10:50:15 [Warning] WSREP: empty rbr buffer, query: REPLACE INTO settings (name,value) VALUES ('stats_recache','RecacheTime:0.0 HostsRecached:0'), affected rows: 1

It seems there is no other database/tables affected since there is no other logs entries on other database, I will do a more detailed check on each log of the 3 nodes and let you know if I find others.

If you need any others informations, don't hesitate and ask.

Thanks.
Regards,

Laurent

[seppo....@codership.com]

Hi Laurent,

Thanks for the material. I went ahead, and installed centreon to see
if I can reproduce these warnings. But, so far I have not seen such
warnings in my site :(. There are many non-effective updates though,
so centreon knows how to "update without updating". Also, my centreon
is probably later release, as instance table has a bit different
structure.

If it is possible for you to collect query logs from you server, it
might speed up my troubleshooting. To enable query logging, you need to:

mysql> SET GLOBAL log=1;

..and after that MySQL will start writing to query log file in your
data directory.
NOTE: Query logging will affect performance so you might not want to
do this if your site is under heavy load.

You can turn off query logging by:
mysql> SET GLOBAL log=0;

A short query log sample from the period when one such warning is
logged in error log, should reveal what happens in the connection
before the warning.

But, I will keep on testing with centreon, probably different
configuration will fire these warnings for me as well.

-seppo

[Laurent MINOST]

Hi Seppo,

Thanks for your investigation.

I enabled the general log file on one of the node to log some requests for you (file attached).
During the time the general log was enabled, I got 3 Warning on the error log :

120511 13:30:01 [Warning] WSREP: empty rbr buffer, query: UPDATE `instance` SET `instance_name` = 'Nagios Cygnus' WHERE `instance_id` = '1' LIMIT 1, affected rows: 1

120511 13:30:01 [Warning] WSREP: empty rbr buffer, query: REPLACE INTO settings (name,value) VALUES ('path_webroot','/usr/share/cacti'), affected rows: 1

120511 13:30:01 [Warning] WSREP: empty rbr buffer, query: UPDATE `instance` SET `log_flag` = '5191' WHERE `instance_id` = '1', affected rows: 1

It will help to follow on the general log I think, this one is attached.
As I had a look on it, it seems that this is stream/ID 7018 which is concerned for the first and third queries and 7014 for the second one.

As you said, Centreon seems to do a lot of queries ... maybe there is a lot which are useless :)

Hope that it will help to understand why these warnings are there, if you need others informations, don"t hesitate !

Regards,

Laurent

[Laurent MINOST]

Hi Seppo,

To be sure that the problem was not coming from something special with my v2.3.3 of Centreon, I've updated it to v2.3.8 (latest available on their website), but warning are still there, this has something related with the news version of MySQL-wsrep because of with the previous one (5.5.20-23.4) these warnings were not present.

Regards,

Laurent

[seppo....@codership.com]

Laurent,

I have still not seen such warnings in my centreon installation. I
have v2.3.7, a bit different from what you have. But I doubt, it makes
difference, when I scanned my query log, I could not find similar
updates as in your case for instance and metrics tables. So I probably
have to configure my centreon somewhat to yield same kind of SQL...

You query log did not help much in analysis. The warning comes from a
single autocommit update, and there is no conflicting access at same
time. It might help if you can collect debug level logs from one such
warning situation. For debug logging, issue:

mysql> SET GLOBAL wsrep_debug=1;

When done, disable debug logging by:

mysql> SET GLOBAL wsrep_debug=0;

Debug messages go in mysql error log. Please, show also configuration with:

mysql> SHOW VARIABLES\G

-seppo

Quoting Laurent MINOST <lol...@gmail.com>:

> Hi Seppo,
>

[Laurent MINOST]

Hi Seppo,

You will find debug logs from one node at the link below :

http://pastie.org/3929508

Also the configuration :
http://pastie.org/3929523

Hope this will help.

Laurent

[seppo....@codership.com]

Hi Laurent,

There are no debug messages related to these warnings :(

However, I learned that you are running a source build, which is
somewhat different than our releases. e.g. rpl_semi_* variables are
present in your build. I was out of the loop and missed the fact that
you are building for Solaris. And it may be that affected rows
statistics work differently in your build.

Also, your configuration seems to have innodb_autoinc_lock_mode == 1,
and this is not supported. You should set value 2 for this variable.

I suggest testing for consistency in instance table to make sure that
these warnings are really false positives.

[Laurent MINOST]

Hi Seppo,

My answers inline :

Le vendredi 18 mai 2012 14:29:42 UTC+2, Seppo Jaakola a écrit :

Hi Laurent,

There are no debug messages related to these warnings :(

Yes, I was not sure but that's what it seemed to me when I saw the logs ...
 

However, I learned that you are running a source build, which is
somewhat different than our releases.

What do you mean by source build please ?
The build which I'm using is the one downloaded from : https://launchpad.net/codership-mysql/5.5/5.5.23-23.5/+download/mysql-5.5.23_wsrep_23.5-linux-x86_64.tar.gz

-rw-r--r--   1 root    root    63447680 23 avril 23:30 mysql-5.5.23_wsrep_23.5-linux-x86_64.tar.gz

# md5sum mysql-5.5.23_wsrep_23.5-linux-x86_64.tar.gz 

7883c44adac4498cfc575fe96c45b8dc  mysql-5.5.23_wsrep_23.5-linux-x86_64.tar.gz

which is the same md5sum as the one reported at : https://launchpad.net/codership-mysql/5.5/5.5.23-23.5/+download/mysql-5.5.23_wsrep_23.5-linux-x86_64.tar.gz/+md5

 

e.g. rpl_semi_* variables are
present in your build.

These variables are fro semi sync replication which is not used here, I was using it on another MySQL server before discovering Galera but in my present my.cnf, these parameters are commented on my.cnf :

# Replication semi synchrone

#rpl_semi_sync_master_enabled           = 1

#rpl_semi_sync_master_timeout           = 10000

#rpl_semi_sync_slave_enabled            = 1

#rpl_semi_sync_master_trace_level = 32

#rpl_semi_sync_slave_trace_level        = 32

#rpl_semi_sync_master_wait_no_slave     = 1

I was out of the loop and missed the fact that
you are building for Solaris.

No, these servers are our testing environnment and we are under Linux (Fedora 16 x64) for the node on which I gave you the variables. Solaris should have been our production environment but as Galera is not compiling properly without an headache under Solaris 10, we will probably give up with this crappy OS that is Solaris ...

 

And it may be that affected rows
statistics work differently in your build.

Why ? Is Galera/WSREP is working differently based upon the build we are choosing ? I don't understand.

 

Also, your configuration seems to have innodb_autoinc_lock_mode == 1,
and this is not supported. You should set value 2 for this variable.

Oh, OK, I was not aware of this sorry

MySQL's default is 1 : http://dev.mysql.com/doc/refman/5.5/en/innodb-parameters.html#sysvar_innodb_autoinc_lock_mode
I have now set it to 2 on each of my node but warnings seems to be still present in each of the 3 nodes error logs ...
By the way, could you please tell if there is a documentation somewhere where I can see/know what are the needed changes for such parameters for Galera/WSrep operate properly please ?
 

I suggest testing for consistency in instance table to make sure that
these warnings are really false positives.

I have already did some CHECK TABLE, ANALYZE TABLE and REPAIR TABLE on these tables but every time result was OK ...
Do you advise to do some others maintenance actions on these tables and if so which one please ? 
 

-seppo

Thks for your answers and explanations seppo !
Regards.

Laurent

[seppo....@codership.com]

Hi Laurent,

I made too hasty conclusions here - my bad. Seems your build is valid
and does not explain these warnings.
For consistency checking, you can check manually the tables which
logged warnings, e.g. by CHECKSUM TABLE
mysql> CHECKSUM TABLE instance;

you can try this approach, if you have and idle period for the checked
table(s). Get checksums from every node - they should match or we have
a problem...

Can you give some more information of your nagios/centreon monitoring.
I have now a simple centreon server installed in one of the cluster
nodes monitoring 3 servers in same rack. I wonder if I could change my
centreon configuration somehow to make these warnings surface.

[Laurent MINOST]

Hi Seppo,

Thks for your reply.

You will find below some checks about the CHECKSUM queries :

[root@cygnus MAISON ~]# for s in 192.168.0.1 192.168.0.5 192.168.0.10 ; do echo "CHECKSUM TABLE centstorage.instance;" | mysql -u root -h $s --password=XXXXXXXX ; done

Table   Checksum

centstorage.instance    653113639

Table   Checksum

centstorage.instance    653113639

Table   Checksum

centstorage.instance    653113639

[root@cygnus MAISON ~]# for s in 192.168.0.1 192.168.0.5 192.168.0.10 ; do echo "CHECKSUM TABLE centstorage.metrics;" | mysql -u root -h $s --password=XXXXXXXX ; done

Table   Checksum

centstorage.metrics     1455138591

Table   Checksum

centstorage.metrics     1455138591

Table   Checksum

centstorage.metrics     1455138591

It seems OK for the two tables which mainly generates warnings.

Concerning my Centreon configuration, I would say that I have nothing really particular at least I think.
Conceptually, Centreon is used as a Web Frontend to interact with a Nagios Server, it is used to better control configuration of this one which can be quickly hard to manage when having a lot of services to monitor. This is mainly how I'm using Centreon, I configure services which I want to monitor then it generates by itself the Nagios configuration accordingly, then I ask it to apply it on the Nagios Server and reload the new conf.

I do not know which usage the centstorage database is done for within Centreon as this one uses 3 different databases (centreon, censtatus, centstorage), I will check if it's possible to do a configuration backup to forward it to you so maybe you will be able to reproduce the same warnings ?

Regards,

Laurent

[Erik]

Hi all,
Sorry to interrupt your discussions, but I have the same symptoms -
so
maybe I can help troubleshoot/verify your findings...Of course I'm
more than interested in the outcome because we were planning to roll
out galera into production shortly...
Our situation:
3 Galera nodes (Server version: 5.5.23, wsrep_23.5.r333), several
other servers which run Drupal 6 & 7 and connect (for the time being)
to a single Galera node.
symptom:
error log grows fast with sporadic warning messages like discussed
here:
eg.
120521 11:33:44 [Warning] WSREP: empty rbr buffer, query: UPDATE
node_revisions SET nid = 474249, uid = 1, title = 'Infolijn', body =
'', teaser = '', timestamp = 1337592824, format = 0 WHERE vid =
11595,
affected rows: 1
120521 11:33:44 [Warning] WSREP: empty rbr buffer, query: UPDATE
apachesolr_search_node SET changed = 1337592824, status = 1 WHERE nid
= 474249, affected rows: 1
120521 11:36:54 [Warning] WSREP: empty rbr buffer, query: UPDATE node
SET vid = 11598, type = 'persoon', language = 'nl', title = 'xxxxx
xxx xxxx', uid = 17100, status = 1, created = 1337593014, changed =
1337593014, comment = 0, promote = 0, moderate = 0, sticky = 0, tnid
=
0, transl
120521 11:36:54 [Warning] WSREP: empty rbr buffer, query: UPDATE
apachesolr_search_node SET changed = 1337593014, status = 1 WHERE nid
= 474252, affected rows: 1
120521 11:40:02 [Warning] WSREP: empty rbr buffer, query: UPDATE
variable SET value = 'd:1;' WHERE name = 'node_cron_comments_scale',
affected rows: 1
120521 11:40:02 [Warning] WSREP: empty rbr buffer, query: UPDATE
variable SET value = 'd:1;' WHERE name = 'node_cron_views_scale',
affected rows: 1
I tested consistency between nodes with CHECKSUM TABLE commands on
different nodes on several tables, and found no differences.
So I guess (or hope) that these warnings are indeed too-loose ?
thx!, regards
Erik
some mysql config:

+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| wsrep_on      | ON    |

| sql_log_bin   | ON    |
| sync_binlog   | 0     |
| binlog_format              | ROW   |

[Laurent MINOST]

Hi Erik,

Was thinking if I was not having a bad configuration somewhere or a specific problem which was only affecting my installation lol :) but with your post, I think this is maybe not an isolated problem ... Hope it will help Seppo to find the source of these warnings even if they seems pretty unharmful :)

From your posted queries, I see that you're not using Centreon so maybe the correlation of our both queries will help to identify the origin.

Regards,

Laurent

[seppo....@codership.com]

Erik, Laurent,

Taken that the tables are consistent after these warnings, it is very
probable that the warnings are false positives, and the condition for
the warning is buggy. I tried some Drupal 7 sessions today, but could
not repeat such warnings... Maybe they happen only with apachesolr
module.

-seppo

Quoting Laurent MINOST <lol...@gmail.com>:

[Laurent MINOST]

Hi Seppo,

For sure, the warning are harmless and the cluster nodes are working well even with these warnings displayed because I already have a lot of these warnings for now many days but these are problematic because it fills error log a lot and it could be a problem on heavy site with lot of queries.

Do you need anything else to find the culprit buggy condition in the code please ? Don't hesitate if I can provide some more informations, I will try to help.
There is surely something similar win the way queries are managed with Centreon and Drupal if warnings are triggered in both case but this is probably hard to identify.

Regards,

Laurent

[Alex Yurchenko]

On 2012-07-20 06:34, jbcorwin wrote:
> Alex,
>
> I'd like to learn more about the following bug fix: locking session
> can
> deadlock multi-master
>
> We recently had an issue with restoring from a mysqldump file where
> the
> entire cluster locked (no queries in or out for the applications).
>
> The issue on our side was resolved by dropping the node that had the
> locked
> query. After that node was dropped the cluster status returned to
> normal.

Hi Jesse,

Do you mean that you had this situation with the recent release? If so
we need list of wsrep variables from the hanging node and mysqldump
command line to diagnose that.

The bug was about slave applier entering a deadlock with the locking
session and as a result replication events processing on the node was
blocked. Then this node would block whole cluster replication.

Regards,
Alex

> Best,
>
> --
> Jesse Corwin

>
> On Tuesday, April 24, 2012 6:19:27 AM UTC-5, Alexey Yurchenko wrote:
>>
>> This an important security bugfix release which also adds a number
>> of
>> experimental features.
>>
>> Bugfixes:
>> - merged with upstream MySQL 5.5.23 (security bugs fixed in 5.5.22
>> and
>> 5.5.23)
>> - IO cache was not reset on trx cleanup if the writeset was empty
>> - ALTER TABLE RENAME and row deletion could conflict on slave
>> - slave applier can fail for exceeded max_allowed_packet size
>> - clustered index not included in key set
>> - locking session can deadlock multi-master
>>
>> New *experimental* features:
>> - Runtime consistency check support (to be integrated with Percona
>> tools)
>> - Hard crash recovery support (global transaction ID can be
>> recovered by
>> running 'mysqld --wsrep-recover')
>> - MyISAM storage engine support (non-deterministic functions
>> unsupported),
>> disabled by default, use wsrep_replicate_myisam to enable
>> - Solaris 11 x86 build support (see
>> http://www.codership.com/wiki/doku.php?id=compile_galera)
>>