fallocate with FALLOC_FL_ZERO_RANGE produces zero-size files on zfs in Jammy

Bug #1969247 reported by Lena Voytek
138
This bug affects 18 people
Affects Status Importance Assigned to Milestone
Native ZFS for Linux
Fix Released
Unknown
mysql-8.0 (Ubuntu)
Invalid
Undecided
Unassigned
zfs-linux (Ubuntu)
Fix Released
High
Unassigned
Jammy
Fix Released
Undecided
Unassigned

Bug Description

[Summary]

When running Jammy on zfs or LXD with a zfs pool on a Jammy host, fallocate creates a zero-sized file.

The issue was originally found when installing mysql on LXD, where fallocate would create a zero-sized ib_logfile1 file. The original information in this bug is based on that.

[Steps to Reproduce]

touch foo.img
fallocate -z -l 10M foo.img
ls -la foo.img

On a non-zfs Jammy system this will show something like:
-rw-r--r-- 1 root root 10M ...

while on zfs it will show:
-rw-rw-r-- 1 root root 0 ...

[Original Description]
I came across this error when testing various mysql setups in an LXD container and managed to reproduce it consistently. I'm unable to reproduce on Ubuntu desktop or server though since the prerequisites are probably handled properly there.

ProblemType: Package
DistroRelease: Ubuntu 20.04
Package: mysql-server-8.0 8.0.28-0ubuntu0.20.04.3
ProcVersionSignature: Ubuntu 5.15.0-25.25-generic 5.15.30
Uname: Linux 5.15.0-25-generic x86_64
ApportVersion: 2.20.11-0ubuntu27.23
Architecture: amd64
CasperMD5CheckResult: skip
Date: Fri Apr 15 21:31:09 2022
Dmesg:

ErrorMessage: installed mysql-server-8.0 package post-installation script subprocess returned error exit status 1
KernLog:

Logs.var.log.daemon.log:

MySQLConf.etc.mysql.conf.d.mysql.cnf: [mysql]
MySQLConf.etc.mysql.conf.d.mysqldump.cnf:
 [mysqldump]
 quick
 quote-names
 max_allowed_packet = 16M
MySQLConf.etc.mysql.my.cnf: Error: [Errno 40] Too many levels of symbolic links: '/etc/mysql/my.cnf'
MySQLVarLibDirListing: ['ibdata1', 'ib_logfile0', '#innodb_temp', 'debian-5.7.flag', '#ib_16384_0.dblwr', 'client-cert.pem', 'undo_001', 'server-cert.pem', 'mysql.ibd', '#ib_16384_1.dblwr', 'client-key.pem', 'ca-key.pem', 'sys', 'private_key.pem', 'mysql', 'undo_002', 'binlog.index', 'performance_schema', 'ib_buffer_pool', 'auto.cnf', 'ib_logfile1', 'public_key.pem', 'ca.pem', 'server-key.pem']
ProcCmdline: BOOT_IMAGE=/boot/vmlinuz-5.15.0-25-generic root=UUID=93666562-b5e4-4fb4-ba8c-7b42a3e6bf61 ro quiet splash mem_sleep_default=deep vt.handoff=7
Python3Details: /usr/bin/python3.8, Python 3.8.10, python3-minimal, 3.8.2-0ubuntu2
PythonDetails: N/A
RelatedPackageVersions:
 dpkg 1.19.7ubuntu3
 apt 2.0.6
SourcePackage: mysql-8.0
Title: package mysql-server-8.0 8.0.28-0ubuntu0.20.04.3 failed to install/upgrade: installed mysql-server-8.0 package post-installation script subprocess returned error exit status 1
UpgradeStatus: No upgrade log present (probably fresh install)

Revision history for this message
Lena Voytek (lvoytek) wrote :
Revision history for this message
Lena Voytek (lvoytek) wrote (last edit ):

Steps to reproduce:

# lxc launch images:ubuntu/focal test-mysql
# lxc exec test-mysql bash

# apt update && apt dist-upgrade -y

# apt install mysql-server

Lena Voytek (lvoytek)
summary: - mysql-server install crashes after installing mysql-common and
- libmysqlclient21 first
+ mysql-server install crashes in LXD container
description: updated
Revision history for this message
Lena Voytek (lvoytek) wrote : Re: mysql-server install crashes in LXD container

This affects Focal, Impish, and Jammy (not Bionic).
I figured out that the error only shows up on my laptop (on Jammy) though.
Meanwhile my Desktop (on Focal) installs it successfully for all.
Both systems are running the same LXD snap version 5.0.0-e478009 (latest/stable).

Lena Voytek (lvoytek)
summary: - mysql-server install crashes in LXD container
+ mysql-server install crashes in LXD container on Jammy host
Revision history for this message
Lena Voytek (lvoytek) wrote : Re: mysql-server install crashes in LXD container on Jammy host

Confirmed by others with Jammy host systems and by me on a second Jammy host system

Changed in mysql-8.0 (Ubuntu):
status: New → Confirmed
assignee: nobody → Lena Voytek (lvoytek)
Revision history for this message
Sergio Durigan Junior (sergiodj) wrote :

I was also able to confirm this by using a Jammy VM (launched with lxd) and then launching a Focal container inside it.

Revision history for this message
Lena Voytek (lvoytek) wrote :

This seems to be due to a zfs regression when running fallocate, causing mysql's initialization to produce an ib_logfile1 of size 0:

1893 fallocate(3, FALLOC_FL_ZERO_RANGE, 0, 50331648) = 0

Revision history for this message
Andreas Hasenack (ahasenack) wrote :

I'm suspecting fallocate() on zfs.

To reproduce, one can follow these steps:

rm -rf /var/lib/mysql/*
mysqld --initialize

This will produce a zero-sized file:
# ll /var/lib/mysql/ib_logfile1
-rw-r----- 1 mysql mysql 0 Apr 18 17:37 /var/lib/mysql/ib_logfile1

Attempting to start mysql now will fail with this error:
2022-04-18T17:41:30.181861Z 1 [ERROR] [MY-012963] [InnoDB] Log file ./ib_logfile1 is of different size 0 bytes than other log files 17809408 bytes!

On a working system, that file is not zero-sized.

straceing mysqld --initialize shows:
2253 openat(AT_FDCWD, "./ib_logfile1", O_RDWR|O_CREAT|O_EXCL, 0640) = 3
2253 fcntl(3, F_SETLK, {l_type=F_WRLCK, l_whence=SEEK_SET, l_start=0, l_len=0}) = 0
2253 fallocate(3, FALLOC_FL_ZERO_RANGE, 0, 50331648) = 0
2253 fsync(3) = 0
2253 close(3) = 0

There have been previous bugs with zfs and fallocate():
https://bugs.launchpad.net/ubuntu/+source/libvirt/+bug/1847105
https://github.com/openzfs/zfs/issues/326

I tried --innodb-extend-and-initialize and --skip-innodb-extend-and-initialize, from https://dev.mysql.com/worklog/task/?id=13782, but both ended up using fallocate().

A quick attempt with using the dir backend for lxd worked. Further investigation needs to be done.

Revision history for this message
Lena Voytek (lvoytek) wrote (last edit ):

mysql's install also fails with the same error when using a native Jammy Desktop with zfs. I can also confirm fallocate fails on this system as it produces zero-size files on its own.

I'm going to mark mysql invalid here and set this up as a kernel bug for zfs

Changed in mysql-8.0 (Ubuntu):
status: Confirmed → Invalid
assignee: Lena Voytek (lvoytek) → nobody
Changed in zfs-linux (Ubuntu):
status: New → Confirmed
summary: - mysql-server install crashes in LXD container on Jammy host
+ fallocate produces zero-size files on zfs in Jammy
Lena Voytek (lvoytek)
summary: - fallocate produces zero-size files on zfs in Jammy
+ fallocate with FALLOC_FL_ZERO_RANGE produces zero-size files on zfs in
+ Jammy
description: updated
Changed in zfs:
status: Unknown → New
Revision history for this message
Dimitri John Ledkov (xnox) wrote :

given how zfs works, to me this is normal and expected.

Also this is expected on btrfs, and on xfs with cow turned on.

zfs is copy on write filesystem, thus calling fallocate to "reserve" a large amount of free space doesn't make sense. As the created file is immutable in zfs, and any writes to it will be written to a newly allocated quota in the zvol.

There is an option to tune the behaviour of fallocate https://manpages.ubuntu.com/manpages/jammy/en/man4/zfs.4.html

zfs_fallocate_reserve_percent=110% (uint)

Since ZFS is a copy-on-write filesystem with snapshots, blocks cannot be preallocated for a file in order to guarantee that later writes will not run out of space. Instead, fallocate(2) space preallocation only checks that sufficient space is currently available in the pool or the user's project quota allocation, and then creates a sparse file of the requested size. The requested space is multiplied by zfs_fallocate_reserve_percent to allow additional space for indirect blocks and other internal metadata. Setting this to 0 disables support for fallocate(2) and causes it to return EOPNOTSUPP.

This functionality / behaviour was added in zfs-0.8.0-847-gf734301d22 upstream, this is why you don't see it with bionic GA kernel, but do observe this new behaviour with bionic HWE kernels or newer.

If things are using fallocate, on top of zfs, they should be aware that fallocate on zfs proofs that the there is enough quota in the zvol pool. Thus mysql needs to gain zfs specific knowledge w.r.t. this.

Alternatively, you can disable fallocate support on your system by adding modprobe.d snippet to set zfs module option zfs_fallocate_reserve_percent to zero.

Revision history for this message
Dimitri John Ledkov (xnox) wrote :

However there is now also this: https://github.com/openzfs/zfs/pull/13338/files

which seems to indicate that my / zfs understanding of the fallocate kernel flags are not what is done on other filesystems (and expected by stuff).

If needed, we can look into pulling in https://github.com/openzfs/zfs/pull/13338/files

Please let me know if setting zfs_fallocate_reserve_percent=0 is a workaround for now.

Revision history for this message
Dimitri John Ledkov (xnox) wrote :

imho, mysql should still gain zfs specific knowledge that doing fallocate on CoW filesystems doesn't do what one expects it to do.

Changed in mysql-8.0 (Ubuntu):
status: Invalid → Triaged
Changed in zfs-linux (Ubuntu):
importance: Undecided → Wishlist
Revision history for this message
Andreas Hasenack (ahasenack) wrote :

The impish kernel returns "not supported" when fallocate is used in the way mysql does it. That makes mysql aware of the problem, and switch strategies, and it works.

The jammy kernel is saying all is fine with the call and its results, but it isn't. Mysql, or any userspace, shouldn't be second guessing the kernel.

> Please let me know if setting zfs_fallocate_reserve_percent=0 is a workaround for now.

We will test it and put in the release notes as a workaround if it works.

Revision history for this message
Andreas Hasenack (ahasenack) wrote :

Impish kernel on zfs:

andreas@nsnx:~$ rm foo.img
andreas@nsnx:~$ touch foo.img
andreas@nsnx:~$ fallocate -z -l 10M foo.img
fallocate: fallocate failed: Operation not supported

Jammy kernel on zfs:

root@j1:~# touch foo.img
root@j1:~# fallocate -z -l 10M foo.img
root@j1:~# ll foo.img
-rw-r--r-- 1 root root 0 Apr 18 18:06 foo.img

Jammy kernel on ext4:

andreas@nsn7:~$ touch foo.img
andreas@nsn7:~$ fallocate -z -l 10M foo.img
andreas@nsn7:~$ l foo.img
-rw-rw-r-- 1 andreas andreas 10M abr 19 09:32 foo.img
andreas@nsn7:~$

Revision history for this message
Andreas Hasenack (ahasenack) wrote :

I applied zfs_fallocate_reserve_percent=0 to the kernel module, confirmed it was set, but I still see the same incorrect behavior with fallocate:

root@nsn7:/tank/test# rm -f foo.img; touch foo.img; fallocate -z -l 10M foo.img; ls -lah foo.img
-rw-r--r-- 1 root root 0 abr 19 10:35 foo.img

root@nsn7:/tank/test# uname -a
Linux nsn7 5.15.0-25-generic #25-Ubuntu SMP Wed Mar 30 15:54:22 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux

root@nsn7:/tank/test# cat /sys/module/zfs/parameters/zfs_fallocate_reserve_percent
0

Revision history for this message
Andreas Hasenack (ahasenack) wrote :

On jammy, it works on btrfs:

root@nsn7:/mnt# rm -f foo.img; touch foo.img; fallocate -z -l 10M foo.img; ls -lah foo.img
-rw-r--r-- 1 root root 10M abr 19 10:46 foo.img

root@nsn7:/mnt# mount -t btrfs
/btrfs.img on /mnt type btrfs (rw,relatime,ssd,space_cache=v2,subvolid=5,subvol=/)

Revision history for this message
Dimitri John Ledkov (xnox) wrote :

yeap that's bad.

Changed in zfs-linux (Ubuntu):
status: Confirmed → Triaged
importance: Wishlist → High
Changed in mysql-8.0 (Ubuntu):
status: Triaged → Invalid
Revision history for this message
Dimitri John Ledkov (xnox) wrote :

I've picked up the PR into a bileto ppa

https://launchpad.net/~ci-train-ppa-service/+archive/ubuntu/4831

it seems to work for me correctly. If one has MOK dkms key enrolled or secureboot disabled, one can use zfs-dkms package from the above ppa as a solution. Please test it and let me know.

I will try to SRU that, but it may take a kernel sru cycle to fully land.

Revision history for this message
Lena Voytek (lvoytek) wrote :

zfs-dkms ended up working for me using LXD with the following test case:

sudo add-apt-repository ppa:ci-train-ppa-service/4831
sudo apt update
sudo apt upgrade
sudo apt install zfs-dkms

lxd init
lxc launch images:ubuntu/focal test-mysql
lxc exec test-mysql bash

# apt update && apt dist-upgrade -y
# apt install mysql-server

# touch foo.img
# fallocate -z -l 10M foo.img
# ll foo.img

-rw-r--r-- 1 root root 10485760 ...

Changed in zfs:
status: New → Fix Released
Changed in zfs-linux (Ubuntu):
status: Triaged → In Progress
Revision history for this message
Andy Whitcroft (apw) wrote : Please test proposed package

Hello Lena, or anyone else affected,

Accepted zfs-linux into jammy-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/zfs-linux/2.1.4-0ubuntu0.1 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation on how to enable and use -proposed. Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested, what testing has been performed on the package and change the tag from verification-needed-jammy to verification-done-jammy. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed-jammy. In either case, without details of your testing we will not be able to proceed.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance for helping!

N.B. The updated package will be released to -updates after the bug(s) fixed by this package have been verified and the package has been in -proposed for a minimum of 7 days.

Changed in zfs-linux (Ubuntu Jammy):
status: New → Fix Committed
Revision history for this message
Lena Voytek (lvoytek) wrote :

The update fixed my lxd containers using the same method from above on my zfs jammy system. However it did not fix the base system itself. When I try to install mysql-server or run the fallocate test it still fails. Are there additional steps, other than just apt updating and upgrading, that I or other users will have to take to make sure it works on the base system once the fix is released?

Thanks

Revision history for this message
Launchpad Janitor (janitor) wrote :

This bug was fixed in the package zfs-linux - 2.1.4-0ubuntu0.1

---------------
zfs-linux (2.1.4-0ubuntu0.1) jammy; urgency=medium

  * New upstream point release (LP: #1969482):
    - bufixes
    - performance fixes
    - v5.17 & v5.18 compat
    - scrub services
    - fix fallocate LP: #1969247

 -- Dimitri John Ledkov <email address hidden> Tue, 19 Apr 2022 15:44:23 +0100

Changed in zfs-linux (Ubuntu):
status: In Progress → Fix Released
Lena Voytek (lvoytek)
tags: added: verification-done-jammy
Revision history for this message
KaMZaTa (kamzata) wrote :

It still doesn't work. I'm not able to start mysql-server or mariadb on Ubuntu 22.04 LXC Container running on Proxmox 7.2-3 with ZFS.

Revision history for this message
Lena Voytek (lvoytek) wrote :

I've done some more testing with Jammy and can confirm this does not fully fix the issue. I also tried to install mysql on kinetic now that the fix is 'released' and it still fails. I think more needs to be done with this to get fallocate working on zfs

tags: added: verification-failed-jammy
removed: verification-done-jammy
Revision history for this message
Lena Voytek (lvoytek) wrote :

Added the apport output of kinetic in its current state to a duplicate bug: https://pad.lv/1975513

Revision history for this message
andrum99 (andrum99) wrote (last edit ):

Unless you've also installed zfs-dkms and built the ZFS kernel modules using DKMS, you've not installed the fix completely on your system.

Revision history for this message
Lena Voytek (lvoytek) wrote :

That's fair, it does seem to work when using that method. However, for this to be an actual fix it needs to work out of the box. Since mysql still fails to install and fallocate still fails on kinetic after installing with zfs, it isn't ready for normal users yet

Revision history for this message
andrum99 (andrum99) wrote : Re: [Bug 1969247] Re: fallocate with FALLOC_FL_ZERO_RANGE produces zero-size files on zfs in Jammy
Download full text (3.6 KiB)

Once an updated kernel is made available, this will just work.

On Mon, 23 May 2022, 18:40 Lena Voytek, <email address hidden> wrote:

> That's fair, it does seem to work when using that method. However, for
> this to be an actual fix it needs to work out of the box. Since mysql
> still fails to install and fallocate still fails on kinetic after
> installing with zfs, it isn't ready for normal users yet
>
> --
> You received this bug notification because you are subscribed to the bug
> report.
> https://bugs.launchpad.net/bugs/1969247
>
> Title:
> fallocate with FALLOC_FL_ZERO_RANGE produces zero-size files on zfs in
> Jammy
>
> Status in Native ZFS for Linux:
> Fix Released
> Status in mysql-8.0 package in Ubuntu:
> Invalid
> Status in zfs-linux package in Ubuntu:
> Fix Released
> Status in zfs-linux source package in Jammy:
> Fix Committed
>
> Bug description:
> [Summary]
>
> When running Jammy on zfs or LXD with a zfs pool on a Jammy host,
> fallocate creates a zero-sized file.
>
> The issue was originally found when installing mysql on LXD, where
> fallocate would create a zero-sized ib_logfile1 file. The original
> information in this bug is based on that.
>
> [Steps to Reproduce]
>
> touch foo.img
> fallocate -z -l 10M foo.img
> ls -la foo.img
>
> On a non-zfs Jammy system this will show something like:
> -rw-r--r-- 1 root root 10M ...
>
> while on zfs it will show:
> -rw-rw-r-- 1 root root 0 ...
>
> [Original Description]
> I came across this error when testing various mysql setups in an LXD
> container and managed to reproduce it consistently. I'm unable to reproduce
> on Ubuntu desktop or server though since the prerequisites are probably
> handled properly there.
>
> ProblemType: Package
> DistroRelease: Ubuntu 20.04
> Package: mysql-server-8.0 8.0.28-0ubuntu0.20.04.3
> ProcVersionSignature: Ubuntu 5.15.0-25.25-generic 5.15.30
> Uname: Linux 5.15.0-25-generic x86_64
> ApportVersion: 2.20.11-0ubuntu27.23
> Architecture: amd64
> CasperMD5CheckResult: skip
> Date: Fri Apr 15 21:31:09 2022
> Dmesg:
>
> ErrorMessage: installed mysql-server-8.0 package post-installation
> script subprocess returned error exit status 1
> KernLog:
>
> Logs.var.log.daemon.log:
>
> MySQLConf.etc.mysql.conf.d.mysql.cnf: [mysql]
> MySQLConf.etc.mysql.conf.d.mysqldump.cnf:
> [mysqldump]
> quick
> quote-names
> max_allowed_packet = 16M
> MySQLConf.etc.mysql.my.cnf: Error: [Errno 40] Too many levels of
> symbolic links: '/etc/mysql/my.cnf'
> MySQLVarLibDirListing: ['ibdata1', 'ib_logfile0', '#innodb_temp',
> 'debian-5.7.flag', '#ib_16384_0.dblwr', 'client-cert.pem', 'undo_001',
> 'server-cert.pem', 'mysql.ibd', '#ib_16384_1.dblwr', 'client-key.pem',
> 'ca-key.pem', 'sys', 'private_key.pem', 'mysql', 'undo_002',
> 'binlog.index', 'performance_schema', 'ib_buffer_pool', 'auto.cnf',
> 'ib_logfile1', 'public_key.pem', 'ca.pem', 'server-key.pem']
> ProcCmdline: BOOT_IMAGE=/boot/vmlinuz-5.15.0-25-generic
> root=UUID=93666562-b5e4-4fb4-ba8c-7b42a3e6bf61 ro quiet splash
> mem_sleep_default=deep vt.handoff=7
> Python3Details: /usr/bin/python3.8, Python 3.8.10, python3-mini...

Read more...

Revision history for this message
Lena Voytek (lvoytek) wrote :

Ah alright, that's fine then. Hopefully the Jammy version can move from proposed to release soon.

Thanks!

tags: added: verification-done-jammy
removed: verification-failed-jammy
Revision history for this message
Lena Voytek (lvoytek) wrote :

Are there any updates on getting this released into Jammy? We've gotten several reports of mysql failing due to this issue

Revision history for this message
Marcos Alano (mhalano) wrote :

@lvoytek

The fix was released 19th, April

Revision history for this message
Lena Voytek (lvoytek) wrote :

The bug was fixed in 2.1.4-0ubuntu0.1 but that version is still in proposed for Jammy. The current release version still seems to be 2.1.2-1ubuntu3.

Revision history for this message
Marcos Alano (mhalano) wrote :

In deed. It's a good question why it is taking so long between proposed and updates repositories. Anyone knows why the delay?

Revision history for this message
Lucas Kanashiro (lucaskanashiro) wrote :

The fix for this bug is already verified but the same upload also contains the fix for this bug which is still not verified:

https://bugs.launchpad.net/ubuntu/+source/zfs-linux/+bug/1969482

That's why it is blocked in jammy-proposed at the moment.

Revision history for this message
Launchpad Janitor (janitor) wrote :

This bug was fixed in the package zfs-linux - 2.1.4-0ubuntu0.1

---------------
zfs-linux (2.1.4-0ubuntu0.1) jammy; urgency=medium

  * New upstream point release (LP: #1969482):
    - bufixes
    - performance fixes
    - v5.17 & v5.18 compat
    - scrub services
    - fix fallocate LP: #1969247

 -- Dimitri John Ledkov <email address hidden> Tue, 19 Apr 2022 15:44:23 +0100

Changed in zfs-linux (Ubuntu Jammy):
status: Fix Committed → Fix Released
Revision history for this message
Brian Murray (brian-murray) wrote : Update Released

The verification of the Stable Release Update for zfs-linux has completed successfully and the package is now being released to -updates. Subsequently, the Ubuntu Stable Release Updates Team is being unsubscribed and will not receive messages about this bug report. In the event that you encounter a regression using the package from -updates please report a new bug using ubuntu-bug and tag the bug report regression-update so we can easily find any regressions.

Revision history for this message
Vasya Pupkin (shadowlmd) wrote :

This bug is still not fixed in Ubuntu 20.04.

Revision history for this message
Vasya Pupkin (shadowlmd) wrote :

Also, MySQL 8.0.30 was released recently in Ubuntu 20.04. This version uses falloate() for redo files. This leads to very hard to recover corruption after MySQL server restart.

https://bugs.mysql.com/bug.php?id=108012

Please fix this in Ubuntu 20.04 ASAP.

Revision history for this message
Martin Richtarsky (mrichtarsky) wrote :
Download full text (3.6 KiB)

I ran into this today on jammy, which I understand should have the fix? Here are my symptoms:

- unattended-upgrades upgraded mysql server:
$ grep upgrade /var/log/dpkg.log | grep mysql
2022-07-30 06:38:00 upgrade mysql-server:all 8.0.29-0ubuntu0.22.04.2 8.0.30-0ubuntu0.22.04.1
2022-07-30 06:38:05 upgrade mysql-client-8.0:amd64 8.0.29-0ubuntu0.22.04.2 8.0.30-0ubuntu0.22.04.1
2022-07-30 06:38:09 upgrade mysql-client-core-8.0:amd64 8.0.29-0ubuntu0.22.04.2 8.0.30-0ubuntu0.22.04.1
2022-07-30 06:38:15 upgrade libmysqlclient21:amd64 8.0.29-0ubuntu0.22.04.2 8.0.30-0ubuntu0.22.04.1
2022-07-30 06:38:20 upgrade mysql-server-8.0:amd64 8.0.29-0ubuntu0.22.04.2 8.0.30-0ubuntu0.22.04.1
2022-07-30 06:38:25 upgrade mysql-server-core-8.0:amd64 8.0.29-0ubuntu0.22.04.2 8.0.30-0ubuntu0.22.04.1

- however, the restart failed:
$ /var/log/mysql/error.log
2022-07-30T06:38:31.591223Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.30-0ubuntu0.22.04.1) starting as process 457250
2022-07-30T06:38:31.646707Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2022-07-30T06:38:35.237627Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2022-07-30T06:38:38.804696Z 4 [System] [MY-013381] [Server] Server upgrade from '80029' to '80030' started.
2022-07-30T06:38:44.914043Z 4 [System] [MY-013381] [Server] Server upgrade from '80029' to '80030' completed.
2022-07-30T06:38:45.097152Z 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed.
2022-07-30T06:38:45.097223Z 0 [System] [MY-013602] [Server] Channel mysql_main configured to support TLS. Encrypted connections are now supported for this channel.
2022-07-30T06:38:45.108326Z 0 [Warning] [MY-011810] [Server] Insecure configuration for --pid-file: Location '/tmp' in the path is accessible to all OS users. Consider choosing a different directory.
2022-07-30T06:38:45.156661Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Socket: /var/run/mysqld/mysqlx.sock
2022-07-30T06:38:45.156821Z 0 [System] [MY-010931] [Server] /usr/sbin/mysqld: ready for connections. Version: '8.0.30-0ubuntu0.22.04.1' socket: '/tmp/tmp.hmxTqM13bi/mysqld.sock' port: 0 (Ubuntu).
2022-07-30T06:38:45.190816Z 0 [System] [MY-013172] [Server] Received SHUTDOWN from user <via user signal>. Shutting down mysqld (Version: 8.0.30-0ubuntu0.22.04.1).
2022-07-30T06:38:47.795072Z 0 [System] [MY-010910] [Server] /usr/sbin/mysqld: Shutdown complete (mysqld 8.0.30-0ubuntu0.22.04.1) (Ubuntu).
2022-07-30T06:38:49.617486Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.30-0ubuntu0.22.04.1) starting as process 458616
2022-07-30T06:38:49.628355Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2022-07-30T06:38:49.749634Z 1 [ERROR] [MY-012962] [InnoDB] The redo log file ./#innodb_redo/#ib_redo6 size 1712128 is not a multiple of innodb_page_size
2022-07-30T06:38:49.749689Z 1 [ERROR] [MY-012930] [InnoDB] Plugin initialization aborted with error Generic error.
2022-07-30T06:38:50.180894Z 1 [ERROR] [MY-010334] [Server] Failed to initialize DD Storage Engine
2022-07-30T06:38:50.181389Z 0 [ERROR] [MY-010020] [Server] Data Dictionary initialization failed.
2022-07-30T06:38:50.1826...

Read more...

Revision history for this message
Lucas Kanashiro (lucaskanashiro) wrote :

There is no task for this bug targeting Ubuntu Focal (20.04), that's why it is not fixed there. Apparently, no one reported this issue there, only in Jammy (22.04). @shadowlmd could you confirm if you are facing the very same issue described on this bug in Focal? If it is another issue please file another bug with details.

Revision history for this message
Lucas Kanashiro (lucaskanashiro) wrote :

@mrichtarsky from the logs, mysql was not able to redo the actions during the upgrade because the size of the ib_redo6 file was not multiple of innodb_page_size. However, the default of innodb_page_size is 16kb (https://dev.mysql.com/doc/refman/8.0/en/server-status-variables.html#statvar_Innodb_page_size), and 1712128/16 = 107008. Did you change the innodb_page_size global value by any chance? If you can share your configuration it might be helpful.

Revision history for this message
Jay Lepore (amazon-compumatter) wrote :

Until such time the fix makes it into mainstream, this hack gets things going again for me.

I took a look at the contents of the directory /var/lib/mysql/#innodb_redo#
There was only a single file there which of course matched the filename identified in the /var/log/mysql/error.log and this was:

-rw-r----- 1 mysql mysql 0 Aug 1 19:10 '#ib_redo0'

I deleted it.

Mysql immediately restarted.

In addition, upon restarting generated these files within that same directory /var/lib/mysql/#innodb_redo#

-rw-r----- 1 mysql mysql 3276800 Aug 1 19:10 '#ib_redo0'
-rw-r----- 1 mysql mysql 3276800 Aug 1 19:10 '#ib_redo10_tmp'
-rw-r----- 1 mysql mysql 3276800 Aug 1 19:10 '#ib_redo11_tmp'
-rw-r----- 1 mysql mysql 3276800 Aug 1 19:10 '#ib_redo12_tmp'
-rw-r----- 1 mysql mysql 3276800 Aug 1 19:10 '#ib_redo13_tmp'
-rw-r----- 1 mysql mysql 3276800 Aug 1 19:10 '#ib_redo14_tmp'
-rw-r----- 1 mysql mysql 3276800 Aug 1 19:10 '#ib_redo15_tmp'
-rw-r----- 1 mysql mysql 3276800 Aug 1 19:10 '#ib_redo16_tmp'
-rw-r----- 1 mysql mysql 3276800 Aug 1 19:10 '#ib_redo17_tmp'
-rw-r----- 1 mysql mysql 3276800 Aug 1 19:10 '#ib_redo18_tmp'
-rw-r----- 1 mysql mysql 3276800 Aug 1 19:10 '#ib_redo19_tmp'
-rw-r----- 1 mysql mysql 3276800 Aug 1 19:10 '#ib_redo1_tmp'
-rw-r----- 1 mysql mysql 3276800 Aug 1 19:10 '#ib_redo20_tmp'
-rw-r----- 1 mysql mysql 3276800 Aug 1 19:10 '#ib_redo21_tmp'
-rw-r----- 1 mysql mysql 3276800 Aug 1 19:10 '#ib_redo22_tmp'
-rw-r----- 1 mysql mysql 3276800 Aug 1 19:10 '#ib_redo23_tmp'
-rw-r----- 1 mysql mysql 3276800 Aug 1 19:10 '#ib_redo24_tmp'
-rw-r----- 1 mysql mysql 3276800 Aug 1 19:10 '#ib_redo25_tmp'
-rw-r----- 1 mysql mysql 3276800 Aug 1 19:10 '#ib_redo26_tmp'
-rw-r----- 1 mysql mysql 3276800 Aug 1 19:10 '#ib_redo27_tmp'
-rw-r----- 1 mysql mysql 3276800 Aug 1 19:10 '#ib_redo28_tmp'
-rw-r----- 1 mysql mysql 3276800 Aug 1 19:10 '#ib_redo29_tmp'
-rw-r----- 1 mysql mysql 3276800 Aug 1 19:10 '#ib_redo2_tmp'
-rw-r----- 1 mysql mysql 3276800 Aug 1 19:10 '#ib_redo30_tmp'
-rw-r----- 1 mysql mysql 3276800 Aug 1 19:10 '#ib_redo31_tmp'
-rw-r----- 1 mysql mysql 3276800 Aug 1 19:10 '#ib_redo3_tmp'
-rw-r----- 1 mysql mysql 3276800 Aug 1 19:10 '#ib_redo4_tmp'
-rw-r----- 1 mysql mysql 3276800 Aug 1 19:10 '#ib_redo5_tmp'
-rw-r----- 1 mysql mysql 3276800 Aug 1 19:10 '#ib_redo6_tmp'
-rw-r----- 1 mysql mysql 3276800 Aug 1 19:10 '#ib_redo7_tmp'
-rw-r----- 1 mysql mysql 3276800 Aug 1 19:10 '#ib_redo8_tmp'
-rw-r----- 1 mysql mysql 3276800 Aug 1 19:10 '#ib_redo9_tmp'

Revision history for this message
Michael Wood (mwood) wrote :

@lucaskanashiro

> However, the default of innodb_page_size is 16kb
> (https://dev.mysql.com/doc/refman/8.0/en/server-status-variables.html#statvar_Innodb_page_size),
> and 1712128/16 = 107008. Did you change the innodb_page_size global
> value by any chance? If you can share your configuration it might be
> helpful.

It's 16kB, not 16B :)

1712128/16384 = 104.5

I have a similar problem. I do not have the InnoDB page size specified in my MySQL config:

2022-08-02T04:25:16.296624Z 1 [ERROR] [MY-012962] [InnoDB] The redo log file ./#innodb_redo/#ib_redo6 size 2908160 is not a multiple of innodb_page_size

2908160/16384 = 177.5

The following Stack Overflow answer has a redo size of 23289856.
23289856/16384 = 1421.5

https://stackoverflow.com/a/73200473/495319

It is suspicious to me that all three of these examples are off by exactly 8k.

@xnox:

> Instead, fallocate(2) space preallocation only checks that sufficient
> space is currently available in the pool or the user's project quota
> allocation, and then creates a sparse file of the requested size.

But it doesn't create a sparse file.

If I create a normal, non-sparse file and a sparse file and then create a third file using fallocate I get the following:

$ dd if=/dev/urandom of=not-sparse bs=1M count=100
100+0 records in
100+0 records out
104857600 bytes (105 MB, 100 MiB) copied, 1.51608 s, 69.2 MB/s
$ dd if=/dev/urandom of=sparse bs=1M seek=100 count=0
0+0 records in
0+0 records out
0 bytes copied, 0.000245428 s, 0.0 kB/s
$ touch fallocated-file; fallocate -z -l 100M fallocated-file
$ ls -lsh not-sparse sparse fallocated-file
1.0K -rw-rw-r-- 1 michael michael 0 2022-08-02 09:30 fallocated-file
101M -rw-rw-r-- 1 michael michael 100M 2022-08-02 08:54 not-sparse
1.0K -rw-rw-r-- 1 michael michael 100M 2022-08-02 08:54 sparse

As you can see, the "not-sparse" file is 100MB, and it's taking up about 100MB on disk (not sure why it's 101MB, but it's clearly not sparse). The "sparse" file is also 100MB, but it is only taking up 1KB on disk.

On the other hand, the "fallocated-file" is zero size.

Revision history for this message
Sergio Durigan Junior (sergiodj) wrote :

Hi Michael,

In order to confirm whether we're talking about the same bug here, I tried to reproduce it. Here's what I did:

1) Grab a Focal machine, up-to-date.

2) Run "lxd init" and make sure to choose "zfs" as the backend format for its storage.

3) Fire up a Focal VM using "lxc launch ubuntu-daily:focal fallocate-focal --vm".

4) Shell into the VM, and perform the steps described in the "Steps to reproduce" section from the description.

Here's what I see:

root@fallocate-focal:~# touch foo.img
root@fallocate-focal:~# fallocate -z -l 10M foo.img
root@fallocate-focal:~# ls -la foo.img
-rw-r--r-- 1 root root 10485760 Aug 4 01:02 foo.img

It seems to me that this is working according to what's expected, at least when we consider the fallocate bug that's been originally fixed in Jammy.

Maybe you're experiencing a different problem?

Revision history for this message
Michael Wood (mwood) wrote :

Hi Sergio

Thanks for the response.

I'm actually running a desktop installation of Jammy (Ubuntu MATE), originally 20.04 and upgraded through the non-LTS releases.

After a dist-upgrade the other day I found that the mysql-server-8.0 package could not be configured and I found errors in the error log like this:

2022-08-02T04:25:16.296624Z 1 [ERROR] [MY-012962] [InnoDB] The redo log file ./#innodb_redo/#ib_redo6 size 2908160 is not a multiple of innodb_page_size

I found this bug which appeared to be related. I tried `fallocate` and discovered that it created a 0 byte file instead of a sparse file of the specified size.

I had a power failure yesterday afternoon. When I try it now, it works as expected!

I'm pretty sure `zfs version` is the same now as it was when I ran into this problem, but somehow the reboot seems to have fixed it.

Revision history for this message
Martin Richtarsky (mrichtarsky) wrote :

@lucaskanashiro: I do not have innodb_page_size set.

Revision history for this message
Dimitri John Ledkov (xnox) wrote :

Hi, the zfs userspace .deb package versions can be out of sync with the kernel driver zfs kernel module version number. This can be seen in the output of

$ zfs version

For example on my test system I have:

$ sudo zfs version
zfs-2.1.4-0ubuntu0.1
zfs-kmod-2.1.5-1ubuntu2

Because I have a newer kernel version, than userspace tooling (I am testing upgrades). Or vice versa.

This particular bug is fixed in zfs 2.1.4-0ubuntu0.1 or higher, which is included in linux 5.15.0-43.46 or higher (or kernels based of it). Thus without upgrading zfs packages, one can reboot into newer kernel, which has never zfs, and things should be fine.

If anyone is having issues, please provide output of:

uname -r
sudo zfs version

Revision history for this message
Martin Richtarsky (mrichtarsky) wrote :

@xnox: I have:

$ uname -r
5.15.0-43-generic
$ sudo zfs version
zfs-2.1.4-0ubuntu0.1
zfs-kmod-2.1.4-0ubuntu0.1

Can you confirm that the bug is not fixed there, since presumably kernel 5.15.0-43 < 5.15.0-43.46?

And is it possible to upgrade the kernel within jammy to get the fix?

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.