[py] Support request-stack context metadata

[gabe-l-hart]

Is your feature request related to a problem? Please describe.

In cloud services, it's common practice to attach a trace ID to each request that is processed. When logging with alog, this id should be included as a field in the metadata of every log line during the request's scope.

Describe the solution you'd like

The metadata be attached to the call stack (and not a local thread ID) so that all log lines made within a call stack will have the ID included as a field.

Describe alternatives you've considered

Attaching a trace ID to a thread using threading.local is a simple solution, but insufficient to properly handle several cases:

1. Threads that spawn other threads
2. Requests handled with long-lived threads from a pool

[gabe-l-hart]

This turns out to be quite difficult since the various stack-tracing functions in inspect do not capture stacks that span across thread boundaries.

import inspect
import threading
import time


class StackFrameLookup:
    def __init__(self):
        self.frame_map = {}
    def add_val(self, val):
        caller_frame = inspect.stack()[1].frame
        self.frame_map[caller_frame] = val
    def remove_val(self):
        caller_frame = inspect.stack()[1].frame
        self.frame_map.pop(caller_frame, None)
    def get_val(self):
        for caller_frame in inspect.stack()[1:]:
            if caller_frame.frame in self.frame_map:
                return self.frame_map[caller_frame.frame]

lookups = StackFrameLookup()

def inner_fun():
    print(f"[inner] Outside PRE: {lookups.get_val()}")
    lookups.add_val("inner")
    print(f"[inner] Inside: {lookups.get_val()}")
    lookups.remove_val()
    print(f"[inner] Outside POST: {lookups.get_val()}")

def threaded_inner(x):
    print(f"[thread-inner {x}] Outside PRE: {lookups.get_val()}")
    lookups.add_val(f"thread-inner-{x}")
    print(f"[thread-inner {x}] Inside before sleep: {lookups.get_val()}")
    time.sleep(1)
    print(f"[thread-inner {x}] Inside after sleep: {lookups.get_val()}")
    lookups.remove_val()
    print(f"[thread-inner {x}] Outside POST: {lookups.get_val()}")

def outer_fun():
    print(f"[outer] Outside PRE: {lookups.get_val()}")
    lookups.add_val("outer")
    print(f"[outer] Inside before inner: {lookups.get_val()}")
    inner_fun()
    th1 = threading.Thread(target=threaded_inner, args=(1,))
    th2 = threading.Thread(target=threaded_inner, args=(2,))
    th1.start()
    th2.start()
    th1.join()
    th2.join()
    print(f"[outer] Inside after inner: {lookups.get_val()}")
    lookups.remove_val()
    print(f"[outer] Outside POST: {lookups.get_val()}")