Weird messages sometimes when restarting nodes

[Laurent MINOST]

Hi,

I have seen some cases where sometimes my nodes are displaying a lot of messages within error log, a few minutes after normal shutdown and restart of the concerned node, below is a sample of these lines :

...

120918 12:05:49 [Note] WSREP: Flow-control interval: [14, 28]

120918 12:05:49 [Note] WSREP: New cluster view: global state: 8b6ad718-d711-11e1-0800-6c241ae903cd:1205363, view# 105: Primary, number of nodes: 3, my index: 0, protocol version 2

120918 12:05:49 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.

120918 12:05:49 [Note] WSREP: Assign initial position for certification: 1205363, protocol version: 2

120918 12:05:49 [Note] WSREP: Member 1 (galera3) synced with group.

120918 12:07:13 [ERROR] Slave SQL: Error 'Duplicate column name 'File_priv'' on query. Default database: 'mysql'. Query: 'ALTER TABLE user add File_priv enum('N','Y') COLLATE utf8_general_ci NOT NULL', Error_code: 1060

120918 12:07:13 [Warning] WSREP: RBR event 1 Query apply warning: 1, 1205407

120918 12:07:13 [Warning] WSREP: Ignoring error for TO isolated action: source: 6ba6cfde-0178-11e2-0800-c2cc3f1a1850 version: 2 local: 0 state: APPLYING flags: 65 conn_id: 56 trx_id: -1 seqnos (l: 402, g: 1205407, s: 1205406, d: 1205406, ts: 1347962833720579376)

120918 12:07:13 [ERROR] Slave SQL: Error 'Duplicate column name 'Grant_priv'' on query. Default database: 'mysql'. Query: 'ALTER TABLE user add Grant_priv enum('N','Y') COLLATE utf8_general_ci NOT NULL,add References_priv enum('N','Y') COLLATE utf8_general_ci NOT NULL,add Index_priv enum('N','Y') COLLATE utf8_general_ci NOT NULL,add Alter_priv enum('N','Y') COLLATE utf8_general_ci NOT NULL', Error_code: 1060

120918 12:07:13 [Warning] WSREP: RBR event 1 Query apply warning: 1, 1205408

120918 12:07:13 [Warning] WSREP: Ignoring error for TO isolated action: source: 6ba6cfde-0178-11e2-0800-c2cc3f1a1850 version: 2 local: 0 state: APPLYING flags: 65 conn_id: 56 trx_id: -1 seqnos (l: 403, g: 1205408, s: 1205407, d: 1205407, ts: 1347962833721546765)

120918 12:07:13 [ERROR] Slave SQL: Error 'Duplicate column name 'Grant_priv'' on query. Default database: 'mysql'. Query: 'ALTER TABLE host add Grant_priv enum('N','Y') NOT NULL,add References_priv enum('N','Y') COLLATE utf8_general_ci NOT NULL,add Index_priv enum('N','Y') COLLATE utf8_general_ci NOT NULL,add Alter_priv enum('N','Y') COLLATE utf8_general_ci NOT NULL', Error_code: 1060

120918 12:07:13 [Warning] WSREP: RBR event 1 Query apply warning: 1, 1205409

120918 12:07:13 [Warning] WSREP: Ignoring error for TO isolated action: source: 6ba6cfde-0178-11e2-0800-c2cc3f1a1850 version: 2 local: 0 state: APPLYING flags: 65 conn_id: 56 trx_id: -1 seqnos (l: 404, g: 1205409, s: 1205408, d: 1205408, ts: 1347962833722201884)

120918 12:07:13 [ERROR] Slave SQL: Error 'Duplicate column name 'Grant_priv'' on query. Default database: 'mysql'. Query: 'ALTER TABLE db add Grant_priv enum('N','Y') COLLATE utf8_general_ci NOT NULL,add References_priv enum('N','Y') COLLATE utf8_general_ci NOT NULL,add Index_priv enum('N','Y') COLLATE utf8_general_ci NOT NULL,add Alter_priv enum('N','Y') COLLATE utf8_general_ci NOT NULL', Error_code: 1060

...

It seems this has something to do with replication of mysql database, I have wsrep_replicate_myisam set to 1 on these nodes, maybe is it related ?
At the moment, I did not find yet any logic/clue to identify the cause of these sporadic messages ...

Thanks by advance for your answers.
Regards,

Laurent

[Mikkel Christensen]

Den 18/09/12 14.59, Laurent MINOST skrev:

> wsrep_replicate_myisam set to 1 on these nodes

Where can i read more about this?

--
De bedste hilsener / Best Regards
Mikkel Christensen

Mikjaer ApS
Silkeborgvej 128
8000 �rhus C

Tlf. +45 4440 1337

Hosting - High Availability - High Performance Hosting - Webshops
Linux - Unix - BSD - Firewalls - Sikkerhed - S�gemaskineoptimering

Systemudvikling: Php, Perl - C - C+ - C# - Javascript - Smarty
MySQL - Delphi mv.

Vi anvender udelukkende professionelle folk, de ydelser vi ikke
umiddelbart kan levere vha. inhouse konsulenter l�ser vi via vort
enorme netv�rk af freelancere. P� samme vis kan vi via s�ster-
virksomheder, samarbejdspartnere og interne resourcer levere s�
godt som alt inden for IT Udstyr, Hosting, Internet forbindelser,
Udvikling, Mobil kommunikation, Auditering, Fejlfinding, mv.

[seppo....@codership.com]

Looks to me that somebody is running fix_privilege_tables on some node...

-seppo

> --

[Laurent MINOST]

Hi mc,

You should begin with a search on this group for wsrep_replicate_myisam :

https://groups.google.com/forum/?fromgroups=#!search/wsrep_replicate_myisam 

I don't think this one is documented on codership wiki or maybe I've not find it, it seems to be an experimental feature.

Regards,

Laurent

[Laurent MINOST]

Hi Seppo,

I'm using Percona XtraDB Cluster 5.5.27-23.6-356.squeeze, do you know of any scripts that can be executed and cause this behaviour please ?
Each time I restart a node, I know that some checks are done on tables automatically by the init script :

root@galera1:/var/log/mysql# /etc/init.d/mysql start

[ ok ] Starting MySQL (Percona XtraDB Cluster) database server: mysqld . . . ..

[info] Checking for corrupt, not cleanly closed and upgrade needing tables..

It seems to do :

| 27 | debian-sys-maint | localhost                          | NULL | Query   |   61 | Opening tables     | select count(*) into @discard from `information_schema`.`PARTITIONS` |         0 |             0 |  

Do you think it could be the culprit ?

Thanks,

Regards.

Laurent

[Alex Yurchenko]

On 2012-09-18 16:03, Mikkel Christensen wrote:
> Den 18/09/12 14.59, Laurent MINOST skrev:
>> wsrep_replicate_myisam set to 1 on these nodes
> Where can i read more about this?

Uh, nowhere ;) It is an experimental feature, don't use it. (I guess
this is one valid use case for security-through-obscurity approach)

[Alex Yurchenko]

You should be seeing such messages on all nodes. If so, this must be it
and it should be rather harmless.

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

[Laurent MINOST]

Hi Alexey,

Yes, that's the case, on all nodes within error log.
Ok if it harmless but why these messages are displayed so and what are their meaning please ?
Is there something to do to avoid having them displayed ?

Thks,
Regards.

Laurent

[Alex Yurchenko]

On 2012-09-19 10:00, Laurent MINOST wrote:
> Hi Alexey,
>
> Yes, that's the case, on all nodes within error log.
> Ok if it harmless but why these messages are displayed so and what
> are
> their meaning please ?

Something, most likely Debian MySQL startup script, is issuing improper
DDL commands. Since Galera has no way to know if those actions are
invalid or not, it prints a warning for the user that the action. If you
have such warning on one node, but not on another, then it succeeded
there and therefore you're likely to have data inconsistency.

You may want to see
http://www.codership.com/wiki/doku.php?id=faq#qhow_ddls_are_handled_by_galera

> Is there something to do to avoid having them displayed ?

To begin with you need to figure out who and why is trying to execute
inapplicable DDL commands after mysqld startup. Why is it trying to add
a column when there already is one.