requests icon indicating copy to clipboard operation
requests copied to clipboard

requests treats urllib3's SSL handshake timeout as ReadTimeout

Open metheoryt opened this issue 6 years ago • 15 comments

Expected Result

When connecting to a remote machine via SSL/TLS, and SSL handshake timeout happens, I expect to have SSLError or ConnectionError exception.

Actual Result

requests raises ReadTimeout

Reproduction Steps

I don't know how to reproduce this, but I have a real stacktrace (most recent call first):

timeout: _ssl.c:704: The handshake operation timed out
  File "urllib3/connectionpool.py", line 346, in _make_request
    self._validate_conn(conn)
  File "urllib3/connectionpool.py", line 850, in _validate_conn
    conn.connect()
  File "urllib3/connection.py", line 326, in connect
    ssl_context=context)
  File "urllib3/util/ssl_.py", line 329, in ssl_wrap_socket
    return context.wrap_socket(sock, server_hostname=server_hostname)
  File "python3.5/ssl.py", line 385, in wrap_socket
    _context=self)
  File "python3.5/ssl.py", line 760, in __init__
    self.do_handshake()
  File "python3.5/ssl.py", line 996, in do_handshake
    self._sslobj.do_handshake()
  File "python3.5/ssl.py", line 641, in do_handshake
    self._sslobj.do_handshake()
ReadTimeoutError: HTTPSConnectionPool(host='somehost.com', port=443): Read timed out. (read timeout=5)
  File "requests/adapters.py", line 440, in send
    timeout=timeout
  File "urllib3/connectionpool.py", line 639, in urlopen
    _stacktrace=sys.exc_info()[2])
  File "urllib3/util/retry.py", line 357, in increment
    raise six.reraise(type(error), error, _stacktrace)
  File "urllib3/packages/six.py", line 686, in reraise
    raise value
  File "urllib3/connectionpool.py", line 601, in urlopen
    chunked=chunked)
  File "urllib3/connectionpool.py", line 349, in _make_request
    self._raise_timeout(err=e, url=url, timeout_value=conn.timeout)
  File "urllib3/connectionpool.py", line 309, in _raise_timeout
    raise ReadTimeoutError(self, url, "Read timed out. (read timeout=%s)" % timeout_value)
ReadTimeout: HTTPSConnectionPool(host='somehost.com', port=443): Read timed out. (read timeout=5)
  File "wsa/external/soap.py", line 234, in call
    response = command(**params)
  File "zeep/client.py", line 45, in __call__
    self._op_name, args, kwargs)
  File "zeep/wsdl/bindings/soap.py", line 113, in send
    options['address'], envelope, http_headers)
  File "zeep/transports.py", line 95, in post_xml
    return self.post(address, message, headers)
  File "wsa/external/soap.py", line 75, in post
    return super(NonPersistentTransport, self).post(address, message, headers)
  File "zeep/transports.py", line 67, in post
    timeout=self.operation_timeout)
  File "requests/sessions.py", line 555, in post
    return self.request('POST', url, data=data, json=json, **kwargs)
  File "requests/sessions.py", line 508, in request
    resp = self.send(prep, **send_kwargs)
  File "raven/breadcrumbs.py", line 297, in send
    resp = real_send(self, request, *args, **kwargs)
  File "requests/sessions.py", line 618, in send
    r = adapter.send(request, **kwargs)
  File "requests/adapters.py", line 521, in send
    raise ReadTimeout(e, request=request)

System Information

$ python -m requests.help
{
  "chardet": {
    "version": "3.0.4"
  },
  "cryptography": {
    "version": ""
  },
  "idna": {
    "version": "2.6"
  },
  "implementation": {
    "name": "CPython",
    "version": "3.5.3"
  },
  "platform": {
    "release": "3.10.0-693.5.2.el7.x86_64",
    "system": "Linux"
  },
  "pyOpenSSL": {
    "openssl_version": "",
    "version": null
  },
  "requests": {
    "version": "2.18.4"
  },
  "system_ssl": {
    "version": "1000105f"
  },
  "urllib3": {
    "version": "1.22"
  },
  "using_pyopenssl": false
}
$ openssl version
OpenSSL 1.0.2k-fips  26 Jan 2017
$ cat /etc/redhat-release
$ uname -spori
OS: CentOS Linux release 7.4.1708 (Core), Linux 3.10.0-693.5.2.el7.x86_64 x86_64 x86_64 GNU/Linux

metheoryt avatar Apr 16 '18 06:04 metheoryt

Can you share more details about what makes you think there was a handshake error or other TLS issue that happened here?

sigmavirus24 avatar Apr 16 '18 15:04 sigmavirus24

screen shot 2018-04-16 at 10 45 03 am

curl produces a time out error.

ghost avatar Apr 16 '18 17:04 ghost

@gahancorpcfo I replaced original host with somehost.com, cause original host produces these errors maybe once a month, so there's no reason to try to reproduce the error with it. @sigmavirus24 I guess first lines of stacktrace show that problem is hiding somewhere in TLS layer. Code, that raises first exception, is contained in ssl.c file, and exception message states The handshake operation timed out. Another interesting detail is that the timeout value, passed in exception message (...(read timeout=5)) presents connection timeout instead of read timeout. In my particular case, timeouts were equal to 5 and 22 seconds for connection and read respectively.

metheoryt avatar Apr 17 '18 05:04 metheoryt

Hey @metheoryt, you're right that this does seem to be a misclassification of this particular timeout. If you look at the stacktrace though, you can see this is being done in urllib3, not Requests.

File "urllib3/connectionpool.py", line 309, in _raise_timeout raise ReadTimeoutError(self, url, "Read timed out. (read timeout=%s)" % timeout_value)

We only know what urllib3 is sending to us, so I don't know if we're easily able to do anything here. I'd recommend raising an issue with the urllib3 project and seeing if this can get clearer handling there.

nateprewitt avatar Apr 17 '18 06:04 nateprewitt

@metheoryt so the fact that a we timed out while in an SSL call doesn't inherently mean this is a SSL error that's being hidden. Let's look closely:

ReadTimeoutError: HTTPSConnectionPool(host='somehost.com', port=443): Read timed out. (read timeout=5)

What this says is that while we were in the process of the handshake, we waited for 5 seconds while waiting for the server to write bytes. We'd already connected to the server (even if we hadn't established a TLS connection). In short, I personally do not see anything wrong here. It may not match what you expect, but it is absolutely correct.

sigmavirus24 avatar Apr 17 '18 14:04 sigmavirus24

@sigmavirus24 yes, you're right in some ways, but I think this particular case should be treaten as connect timeout, cause

Requests that produced this error are safe to retry

There's a significant difference between read timeout, when we don't know, does the server begins process of our request or not, and SSL stuff timeout, when we confident in fact that our request hasn't been processed at all. I think there's should be a distinction.

metheoryt avatar Apr 18 '18 06:04 metheoryt

@metheoryt I don't believe there's a way for urllib3 or requests to produce that distinction. I could be wrong, but I think that any solution would need to take place in the Python standard library since you can see the last portions of that trace are in

  File "python3.5/ssl.py", line 385, in wrap_socket
    _context=self)
  File "python3.5/ssl.py", line 760, in __init__
    self.do_handshake()
  File "python3.5/ssl.py", line 996, in do_handshake
    self._sslobj.do_handshake()
  File "python3.5/ssl.py", line 641, in do_handshake
    self._sslobj.do_handshake()

sigmavirus24 avatar Apr 18 '18 13:04 sigmavirus24

@sigmavirus24 we're using sentry as exception collector with our app, but I cannot share the original issue because our sentry instance is local. But I can explain stacktrace with screenshots below:

how the low-level timeout exception is appeared

how the low-level timeout exception is appeared

where it is being handled

where it is being handled

how it looks and where it turns to ReadTimeoutError

how it looks and where it turns to ReadTimeoutError

metheoryt avatar Apr 19 '18 09:04 metheoryt

Now I see clearly, @nateprewitt, you're right, I've posted an issue urllib3/urllib3#1366 with reference to this one

metheoryt avatar Apr 19 '18 09:04 metheoryt

@metheoryt you've only confirmed exactly what I've been saying. The exception is a SocketTimeout, not an SSLError. I really don't see why this should be an SSL exception. You haven't provided a convincing argument that this should be represented as an issue with TLS instead of a timeout.

sigmavirus24 avatar Apr 19 '18 10:04 sigmavirus24

@sigmavirus24 neither SSLError, nor ReadTimeout, I guess. It should be a ConnectionError, since it represents an error, produced while connecting to remote host, and subject request is safe to retry.

metheoryt avatar Apr 20 '18 05:04 metheoryt

@metheoryt let's review the sequence of events:

  • urllib3 successfully creates a socket connection to the server on port 443
  • urllib3 tries to negotiate TLS with the server (also known as the handshake)
  • while negotiating TLS, we don't receive any bytes from the server within the read timeout, as that was set on the successfully created socket connection, we hit a timeout exception for reading and re-raise that appropriately
  • urllib3 might be able to separately try to catch that read timeout during the handshake, and re-raise it as something else, but I'm not certain ConnectionError is the right thing either.

sigmavirus24 avatar Apr 23 '18 15:04 sigmavirus24

@sigmavirus24 I'm sorry if I misled you with ConnectionError, I meant ConnectTimeout.

I think of this situation as of borderline case between connection timeout and read timeout. Intuition acts as a background for the left part, while technical nature is a background for the right part.

Indeed, TLS negotiation is a part of connection procedure. At this stage no business data is sent (even headers). There is no logical reason to treat this case as ReadTimeout, because ReadTimeout by design tell us that the request COULD BE received and processed by server, while ConnectTimeout tells that the request WAS NOT received and, therefore, wasn't processed.

Another argument for ConnectTimeout is that message of this particular ReadTimeout contains waiting time for connection but not for response. (the exception sais (read timeout=5) while i was having 5 seconds for connection and 22 for response waiting).

metheoryt avatar Apr 24 '18 09:04 metheoryt

I am seeing this issue as well. If you use a different timeout value for connect timeout and read timeout. For instance if you pass in (10, 1000), you will see a read timeout after 10 seconds even though the connect timeout is 10 seconds. Observed in requests 2.19.1

drice avatar Jul 20 '18 20:07 drice

I confirm this behavior with 1.26.7 also when using urllib3 via requests. Passing two different timeouts makes it visible. If the connect timeout is large enough for the TCP connection to be established, but short enough for the TLS handshaking to fail, you get a ReadTimeout with the timeout value in its description matching the connection timeout specified, not the read timeout.

It's all about the semantic we and urllib3 want to associate to the meaning of "connection". The TCP or the TLS ?? In any case, ReadTimeout should not be raised with connection timeout value in its description, after that connection timeout period expires.

stefano-xy avatar Nov 29 '21 16:11 stefano-xy