Observability — Metrics, Logs, আর Trace কীভাবে একসাথে কাজ করে

লক্ষ্য: log এবং trace — দুইটা আলাদা backend-এ বসা দুইটা আলাদা pillar — কীভাবে একটা মাত্র shared identifier (trace_id) দিয়ে জোড়া লাগে, সেই correlation মেকানিজমটা কোডে দেখানো। এখানে কোনো নতুন span-mechanic নেই — span assembly-র যুক্তি (parent-edge দিয়ে tree, timestamp দিয়ে না) হুবহু distributed-systems/distributed-tracing-এর TraceCollector-এর মতোই; আজকের নতুনত্ব শুধু log-থেকে-trace-এ jump করার entry point।

# log_trace_correlation.py -- given ONE suspicious log line, find and print
# the FULL trace it belongs to. Reuses the exact checkout-request example
# (gateway -> cart -> inventory -> queue -> notifier) and the exact span
# fields (trace_id, span_id, parent_span_id, name, start_ms, duration_ms)
# from distributed-systems/distributed-tracing -- no new tracing mechanics
# introduced here, only the CORRELATION step: trace_id as the shared key
# between the logs backend and the traces backend.

LOGS = [
    {"ts": "10:02:01.004", "level": "INFO",  "service": "gateway",
     "trace_id": "tr-88", "msg": "GET /checkout accepted"},
    {"ts": "10:02:01.041", "level": "INFO",  "service": "cart",
     "trace_id": "tr-88", "msg": "cart processed, 3 items"},
    {"ts": "10:02:01.520", "level": "ERROR", "service": "inventory",
     "trace_id": "tr-88", "msg": "reserve_stock timed out after 503ms, retrying"},
    {"ts": "10:02:03.900", "level": "INFO",  "service": "gateway",
     "trace_id": "tr-91", "msg": "GET /checkout accepted"},
    {"ts": "10:02:03.955", "level": "INFO",  "service": "inventory",
     "trace_id": "tr-91", "msg": "reserve_stock ok"},
]

# same six spans as the distributed-tracing lesson's worked example
SPANS = [
    dict(trace_id="tr-88", span_id="g1", parent_span_id="",   name="gateway GET /checkout",  start_ms=0,   duration_ms=562),
    dict(trace_id="tr-88", span_id="a9", parent_span_id="g1",  name="auth-check verify_token", start_ms=2,   duration_ms=33),
    dict(trace_id="tr-88", span_id="c1", parent_span_id="g1",  name="cart process_cart",       start_ms=8,   duration_ms=537),
    dict(trace_id="tr-88", span_id="i1", parent_span_id="c1",  name="inventory reserve_stock", start_ms=15,  duration_ms=503),
    dict(trace_id="tr-88", span_id="q1", parent_span_id="c1",  name="cart.publish order.event", start_ms=549, duration_ms=2),
    dict(trace_id="tr-88", span_id="k1", parent_span_id="q1",  name="notifier.consume",        start_ms=601, duration_ms=41),
    dict(trace_id="tr-91", span_id="g2", parent_span_id="",   name="gateway GET /checkout",  start_ms=0,   duration_ms=58),
    dict(trace_id="tr-91", span_id="i2", parent_span_id="g2",  name="inventory reserve_stock", start_ms=6,   duration_ms=41),
]


def find_trace_for_log(log_line, spans):
    """The correlation mechanism: the log line already carries trace_id
    (the collector/SDK stamped it at emit time) -- jumping to the full
    trace is just a filter + a parent-edge tree assembly, exactly like
    TraceCollector.children_map/roots in the distributed-tracing lesson."""
    tid = log_line["trace_id"]
    matched = [s for s in spans if s["trace_id"] == tid]
    if not matched:
        return tid, []
    by_id = {s["span_id"]: s for s in matched}
    children = {}
    for s in matched:
        children.setdefault(s["parent_span_id"], []).append(s)
    roots = [s for s in matched if s["parent_span_id"] not in by_id]

    ordered = []
    def walk(s, depth):
        ordered.append((depth, s))
        for c in sorted(children.get(s["span_id"], []), key=lambda x: x["start_ms"]):
            walk(c, depth + 1)
    for r in sorted(roots, key=lambda x: x["start_ms"]):
        walk(r, 0)
    return tid, ordered


suspicious = LOGS[2]  # the ERROR line from inventory
print("suspicious log line:")
print(f"  [{suspicious['ts']}] {suspicious['level']:5} {suspicious['service']:10} "
      f"trace_id={suspicious['trace_id']}  \"{suspicious['msg']}\"")

trace_id, tree = find_trace_for_log(suspicious, SPANS)
print(f"\ncorrelated via trace_id={trace_id} -> full trace ({len(tree)} spans):")
for depth, s in tree:
    indent = "  " * depth
    print(f"  {indent}{s['name']:<32} start={s['start_ms']:>4}ms dur={s['duration_ms']:>4}ms  span={s['span_id']}")

print("\nconclusion: the ERROR is 'reserve_stock timed out' at 10:02:01.520 --")
print("the correlated trace shows inventory's reserve_stock span alone is 503ms")
print("of the request's 562ms total -- the log told us something failed,")
print("the trace (already built in the prerequisite lesson) tells us it's the")
print("single most expensive span in the whole call tree, not a red herring.")

প্রকৃত চালিয়ে পাওয়া output (deterministic — হুবহু এটাই আসবে):

suspicious log line:
  [10:02:01.520] ERROR inventory  trace_id=tr-88  "reserve_stock timed out after 503ms, retrying"

correlated via trace_id=tr-88 -> full trace (6 spans):
  gateway GET /checkout            start=   0ms dur= 562ms  span=g1
    auth-check verify_token          start=   2ms dur=  33ms  span=a9
    cart process_cart                start=   8ms dur= 537ms  span=c1
      inventory reserve_stock          start=  15ms dur= 503ms  span=i1
      cart.publish order.event         start= 549ms dur=   2ms  span=q1
        notifier.consume                 start= 601ms dur=  41ms  span=k1

conclusion: the ERROR is 'reserve_stock timed out' at 10:02:01.520 --
the correlated trace shows inventory's reserve_stock span alone is 503ms
of the request's 562ms total -- the log told us something failed,
the trace (already built in the prerequisite lesson) tells us it's the
single most expensive span in the whole call tree, not a red herring.

তিনটা মুহূর্ত মন দিয়ে পড়ুন: (১) find_trace_for_log-এর ভেতরে trace-tree assembly ঠিক distributed-tracing-এর TraceCollector-এরই সংক্ষিপ্ত রূপ — parent-edge দিয়ে গাছ, timestamp দিয়ে না। কোনো নতুন ধারণা তৈরি হয়নি, শুধু পুনর্ব্যবহার হয়েছে। (২) দ্বিতীয় trace (tr-91) সম্পূর্ণ সুস্থ — একই query একটা healthy trace-এর জন্য চালালে কিছুই সন্দেহজনক দেখাত না, তাই correlation সবসময় একটা নির্দিষ্ট সন্দেহজনক log line থেকে শুরু হয়, সব trace থেকে না। (৩) এই পুরো mechanism কাজ করার একমাত্র পূর্বশর্ত — log emit করার সময়েই কোডে trace_id-টা হাতে থাকা লাগে, যেটা OTel SDK-র auto-instrumentation দেয় (distributed-tracing লেসনের traceparent propagation-এর সরাসরি ফল)।

নিজে বাড়ান:

1. LOGS-এ আরেকটা trace_id (tr-91-এর একটা INFO log) দিয়ে ফাংশনটা চালান — দেখুন healthy trace-এর জন্য কী পার্থক্য দেখা যায়।
2. একটা log line-এ trace_id না থাকলে কী হবে তা handle করুন — বাস্তবে এটা ঘটে যখন কোনো পুরনো, un-instrumented কোড-পথ থেকে log আসে।
3. ফাংশনটা extend করুন যাতে সেই trace-এর critical path-ও highlight করে (আগের লেসনের critical_path ফাংশনের মতো) — log থেকে সরাসরি “কোন span-টা আসল দোষী” পর্যন্ত এক লাফে পৌঁছানো।