Error "Too many arguments (first extra is 'file')" when log file has null pointers

[hadret]

Hello 👋🏻

Recently we encountered a rather unpleasant edge case when one of nodes received non-graceful reboot. It tried to re-join the cluster, but was looping in the error log with the following message:

[...]
2023-02-03T11:58:39.629737Z 0 [ERROR] [MY-010147] [Server] Too many arguments (first extra is 'file').
2023-02-03T11:58:39.630568Z 0 [ERROR] [MY-010119] [Server] Aborting
terminate called after throwing an instance of 'wsrep::runtime_error'
  what():  State wait was interrupted
11:58:41 UTC - mysqld got signal 6 ;
Most likely, you have hit a bug, but this error can also be caused by malfunctioning hardware.
Thread pointer: 0x7fc730004900
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 7fc74d949b58 thread_stack 0x100000
/usr/sbin/mysqld(my_print_stacktrace(unsigned char const*, unsigned long)+0x41) [0x5616ca5a3cd1]
/usr/sbin/mysqld(handle_fatal_signal+0x313) [0x5616c93f2e43]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x143c0) [0x7fc85cf2a3c0]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0xcb) [0x7fc85c60203b]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x12b) [0x7fc85c5e1859]
/lib/x86_64-linux-gnu/libstdc++.so.6(+0x9e911) [0x7fc85c9b9911]
/lib/x86_64-linux-gnu/libstdc++.so.6(+0xaa38c) [0x7fc85c9c538c]
/lib/x86_64-linux-gnu/libstdc++.so.6(+0xaa3f7) [0x7fc85c9c53f7]
/lib/x86_64-linux-gnu/libstdc++.so.6(+0xaa6a9) [0x7fc85c9c56a9]
/usr/sbin/mysqld(+0xf0501e) [0x5616c913f01e]
/usr/sbin/mysqld(wsrep::server_state::sst_received(wsrep::client_service&, int)+0xf55) [0x5616cad18645]
/usr/sbin/mysqld(+0x11e2ab6) [0x5616c941cab6]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x8609) [0x7fc85cf1e609]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x43) [0x7fc85c6de163]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0): Connection ID (thread ID): 3
Status: NOT_KILLED

The manual page at [http://dev.mysql.com/doc/mysql/en/crashing.html](http://dev.mysql.com/doc/mysql/en/crashing.html) contains
information that should help you find out what is causing the crash.
[...]

Long story short, it's because GNU grep tries to be clever sometimes with discovering file type and it was treating /var/log/mysql/error.log as a binary — simply because there were null pointers in that file (^@). When it does that, the last line it's printing is "Binary file /var/log/mysql/error.log matches", which is then passed to mysql --wsrep_start_position= on start.

I wrote a little bit more about that subject here: https://chabik.com/galera-cluster-and-mysql-signal-6-loop/

I have tiny fix for this and from what I can tell it affects all versions 5.7+ (for us it was 8.0.27). I couldn't find publicly available repository/branch for 8.0+ so I'll create PR against 5.7 branch in this repository.

[Dani4kor]

I caught the same problem, I also got to the argument passing function, and the "-a" flag also fixed the problem

Package: galera-4
Status: install ok installed
Priority: optional
Section: libs
Installed-Size: 2655
Maintainer: Codership Oy <info@codership.com>
Architecture: amd64
Version: 26.4.12+1focal


Package: mysql-wsrep-8.0
Status: install ok installed
Priority: optional
Section: database
Installed-Size: 10
Maintainer: MySQL Release Engineering <mysql-build@oss.oracle.com>
Architecture: amd64
Source: mysql-wsrep
Version: 8.0.28-26.10+1ubuntu20.04


Package: mysql-wsrep-server
Status: install ok installed
Priority: optional
Section: database
Installed-Size: 147
Maintainer: MySQL Release Engineering <mysql-build@oss.oracle.com>
Architecture: amd64
Source: mysql-wsrep
Version: 8.0.28-26.10+1ubuntu20.04


Package: mysql-wsrep-client
Status: install ok installed
Priority: optional
Section: database
Installed-Size: 179715
Maintainer: MySQL Release Engineering <mysql-build@oss.oracle.com>
Architecture: amd64
Source: mysql-wsrep
Version: 8.0.28-26.10+1ubuntu20.04

2024-02-20T01:08:46.387646Z 0 [ERROR] [MY-010147] [Server] Too many arguments (first extra is 'file').
2024-02-20T01:08:46.390810Z 0 [ERROR] [MY-010119] [Server] Aborting
terminate called after throwing an instance of 'wsrep::runtime_error'
  what():  State wait was interrupted
01:08:48 UTC - mysqld got signal 6 ;
Most likely, you have hit a bug, but this error can also be caused by malfunctioning hardware.
Thread pointer: 0x7f11f4004900
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 7f12137fdb58 thread_stack 0x100000
/usr/sbin/mysqld(my_print_stacktrace(unsigned char const*, unsigned long)+0x41) [0x55883d93c3d1]
/usr/sbin/mysqld(print_fatal_signal(int)+0x2f3) [0x55883c773cb3]
/usr/sbin/mysqld(handle_fatal_signal+0xa5) [0x55883c773d65]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x14420) [0x7f122f640420]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0xcb) [0x7f122ed1700b]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x12b) [0x7f122ecf6859]
/lib/x86_64-linux-gnu/libstdc++.so.6(+0x9e8d1) [0x7f122f0ce8d1]
/lib/x86_64-linux-gnu/libstdc++.so.6(+0xaa37c) [0x7f122f0da37c]
/lib/x86_64-linux-gnu/libstdc++.so.6(+0xaa3e7) [0x7f122f0da3e7]
/lib/x86_64-linux-gnu/libstdc++.so.6(+0xaa699) [0x7f122f0da699]
/usr/sbin/mysqld(+0xf0d928) [0x55883c4bd928]
/usr/sbin/mysqld(wsrep::server_state::sst_received(wsrep::client_service&, int)+0xf55) [0x55883e0da915]
/usr/sbin/mysqld(+0x11edae6) [0x55883c79dae6]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x8609) [0x7f122f634609]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x43) [0x7f122edf3353]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0): Connection ID (thread ID): 3
Status: NOT_KILLED

The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.

[temeo]

Fix will be included in upcoming release 8.0.36-26.17.