[MDEV-14312] Server fails to start when parameter is unknown with no reference to the problem Created: 2017-11-07  Updated: 2017-12-29  Resolved: 2017-11-10

Status: Closed
Project: MariaDB Server
Component/s: Server, wsrep
Affects Version/s: 10.1, 10.2
Fix Version/s: N/A

Type: Bug Priority: Critical
Reporter: Claudio Nanni Assignee: Andrii Nikitin (Inactive)
Resolution: Duplicate Votes: 0
Labels: None

Issue Links:
Duplicate
is duplicated by MDEV-14337 mysqld_safe may suppress error messag... Closed
Relates
relates to MDEV-13978 mysqld_safe may incorrectly detect ba... Open

 Description   

If you mistype a parameter or use a valid parameter but in the wrong section MariaDB fails to start logging only two rows in the error log:

[root@tossanc 10209]# grep fantasy mh-my.cnf.10209 
fantasy_parameter=yes
 
 
 
[root@tossanc 10209]# mh service start 10209
 
Welcome to MyHarem (c)2003-2014 By Claudio Nanni
 
 
Working Basedir in: /home/myharem....
 
 
 
 
[root@tossanc 10209]# 171107 14:44:05 mysqld_safe Logging to '/home/myharem/instances/10209/data/error.10209.log'.
 
171107 14:44:05 mysqld_safe Starting mysqld daemon with databases from /home/myharem/instances/10209/data
 
 
 
[root@tossanc 10209]# cat data/error.10209.log
 
171107 14:44:05 mysqld_safe Starting mysqld daemon with databases from /home/myharem/instances/10209/data
 
171107 14:44:05 mysqld_safe WSREP: Running position recovery with --disable-log-error  --pid-file='/home/myharem/instances/10209/data/tossanc-recover.pid'
 
 
 
 
 
[root@tossanc 10209]# sed -i 's/^fantasy/#fantasy/g' mh-my.cnf.10209 
 
 
[root@tossanc 10209]# grep fantasy mh-my.cnf.10209 
#fantasy_parameter=yes
 
 
 
[root@tossanc 10209]# mh service start 10209
 
Welcome to MyHarem (c)2003-2014 By Claudio Nanni
 
 
Working Basedir in: /home/myharem....
 
 
 
 
[root@tossanc 10209]# 171107 14:45:20 mysqld_safe Logging to '/home/myharem/instances/10209/data/error.10209.log'.
 
171107 14:45:20 mysqld_safe Starting mysqld daemon with databases from /home/myharem/instances/10209/data
 
 
 
[root@tossanc 10209]# tail -5 data/error.10209.log
 
2017-11-07 14:45:23 140481334458112 [Note] WSREP: REPL Protocols: 7 (3, 2)
 
2017-11-07 14:45:23 140481334458112 [Note] WSREP: Assign initial position for certification: 0, protocol version: 3
 
2017-11-07 14:45:23 140481125705472 [Note] WSREP: Service thread queue flushed.
 
2017-11-07 14:45:23 140481334458112 [Note] WSREP: Synchronized with group, ready for connections
 
2017-11-07 14:45:23 140481334458112 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.

I actually encountered this problem when configuring `streamfmt` in the wrong section, [mysqld] instead of [sst].
Since I faced many times the case that a Galera node would not join and only those two lines were added to the error log, I suspect now that in most cases was just a wrong or mistyped configuration parameter.

Imho It would be the case to point to the reason why the server failed to start, either non existing parameter or non existing for that section.

 Comments   
Comment by Elena Stepanova [ 2017-11-07 ]

Oddly, it has something to do with wsrep.

Try to start it with a wrong parameter without wsrep – it logs everything as expected:

elenst@ws:/data/bld/10.2$ rm -rf data/mdev14312-*.err 
elenst@ws:/data/bld/10.2$ bin/mysqld_safe --fantasy-parameter --log-error=`pwd`/data/mdev14312-1.err
 
171107 16:13:42 mysqld_safe Logging to '/data/bld/10.2/data/mdev14312-1.err'.
 
171107 16:13:42 mysqld_safe Starting mysqld daemon with databases from /data/bld/10.2/data
 
elenst@ws:/data/bld/10.2$ cat data/mdev14312-1.err 
171107 16:13:42 mysqld_safe Starting mysqld daemon with databases from /data/bld/10.2/data
 
2017-11-07 16:13:43 139976060541824 [Note] /data/bld/10.2/bin/mysqld (mysqld 10.2.10-MariaDB-debug) starting as process 32423 ...
 
2017-11-07 16:13:43 139976060541824 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
 
2017-11-07 16:13:43 139976060541824 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2017-11-07 16:13:43 139976060541824 [Note] InnoDB: Uses event mutexes
 
2017-11-07 16:13:43 139976060541824 [Note] InnoDB: Compressed tables use zlib 1.2.8
 
2017-11-07 16:13:43 139976060541824 [Note] InnoDB: Using Linux native AIO
 
2017-11-07 16:13:43 139976060541824 [Note] InnoDB: Number of pools: 1
 
2017-11-07 16:13:43 139976060541824 [Note] InnoDB: Using SSE2 crc32 instructions
 
2017-11-07 16:13:43 139976060541824 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
 
2017-11-07 16:13:43 139976060541824 [Note] InnoDB: Completed initialization of buffer pool
 
2017-11-07 16:13:43 139975334659840 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
 
2017-11-07 16:13:43 139976060541824 [Note] InnoDB: Highest supported file format is Barracuda.
 
2017-11-07 16:13:43 139976060541824 [Note] InnoDB: 128 out of 128 rollback segments are active.
 
2017-11-07 16:13:43 139976060541824 [Note] InnoDB: Creating shared tablespace for temporary tables
 
2017-11-07 16:13:43 139976060541824 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
 
2017-11-07 16:13:43 139976060541824 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
 
2017-11-07 16:13:43 139976060541824 [Note] InnoDB: Waiting for purge to start
 
2017-11-07 16:13:43 139976060541824 [Note] InnoDB: 5.7.20 started; log sequence number 1620338
 
2017-11-07 16:13:43 139975173588736 [Note] InnoDB: Loading buffer pool(s) from /data/bld/10.2/data/ib_buffer_pool
 
2017-11-07 16:13:43 139976060541824 [Note] Plugin 'FEEDBACK' is disabled.
 
2017-11-07 16:13:43 139976060541824 [ERROR] /data/bld/10.2/bin/mysqld: unknown option '--fantasy-parameter'
 
2017-11-07 16:13:43 139976060541824 [ERROR] Aborting
 
 
 
171107 16:13:45 mysqld_safe mysqld from pid file /data/bld/10.2/data/ws.pid ended

But with wsrep:

elenst@ws:/data/bld/10.2$ bin/mysqld_safe --fantasy-parameter --log-error=`pwd`/data/mdev14312-2.err --wsrep-on
 
171107 16:15:30 mysqld_safe Logging to '/data/bld/10.2/data/mdev14312-2.err'.
 
171107 16:15:30 mysqld_safe Starting mysqld daemon with databases from /data/bld/10.2/data
 
elenst@ws:/data/bld/10.2$ cat data/mdev14312-2.err 
171107 16:15:30 mysqld_safe Starting mysqld daemon with databases from /data/bld/10.2/data
 
171107 16:15:30 mysqld_safe WSREP: Running position recovery with --disable-log-error  --pid-file='/data/bld/10.2/data/ws-recover.pid'

Probably it has something to do with --disable-log-error in the wsrep command line

Comment by Andrii Nikitin (Inactive) [ 2017-11-09 ]

For those who is hitting the problem - please look for file like /tmp/wsrep_recovery.* with related messages

Comment by Andrii Nikitin (Inactive) [ 2017-11-09 ]

It is strange that when I manually insert line `set -x` at start of mysqld_safe - I do see proper logging in file specified with --log-error=
So it looks like some redirection problem.
I cannot try bash -x mysqld_safe because of MDEV-13978

Comment by Andrii Nikitin (Inactive) [ 2017-11-09 ]

Claudio, thank you for this report. I've verified that the root cause is not related to Galera - see MDEV-14337 .
I better will not mark any of the issues as duplicate at the moment and just re-verify the galera - related workflow once MDEV-14337 is fixed.

Generated at Thu Feb 08 08:12:34 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.