test_socket leaks file descriptors on macOS

[tirkarthi]

BPO	36750
Nosy	@vstinner, @giampaolo, @pablogsal, @remilapeyre, @tirkarthi

^{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 2019-04-29.08:26:44.616>
labels = ['3.8', 'type-bug', 'library', '3.9', '3.10']
title = 'test_socket leaks file descriptors on macOS'
updated_at = <Date 2020-06-07.17:06:50.594>
user = 'https://github.com/tirkarthi'

bugs.python.org fields:

activity = <Date 2020-06-07.17:06:50.594>
actor = 'remi.lapeyre'
assignee = 'none'
closed = False
closed_date = None
closer = None
components = ['Library (Lib)']
creation = <Date 2019-04-29.08:26:44.616>
creator = 'xtreak'
dependencies = []
files = []
hgrepos = []
issue_num = 36750
keywords = []
message_count = 4.0
messages = ['341052', '341053', '341136', '370908']
nosy_count = 5.0
nosy_names = ['vstinner', 'giampaolo.rodola', 'pablogsal', 'remi.lapeyre', 'xtreak']
pr_nums = []
priority = 'normal'
resolution = None
stage = None
status = 'open'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue36750'
versions = ['Python 3.8', 'Python 3.9', 'Python 3.10']

Linked PRs

• gh-80931: Skip some socket tests while hunting for refleaks on macOS #114057
• [3.11] gh-80931: Skip some socket tests while hunting for refleaks on macOS (GH-114057) #114380
• [3.12] gh-80931: Skip some socket tests while hunting for refleaks on macOS (GH-114057) #114381

[tirkarthi]

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: SUCCESS

Mac 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: FAILURE

[tirkarthi]

bpo-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.

[tirkarthi]

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]

I 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?

[Eclips4]

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