Joiner node fails to start after successful Sync error is too many arguments

[Angelo Lavides]

Hi,

We want to consult the error we are having [ERROR] Too many arguments (first extra is 'file'). Is this related to Galera or this is related to the innodb?

The joiner node prod3 crashed and we want to bring it up, however mysql cannot start because of this error. We tried looking for what causes this error but we can't find it anywhere. Any help will be appreciated. Thanks

2022-10-22T08:56:33.135409Z 0 [Note] WSREP: 4.1 (Prod2): State transfer to 2.1 (Prod3) complete.
2022-10-22T08:56:33.137752Z 0 [Note] WSREP: Member 4.1 (Prod2) synced with group.
WSREP_SST: [INFO] Joiner cleanup. rsync PID: 2108 (20221022 16:56:33.267)
WSREP_SST: [INFO] Joiner cleanup done. (20221022 16:56:33.777)
2022-10-22T08:56:33.779499Z 0 [Note] WSREP: SST complete, seqno: 722712
2022-10-22T08:56:33.781560Z 0 [Note] InnoDB: PUNCH HOLE support available
2022-10-22T08:56:33.781601Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2022-10-22T08:56:33.781606Z 0 [Note] InnoDB: Uses event mutexes
2022-10-22T08:56:33.781611Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2022-10-22T08:56:33.781616Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2022-10-22T08:56:33.781656Z 0 [Note] InnoDB: Using Linux native AIO
2022-10-22T08:56:33.781962Z 0 [Note] InnoDB: Number of pools: 1
2022-10-22T08:56:33.782074Z 0 [Note] InnoDB: Using CPU crc32 instructions
2022-10-22T08:56:33.785078Z 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2022-10-22T08:56:33.794535Z 0 [Note] InnoDB: Completed initialization of buffer pool
2022-10-22T08:56:33.796812Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2022-10-22T08:56:33.809511Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2022-10-22T08:56:33.815517Z 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 3502937134
2022-10-22T08:56:33.815545Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 3502937143
2022-10-22T08:56:33.815550Z 0 [Note] InnoDB: Database was not shutdown normally!
2022-10-22T08:56:33.815554Z 0 [Note] InnoDB: Starting crash recovery.
2022-10-22T08:56:34.151289Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2022-10-22T08:56:34.151393Z 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2022-10-22T08:56:34.210198Z 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2022-10-22T08:56:34.210973Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
2022-10-22T08:56:34.211001Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
2022-10-22T08:56:34.212729Z 0 [Note] InnoDB: Waiting for purge to start
2022-10-22T08:56:34.262968Z 0 [Note] InnoDB: 5.7.35 started; log sequence number 3502937143
2022-10-22T08:56:34.263003Z 0 [Note] InnoDB: !!! innodb_force_recovery is set to 1 !!!
2022-10-22T08:56:34.263211Z 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2022-10-22T08:56:34.263383Z 0 [Note] Plugin 'FEDERATED' is disabled.
2022-10-22T08:56:34.264719Z 0 [Note] InnoDB: Buffer pool(s) load completed at 221022 16:56:34
2022-10-22T08:56:34.269781Z 0 [ERROR] Too many arguments (first extra is 'file').
2022-10-22T08:56:34.269802Z 0 [Note] Use --verbose --help to get a list of available options!
2022-10-22T08:56:34.269805Z 0 [ERROR] Aborting
2022-10-22T08:56:34.269808Z 0 [Note] Giving 2 client threads a chance to die gracefully

[Brian :]

What command are you using to start mysql / Maria?

Get BlueMail for Android

[Angelo Lavides]

Hi Brian,

Thanks for answering. Yes we just start Mysql with systemctl start mysqld that is why we are confused where the "too many arguments error" come from. The rscync process seemed to finish base on the logs.  State transfer to 2.1 complete.

Then it goes through the InnoDB logs and seem to finish as well.  [Note] InnoDB: Buffer pool(s) load completed

What we can't figure out is what comes after, if this is Galera code or InnoDB and which arguments are being passed. We tried to set to wsrep_debug to ON but can't get more information from this error. The innodb_force_recovery highest level has been set to 3 as well but the same error happens. 

The other 5 nodes in the cluster are started, working fine and are all in the cluster but two nodes encounter this same error and cannot start.

Here is the /etc/my.cnf used. Thanks for any help or input.

[mysqld]
max_allowed_packet=100M
datadir=/var/lib/mysql
socket=/var/lib/mysql/mysql.sock
bind-address=0.0.0.0
user=xxxx

default_storage_engine=InnoDB
innodb_autoinc_lock_mode=2
innodb_flush_log_at_trx_commit=0
innodb_buffer_pool_size=128M
innodb_force_recovery=1

symbolic-links=0

binlog_format=ROW
log-error=/var/log/mysqld.log
pid-file=/var/run/mysqld/mysqld.pid

wsrep_on=ON
wsrep_provider=/usr/lib64/galera-3/libgalera_smm.so

wsrep_node_name= "xxxxx"
wsrep_node_address= "192.XXX.XX.XX"
wsrep_cluster_name="xxxx-xxxx-cluster"
wsrep_provider_options="gmcast.segment=1; gcache.recover=yes; gcache.size=300M; gcache.page_size=300M"

wsrep_cluster_address="gcomm://1XX.XXX.XX.XX,2XX.XXX.XX.XX,3XX.XXX.XX.XX,4XX.XXX.XX.XX,5XX.XXX.XX.XX,6XX.XXX.XX.XX,7XX.XXX.XX.XX"
wsrep_slave_threads=10
wsrep_sst_method=rsync

[Angelo Lavides]

Just to add, we think this is the reason for the error: --wsrep_start_position=Binary file

We assume that the issue has something to do with the code in /usr/bin/mysqld_pre_systemd specifically in the get_recover_pos function.

Any ideas why the wsrep_start_position contains Binary file and how to solve this? Btw, when we start mysql the grastate.dat file is not existing. We tested this in another similar server and it works.

● mysqld.service - MySQL Server
   Loaded: loaded (/usr/lib/systemd/system/mysqld.service; disabled; vendor preset: disabled)
   Active: activating (start) since Tue 2022-10-25 08:35:43 PST; 1h 28min ago
     Docs: man:mysqld(8)
           http://dev.mysql.com/doc/refman/en/using-systemd.html
  Process: 2587 ExecStartPre=/usr/bin/mysqld_pre_systemd --pre (code=exited, status=0/SUCCESS)
Cntrl PID: 2635 (mysqld)
    Tasks: 24 (limit: 49468)
   Memory: 6.9G
   CGroup: /system.slice/mysqld.service
           ├─2635 /usr/sbin/mysqld --daemonize --pid-file=/var/run/mysqld/mysqld.pid --wsrep_start_position=Binary file /var/log/mysqld.log match>
           └─2637 /usr/sbin/mysqld --daemonize --pid-file=/var/run/mysqld/mysqld.pid --wsrep_start_position=Binary file /var/log/mysqld.log match>