1085150 - Handle NickServ "You are already identified" messages on nick change

Status: RESOLVED FIXED

(Chat Core :: IRC, defect)

Description

[aleth [:aleth]]

Since the moznet move, I'm seeing "You are already identified" Nickserv messages when
1) Connect and identify with NICK
2) Get disconnected and reconnect, nick is now NICK1
3) /nick NICK leads to the Nickserv message.
We don't need to show this message.

Comment 1

[aleth [:aleth]]

Relevant part of the debug log

[20/10/2014 13:50:28] LOG   (@ prpl-irc: Socket.sendString resource:///modules/socket.jsm:255)
Sending:
NICK aleth
...
[20/10/2014 13:50:29] LOG   (@ prpl-irc: Socket.sendString resource:///modules/socket.jsm:255)
Sending:
IDENTIFY <password not logged>
...
[20/10/2014 13:50:29] DEBUG (@ prpl-irc: ircSocket.prototype.onDataReceived resource://gre/components/irc.js:687)
{"rawMessage":":fripp.mozilla.org 421 aleth IDENTIFY :Unknown command","command":"421","params":["aleth","IDENTIFY","Unknown command"],"servername":"fripp.mozilla.org"}
[20/10/2014 13:50:29] LOG   (@ prpl-irc: Socket.sendString resource:///modules/socket.jsm:255)
Sending:
NICKSERV IDENTIFY <password not logged>
...
[20/10/2014 13:50:29] DEBUG (@ prpl-irc: ircSocket.prototype.onDataReceived resource://gre/components/irc.js:687)
{"rawMessage":":fripp.mozilla.org 900 aleth aleth!Instantbird@moz aleth :You are now logged in as aleth"
[20/10/2014 13:50:29] LOG   (@ prpl-irc: ircSASL.commands[900] resource://gre/modules/ircSASL.jsm:46)
SASL authentication successful.
[20/10/2014 13:50:29] LOG   (@ prpl-irc: Socket.sendString resource:///modules/socket.jsm:255)
Sending:
CAP END
...
[20/10/2014 13:50:29] DEBUG (@ prpl-irc: ircSocket.prototype.onDataReceived resource://gre/components/irc.js:687)
{"rawMessage":":NickServ![e-mail] MODE aleth +r","command":"MODE","params":["aleth","+r"],"nickname":"NickServ","user":"services","host":"ircservices.mozilla.org","source":"[e-mail]"}
[20/10/2014 13:50:29] DEBUG (@ prpl-irc: ircSocket.prototype.onDataReceived resource://gre/components/irc.js:687)
{"rawMessage":":NickServ![e-mail] NOTICE aleth :You are already identified.","command":"NOTICE","params":["aleth","You are already identified."],"nickname":"NickServ","user":"services","host":"ircservices.mozilla.org","source":"[e-mail]"}

Clearly we are receiving the NOTICE after isAuthenticated=true, so the current code doesn't swallow the message.

Comment 2

[aleth [:aleth]]

Attachment: identified.diff

I think on balance we can live without showing this message in the rare cases where a user reidentifies manually.

Comment 3

[aleth [:aleth]]

An alternative would be to show this message if the server tab pref is set, on the assumption that users that reidentify by hand are the kind of users that like server tabs ;)

Comment 4

[Patrick Cloke [:clokep]]

It sounds more likely to me that we should be flipping the isAuthenticated flag, are you sure we're keeping track of that state properly (when disconnected)? I'm not sure I fully understand the steps you listed above, is nick1 also in your group such that authentication happens appropriately?

Comment 5

[aleth [:aleth]]

If I'm not mistaken, what's happening is that the message from Nickserv is in response to NICKSERV IDENTIFY, which is handled after the SASL auth has succeeded.

Comment 6

[Patrick Cloke [:clokep]]

But we shouldn't even be sending NICKSERV IDENTIFY if SASL succeeds. There's a bug somewhere in here that I think this patch is just papering over.

Comment 7

[aleth [:aleth]]

We send NICKSERV IDENTIFY when IDENTIFY fails (http://dxr.mozilla.org/comm-central/source/chat/protocols/irc/ircServices.jsm#105). As you can see from the debug log, this can happen before SASL succeeds. I'm not sure what we could do to improve this race condition other than maybe wait with the IDENTIFY stuff until CAP END? But there was probably a reason we didn't do that, though I can't remember what it might have been.

Comment 8

[Patrick Cloke [:clokep]]

There should not be any race condition here. We should not be sending IDENTIFY before SASL is complete (i.e. not before CAP END is sent). If this is happening, there's something else wrong. Can you attach a full log?

Comment 9

[aleth [:aleth]]

You're right, looking more closely at the code, there's something very odd about this. Thanks for asking questions ;)

Comment 10

[Patrick Cloke [:clokep]]

Comment on attachment 8507879 [details] [diff] [review]
identified.diff

r- per the rest of our conversation on this bug.

Comment 11

[aleth [:aleth]]

Finally managed to see what is happening in this case. What happens is
1) connect with nick A, send SASL AUTH for nick A
2) nick A is already taken, so use nick A1
3) SASL auth succeeds anyway, for nick A ("You are now logged in as A"). We receive 900 and 903 and send CAP END
4) Later, after A goes offline, /nick A
5) This makes us send IDENTIFY and later NICKSERV IDENTIFY (but not SASL AUTHENTICATE)
6) Receive 900 and 903 again ("You are now logged in as A")
7) send CAP END in response (an obvious bug - the current code doesn't expect to receive 900/903 after CAP is over on connect)
8) NOTICE from Nickserv: "You are already identified"

Not sure at this point how much of this is according to spec, an inspircd bug, or our bug.

Comment 12

[Patrick Cloke [:clokep]]

(In reply to aleth [:aleth] from comment #11)
> Finally managed to see what is happening in this case. What happens is
> 1) connect with nick A, send SASL AUTH for nick A
> 2) nick A is already taken, so use nick A1
> 3) SASL auth succeeds anyway, for nick A ("You are now logged in as A"). We
> receive 900 and 903 and send CAP END
> 4) Later, after A goes offline, /nick A
> 5) This makes us send IDENTIFY and later NICKSERV IDENTIFY (but not SASL
> AUTHENTICATE)
We should *not* send these if we're already identified! Sounds like my assumption in [1] doesn't make sense. (Honestly I'm not sure why I said we should re-authenticate...that doesn't really make sense, IMO.) isAuthenticated should know whether we have successfully authenticated or not, I think.

> 6) Receive 900 and 903 again ("You are now logged in as A")
This seems expected from [2].

> 7) send CAP END in response (an obvious bug - the current code doesn't
> expect to receive 900/903 after CAP is over on connect)
We should throw an exception if any of the CAP methods are called after connection is done. [3] (We should also log if there are unfinished CAP messages during connection.)

> 8) NOTICE from Nickserv: "You are already identified"
I think this is just a result of us doing the above.

I think we should do one of two things:
1. Not try to reauthenticate.
2. Try to reauthenticate, but track that somehow and eat the message "You are already identified."

[1] http://mxr.mozilla.org/comm-central/source/chat/protocols/irc/ircServices.jsm#87
[2] https://github.com/ircv3/ircv3-specifications/blob/master/extensions/sasl-3.1#L119
[3] http://mxr.mozilla.org/comm-central/source/chat/protocols/irc/irc.js#1433
[4]

Comment 13

[aleth [:aleth]]

Attachment: reauthfix.diff

(In reply to Patrick Cloke [:clokep] from comment #12)
> We should *not* send these if we're already identified! Sounds like my
> assumption in [1] doesn't make sense. (Honestly I'm not sure why I said we
> should re-authenticate...that doesn't really make sense, IMO.)

I agree, and that removes a lot of the confusion for me :)

The point is that you can be identified for a nick that is not your current nick, and if you *are* currently identified you shouldn't try to identify for a different nick. I guess we could try to automate regaining an identified nick even further by sending Nickserv RECOVER (formerly known as ghosting).

> > 7) send CAP END in response (an obvious bug - the current code doesn't
> > expect to receive 900/903 after CAP is over on connect)
> We should throw an exception if any of the CAP methods are called after
> connection is done. [3] (We should also log if there are unfinished CAP
> messages during connection.)

Yes indeed.

> > 8) NOTICE from Nickserv: "You are already identified"
> I think this is just a result of us doing the above.

Right, it is caused by IDENTIFY when we are already identified.

Comment 14

[Patrick Cloke [:clokep]]

Comment on attachment 8518867 [details] [diff] [review]
reauthfix.diff

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

Looks like a lot of good improvements! Thanks for taking a look at this.

::: chat/protocols/irc/irc.js
@@ +826,5 @@
>    // For more information, see where these are defined in the prototype below.
>    this.trackQueue = [];
>    this.pendingIsOnQueue = [];
>    this.whoisInformation = new NormalizedMap(this.normalizeNick.bind(this));
> +  this._caps = new Set();

We likely want this to be reset for each connection. (Actually...I wonder how many of the other variables in here are also reset as they should be.)

::: chat/protocols/irc/ircBase.jsm
@@ +380,5 @@
>  
> +      // If we didn't handle all the CAPs we added, something is wrong.
> +      if (this._caps.size) {
> +        this.ERROR("Connected without removing CAPs: " + [...this._caps]);
> +        this._caps = new Set();

Why resetting this here?

::: chat/protocols/irc/ircSASL.jsm
@@ +42,5 @@
>  
>      "900": function(aMessage) {
>        // Now logged in.
>        this.isAuthenticated = true;
>        this.LOG("SASL authentication successful.");

We should likely change this log message.

::: chat/protocols/irc/ircServices.jsm
@@ +84,5 @@
>        if (this.normalize(newNick) != this.normalize(this._accountNickname))
>          return false;
>  
> +      if (!this.isAuthenticated)
> +        ircServices.sendIdentify(this);

Can we have some sort of comment explaining what's going on here?

Comment 15

[aleth [:aleth]]

(In reply to Patrick Cloke [:clokep] from comment #14)
> > +  this._caps = new Set();
> 
> We likely want this to be reset for each connection. (Actually...I wonder
> how many of the other variables in here are also reset as they should be.)

That's already done...

 > +      if (this._caps.size) {
> > +        this.ERROR("Connected without removing CAPs: " + [...this._caps]);
> > +        this._caps = new Set();
> 
> Why resetting this here?

...here! ;)

Comment 16

[Patrick Cloke [:clokep]]

(In reply to aleth [:aleth] from comment #15)
> (In reply to Patrick Cloke [:clokep] from comment #14)
>  > +      if (this._caps.size) {
> > > +        this.ERROR("Connected without removing CAPs: " + [...this._caps]);
> > > +        this._caps = new Set();
> > 
> > Why resetting this here?
> 
> ...here! ;)

What if we don't successfully connect? The CAPs from last time could still be there then. I guess I think it's weird to reset this on successful connection instead of when starting a connection / cleaning up from a connection.

Comment 17

[aleth [:aleth]]

Attachment: reauthfix.diff v2

Nits fixed

Comment 18

[aleth [:aleth]]

https://hg.mozilla.org/comm-central/rev/365a742e3a4d