💊 CircleCI build failures summary and remediations

As of commit fa096bc (more details on the Dr. CI page):

• 1/1 failures introduced in this PR

🕵️ 1 new failure recognized by patterns

The following build failures do not appear to be due to upstream breakages (reran 1 job to discount flakiness):

pytorch_linux_xenial_py3_6_gcc5_4_test (1/1)

Step: "Test" (full log | pattern match details | 🔁 rerun) <confirmed not flaky by 2 failures>

Apr 10 08:03:39 ---------------------------------------------------------------------- 
Apr 10 08:03:39 Traceback (most recent call last): 
Apr 10 08:03:39   File "/opt/conda/lib/python3.6/site-packages/torch/testing/_internal/common_distributed.py", line 175, in wrapper 
Apr 10 08:03:39     self._join_processes(fn) 
Apr 10 08:03:39   File "/opt/conda/lib/python3.6/site-packages/torch/testing/_internal/common_distributed.py", line 285, in _join_processes 
Apr 10 08:03:39     self._check_return_codes(elapsed_time) 
Apr 10 08:03:39   File "/opt/conda/lib/python3.6/site-packages/torch/testing/_internal/common_distributed.py", line 324, in _check_return_codes 
Apr 10 08:03:39     self.assertEqual(p.exitcode, first_process.exitcode) 
Apr 10 08:03:39   File "/opt/conda/lib/python3.6/site-packages/torch/testing/_internal/common_utils.py", line 927, in assertEqual 
Apr 10 08:03:39     super(TestCase, self).assertLessEqual(abs(x - y), prec, message) 
Apr 10 08:03:39 AssertionError: 12 not less than or equal to 1e-05 :  
Apr 10 08:03:39  
Apr 10 08:03:39 ---------------------------------------------------------------------- 
Apr 10 08:03:39 Ran 62 tests in 88.523s 
Apr 10 08:03:39  
Apr 10 08:03:39 FAILED (failures=1, skipped=2) 
Apr 10 08:03:39  
Apr 10 08:03:39 Generating XML reports... 
Apr 10 08:03:39 Generated XML report: test-reports/dist-gloo/TEST-DistAutogradTestWithSpawn-20200410080210.xml 
Apr 10 08:03:39 Traceback (most recent call last): 
Apr 10 08:03:39   File "test/run_test.py", line 696, in <module> 

TL;DR:

• The key issue is most likely in the Python packages multiprocessing, socket or even the C implementation of an AF_UNIX socket. IMO it's best to work around it in PyTorch
• Adding a test would be challenging because the size of the data used in a test would fully depend on the host's limits, or alternatively it might mess up ulimit for subsequent tests if the exit is not clean.

I managed to reproduce the same behaviour outside PyTorch with the following script:

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


if len(sys.argv) != 4:
    print("Usage: ", sys.argv[0], " tmp_dirname iteration (send|recv)")
    sys.exit(1)

if __name__ == '__main__':
    dirname = sys.argv[1]
    sock_path = dirname + "/sock"
    iterations = int(sys.argv[2])
    def dummy_path(i):
        return dirname + "/" + str(i) + ".dummy"


    if sys.argv[3] == 'send':
        while not os.path.exists(sock_path):
            pass
        client = socket.socket(socket.AF_UNIX, socket.SOCK_DGRAM)
        client.connect(sock_path)
        for i in range(iterations):
            fd = os.open(dummy_path(i), os.O_WRONLY | os.O_CREAT)
            ancdata = array.array('i', [fd])
            msg = bytes([i % 256])
            print("Sending fd ", fd, " (iteration #", i, ")")
            client.sendmsg([msg], [(socket.SOL_SOCKET, socket.SCM_RIGHTS, ancdata)])


    else:
        assert sys.argv[3] == 'recv'

        if os.path.exists(dirname):
            raise Exception("Directory exists")

        os.mkdir(dirname)

        print("Opening socket...")
        server = socket.socket(socket.AF_UNIX, socket.SOCK_DGRAM)
        server.bind(sock_path)

        print("Listening...")
        for i in range(iterations):
            a = array.array('i')
            msg, ancdata, flags, addr = server.recvmsg(1, socket.CMSG_SPACE(a.itemsize))
            assert(len(ancdata) == 1)
            cmsg_level, cmsg_type, cmsg_data = ancdata[0]
            a.frombytes(cmsg_data)
            print("Received fd ", a[0], " (iteration #", i, ")")

        shutil.rmtree(dirname)

Steps to reproduce:

1. Run two shells and set lower file descriptor limit in the receiving one:

(shell1) ulimit -n 1020
(shell2) ulimit -n 1022

2. Run the script above with the recv option in the first shell

./test_socket.py sock_tmp 1017 recv

3. Run the script with the send option in the second shell:

./test_socket.py sock_tmp 1017 send

The key problem here is that when the root process is about to receive an FD over a socket from a worker, that FD would exceed the open file descriptors limit. To mitigate that, the FD is silently removed from the message and the MSG_CTRUNC flag is set. (The flag might be a bit misleading since the manpage says that it indicates that some control data were discarded due to lack of space in the buffer for ancillary data. It doesn't really matter, though, since the standard multiprocessing package ignores it.)

I haven't verified it but I suspect that this behaviour of recvmsg in Python's socket is consistent with recvmsg in C. I'm not sure it's the desired behaviour. AFAICT, there is no indication of an issue anywhere, other than the MSG_CTRUNC flag. Anyway, digging into the C implementation of recvmsg would be fun but outside of the scope of the PyTorch issue.

The worker itself does not exceed the limit in the common scenario. If you tweak the ulimit and number of the FDs received/sent in the script above, instead of the RuntimeError: received 0 items of ancdata you might get OSError: Too many open files on the receiver/sender or both. During my testing of PyTorch I have seen that OSError passed through the DataLoader a couple times but I couldn't reproduce it afterwards.

I would love to add a test for this change, but I'm worried that if I lower ulimit for a single test, it might affect subsequent tests if my test exits in an unexpected way. An alternative approach would be to send as many tensors as ulimit allows. But since that environment setting can have very wide range, it might cause some unexpected issues.

@ssnl do you think you would be able to review this PR? (Baranowski bug me again in a day if there's no response)

Re testing, you should just run these tests in a completely separate process from the rest of the tests. There are some examples of how to do this, see for example TestCuda.test_cuda_init_race (in general, grep for subprocess in the test suite)

Code looks generally reasonable, but I'd suggest spending a little time trying to check in the very nice test you've written.

macos failure seems real.

NameError: name 'IS_MACOS' is not defined

@pytorchbot merge this please

Thanks. Sorry for the unnecessary back-and-forth at the end.

No, thank you for the analysis and fix!

Internal CI failure

  warnings.warn(err_msg)
test_fd_limit_exceeded (test_dataloader.TestDataLoader) ... I0319 21:23:47.775116 749361 init.cc:561] Skip logging in unit test environment for event: tensor.create
Traceback (most recent call last):
  File "<string>", line 3, in <module>
ModuleNotFoundError: No module named 'torch.utils'
ERROR

======================================================================
ERROR: test_fd_limit_exceeded (test_dataloader.TestDataLoader)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/data/sandcastle/boxes/eden-trunk-hg-fbcode-fbsource/fbcode/buck-out/dev/gen/caffe2/test/dataloader#binary,link-tree/test_dataloader.py", line 816, in test_fd_limit_exceeded
    """])
  File "/usr/local/fbcode/platform007/lib/python3.7/subprocess.py", line 363, in check_call
    raise CalledProcessError(retcode, cmd)
subprocess.CalledProcessError: Command '['/usr/local/fbcode/platform007/bin/python3.7', '-c', 'import torch\nimport resource\nfrom torch.utils.data import DataLoader, IterableDataset\n\nclass RandomDataset(IterableDataset):\n    def __init__(self, len, size):\n        super(RandomDataset).__init__()\n        self.len = len\n        self.size = size\n\n    def __iter__(self):\n        return self\n\n    def __next__(self):\n        if self.len <= 0:\n            raise StopIteration\n        self.len -= 1\n        return torch.randn(self.size)\n\ntry:\n    keep_fds_alive = []\n    resource.setrlimit(resource.RLIMIT_NOFILE, (100, 100))\n    for random_t in DataLoader(RandomDataset(200, (2,2)),\n                               num_workers=1):\n      random_t.max(dim=0)\n      keep_fds_alive.append(random_t)\nexcept RuntimeError as e:\n    assert "ulimit -n" in str(e)\n    assert "set_sharing_strategy" in str(e)\nelse:\n    assert False, "Expected a RuntimeError with keywords ulimit and set_sharing_strategy"\n']' returned non-zero exit status 1.

----------------------------------------------------------------------
R

Maybe it's just something easy?

I guess AF_UNIX sockets were not used in this test for some reason.

Now that I think of it, this test should not enforce that DataLoader fails. Rather, it should enforce that DataLoader either works correctly or fails in the known way. I will fix that but I'm not sure I will manage to do it today.

Thanks, no hurry.

Sorry about the delay. What I think the internal problem is, is that we're invoking python subprocess and it's not picking up the same python environment as the parent process. I'm pretty sure we've done this correctly elsewhere and I need to figure out how; haven't had a chance to yet.

we're invoking python subprocess and it's not picking up the same python environment as the parent process

I just ran into this somewhere else. A couple of things that may help:

• Using sys.executable instead of python to invoke Python in the subprocess
• If it's a conda env, it needs activation
• If it's a virtualenv it's easier, but still PATH and PYTHONHOME can be different in the subprocess (see e.g. this SO discussion) so setting those or source activateing may help.

We're using sys.executable, but the way Python tests run internally is speshul so I wonder if that's related.

subprocess.check_output should by default pass over the env vars. Could we add pprint(os.environ) in the script to make sure that env vars are the problem?

As best as I can tell, invoking python from subprocess has never actually worked in our internal build environment (I thought it might work, because there were many subprocess invocations that weren't guarded, but as best I can tell they all accidentally weren't run at all in fbcode for various other reasons). So let's just skip this test when we run it internally. You can case on this using IS_SANDCASTLE, just do a skipIf on your test. Sorry about the hold up.

@ezyang Done, this should be ready to merge. The CI failure looks unrelated to me.

@ezyang merged this pull request in 69e3ee2.