`ResourceWarning: Enable tracemalloc to get the object allocation traceback` reported during integration tests

[jessebrennan]

This is visible on the latest dev build https://gitlab.dev.singlecell.gi.ucsc.edu/ucsc/azul/-/jobs/2918 and I have also observed this when running the integration test locally.

ResourceWarning: Enable tracemalloc to get the object allocation traceback

[theathorn]

@hannes-ucsc : "Google and determine if this is benign".

[amarjandu]

(it-trackback.txt)[https://gitlab.dev.singlecell.gi.ucsc.edu/snippets/1]

It appears from this IT output that the unclosed SSL warnings and the tracemalloc warnings are linked together.

$cat it-tracebacks.txt | grep 'ResourceWarning: unclosed' | wc -l
133
$cat it-tracebacks.txt | grep 'ResourceWarning: Enable tracemalloc' | wc -l
133

For additional information into the trackback provided by tracemalloc use python -X tracemalloc=25 -m unittest -v integration_test

(it-trackbacks-tracemalloc.txt)[https://gitlab.dev.singlecell.gi.ucsc.edu/snippets/2]

The number of times the ResourceWarning occurs changes to 127 during a second IT run:

$cat it-tracebacks-tracemalloc.txt | grep  'ResourceWarning: unclosed' | wc -l
127
$cat it-tracebacks-tracemalloc.txt | grep  'Object allocated' | wc -l
127

The source file for the tracebacks come from multiple different files:

$cat it-tracebacks-tracemalloc.txt | grep  'ResourceWarning: unclosed' | cut -d ' ' -f1 | uniq -c
   1 /Users/amar/.pyenv/versions/3.8.2/lib/python3.8/contextlib.py:120:
   1 /Users/amar/dev/hca/azul/src/azul/deployment.py:163:
   2 /Users/amar/.pyenv/versions/3.8.2/lib/python3.8/contextlib.py:120:
   3 /Users/amar/dev/venv/venv-azul/lib/python3.8/re.py:292:
   4 /Users/amar/.pyenv/versions/3.8.2/lib/python3.8/contextlib.py:120:
   1 /Users/amar/dev/hca/azul/test/integration_test.py:141:
  15 /Users/amar/dev/hca/azul/src/azul/deployment.py:152:
  71 /Users/amar/dev/venv/venv-azul/lib/python3.8/site-packages/botocore/parsers.py:432:
   1 /Users/amar/dev/hca/azul/test/integration_test.py:144:
   1 /Users/amar/dev/hca/azul/test/integration_test.py:141:
   1 /Users/amar/dev/hca/azul/test/integration_test.py:144:
   1 /Users/amar/dev/hca/azul/test/integration_test.py:141:
   5 /Users/amar/.pyenv/versions/3.8.2/lib/python3.8/json/decoder.py:353:
   1 /Users/amar/dev/hca/azul/test/integration_test.py:144:
  19 /Users/amar/.pyenv/versions/3.8.2/lib/python3.8/unittest/case.py:704:

~We briefly spoke about suppression earlier today and i believe we both agreed that ignoring ResourceType warnings might lead to other warnings slipping by that we would want to see, however, we can use filterwarnings to suppress just the SSL warnings within the AzulTestCase to make the output cleaner. ~

warnings.filterwarning('ignore', msg='unclosed.*<ssl.SSLSocket.*>', ResourceWarning)

https://docs.python.org/3/library/warnings.html#warnings.filterwarnings

Edit: this would not remove the ResourceWarning: Enable tracemalloc to get the object allocation traceback message, which it more generic, and something that we might want to keep around.

Edit: File links updated

[hannes-ucsc]

Two questions: Aren't we getting the same warnings in a deployed lambda? And why would we only suppress the unclosed socket warning but not the strongly correlated tracemalloc warning? We want to eliminate the noise, not just cut it in half.

The files you link contain a bit too much identifying information for a public website. Could you please delete them and use a Gitlab snippet instead? To prevent G from crawling them I redacted the links in your post.

[hannes-ucsc]

One more thing: could you look for the place in the CPython source that emits the tracemalloc warning?

[amarjandu]

Links updated.

Aren't we getting the same warnings in a deployed lambda?

Not that i can see, i checked within the last spike in activity 5/28 -> 5/29/2020 using cloudwatch insights and dont see any occurrences.

I selected all dev-lambdas and used the query:

fields @timestamp, @message
| filter @message like 'ResourceWarning'
| sort @timestamp desc
| limit 20

And why would we only suppress the unclosed socket warning but not the strongly correlated tracemalloc warning? We want to eliminate the noise, not just cut it in half.

That was my reasoning for striking out that section of the comment, I however i tested with some changes to the IntegrationTest class, and see that the ResourceWarning: Enable tracemalloc to get the object allocation traceback is also reduced.

git diff origin/develop
diff --git a/test/integration_test.py b/test/integration_test.py
index 3722fbe4..04476b59 100644
--- a/test/integration_test.py
+++ b/test/integration_test.py
@@ -1,5 +1,6 @@
 from concurrent.futures.thread import ThreadPoolExecutor
 import csv
+import warnings
 import gzip
 from io import (
     BytesIO,
@@ -139,6 +140,8 @@ class IntegrationTest(AlwaysTearDownTestCase):
         self.test_name = f'integration-test_{self.test_uuid}_{self.bundle_uuid_prefix}'
         self.num_bundles = 0
         self._set_test_mode(True)
+        warnings.filterwarnings('ignore', 'unclosed.*<ssl.SSLSocket.*>', ResourceWarning)
+

     def tearDown(self):
         self._set_test_mode(False)

and the results is a many less ResourceWarnings, although there are still some present.

cat it-tracebacks-filtered-integration-test | grep 'ResourceWarning'
/Users/amar/.pyenv/versions/3.8.2/lib/python3.8/contextlib.py:120: ResourceWarning: unclosed <ssl.SSLSocket fd=15, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('192.168.1.17', 52078), raddr=('54.239.29.25', 443)>
ResourceWarning: Enable tracemalloc to get the object allocation traceback
/Users/amar/dev/hca/azul/src/azul/deployment.py:163: ResourceWarning: unclosed <ssl.SSLSocket fd=16, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('192.168.1.17', 52079), raddr=('52.94.233.129', 443)>
ResourceWarning: Enable tracemalloc to get the object allocation traceback
/Users/amar/.pyenv/versions/3.8.2/lib/python3.8/contextlib.py:120: ResourceWarning: unclosed <ssl.SSLSocket fd=15, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('192.168.1.17', 52080), raddr=('54.239.29.25', 443)>
ResourceWarning: Enable tracemalloc to get the object allocation traceback
/Users/amar/.pyenv/versions/3.8.2/lib/python3.8/contextlib.py:120: ResourceWarning: unclosed <ssl.SSLSocket fd=17, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('192.168.1.17', 52085), raddr=('54.239.29.25', 443)>
ResourceWarning: Enable tracemalloc to get the object allocation traceback
/Users/amar/dev/venv/venv-azul/lib/python3.8/re.py:292: ResourceWarning: unclosed <ssl.SSLSocket fd=14, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('192.168.1.17', 52077), raddr=('54.205.68.120', 443)>
ResourceWarning: Enable tracemalloc to get the object allocation traceback
/Users/amar/dev/venv/venv-azul/lib/python3.8/re.py:292: ResourceWarning: unclosed <ssl.SSLSocket fd=16, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('192.168.1.17', 52084), raddr=('3.222.182.214', 443)>
ResourceWarning: Enable tracemalloc to get the object allocation traceback
/Users/amar/dev/venv/venv-azul/lib/python3.8/re.py:292: ResourceWarning: unclosed <ssl.SSLSocket fd=15, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('192.168.1.17', 52082), raddr=('52.216.239.59', 443)>
ResourceWarning: Enable tracemalloc to get the object allocation traceback
/Users/amar/.pyenv/versions/3.8.2/lib/python3.8/contextlib.py:120: ResourceWarning: unclosed <ssl.SSLSocket fd=39, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('192.168.1.17', 52117), raddr=('54.239.29.25', 443)>
ResourceWarning: Enable tracemalloc to get the object allocation traceback
/Users/amar/.pyenv/versions/3.8.2/lib/python3.8/contextlib.py:120: ResourceWarning: unclosed <ssl.SSLSocket fd=52, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('192.168.1.17', 52133), raddr=('54.239.29.25', 443)>
ResourceWarning: Enable tracemalloc to get the object allocation traceback
/Users/amar/.pyenv/versions/3.8.2/lib/python3.8/contextlib.py:120: ResourceWarning: unclosed <ssl.SSLSocket fd=57, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('192.168.1.17', 52143), raddr=('54.239.29.25', 443)>
ResourceWarning: Enable tracemalloc to get the object allocation traceback
/Users/amar/.pyenv/versions/3.8.2/lib/python3.8/contextlib.py:120: ResourceWarning: unclosed <ssl.SSLSocket fd=74, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('192.168.1.17', 52201), raddr=('54.239.29.25', 443)>
ResourceWarning: Enable tracemalloc to get the object allocation traceback
/Users/amar/dev/hca/azul/test/integration_test.py:142: ResourceWarning: unclosed <ssl.SSLSocket fd=86, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('192.168.1.17', 52217), raddr=('100.25.115.233', 443)>
ResourceWarning: Enable tracemalloc to get the object allocation traceback

Connecting that to this request

One more thing: could you look for the place in the CPython source that emits the tracemalloc warning?

https://github.com/python/cpython/blob/41ec17e45d54473d32f543396293256f1581e44d/Lib/warnings.py#L89

Which makes sense when looking at the section of code in cPython, the traceback message is appended to the end of the SSL warning. We would only need to ignore the former. For any additional messages that dont match that regex-msg, it would be output to the screen.

[amarjandu]

https://github.com/DataBiosphere/azul/blob/474d18054effa2f8344a24ff9a05171eb23ef318/Makefile#L89

It appears that we apply filter for any ResourceWarning that occur during unit-testing.

[amarjandu]

Additional Research, see the status of the warning module to see if AWS is removing the ResourceWarning from being omitted into the logs of a running lambda.

[amarjandu]

@hannes-ucsc from inspecting the runtime for the AWS lambda, it seems that the warnings.filter that is applied is the default filter.

Function Logs:
START RequestId: 938846ef-cd9c-42f6-9ad3-e0bf68c13980 Version: $LATEST
[('default', None, <class 'DeprecationWarning'>, '__main__', 0),
 ('ignore', None, <class 'DeprecationWarning'>, None, 0),
 ('ignore', None, <class 'PendingDeprecationWarning'>, None, 0),
 ('ignore', None, <class 'ImportWarning'>, None, 0),
 ('ignore', None, <class 'ResourceWarning'>, None, 0)]
END RequestId: 938846ef-cd9c-42f6-9ad3-e0bf68c13980

However what i did find was that the TextTestRunner that runs the unit tests has no filter applied to it by default.

https://github.com/python/cpython/blob/087d612efebe7c64e5f079b07e0454111859830e/Lib/unittest/runner.py#L159

Which could explain the lack of ResourceWarnings within the deployments. A simple test could be in the form of : setting the PYTHONWARNINGS=always environment variable, then run a re-index and inspecting the logs.