6.14.6: copy from cifs mount never finishes

6.14.6: copy from cifs mount never finishes

[Johannes Berg]

Hi,

So I'm on 6.14.6 on Fedora, trying to copy a few relatively small files.
I went to lunch and when I came back it still wasn't finished, and the
first file was just growing and growing in size ...

Reproducing it, I see:

$ ls -l /mnt/dmesg_log.txt
-rwxr-xr-x. 1 root root 271261 May 13 13:00 /mnt/dmesg_log.txt
$ strace cp /mnt/dmesg_log.txt /tmp/
execve("/usr/bin/cp", ["cp", "/mnt/dmesg_log.txt", "/tmp/"], 0x7ffcae506680 /* 85 vars */) = 0
...
openat(AT_FDCWD, "/tmp/", O_RDONLY|O_PATH|O_DIRECTORY) = 3
newfstatat(AT_FDCWD, "/mnt/dmesg_log.txt", {st_mode=S_IFREG|0755, st_size=271261, ...}, 0) = 0
newfstatat(3, "dmesg_log.txt", 0x7ffdcacac290, 0) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/mnt/dmesg_log.txt", O_RDONLY) = 4
fstat(4, {st_mode=S_IFREG|0755, st_size=271261, ...}) = 0
openat(3, "dmesg_log.txt", O_WRONLY|O_CREAT|O_EXCL, 0755) = 5
ioctl(5, BTRFS_IOC_CLONE or FICLONE, 4) = -1 EXDEV (Invalid cross-device link)
fstat(5, {st_mode=S_IFREG|0755, st_size=0, ...}) = 0
fadvise64(4, 0, 0, POSIX_FADV_SEQUENTIAL) = 0
uname({sysname="Linux", nodename="jberg1-mobl2.ger.corp.intel.com", ...}) = 0
copy_file_range(4, NULL, 5, NULL, 9223372035781033984, 0) = -1 EXDEV (Invalid cross-device link)
mmap(NULL, 1056768, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f1d2a6fe000
read(4, "[ 3410.434280] iwlwifi 0000:3d:0"..., 1048576) = 983040

now that's already wrong, the file is only 271261 bytes! That should
have returned 271261, not 983040.

Next that data is written out, nothing special, except when I look at
the data, after offset 271261 it's filled up with zeroes.

write(5, "[ 3410.434280] iwlwifi 0000:3d:0"..., 983040) = 983040


It gets worse from here though, because now even the next read doesn't
return 0 for EOF:

read(4, "[ 3410.434280] iwlwifi 0000:3d:0"..., 1048576) = 983040
write(5, "[ 3410.434280] iwlwifi 0000:3d:0"..., 983040) = 983040


And that just repeats forever.


johannes

Re: 6.14.6: copy from cifs mount never finishes

[Johannes Berg]

+netfs, and adding a bit more information



Hi,

So I'm on 6.14.6 on Fedora, trying to copy a few relatively small files.
I went to lunch and when I came back it still wasn't finished, and the
first file was just growing and growing in size ...

The filesystem was mounted with just

# mount.cifs -ouser=<user>,dom=<dom> '\\server\share\some\deep\path' /mnt

The server is some Windows server, I think, our IT runs it. Probably not
Azure since it's an internal IP address.

I also have a pcap now, but I'm not going to post it to the list.


Reproducing it, I see:

$ ls -l /mnt/dmesg_log.txt
-rwxr-xr-x. 1 root root 271261 May 13 13:00 /mnt/dmesg_log.txt
$ strace cp /mnt/dmesg_log.txt /tmp/
execve("/usr/bin/cp", ["cp", "/mnt/dmesg_log.txt", "/tmp/"], 0x7ffcae506680 /* 85 vars */) = 0
...
openat(AT_FDCWD, "/tmp/", O_RDONLY|O_PATH|O_DIRECTORY) = 3
newfstatat(AT_FDCWD, "/mnt/dmesg_log.txt", {st_mode=S_IFREG|0755, st_size=271261, ...}, 0) = 0
newfstatat(3, "dmesg_log.txt", 0x7ffdcacac290, 0) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/mnt/dmesg_log.txt", O_RDONLY) = 4
fstat(4, {st_mode=S_IFREG|0755, st_size=271261, ...}) = 0
openat(3, "dmesg_log.txt", O_WRONLY|O_CREAT|O_EXCL, 0755) = 5
ioctl(5, BTRFS_IOC_CLONE or FICLONE, 4) = -1 EXDEV (Invalid cross-device link)
fstat(5, {st_mode=S_IFREG|0755, st_size=0, ...}) = 0
fadvise64(4, 0, 0, POSIX_FADV_SEQUENTIAL) = 0
uname({sysname="Linux", nodename="jberg1-mobl2.ger.corp.intel.com", ...}) = 0
copy_file_range(4, NULL, 5, NULL, 9223372035781033984, 0) = -1 EXDEV (Invalid cross-device link)
mmap(NULL, 1056768, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f1d2a6fe000
read(4, "[ 3410.434280] iwlwifi 0000:3d:0"..., 1048576) = 983040

now that's already wrong, the file is only 271261 bytes! That should
have returned 271261, not 983040.

Next that data is written out, nothing special, except when I look at
the data, after offset 271261 it's filled up with zeroes.

write(5, "[ 3410.434280] iwlwifi 0000:3d:0"..., 983040) = 983040


It gets worse from here though, because now even the next read doesn't
return 0 for EOF:

read(4, "[ 3410.434280] iwlwifi 0000:3d:0"..., 1048576) = 983040
write(5, "[ 3410.434280] iwlwifi 0000:3d:0"..., 983040) = 983040


And that just repeats forever.


johannes

Re: 6.14.6: copy from cifs mount never finishes

[Paulo Alcantara]

Johannes Berg <johannes@sipsolutions.net> writes:

> So I'm on 6.14.6 on Fedora, trying to copy a few relatively small files.
> I went to lunch and when I came back it still wasn't finished, and the
> first file was just growing and growing in size ...
>
> The filesystem was mounted with just
>
> # mount.cifs -ouser=<user>,dom=<dom> '\\server\share\some\deep\path' /mnt
>
> The server is some Windows server, I think, our IT runs it. Probably not
> Azure since it's an internal IP address.
>
> I also have a pcap now, but I'm not going to post it to the list.
>
>
> Reproducing it, I see:
>
> $ ls -l /mnt/dmesg_log.txt
> -rwxr-xr-x. 1 root root 271261 May 13 13:00 /mnt/dmesg_log.txt
> $ strace cp /mnt/dmesg_log.txt /tmp/
> execve("/usr/bin/cp", ["cp", "/mnt/dmesg_log.txt", "/tmp/"], 0x7ffcae506680 /* 85 vars */) = 0
> ...
> openat(AT_FDCWD, "/tmp/", O_RDONLY|O_PATH|O_DIRECTORY) = 3
> newfstatat(AT_FDCWD, "/mnt/dmesg_log.txt", {st_mode=S_IFREG|0755, st_size=271261, ...}, 0) = 0
> newfstatat(3, "dmesg_log.txt", 0x7ffdcacac290, 0) = -1 ENOENT (No such file or directory)
> openat(AT_FDCWD, "/mnt/dmesg_log.txt", O_RDONLY) = 4
> fstat(4, {st_mode=S_IFREG|0755, st_size=271261, ...}) = 0
> openat(3, "dmesg_log.txt", O_WRONLY|O_CREAT|O_EXCL, 0755) = 5
> ioctl(5, BTRFS_IOC_CLONE or FICLONE, 4) = -1 EXDEV (Invalid cross-device link)
> fstat(5, {st_mode=S_IFREG|0755, st_size=0, ...}) = 0
> fadvise64(4, 0, 0, POSIX_FADV_SEQUENTIAL) = 0
> uname({sysname="Linux", nodename="jberg1-mobl2.ger.corp.intel.com", ...}) = 0
> copy_file_range(4, NULL, 5, NULL, 9223372035781033984, 0) = -1 EXDEV (Invalid cross-device link)
> mmap(NULL, 1056768, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f1d2a6fe000
> read(4, "[ 3410.434280] iwlwifi 0000:3d:0"..., 1048576) = 983040
>
> now that's already wrong, the file is only 271261 bytes! That should
> have returned 271261, not 983040.
>
> Next that data is written out, nothing special, except when I look at
> the data, after offset 271261 it's filled up with zeroes.
>
> write(5, "[ 3410.434280] iwlwifi 0000:3d:0"..., 983040) = 983040
>
>
> It gets worse from here though, because now even the next read doesn't
> return 0 for EOF:
>
> read(4, "[ 3410.434280] iwlwifi 0000:3d:0"..., 1048576) = 983040
> write(5, "[ 3410.434280] iwlwifi 0000:3d:0"..., 983040) = 983040
>
>
> And that just repeats forever.

As we've talked, this should be fixed by

        34eb98c6598c ("netfs: Fix setting of transferred bytes with short DIO reads") [1]

I'll make sure to get it through -stable once released.

Thanks.

[1] https://git.kernel.org/pub/scm/linux/kernel/git/vfs/vfs.git #vfs-6.16.netfs