https://archtenet.dev/assets/js/c7d04f2e.db603569.js

1"use strict";(self.webpackChunkengineering_playbook=self.webpackChunkengineering_playbook||[]).push([["1941"],{56631(e,t,a){a.r(t),a.d(t,{assets:()=>d,contentTitle:()=>o,default:()=>c,frontMatter:()=>s,metadata:()=>n,toc:()=>h});var n=a(65536),r=a(74848),i=a(28453);let s={slug:"trace-id-in-every-log-line",title:"A Trace Id in Every Log Line: How Cross-Service Debugging Went From a Four-Engineer Session to One Grafana Query",authors:["ivan"],tags:["observability","nestjs","microservices","architecture"],date:new Date("2026-09-09T00:00:00.000Z"),description:"Field report from a 200+ microservice enterprise platform. A trace id delivered through the shared libraries one team's 80+ NestJS services already used now covers more than 100 services, and turned hours of multi-engineer debugging into a query an analyst runs in minutes \u2013 and later into a tool an AI agent drives. The cost: call topology is inferred, not known.",featured:!0,featured_order:5},o,d={authorsImageUrls:[void 0]},h=[{value:"Debugging was a meeting",id:"debugging-was-a-meeting",level:2},{value:"The libraries were already everywhere, so the ID was nearly free",id:"the-libraries-were-already-everywhere-so-the-id-was-nearly-free",level:2},{value:"What a developer sees, and what they never see",id:"what-a-developer-sees-and-what-they-never-see",level:2},{value:"The analyst became the first responder",id:"the-analyst-became-the-first-responder",level:2},{value:"A production incident that never reached the owning team",id:"a-production-incident-that-never-reached-the-owning-team",level:2},{value:"What the other teams did with it",id:"what-the-other-teams-did-with-it",level:2},{value:"Payload logs stay off, and that is a discipline",id:"payload-logs-stay-off-and-that-is-a-discipline",level:2},{value:"Then agents arrived",id:"then-agents-arrived",level:2},{value:"What made it true for us",id:"what-made-it-true-for-us",level:2}];function l(e){let t={a:"a",code:"code",em:"em",h2:"h2",p:"p",pre:"pre",...(0,i.R)(),...e.components};return(0,r.jsxs)(r.Fragment,{children:[(0,r.jsx)(t.p,{children:"In 2022, I added a trace id to the two shared libraries every service my team owned already used \u2013 the logger and the HTTP client \u2013 so that one query in Grafana would return every log line of one request, across every service it touched. The platform is an enterprise system built as microservices from day one; it runs more than 200 of them today across several teams. My team owns 80+ of those. The trace id now covers more than 100 \u2013 more than we own \u2013 because other teams adopted it."}),"\n",(0,r.jsx)(t.p,{children:"Before that change, a cross-service bug on a test environment was a meeting: a QA engineer, a business analyst, the team lead, usually a developer or two, sometimes DevOps \u2013 several hours of reading logs by timestamp and reconstructing the call chain from memory of the code. After that, the same investigation became a text field on a Grafana board, and the person typing into it was most often the analyst, not an engineer. Minutes rather than hours, and in most cases no engineer at all."}),"\n",(0,r.jsxs)(t.p,{children:["The cost is stated up front because it matters. There are no span IDs. Which service called which is inferred from a forwarded ",(0,r.jsx)(t.code,{children:"User-Agent"})," and timestamps rather than being known. That was the trade."]}),"\n",(0,r.jsxs)(t.p,{children:["This is a field report: what debugging looked like, what changed, and two cases as they happened. The mechanism is documented as a reference architecture, ",(0,r.jsx)(t.a,{href:"/docs/reference-architectures/ra-004-log-based-tracing",children:"RA-004"}),", and reconstructed as runnable code in ",(0,r.jsx)(t.a,{href:"https://github.com/ivanbaha/team-workspace",children:"team-workspace"}),"; this article explains it only as far as the story needs. If you read one section, read the two cases."]}),"\n","\n",(0,r.jsx)(t.h2,{id:"debugging-was-a-meeting",children:"Debugging was a meeting"}),"\n",(0,r.jsx)(t.p,{children:"The platform was adding third-party integrations quickly, and integrations are where things break. Most issues surfaced in test environments during pre-release, which is the right place for them to surface and the wrong place to spend a day on each."}),"\n",(0,r.jsx)(t.p,{children:"Grafana had every log line from every service. What it lacked was any way to join them. A request that crossed six services left six sets of lines, and the only links between them were timestamps and whatever the engineer reading them remembered about the call chain. Finding the one line that mattered meant knowing which service to look in, narrowing the time window by hand, filtering, and repeating for the next hop."}),"\n",(0,r.jsx)(t.p,{children:"So it became a session. The QA engineer to explain what happened and why it was wrong. The analyst to confirm what the behaviour should have been \u2013 there was never time for documentation. The team lead was the person responsible. The developer who owned the related code, if they could be found, and DevOps if infrastru

1cture was involved. Two to four people, sometimes more, for several hours per issue. I understand that is not how it should work. It is how many teams work."}),"\n",(0,r.jsx)(t.h2,{id:"the-libraries-were-already-everywhere-so-the-id-was-nearly-free",children:"The libraries were already everywhere, so the ID was nearly free"}),"\n",(0,r.jsx)(t.p,{children:"I joined the platform at its launch in 2021 as a developer and owned its shared libraries \u2013 the sole contributor, from design through to wiring them into services. That set of libraries was the reason a new service could be assembled by role: add the modules it needed, and it was alive and ready for business logic. Before coding agents, that was a big deal on its own."}),"\n",(0,r.jsx)(t.p,{children:"Two of those libraries mattered here. The HTTP client had started as a Stack Overflow idea and been rewritten for our needs: auth, header forwarding, and payload logging. The logger had started as a copy-and-pasted wrapper around winston and gained automatic context extraction \u2013 the class and method a line came from, derived from the call stack \u2013 before I later rewrote it entirely and removed winston, because every third-party dependency is a vulnerability surface and the framework's own logger was enough."}),"\n",(0,r.jsx)(t.p,{children:"Both were in every service my team owned. That's why what followed was cheap."}),"\n",(0,r.jsx)(t.p,{children:"A tracing stack was not available to us in 2022 \u2013 mostly cost. So the question was what could be done with what we already had, and the answer was one field. Put an id on every inbound request, write it into every log line, forward it on every outbound call, and Grafana's existing line filter becomes the join. I explained the benefit to the analyst and the product owner, framed it as tech debt, and secured the slot."}),"\n",(0,r.jsx)(t.p,{children:"What made it work in practice, rather than just in principle, was the framework. NestJS request-scoped dependency injection lets the logger and the HTTP client read the id from the current request without any application code passing it. A developer imports two modules and writes ordinary log lines; the correlation happens automatically. Coverage went high because there was nothing to forget. And the discipline it asks of developers is the same one ordinary logging already asks \u2013 enough lines to make a process legible, not so many that they are noise \u2013 so it was not a new scope for anyone."}),"\n",(0,r.jsx)(t.h2,{id:"what-a-developer-sees-and-what-they-never-see",children:"What a developer sees, and what they never see"}),"\n",(0,r.jsx)(t.p,{children:"Adoption per service is this:"}),"\n",(0,r.jsx)(t.pre,{children:(0,r.jsx)(t.code,{className:"language-ts",children:"@Module({\n  imports: [\n    TracingModule.forRoot(),   // seeds x-trace-id before guards and interceptors\n    LoggerModule.forRoot(),    // id on every log line; request/response pair\n    HttpConnectionModule.forRoot({ userAgent: SERVICE_NAME, /* \u2026 */ }), // carries it onward\n  ],\n})\nexport class AppModule {}\n"})}),"\n",(0,r.jsx)(t.p,{children:"After that, a developer writes what they always wrote:"}),"\n",(0,r.jsx)(t.pre,{children:(0,r.jsx)(t.code,{className:"language-ts",children:"this.logger.warn(`User ${id} not found`, 'UsersService.findOne');\n"})}),"\n",(0,r.jsx)(t.p,{children:"and this comes out:"}),"\n",(0,r.jsx)(t.pre,{children:(0,r.jsx)(t.code,{className:"language-json",children:'{"timestamp":"2026-09-05T15:21:43.738Z","level":"warn","serviceName":"users-service","podId":"b4799cf77-8t452","context":"UsersService.findOne","traceId":"01M0J6EYRY4TFEPR9PHJZ1QHPF","message":"User 9 not found"}\n'})}),"\n",(0,r.jsxs)(t.p,{children:["Three fields on that line do the work. ",(0,r.jsx)(t.code,{children:"traceId"})," groups the lines of one request across every service. ",(0,r.jsx)(t.code,{children:"serviceName"})," and ",(0,r.jsx)(t.code,{children:"context"})," indicate where in the code each line came from \u2013 and that pair turns a found line into a place to look, which is most of what an investigation is. The id alone would tell you ",(0,r.jsx)(t.em,{children:"that"})," something happened; the name and the context tell you ",(0,r.jsx)(t.em,{children:"where"}),"."]}),"\n",(0,r.jsx)(t.p,{children:"One more record pair, emitted automatically, is what turns grouped lines into a chain \u2013 who called whom, with what status, and how long each call took:"}),"\n",(0,r.jsx)(t.pre,{children:(0,r.jsx)(t.code,{className:"language-json",children:'{"direction":"request.in","method":"GET","path":"/v1/users/1","caller":"products-service"}\n{"direction":"response.out","method":"GET","path":"/v1/users/1","statusCode":200,"duration":1}\n'})}),"\n",(0,r.jsxs)(t.p,{children:[(0,r.jsx)(t.code,{children:"caller"})," is the forwarded ",(0,r.jsx)(t.code,{children:"User-Agent"}),". That is the only edge information a trace has \u2013 there is no parent span id \u2013 which is the cost of opening in concrete form. It is also why every service names itself with one string in four places: the container name, the ",(0,r.jsx)(t.code,{children:"DEPLOYMENT_NAME"})," variable, the ",(0,r.jsx)(t.code,{children:"serviceName"})," log field, and the outbound ",(0,r.jsx)(t.code,{children:"User-Agent"}),". Let those drift and a service's calls turn into orphaned roots, while every individual line still looks fine."]}),"\n",(0,r.jsxs)(t.p,{children:["The rest of the mechanism \u2013 why the id is seeded in middleware and not an interceptor, why request scope is affordable, the four direction records, what happens to a scheduled job with no inbound request \u2013 is in ",(0,r.jsx)(t.a,{href:"/docs/reference-architectures/ra-004-log-based-tracing",children:"RA-004"})," with the code it points at."]}),"\n",(0,r.jsx)(t.h2,{id:"the-analyst-became-the-first-responder",children:"The analyst became the first responder"}),"\n",(0,r.jsxs)(t.p,{children:["A trace id has to reach a person before it is useful, and it reaches them in three ways. Every response echoes it back as ",(0,r.jsx)(t.code,{children:"x-trace-id"}),", so anyone reproducing a problem with the browser's network tab open has it on the failing request. Some user-facing error notifications display it and suggest attaching it to the ticket. Most often, it is simply read off an error line found by time window or by a business identifier \u2013 an order number, an account id \u2013 because most investigations start from an error."]}),"\n",(0,r.jsx)(t.p,{children:"The Grafana board our analyst uses is the simplest possible thing: a text field for the id, feeding one Loki panel. She learned it in minutes. There was no runbook."}),"\n",(0,r.jsxs)(t.p,{children:["The first case was in a test environment. An independent tester conducting pre-production testing called our analyst: edits to a review form would not save. She asked him to share his screen and reproduce the issue with the network tab open. The failing response was visible, and so was its ",(0,r.jsx)(t.code,{children:"x-trace-id"})," header. She opened the board, pasted the id, and traced the chain down to the error: the database connector reported the write had failed because the cluster was in read-only mode. The operations team was in the middle of maintenance. Five minutes from the call to the answer, and n

1o engineer involved."]}),"\n",(0,r.jsx)(t.p,{children:"That case is representative. With the chain in front of her, the analyst can usually classify an issue on the spot \u2013 a test data mismatch, an incorrect flow during testing, a misunderstanding of the product, or a real defect \u2013 and route it: back to the tester with an explanation, or to the developer who owns that code, with the evidence already attached. For most issues, the multi-hour session did not get shorter \u2013 it was discontinued."}),"\n",(0,r.jsx)(t.h2,{id:"a-production-incident-that-never-reached-the-owning-team",children:"A production incident that never reached the owning team"}),"\n",(0,r.jsx)(t.p,{children:"The second case is production, and it crosses two teams."}),"\n",(0,r.jsx)(t.p,{children:"A user raised an incident: they could not start a session in one of the platform's real-time features. Second-line support reviewed that service's logs for the reported time window and found the error \u2013 the user's organisation was not on an allow list. That service belongs to another team, so their engineer joined."}),"\n",(0,r.jsxs)(t.p,{children:["They took the ",(0,r.jsx)(t.code,{children:"traceId"})," off the error line and restored the full chain, which revealed the organisation's identifier. Searching by that identifier found the moment the organisation had been ",(0,r.jsx)(t.em,{children:"added"})," to the allow list \u2013 or rather, the moment the addition had been attempted \u2013 and the trace of that request led into my team's area, where a database availability problem at that time was plainly visible. The addition had failed, and the user hadn\u2019t noticed the issue."]}),"\n",(0,r.jsx)(t.p,{children:"Support asked the user to add the organisation again. It worked. The end-to-end time was about thirty minutes. Nobody from my team was called into the session, because the chain had already said everything we could have said. The database availability question was escalated to DevOps as a separate investigation, with its context attached."}),"\n",(0,r.jsx)(t.p,{children:"Two things in that case are worth noting. The investigation crossed a team boundary without a hand-off meeting because the id crossed it first. And the person who found the root cause was not on the team that owned the root cause."}),"\n",(0,r.jsx)(t.h2,{id:"what-the-other-teams-did-with-it",children:"What the other teams did with it"}),"\n",(0,r.jsx)(t.p,{children:"Our team was one of several on the platform, owning 80+ of its 200+ services. At least two others adopted the approach for their parts of the system \u2013 which is how the trace id came to cover more than 100 services \u2013 but they implemented it differently."}),"\n",(0,r.jsx)(t.p,{children:"One took our libraries as they were. One reimplemented the contract in its own codebase \u2013 a Python service, FastAPI, as far as I recall \u2013 because the contract is small enough to reimplement: one header, one field in the log line, and one record pair. Other teams did nothing at all and still benefit; they see the id in their own logs and quote it in investigation threads."}),"\n",(0,r.jsxs)(t.p,{children:["The case I find most telling involves another organisation entirely. For one flow, we receive events from a partner's application. The handler uses ",(0,r.jsx)(t.em,{children:"the partner's event id"})," as the trace id for every chain it fires. We share no logging stack with them, but when an issue appears on our side, the id we hand them is one they can search on theirs, and both sides end up with the full picture. That works only because the id was never given a format to validate \u2013 any non-empty string is a trace id \u2013 and it was one of the design's quieter decisions that paid off most."]}),"\n",(0,r.jsx)(t.h2,{id:"payload-logs-stay-off-and-that-is-a-discipline",children:"Payload logs stay off, and that is a discipline"}),"\n",(0,r.jsx)(t.p,{children:"The request/response pair is compact by default: direction, method, path, caller, status, and duration. Full payload logging \u2013 headers and bodies, with credentials masked \u2013 is a separate opt-in mode everywhere. I switch it on for a flow I want to watch. In lower environments, it pays for itself during third-party integration work, when the aim is to confirm exactly what we sent and to read the partner's complete response. In production, it is almost never needed, because by the time a flow reaches production, the integration has been verified; when it is needed, it is switched on, and the issue is reproduced for c

1ollecting related details."}),"\n",(0,r.jsx)(t.p,{children:"Ninety per cent or more of issues are caught in test environments. The consequence for developers is a discipline rather than a tool: ordinary log lines have to make a process legible on their own, because most of the time they are all there is. The record pair increases log volume \u2013 two lines per request per service, two more per outbound call. Payloads sit on top of that, which is one more reason they stay opt-in."}),"\n",(0,r.jsx)(t.h2,{id:"then-agents-arrived",children:"Then agents arrived"}),"\n",(0,r.jsxs)(t.p,{children:["By the time coding agents were ready for real-world work, I was leading the team. I built an AI-native workspace that gives an agent the whole system's context \u2013 documented separately as ",(0,r.jsx)(t.a,{href:"/docs/reference-architectures/ra-003-ai-native-meta-repo",children:"RA-003"}),", which is not the subject here \u2013 and, within it, an MCP server with tools for Grafana."]}),"\n",(0,r.jsxs)(t.p,{children:["One of those tools takes a trace ID \u2013 or a pasted log line, or a URL containing an ID \u2013 and returns the reconstructed chain: who called whom, status and duration per call, which services took part but logged nothing, and every error and warning under the ID. A skill drives the investigation end to end. Because the chain names services whose source is checked out in the same workspace, the agent goes from ",(0,r.jsx)(t.em,{children:"which service failed"})," to ",(0,r.jsx)(t.em,{children:"which line failed"})," without any context-gathering, and if a fix is needed, it can be made in place."]}),"\n",(0,r.jsx)(t.p,{children:"Our analyst uses it. Her output is either an explanation that the test setup was wrong or a task a developer can pick up as is. Second-line support is adopting the same flow and now produces grounded reports; they escalate less because most incidents turn out to be misunderstandings about how to use the product rather than defects, and the chain says so."}),"\n",(0,r.jsxs)(t.p,{children:['The reconstruction is a heuristic, and the tool declares its own uncertainty \u2013 an ambiguous pairing means "do not trust the duration", never "the call did not happen". The flags and what they do and do not mean are in ',(0,r.jsx)(t.a,{href:"/docs/reference-architectures/ra-004-log-based-tracing#5-reconstruction-tooling-optional-layer",children:"RA-004"}),"."]}),"\n",(0,r.jsx)(t.p,{children:"The same records include timestamps and durations, so I built a small opt-in tool that lays out a chain's timings: wall time, per-call durations, repeated calls, and gaps. It is separate from tracing proper and has more potential than I have used. So far, it has found a broken auth-token cache in our own service and events still being sent to an outdated third-party tool."}),"\n",(0,r.jsx)(t.h2,{id:"what-made-it-true-for-us",children:"What made it true for us"}),"\n",(0,r.jsx)(t.p,{children:"None of this argues that a tracing stack is unnecessary. It is a statement about one platform under one constraint: we could not have one in 2022, and correlation was the part that could not wait. What made the cheap version work was a precondition not every team has \u2013 shared libraries that already reached every service, owned by someone who could change them. Given that, the id was two imports away from everywhere, the framework made it ambient, and the log pipeline we already ran became the tracing backend."}),"\n",(0,r.jsx)(t.p,{children:"What it gave up is real and permanent: edges are inferred, not known, and nothing below the request is visible. What it produced is the two cases above, repeated across four years of release cycles \u2013 drawn from my own sessions and the analyst's feedback, not from a ticket count."}),"\n",(0,r.jsxs)(t.p,{children:["The mechanism is documented in ",(0,r.jsx)(t.a,{href:"/docs/reference-architectures/ra-004-log-based-tracing",children:"RA-004"}),". The code is in ",(0,r.jsx)(t.a,{href:"https://github.com/ivanbaha/team-workspace",children:"team-workspace"}),", a sanitised reconstruction of the production design rather than the production code; its design document ",(0,r.jsx)(t.a,{href:"https://github.com/ivanbaha/team-workspace/blob/main/docs/architecture/distributed-tracing.md#what-this-repository-does-and-does-not-demonstrate",children:"says what it exercises and what it only describes"}),". Both are small enough to read in an afternoon."]})]})}function c(e={}){let{wrapper:t}={...(0,i.R)(),...e.components};return t?(0,r.jsx)(t,{...e,children:(0,r.jsx)(l,{...e})}):l(e)}},28453(e,t,a){a.d(t,{R:()=>s,x:()=>o});var n=a(96540);let r={},i=n.createContext(r);function s(e){let t=n.useContext(i);return n.useMemo(function(){return"function"==typeof e?e(t):{...t,...e}},[t,e])}function o(e){let t;return t=e.disableParentContext?"function"==typeof e.components?e.components(r):e.components||r:s(e.components),n.createElement(i.Provider,{value:t},e.children)}},65536(e){e.exports=JSON.parse('{"permalink":"/blog/trace-id-in-every-log-line","source":"@site/blog/2026-09-09-trace-id-in-every-log-line/index.md","title":"A Trace Id in Every Log Line: How Cross-Service Debugging Went From a Four-Engineer Session to One Grafana Query","description":"Field report from a 200+ microservice enterprise platform. A trace id delivered through the shared libraries one team\'s 80+ NestJS services already used now covers more than 100 services, and turned hours of multi-engineer debugging into a query an analyst runs in minutes \u2013 and later into a tool an AI agent drives. The cost: call topology is inferred, not known.","date":"2026-09-09T00:00:00.000Z","tags":[{"inline":true,"label":"observability","permalink":"/blog/tags/observability"},{"inline":true,"label":"nestjs","permalink":"/blog/tags/nestjs"},{"inline":true,"label":"microservices","permalink":"/blog/tags/microservices"},{"inline":true,"label":"architecture","permalink":"/blog/tags/architecture"}],"readingTime":13.59,"hasTruncateMarker":true,"authors":[{"name":"Ivan Baha","title":"Software Team Lead & Architect","url":"/about#ivan-baha","orcid":"https://orcid.org/0009-0005-7024-7724","imageURL":"https://github.com/ivanbaha.png","key":"ivan","page":null}],"frontMatter":{"slug":"trace-id-in-every-log-line","title":"A Trace Id in Every Log Line: How Cross-Service Debugging Went From a Four-Engineer Session to One Grafana Query","authors":["ivan"],"tags":["observability","nestjs","microservices","architecture"],"date":"2026-09-09T00:00:00.000Z","description":"Field report from a 200+ microservice enterprise platform. A trace id delivered through the shared libraries one team\'s 80+ NestJS services already used now covers more than 100 services, and turned hours of multi-engineer debugging into a query an analyst runs in minutes \u2013 and later into a tool an AI agent drives. The cost: call topology is inferred, not known.","featured":true,"featured_order":5},"unlisted":false,"prevItem":{"title":"Spec-Driven Development Is Simpler Than You Thought","permalink":"/blog/spec-driven-development-is-simpler-than-you-thought"},"nextItem":{"title":"Prevention Has a Ceiling: Designing CI Pipelines That Survive Being Breached","permalink":"/blog/prevention-has-a-ceiling"}}')}}]);