asyncio open_connection fails when a socket is explicitly closed

@pfmoore

BPO	43253
Nosy	@pfmoore, @tjguk, @asvetlov, @zware, @1st1, @zooba, @mhils, @eamanu, @miss-islington
PRs	bpo-43253: don't shutdown invalid socket handles #31892 [3.9] bpo-43253: Don't call shutdown() for invalid socket handles (GH-31892) #31905 [3.10] bpo-43253: Don't call shutdown() for invalid socket handles (GH-31892) #31906

^{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 = <Date 2022-03-15.15:49:39.190>
created_at = <Date 2021-02-18.13:46:25.959>
labels = ['3.10', '3.11', '3.9', 'OS-windows', 'expert-asyncio']
title = 'asyncio open_connection fails when a socket is explicitly closed'
updated_at = <Date 2022-03-16.12:19:30.989>
user = 'https://bugs.python.org/danielen1337'

bugs.python.org fields:

activity = <Date 2022-03-16.12:19:30.989>
actor = 'mhils'
assignee = 'none'
closed = True
closed_date = <Date 2022-03-15.15:49:39.190>
closer = 'asvetlov'
components = ['Windows', 'asyncio']
creation = <Date 2021-02-18.13:46:25.959>
creator = 'danielen1337'
dependencies = []
files = []
hgrepos = []
issue_num = 43253
keywords = []
message_count = 12.0
messages = ['387228', '387235', '387238', '414620', '415071', '415128', '415205', '415250', '415254', '415255', '415257', '415338']
nosy_count = 11.0
nosy_names = ['paul.moore', 'tim.golden', 'asvetlov', 'zach.ware', 'yselivanov', 'steve.dower', 'mhils', 'eamanu', 'miss-islington', 'danielen1337', 'adhika.setyap']
pr_nums = ['31892', '31905', '31906']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = None
url = 'https://bugs.python.org/issue43253'
versions = ['Python 3.9', 'Python 3.10', 'Python 3.11']

Python 3.9.0 (tags/v3.9.0:9cf6752, Oct 5 2020, 15:34:40) [MSC v.1927 64 bit (AMD64)]
Type 'copyright', 'credits' or 'license' for more information
IPython 7.18.1 -- An enhanced Interactive Python. Type '?' for help.

In [1]: import socket
   ...: s1, s2 = socket.socketpair()
   ...: import asyncio
   ...: async def test():
   ...:     r1, w1 = await asyncio.open_connection(sock=s1)
   ...:     r2, w2 = await asyncio.open_connection(sock=s2)
   ...:     s1.close()
   ...: asyncio.run(test())
Exception in callback _ProactorBasePipeTransport._call_connection_lost(ConnectionAbo...e, 1236, None))
handle: <Handle _ProactorBasePipeTransport._call_connection_lost(ConnectionAbo...e, 1236, None))>
Traceback (most recent call last):
  File "c:\python39\lib\asyncio\events.py", line 80, in _run
    self._context.run(self._callback, *self._args)
  File "c:\python39\lib\asyncio\proactor_events.py", line 162, in _call_connection_lost
    self._sock.shutdown(socket.SHUT_RDWR)
OSError: [WinError 10038] An operation was attempted on something that is not a socket

I cannot reproduce on a Debian machine. Seems to be a Windows component issue?

It reproduced on a windows machine

Please consider passing 'sock' argument as the ownership transfer.

You should not perform any action on 'sock' object directly anymore.
This is true for all asyncio API.

We are hitting the same traceback with mitmproxy on Windows without ever passing a socket object to open_connection. In other words, this can be triggered without performing any action on 'sock' due to some race conditions in the Windows network stack. I unfortunately don't have a better repro for that race other than what Daniel provided.

asvetlov: Sorry if I articulated myself badly, but I do think this is a valid bug. It's unfortunately hard to provide a better repro (I tried), but we are hitting this regularly when mitmproxy is accepting connections under heavy load. We're just calling asyncio.start_server(handler, "127.0.0.1", 8080) in mitmproxy and never interact with the underlying socket object.

Here are some observations that are true for all crashes:

The socket fileno is -1 when it crashes.
_call_connection_lost is called by _ProactorBasePipeTransport.close, which is called by _ProactorBasePipeTransport.__del__ [1]
There are no previous calls to _call_connection_lost.
Windows only, loopback connections in our case.
Wireshark shows that client and server are first happily exchanging packets. At some point the client sends a FIN, which the Python server ACKs immediately. A few seconds later the Python server sends a FIN back.

An obvious fix without understanding the root cause would be to check fileno in

cpython/Lib/asyncio/proactor_events.py

Line 161 in d929aa7

if hasattr(self._sock, 'shutdown'):

. I'm not too familar with proactor to assess if that is a good idea. Sorry for not being able to provide more details.

[1]

cpython/Lib/asyncio/proactor_events.py

Lines 102 to 116 in d929aa7

    
           def close(self): 
        
               if self._closing: 
        
                   return 
        
               self._closing = True 
        
               self._conn_lost += 1 
        
               if not self._buffer and self._write_fut is None: 
        
                   self._loop.call_soon(self._call_connection_lost, None) 
        
               if self._read_fut is not None: 
        
                   self._read_fut.cancel() 
        
                   self._read_fut = None 
        
           def __del__(self, _warn=warnings.warn): 
        
               if self._sock is not None: 
        
                   _warn(f"unclosed transport {self!r}", ResourceWarning, source=self) 
        
                   self.close()

Maximilian, thanks for the investigation.

A check for 'fileno != -1' seems correct to me.
Would you prepare a pull request?

New changeset 7015541 by Maximilian Hils in branch 'main':
bpo-43253: Don't call shutdown() for invalid socket handles (GH-31892)
7015541

New changeset 88c243f by Miss Islington (bot) in branch '3.10':
bpo-43253: Don't call shutdown() for invalid socket handles (GH-31892)
88c243f

New changeset 64a68c3 by Miss Islington (bot) in branch '3.9':
bpo-43253: Don't call shutdown() for invalid socket handles (GH-31892)
64a68c3

Thanks!

Thank you for the super quick turnaround.
My heart goes out to you and everyone else in Ukraine.

fix(dev/bundle): cmd.exe echoes + dev mode entry + WinError 10054 + p…

Navigation Menu

Repository navigation

asyncio open_connection fails when a socket is explicitly closed #87419

4 remaining items

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

	def close(self):
	if self._closing:
	return
	self._closing = True
	self._conn_lost += 1
	if not self._buffer and self._write_fut is None:
	self._loop.call_soon(self._call_connection_lost, None)
	if self._read_fut is not None:
	self._read_fut.cancel()
	self._read_fut = None

	def __del__(self, _warn=warnings.warn):
	if self._sock is not None:
	_warn(f"unclosed transport {self!r}", ResourceWarning, source=self)
	self.close()

asyncio open_connection fails when a socket is explicitly closed #87419

Description

Activity

danielen1337 commented on Feb 18, 2021

eamanu commented on Feb 18, 2021

danielen1337 commented on Feb 18, 2021

asvetlov commented on Mar 6, 2022

mhils commented on Mar 13, 2022

4 remaining items

mhils commented on Mar 14, 2022

asvetlov commented on Mar 14, 2022

asvetlov commented on Mar 15, 2022

miss-islington commented on Mar 15, 2022

miss-islington commented on Mar 15, 2022

asvetlov commented on Mar 15, 2022

mhils commented on Mar 16, 2022

Metadata

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

Issue actions