high number of route=undefined in logs for rate-limited requests

[ire-and-curses]

From Tom LS:

We are getting a high number (95%) of route=undefined for rate limited requests even though the path field is defined correctly in the same request.

To demonstrate this I am using requests to
https://horizon.stellar.org/accounts/GCCUFCDJ5WL6JQEXGJONFZOT5RXDQLMMLCXP3JYKCRW4VFRJ2MQP7J37/transactions?cursor=now

This request for that route was rate limited and logged

route=/accounts/{account_id}/transactions
and
path=/accounts/GCCUFCDJ5WL6JQEXGJONFZOT5RXDQLMMLCXP3JYKCRW4VFRJ2MQP7J37/transactions?cursor=now

correctly but this request was rate limited and logged route=undefined with

path=/accounts/GCCUFCDJ5WL6JQEXGJONFZOT5RXDQLMMLCXP3JYKCRW4VFRJ2MQP7J37/transactions?cursor=now

From what I can tell both of these requests appear to be identical, they hit the same instance horizon-blue-004c and got the same response (429) yet they log differently.

Although we still get some route=undefined for non rate limited requests (6%) it is a much more significant for rate limited requests (95%).
Am I missing something obvious?

Links to logging data here (slack).

[bartekn]

I spent some time debugging this today. There are two issues.

First issue, known before, is undefined value of route param for rate limited requests. I checked the chi code once again and the problem is that ctx is updated with route just before the final handler is executed (for the record it's happening in FindRoute). I think it should be possible to fix but it requires some changes in Horizon's httpx package. Question is: how important this data is @brahman81?

Second issue: route value actually set for some rate limited requests. It's happening only for streaming requests and the reason is that we also execute rate limiting checks in streaming handler itself (so the final handler), not only the middlewares. So in cases when streaming starts but is rate limited (and headers were not sent yet) the route value is set to the correct route (this is really connected to #2852).. We can easily change this to undefined if needed.

[brahman81]

@bartekn I think it's important for us to get an accurate understanding of our per route rate limited requests, how much work / how complex would modifying the httpx package be ?

[bartekn]

@brahman81 luckily I found a hack workaround that solved the issue: #3658.