Healthcheck at /cgi/apptest.py generates stack trace when requested by simple client

[byoungstrom]

Originally came up when the F5 LTM health check was configured to look at a datacube instance. Reproduceable with dc_8080.txt (note txt extension to make github happy).

The F5 makes a request of "GET /cgi/apptest.py HTTP/1.1\r\nHost: datacube.brain-map.org\r\n\r\n". Datacube correctly responds with status. Additionally datacube writes this to the log file:

2018-06-11T15:27:26-0700 [Router      31860] Starting factory <twisted.web.proxy.ProxyClientFactory object at 0x7f14c43944e0>
2018-06-11T15:27:26-0700 [Guest       31872] 2018-06-11 15:27:26-0700 [-] "127.0.0.1" - - [11/Jun/2018:22:27:26 +0000] "GET /data/health HTTP/1.0" 200 75 "-" "python-requests/2.18.4"
2018-06-11T15:27:26-0700 [Guest       31872] 2018-06-11T15:27:26-0700 "127.0.0.1" - - [11/Jun/2018:22:27:26 +0000] "GET /data/health HTTP/1.0" 200 75 "-" "python-requests/2.18.4"
2018-06-11T15:27:26-0700 [Router      31860] Stopping factory <twisted.web.proxy.ProxyClientFactory object at 0x7f14c43944e0>
2018-06-11T15:27:26-0700 [Router      31860] unexpected error in processEnded
Traceback (most recent call last):
  File "/local1/miniconda3/envs/datacube/lib/python3.6/site-packages/twisted/internet/process.py", line 64, in reapAllProcesses
    process.reapProcess()
  File "/local1/miniconda3/envs/datacube/lib/python3.6/site-packages/twisted/internet/process.py", line 350, in reapProcess
    self.processEnded(status)
  File "/local1/miniconda3/envs/datacube/lib/python3.6/site-packages/twisted/internet/_baseprocess.py", line 52, in processEnded
    self.maybeCallProcessEnded()
  File "/local1/miniconda3/envs/datacube/lib/python3.6/site-packages/twisted/internet/process.py", line 987, in maybeCallProcessEnded
    _BaseProcess.maybeCallProcessEnded(self)
--- <exception caught here> ---
  File "/local1/miniconda3/envs/datacube/lib/python3.6/site-packages/twisted/internet/_baseprocess.py", line 64, in maybeCallProcessEnded
    proto.processEnded(Failure(reason))
  File "/local1/miniconda3/envs/datacube/lib/python3.6/site-packages/twisted/web/twcgi.py", line 321, in processEnded
    self.request.unregisterProducer()
  File "/local1/miniconda3/envs/datacube/lib/python3.6/site-packages/twisted/web/http.py", line 913, in unregisterProducer
    self.channel.unregisterProducer()
builtins.AttributeError: 'NoneType' object has no attribute 'unregisterProducer'

Please find a way to quiet this stack trace while maintaining troubleshooting capability.

[chrisbarber]

Might be able to get this fixed upstream.

--- web/twcgi.py.old    2018-06-12 12:08:23.556509217 -0700
+++ web/twcgi.py        2018-06-12 12:09:43.252589293 -0700
@@ -202,6 +202,7 @@
     headertext = b''
     errortext = b''
     _log = Logger()
+    _requestFinished = False

     # Remotely relay producer interface.

@@ -231,6 +232,7 @@

     def __init__(self, request):
         self.request = request
+        self.request.notifyFinish().addBoth(self._finished)

     def connectionMade(self):
@@ -318,5 +320,18 @@
                 resource.ErrorPage(http.INTERNAL_SERVER_ERROR,
                     "CGI Script Error",
                     "Premature end of script headers.").render(self.request))
+        if self._requestFinished:
+            return
+
         self.request.unregisterProducer()
         self.request.finish()
+
+
+    def _finished(self, ignored):
+        """
+        Record the end of the response generation for the request being
+        serviced.
+        """
+        self._requestFinished = True
+
+

[chrisbarber]

@byoungstrom , even if we suppress the traceback or prevent it from happening in the first place, these four lines are generated on each health check:

2018-06-12T12:12:34-0700 [Router       7496] Starting factory <twisted.web.proxy.ProxyClientFactory object at 0x7fa57b90ec18>
2018-06-12T12:12:34-0700 [Guest        7525] 2018-06-12 12:12:34-0700 [-] "127.0.0.1" - - [12/Jun/2018:19:12:34 +0000] "GET /data/health HTTP/1.0" 200 75 "-" "python-requests/2.18.4"
2018-06-12T12:12:34-0700 [Guest        7525] 2018-06-12T12:12:34-0700 "127.0.0.1" - - [12/Jun/2018:19:12:34 +0000] "GET /data/health HTTP/1.0" 200 75 "-" "python-requests/2.18.4"
2018-06-12T12:12:34-0700 [Router       7496] Stopping factory <twisted.web.proxy.ProxyClientFactory object at 0x7fa57b90ec18>

These are generated at the 'info' loglevel. Maybe it would make sense to move up to 'warn' loglevel in production anyways? If so I can open a separate issue as there is some work I'd need to do on datacube first, to make sure messages are produced at the appropriate level.

[chrisbarber]

https://github.com/twisted/twisted/pull/1027