Author David Ford (FirefighterBlu3)
Recipients David Ford (FirefighterBlu3), martin.panter
Date 2017-02-15.09:48:04
SpamBayes Score -1.0
Marked as misclassified Yes
Message-id <1487152086.44.0.28441467191.issue29564@psf.upfronthosting.co.za>
In-reply-to
Content
i do know what's causing it, it's the twilio module not cleanly finishing up. i pointed out my call to this in the initial description.

/usr/lib/python3.6/site-packages/httplib2/__init__.py:857: DeprecationWarning: key_file, cert_file and check_hostname are deprecated, use a custom context instead.
  check_hostname=disable_ssl_certificate_validation ^ True)
/usr/lib/python3.6/site-packages/psycopg2/extras.py:314: ResourceWarning: unclosed <ssl.SSLSocket fd=10, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('173.12.76.132', 42016), raddr=('52.7.124.13', 443)>
  ts = super(NamedTupleCursor, self).fetchall()
Object allocated at (most recent call first):
  File "/usr/lib/python3.6/ssl.py", lineno 401
    _context=self, _session=session)
  File "/usr/lib/python3.6/http/client.py", lineno 1400
    server_hostname=server_hostname)
  File "/usr/lib/python3.6/site-packages/httplib2/__init__.py", lineno 994
    conn.connect()
  File "/usr/lib/python3.6/site-packages/httplib2/__init__.py", lineno 1071
    (response, content) = self._conn_request(conn, request_uri, method, body, headers)
  File "/usr/lib/python3.6/site-packages/httplib2/__init__.py", lineno 1321
    (response, content) = self._request(conn, authority, uri, request_uri, method, body, headers, redirections, cachekey)
  File "/usr/lib/python3.6/site-packages/twilio/rest/resources/base.py", lineno 117
    resp, content = http.request(url, method, headers=headers, body=data)
  File "/usr/lib/python3.6/site-packages/twilio/rest/resources/base.py", lineno 152
    resp = make_request(method, uri, **kwargs)
  File "/usr/lib/python3.6/site-packages/twilio/rest/resources/base.py", lineno 200
    resp = make_twilio_request(method, uri, auth=self.auth, **kwargs)
  File "/usr/lib/python3.6/site-packages/twilio/rest/resources/base.py", lineno 333
    resp, item = self.request("GET", uri)
  File "/usr/lib/python3.6/site-packages/twilio/rest/resources/base.py", lineno 328
    return self.get_instance(sid)
  File "provider.py", lineno 524
    msg = self._twilio.messages.get(r.delivery_id)
  File "/usr/lib/python3.6/asyncio/events.py", lineno 126
    self._callback(*self._args)
  File "/usr/lib/python3.6/asyncio/base_events.py", lineno 1425
    handle._run()
  File "/usr/lib/python3.6/asyncio/base_events.py", lineno 421
    self._run_once()
  File "/usr/lib/python3.6/site-packages/autobahn/asyncio/wamp.py", lineno 168
    loop.run_forever()
  File "provider.py", lineno 595
    runner.run(make)

the socket is referenced by ip:port correctly and is coherent with the stack trace. nothing about the IP, socket, or stack trace, is related to the referenced file:position that is reported:

/usr/lib/python3.6/site-packages/psycopg2/extras.py:314: ResourceWarning: unclosed <ssl.SSLSocket fd=10, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('173.12.76.132', 42016), raddr=('52.7.124.13', 443)>
  ts = super(NamedTupleCursor, self).fetchall()

the psycopg2 connection is against a completely different IP and on the standard pgsql port of 5432.

here's the snippet of psycopg2/extras.py:

    313     def fetchall(self):
    314         ts = super(NamedTupleCursor, self).fetchall()
    315         nt = self.Record
    316         if nt is None:
    317             nt = self.Record = self._make_nt()
    318         return list(map(nt._make, ts))

nothing at all between my pgsql database and twilio share any form of connection or socket and there are no similarly named variables, complex code paths, or global variables. the only object data which has any shared scope is the twilio message fetch using the ID fetched from the pgsql database. if this section of code is commented out, the resource warning vanishes.

msg = self._twilio.messages.get(r.delivery_id)

if i patch the involved calls in twilio so i can touch the socket object and close it such as:

class Response(object):
    """
    Take a httplib2 response and turn it into a requests response
    """
    def __init__(self, httplib_resp, content, url, http_obj):
        self.content = content
        self.cached = False
        self.status_code = int(httplib_resp.status)
        self.ok = self.status_code < 400
        self.url = url
        self.connections = http_obj.connections

(http_obj added which is an instance of httplib2.Http which has a property of .connections wherein sockets are cached)

then after modifying the twilio module to pass the Response object to me as well as the message resource, i can eventually in my code:

            for r in rows:
                resp, msg = self._twilio.messages.get(r.delivery_id)
                errors[r.delivery_id] = r.recipient, msg.error_code, msg.error_message

            for k in resp.connections:
                resp.connections[k].close()

this closes all the cached sockets and ensures the ResourceWarning is never emitted. this messiness is another conversation however, the incorrect file:pos annotation for the ResourceWarning is the purpose of this bug.
========

the only way i can see this inaccurate message being presented as above, is if the resource warning code is not correctly tracking state inside GC runs. supposition:

* psycopg2 opened the socket to the PG database (threading is involved when the pool is used)
* psycopg2 fetches the rows
* psycopg2 closed socket, releasing object
* twilio opens a socket which coincidently uses the same object resource just closed but not purged in GC
* twilio doesn't close it the SSL socket so it is left hanging
* method exits, GC runs but RW state wasn't updated somewhere to say that the twilio/httplib2/http/ssl series of calls now owns that object memory
* RW code emits an unclosed socket warning against the outdated psycopg2/extras.py:314 information

i'm definitely not intimate with GC code so the above is purely speculation. i've seen people post some vague references to confusing resource warnings when threading is involved. as nothing appears to be affected with long running instances, the actual object handling seems solid, it's just the state tracking for the resource warning which is not correct
History
Date User Action Args
2017-02-15 09:48:07David Ford (FirefighterBlu3)setrecipients: + David Ford (FirefighterBlu3), martin.panter
2017-02-15 09:48:06David Ford (FirefighterBlu3)setmessageid: <1487152086.44.0.28441467191.issue29564@psf.upfronthosting.co.za>
2017-02-15 09:48:06David Ford (FirefighterBlu3)linkissue29564 messages
2017-02-15 09:48:04David Ford (FirefighterBlu3)create