Add more placeholders to rate-limit messages, move template interpolation from Rule to Sopel

[SnoopJ]

Description

Fix #2325.

This changeset includes:

• plumbing changes in data flow about rate-limiting between Sopel and Rule
• new template fields for rate limit messages
  • unless somebody has suggestions for more fields, I'm considering this complete

---

Checklist

• I have read CONTRIBUTING.md
• I can and do license this contribution under the EFLv2
• No issues are reported by make qa (runs make quality and make test)
• I have tested the functionality of the things this change touches

[dgw]

Since I wanted to respond to the thread about public API concerns, thought I'd give the rest a quick skim too.

[Exirel]

I've been thinking a lot about rate limiting (yes, since yesterday evening when I said I went to bed, apparently that kept me awake for an hour or so...). I understand why you want to change the existing methods, yet I want to go another way: add more methods!

For instance, most of the logic is in the RuleMetrics class: once you have it, you can ask if it is limited, and it contains most of the required information to format the rule's template for rate limiting.

Consider this:

@property
def user_rate_limit(self) -> datetime.timedelta:
    return  datetime.timedelta(seconds=self._*_rate_limit)

@property
def user_rate_template(self) -> Optional[str]:
    return self._user_rate_message or self._default_rate_message

def get_user_metrics(self, nick: Identifier) -> RuleMetrics:
    return self._metrics_nick.setdefault(nick, RuleMetrics())

Then you can have something like that:

triggered_at = datetime.datetime.utcnow()
user_rate_limit = rule.user_rate_limit  
channel_rate_limit = rule.channel_rate_limit
global_rate_limit = rule.global_rate_limit
user_metrics = rule.get_user_metrics(trigger.nick)
channel_metrics = rule.get_channel_metrics(trigger.sender)
global_metrics = rule.global_metrics

metrics, template = None, None
if user_metrics.is_limited(triggered_at - user_rate_limit):
    template = rule.user_rate_template
    metrics = user_metrics
elif channel_metrics.is_limited(triggered_at - user_rate_limit):
    template = rule.channel_rate_template
    metrics = channel_metrics
elif global_metrics.is_limited(triggered_at - global_rate_limit):
    template = rule.global_rate_template
    metrics  = global_metrics

message = None
if metrics and template:
    message = template.format(...)

return RateLimitCheckInfo(limited=metrics is not None, metrics, triggered_at, message)

In the end, you still get an object that can tell you if 1. it was rate limited, 2. the data and metrics for that, and 3. the message to send if any! With some magic @property you can even prevent yourself from having to pass the limited, as it can be derived from the existence of a metrics object.

[SnoopJ]

This PR is functionally complete now, but still needs a pass for testing and general quality (docstrings etc.)

Edit: I figured out the cause of the following failures, read my later reply for more info

Additionally, using at_time = trigger.time in Sopel.rate_limit_info() (which might need a better name, can anybody think of one?) seems to break some of the tests for call_rule():

___________________________________________________________________________ test_call_rule ___________________________________________________________________________
test/test_bot.py:643: in test_call_rule
    assert mockbot.backend.message_sent == rawlist(
E   AssertionError: assert [b'PRIVMSG #channel :hi\r\n'] == [b'PRIVMSG #c...nnel :hi\r\n']
E     Right contains one more item: b'PRIVMSG #channel :hi\r\n'
E     Use -v to get more diff
__________________________________________________________ test_call_rule_rate_limited_channel_with_message __________________________________________________________
test/test_bot.py:855: in test_call_rule_rate_limited_channel_with_message
    assert mockbot.backend.message_sent == rawlist(
E   AssertionError: A NOTICE should appear here.
E   assert [b'PRIVMSG #channel :hi\r\n'] == [b'PRIVMSG #c...e limit.\r\n']
E     Right contains one more item: b'NOTICE Test :You reached the channel rate limit.\r\n'
E     Use -v to get more diff
__________________________________________________________ test_call_rule_rate_limited_global_with_message ___________________________________________________________
test/test_bot.py:963: in test_call_rule_rate_limited_global_with_message
    assert mockbot.backend.message_sent == rawlist(
E   AssertionError: A NOTICE should appear here.
E   assert [b'PRIVMSG #channel :hi\r\n'] == [b'PRIVMSG #c...e limit.\r\n']
E     Right contains one more item: b'NOTICE Test :You reached the server rate limit.\r\n'
E     Use -v to get more diff
====================================================================== short test summary info =======================================================================
FAILED test/test_bot.py::test_call_rule - AssertionError: assert [b'PRIVMSG #channel :hi\r\n'] == [b'PRIVMSG #c...nnel :hi\r\n']
FAILED test/test_bot.py::test_call_rule_rate_limited_channel_with_message - AssertionError: A NOTICE should appear here.
FAILED test/test_bot.py::test_call_rule_rate_limited_global_with_message - AssertionError: A NOTICE should appear here.
==================================================================== 3 failed, 47 passed in 2.60s ====================================================================

Looks like test_call_rule is getting rate-limited where no limit is expected, and a NOTICE is not being sent for test_call_rule_rate_limited_channel_with_message and test_call_rule_rate_limited_global_with_message.

I suspect this is caused by some implicit dependence of the tests on the passage of time between the construction of a Trigger associated with the relevant even and calling of Sopel.call_rule(). It's not a very long difference, I observe it to be O(1 ms), but something is amiss there.

[dgw]

Haven't poked at all of the failing-with-at_time = trigger.time tests, but I threw pdb into Sopel.rate_limit_info() and tried out test_call_rule_rate_limited_channel_with_message:

test/test_bot.py::test_call_rule_rate_limited_channel_with_message
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>> PDB set_trace (IO-capturing turned off) >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
> /home/dgw/github/sopel/sopel/bot.py(597)rate_limit_info()
-> if trigger.admin or rule.is_unblockable():
(Pdb) c

>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>> PDB continue (IO-capturing resumed) >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>

>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>> PDB set_trace (IO-capturing turned off) >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
> /home/dgw/github/sopel/sopel/bot.py(597)rate_limit_info()
-> if trigger.admin or rule.is_unblockable():
(Pdb) n
> /home/dgw/github/sopel/sopel/bot.py(600)rate_limit_info()
-> is_channel = trigger.sender and not trigger.sender.is_nick()
(Pdb) n
> /home/dgw/github/sopel/sopel/bot.py(601)rate_limit_info()
-> channel = trigger.sender if is_channel else None
(Pdb) n
> /home/dgw/github/sopel/sopel/bot.py(606)rate_limit_info()
-> at_time = trigger.time
(Pdb) n
> /home/dgw/github/sopel/sopel/bot.py(608)rate_limit_info()
-> user_metrics = rule.get_user_metrics(trigger.nick)
(Pdb) print(at_time)
2023-03-27 07:51:05.409947+00:00
(Pdb) print(rule.channel_rate_limit)
0:01:40
(Pdb) n
> /home/dgw/github/sopel/sopel/bot.py(609)rate_limit_info()
-> channel_metrics = rule.get_channel_metrics(channel)
(Pdb) n
> /home/dgw/github/sopel/sopel/bot.py(610)rate_limit_info()
-> global_metrics = rule.get_global_metrics()
(Pdb) n
> /home/dgw/github/sopel/sopel/bot.py(612)rate_limit_info()
-> if user_metrics.is_limited(at_time - rule.user_rate_limit):
(Pdb) n
> /home/dgw/github/sopel/sopel/bot.py(613)rate_limit_info()
-> template = rule.user_rate_template
(Pdb) print(user_metrics.is_limited(at_time - rule.user_rate_limit))
True
(Pdb) print(rule.user_rate_limit)
0:00:00
(Pdb) n
> /home/dgw/github/sopel/sopel/bot.py(614)rate_limit_info()
-> rate_limit_type = "user"
(Pdb) n
> /home/dgw/github/sopel/sopel/bot.py(615)rate_limit_info()
-> rate_limit = rule.user_rate_limit
(Pdb) n
> /home/dgw/github/sopel/sopel/bot.py(616)rate_limit_info()
-> metrics = user_metrics
(Pdb) n
> /home/dgw/github/sopel/sopel/bot.py(630)rate_limit_info()
-> next_time = metrics.last_time + rate_limit
(Pdb) print(rate_limit_type)
user

The user rate-limit type is being triggered somehow, not the channel type.

Same happens for the second trigger in test_call_rule_rate_limited_global—the test code enters the if user_metrics.is_limited( block even though rule.user_rate_limit in this context is a datetime.timedelta(0).

More tests than are throwing errors are failing with at_time = trigger.time; they just don't check any conditions that reveal the failure. The second message isn't sent, as expected, but the wrong rate-limit type is responsible for blocking it. Only the non-user _with_message tests reveal the problem, because there's no associated message in the (unset) user rate limit properties.

[SnoopJ]

using at_time = trigger.time in Sopel.rate_limit_info() … seems to break some of the tests for call_rule()

It turns out that these failures were caused by re-use of the triggers in these tests, failing to trigger the rate-limiting behavior because too much time had elapsed since the first event. Re-creating the triggers associated with the event resolves the failures.

[Exirel]

That looks better already!

A lot of nitpicking and formatting. In theory, the code works as expected, so it's not that important. The review is more about added quality than anything else.

The idea of adding a fixture to create a match for a rule and a trigger is nice. I'm not sure I would have made it that way, since I prefer when things don't have that many hard-coded text, otherwise it's cool to see the reduction in code repetition.

[Exirel]

Given the amount of commits you have, good luck with the squash that will inevitably be a nightmare. 😁

Remember that we use modules: short message format for commits, not just for PR.

[SnoopJ]

Squashed this down as best as I could, but if it needs to be squashed any further, I think I might just discard all of the working history and re-arrange from scratch. Let me know if that needs done.

[SnoopJ]

CI failure is unrelated to the contents of this PR, seems to be an issue where CI has a more recent urllib3 than what is in dev-requirements.txt causing an issue with vcrpy

AttributeError: module 'urllib3.connectionpool' has no attribute 'VerifiedHTTPSConnection'

This issue is being tracked upstream but probably we want to add a pin for urllib3.

(oops, I fat-fingered while typing this comment and accidentally closed this PR…)

[SnoopJ]

Squashed this down as best as I could, but if it needs to be squashed any further, I think I might just discard all of the working history and re-arrange from scratch. Let me know if that needs done.

Can I get a yes/no on the current squash of this PR? 12 commits still feels like a lot, but squashing to a single commit also feels excessive.

[Exirel]

LGTM. Reading the list of commits, each has a purpose that is clear and separate from other commits. Sure, we can see the progress "add this one, then this one, also fix that, change this, add another one", etc. and personally, I don't mind / I like it this way.

Note that I don't mind either if you prefer to squash down to 2 or 3 commits (one for code, one for doc), I think both version of the history are acceptable. Maybe dgw has a stronger opinion, but from my perspective, LGTM!

[dgw]

I don't mind the current history either, really. I tend to commit related code, docs, & tests all at once if I'm building an ideal history as I go, but doing that in a rebase can be error-prone so it's fine if you'd rather not go there. 😸

[dgw]

Doc nitpicks, what would my self-identity be without them?