open(), rename(), fstat() -> ENOENT #8443

grooverdan · 2022-05-25T05:18:47Z

Version

Windows 11 Pro 22H2 22621.1848
Windows 11 Pro 22631.2506

Microsoft Windows [Version 10.0.19044.1706]
Windows 10 19044.2311

WSL Version

WSL 2
WSL 1

Kernel Version

5.10.102.1

Distro Version

Ubuntu 20.04

Other Software

Docker Desktop (Windows), version 4.8.2

Repro Steps

At a high level:

The calling of the system calls in this sequence:

fd = openat( a file )
rename ( a file, b file);
fstat(fd) results in ENOENT

As the fstat is on a open file descriptor it should return successful and the information about the file opened in the first step.

This sequence works fine on all Linux, BSD, Solaris systems that MariaDB has been running on. An ALTER TABLE is all that's required to trigger this and there's no non-WSL systems affected.

This was reproduced with:

docker run --env MARIADB_ROOT_PASSWORD=bob --env MARIADB_DATABASE=test --env MARIADB_USER=test --env MARIADB_PASSWORD=test --name m107 -d mariadb:10.7.3

docker exec -ti m107 mariadb -u test -ptest test

Past the following SQL on the prompt

-- From: https://jira.mariadb.org/browse/MDEV-24189
create table player_profiles (
--
id                            varchar(40) not null,
name                          varchar(255) not null,
tokens                        integer default 0 not null,
constraint pk_player_profiles primary key (id)
);
 
create table player_report (
id                            varchar(40) not null,
sender_player_id              varchar(40) not null,
target_player_id              varchar(40) not null,
created_at                    datetime(6) not null,
constraint pk_player_report primary key (id)
);
 
create index ix_player_report_sender_player_id on player_report (sender_player_id);
 
-- the next line adds a foreign key, removing this line will prevent a server crash
alter table player_report add constraint fk_player_report_sender_player_id foreign key (sender_player_id) references player_profiles (id) on delete restrict on update restrict;
 
-- server crashes on this query
create index ix_player_report_target_player_id on player_report (target_player_id);

-- https://jira.mariadb.org/browse/MDEV-24189 (another crash, not sure if still there)
rename table player_report to player_report2;
rename table player_report2 to player_report3;

To get a strace:

--cap-add SYS_PTRACE to docker run command line
docker exec m107 sh -c 'apt-get update && apt-get install -y strace'
docker exec m107 strace -f -p1 -s 99 -o /var/lib/mysql/m.strace

Expected Behavior

All SQL successful and no server crashes. show create table player_report should show the result of the table alterations and created indexes.

Actual Behavior

mariadb-crash-1.log

2022-05-16Â 17:28:24Â 6Â [ERROR]Â InnoDB:Â preallocatingÂ 131072Â bytesÂ forÂ fileÂ ./wollysocial/player_report.ibdÂ failedÂ withÂ errorÂ 2
2022-05-16Â 17:28:24Â 0x7f9a1009c700Â Â InnoDB:Â AssertionÂ failureÂ inÂ fileÂ /home/buildbot/buildbot/build/mariadb-10.7.3/storage/innobase/fil/fil0fil.ccÂ lineÂ 606
InnoDB:Â FailingÂ assertion:Â fsizeÂ !=Â os_offset_t(-1)

(evidently wollysocial was the original database name)

Diagnostic Logs

Original bug report: https://jira.mariadb.org/browse/MDEV-28580

extract from mariadb-1.strace


659: 68    openat(AT_FDCWD, "./testdb/#sql-alter-1-9a.ibd", O_RDWR\|O_CREAT\|O_EXCL\|O_CLOEXEC, 0660) = 50
--
..
706: 68    pwrite64(50, "\0", 1, 114687)     = 1
707: 68    fdatasync(50)                     = 0
708: 68    fdatasync(50)                     = 0
..
(no closing of fd 50)
...
740: 68    stat("./testdb/#sql-alter-1-9a.ibd",  <unfinished ...>
744: 68    <... stat resumed>{st_mode=S_IFREG\|0660, st_size=114688, ...}) = 0
 
830: 68    rename("./testdb/#sql-alter-1-9a.ibd", "./testdb/player_report.ibd") = 0
...
 
968: 68    recvfrom(41, "\3-- server crashes on this que....
..
1002: 68    fstat(50, 0x7fd0144c9130)         = -1 ENOENT (No such file or directory)
1003: 68    write(2, "2022-05-19 10:51:51 154 [ERROR] InnoDB: preallocating 131072 bytes for file ./testdb/player_report."..., 123) = 123
1004: 68    fstat(50, 0x7fd0144c92e0)         = -1 ENOENT (No such file or directory)

Note the preallocation ERROR isn't fatal (fallocate not implemented in WSL, and we do a write based fallback`).

My analysis:

In the strace there is no closing of file descriptor 50.

So its looking like the final fstat on an open file descriptor is loosing track of the file because it was renamed earlier. Without this fstat there is a resulting in a -1 filesize (from the error) and the assertion.

Procmon trace from same time as strace: LOGFile3.PML.

The text was updated successfully, but these errors were encountered:

WSL wasn't keeping stack of renamed files (microsoft/WSL#8443) resulting in the fstat calls in os_file_set_size returning ENOENT and no fallocate fallback being possible. Users reported MySQL was ok, and it used my_seek to determine the size. We copy this concept here to avoid the WSL bug.

grooverdan · 2022-07-22T12:57:25Z

Failed to reproduce on Windows 11 22000.795 and Windows 10 - 19044.1826

grooverdan · 2022-12-13T05:32:23Z

Our users are reporting this is back with Windows 10 19044.2311.

grooverdan · 2023-06-19T01:02:43Z

Still a problem - MDEV-31486:

Windows11Pro 22H2 22621.1848

Biswa96 · 2023-06-19T03:04:44Z

Did you try without Docker Desktop? Try to run the dockerd service with systemd or manually with dockerd command in different console.

izogfif · 2023-06-21T01:21:17Z

Did you try without Docker Desktop? Try to run the dockerd service with systemd or manually with dockerd command in different console.

Works on Windows 11 Pro 22H2 22621.1848 when running everything under WSL 2 with Ubuntu 22.04. The bug is still there when running latest version of Docker Desktop on Windows itself (can't run Linux container when starting dockerd inside cmd.exe on Windows).

But even when running Docker inside WSL, there is still the rename table error "Tablespace is missing for a table" as mentioned in this issue which points to this one in MariaDB tracker which finally leads to the current issue of WSL.

gavinbaumanis · 2023-11-10T01:51:24Z

Hi
I am suffering from this, now.
Here are my machine's details.

Please fix this.
As we use docker contaioners in production, it is important to us that we duplicate the environment as best we can for local development work.

Edition Windows 11 Pro
Version 23H2
Installed on ‎3/‎06/‎2023
OS build 22631.2506
Experience Windows Feature Experience Pack 1000.22677.1000.0

I'm using WSL 2

Please let me know if you need any further information from me.

klinki · 2023-11-30T13:28:43Z

I'm also facing this issue with WSL2 and MariaDB.

brunoborges · 2023-12-01T19:43:53Z

May I suggest you try this on a Ubuntu image running on Windows with VirtualBox? Use same version of Ubuntu and Docker, and see if it also fails.

Idea is to try to narrow where problem might be.

grooverdan · 2023-12-01T21:38:57Z

May I suggest you try this on a Ubuntu image running on Windows with VirtualBox? Use same version of Ubuntu and Docker, and see if it also fails.

Idea is to try to narrow where problem might be.

If its Virtualbox VM that wouldn't be using WSL. All other container users of MariaDB based on Ubuntu image and native and VM Ubuntu have not reported a problem and the simple ALTER TABLE is executed in CI on Ubuntu based tests daily.

However the following minimal container images have been made and the wsl8443.c file is in the top of the image.
wsl8443.c

#include <fcntl.h>
#include <stdio.h>
#include <sys/stat.h>
#include <errno.h>
#include <stdlib.h>
#include <unistd.h>

static const char *dest="/tmp/movedtestfile";

int main(int argc, char **argv)
{
  char *fn= "/tmp/testfile";
  if (argc > 1)
    fn= argv[1];

  int fd= open(fn, O_RDWR|O_CREAT|O_EXCL, 0660);
  
  if (fd >= 0)
    fprintf(stderr, "file %s opened - fd %d\n", fn, fd);
  else
    fprintf(stderr, "file %s not opened errno %d", fn, errno);
  
  if (rename(fn, dest))
    fprintf(stderr, "file %s not renamed to %s errno %d", fn, dest, errno);

  struct stat s;
  if (fstat(fd, &s) == -1) {
    fprintf(stderr, "error on fstat errno %d\n", errno);
    return 1;
  }
  else
    fprintf(stderr, "stat fd %d successful\n", fd);

  close(fd);
  unlink(fn);
  unlink(dest);

  return 0;
}

Occurs to me that tmpfs/tmp storage may not be enough hence volume.

https://quay.io/repository/danielgblack/wsl8443?tab=tags

docker volume storage
docker run --rm -v storage:/tmp quay.io/danielgblack/wsl8443:ubunu2204 ./wsl8443
docker run --rm -v storage:/tmp quay.io/danielgblack/wsl8443:ubunu2204 strace ./wsl8443

docker run  --rm -v storage:/tmp quay.io/danielgblack/wsl8443:ubunu2004 ./wsl8443
docker run  --rm -v storage:/tmp quay.io/danielgblack/wsl8443:ubunu2204 strace ./wsl8443

A reproduction on this would look like "error on fstat errno 2" on output.

gavinbaumanis · 2023-12-28T02:47:23Z

This issue was openeed in May of 2022.
Is there any chance of having this looked into / resolved?

holzerseb · 2024-04-23T15:14:27Z

Issue still persists as of today, 23.04.2024.

Using Docker Desktop v4.29.0, WSL 2 (incl. Windows Subsystem for Linux Update - 5.10.102.2)
Edition Windows 11 Pro
Version 23H2
Installed ‎18.‎06.‎2023
Build 22631.3447
Experience Windows Feature Experience Pack 1000.22688.1000.0

The issue only occurs when I use bind mounted volumes on an external SSD (bind mount /h/stuff/source to /data). Using regular docker volumes works fine.

Can we have someone look into this please?

gopaltechie · 2024-06-05T17:14:55Z

Using Docker Desktop v4.29.0, WSL 2 (incl. Windows Subsystem for Linux Update - 5.10.102.2)
Edition Windows 11 Pro
Version 23H2

Got the similar error.

Xiphoseer · 2024-06-05T18:40:14Z

Ok, finally got around to look at this myself on a windows machine. Can confirm that this (whatever the root cause is) is still happening on

Edition Windows 11 Enterprise
Version 23H2
Installed on ‎10.‎11.‎2022
OS build 22631.3672
Experience Windows Feature Experience Pack 1000.22700.1009.0

Last Update: KB5037853

I can confirm the observation from @holzerseb that it only happens if you mount a directory from the host file system into the
container, a volume is not sufficient:

$ docker volume create storage
$ docker run --rm -v "storage:/tmp" quay.io/danielgblack/wsl8443:ubunu2204 ./wsl8443
file /tmp/testfile opened - fd 3
stat fd 3 successful

This is likely because volumes are hosted on the "normal" filesystem of the WSL distro hosting docker engine (c.f. https://stackoverflow.com/a/64430683/4087068), which would use a "normal" block device filesystem driver like ext4.
If using rancher desktop, which also uses moby (the docker container runtime), it's \\wsl$\rancher-desktop-data\var\lib\docker\volumes\storage\_data. I checked the mountpoint for that and as expected:

$  docker run --rm -v "volume:/tmp" docker.io/bash sh -c "mount | grep /tmp"
/dev/sdf on /tmp type ext4 (rw,relatime,discard,errors=remount-ro,data=ordered)

If you compare that to a mounted path, you'll see that it's using the 9p filesystem driver instead:

$ mkdir hostdir
$ docker run --rm -v "$($(pwd).Path)\hostdir:/tmp" docker.io/bash sh -c "mount | grep /tmp"
C:\ on /tmp type 9p (rw,dirsync,noatime,aname=drvfs;path=C:\;uid=0;gid=0;metadata;symlinkroot=/mnt/,mmap,access=client,msize=65536,trans=fd,rfd=4,wfd=4)

And running the reproducer above indeed results in the expected "error on fstat errno 2". The full strace I get there is:

$ mkdir hostdir
$ docker run --rm -v "$($(pwd).Path)\hostdir:/tmp" quay.io/danielgblack/wsl8443:ubunu2204 ./wsl8443
file /tmp/testfile opened - fd 3
error on fstat errno 2
$ docker run --rm -v "$($(pwd).Path)\hostdir:/tmp" quay.io/danielgblack/wsl8443:ubunu2204 strace ./wsl8443
execve("./wsl8443", ["./wsl8443"], 0x7ffe38267590 /* 3 vars */) = 0
brk(NULL)                               = 0x55b6b28d7000
arch_prctl(0x3001 /* ARCH_??? */, 0x7fff8d629830) = -1 EINVAL (Invalid argument)
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f0f1586a000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=8735, ...}, AT_EMPTY_PATH) = 0
mmap(NULL, 8735, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f0f15867000
close(3)                                = 0
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0P\237\2\0\0\0\0\0"..., 832) = 832
pread64(3, "\6\0\0\0\4\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0"..., 784, 64) = 784
pread64(3, "\4\0\0\0 \0\0\0\5\0\0\0GNU\0\2\0\0\300\4\0\0\0\3\0\0\0\0\0\0\0"..., 48, 848) = 48
pread64(3, "\4\0\0\0\24\0\0\0\3\0\0\0GNU\0\244;\374\204(\337f#\315I\214\234\f\256\271\32"..., 68, 896) = 68
newfstatat(3, "", {st_mode=S_IFREG|0755, st_size=2216304, ...}, AT_EMPTY_PATH) = 0
pread64(3, "\6\0\0\0\4\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0"..., 784, 64) = 784
mmap(NULL, 2260560, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f0f1563f000
mmap(0x7f0f15667000, 1658880, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x28000) = 0x7f0f15667000
mmap(0x7f0f157fc000, 360448, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1bd000) = 0x7f0f157fc000
mmap(0x7f0f15854000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x214000) = 0x7f0f15854000
mmap(0x7f0f1585a000, 52816, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f0f1585a000
close(3)                                = 0
mmap(NULL, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f0f1563c000
arch_prctl(ARCH_SET_FS, 0x7f0f1563c740) = 0
set_tid_address(0x7f0f1563ca10)         = 9
set_robust_list(0x7f0f1563ca20, 24)     = 0
rseq(0x7f0f1563d0e0, 0x20, 0, 0x53053053) = 0
mprotect(0x7f0f15854000, 16384, PROT_READ) = 0
mprotect(0x55b6b1a7f000, 4096, PROT_READ) = 0
mprotect(0x7f0f158a4000, 8192, PROT_READ) = 0
prlimit64(0, RLIMIT_STACK, NULL, {rlim_cur=8192*1024, rlim_max=RLIM64_INFINITY}) = 0
munmap(0x7f0f15867000, 8735)            = 0
openat(AT_FDCWD, "/tmp/testfile", O_RDWR|O_CREAT|O_EXCL, 0660) = 3
write(2, "file /tmp/testfile opened - fd 3"..., 33file /tmp/testfile opened - fd 3
) = 33
rename("/tmp/testfile", "/tmp/movedtestfile") = 0
newfstatat(3, "", 0x7fff8d629840, AT_EMPTY_PATH) = -1 ENOENT (No such file or directory)
write(2, "error on fstat errno 2\n", 23error on fstat errno 2
) = 23
exit_group(1)                           = ?
+++ exited with 1 +++

So given the reproducer works, there are two options:

MariaDB relies on unspecified behavior and this reproducer just does the same wrong thing
The networked filesystem 9P has a bug, either in the driver in the kernel or on the windows side of WSL.

Hopefully this helps @grooverdan and/or the WSL team to narrow down the issue.

Edit:

$ wsl -v
WSL-Version: 2.1.5.0
Kernelversion: 5.15.146.1-2
WSLg-Version: 1.0.60
MSRDC-Version: 1.2.5105
Direct3D-Version: 1.611.1-81528511
DXCore-Version: 10.0.25131.1002-220531-1700.rs-onecore-base2-hyp
Windows-Version: 10.0.22631.3672

Xiphoseer · 2024-06-05T19:35:05Z

As for what the behavior should be. The man page for rename(2) is relatively clear on this:

Open file descriptors for oldpath are also unaffected.

So this should not happen and is indeed some sort of WSL bug. Interestingly, the POSIX definition of rename makes no such commitment: https://pubs.opengroup.org/onlinepubs/9699919799/functions/rename.html

Xiphoseer · 2024-06-05T19:45:01Z

One more datapoint:

I was curious and tried the reproducer on a directory mounted with 9p in WSL (i.e. same kernel version => same vfs implementation) against the https://github.com/chaos/diod 9P server and got

$ ./wsl8443
file /tmp/9c/testfile opened - fd 3
stat fd 3 successful

My takeaway from this is that it's probably a bug with the 9P server in windows.

EDIT: If someone wants to try:

In a new WSL terminal for ubuntu, run sudo apt install diod
Create a directory to host from: sudo mkdir /srv/9p
Run the server in debug mode sudo diod -f -d 1 -n -e /srv/9p
Open a new terminal in the same WSL distro
Mount the vfs client: sudo diodmount -n localhost:/srv/9p /tmp
Save the reproducer as wsl8443.c
Compile it: cc wsl8443.c -o wsl8443 (obviously needs a C compiler, e.g. sudo apt install gcc)
Run it ./wsl8443
Unmount with sudo umount /tmp

Xiphoseer · 2024-06-05T20:09:42Z

Since it seems to be specific to drvfs and not 9p directly, further testing reveals that just using /mnt/c/Users/{username}/testfile and /mnt/c/Users/{username}/movedtestfile with the reproducer fails with the (un)expected:

$ ./wsl8443
file /mnt/c/Users/{username}/testfile opened - fd 3
error on fstat errno 2

This is using a "normal" Ubuntu WSL distro opened with wsl -d Ubuntu, no Docker mounts needed.

EDIT: Sorry for spamming y'all with emails. Thought I was done with this, but there's always something more to look at.

EDIT 2: https://learn.microsoft.com/de-de/archive/blogs/wsl/wsl-file-system-support#interoperability-with-windows-1 feels relevant for this case. The reason I'm talking about drvfs at all is that the aname of the 9p mount for both the docker case and /mnt/c is something like aname=drvfs;path=C:\;uid=0;gid=0;metadata;symlinkroot=/mnt/

grooverdan mentioned this issue May 25, 2022

MySQL server has gone away in Windows MariaDB/mariadb-docker#403

Closed

grooverdan mentioned this issue Jul 7, 2022

MariaDB fails to start after Windows Updates #8475

Open

2 tasks

grooverdan closed this as completed Jul 22, 2022

grooverdan reopened this Dec 13, 2022

grooverdan mentioned this issue Nov 6, 2023

🐛 Bug Report: When i try to start appwrite in docket. Error in Starting MariaDB appwrite/appwrite#3003

Closed

2 tasks

Xiphoseer mentioned this issue Jan 27, 2024

Web not connecting to the db on docker DarkflameUniverse/NexusDashboard#92

Open

grooverdan mentioned this issue Jun 21, 2024

.my-healthcheck.cnf permissions problems MariaDB/mariadb-docker#573

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

open(), rename(), fstat() -> ENOENT #8443

open(), rename(), fstat() -> ENOENT #8443

grooverdan commented May 25, 2022 •

edited

Loading

grooverdan commented Jul 22, 2022

grooverdan commented Dec 13, 2022

grooverdan commented Jun 19, 2023

Biswa96 commented Jun 19, 2023

izogfif commented Jun 21, 2023

gavinbaumanis commented Nov 10, 2023

klinki commented Nov 30, 2023

brunoborges commented Dec 1, 2023

grooverdan commented Dec 1, 2023 •

edited

Loading

gavinbaumanis commented Dec 28, 2023

holzerseb commented Apr 23, 2024

gopaltechie commented Jun 5, 2024 •

edited

Loading

Xiphoseer commented Jun 5, 2024 •

edited

Loading

Xiphoseer commented Jun 5, 2024

Xiphoseer commented Jun 5, 2024 •

edited

Loading

Xiphoseer commented Jun 5, 2024 •

edited

Loading

open(), rename(), fstat() -> ENOENT #8443

open(), rename(), fstat() -> ENOENT #8443

Comments

grooverdan commented May 25, 2022 • edited Loading

Version

WSL Version

Kernel Version

Distro Version

Other Software

Repro Steps

Expected Behavior

Actual Behavior

Diagnostic Logs

grooverdan commented Jul 22, 2022

grooverdan commented Dec 13, 2022

grooverdan commented Jun 19, 2023

Biswa96 commented Jun 19, 2023

izogfif commented Jun 21, 2023

gavinbaumanis commented Nov 10, 2023

klinki commented Nov 30, 2023

brunoborges commented Dec 1, 2023

grooverdan commented Dec 1, 2023 • edited Loading

gavinbaumanis commented Dec 28, 2023

holzerseb commented Apr 23, 2024

gopaltechie commented Jun 5, 2024 • edited Loading

Xiphoseer commented Jun 5, 2024 • edited Loading

Xiphoseer commented Jun 5, 2024

Xiphoseer commented Jun 5, 2024 • edited Loading

Xiphoseer commented Jun 5, 2024 • edited Loading

grooverdan commented May 25, 2022 •

edited

Loading

grooverdan commented Dec 1, 2023 •

edited

Loading

gopaltechie commented Jun 5, 2024 •

edited

Loading

Xiphoseer commented Jun 5, 2024 •

edited

Loading

Xiphoseer commented Jun 5, 2024 •

edited

Loading

Xiphoseer commented Jun 5, 2024 •

edited

Loading