shutil._fastcopy_sendfile() makes wrong (?) assumption about sendfile() return value

[lhuedepohl]

BPO	43388
Nosy	@akulakov

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = None
closed_at = None
created_at = <Date 2021-03-03.16:06:53.444>
labels = ['3.8', 'library', '3.9', '3.10']
title = 'shutil._fastcopy_sendfile() makes wrong (?) assumption about sendfile() return value'
updated_at = <Date 2021-07-05.15:28:45.015>
user = 'https://bugs.python.org/lhuedepohl'

bugs.python.org fields:

activity = <Date 2021-07-05.15:28:45.015>
actor = 'lhuedepohl'
assignee = 'none'
closed = False
closed_date = None
closer = None
components = ['Library (Lib)']
creation = <Date 2021-03-03.16:06:53.444>
creator = 'lhuedepohl'
dependencies = []
files = []
hgrepos = []
issue_num = 43388
keywords = []
message_count = 3.0
messages = ['388027', '396995', '396996']
nosy_count = 2.0
nosy_names = ['andrei.avk', 'lhuedepohl']
pr_nums = []
priority = 'normal'
resolution = None
stage = None
status = 'open'
superseder = None
type = None
url = 'https://bugs.python.org/issue43388'
versions = ['Python 3.8', 'Python 3.9', 'Python 3.10']

[lhuedepohl]

Since version 3.8, the shutil.copyfile() function tries to make use of os.sendfile(). Currently, this is done in a loop that aborts as soon as sendfile() returns 0, as it is assumed that this signifies the end of the file.

The problem: the return value of sendfile() is simply the amount of bytes that could be successfully copied in that one syscall, with no guarantee that a return value of 0 only happens when there is truly no data left to copy. Some other urgent task could have interrupted the kernel before any data was copied. At least, I could not find documentation to the contrary.

(Note: This might or might not be actual behavior of current Linux kernels today, but the spec of sendfile() certainly allows this)

In any case, in that same routine the size of the source file is anyway requested in an os.fstat() call, one could thus restructure the loop like this, for example:

filesize = os.fstat(infd).st_size
offset = 0
while offset < filesize:
   sent = os.sendfile(outfd, infd, offset, blocksize)
   offset += sent

(Error handling etc. left out for clarity, just to point out the new structure)

This would also optimize the case of an empty input file, in that case the loop is never entered and no os.sendfile() call is issued, at all.

In the normal case, it would also save the unnecessary last os.sendfile() call, when 'offset' has already grown to 'filesize'. (This was the actual reason for me to look into this in the first place, a filesystem bug where sendfile() called with an offset set to the file's size returns "EAGAIN" in certain cases. But this is another topic entirely and has nothing to do with Python, of course.)

Note that in Modules/posixmodule.c os_sendfile_impl() there is also another loop around individual actual sendfile() system call, but a return value of 0 there would also exit that loop and be passed up:

    do {
        Py_BEGIN_ALLOW_THREADS
#ifdef __APPLE__
        ret = sendfile(in_fd, out_fd, offset, &sbytes, &sf, flags);
#else
        ret = sendfile(in_fd, out_fd, offset, count, &sf, &sbytes, flags);
#endif
        Py_END_ALLOW_THREADS
    } while (ret < 0 && errno == EINTR && !(async_err = PyErr_CheckSignals()));

Kind regards,
Lorenz

[akulakov]

Wouldn't this create infinite loop if a file cannot be fully copied for some reason?

[lhuedepohl]

Sure, as written it would. As I said: Error handling etc. left out for clarity, just to point out the new structure.

[omula]

We, at European Centre for Medium-Range Weather Forecast (@ecmwf), have recently been reported file truncation by a couple of our HPC platform users. After some investigation we have been able to identify and reproduce the issue. As mentioned by @lhuedepohl and detailed on the sendfile Linux man page for return value

If the transfer was successful, the number of bytes written to out_fd is returned. Note that a successful call to sendfile() may write fewer bytes than requested; the caller should be prepared to retry the call if there were unsent bytes.

In Python’s shutil implementation, a return value of 0 is interpreted as the end-of-file (EOF)(https://github.com/python/cpython/blob/main/Lib/shutil.py#L218), which causes the copy operation to halt prematurely.

We have investigated this with multiple file systems (xfs, nfsv4, lustre) and we have only been able to reproduce this on lustre file system. Although we have only been able to reproduce this with lustre, its behaviour is conformant to the API specification and the python implementation should be fixed.

Within our reproducer we verified that reissuing the sendfile infinitely will completely copy the file. However, as also mentioned by @akulakov one could end up on an infinite loop if only checking for the file size. A possible solution, would be to raise _GiveupOnFastCopy after first time you get 0 as return value. Alternatively reissue sendfile a fixed number of times, need to evaluate how expensive retrying to fix this number, and raise _GiveupOnFastCopy.

Details on reproducing/triggering the phenomenon on demand are run the script below on a target lustre file system while dropping kernel caches with while :; do date; sync; echo 2 > /proc/sys/vm/drop_caches ; sleep 0.1; done

testing script

#!/usr/bin/env python3
import shutil
import os
import sys

def test_copy_file_size():
    src = 'input_file'
    dst = 'output_file'

    # Copy the file using shutil.copyfile
    shutil.copyfile(src, dst)

    # Get file sizes
    src_size = os.path.getsize(src)
    dst_size = os.path.getsize(dst)

    # Compare file sizes
    if src_size != dst_size:
        print(f"Test Failed: src_size: {src_size} dst_size: {dst_size} File size does not match.")
        sys.exit(1)

if __name__ == '__main__':
    test_copy_file_size()

$ ls -l input_file
-rw-r--r-- 1 user group 512863 Aug 12  2022 input_file

$ counter=0; while true; do ./sendfile.py || echo "ATTEMPT: $counter" ; sleep 1; rm output_file; counter=$((counter+1)); done 
Test Failed: src_size: 512863 dst_size: 262144 File size does not match.
ATTEMPT: 10
Test Failed: src_size: 512863 dst_size: 462848 File size does not match.
ATTEMPT: 12
Test Failed: src_size: 512863 dst_size: 0 File size does not match.
ATTEMPT: 15
Test Failed: src_size: 512863 dst_size: 319488 File size does not match.
ATTEMPT: 22
Test Failed: src_size: 512863 dst_size: 446464 File size does not match.
ATTEMPT: 28
Test Failed: src_size: 512863 dst_size: 266240 File size does not match.
ATTEMPT: 38
Test Failed: src_size: 512863 dst_size: 266240 File size does not match.
ATTEMPT: 43
Test Failed: src_size: 512863 dst_size: 454656 File size does not match.
ATTEMPT: 44
Test Failed: src_size: 512863 dst_size: 135168 File size does not match.
ATTEMPT: 51
...