💩 🔊 Add additional logging to the request handling

We have been a mysterious 403 error during `/usercache/put` from some users
only. However, we don't see the `usercache/put` in the application logs.

This adds additional logging to the incoming call path on the webapp, allowing
us to intercept messages earlier and figure out where the error is thrown from.

This helps with
e-mission/e-mission-docs#1127

We log the messages using `logging` instead of `print` so that they show up in
the correct order with the rest of the log messages. We also log the raw token
in the input hook so we can see what we receive before trying to map it to a
local UUID.

We also cannot get the length of an error so we need to check the output type first

```
Traceback (most recent call last):
  File "/usr/src/devapp/emission/net/api/bottle.py", line 1022, in _handle
    if len(out) > 40:
TypeError: object of type 'HTTPError' has no len()
```

We also have to handle a `None` output

Author: shankari

emission/net/api/bottle.py

@@ -14,6 +14,7 @@
 """
 
 import sys
+import logging
 
 __author__ = 'Marcel Hellkamp'
 __version__ = '0.13-dev'
@@ -470,6 +471,7 @@ def build(self, _name, *anons, **query):
 
     def match(self, environ):
         """ Return a (target, url_args) tuple or raise HTTPError(400/404/405). """
+        logging.debug(f"403_CHECK: bottle just tried to match {environ['REQUEST_METHOD']} {environ['PATH_INFO']}")
         verb = environ['REQUEST_METHOD'].upper()
         path = environ['PATH_INFO'] or '/'
 
@@ -977,6 +979,7 @@ def default_error_handler(self, res):
         return tob(template(ERROR_PAGE_TEMPLATE, e=res, template_settings=dict(name='__ERROR_PAGE_TEMPLATE')))
 
     def _handle(self, environ):
+        logging.debug(f"403_CHECK: bottle just received {environ['REQUEST_METHOD']} {environ['PATH_INFO']}")
         path = environ['bottle.raw_path'] = environ['PATH_INFO']
         if py3k:
             environ['PATH_INFO'] = path.encode('latin1').decode('utf8', 'ignore')
@@ -985,18 +988,27 @@ def _handle(self, environ):
         request.bind(environ)
         response.bind()
 
+        try:
+            logging.debug(f"403_CHECK: parsed body {request.json}")
+        except Exception as e:
+            print_exc()
+
         try:
             while True: # Remove in 0.14 together with RouteReset
                 out = None
                 try:
+                    logging.debug(f"403_CHECK: bottle just called hook with {environ['REQUEST_METHOD']} {environ['PATH_INFO']}")
                     self.trigger_hook('before_request')
                     route, args = self.router.match(environ)
                     environ['route.handle'] = route
                     environ['bottle.route'] = route
                     environ['route.url_args'] = args
+                    logging.debug(f"403_CHECK: bottle just called route with {args}")
                     out = route.call(**args)
                     break
                 except HTTPResponse as E:
+                    logging.error(f"403_CHECK: exception at first level {E}")
+                    print_exc()
                     out = E
                     break
                 except RouteReset:
@@ -1006,16 +1018,24 @@ def _handle(self, environ):
                     route.reset()
                     continue
                 finally:
+                    if out and not isinstance(out, HTTPError) and len(out) > 40:
+                        logging.debug(f"403_CHECK: after call, truncated output {out[:20]}...{out[-20:]}")
+                    else:
+                        logging.debug(f"403_CHECK: after call, full output is {out}")
                     if isinstance(out, HTTPResponse):
                         out.apply(response)
                     try:
                         self.trigger_hook('after_request')
                     except HTTPResponse as E:
+                        logging.error(f"403_CHECK: exception while handling post-hook {E}")
+                        print_exc()
                         out = E
                         out.apply(response)
         except (KeyboardInterrupt, SystemExit, MemoryError):
+            print_exc()
             raise
         except Exception as E:
+            print_exc()
             if not self.catchall: raise
             stacktrace = format_exc()
             environ['wsgi.errors'].write(stacktrace)

emission/net/api/cfc_webapp.py

@@ -432,7 +432,8 @@ def before_request():
   request.params.start_ts = time.time()
   request.params.timer = ect.Timer()
   request.params.timer.__enter__()
-  logging.debug("START %s %s" % (request.method, request.path))
+  logging.debug("START %s %s %s" % (request.method, request.path,
+        request.json.get('user', None) if request.json else None))
 
 @app.hook('after_request')
 def after_request():

emission/net/api/wsgiserver2.py

@@ -590,6 +590,7 @@ def __init__(self, server, conn):
 
     def parse_request(self):
         """Parse the next HTTP request start-line and message-headers."""
+        print(f"403_CHECK: wsgiserver started parsing request")
         self.rfile = SizeCheckWrapper(self.conn.rfile,
                                       self.server.max_request_header_size)
         try:
@@ -600,6 +601,7 @@ def parse_request(self):
                 "allowed bytes.")
             return
         else:
+            print(f"403_CHECK: wsgiserver in else block with {success=}")
             if not success:
                 return
 
@@ -614,6 +616,7 @@ def parse_request(self):
             if not success:
                 return
 
+        print(f"403_CHECK: wsgiserver ready to read request")
         self.ready = True
 
     def read_request_line(self):
@@ -625,6 +628,7 @@ def read_request_line(self):
         # (although your TCP stack might suffer for it: cf Apache's history
         # with FIN_WAIT_2).
         request_line = self.rfile.readline()
+        print(f"403_CHECK: wsgiserver read request line {request_line}")
 
         # Set started_request to True so communicate() knows to send 408
         # from here on out.
@@ -716,6 +720,7 @@ def read_request_headers(self):
         """Read self.rfile into self.inheaders. Return success."""
 
         # then all the http headers
+        print(f"403_CHECK: wsgiserver reading headers {request_line}")
         try:
             read_headers(self.rfile, self.inheaders)
         except ValueError:
@@ -809,6 +814,7 @@ def parse_request_uri(self, uri):
             segment       = *pchar *( ";" param )
             param         = *pchar
         """
+        print(f"403_CHECK: wsgiserver parsing {uri=}")
         if uri == ASTERISK:
             return None, None, uri
 
@@ -1921,6 +1927,7 @@ def tick(self):
         """Accept a new connection and put it on the Queue."""
         try:
             s, addr = self.socket.accept()
+            print(f"403_CHECK: wsgiserver accepted connection from socket")
             if self.stats['Enabled']:
                 self.stats['Accepts'] += 1
             if not self.ready:
@@ -1977,6 +1984,7 @@ def tick(self):
 
             conn.ssl_env = ssl_env
 
+            print(f"403_CHECK: wsgiserver queued new connection from {conn.remote_port=}")
             self.requests.put(conn)
         except socket.timeout:
             # The only reason for the timeout in start() is so we can