httpclient: Fix warning logged by sync HTTPClient destructor

If an HTTPClient is closed from its destructor instead of an explicit
close() call, it sometimes logs an "inconsistent AsyncHTTPClient
cache" error because the weakrefs appear to get cleaned up in an
unexpected order. Relax the checks in AsyncHTTPClient.close to allow
for a missing value in the instance cache.

Fixes tornadoweb#2539

.travis.yml

@@ -84,8 +84,8 @@ script:
     # run it with nightly cpython. Coverage is very slow on pypy.
     - if [[ $TRAVIS_PYTHON_VERSION != nightly && $TRAVIS_PYTHON_VERSION != 'pypy'* ]]; then export RUN_COVERAGE=1; fi
     - if [[ "$RUN_COVERAGE" == 1 ]]; then export TARGET="-m coverage run $TARGET"; fi
-    # See comments in tox.ini
-    - export PYTHONWARNINGS=error,ignore:::site
+    # See comments in tox.ini. Disabled on py35 because ResourceWarnings are too noisy there.
+    - if [[ $TRAVIS_PYTHON_VERSION != '3.5' ]]; then export PYTHONWARNINGS=error,ignore:::site; fi
     - python -bb $TARGET
     - python -O $TARGET
     - LANG=C python $TARGET

tornado/httpclient.py

@@ -233,9 +233,14 @@ def close(self) -> None:
             return
         self._closed = True
         if self._instance_cache is not None:
-            if self._instance_cache.get(self.io_loop) is not self:
+            cached_val = self._instance_cache.pop(self.io_loop, None)
+            # If there's an object other than self in the instance
+            # cache for our IOLoop, something has gotten mixed up. A
+            # value of None appears to be possible when this is called
+            # from a destructor (HTTPClient.__del__) as the weakref
+            # gets cleared before the destructor runs.
+            if cached_val is not None and cached_val is not self:
                 raise RuntimeError("inconsistent AsyncHTTPClient cache")
-            del self._instance_cache[self.io_loop]
 
     def fetch(
         self,

tornado/test/httpclient_test.py

@@ -6,12 +6,14 @@
 import threading
 import datetime
 from io import BytesIO
+import subprocess
+import sys
 import time
 import typing  # noqa: F401
 import unicodedata
 import unittest
 
-from tornado.escape import utf8, native_str
+from tornado.escape import utf8, native_str, to_unicode
 from tornado import gen
 from tornado.httpclient import (
     HTTPRequest,
@@ -676,6 +678,35 @@ def test_sync_client_error(self):
         self.assertEqual(assertion.exception.code, 404)
 
 
+class SyncHTTPClientSubprocessTest(unittest.TestCase):
+    def test_destructor_log(self):
+        # Regression test for
+        # https://github.com/tornadoweb/tornado/issues/2539
+        #
+        # In the past, the following program would log an
+        # "inconsistent AsyncHTTPClient cache" error from a destructor
+        # when the process is shutting down. The shutdown process is
+        # subtle and I don't fully understand it; the failure does not
+        # manifest if that lambda isn't there or is a simpler object
+        # like an int (nor does it manifest in the tornado test suite
+        # as a whole, which is why we use this subprocess).
+        proc = subprocess.run(
+            [
+                sys.executable,
+                "-c",
+                "from tornado.httpclient import HTTPClient; f = lambda: None; c = HTTPClient()",
+            ],
+            stdout=subprocess.PIPE,
+            stderr=subprocess.STDOUT,
+            check=True,
+        )
+        if proc.stdout:
+            print("STDOUT:")
+            print(to_unicode(proc.stdout))
+        if proc.stdout:
+            self.fail("subprocess produced unexpected output")
+
+
 class HTTPRequestTestCase(unittest.TestCase):
     def test_headers(self):
         request = HTTPRequest("http://example.com", headers={"foo": "bar"})