TT Lab
Get started
Learn Learning paths Courses

Where Distributed Tracing Breaks

How many spans should one retried request become?

Continue in TT Lab

Goal

You see for yourself what the dump loses when a retry is put in one span, create a span per attempt and put the error in the right place, and then calculate how far apart the span-based error rate and the request-based error rate are on the same data. Finally, you harden those rules into a linter and catch a dump that breaks them.

Why it matters

Retries are in almost every service, but almost nobody has decided how to draw them in a trace. If you quietly repeat inside one span, which attempt took how long and what made it fail disappears entirely, and all that remains is "this span took a long time." Conversely, if you create a span per attempt but put the error anywhere, the error rate counted by spans inflates to more than double the failures users experienced, and the dashboard lies. If you separate the two layers — the wrapping span is the one thing the user went through, and an attempt span is one call that actually went out to the upstream — where to count which number is decided on its own. Which API records a caught exception is the SDK lifecycle module's job; what is decided here is how many spans to split into and where to put the error.

Steps

  1. Create /root/tp-retry/one_span.py. Read the dump path first from the environment variable TRACELAB_OUT, and if it is absent use /root/tp-retry/01-one.jsonl. Get a tracer with provider("shop-api", OUT) and create just one charge span, and inside it repeat upstream.call("charge", 시도번호, idempotency_key="ord-7781") (the placeholder is the attempt number) until it succeeds (when it fails, rest for upstream.backoff_s(시도번호) seconds). Call flush() at the end of the program. Then write two lines in /root/tp-retry/01-lost.txt — after attempts=, the number of attempts actually made, as an integer, and after lost=, what can no longer be known from this dump, in at least 40 characters.
  2. Create /root/tp-retry/attempts.py. The default dump path is /root/tp-retry/02-attempts.jsonl. Leave the wrapping span charge as it is, create a child span charge.attempt for each attempt, and write which attempt it is (from 1) in the integer attribute retry.attempt. The wait is done outside the attempt span. After running it, the dump must contain 4 spans (1 wrapping + 3 attempts).
  3. Create /root/tp-retry/error_place.py. The default dump path is /root/tp-retry/03-error.jsonl. On a failed attempt span, set the status to ERROR and write exc.kind in the string attribute error.type. Do not touch the status of a successful attempt span. The wrapping charge span sets its status to OK at the end — because the result the user experienced was a success.
  4. Create /root/tp-retry/rates.py. The default dump path is /root/tp-retry/04-rates.jsonl, and it processes four jobs, charge, quote, ship, and notify, in turn. For each job, create a wrapping span <작업>.request and attempt spans <작업>.attempt (the placeholder is the job name), with at most 3 attempts. The wrapping span of a job that failed in the end is ERROR, and of a job that succeeded is OK. Then write two lines with four tab-separated columns in /root/tp-retry/04-rates.tsv — the first line is span_level, the second is request_level, and the columns are <id> <오류 수> <전체 수> <비율> (the placeholders are the id, the error count, the total count, and the ratio). span_level counts every span in the dump, and request_level counts only spans with no parent. The ratio is to four decimal places.
  5. Create /root/tp-retry/backoff.py (default dump path /root/tp-retry/05-backoff.jsonl). Process only charge again, but each time a wait finishes, add a retry.backoff event to the wrapping span and attach retry.attempt (an integer) and backoff.ms (milliseconds) to that event. At the end, write the sum of the wait times in milliseconds in the wrapping span's attribute retry.backoff_ms_total. Then write two lines in /root/tp-retry/05-gap.txt — after backoff_total_ms=, the total you recorded, and after uncovered_ms=, the value you get by subtracting the intervals covered by the attempt spans from the wrapping span's length (to one decimal place).
  6. Create /root/tp-retry/attrs.py (default dump path /root/tp-retry/06-attrs.jsonl). Process charge again, but attach retry.count (an integer, the actual number of attempts), retry.last_error (the kind of the last failure), and idempotency.key (ord-7781) to the wrapping span, and attach to each attempt span retry.attempt and an idempotency.key with the same value. On a failed attempt, leave error.type and the ERROR status as in step 3. Then write four lines with three tab-separated columns in /root/tp-retry/06-rules.tsv — the first column is the attribute name, in order retry.count, retry.last_error, idempotency.key, and retry.attempt, the second column is where that attribute is attached, root or attempt, and the third column is why it goes there, in at least 20 characters.
  7. Create /root/tp-retry/ship_spans.py (default dump path /root/tp-retry/07-ship.jsonl). dispatch(order_id, hooks) in the material tracelab.tp_retry.shipping already has a loop and opens only three places, attempt_begin, attempt_end, and waited. Using a class that inherits shipping.Hooks, create spans at those three places, and leave a wrapping span ship.dispatch and an attempt span ship.attempt under the service name shipping-api with the same attribute rules as step 6. Also attach retry.backoff_ms_total to the wrapping span. The idempotency key is ord-7781.
  8. Create /root/tp-retry/retry_lint.py. When run as python3 retry_lint.py <덤프경로> (the placeholder is the dump path), it prints one line <규칙이름><탭><스팬아이디> (the placeholders are the rule name, a tab, and the span id) for each place that breaks a rule and ends with exit code 1, and if nothing breaks it prints one line ok<탭><루트 스팬 수> (the placeholders are a tab and the number of root spans) and ends with 0. There are exactly four rule names — root-status (the last attempt is not a failure but the wrapping span is ERROR), retry-count (the wrapping span's retry.count differs from the number of children), attempt-error-type (an attempt span that is ERROR has no error.type), and idem-key (an attempt span's idempotency.key differs from the wrapping span's). Run the linter you built on /root/tp-retry/06-attrs.jsonl to see that it passes, and save the output of running it on /opt/app/tracelab/tp_retry/broken.jsonl in /root/tp-retry/08-lint.txt.

Notes

What the dump loses when a retry is put in one span

Create /root/tp-retry/one_span.py. Read the dump path first from the environment variable TRACELAB_OUT, and if it is absent use /root/tp-retry/01-one.jsonl. Get a tracer with provider("shop-api", OUT) and create just one charge span, and inside it repeat upstream.call("charge", 시도번호, idempotency_key="ord-7781") (the placeholder is the attempt number) until it succeeds (when it fails, rest for upstream.backoff_s(시도번호) seconds). Call flush() at the end of the program. Then write two lines in /root/tp-retry/01-lost.txt — after attempts=, the number of attempts actually made, as an integer, and after lost=, what can no longer be known from this dump, in at least 40 characters.

The material is /opt/app/tracelab/tp_retry/upstream.py. If you open PLAN, it says on which attempt charge succeeds. Delete the file before making the dump again — the dump is appended to. Always run the program with /opt/otel-lab/bin/python (the system python3 does not have otel).

Create a span per attempt to reveal the time

Create /root/tp-retry/attempts.py. The default dump path is /root/tp-retry/02-attempts.jsonl. Leave the wrapping span charge as it is, create a child span charge.attempt for each attempt, and write which attempt it is (from 1) in the integer attribute retry.attempt. The wait is done outside the attempt span. After running it, the dump must contain 4 spans (1 wrapping + 3 attempts).

If you nest with tracer.start_as_current_span(...), the parent of the inner span automatically becomes the outer span. If you do the wait inside the attempt span, that attempt looks as if it took longer than it really did, so be careful about the placement. You can see the list of spans with python3 /opt/lab/checks/_tplib.py summary <덤프> (the placeholder is the dump).

Only the failed attempts are errors, and the wrapping span is OK

Create /root/tp-retry/error_place.py. The default dump path is /root/tp-retry/03-error.jsonl. On a failed attempt span, set the status to ERROR and write exc.kind in the string attribute error.type. Do not touch the status of a successful attempt span. The wrapping charge span sets its status to OK at the end — because the result the user experienced was a success.

If you use from opentelemetry.trace import Status, StatusCode, you can set the status with set_status(Status(StatusCode.ERROR, 설명)) (the placeholder is the description). A span that has had no status set remains UNSET in the dump — OK and UNSET are different values, and this step requires that difference.

If you count errors by spans, retries are counted twice

Create /root/tp-retry/rates.py. The default dump path is /root/tp-retry/04-rates.jsonl, and it processes four jobs, charge, quote, ship, and notify, in turn. For each job, create a wrapping span <작업>.request and attempt spans <작업>.attempt (the placeholder is the job name), with at most 3 attempts. The wrapping span of a job that failed in the end is ERROR, and of a job that succeeded is OK. Then write two lines with four tab-separated columns in /root/tp-retry/04-rates.tsv — the first line is span_level, the second is request_level, and the columns are <id> <오류 수> <전체 수> <비율> (the placeholders are the id, the error count, the total count, and the ratio). span_level counts every span in the dump, and request_level counts only spans with no parent. The ratio is to four decimal places.

notify does not succeed on any attempt — look at upstream.PLAN. The whole point of this step is that the denominators of the two ratios differ. For counting, just read the dump with Python and look only at status and parent_id, and with load from /opt/lab/checks/_tplib.py it reads in one line.

The time spent waiting is in no span

Create /root/tp-retry/backoff.py (default dump path /root/tp-retry/05-backoff.jsonl). Process only charge again, but each time a wait finishes, add a retry.backoff event to the wrapping span and attach retry.attempt (an integer) and backoff.ms (milliseconds) to that event. At the end, write the sum of the wait times in milliseconds in the wrapping span's attribute retry.backoff_ms_total. Then write two lines in /root/tp-retry/05-gap.txt — after backoff_total_ms=, the total you recorded, and after uncovered_ms=, the value you get by subtracting the intervals covered by the attempt spans from the wrapping span's length (to one decimal place).

You attach an event with span.add_event(이름, {속성}) (the placeholders are the name and the attributes). Get the uncovered interval with covered_ns(부모, 자식들) (the placeholders are the parent and the children) from /opt/lab/checks/_tplib.py and subtract it from the parent's length — that function does not count overlapping children twice. The two numbers will be similar but not exactly the same. Think about why.

Settle the attribute rules and instrument exactly by them

Create /root/tp-retry/attrs.py (default dump path /root/tp-retry/06-attrs.jsonl). Process charge again, but attach retry.count (an integer, the actual number of attempts), retry.last_error (the kind of the last failure), and idempotency.key (ord-7781) to the wrapping span, and attach to each attempt span retry.attempt and an idempotency.key with the same value. On a failed attempt, leave error.type and the ERROR status as in step 3. Then write four lines with three tab-separated columns in /root/tp-retry/06-rules.tsv — the first column is the attribute name, in order retry.count, retry.last_error, idempotency.key, and retry.attempt, the second column is where that attribute is attached, root or attempt, and the third column is why it goes there, in at least 20 characters.

There is one criterion for choosing the place — is that value decided once per logical request, or does it differ per attempt. The idempotency key is put on both with the same value. This is because the very fact that it went out several times with the same key is a clue for sorting out duplicate-processing incidents.

Hook the same rules into someone else's loop that you cannot fix

Create /root/tp-retry/ship_spans.py (default dump path /root/tp-retry/07-ship.jsonl). dispatch(order_id, hooks) in the material tracelab.tp_retry.shipping already has a loop and opens only three places, attempt_begin, attempt_end, and waited. Using a class that inherits shipping.Hooks, create spans at those three places, and leave a wrapping span ship.dispatch and an attempt span ship.attempt under the service name shipping-api with the same attribute rules as step 6. Also attach retry.backoff_ms_total to the wrapping span. The idempotency key is ord-7781.

Make the second service's provider with provider("shipping-api", OUT, set_global=False). You cannot use with in a hook, so create it with tracer.start_span(...) and call end() in attempt_end. If the wrapping span is the current span, the attempt span's parent is picked up automatically.

Harden the rules into a linter and catch a dump that breaks them

Create /root/tp-retry/retry_lint.py. When run as python3 retry_lint.py <덤프경로> (the placeholder is the dump path), it prints one line <규칙이름><탭><스팬아이디> (the placeholders are the rule name, a tab, and the span id) for each place that breaks a rule and ends with exit code 1, and if nothing breaks it prints one line ok<탭><루트 스팬 수> (the placeholders are a tab and the number of root spans) and ends with 0. There are exactly four rule names — root-status (the last attempt is not a failure but the wrapping span is ERROR), retry-count (the wrapping span's retry.count differs from the number of children), attempt-error-type (an attempt span that is ERROR has no error.type), and idem-key (an attempt span's idempotency.key differs from the wrapping span's). Run the linter you built on /root/tp-retry/06-attrs.jsonl to see that it passes, and save the output of running it on /opt/app/tracelab/tp_retry/broken.jsonl in /root/tp-retry/08-lint.txt.

The linter does not need otel — you can read the JSONL with only the standard library, so write it to run under the system python3. A child span is a line whose parent_id is the parent's span_id. The last attempt is the child with the largest start_ns. The grader runs your linter on other dumps too, so you must not judge by file name or by particular ids.