Merge pull request #111 from fnproject/logging-context

Python logging enhancements

Author: jan-g

README.md

@@ -29,11 +29,12 @@ You can set outbound HTTP headers and the HTTP status of the request using `ctx.
   - e.g. `ctx.SetResponseHeaders({"Location","http://example.com/","My-Header2": ["v1","v2"]}, 302)` 
   - or by passing these to the Response object : 
 ```python
-        return new Response(ctx,
-                        headers={"Location","http://example.com/","My-Header2": ["v1","v2"]},
-                        response_data="Page moved",
-                        status_code=302)
-``` 
+return new Response(
+    ctx,
+    headers={"Location","http://example.com/","My-Header2": ["v1","v2"]},
+    response_data="Page moved",
+    status_code=302)
+```
 
 e.g. to redirect users to a different page : 
 ```python
@@ -171,11 +172,11 @@ PASSED
 
 To add coverage first install one more package:
 ```bash
-    pip install pytest-cov
+pip install pytest-cov
 ```
 then run tests with coverage flag:
 ```bash
-    pytest -v -s --tb=long --cov=func func.py
+pytest -v -s --tb=long --cov=func func.py
 ```
 
 ```bash
@@ -208,15 +209,15 @@ func.py      19      1    95%
 
 Create a virtualenv:
 ```bash
-    python3 -m venv .venv
+python3 -m venv .venv
 ```
 Activate virtualenv:
 ```bash
-    source .venv/bin/activate
+source .venv/bin/activate
 ```
 All you have to do is:
 ```bash
-    pip install fdk
+pip install fdk
 ```
 Now you have a new tools added!
 
@@ -236,7 +237,7 @@ This is an entry point to a function, this tool you'd be using while working wit
 `fdk` is a Python CLI script that has the following signature:
 
 ```bash
-    fdk <path-to-a-function-module> [module-entrypoint]
+fdk <path-to-a-function-module> [module-entrypoint]
 ```
 
 where:
@@ -254,6 +255,20 @@ fdk func.py
 the CLI will look for `handler` Python function.
 In order to override `[module-entrypoint]` you need to specify your custom entry point.
 
+### Testing locally
+
+To run a function locally (outside Docker) you need to set `FN_FORMAT` and `FN_LISTENER`, like so:
+
+```bash
+env FDK_DEBUG=1 FN_FORMAT=http-stream FN_LISTENER=unix://tmp/func.sock fdk <path-to-a-function-module> [module-entrypoint]
+```
+
+You can then test with curl:
+
+```bash
+curl -v --unix-socket /tmp/func.sock -H "Fn-Call-Id: 0000000000000000" -H "Fn-Deadline: 2030-01-01T00:00:00.000Z" -XPOST http://function/call -d '{"name":"Tubbs"}'
+```
+
 ## CLI tool: `fdk-tcp-debug`
 
 The reason why this tool exists is to give a chance to developers to debug their function on their machines.
@@ -265,7 +280,7 @@ when this tool works on top of TCP socket, so, the difference is a transport, no
 `fdk-tcp-debug` is a Python CLI script that has the following signature:
 
 ```bash
-    fdk-tcp-debug <port> <path-to-a-function-module> [module-entrypoint]
+fdk-tcp-debug <port> <path-to-a-function-module> [module-entrypoint]
 ```
 
 The behaviour of this CLI is the same, but it will start an FDK on top of the TCP socket.
@@ -292,14 +307,14 @@ In order to test an FDK changes do the following:
 Test an FDK change with sample function using `fdk-tcp-debug`:
 
 ```bash
-    pip install -e .
-    FDK_DEBUG=1 fdk-tcp-debug 5001 samples/echo/func.py handler
+pip install -e .
+FDK_DEBUG=1 fdk-tcp-debug 5001 samples/echo/func.py handler
 ```
 
 Then just do:
 
 ```bash
-    curl -v -X POST localhost:5001 -d '{"name":"denis"}'
+curl -v -X POST localhost:5001 -d '{"name":"denis"}'
 ```
 
 ### Testing within a function
@@ -331,16 +346,16 @@ ENTRYPOINT ["/python/bin/fdk", "/function/func.py", "handler"]
 
 Build an FDK wheel:
 ```bash
-    pip install wheel
-    PBR_VERSION=test python setup.py bdist_wheel
+pip install wheel
+PBR_VERSION=test python setup.py bdist_wheel
 ```
 
 Move an FDK wheel (located at `dist/fdk-test-py3-none-any.whl`) into a function's folder.
 
 Do the deploy:
 ```bash
-    fn --versbose deploy --app testapp --local --no-bump
-    fn config fn testapp test-function FDK_DEBUG 1
+fn --versbose deploy --app testapp --local --no-bump
+fn config fn testapp test-function FDK_DEBUG 1
 ```
 
 And the last step - invoke it and see how it goes:
@@ -354,7 +369,7 @@ FDK is based on the asyncio event loop. Default event loop is not quite fast, bu
 In order to make an FDK to process IO operation at least 4 times faster you need to add another dependency to your function:
 
 ```text
-    uvloop
+uvloop
 ```
 
 [UVLoop](https://github.com/MagicStack/uvloop) is a CPython wrapper on top of cross-platform [libuv](https://github.com/libuv/libuv).
@@ -372,8 +387,8 @@ A new FDK is here which means there suppose to be a way to upgrade your code fro
 As you noticed - an entry point a function changed, i.e., func.py no longer considered as the main module (`__main__`) which means that the following section:
 
 ```python
-    if __name__ == "__main__":
-        fdk.handle(handler)
+if __name__ == "__main__":
+    fdk.handle(handler)
 ```
 
 has no effect any longer. Please note that FDK will fail-fast with an appropriate message if old-style FDK format used.
@@ -389,10 +404,10 @@ data = data.read()
 If you've been using json lib to turn an incoming data into a dictionary you need to replace: `json.loads` with `json.load`
 
 ```python
-    try:
-        dct = json.load(data)
-    except ValueError as ex:
-        # do here whatever is reasonable
+try:
+    dct = json.load(data)
+except ValueError as ex:
+    # do here whatever is reasonable
 ```
 
 ### Dockerfile
@@ -404,13 +419,13 @@ If you've been using custom multi-stage Dockerfile (derived from what Fn CLI gen
 the only thing that is necessary to change is an `ENTRYPOINT` from:
 
 ```text
-    ENTRYPOINT["python", "func.py"]
+ENTRYPOINT["python", "func.py"]
 ```
 
 to:
 
 ```text
-    ENTRYPOINT["/python/bin/fdk", "func.py", "handler"]
+ENTRYPOINT["/python/bin/fdk", "func.py", "handler"]
 ```
 
 If you've been using your own Dockerfile that wasn't derived from the Dockerfile 

fdk/async_http/app.py

@@ -74,7 +74,7 @@ async def handle_request(self, request, write_callback, stream_callback):
 
             request.uri_template = uri
             response = handler(request)
-            logger.info("got response from function")
+            logger.debug("got response from function")
             res = await response
             body = res.body
             headers = res.headers

fdk/async_http/protocol.py

@@ -251,7 +251,7 @@ def keep_alive_timeout_callback(self):
                 time_left, self.keep_alive_timeout_callback
             )
         else:
-            logger.info("KeepAlive Timeout. Closing connection.")
+            logger.debug("KeepAlive Timeout. Closing connection.")
             self.transport.close()
             self.transport = None
 

fdk/async_http/server.py

@@ -203,7 +203,7 @@ def start_serving():
     def start():
         pid = os.getpid()
         try:
-            logger.info("Starting worker [%s]", pid)
+            logger.debug("Starting worker [%s]", pid)
             if constants.is_py37():
                 loop.run_until_complete(http_server.serve_forever())
             else:

fdk/event_handler.py

@@ -18,6 +18,7 @@
 import sys
 
 from fdk import constants
+from fdk import log
 
 from fdk.async_http import response
 
@@ -36,13 +37,13 @@ def event_handle(handle_code):
     """
     async def pure_handler(request):
         from fdk import runner
-        logger.info("in pure_handler")
+        log.log("in pure_handler")
         headers = dict(request.headers)
         log_frame_header(headers)
         func_response = await runner.handle_request(
             handle_code, constants.HTTPSTREAM,
             headers=headers, data=io.BytesIO(request.body))
-        logger.info("request execution completed")
+        log.log("request execution completed")
 
         headers = func_response.context().GetResponseHeaders()
         status = func_response.status()

fdk/log.py

@@ -15,22 +15,46 @@
 import logging
 import os
 import sys
+from contextvars import ContextVar
+
+
+__fn_request_id__ = ContextVar("fn_request_id", default=None)
+
+
+def set_request_id(rid):
+    __fn_request_id__.set(rid)
+
+
+class RequestFormatter(logging.Formatter):
+    def format(self, record):
+        record.fn_request_id = __fn_request_id__.get()
+        return super().format(record)
 
 
 def __setup_logger():
-    logging.getLogger("asyncio").setLevel(logging.DEBUG)
+    fdk_debug = os.environ.get("FDK_DEBUG") in [
+        'true', '1', 't', 'y', 'yes', 'yeah', 'yup', 'certainly', 'uh-huh']
+
+    logging.getLogger("asyncio").setLevel(logging.WARNING)
     root = logging.getLogger()
     root.setLevel(logging.DEBUG)
+
     ch = logging.StreamHandler(sys.stderr)
-    formatter = logging.Formatter(
-        '%(asctime)s - '
+    formatter = RequestFormatter(
+        '%(fn_request_id)s - '
         '%(name)s - '
         '%(levelname)s - '
         '%(message)s'
     )
     ch.setFormatter(formatter)
     root.addHandler(ch)
-    return root
+    logger = logging.getLogger("fdk")
+    if fdk_debug:
+        logger.setLevel(logging.DEBUG)
+    else:
+        logger.setLevel(logging.WARNING)
+
+    return logger
 
 
 __log__ = __setup_logger()
@@ -41,7 +65,11 @@ def get_logger():
 
 
 def log(message):
-    fdk_debug = os.environ.get("FDK_DEBUG")
-    if fdk_debug in ['true', '1', 't', 'y', 'yes',
-                     'yeah', 'yup', 'certainly', 'uh-huh']:
-        __log__.info(message)
+    __log__.debug(message)
+
+
+__request_log__ = logging.getLogger('fn')
+
+
+def get_request_log():
+    return __request_log__

fdk/runner.py

@@ -81,6 +81,7 @@ async def handle_request(handler_code, format_def, **kwargs):
     """
     log.log("in handle_request")
     ctx, body = context.context_from_format(format_def, **kwargs)
+    log.set_request_id(ctx.CallID())
     log.log("context provisioned")
     try:
         response_data = await with_deadline(ctx, handler_code, body)
@@ -96,5 +97,8 @@ async def handle_request(handler_code, format_def, **kwargs):
 
     except (Exception, TimeoutError) as ex:
         log.log("exception appeared: {0}".format(ex))
-        traceback.print_exc(file=sys.stderr)
+        (exctype, value, tb) = sys.exc_info()
+        tb_flat = ''.join(
+            s.replace('\n', '\\n') for s in traceback.format_tb(tb))
+        log.get_request_log().error('{}:{}'.format(value, tb_flat))
         return errors.DispatchException(ctx, 502, str(ex)).response()