1108540 - Avoid triggering fakelags on connection

Status: VERIFIED FIXED

(Chat Core :: IRC, defect)

Description

[aleth [:aleth]]

Some servers (e.g. inspircd) have a fakelag system which assigns a command penalty value to each user. Each command and certain actions carry a penalty. If the user's command penalty crosses a configurable threshold, further commands aren't handled until the passing of time has reduced the command penalty sufficiently.

Most commands carry a penalty value of 1 and the default threshold is 10. The command penalty decays by 1 every second (by default).

Among the commands we send on connection, the JOIN command is notable in that it carries a penalty of 2. Therefore a user with many autojoined channels will rapidly accrue a noticeable command penalty.

Comment 1

[aleth [:aleth]]

Attachment: fakelag.diff WIP

This WIP should fix the problem, please test!

Comment 2

[aleth [:aleth]]

Todo: we need to throttle WHOIS requests as that carries a penalty of 2 as well, and we send one for every contact that is away when receiving their status.

Comment 3

[aleth [:aleth]]

Attachment: fakelag.diff

Comment 4

[Patrick Cloke [:clokep]]

Comment on attachment 8534527 [details] [diff] [review]
fakelag.diff

Review of attachment 8534527 [details] [diff] [review]:
-----------------------------------------------------------------

I think that overall this approach will work, but that it needs more comments, tests, and maybe a bit of refactoring. But I'm having trouble deciding what to ask changed to make it clearer. Part of it is the nested functions seem a bit confusing (and I don't think much is gained by them).

::: chat/protocols/irc/irc.js
@@ +998,5 @@
>      delete this._pendingList;
>    },
>  
> +  _lastCommandSendTime: 0,
> +  _commandBuffers: new Map(),

Please add a comment describing what these fields are and contain.

@@ +1009,5 @@
> +    // by the prpl on connection (e.g. WHOIS sent in response to incoming
> +    // WATCH results).
> +    let delay = 1000 - (Date.now() - this._lastCommandSendTime);
> +    if (delay > 0) {
> +      setTimeout(() => this._handleCommandBuffer(aCommand), delay);

Why the setTimeout here and the executeSoon earlier? Why are both not setTimeouts?

@@ +1014,5 @@
> +      return;
> +    }
> +    this._lastCommandSendTime = Date.now();
> +
> +    let getParams = (aItems) => {

Can you add a description of what this is actually doing? It looks to me like it's joining all channels with ",", then joining all keys with ",", then putting those two into an array. Are we positive this works if you give blank keys?

@@ +1060,5 @@
> +  _sendBufferedCommand: function(aCommand, aParam, aKey = "") {
> +    if (!this._commandBuffers.has(aCommand))
> +      this._commandBuffers.set(aCommand, new Map());
> +    let buffer = this._commandBuffers.get(aCommand);
> +    if (!buffer.size)

Maybe I'm just tired, but can you add a comment above this saying what this check is doing. I really thought the ! was erroneous when first looking at it.

Comment 5

[aleth [:aleth]]

Attachment: fakelag.diff v2

(In reply to Patrick Cloke [:clokep] from comment #4)

I've added some more comments. I'll add tests when this is r+.

> Part of it is the nested
> functions seem a bit confusing (and I don't think much is gained by them).

I disagree, apart from removing duplication they make the loop in handleCommandBuffer very easy to read. What's wrong with encapsulating stuff in functions? ;)
 
> Why the setTimeout here and the executeSoon earlier? Why are both not
> setTimeouts?

The main purpose of the setTimeout isn't to throttle the rate at which we send these commands, though it helps a bit with that too. It's there to ensure that if we send a number of these commands in response to incoming messages, they still get gathered together. E.g. during connection, each incoming WATCH response for a contact that is AWAY triggers a WHOIS, but that's not all on the same tick of the event loop.

> Are we positive this works if you give
> blank keys?

Sure.

Comment 6

[aleth [:aleth]]

Attachment: Tests!

Comment 7

[aleth [:aleth]]

Attachment: fakelag.diff v3

Comment 8

[Patrick Cloke [:clokep]]

Comment on attachment 8536120 [details] [diff] [review]
fakelag.diff v3

Review of attachment 8536120 [details] [diff] [review]:
-----------------------------------------------------------------

I don't have time to do a full review right now, but do you think this would simplify sendIsOn at all? https://mxr.mozilla.org/comm-central/source/chat/protocols/irc/irc.js#1358 (That also does a neat thing where it builds the "best possible" messages to send. ;))

Comment 9

[aleth [:aleth]]

(In reply to Patrick Cloke [:clokep] from comment #8)
> I don't have time to do a full review right now, but do you think this would
> simplify sendIsOn at all?
> https://mxr.mozilla.org/comm-central/source/chat/protocols/irc/irc.js#1358
> (That also does a neat thing where it builds the "best possible" messages to
> send. ;))

It's similar, but not enough to gain from being brought under one hat I think. ISON is sent once a minute, and the goal is to endlessly cycle the nicks that are sent. sendCommandBuffer is more opportunistic, and its goal is to send as few commands as possible but as soon as possible. One could use sendCommandBuffer to actually send the ISON messages (gathering the nicks), but since the clever "best possible" selection mechanism already has to calculate the length to select the nicks that are sent in each batch, that's not really helpful.

Comment 10

[Patrick Cloke [:clokep]]

Comment on attachment 8536119 [details] [diff] [review]
Tests!

Review of attachment 8536119 [details] [diff] [review]:
-----------------------------------------------------------------

Overall this looks good! There's a few changes I'd like...and I'd like to take one more look at it before giving it an r+.

::: chat/protocols/irc/test/test_sendBufferedCommand.js
@@ +14,5 @@
> +  __proto__: irc.ircAccount.prototype,
> +  maxMessageLength: 60,
> +  callbacks: [],
> +  sendMessage: function(aCommand, aParams) {
> +    (this.callbacks.shift())(aCommand,aParams);

Nit: Space after the ,.

@@ +22,5 @@
> +let account = new FakeAccount();
> +
> +function run_test() {
> +  test_parametercollect();
> +  test_maxlength();

Nit: Please camelcase these names.

@@ +28,5 @@
> +}
> +
> +function test_parametercollect() {
> +  // Individual tests, data consisting of [channel, key] pairs.
> +  let tests = [

Please add a test for any edge cases (e.g. an empty password string).

@@ +74,5 @@
> +      let delay = 0;
> +      for (let params of data) {
> +        let [channel, key] = params;
> +        delay += 200;
> +        setTimeout(() => {

I'm unsure of the ramifications of using setTimeout in a test. I don't know if there are any gotchas that we should think about. Let's ask Florian about this specifically.

@@ +75,5 @@
> +      for (let params of data) {
> +        let [channel, key] = params;
> +        delay += 200;
> +        setTimeout(() => {
> +          account.sendBufferedCommand("JOIN", channel, key); },

This is funky formatting, can you put it all on one line or move the } to a second line. I just spent 2 minutes looking for the syntax error.

@@ +87,5 @@
> +  let tests = [
> +    {
> +      data: [["applecustard"], ["pearpie"], ["strawberryfield"],
> +        ["blueberrypancake"], ["mangojuice"], ["raspberryberet"],
> +        ["pineapplesoup"], ["limejelly"], ["lemonsorbet"]],

Yum. :)

@@ +109,5 @@
> +
> +  account._lastCommandSendTime = 0;
> +  for (let test of tests) {
> +    // Destructure test to local variables so each function
> +    // generated here gets the correct value in its scope.

Nit: Wrap this at the proper column.

@@ +112,5 @@
> +    // Destructure test to local variables so each function
> +    // generated here gets the correct value in its scope.
> +    let {data, results} = test;
> +    for (let r of results) {
> +      let result = r;

Isn't this just for (let result of results)?

@@ +117,5 @@
> +      account.callbacks.push((aCommand, aParams) => {
> +        let msg = account.buildMessage(aCommand, aParams);
> +        equal(msg, result, "Test maximum message length constraint");
> +        if (result == results[results.length - 1])
> +          run_next_test();

This if-statement was pretty confusing, I was trying to figure out where results changed...please just add a quick comment "After all results are checked, run the next test." I'm a little concerned that this can cause the tests to hang if there's an error (e.g. if equal throws). Does this work?

::: chat/protocols/irc/test/xpcshell.ini
@@ +7,5 @@
>  [test_ctcpDequote.js]
>  [test_ctcpQuote.js]
>  [test_ircMessage.js]
>  [test_setMode.js]
> +[test_sendBufferedCommand.js]

send < set :)

Comment 11

[Patrick Cloke [:clokep]]

Comment on attachment 8536120 [details] [diff] [review]
fakelag.diff v3

Review of attachment 8536120 [details] [diff] [review]:
-----------------------------------------------------------------

::: chat/protocols/irc/irc.js
@@ +1059,5 @@
> +        send(items);
> +        items = [item];
> +      }
> +    }
> +    send(items);

Is it possible at this point for items to be empty?

@@ +1779,5 @@
>    _reportDisconnecting: function(aErrorReason, aErrorMessage) {
>      this.reportDisconnecting(aErrorReason, aErrorMessage);
>  
> +    // Cancel any pending buffered commands.
> +    this._commandBuffers.clear();

What if there are any setTimeouts?

Comment 12

[aleth [:aleth]]

(In reply to Patrick Cloke [:clokep] from comment #11)
> Comment on attachment 8536120 [details] [diff] [review]
> fakelag.diff v3
> 
> Review of attachment 8536120 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: chat/protocols/irc/irc.js
> @@ +1059,5 @@
> > +        send(items);
> > +        items = [item];
> > +      }
> > +    }
> > +    send(items);
> 
> Is it possible at this point for items to be empty?

No, there is always at least one item.

> @@ +1779,5 @@
> >    _reportDisconnecting: function(aErrorReason, aErrorMessage) {
> >      this.reportDisconnecting(aErrorReason, aErrorMessage);
> >  
> > +    // Cancel any pending buffered commands.
> > +    this._commandBuffers.clear();
> 
> What if there are any setTimeouts?

We don't care as the callback simply returns if the buffer is empty.

Comment 13

[aleth [:aleth]]

Attachment: buffertests.diff v2

This extra timeout stuff makes the code more messy, but the output much easier to understand if a test fails. Shame about the duplication...

Comment 14

[aleth [:aleth]]

Is the patch here r+? Probably got overlooked.

Comment 15

[Patrick Cloke [:clokep]]

No, I want to look at it again.

Comment 16

[Patrick Cloke [:clokep]]

Comment on attachment 8536120 [details] [diff] [review]
fakelag.diff v3

Review of attachment 8536120 [details] [diff] [review]:
-----------------------------------------------------------------

(In reply to aleth [:aleth] from comment #12)
> (In reply to Patrick Cloke [:clokep] from comment #11)
> > @@ +1779,5 @@
> > >    _reportDisconnecting: function(aErrorReason, aErrorMessage) {
> > >      this.reportDisconnecting(aErrorReason, aErrorMessage);
> > >  
> > > +    // Cancel any pending buffered commands.
> > > +    this._commandBuffers.clear();
> > 
> > What if there are any setTimeouts?
> 
> We don't care as the callback simply returns if the buffer is empty.

I'm concerned about _commandBuffers being nulled out or something, but it doesn't look like that can happen. Sorry for the long gap in the review, I was on vacation.

::: chat/protocols/irc/irc.js
@@ +1018,5 @@
> +    // This short delay should usually not affect commands triggered by
> +    // user action, but helps gather commands together which are sent
> +    // by the prpl on connection (e.g. WHOIS sent in response to incoming
> +    // WATCH results).
> +    let delay = 1000 - (Date.now() - this._lastCommandSendTime);

Should we make the 1000 a constant?

Comment 17

[aleth [:aleth]]

https://hg.mozilla.org/comm-central/rev/f4fc9cbd61cd
https://hg.mozilla.org/comm-central/rev/482cbc2479e7

Comment 18

[Florian Quèze [:florian]]

Just looked at the time it takes to connect my IRC account. It used to be more than a minute, now it takes about 4 seconds. Thanks! :-)