Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-14312

Server fails to start when parameter is unknown with no reference to the problem

Details

    • Bug
    • Status: Closed (View Workflow)
    • Critical
    • Resolution: Duplicate
    • 10.1(EOL), 10.2(EOL)
    • N/A
    • Server, wsrep
    • None

    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.

      Attachments

        Issue Links

          is duplicated by

          Bug - A problem which impairs or prevents the functions of the product. MDEV-14337 mysqld_safe may suppress error messages with --log-output=file

          • Critical - Crashes, loss of data, severe memory leak.
          • Closed
          relates to

          Bug - A problem which impairs or prevents the functions of the product. MDEV-13978 mysqld_safe may incorrectly detect basedir when started as script

          • Major - Major loss of function.
          • Open

          Activity

            Ascending order - Click to sort in descending order
            elenst Elena Stepanova added a comment - - edited

            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

            elenst Elena Stepanova added a comment - - edited 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
            anikitin Andrii Nikitin (Inactive) added a comment -

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

            anikitin Andrii Nikitin (Inactive) added a comment - For those who is hitting the problem - please look for file like /tmp/wsrep_recovery.* with related messages
            anikitin Andrii Nikitin (Inactive) added a comment - - edited

            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

            anikitin Andrii Nikitin (Inactive) added a comment - - edited 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
            anikitin Andrii Nikitin (Inactive) added a comment -

            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.

            anikitin Andrii Nikitin (Inactive) added a comment - 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.

            People

              anikitin Andrii Nikitin (Inactive)
              claudio.nanni Claudio Nanni
              Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

                  Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.