Repository navigation
test_socket leaks file descriptors on macOS #80931
Description
Activity
This PR #12271 has consistent build failures in test_socket even after merging the master branch.
Sample build failure : https://dev.azure.com/Python/cpython/_build/results?buildId=41411
I tried reproducing this and I can't reproduce it in Ubuntu. Mac OS seems to fail with leaked references which I think is unrelated to the above Azure failure. The Mac issue is open (bpo-35092 reported by Victor closed as duplicate of bpo-23828) but it was about warning though running with regrtest seems to leak references in addition to warnings.
Ubuntu build :
karthi@ubuntu-s-1vcpu-1gb-blr1-01:~/cpython$ ./python -m test -R 3:3 test_socket Run tests sequentially 0:00:00 load avg: 0.01 [1/1] test_socket beginning 6 repetitions 123456 ...... test_socket passed in 3 min 7 sec == Tests result: SUCCESS == 1 test OK. Total duration: 3 min 7 sec Tests result: SUCCESSMac OS build (Mac OS 10.10.4 (14E46))
➜ cpython git:(master) ./python.exe -m test -R 3:3 test_socket Run tests sequentially 0:00:00 load avg: 2.00 [1/1] test_socket beginning 6 repetitions 123456 /Users/karthikeyansingaravelan/stuff/python/cpython/Lib/test/test_socket.py:2419: RuntimeWarning: received malformed or improperly-truncated ancillary data result = sock.recvmsg(bufsize, \*args) /Users/karthikeyansingaravelan/stuff/python/cpython/Lib/test/test_socket.py:2510: RuntimeWarning: received malformed or improperly-truncated ancillary data result = sock.recvmsg_into([buf], \*args) ./Users/karthikeyansingaravelan/stuff/python/cpython/Lib/test/test_socket.py:2419: RuntimeWarning: received malformed or improperly-truncated ancillary data result = sock.recvmsg(bufsize, \*args) /Users/karthikeyansingaravelan/stuff/python/cpython/Lib/test/test_socket.py:2510: RuntimeWarning: received malformed or improperly-truncated ancillary data result = sock.recvmsg_into([buf], \*args) ./Users/karthikeyansingaravelan/stuff/python/cpython/Lib/test/test_socket.py:2419: RuntimeWarning: received malformed or improperly-truncated ancillary data result = sock.recvmsg(bufsize, \*args) /Users/karthikeyansingaravelan/stuff/python/cpython/Lib/test/test_socket.py:2510: RuntimeWarning: received malformed or improperly-truncated ancillary data result = sock.recvmsg_into([buf], \*args) ./Users/karthikeyansingaravelan/stuff/python/cpython/Lib/test/test_socket.py:2419: RuntimeWarning: received malformed or improperly-truncated ancillary data result = sock.recvmsg(bufsize, \*args) /Users/karthikeyansingaravelan/stuff/python/cpython/Lib/test/test_socket.py:2510: RuntimeWarning: received malformed or improperly-truncated ancillary data result = sock.recvmsg_into([buf], \*args) ./Users/karthikeyansingaravelan/stuff/python/cpython/Lib/test/test_socket.py:2419: RuntimeWarning: received malformed or improperly-truncated ancillary data result = sock.recvmsg(bufsize, \*args) /Users/karthikeyansingaravelan/stuff/python/cpython/Lib/test/test_socket.py:2510: RuntimeWarning: received malformed or improperly-truncated ancillary data result = sock.recvmsg_into([buf], \*args) ./Users/karthikeyansingaravelan/stuff/python/cpython/Lib/test/test_socket.py:2419: RuntimeWarning: received malformed or improperly-truncated ancillary data result = sock.recvmsg(bufsize, \*args) /Users/karthikeyansingaravelan/stuff/python/cpython/Lib/test/test_socket.py:2510: RuntimeWarning: received malformed or improperly-truncated ancillary data result = sock.recvmsg_into([buf], \*args) . test_socket leaked [20, 20, 20] file descriptors, sum=60 test_socket failed in 2 min 31 sec == Tests result: FAILURE == 1 test failed: test_socket Total duration: 2 min 31 sec Tests result: FAILUREbpo-35092 reported by Victor closed as duplicate of bpo-23828
Sorry, it was reported by Pablo in bpo-35092. I haven't seen any old reports of this in search. The other buildbots on Ubuntu run fine so not sure if it's only for Azure and Ubuntu for the PR since master is green on Azure and the buildbots so feel free to close this if needed.
- changed the title
[-]test_socket failed (env changed) on Azure pipeline[/-][+]test_socket leaks file descriptors on macOS[/+]on Apr 29, 2019 The test failure is reproducible on the PR 12271 merging master branch on Ubuntu with -R 3:3 test_socket. Sorry, I tried it initially on master thinking it was a master branch problem. I don't see C related code in the PR. There was a merge commit [0] after which the failure is consistently reproducible. I tried reverting parts of the PR to narrow down the failure and happened to come across the below statement in the diff where the test object and elapsed test for time are stored to be printed later. Commenting out the call makes tests pass for test_socket and much more baffling is that changing the code to use list instead of tuple causes the error to go away. Also I tried changing append to use extend or just to append test object instead of a tuple of test object and elapsed time which all pass. Instead of using test object in tuple just using (object(), elapsed) as a tuple also causes failure. I guess there is something with tuples here but it doesn't make much sense.
On trying to bisect the merge commit I have narrowed down the below commits where the PR passes with tuple itself and then fails. In between the success and failure commit there were some changes made to hunterleaks and socket.create_server utility was added.
f66e336 (success)
58721a9 (success)
2b00db6 (fails)# Sample failure on PR's HEAD on Ubuntu
⋊\> \~/cpython on pr_12271 ./python -m test --fail-env-changed -R 3:3 test_socket 05:45:52 Run tests sequentially 0:00:00 load avg: 0.22 [1/1] test_socket beginning 6 repetitions 123456 Warning -- threading_cleanup() failed to cleanup 0 threads (count: 0, dangling: 5) Dangling thread: \<Thread(Thread-3, stopped 140152613795584)\> Dangling thread: \<Thread(Thread-1, stopped 140152613795584)\> Dangling thread: \<Thread(Thread-4, stopped 140152613795584)\> Dangling thread: \<Thread(Thread-2, stopped 140152613795584)\> Dangling thread: \<_MainThread(MainThread, started 140152731227904)\> ...... test_socket failed (env changed) in 3 min 6 sec == Tests result: ENV CHANGED == 1 test altered the execution environment: test_socket Total duration: 3 min 6 sec Tests result: ENV CHANGED
The below patch on the PR to use list causes the tests to pass but I am highly confused over how changing to tuple to list fixes this and this might potentially be hiding a bug.
$ git diff diff --git a/Lib/unittest/result.py b/Lib/unittest/result.py index 273ca3beef..b8fd714679 100644 --- a/Lib/unittest/result.py +++ b/Lib/unittest/result.py @@ -160,7 +160,7 @@ class TestResult(object):
def addDuration(self, test, elapsed): """Called when a test finished to run, regardless of its outcome.""" - self.collectedDurations.append((test, elapsed)) + self.collectedDurations.append([test, elapsed])def wasSuccessful(self): """Tells whether or not this result was a success."""
[0] 3c4af91
remilapeyre commented
on Jun 7, 2020 remilapeyremannequinMannequinI think I stumbled on this too, I think the test that causes some issue is testCmsgTrunc2Int:
./python -m test -R: test_socket -m testCmsgTrunc2Int 0:00:00 load avg: 1.66 Run tests sequentially 0:00:00 load avg: 1.66 [1/1] test_socket beginning 9 repetitions 123456789 ......... test_socket leaked [2, 2, 2, 2] file descriptors, sum=8 test_socket failed == Tests result: FAILURE == 1 test failed: test_socket Total duration: 2.0 sec Tests result: FAILURE
There is some file descriptors that are created by newFDs() but they are supposed to be cleaned up, maybe it is some race condition as I see that test_socket create a thread for each test?
This still reproducible on current main and seems that hasn't been fixed yet.
Trace:./python.exe -m test -q test_socket 0:00:00 load avg: 2.44 Run tests sequentially /Users/admin/Projects/cpython/Lib/test/test_socket.py:2940: RuntimeWarning: received malformed or improperly-truncated ancillary data result = sock.recvmsg_into([buf], *args) /Users/admin/Projects/cpython/Lib/test/test_socket.py:2849: RuntimeWarning: received malformed or improperly-truncated ancillary data result = sock.recvmsg(bufsize, *args) test_socket passed in 58.0 sec == Tests result: SUCCESS == Total duration: 58.0 sec Tests result: SUCCESS
Refleaks:
./python.exe -m test -R 3:3 test_socket -m testCmsgTrunc2Int 0:00:00 load avg: 3.14 Run tests sequentially 0:00:00 load avg: 3.14 [1/1] test_socket beginning 6 repetitions 123456 ...... test_socket leaked [2, 2, 2] file descriptors, sum=6 test_socket failed (reference leak) == Tests result: FAILURE == 1 test failed: test_socket Total duration: 354 ms Tests result: FAILURE
19 remaining items
The linked draft PR avoids the FD leaks by effectively skipping the problematic tests when detecting a refleak hunting run on macOS.
The way the PR detects such a run is gross and shouldn't be merged. If the general approach is OK (that is, detect a refleak hunting run and skip tests) there should be a better interface.
Something we could do:
- Have a
test.support.hunting_for_refleaksfunction that checks a global flag in that module - Have
test.libregrtest.refleaks.runtest_refleakset this flag while running tests
The integration into the test functions is also not optimal, could be make nicer with two new decorators:
@skipForRefleakingHuntingIf(sys.platform == "darwin") def testCmsgTrunc0(self): ... @testCmsgTrunk0.client_skip def _testCmsgTrunc0(self): ...
The latter mirrors
skipWithClientIf, but would have a different implementation because theskipForRefleakingHuntingIfdecorator needs to do something at test time instead of at load time.- Have a
I've updated the PR:
- Testing for a ref leaking run is not integrated into
test.libregrtestandtest.support.refleak_helper - Using decorators to skip tests while hunting for refleaks
The decorators are still part of
test_socket, but that's primarily because I mirrored theclient_skipfunctionality as sketched in my previous message. Maybe it is better to move the skip function totest.support.refleak_helperand have a new decorator intest_socketthat replaces theclient_skiplogic.- Testing for a ref leaking run is not integrated into
thanks for the @-mention on the other issue @corona10 !
just wanted to mention that this buildbot is now covering refleaks on macOS. it was originally intended to provide free-threaded macOS refleaks coverage, but since it was consistently failing (due to this issue), I changed it to cover the default (with GIL) configuration until it is fixed.
this means you can invoke this builder on PRs using the correct incantation :)I don't think it's related, but worth calling out that the ASAN macOS builder has also been failing consistently (3 failing tests: test_cmd_line test_posix test_subprocess). I can file a separate issue (or search for an existing one).
Well, it's not reproducible on my local machine.
But all failures are about missing file descriptors; it could be a local system issue.
Apparently, it's worth creating an issue on the build bot repo.➜ cpython git:(main) ✗ ./python.exe -m test test_cmd_line test_posix test_subprocess -R 3:3 Using random seed: 2522577964 Raised RLIMIT_NOFILE: 256 -> 1024 0:00:00 load avg: 2.02 Run 3 tests sequentially 0:00:00 load avg: 2.02 [1/3] test_cmd_line beginning 6 repetitions 123456 ...... 0:00:22 load avg: 2.80 [2/3] test_posix beginning 6 repetitions 123456 ...... 0:00:30 load avg: 2.73 [3/3] test_subprocess beginning 6 repetitions 123456 ...... test_subprocess passed in 1 min 51 sec == Tests result: SUCCESS == All 3 tests OK. Total duration: 2 min 22 sec Total tests: run=485 skipped=85 Total test files: run=3/3 Result: SUCCESSReacted by Itamar OrenWell, it's not reproducible on my local machine. But all failures are about missing file descriptors; it could be a local system issue. Apparently, it's worth creating an issue on the build bot repo.
...I've filed an issue with Apple about this: FB1354223
The attached program reproduces the issue. When run without arguments it sends and receives two file descriptors, when run with arguments the receive buffer is too small and the proces leaks file descriptors.
/* * This program sends and receives a number of file descriptors between * a socket pair. * * To build: * $ cc -o repro repro.c * * There are two options to run: * * - Run with a buffer that's the right size to receive file descriptors: * * $ ./repro * * - Run with a too small buffer: * * $ ./repro arg * * The former works as expected, the latter leaks a file descriptor. */ #include <dirent.h> #include <stdio.h> #include <sys/socket.h> #include <fcntl.h> #include <string.h> #include <unistd.h> #define NUM_FD 2 int fd_count() { int count = 0; DIR* dir; struct dirent* ent; dir = opendir("/dev/fd"); if (dir == NULL) { perror("opendir"); return -1; } for (ent = readdir(dir); ent != NULL; ent = readdir(dir)) { count += 1; } closedir(dir); /* opendir uses a file descriptor */ count -= 1; return count; } int main(int argc, char** argv) { int fd[2]; int r; int data_fds[NUM_FD]; int before, after; int data; int xit = 0; /* * Setup: Create a socket pair for sending an receving * and open a file to send. */ r = socketpair(AF_UNIX, SOCK_STREAM, 0, fd); if (r == -1) { perror("socketpair"); return 1; } for (int i = 0; i < NUM_FD; i++) { data_fds[i] = open("/dev/zero", O_RDONLY); if (data_fds[i] == -1) { perror("open data_fd"); return 1; } } before = fd_count(); if (before == -1) { return 1; } /* * Send file desciptors using SCM_RIGHTS */ { struct msghdr msg = { 0 }; struct cmsghdr* cmsg; union { char buf[CMSG_SPACE(sizeof(data_fds))]; struct cmsghdr align; } u; struct iovec vec; msg.msg_name = NULL; msg.msg_namelen = 0; msg.msg_control = u.buf; msg.msg_controllen = sizeof(u.buf); data = 1234; msg.msg_iov = &vec; msg.msg_iovlen = 1; vec.iov_base = &data; vec.iov_len = sizeof(data); cmsg = CMSG_FIRSTHDR(&msg); cmsg->cmsg_level = SOL_SOCKET; cmsg->cmsg_type = SCM_RIGHTS; cmsg->cmsg_len = CMSG_LEN(sizeof(int) * NUM_FD); memcpy((int *)CMSG_DATA(cmsg), data_fds, NUM_FD * sizeof(int)); r = sendmsg(fd[0], &msg, 0); if (r == -1) { perror("sendmsg"); return 1; } } /* * Receive file descriptors */ { struct msghdr recv_msg = { 0 }; int recv_fds[NUM_FD]; int recv_data; struct iovec recv_vec; struct cmsghdr* recv_cmsg; char recv_ch; union { char buf[CMSG_SPACE(sizeof(recv_fds))]; struct cmsghdr align; } recv_u; union { char buf[0]; struct cmsghdr align; } recv_u_small; recv_msg.msg_name = NULL; recv_msg.msg_namelen = 0; recv_msg.msg_iov = &recv_vec; recv_msg.msg_iovlen = 1; recv_vec.iov_base = &recv_data; recv_vec.iov_len = sizeof(recv_data); if (argc == 1) { recv_msg.msg_control = recv_u.buf; recv_msg.msg_controllen = sizeof(recv_u.buf); } else { recv_msg.msg_control = recv_u_small.buf; recv_msg.msg_controllen = sizeof(recv_u_small.buf); } r = recvmsg(fd[1], &recv_msg, 0); if (r == -1) { perror("recvmsg"); return 1; } recv_cmsg = CMSG_FIRSTHDR(&recv_msg); if (recv_cmsg == NULL) { fputs("No control message received\n", stderr); xit = 3; goto done; } if (recv_cmsg->cmsg_level != SOL_SOCKET || recv_cmsg->cmsg_type != SCM_RIGHTS) { fputs("Unexpected control message", stderr); xit = 3; goto done; } memcpy(recv_fds, CMSG_DATA(recv_cmsg), sizeof(recv_fds)); fputs("Received fds", stdout); for (int i = 0; i < NUM_FD; i++) { printf("%c %d", i == 0?':':',', recv_fds[i]); close(recv_fds[i]); } fputs("\n", stdout); } /* Test assertions */ done: after = fd_count(); if (after == -1) { return 1; } if (after != before) { printf("Number of open descriptors changed: before=%d after=%d\n", before, after); return 2; } return xit; }
Reacted by Donghee Na and Itamar Oren- added a commit that references this issue
on Feb 11, 2024 What's the status of this issue?
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:
bugs.python.org fields:
Linked PRs