The retry succeeded and the first attempt also landed

# Self-authored for the EML case corpus (no external origin). A client times
# out at two seconds and retries. The server is slower than that for a small
# share of requests, and it finishes them. What each party records is computed
# below.
#
# The retry is correct and it is why the client-visible error rate is zero. A
# request that has not answered in two seconds is, from the caller's side,
# indistinguishable from one that never will, and waiting longer converts a
# recoverable blip into a user-visible failure. The timeout was set from a
# measured latency distribution and the retry count is one, not five.
#
# A timeout tells the caller that no answer arrived. It does not tell the
# caller whether the work happened. Those are different facts and only one of
# them crosses the wire.
#
# So the first attempt completes, the retry completes, and every party's own
# numbers are correct. The defect is not in either party's record; it is that
# nobody holds both.

1200000 => requests_per_day
2000 => client_timeout_ms
31 => slower_than_timeout_per_thousand
1 => retries_per_timeout

int(requests_per_day * slower_than_timeout_per_thousand / 1000) => timed_out
timed_out * retries_per_timeout => retries_sent

"requests per day            : " + str(requests_per_day) ^0
"client timeout              : " + str(client_timeout_ms) + " ms" ^0
"slower than the timeout     : " + str(slower_than_timeout_per_thousand) + " per thousand" ^0
"requests that timed out     : " + str(timed_out) ^0
"retries sent                : " + str(retries_sent) ^0
"" ^0

# ---- what each side records ----

timed_out + retries_sent => attempts_for_those_requests
timed_out => duplicate_effects

"the client's record" ^0
"  requests issued        : " + str(requests_per_day) ^0
"  errors returned to user: 0" ^0
"  success rate           : 100 percent" ^0
"  retries, all successful: " + str(retries_sent) ^0
"" ^0
"the server's record" ^0
"  attempts received for those requests : " + str(attempts_for_those_requests) ^0
"  attempts that failed                 : 0" ^0
"  success rate                         : 100 percent" ^0
"" ^0
"the ledger" ^0
"  intended effects : " + str(timed_out) ^0
"  recorded effects : " + str(attempts_for_those_requests) ^0
"  duplicates       : " + str(duplicate_effects) ^0
"" ^0
"  both parties report 100 percent and neither is wrong" ^0
"" ^0

# ---- the timeline of one request ----

2400 => this_request_ms

"one request, in milliseconds" ^0
"  0     client sends" ^0
"  " + str(client_timeout_ms) + "  client gives up, records a timeout" ^0
"  " + str(client_timeout_ms) + "  client sends the retry" ^0
"  " + str(this_request_ms) + "  first attempt COMMITS" ^0
"  " + str(this_request_ms + 900) + "  retry COMMITS" ^0
"" ^0
"  the client saw one failure and one success" ^0
"  the server saw two successes" ^0
"  the account was debited " + str(1 + retries_per_timeout) + " times" ^0
"" ^0

# ---- where the timeout sits relative to the work ----

"what the two-second mark separates" ^0
"  answers that arrived in time  : left of the line" ^0
"  answers that arrived late     : right of the line" ^0
"  work that did not happen      : right of the line" ^0
"  work that did happen          : right of the line" ^0
"" ^0
"  the last two are the same side, and the status code is the same" ^0
"" ^0

# ---- the cost, at the same rate, over a month ----

"day    timed out   duplicates   cumulative" ^0
0 => cumulative
for d in [1:5]:
    cumulative + duplicate_effects => cumulative
    "  " + str(d) + "      " + str(timed_out) + "        " + str(duplicate_effects) + "        " + str(cumulative) ^0
"" ^0
"  nothing in that table is an error condition anywhere" ^0
"" ^0

# ---- the control ----
#
# The retry policy, against what it was chosen to do. Without it those
# requests are user-visible failures; with it they are not, and it does not
# amplify - one retry, not a cascade.

"control - is the retry doing its job" ^0
"  user-visible failures without it : " + str(timed_out) ^0
"  user-visible failures with it    : 0" ^0
"  retry storms                     : 0, the count is " + str(retries_per_timeout) ^0
"  defects in the retry policy      : 0" ^0
"" ^0
"  removing the retry removes the duplicates and returns " + str(timed_out) ^0
"  failures to users, which is a worse trade, not a better one" ^0
"" ^0

# ---- the null control ----
#
# The same timeout, the same retry, the same slow tail, on a read. Every one of
# the duplicates still happens and none of them costs anything, because the
# second execution of a read leaves the same world behind as the first.

"null control - the identical retry on an idempotent call" ^0
"  requests that timed out : " + str(timed_out) ^0
"  retries sent            : " + str(retries_sent) ^0
"  duplicate executions    : " + str(duplicate_effects) ^0
"  duplicate EFFECTS       : 0" ^0
"  the retry did not change; what it was retrying did" ^0
"" ^0

# ---- the rule ----

"what a timeout is evidence of" ^0
"  no answer arrived within the window : yes, that is measured" ^0
"  the work did not run                : not measured, not implied" ^0
"  the work will not run               : not measured, not implied" ^0
"  and the caller must decide using only the first" ^0
"" ^0
"the fix is not a longer timeout, which moves the line without" ^0
"removing it; it is a key the second attempt can present so the" ^0
"server can recognise it as the same intent" ^0
"" ^0

"The timeout is correctly set and the retry is why " + str(timed_out) + " users saw a" ^0
"success instead of an error. Both parties report a 100 percent success rate" ^0
"and both are telling the truth: the client counts " + str(requests_per_day) + " requests with 0" ^0
"errors, the server counts " + str(attempts_for_those_requests) + " attempts with 0 failures, and the " + str(duplicate_effects) ^0
"duplicate effects appear in neither record because neither party holds both." ^0

requests_per_day = 1200000
client_timeout_ms = 2000
slower_than_timeout_per_thousand = 31
retries_per_timeout = 1
timed_out = int(requests_per_day * slower_than_timeout_per_thousand / 1000)
retries_sent = timed_out * retries_per_timeout
print("requests per day            : " + str(requests_per_day))
print("client timeout              : " + str(client_timeout_ms) + " ms")
print("slower than the timeout     : " + str(slower_than_timeout_per_thousand) + " per thousand")
print("requests that timed out     : " + str(timed_out))
print("retries sent                : " + str(retries_sent))
print("")
attempts_for_those_requests = timed_out + retries_sent
duplicate_effects = timed_out
print("the client's record")
print("  requests issued        : " + str(requests_per_day))
print("  errors returned to user: 0")
print("  success rate           : 100 percent")
print("  retries, all successful: " + str(retries_sent))
print("")
print("the server's record")
print("  attempts received for those requests : " + str(attempts_for_those_requests))
print("  attempts that failed                 : 0")
print("  success rate                         : 100 percent")
print("")
print("the ledger")
print("  intended effects : " + str(timed_out))
print("  recorded effects : " + str(attempts_for_those_requests))
print("  duplicates       : " + str(duplicate_effects))
print("")
print("  both parties report 100 percent and neither is wrong")
print("")
this_request_ms = 2400
print("one request, in milliseconds")
print("  0     client sends")
print("  " + str(client_timeout_ms) + "  client gives up, records a timeout")
print("  " + str(client_timeout_ms) + "  client sends the retry")
print("  " + str(this_request_ms) + "  first attempt COMMITS")
print("  " + str(this_request_ms + 900) + "  retry COMMITS")
print("")
print("  the client saw one failure and one success")
print("  the server saw two successes")
print("  the account was debited " + str(1 + retries_per_timeout) + " times")
print("")
print("what the two-second mark separates")
print("  answers that arrived in time  : left of the line")
print("  answers that arrived late     : right of the line")
print("  work that did not happen      : right of the line")
print("  work that did happen          : right of the line")
print("")
print("  the last two are the same side, and the status code is the same")
print("")
print("day    timed out   duplicates   cumulative")
cumulative = 0
for d in range(1, 6):
    cumulative = cumulative + duplicate_effects
    print("  " + str(d) + "      " + str(timed_out) + "        " + str(duplicate_effects) + "        " + str(cumulative))
print("")
print("  nothing in that table is an error condition anywhere")
print("")
print("control - is the retry doing its job")
print("  user-visible failures without it : " + str(timed_out))
print("  user-visible failures with it    : 0")
print("  retry storms                     : 0, the count is " + str(retries_per_timeout))
print("  defects in the retry policy      : 0")
print("")
print("  removing the retry removes the duplicates and returns " + str(timed_out))
print("  failures to users, which is a worse trade, not a better one")
print("")
print("null control - the identical retry on an idempotent call")
print("  requests that timed out : " + str(timed_out))
print("  retries sent            : " + str(retries_sent))
print("  duplicate executions    : " + str(duplicate_effects))
print("  duplicate EFFECTS       : 0")
print("  the retry did not change; what it was retrying did")
print("")
print("what a timeout is evidence of")
print("  no answer arrived within the window : yes, that is measured")
print("  the work did not run                : not measured, not implied")
print("  the work will not run               : not measured, not implied")
print("  and the caller must decide using only the first")
print("")
print("the fix is not a longer timeout, which moves the line without")
print("removing it; it is a key the second attempt can present so the")
print("server can recognise it as the same intent")
print("")
print("The timeout is correctly set and the retry is why " + str(timed_out) + " users saw a")
print("success instead of an error. Both parties report a 100 percent success rate")
print("and both are telling the truth: the client counts " + str(requests_per_day) + " requests with 0")
print("errors, the server counts " + str(attempts_for_those_requests) + " attempts with 0 failures, and the " + str(duplicate_effects))
print("duplicate effects appear in neither record because neither party holds both.")

requests per day            : 1200000
client timeout              : 2000 ms
slower than the timeout     : 31 per thousand
requests that timed out     : 37200
retries sent                : 37200

the client's record
  requests issued        : 1200000
  errors returned to user: 0
  success rate           : 100 percent
  retries, all successful: 37200

the server's record
  attempts received for those requests : 74400
  attempts that failed                 : 0
  success rate                         : 100 percent

the ledger
  intended effects : 37200
  recorded effects : 74400
  duplicates       : 37200

  both parties report 100 percent and neither is wrong

one request, in milliseconds
  0     client sends
  2000  client gives up, records a timeout
  2000  client sends the retry
  2400  first attempt COMMITS
  3300  retry COMMITS

  the client saw one failure and one success
  the server saw two successes
  the account was debited 2 times

what the two-second mark separates
  answers that arrived in time  : left of the line
  answers that arrived late     : right of the line
  work that did not happen      : right of the line
  work that did happen          : right of the line

  the last two are the same side, and the status code is the same

day    timed out   duplicates   cumulative
  1      37200        37200        37200
  2      37200        37200        74400
  3      37200        37200        111600
  4      37200        37200        148800
  5      37200        37200        186000

  nothing in that table is an error condition anywhere

control - is the retry doing its job
  user-visible failures without it : 37200
  user-visible failures with it    : 0
  retry storms                     : 0, the count is 1
  defects in the retry policy      : 0

  removing the retry removes the duplicates and returns 37200
  failures to users, which is a worse trade, not a better one

null control - the identical retry on an idempotent call
  requests that timed out : 37200
  retries sent            : 37200
  duplicate executions    : 37200
  duplicate EFFECTS       : 0
  the retry did not change; what it was retrying did

what a timeout is evidence of
  no answer arrived within the window : yes, that is measured
  the work did not run                : not measured, not implied
  the work will not run               : not measured, not implied
  and the caller must decide using only the first

the fix is not a longer timeout, which moves the line without
removing it; it is a key the second attempt can present so the
server can recognise it as the same intent

The timeout is correctly set and the retry is why 37200 users saw a
success instead of an error. Both parties report a 100 percent success rate
and both are telling the truth: the client counts 1200000 requests with 0
errors, the server counts 74400 attempts with 0 failures, and the 37200
duplicate effects appear in neither record because neither party holds both.

Trace event types