Some tests failing due to shutdown(2) returning EINVAL

A short experiment with python to show that shutdown doesn't just always fails with EINVAL:

$ cat sock.py
import socket

s = socket.create_connection(('127.0.0.1', 22))
s.shutdown(socket.SHUT_RDWR)
print(socket.SHUT_RDWR)
s.shutdown(3) # deliberate error
$ python3.7 sock.py
2
Traceback (most recent call last):
  File "sock.py", line 6, in <module>
    s.shutdown(3)
OSError: [Errno 22] Invalid argument

On Sat, Oct 26, 2019 at 04:44:41PM -0000, Olaf Seibert wrote:
> Public bug reported:
>
> I am preparing a package of breezy 3.0.1 on NetBSD's pkgsrc. I am using
> NetBSD/amd64 8.1 and Python 3.7.4.
>
> Several of the tests fail with the same or very similar stack traces:
>
> ```
> ...ary.test_symlink_content_summary(WorkingTreeFormat6,remote)ERROR 69ms
> log: {{{
> 1281.701 creating repository in chroot-132261157529056:///tree/.bzr/.
> 1281.705 creating branch <breezy.bzr.branch.BzrBranchFormat8 object at 0x784a6b0a60a0> in chroot-132261157529056:///tree/
> 1281.712 creating branch reference in file:///mnt/scratch/scratch/tmp/testbzr-u569akfo.tmp/breezy.tests.per_tree.test_path_content_summary.TestPathContentSummary.test_symlink_content_summary%28WorkingTreeFormat6%2Cremote%29/work/tree/
> 1281.730 trying to create missing lock '/mnt/scratch/scratch/tmp/testbzr-u569akfo.tmp/breezy.tests.per_tree.test_path_content_summary.TestPathContentSummary.test_symlink_content_summary(WorkingTreeFormat6,remote)/work/tree/.bzr/checkout/dirstate'
> 1281.731 opening working tree '/mnt/scratch/scratch/tmp/testbzr-u569akfo.tmp/breezy.tests.per_tree.test_path_content_summary.TestPathContentSummary.test_symlink_content_summary(WorkingTreeFormat6,remote)/work/tree'
> }}}
>
> Traceback (most recent call last):
> File "/home/tmp/devel/breezy/work.x86_64/breezy-3.0.1/breezy/tests/test_server.py", line 702, in stop_server
> super(SmartTCPServer_for_testing, self).stop_server()
> File "/home/tmp/devel/breezy/work.x86_64/breezy-3.0.1/breezy/tests/test_server.py", line 571, in stop_server
> self.server.stop_client_connections()
> File "/home/tmp/devel/breezy/work.x86_64/breezy-3.0.1/breezy/tests/test_server.py", line 375, in stop_client_connections
> self.shutdown_client(c)
> File "/home/tmp/devel/breezy/work.x86_64/breezy-3.0.1/breezy/tests/test_server.py", line 480, in shutdown_client
> self.shutdown_socket(sock)
> File "/home/tmp/devel/breezy/work.x86_64/breezy-3.0.1/breezy/tests/test_server.py", line 384, in shutdown_socket
> sock.shutdown(socket.SHUT_RDWR)
> OSError: [Errno 22] Invalid argument
> ```
> I'm not sure why this errno is returned from shutdown, but I suppose for the purposes of the test it can be ignored. (Unless you're passing the wrong file descriptor or something, or there is some bug in Python with the definition of SHUT_RDWR,)

We're not hitting this on Linux (and we run the test suite there quite
a lot). I suspect this is a behaviour in the underlying shutdown()
implementation on NetBSD and Linux.

The Linux manpage for shutdown has a BUGS section that says:

Checks for the validity of how are done in domain-specific code, and
before Linux 3.7 not all domains performed these checks. Most
notably, UNIX domain sockets simply ignored invalid values. This
problem was fixed for UNIX domain sockets in Linux 3.7.

I also wonder passing a socket that's already shutdown perhaps results
in EINVAL.

Jelmer

--
Jelmer Vernooij <email address hidden>
PGP Key: https://www.jelmer.uk/D729A457.asc

I had the same idea about multiple shutdowns, but in my test that didn't trigger any exception. I also tried UNIX domain sockets to see if they behaved differently perhaps, but no. At least not in the super simple test below.

$ cat sock.py
import socket

s = socket.socket(socket.AF_UNIX, -1, -1, None)
print(s)
s.shutdown(socket.SHUT_WR)
s.shutdown(socket.SHUT_RDWR)
s.shutdown(socket.SHUT_RDWR)
$ python3.7 sock.py
<socket.socket fd=3, family=AddressFamily.AF_UNIX, type=SocketKind.SOCK_STREAM, proto=0>
$

I am currently running all tests again, but with the sock.shutdown() simply commented out. On first sight, it seems unneeded just before close(). The test results look much better now. I'm down to 2 errors and 2 failures, some of those probably because I use a boring old C locale instead of UTF-8.

ERROR: breezy.tests.blackbox.test_testament.TestTestament.test_testament_non_ascii
...
UnicodeDecodeError: 'ascii' codec can't decode byte 0xc3 in position 6: ordinal not in range(128)

======================================================================

ERROR: unittest.loader._FailedTest.breezy.plugins.launchpad
breezy.plugins.launchpad.lp_api.LaunchpadlibMissing: launchpadlib is required for Launchpad API access. Please install the launchpadlib package.
======================================================================
FAIL: breezy.tests.blackbox.test_locale.TestLocale.test_log_BOGUS
...
AssertionError: string b'brz: warning: some compiled extensions could not be loaded; see ``brz help missing-extensions``\n' does not start with b'brz: warning: unsupported locale setting'
======================================================================
FAIL: breezy.tests.test_mail_client.TestClaws.test_commandline_is_8bit

How do I find which compiled extensions are failing? Bazaar already reported that as a problem, but I've never seen the root cause of it, so far. I am aware that I don't have the launchpadlib installed (there was no pkgsrc package for it yet, and it seemed to be used only in tools/check-newsbugs.py which is not installed.

-Olaf.

On Sat, Oct 26, 2019 at 06:12:40PM -0000, Olaf Seibert wrote:
> I am currently running all tests again, but with the sock.shutdown()
> simply commented out. On first sight, it seems unneeded just before
> close(). The test results look much better now. I'm down to 2 errors and
> 2 failures, some of those probably because I use a boring old C locale
> instead of UTF-8.
>
> ERROR: breezy.tests.blackbox.test_testament.TestTestament.test_testament_non_ascii
> ...
> UnicodeDecodeError: 'ascii' codec can't decode byte 0xc3 in position 6: ordinal not in range(128)
Please file a new bug about this, with the full backtrace.

>
> ======================================================================
>
> ERROR: unittest.loader._FailedTest.breezy.plugins.launchpad
> breezy.plugins.launchpad.lp_api.LaunchpadlibMissing: launchpadlib is required for Launchpad API access. Please install the launchpadlib package.
launchpadlib is required for the launchpad plugin, but that plugin
should be optional. The tests should simply be skipped if it is
missing.

Can you file a separate bug about this issue as well?

> ======================================================================
> FAIL: breezy.tests.blackbox.test_locale.TestLocale.test_log_BOGUS
> ...
> AssertionError: string b'brz: warning: some compiled extensions could not be loaded; see ``brz help missing-extensions``\n' does not start with b'brz: warning: unsupported locale setting'
> ======================================================================
> FAIL: breezy.tests.test_mail_client.TestClaws.test_commandline_is_8bit
>
>
> How do I find which compiled extensions are failing? Bazaar already reported that as a problem, but I've never seen the root cause of it, so far. I am aware that I don't have the launchpadlib installed (there was no pkgsrc package for it yet, and it seemed to be used only in tools/check-newsbugs.py which is not installed.

The compiled extensions should be optional, none of the tests should
fail if they are missing.

You can build the C extensions (and see which ones fail to build) by
running "make".

Jelmer

--
Jelmer Vernooij <email address hidden>
PGP Key: https://www.jelmer.uk/D729A457.asc

Oh, if you close() the socket before the shutdown, it results in "OSError: [Errno 9] Bad file descriptor", so that is not what is happening.

I'll be happy to just stub out the call do shutdown() if it takes too long to find a root cause here. But maybe I found something: I stuck a pdb.set_trace() just before the shutdown(), and it seems that the socket object is not quite as expected:

(Pdb) sock
<socket.socket [closed] fd=-1, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0>
(Pdb) sock._io_refs
0

although an attempt to simulate this still doesn't get EINVAL:

$ cat sock.py
import socket

s = socket.create_connection(("127.0.0.1", 22))
print(s)
s.detach()
print(s)
s.shutdown(socket.SHUT_RDWR)
$ python3.7 sock.py
<socket.socket fd=3, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('127.0.0.1', 62722), raddr=('127.0.0.1', 22)>
<socket.socket [closed] fd=-1, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6>
Traceback (most recent call last):
  File "sock.py", line 7, in <module>
    s.shutdown(socket.SHUT_RDWR)
OSError: [Errno 9] Bad file descriptor

Another difference is proto=6 in the my test versus proto=0 in the real case.

Could the socket maybe a listening socket or something? (just wild guesswork)

-Olaf.

There may be some race condition involved. I added a check for sock._closed, and still the EINVAL came in one case.

Code as tested:

    def shutdown_socket(self, sock):
        """Properly shutdown a socket.

        This should be called only when no other thread is trying to use the
        socket.
        """
        if not sock._closed:
            try:
                # import pdb; pdb.set_trace()
                sock.shutdown(socket.SHUT_RDWR) # fails with EINVAL
                sock.close()
            except Exception as e:
                import pdb; pdb.set_trace()
                if self.ignored_exceptions(e):
                    pass
                else:
                    raise

...x.test_commit.TestCommit.test_verbose_commit_with_unchanged OK 128ms
...box.test_commit.TestCommit.test_verbose_commit_with_unknown OK 281ms
..._commit.TestCommit.test_warn_about_forgotten_commit_message OK 78ms
...est_commit.TestSmartServerCommit.test_commit_to_lightweight> /home/tmp/devel/breezy/work.x86_64/breezy-3.0.1/breezy/tests/test_server.py(390)shutdown_socket()
-> if self.ignored_exceptions(e):
(Pdb) e
OSError(22, 'Invalid argument')
(Pdb) sock
<socket.socket [closed] fd=-1, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0>
(Pdb) sock._closed
True

-Olaf.

fd=-1 ? That doesn't seem right

On 26 October 2019 19:51:01 BST, Olaf Seibert <email address hidden> wrote:
>Oh, if you close() the socket before the shutdown, it results in
>"OSError: [Errno 9] Bad file descriptor", so that is not what is
>happening.
>
>I'll be happy to just stub out the call do shutdown() if it takes too
>long to find a root cause here. But maybe I found something: I stuck a
>pdb.set_trace() just before the shutdown(), and it seems that the
>socket
>object is not quite as expected:
>
>(Pdb) sock
><socket.socket [closed] fd=-1, family=AddressFamily.AF_INET,
>type=SocketKind.SOCK_STREAM, proto=0>
>(Pdb) sock._io_refs
>0
>
>although an attempt to simulate this still doesn't get EINVAL:
>
>$ cat sock.py
>import socket
>
>s = socket.create_connection(("127.0.0.1", 22))
>print(s)
>s.detach()
>print(s)
>s.shutdown(socket.SHUT_RDWR)
>$ python3.7 sock.py
><socket.socket fd=3, family=AddressFamily.AF_INET,
>type=SocketKind.SOCK_STREAM, proto=6, laddr=('127.0.0.1', 62722),
>raddr=('127.0.0.1', 22)>
><socket.socket [closed] fd=-1, family=AddressFamily.AF_INET,
>type=SocketKind.SOCK_STREAM, proto=6>
>Traceback (most recent call last):
> File "sock.py", line 7, in <module>
> s.shutdown(socket.SHUT_RDWR)
>OSError: [Errno 9] Bad file descriptor
>
>Another difference is proto=6 in the my test versus proto=0 in the real
>case.
>
>Could the socket maybe a listening socket or something? (just wild
>guesswork)
>
>-Olaf.
>
>--
>You received this bug notification because you are subscribed to
>Breezy.
>https://bugs.launchpad.net/bugs/1849971
>
>Title:
> Some tests failing due to shutdown(2) returning EINVAL
>
>To manage notifications about this bug go to:
>https://bugs.launchpad.net/brz/+bug/1849971/+subscriptions