Fix incorrect juggling of logging contexts in _PerHostRatelimiter

[squahtx]

Introduced in #13499.
Likely to be the cause of most of the errors seen in #13552.

Signed-off-by: Sean Quah [email protected]

[richvdh]

lgtm either way

[richvdh]

finding this slightly hard to wrap my head around. Rather than passing in a deferred, I would pass in the request id and have it call _on_enter. And do some renaming of things.

[richvdh]

lgtm

[MadLittleMods]

Is there discussion somewhere about how this fixes the log context? Trying to learn and understand.

[richvdh]

@MadLittleMods there was some discussion in Backend Internal (https://matrix.to/#/!SGNQGPGUwtcPBUotTL:matrix.org/$xqpsbzDjJpmqAt9xTBtpS6qAAWXrBv3N_HkjwwK2QoM?via=jki.re&via=matrix.org&via=element.io), but I don't think there's much detailed discussion.

As @squahtx said:

iirc make_deferred_yieldable stashes away the current logcontext and adds its own callback to the deferred to restore it
and each opentracing spans "wraps" its own logcontext (more or less)

In other words: make_deferred_yieldable adds a callback to the deferred, and that callback would restore the logcontext created by start_active_span once the ratelimit wait completed.

It might also be instructive to look at @squahtx's initial fix for this, which effectively just moved the call to make_deferred_yieldable to before the call to start_active_span. That was an entirely valid fix, we just decided that doing it this way felt more natural and more obviously correct.

The lesson I take here (other than that logcontexts are confusing, which we knew) is that __enter__ and __exit__ are hazardous materials and it's best to avoid messing with them directly where possible.

[squahtx]

It's a subtlety in the way spans, logging contexts and make_deferred_yieldable work.

Spans are implemented on top of logging contexts. That is, every span creates its own nested logging context (minus an optimization).

# parent span's logging context active
span = start_active_span(...)
span.__enter__(...)
# child span's logging context is now active

ret_defer.addCallbacks(on_start, on_err)
ret_defer.addBoth(on_both)  # <-- `span.__exit__` is called inside `on_both`
return make_deferred_yieldable(ret_defer)

Just before make_deferred_yieldable is called, the active logging context is the one associated with span.

make_deferred_yieldable is a little big magical. It clears the active logging context and attaches a callback to ret_defer to restore the logging context after the deferred has resolved. With the previous code, the order of callbacks on ret_defer was:

1. [no logging context yet] (on_start, on_err)
2. [no logging context yet] on_both, calling span.__exit__ and restoring the parent span's logging context.
3. [parent span's logging context] make_deferred_yieldable's callback to restore the child span's logging context.
4. [child span's logging context]

But we need 2 and 3 to be the other way around. The child logging context needs to be restored, then __exit__ed, which makes it restore the parent logging context.

[MadLittleMods]

Wow, this is subtle!

It might also be instructive to look at @squahtx's initial fix for this, which effectively just moved the call to make_deferred_yieldable to before the call to start_active_span. That was an entirely valid fix, we just decided that doing it this way felt more natural and more obviously correct.

@squahtx's initial fix is useful to look at 👍 But I think the initial fix does something a little different than this description. It moves the span.__exit__() after the make_deferred_yieldable so that make_deferred_yieldable's callback restores span's logging context. And then span.__exit__() restores the parent context. From my understanding, this also aligns with what @squahtx mentions is the subtlety.

But moving the call to make_deferred_yieldable to before the call to start_active_span sounds like it would work as well. That way the span.__exit__() would restore the nested context and then make_deferred_yieldable's callback would restore the parent logging context.

In any case, we want the parent logging context restored when we get out of everything (fold and unfold in the correct order).

---

Now in the final form of the fix, the span is entered via the with context manager so it has the outermost parent context, then make_deferred_yieldable is called which is in the span context. And because we are using the proper with nesting context manager stuff it also properly unfolds in the correct order: make_deferred_yieldable's callback restores the span context, and the span context manager exit restores the parent context.

🎉

Thanks for explaining @richvdh and @squahtx ❤️

---

The key pitfall in my change is not knowing the magic in make_deferred_yieldable:

make_deferred_yieldable is a little big magical. It clears the active logging context and attaches a callback to ret_defer to restore the logging context after the deferred has resolved

[richvdh]

You're right, sorry, my description of @squahtx's fix was incorrect.

But moving the call to make_deferred_yieldable to before the call to start_active_span sounds like it would work as well.

Actually it seems it wouldn't. We tried something equivalent in this thread and as @squahtx points out there are other problems.