[MDEV-14244] MariaDB 10.2.10 fails to run on Debian Stretch with ext3 and O_DIRECT Created: 2017-11-01  Updated: 2017-11-16  Resolved: 2017-11-07

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB, Storage Engine - XtraDB
Affects Version/s: 5.5.55, 10.0.30, 10.1.22, 10.2.10
Fix Version/s: 10.1.29, 10.2.11, 10.3.3

Type: Bug Priority: Blocker
Reporter: Mark Samman Assignee: Marko Mäkelä
Resolution: Fixed Votes: 1
Labels: None
Environment:

Debian Stretch 64-bit
MariaDB version: 10.2.10+maria~stretch

Issue Links:
Duplicate
is duplicated by MDEV-14416 Installing mariadb 10.2 in a fresh sy... Closed
Relates
relates to MDEV-4338 Support FusionIO/directFS atomic writes. Closed
relates to MDEV-5746 Slow file extend when innodb_use_fall... Closed
relates to MDEV-11520 Extending an InnoDB data file unneces... Closed
relates to MDEV-13941 Innodb/Windows, 10.2 : High NTFS fra... Closed
relates to MDEV-14132 innodb.innodb-64k failed in buildbot,... Closed

 Description   

I first spotted this issue when upgrading a production server to 10.2.10, it would fail to start MariaDB after the upgrade with some error along the lines of ibtmp1 failing to be created. I purged mariadb-server-10.2 and tried reinstalling, it still failed, so I downgraded that server to 10.1 and it's now running fine.

Now I tried installing mariadb-server-10.2 on a different server where it has never been installed before, and this is the output from apt-get install mariadb-server-10.2:

# apt-get install mariadb-server-10.2
 
Reading package lists... Done
 
Building dependency tree       
Reading state information... Done
 
The following additional packages will be installed:
 
  galera-3 gawk libcgi-fast-perl libcgi-pm-perl libdbd-mysql-perl libdbi-perl
 
  libencode-locale-perl libfcgi-perl libhtml-parser-perl libhtml-tagset-perl
 
  libhtml-template-perl libhttp-date-perl libhttp-message-perl libio-html-perl
 
  liblwp-mediatypes-perl libmariadb3 libmariadbclient18 libreadline5
 
  libsigsegv2 libterm-readkey-perl libtimedate-perl liburi-perl
 
  mariadb-client-10.2 mariadb-client-core-10.2 mariadb-common
 
  mariadb-server-core-10.2 mysql-common psmisc socat
 
Suggested packages:
 
  gawk-doc libclone-perl libmldbm-perl libnet-daemon-perl
 
  libsql-statement-perl libdata-dump-perl libipc-sharedcache-perl libwww-perl
 
  mailx mariadb-test netcat-openbsd tinyca
 
The following NEW packages will be installed:
 
  galera-3 gawk libcgi-fast-perl libcgi-pm-perl libdbd-mysql-perl libdbi-perl
 
  libencode-locale-perl libfcgi-perl libhtml-parser-perl libhtml-tagset-perl
 
  libhtml-template-perl libhttp-date-perl libhttp-message-perl libio-html-perl
 
  liblwp-mediatypes-perl libmariadb3 libmariadbclient18 libreadline5
 
  libsigsegv2 libterm-readkey-perl libtimedate-perl liburi-perl
 
  mariadb-client-10.2 mariadb-client-core-10.2 mariadb-common
 
  mariadb-server-10.2 mariadb-server-core-10.2 mysql-common psmisc socat
 
0 upgraded, 30 newly installed, 0 to remove and 0 not upgraded.
 
Need to get 22.6 MB of archives.
 
After this operation, 186 MB of additional disk space will be used.
 
Do you want to continue? [Y/n] 
Get:1 http://ftp.debian.org/debian stretch/main amd64 libsigsegv2 amd64 2.10-5 [28.9 kB]
 
Get:2 http://ftp.debian.org/debian stretch/main amd64 gawk amd64 1:4.1.4+dfsg-1 [571 kB]
 
Get:3 http://ftp.debian.org/debian stretch/main amd64 libdbi-perl amd64 1.636-1+b1 [766 kB]
 
Get:4 http://ftp.debian.org/debian stretch/main amd64 libreadline5 amd64 5.2+dfsg-3+b1 [119 kB]
 
Get:5 http://ftp.debian.org/debian stretch/main amd64 psmisc amd64 22.21-2.1+b2 [123 kB]
 
Get:6 http://ftp.debian.org/debian stretch/main amd64 socat amd64 1.7.3.1-2+deb9u1 [353 kB]
 
Get:7 http://ftp.debian.org/debian stretch/main amd64 libhtml-tagset-perl all 3.20-3 [12.7 kB]
 
Get:8 http://ftp.debian.org/debian stretch/main amd64 liburi-perl all 1.71-1 [88.6 kB]
 
Get:9 http://ftp.debian.org/debian stretch/main amd64 libhtml-parser-perl amd64 3.72-3 [104 kB]
 
Get:10 http://ftp.debian.org/debian stretch/main amd64 libcgi-pm-perl all 4.35-1 [222 kB]
 
Get:11 http://ftp.debian.org/debian stretch/main amd64 libfcgi-perl amd64 0.78-2 [38.2 kB]
 
Get:12 http://ftp.debian.org/debian stretch/main amd64 libcgi-fast-perl all 1:2.12-1 [11.2 kB]
 
Get:13 http://ftp.debian.org/debian stretch/main amd64 libdbd-mysql-perl amd64 4.041-2 [114 kB]
 
Get:14 http://ftp.debian.org/debian stretch/main amd64 libencode-locale-perl all 1.05-1 [13.7 kB]
 
Get:15 http://ftp.debian.org/debian stretch/main amd64 libhtml-template-perl all 2.95-2 [67.1 kB]
 
Get:16 http://ftp.debian.org/debian stretch/main amd64 libtimedate-perl all 2.3000-2 [42.2 kB]
 
Get:17 http://ftp.debian.org/debian stretch/main amd64 libhttp-date-perl all 6.02-1 [10.7 kB]
 
Get:18 http://ftp.debian.org/debian stretch/main amd64 libio-html-perl all 1.001-1 [17.6 kB]
 
Get:19 http://ftp.debian.org/debian stretch/main amd64 liblwp-mediatypes-perl all 6.02-1 [22.1 kB]
 
Get:20 http://ftp.debian.org/debian stretch/main amd64 libhttp-message-perl all 6.11-1 [75.9 kB]
 
Get:21 http://ftp.debian.org/debian stretch/main amd64 libterm-readkey-perl amd64 2.37-1 [27.2 kB]
 
Get:22 http://ftp.ddg.lth.se/mariadb/repo/10.2/debian stretch/main i386 mysql-common all 10.2.10+maria~stretch [8432 B]
 
Get:23 http://ftp.ddg.lth.se/mariadb/repo/10.2/debian stretch/main i386 mariadb-common all 10.2.10+maria~stretch [3328 B]
 
Get:24 http://ftp.ddg.lth.se/mariadb/repo/10.2/debian stretch/main amd64 galera-3 amd64 25.3.20-stretch [8267 kB]
 
Get:25 http://ftp.ddg.lth.se/mariadb/repo/10.2/debian stretch/main amd64 mariadb-client-core-10.2 amd64 10.2.10+maria~stretch [741 kB]
 
Get:26 http://ftp.ddg.lth.se/mariadb/repo/10.2/debian stretch/main amd64 mariadb-client-10.2 amd64 10.2.10+maria~stretch [1101 kB]
 
Get:27 http://ftp.ddg.lth.se/mariadb/repo/10.2/debian stretch/main amd64 mariadb-server-core-10.2 amd64 10.2.10+maria~stretch [5474 kB]
 
Get:28 http://ftp.ddg.lth.se/mariadb/repo/10.2/debian stretch/main amd64 mariadb-server-10.2 amd64 10.2.10+maria~stretch [4112 kB]
 
Get:29 http://ftp.ddg.lth.se/mariadb/repo/10.2/debian stretch/main amd64 libmariadb3 amd64 10.2.10+maria~stretch [110 kB]
 
Get:30 http://ftp.ddg.lth.se/mariadb/repo/10.2/debian stretch/main amd64 libmariadbclient18 amd64 10.2.10+maria~stretch [2940 B]
 
Fetched 22.6 MB in 2s (9522 kB/s)             
perl: warning: Setting locale failed.
 
perl: warning: Please check that your locale settings:
 
	LANGUAGE = (unset),
 
	LC_ALL = (unset),
 
	LC_CTYPE = "UTF-8",
 
	LANG = "en_US.UTF-8"
 
    are supported and installed on your system.
 
perl: warning: Falling back to a fallback locale ("en_US.UTF-8").
 
locale: Cannot set LC_CTYPE to default locale: No such file or directory
 
locale: Cannot set LC_ALL to default locale: No such file or directory
 
Preconfiguring packages ...
 
/usr/bin/locale: Cannot set LC_CTYPE to default locale: No such file or directory
 
/usr/bin/locale: Cannot set LC_ALL to default locale: No such file or directory
 
Selecting previously unselected package libsigsegv2:amd64.
 
(Reading database ... 76085 files and directories currently installed.)
 
Preparing to unpack .../libsigsegv2_2.10-5_amd64.deb ...
 
Unpacking libsigsegv2:amd64 (2.10-5) ...
 
Setting up libsigsegv2:amd64 (2.10-5) ...
 
Selecting previously unselected package gawk.
 
(Reading database ... 76095 files and directories currently installed.)
 
Preparing to unpack .../00-gawk_1%3a4.1.4+dfsg-1_amd64.deb ...
 
Unpacking gawk (1:4.1.4+dfsg-1) ...
 
Selecting previously unselected package mysql-common.
 
Preparing to unpack .../01-mysql-common_10.2.10+maria~stretch_all.deb ...
 
Unpacking mysql-common (10.2.10+maria~stretch) ...
 
Selecting previously unselected package mariadb-common.
 
Preparing to unpack .../02-mariadb-common_10.2.10+maria~stretch_all.deb ...
 
Unpacking mariadb-common (10.2.10+maria~stretch) ...
 
Selecting previously unselected package galera-3.
 
Preparing to unpack .../03-galera-3_25.3.20-stretch_amd64.deb ...
 
Unpacking galera-3 (25.3.20-stretch) ...
 
Selecting previously unselected package libdbi-perl.
 
Preparing to unpack .../04-libdbi-perl_1.636-1+b1_amd64.deb ...
 
Unpacking libdbi-perl (1.636-1+b1) ...
 
Selecting previously unselected package libreadline5:amd64.
 
Preparing to unpack .../05-libreadline5_5.2+dfsg-3+b1_amd64.deb ...
 
Unpacking libreadline5:amd64 (5.2+dfsg-3+b1) ...
 
Selecting previously unselected package mariadb-client-core-10.2.
 
Preparing to unpack .../06-mariadb-client-core-10.2_10.2.10+maria~stretch_amd64.deb ...
 
Unpacking mariadb-client-core-10.2 (10.2.10+maria~stretch) ...
 
Selecting previously unselected package mariadb-client-10.2.
 
Preparing to unpack .../07-mariadb-client-10.2_10.2.10+maria~stretch_amd64.deb ...
 
Unpacking mariadb-client-10.2 (10.2.10+maria~stretch) ...
 
Selecting previously unselected package mariadb-server-core-10.2.
 
Preparing to unpack .../08-mariadb-server-core-10.2_10.2.10+maria~stretch_amd64.deb ...
 
Unpacking mariadb-server-core-10.2 (10.2.10+maria~stretch) ...
 
Selecting previously unselected package psmisc.
 
Preparing to unpack .../09-psmisc_22.21-2.1+b2_amd64.deb ...
 
Unpacking psmisc (22.21-2.1+b2) ...
 
Selecting previously unselected package socat.
 
Preparing to unpack .../10-socat_1.7.3.1-2+deb9u1_amd64.deb ...
 
Unpacking socat (1.7.3.1-2+deb9u1) ...
 
Setting up mysql-common (10.2.10+maria~stretch) ...
 
Setting up mariadb-common (10.2.10+maria~stretch) ...
 
Selecting previously unselected package mariadb-server-10.2.
 
(Reading database ... 76669 files and directories currently installed.)
 
Preparing to unpack .../00-mariadb-server-10.2_10.2.10+maria~stretch_amd64.deb ...
 
locale: Cannot set LC_CTYPE to default locale: No such file or directory
 
locale: Cannot set LC_ALL to default locale: No such file or directory
 
Unpacking mariadb-server-10.2 (10.2.10+maria~stretch) ...
 
Selecting previously unselected package libhtml-tagset-perl.
 
Preparing to unpack .../01-libhtml-tagset-perl_3.20-3_all.deb ...
 
Unpacking libhtml-tagset-perl (3.20-3) ...
 
Selecting previously unselected package liburi-perl.
 
Preparing to unpack .../02-liburi-perl_1.71-1_all.deb ...
 
Unpacking liburi-perl (1.71-1) ...
 
Selecting previously unselected package libhtml-parser-perl.
 
Preparing to unpack .../03-libhtml-parser-perl_3.72-3_amd64.deb ...
 
Unpacking libhtml-parser-perl (3.72-3) ...
 
Selecting previously unselected package libcgi-pm-perl.
 
Preparing to unpack .../04-libcgi-pm-perl_4.35-1_all.deb ...
 
Unpacking libcgi-pm-perl (4.35-1) ...
 
Selecting previously unselected package libfcgi-perl.
 
Preparing to unpack .../05-libfcgi-perl_0.78-2_amd64.deb ...
 
Unpacking libfcgi-perl (0.78-2) ...
 
Selecting previously unselected package libcgi-fast-perl.
 
Preparing to unpack .../06-libcgi-fast-perl_1%3a2.12-1_all.deb ...
 
Unpacking libcgi-fast-perl (1:2.12-1) ...
 
Selecting previously unselected package libmariadb3.
 
Preparing to unpack .../07-libmariadb3_10.2.10+maria~stretch_amd64.deb ...
 
Unpacking libmariadb3 (10.2.10+maria~stretch) ...
 
Selecting previously unselected package libmariadbclient18.
 
Preparing to unpack .../08-libmariadbclient18_10.2.10+maria~stretch_amd64.deb ...
 
Unpacking libmariadbclient18 (10.2.10+maria~stretch) ...
 
Selecting previously unselected package libdbd-mysql-perl.
 
Preparing to unpack .../09-libdbd-mysql-perl_4.041-2_amd64.deb ...
 
Unpacking libdbd-mysql-perl (4.041-2) ...
 
Selecting previously unselected package libencode-locale-perl.
 
Preparing to unpack .../10-libencode-locale-perl_1.05-1_all.deb ...
 
Unpacking libencode-locale-perl (1.05-1) ...
 
Selecting previously unselected package libhtml-template-perl.
 
Preparing to unpack .../11-libhtml-template-perl_2.95-2_all.deb ...
 
Unpacking libhtml-template-perl (2.95-2) ...
 
Selecting previously unselected package libtimedate-perl.
 
Preparing to unpack .../12-libtimedate-perl_2.3000-2_all.deb ...
 
Unpacking libtimedate-perl (2.3000-2) ...
 
Selecting previously unselected package libhttp-date-perl.
 
Preparing to unpack .../13-libhttp-date-perl_6.02-1_all.deb ...
 
Unpacking libhttp-date-perl (6.02-1) ...
 
Selecting previously unselected package libio-html-perl.
 
Preparing to unpack .../14-libio-html-perl_1.001-1_all.deb ...
 
Unpacking libio-html-perl (1.001-1) ...
 
Selecting previously unselected package liblwp-mediatypes-perl.
 
Preparing to unpack .../15-liblwp-mediatypes-perl_6.02-1_all.deb ...
 
Unpacking liblwp-mediatypes-perl (6.02-1) ...
 
Selecting previously unselected package libhttp-message-perl.
 
Preparing to unpack .../16-libhttp-message-perl_6.11-1_all.deb ...
 
Unpacking libhttp-message-perl (6.11-1) ...
 
Selecting previously unselected package libterm-readkey-perl.
 
Preparing to unpack .../17-libterm-readkey-perl_2.37-1_amd64.deb ...
 
Unpacking libterm-readkey-perl (2.37-1) ...
 
Setting up libhtml-tagset-perl (3.20-3) ...
 
Setting up libmariadb3 (10.2.10+maria~stretch) ...
 
Setting up psmisc (22.21-2.1+b2) ...
 
Setting up libencode-locale-perl (1.05-1) ...
 
Setting up libtimedate-perl (2.3000-2) ...
 
Setting up socat (1.7.3.1-2+deb9u1) ...
 
Setting up libio-html-perl (1.001-1) ...
 
Setting up libmariadbclient18 (10.2.10+maria~stretch) ...
 
Setting up gawk (1:4.1.4+dfsg-1) ...
 
Setting up libterm-readkey-perl (2.37-1) ...
 
Setting up liblwp-mediatypes-perl (6.02-1) ...
 
Processing triggers for libc-bin (2.24-11+deb9u1) ...
 
Setting up galera-3 (25.3.20-stretch) ...
 
Setting up liburi-perl (1.71-1) ...
 
Processing triggers for systemd (232-25+deb9u1) ...
 
Setting up libhtml-parser-perl (3.72-3) ...
 
Setting up libcgi-pm-perl (4.35-1) ...
 
Processing triggers for man-db (2.7.6.1-2) ...
 
Setting up libreadline5:amd64 (5.2+dfsg-3+b1) ...
 
Setting up mariadb-server-core-10.2 (10.2.10+maria~stretch) ...
 
Setting up libfcgi-perl (0.78-2) ...
 
Setting up libdbi-perl (1.636-1+b1) ...
 
Setting up mariadb-client-core-10.2 (10.2.10+maria~stretch) ...
 
Setting up mariadb-client-10.2 (10.2.10+maria~stretch) ...
 
Setting up libhttp-date-perl (6.02-1) ...
 
Setting up libhtml-template-perl (2.95-2) ...
 
Setting up libcgi-fast-perl (1:2.12-1) ...
 
Setting up mariadb-server-10.2 (10.2.10+maria~stretch) ...
 
locale: Cannot set LC_CTYPE to default locale: No such file or directory
 
locale: Cannot set LC_ALL to default locale: No such file or directory
 
2017-11-01 18:34:37 140273120094400 [Note] /usr/sbin/mysqld (mysqld 10.2.10-MariaDB-10.2.10+maria~stretch) starting as process 14433 ...
 
2017-11-01 18:34:37 140273120094400 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2017-11-01 18:34:37 140273120094400 [Note] InnoDB: Uses event mutexes
 
2017-11-01 18:34:37 140273120094400 [Note] InnoDB: Compressed tables use zlib 1.2.8
 
2017-11-01 18:34:37 140273120094400 [Note] InnoDB: Using Linux native AIO
 
2017-11-01 18:34:37 140273120094400 [Note] InnoDB: Number of pools: 1
 
2017-11-01 18:34:37 140273120094400 [Note] InnoDB: Using SSE2 crc32 instructions
 
2017-11-01 18:34:37 140273120094400 [Note] InnoDB: Initializing buffer pool, total size = 256M, instances = 1, chunk size = 128M
 
2017-11-01 18:34:37 140273120094400 [Note] InnoDB: Completed initialization of buffer pool
 
2017-11-01 18:34:37 140272383637248 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
 
2017-11-01 18:34:37 140273120094400 [ERROR] InnoDB: The Auto-extending innodb_system data file './ibdata1' is of a different size 0 pages than specified in the .cnf file: initial 768 pages, max 0 (relevant if non-zero) pages!
 
2017-11-01 18:34:37 140273120094400 [ERROR] InnoDB: Plugin initialization aborted with error Generic error
 
2017-11-01 18:34:38 140273120094400 [Note] InnoDB: Starting shutdown...
 
2017-11-01 18:34:38 140273120094400 [ERROR] Plugin 'InnoDB' init function returned error.
 
2017-11-01 18:34:38 140273120094400 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
 
2017-11-01 18:34:38 140273120094400 [Note] Plugin 'FEEDBACK' is disabled.
 
ERROR: 1146  Table 'mysql.user' doesn't exist
 
2017-11-01 18:34:38 140273120094400 [ERROR] Aborting
 
 
 
/usr/bin/locale: Cannot set LC_CTYPE to default locale: No such file or directory
 
/usr/bin/locale: Cannot set LC_ALL to default locale: No such file or directory
 
Created symlink /etc/systemd/system/mysql.service → /lib/systemd/system/mariadb.service.
 
Created symlink /etc/systemd/system/mysqld.service → /lib/systemd/system/mariadb.service.
 
Created symlink /etc/systemd/system/multi-user.target.wants/mariadb.service → /lib/systemd/system/mariadb.service.
 
Job for mariadb.service failed because the control process exited with error code.
 
See "systemctl status mariadb.service" and "journalctl -xe" for details.
 
invoke-rc.d: initscript mysql, action "start" failed.
 
● mariadb.service - MariaDB database server
 
   Loaded: loaded (/lib/systemd/system/mariadb.service; enabled; vendor preset: enabled)
 
  Drop-In: /etc/systemd/system/mariadb.service.d
 
           └─migrated-from-my.cnf-settings.conf
 
   Active: failed (Result: exit-code) since Wed 2017-11-01 18:34:43 CET; 10ms ago
 
  Process: 14950 ExecStart=/usr/sbin/mysqld $MYSQLD_OPTS $_WSREP_NEW_CLUSTER $_WSREP_START_POSITION (code=exited, status=1/FAILURE)
 
  Process: 14791 ExecStartPre=/bin/sh -c [ ! -e /usr/bin/galera_recovery ] && VAR= ||   VAR=`/usr/bin/galera_recovery`; [ $? -eq 0 ]   && systemctl set-environment _WSREP_START_POSITION=$VAR || exit 1 (code=exited, status=0/SUCCESS)
 
  Process: 14787 ExecStartPre=/bin/sh -c systemctl unset-environment _WSREP_START_POSITION (code=exited, status=0/SUCCESS)
 
  Process: 14784 ExecStartPre=/usr/bin/install -m 755 -o mysql -g root -d /var/run/mysqld (code=exited, status=0/SUCCESS)
 
 Main PID: 14950 (code=exited, status=1/FAILURE)
 
   Status: "MariaDB server is down"
 
 
 
Nov 01 18:34:43 vps.ovh.net mysqld[14950]: 2017-11-01 18:34:43 140586479507648 [ERROR] Plugin 'InnoDB' init function returned error.
 
Nov 01 18:34:43 vps.ovh.net mysqld[14950]: 2017-11-01 18:34:43 140586479507648 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
 
Nov 01 18:34:43 vps.ovh.net mysqld[14950]: 2017-11-01 18:34:43 140586479507648 [Note] Plugin 'FEEDBACK' is disabled.
 
Nov 01 18:34:43 vps.ovh.net mysqld[14950]: 2017-11-01 18:34:43 140586479507648 [ERROR] Could not open mysql.plugin table. Some plugin…ot loaded
 
Nov 01 18:34:43 vps.ovh.net mysqld[14950]: 2017-11-01 18:34:43 140586479507648 [ERROR] Unknown/unsupported storage engine: InnoDB
 
Nov 01 18:34:43 vps.ovh.net mysqld[14950]: 2017-11-01 18:34:43 140586479507648 [ERROR] Aborting
 
Nov 01 18:34:43 vps.ovh.net systemd[1]: mariadb.service: Main process exited, code=exited, status=1/FAILURE
 
Nov 01 18:34:43 vps.ovh.net systemd[1]: Failed to start MariaDB database server.
 
Nov 01 18:34:43 vps.ovh.net systemd[1]: mariadb.service: Unit entered failed state.
 
Nov 01 18:34:43 vps.ovh.net systemd[1]: mariadb.service: Failed with result 'exit-code'.
 
Hint: Some lines were ellipsized, use -l to show in full.
 
dpkg: error processing package mariadb-server-10.2 (--configure):
 
 subprocess installed post-installation script returned error exit status 1
 
Setting up libhttp-message-perl (6.11-1) ...
 
Setting up libdbd-mysql-perl (4.041-2) ...
 
Processing triggers for libc-bin (2.24-11+deb9u1) ...
 
Processing triggers for systemd (232-25+deb9u1) ...
 
Errors were encountered while processing:
 
 mariadb-server-10.2
 
E: Sub-process /usr/bin/dpkg returned an error code (1)



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

Please attach all of your cnf files and paste the list of files in the data directory.

Comment by Mark Samman [ 2017-11-01 ]

The log is from a fresh install, so I'm not sure how useful that information is, but here it is:

# ls -lash /var/lib/mysql/
 
total 32K
 
4.0K drwxr-xr-x  3 mysql mysql 4.0K Nov  1 18:34 .
 
4.0K drwxr-xr-x 28 root  root  4.0K Nov  1 18:34 ..
 
 16K -rw-rw----  1 mysql mysql  16K Nov  1 18:34 aria_log.00000001
 
4.0K -rw-rw----  1 mysql mysql   52 Nov  1 18:34 aria_log_control
 
   0 -rw-r--r--  1 root  root     0 Nov  1 18:34 debian-10.2.flag
 
   0 -rw-rw----  1 mysql mysql    0 Nov  1 18:34 ibdata1
 
4.0K drwx------  2 mysql root  4.0K Nov  1 18:34 mysql

my.cnf:

# MariaDB database server configuration file.
 
#
 
# You can copy this file to one of:
 
# - "/etc/mysql/my.cnf" to set global options,
 
# - "~/.my.cnf" to set user-specific options.
 
# 
# One can use all long options that the program supports.
 
# Run program with --help to get a list of available options and with
 
# --print-defaults to see which it would actually understand and use.
 
#
 
# For explanations see
 
# http://dev.mysql.com/doc/mysql/en/server-system-variables.html
 
 
 
# This will be passed to all mysql clients
 
# It has been reported that passwords should be enclosed with ticks/quotes
 
# escpecially if they contain "#" chars...
 
# Remember to edit /etc/mysql/debian.cnf when changing the socket location.
 
[client]
 
port		= 3306
 
socket		= /var/run/mysqld/mysqld.sock
 
 
 
# Here is entries for some specific programs
 
# The following values assume you have at least 32M ram
 
 
 
# This was formally known as [safe_mysqld]. Both versions are currently parsed.
 
[mysqld_safe]
 
socket		= /var/run/mysqld/mysqld.sock
 
nice		= 0
 
 
 
[mysqld]
 
#
 
# * Basic Settings
 
#
 
user		= mysql
 
pid-file	= /var/run/mysqld/mysqld.pid
 
socket		= /var/run/mysqld/mysqld.sock
 
port		= 3306
 
basedir		= /usr
 
datadir		= /var/lib/mysql
 
tmpdir		= /tmp
 
lc_messages_dir	= /usr/share/mysql
 
lc_messages	= en_US
 
skip-external-locking
 
#
 
# Instead of skip-networking the default is now to listen only on
 
# localhost which is more compatible and is not less secure.
 
bind-address		= 127.0.0.1
 
#
 
# * Fine Tuning
 
#
 
max_connections		= 100
 
connect_timeout		= 5
 
wait_timeout		= 600
 
max_allowed_packet	= 16M
 
thread_cache_size       = 128
 
sort_buffer_size	= 4M
 
bulk_insert_buffer_size	= 16M
 
tmp_table_size		= 32M
 
max_heap_table_size	= 32M
 
#
 
# * MyISAM
 
#
 
# This replaces the startup script and checks MyISAM tables if needed
 
# the first time they are touched. On error, make copy and try a repair.
 
myisam_recover_options = BACKUP
 
key_buffer_size		= 128M
 
#open-files-limit	= 2000
 
table_open_cache	= 400
 
myisam_sort_buffer_size	= 512M
 
concurrent_insert	= 2
 
read_buffer_size	= 2M
 
read_rnd_buffer_size	= 1M
 
#
 
# * Query Cache Configuration
 
#
 
# Cache only tiny result sets, so we can fit more in the query cache.
 
query_cache_limit		= 128K
 
query_cache_size		= 64M
 
# for more write intensive setups, set to DEMAND or OFF
 
#query_cache_type		= DEMAND
 
#
 
# * Logging and Replication
 
#
 
# Both location gets rotated by the cronjob.
 
# Be aware that this log type is a performance killer.
 
# As of 5.1 you can enable the log at runtime!
 
#general_log_file        = /var/log/mysql/mysql.log
 
#general_log             = 1
 
#
 
# Error logging goes to syslog due to /etc/mysql/conf.d/mysqld_safe_syslog.cnf.
 
#
 
# we do want to know about network errors and such
 
log_warnings		= 2
 
#
 
# Enable the slow query log to see queries with especially long duration
 
#slow_query_log[={0|1}]
 
slow_query_log_file	= /var/log/mysql/mariadb-slow.log
 
long_query_time = 10
 
#log_slow_rate_limit	= 1000
 
log_slow_verbosity	= query_plan
 
 
 
#log-queries-not-using-indexes
 
#log_slow_admin_statements
 
#
 
# The following can be used as easy to replay backup logs or for replication.
 
# note: if you are setting up a replication slave, see README.Debian about
 
#       other settings you may need to change.
 
#server-id		= 1
 
#report_host		= master1
 
#auto_increment_increment = 2
 
#auto_increment_offset	= 1
 
log_bin			= /var/log/mysql/mariadb-bin
 
log_bin_index		= /var/log/mysql/mariadb-bin.index
 
# not fab for performance, but safer
 
#sync_binlog		= 1
 
expire_logs_days	= 10
 
max_binlog_size         = 100M
 
# slaves
 
#relay_log		= /var/log/mysql/relay-bin
 
#relay_log_index	= /var/log/mysql/relay-bin.index
 
#relay_log_info_file	= /var/log/mysql/relay-bin.info
 
#log_slave_updates
 
#read_only
 
#
 
# If applications support it, this stricter sql_mode prevents some
 
# mistakes like inserting invalid dates etc.
 
#sql_mode		= NO_ENGINE_SUBSTITUTION,TRADITIONAL
 
#
 
# * InnoDB
 
#
 
# InnoDB is enabled by default with a 10MB datafile in /var/lib/mysql/.
 
# Read the manual for more InnoDB related options. There are many!
 
default_storage_engine	= InnoDB
 
# you can't just change log file size, requires special procedure
 
#innodb_log_file_size	= 50M
 
innodb_buffer_pool_size	= 256M
 
innodb_log_buffer_size	= 8M
 
innodb_file_per_table	= 1
 
innodb_open_files	= 400
 
innodb_io_capacity	= 400
 
innodb_flush_method	= O_DIRECT
 
#
 
# * Security Features
 
#
 
# Read the manual, too, if you want chroot!
 
# chroot = /var/lib/mysql/
 
#
 
# For generating SSL certificates I recommend the OpenSSL GUI "tinyca".
 
#
 
# ssl-ca=/etc/mysql/cacert.pem
 
# ssl-cert=/etc/mysql/server-cert.pem
 
# ssl-key=/etc/mysql/server-key.pem
 
 
 
#
 
# * Galera-related settings
 
#
 
[galera]
 
# Mandatory settings
 
#wsrep_on=ON
 
#wsrep_provider=
 
#wsrep_cluster_address=
 
#binlog_format=row
 
#default_storage_engine=InnoDB
 
#innodb_autoinc_lock_mode=2
 
#
 
# Allow server to accept connections on all interfaces.
 
#
 
#bind-address=0.0.0.0
 
#
 
# Optional setting
 
#wsrep_slave_threads=1
 
#innodb_flush_log_at_trx_commit=0
 
 
 
[mysqldump]
 
quick
 
quote-names
 
max_allowed_packet	= 16M
 
 
 
[mysql]
 
#no-auto-rehash	# faster start of mysql but no tab completion
 
 
 
[isamchk]
 
key_buffer		= 16M
 
 
 
#
 
# * IMPORTANT: Additional settings that can override those from this file!
 
#   The files must end with '.cnf', otherwise they'll be ignored.
 
#
 
!includedir /etc/mysql/conf.d/

Comment by Elena Stepanova [ 2017-11-01 ]

Thanks.
Well, it doesn't lie at least, ibdata1 is indeed of zero size.
Could it be that there is a disk space problem at /var/lib/mysql, or whatever security protection that does not allow to write there properly?
What happens if you do

sudo rm -rf /var/lib/mysql/*
 
sudo mysql_install_db

?

Comment by Mark Samman [ 2017-11-01 ] 

root@vps334402:~# rm -rf /var/lib/mysql/*
 
root@vps334402:~# mysql_install_db
 
Installing MariaDB/MySQL system tables in '/var/lib/mysql' ...
 
2017-11-01 19:35:41 140540184721600 [ERROR] InnoDB: preallocating 12582912 bytes for file ./ibdata1 failed with error 22
 
2017-11-01 19:35:41 140540184721600 [ERROR] InnoDB: Could not set the file size of './ibdata1'. Probably out of disk space
 
2017-11-01 19:35:41 140540184721600 [ERROR] InnoDB: Database creation was aborted with error Generic error. You may need to delete the ibdata1 file before trying to start up again.
 
2017-11-01 19:35:41 140540184721600 [ERROR] Plugin 'InnoDB' init function returned error.
 
2017-11-01 19:35:41 140540184721600 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
 
2017-11-01 19:35:41 140540184721600 [ERROR] Unknown/unsupported storage engine: InnoDB
 
2017-11-01 19:35:41 140540184721600 [ERROR] Aborting
 
 
 
 
 
Installation of system tables failed!  Examine the logs in
 
/var/lib/mysql for more information.
 
 
 
The problem could be conflicting information in an external
 
my.cnf files. You can ignore these by doing:
 
 
 
    shell> /usr/bin/mysql_install_db --defaults-file=~/.my.cnf
 
 
 
You can also try to start the mysqld daemon with:
 
 
 
    shell> /usr/sbin/mysqld --skip-grant --general-log &
 
 
 
and use the command line tool /usr/bin/mysql
 
to connect to the mysql database and look at the grant tables:
 
 
 
    shell> /usr/bin/mysql -u root mysql
 
    mysql> show tables;
 
 
 
Try 'mysqld --help' if you have problems with paths.  Using
 
--general-log gives you a log in /var/lib/mysql that may be helpful.
 
 
 
The latest information about mysql_install_db is available at
 
https://mariadb.com/kb/en/installing-system-tables-mysql_install_db
 
MariaDB is hosted on launchpad; You can find the latest source and
 
email lists at http://launchpad.net/maria
 
 
 
Please check all of the above before submitting a bug report
 
at http://mariadb.org/jira

Comment by Mark Samman [ 2017-11-01 ]

df -h:

root@vps334402:~# df -h
 
Filesystem      Size  Used Avail Use% Mounted on
 
udev            3.8G     0  3.8G   0% /dev
 
tmpfs           780M   17M  764M   3% /run
 
/dev/vda1        40G   25G   14G  66% /
 
tmpfs           3.9G     0  3.9G   0% /dev/shm
 
tmpfs           5.0M     0  5.0M   0% /run/lock
 
tmpfs           3.9G     0  3.9G   0% /sys/fs/cgroup
 
tmpfs           780M     0  780M   0% /run/user/0

The error looks similar to the issue I had on the other server. Note that installing MariaDB 10.1 worked fine, and 10.2.9 was also working fine until I upgraded to 10.2.10.

Comment by Elena Stepanova [ 2017-11-01 ]

marko, do you have an idea on what might have changed in 10.2.10 in this regard?
I tried to reproduce it on our Stretch VM, but it works all right there.

Maybe related to MDEV-14132, the cause and/or the fix?

Samman, what file system type is the datadir on?

Comment by Mark Samman [ 2017-11-01 ]

The file system is ext3

Comment by Elena Stepanova [ 2017-11-01 ]

Thanks, it is indeed reproducible on Stretch with ext3 and innodb_flush_method=O_DIRECT. Probably not only on Stretch.

Samman, can you try to disable O_DIRECT in the config? Hopefully it will help as a workaround, for now.

Comment by Mark Samman [ 2017-11-01 ]

Commenting out innodb_flush_method in my.cnf seems to do the trick.

Comment by Marko Mäkelä [ 2017-11-02 ]

This regression is related to some InnoDB I/O code refactoring.

There was some duplicated code for extending InnoDB files, in os_file_set_size() and fil_space_extend_must_retry().

When wlad was working on fixing MDEV-13941, he decided to clean up the code. Unfortunately, he was unaware of the changes that had been made to the GNU libc function posix_fallocate() over time.

While the old code had a fallback to write NUL bytes to the file in case posix_fallocate() returned EINVAL, the new code lacked this fallback. Some versions of posix_fallocate() in the GNU libc would fall back to calling pwrite() if the fallocate() system call fails.

Apparently, under some circumstances this emulation is disabled. (In the libc-2.24.so on my Debian GNU/Linux unstable system, I see that posix_fallocate() invokes the ftruncate syscall, and on the -EOPNOTSUPP return value falls back to internal_fallocate() that uses ftruncate(), pread() and pwrite().)
The ext3 file system probably does not support the needed fallocate() functionality due to the file mode, and therefore it likely returned -EINVAL, which would cause posix_fallocate() to return EINVAL.

With innodb_flush_method=O_DIRECT or innodb_flush_method=O_DIRECT_NO_FSYNC InnoDB would invoke os_file_set_nocache(), which translates to fcntl(fd, F_SETFL, O_DIRECT). I did not find the exact point where -EINVAL would be returned by the Linux file system code (fs/ext4/extents.c seems to handle also ext3 nowadays), but I think that it is plausible that setting O_DIRECT may cause the fallocate() system call to fail on ext3.

Also, some versions of the pwrite() fallback code in posix_fallocate() apparently had a bug that would cause the pre-existing part of the file to be overwritten with zeroes (causing data corruption). This one was caught and fixed as MDEV-14132 before the 10.2.10 release.

Comment by Marko Mäkelä [ 2017-11-02 ]

I tried to look where the Linux kernel would return -EINVAL for fallocate(), but I could not find it. All I could find is that it should return -EOPNOTSUPP. Neither ext2 nor ext3 implemented fallocate(). It seems that the ext4_fallocate() is correctly returning -EOPNOTSUPP for ext3 file systems.
Side note: ext3 support was removed in Linux 4.3.0, and now the ext4 driver is being used for ext3.
wlad suggested that the problem might be in the GNU libc implementation of posix_fallocate(), and he seems to be right, as demonstrated by this strace output collected from a Linux 4.9.0 kernel by elenst:

fallocate(4, 0, 0, 12582912)            = -1 EOPNOTSUPP (Operation not supported)
 
fcntl(4, F_GETFL)                       = 0xc002 (flags O_RDWR|O_DIRECT|O_LARGEFILE)
 
fstat(4, {st_mode=S_IFREG|0660, st_size=0, ...}) = 0
 
fstatfs(4, {f_type=EXT2_SUPER_MAGIC, f_bsize=4096, f_blocks=5126157, f_bfree=4605044, f_bavail=4342985, f_files=1310720, f_ffree=1303159, f_fsid={val=[1470644214, 2964447716]}, f_namelen=255, f_frsize=4096, f_flags=ST_VALID|ST_RELATIME}) = 0
 
pwrite64(4, "\0", 1, 4095)              = -1 EINVAL (Invalid argument)
 
clock_gettime(CLOCK_REALTIME, {tv_sec=1509631447, tv_nsec=707693773}) = 0
 
write(2, "2017-11-02 10:04:07 139962507741"..., 1212017-11-02 10:04:07 139962507741376 [ERROR] InnoDB: preallocating 12582912 bytes for file ./ibdata1 failed with error 22
 
) = 121

The posix_fallocate() code is calling pwrite(fd, "", 1, aligned_offset-1) to extend the file by one page. This will not work in O_DIRECT mode, because both the buffer and the write size must be aligned to the file system block size.

This explains why we have to handle the EINVAL return value from the GNU posix_fallocate(). The fallback code in InnoDB should be compatible with O_DIRECT, provided that no file system block size is bigger than innodb_page_size.

Comment by Marko Mäkelä [ 2017-11-03 ]

There were several issues with the posix_fallocate() call, many of which I fixed as part of MDEV-11520.

In my refactoring of the code in MariaDB 5.5, 10.0 and 10.1, I made the mistake that an EINVAL return value from posix_fallocate() would be treated as a hard error, and we would not fall back to writing NUL bytes in a pwrite() loop.

Because the parameter innodb_use_fallocate was OFF by default until 10.2 deprecated the parameter and treated it as if it is always ON, this issue does not affect older MariaDB releases in the same way.

In 5.5, 10.0, 10.1, if you ask for innodb_use_fallocate, maybe you really should ensure that the file system supports that. If you fail to do that, and if also O_DIRECT is enabled, you would get the same error as the reported error on 10.2.10.

I already pushed a fix for MariaDB 10.2.11, and I plan to fix this bug in MariaDB 10.1.29, but not in 5.5 or 10.0.

Comment by Marko Mäkelä [ 2017-11-03 ]

Originally, as part of MDEV-4338 (MariaDB 5.5.37, 10.0.11, 10.1.0) the function posix_fallocate() was used incorrectly: only the return value -1 was treated as an error. So, an EINVAL return value would have been ignored, and the file would not have been extended. This incorrect code was duplicated in MDEV-5746.

MDEV-11520 introduced almost correct error handling for posix_fallocate(): the only thing that was missing was the fallback for the EINVAL return value.

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