Various symlink test failures in test_shutil on FreeBSD

[tpn]

BPO	15748
Nosy	@vstinner, @larryhastings, @tpn
Files	test_readlink.sh

^{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 = 'https://github.com/tpn'
closed_at = None
created_at = <Date 2012-08-21.02:26:57.408>
labels = ['type-bug', 'tests']
title = 'Various symlink test failures in test_shutil on FreeBSD'
updated_at = <Date 2019-03-16.00:08:09.049>
user = 'https://github.com/tpn'

bugs.python.org fields:

activity = <Date 2019-03-16.00:08:09.049>
actor = 'BreamoreBoy'
assignee = 'trent'
closed = False
closed_date = None
closer = None
components = ['Tests']
creation = <Date 2012-08-21.02:26:57.408>
creator = 'trent'
dependencies = []
files = ['26979']
hgrepos = []
issue_num = 15748
keywords = []
message_count = 15.0
messages = ['168731', '168749', '168804', '168806', '168814', '168870', '168887', '168908', '168971', '169007', '169590', '169592', '169620', '169758', '221883']
nosy_count = 3.0
nosy_names = ['vstinner', 'larry', 'trent']
pr_nums = []
priority = 'normal'
resolution = 'postponed'
stage = 'needs patch'
status = 'open'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue15748'
versions = ['Python 3.4', 'Python 3.5']

[tpn]

FreeBSD slaves are running into this:

======================================================================
ERROR: test_copy2_symlinks (test.test_shutil.TestShutil)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/home/buildslave/cpython/3.x.snakebite-freebsd91-amd64/build/Lib/test/test_shutil.py", line 490, in test_copy2_symlinks
    shutil.copy2(src_link, dst, follow_symlinks=False)
  File "/home/buildslave/cpython/3.x.snakebite-freebsd91-amd64/build/Lib/shutil.py", line 237, in copy2
    copyfile(src, dst, follow_symlinks=follow_symlinks)
  File "/home/buildslave/cpython/3.x.snakebite-freebsd91-amd64/build/Lib/shutil.py", line 107, in copyfile
    os.symlink(os.readlink(src), dst)
TypeError: embedded NUL character

======================================================================
ERROR: test_copy_symlinks (test.test_shutil.TestShutil)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/home/buildslave/cpython/3.x.snakebite-freebsd91-amd64/build/Lib/test/test_shutil.py", line 463, in test_copy_symlinks
    shutil.copy(src_link, dst, follow_symlinks=False)
  File "/home/buildslave/cpython/3.x.snakebite-freebsd91-amd64/build/Lib/shutil.py", line 221, in copy
    copyfile(src, dst, follow_symlinks=follow_symlinks)
  File "/home/buildslave/cpython/3.x.snakebite-freebsd91-amd64/build/Lib/shutil.py", line 107, in copyfile
    os.symlink(os.readlink(src), dst)
TypeError: embedded NUL character

======================================================================
FAIL: test_copytree_symlinks (test.test_shutil.TestShutil)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/home/buildslave/cpython/3.x.snakebite-freebsd91-amd64/build/Lib/test/test_shutil.py", line 606, in test_copytree_symlinks
    os.path.join(src_dir, 'file.txt'))
AssertionError: '/tmp/tmpqlihz5/src/file.' != '/tmp/tmpqlihz5/src/file.txt'
- /tmp/tmpqlihz5/src/file.
+ /tmp/tmpqlihz5/src/file.txt
?                         +++

Haven't had time to debug it any further yet. Have no clue what's going on either just from a cursory look at the error messages. Not sure if it's ZFS related like the other FreeBSD issues.

[tpn]

Looks like os.readlink() is busted:

> /home/trent/src/cpython/Lib/shutil.py(107)copyfile()
-> os.symlink(os.readlink(src), dst)
(Pdb) s
TypeError: embedded NUL character
> /home/trent/src/cpython/Lib/shutil.py(107)copyfile()
-> os.symlink(os.readlink(src), dst)
(Pdb) os.readlink(src)
'/tmp/tmpr3obfj/foo\x00\x00\x00\x00\x00\x00'
(Pdb) p src
'/tmp/tmpr3obfj/baz'
(Pdb) l
102  	            # XXX What about other special files? (sockets, devices...)
103  	            if stat.S_ISFIFO(st.st_mode):
104  	                raise SpecialFileError("`%s` is a named pipe" % fn)
105  	
106  	    if not follow_symlinks and os.path.islink(src):
107  ->	        os.symlink(os.readlink(src), dst)
108  	    else:
109  	        with open(src, 'rb') as fsrc:
110  	            with open(dst, 'wb') as fdst:
111  	                copyfileobj(fsrc, fdst)
112  	    return dst


> /home/trent/src/cpython/Lib/shutil.py(107)copyfile()
-> os.symlink(os.readlink(src), dst)
(Pdb) s
TypeError: embedded NUL character
> /home/trent/src/cpython/Lib/shutil.py(107)copyfile()
-> os.symlink(os.readlink(src), dst)
(Pdb) os.readlink(src)
'/tmp/tmpr3obfj/foo\x00\x00\x00\x00\x00\x00'
(Pdb) p src
'/tmp/tmpr3obfj/baz'
(Pdb) l
102  	            # XXX What about other special files? (sockets, devices...)
103  	            if stat.S_ISFIFO(st.st_mode):
104  	                raise SpecialFileError("`%s` is a named pipe" % fn)
105  	
106  	    if not follow_symlinks and os.path.islink(src):
107  ->	        os.symlink(os.readlink(src), dst)
108  	    else:
109  	        with open(src, 'rb') as fsrc:
110  	            with open(dst, 'wb') as fdst:
111  	                copyfileobj(fsrc, fdst)
112  	    return dst

i.e.:
(Pdb) os.readlink(src)
'/tmp/tmpr3obfj/foo\\x00\\x00\\x00\\x00\\x00\\x00'

Started another session with gdb, set a breakpoint at posix_readlink:

Breakpoint 1, posix_readlink (self=0x800909858, args=0x805ec2840, kwargs=0x0)
    at ./Modules/posixmodule.c:7007
7007	    int dir_fd = DEFAULT_DIR_FD;
(gdb) l
7002	
7003	static PyObject *
7004	posix_readlink(PyObject \*self, PyObject \*args, PyObject \*kwargs)
7005	{
7006	    path_t path;
7007	    int dir_fd = DEFAULT_DIR_FD;
7008	    char buffer[MAXPATHLEN];
7009	    ssize_t length;
7010	    PyObject \*return_value = NULL;
7011	    static char \*keywords[] = {"path", "dir_fd", NULL};
(gdb) n
7013	    memset(&path, 0, sizeof(path));
(gdb) 
7014	    if (!PyArg_ParseTupleAndKeywords(args, kwargs, "O&|$O&:readlink", keywords,
(gdb) 
7024	    Py_BEGIN_ALLOW_THREADS
(gdb) 
7026	    if (dir_fd != DEFAULT_DIR_FD)
(gdb) p path
$1 = {function_name = 0x0, argument_name = 0x0, nullable = 0, allow_fd = 0, 
  wide = 0x0, narrow = 0x805ec0f10 "/tmp/tmpko8vo_/baz", fd = -1, length = 18, 
  object = 0x805e30d60, cleanup = 0x805ec0ee0}

path.narrow and length are correct at that point.


(gdb) p dir_fd
$2 = -100
(gdb) n
7024	    Py_BEGIN_ALLOW_THREADS
(gdb) n
7026	    if (dir_fd != DEFAULT_DIR_FD)
(gdb) n
7030	        length = readlink(path.narrow, buffer, sizeof(buffer));
(gdb) n
7031	    Py_END_ALLOW_THREADS
(gdb) p length
$3 = 24
(gdb) p sizeof(buffer)
$7 = 1024
(gdb)  p buffer
$9 = "/tmp/tmpko8vo_/foo\\000\\000\\000\\000\\000\\000ͤ\\r\\001\\b\\000\\000\\000\\000\\000\\000\\000??????A", '\\0' \<repeats 77 times\>, "??\\203\\000\\b\\000\\000\\000?v???\\177\\000\\000??A", '\\0' \<repeats 13 times\>, "f\\023J", '\\0' \<repeats 13 times\>, "??A\\000\\000\\000\\000\\000\\001\\000\\000\\000\\000\\000\\000\\000\\030u???\\177\\000\\000 u???\\177\\000\\000RCJ\\000\\000\\000\\000\\000\\000\\001\\000\\000\\000\\000\\000\\000??A\\000\\000\\000\\000\\000?v???\\177\\000\\000?(?\\005\\b\\000\\000\\0000?L\\002\\b\\000\\000\\000\\210N?\\005\\b\\000\\000\\000\\001\\000\\000\\000\\000\\000\\000\\000??A\\000\\000\\000\\000\\000?"...

No idea why readlink is returning 24. Need to look into it more.

[larryhastings]

I'll ask the obvious: was that an optimized build? Not that that explains the bug--but that might explain why "length" appeared to contain 24.

It's hard to believe this is really an OS bug...

[tpn]

Hi Larry,

Funnily enough, I just tried to step through a heavily hacked version of posix_readlink again, only to get gdb telling me I couldn't 'print' the variables I had added in.

Turns out, ./configure --with-pydebug on FreeBSD ends up with '-O2' being appended to CFLAGS some how. I've raised a separate issue for this: http://bugs.python.org/issue15748.

[tpn]

Well, bugger me, check this out:

import os
import stat
import tempfile

d = tempfile.mkdtemp()
src = os.path.join(d, 'foo')
dst = os.path.join(d, 'bar')
src_link = os.path.join(d, 'baz')
dst_link = os.path.join(d, 'qux')

sf = open(dst, 'w')
sf.write('foo')
sf.flush()
sf.close()

df = open(dst, 'w')
df.write('bar')
df.flush()
df.close()

os.symlink(src, src_link)
os.symlink(dst, dst_link)

os.lchmod(src_link, stat.S_IRWXU | stat.S_IRWXO)

os.readlink(dst_link)
os.readlink(src_link)

Results of the last two calls:
>>> os.readlink(dst_link)

path 1: /tmp/tmpfz5v6h/qux, length 1: 18, buf 1: /tmp/tmpfz5v6h/bar
path 2: /tmp/tmpfz5v6h/qux, length 2: 18, buf 2: /tmp/tmpfz5v6h/bar
'/tmp/tmpfz5v6h/bar'
[73299 refs]
>>> os.readlink(src_link)

path 1: /tmp/tmpfz5v6h/baz, length 1: 24, buf 1: /tmp/tmpfz5v6h/foo
path 2: /tmp/tmpfz5v6h/baz, length 2: 24, buf 2: /tmp/tmpfz5v6h/foo
'/tmp/tmpfz5v6h/foo\x00\x00\x00\x00\x00\x00'
[73299 refs]

So, without the os.lchmod() call, the length is returned correctly. With it, it gets returned as 24. Looks like an OS bug.

[tpn]

Hmmmmm... tested against other types of file systems and didn't see any issues. Tested manually against ZFS again:

% ~/src/cpython/python /tmp/test_readlink.py
temp dir: /mnt/t-zfs/trent/d_6i51

path 1: /mnt/t-zfs/trent/d_6i51/qux, length 1: 27, buf 1: /mnt/t-zfs/trent/d_6i51/bar
path 2: /mnt/t-zfs/trent/d_6i51/qux, length 2: 27, buf 2: /mnt/t-zfs/trent/d_6i51/bar
dst: /mnt/t-zfs/trent/d_6i51/bar

path 1: /mnt/t-zfs/trent/d_6i51/baz, length 1: 24, buf 1: /mnt/t-zfs/trent/d_6i51/
path 2: /mnt/t-zfs/trent/d_6i51/baz, length 2: 24, buf 2: /mnt/t-zfs/trent/d_6i51/
src: /mnt/t-zfs/trent/d_6i51/
[47136 refs]

This time, src got truncated by 3 characters back down to 24. (Instead of getting rounded up by 6 from 18->24 in the previous example.)

Next step: replicate with a C snippet and ping the FreeBSD developers, I guess.

[vstinner]

I don't understand if the issue comes from symlink() or readlink(). Can you reproduce the issue using commands on the command line?

$ ln -s setup.py link
`link' -> `setup.py'
$ readlink link
setup.py

(You may need to test different length for filenames.)

Do you only have the issue with ZFS, or with other file systems?

[larryhastings]

haypo: If a series of shell commands duplicated the problem, then okay, but I suspect the problem has to do with persistent state in the process and will only be reproducible with a C program.

[tpn]

Reproduced behaviour with test_readlink.sh. Sending an e-mail to freebsd-fs to see what they think.

[tpn]

Link to my freebsd-fs e-mail: http://lists.freebsd.org/pipermail/freebsd-fs/2012-August/014964.html

[tpn]

Turns out our unit test uncovered a very subtle corner-case bug in ZFS, requiring the following patch to FreeBSD:

a/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/sa.c
b/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/sa.c
index 69374fb..7f61517 100644
--- a/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/sa.c
+++ b/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/sa.c
@@ -1695,6 +1695,7 @@ sa_modify_attrs(sa_handle_t *hdl, sa_attr_type_t newattr,
                                ASSERT(action == SA_REPLACE);
                                SA_ADD_BULK_ATTR(attr_desc, j, attr,
                                    locator, datastart, buflen);
+                               length_idx++;
                        } else {
                                length = SA_REGISTERED_LEN(sa, attr);
                                if (length == 0) {

I guess the unit test should probably be patched to to skip the test IFF the underlying filesystem is ZFS and it exhibits the "length 24" problem. (Actually, detecting if the underlying filesystem is ZFS is non-trivial -- just testing for the "length 24" bug is probably sufficient.) I'll look into this later.

(According to Andriy Gapon (FreeBSD developer that came up with the patch), the bug is likely to affect all ZFS implementations since the beginning of time.)

[larryhastings]

Could we work around it? Ignore the length we get back from readlink() and just measure the buffer ourselves? Or, if we wanted to be *really* paranoid, write a \0 at the length they give us back and *then* strlen it.