Client sending CAP END between receiving 900 and 903 may cause temporary auth failure
Closed this issue · 2 comments
progval commented
So I have this code in irctest that connects a client with SASL, and sends NICK+USER+CAP END as soon as it gets the 900 (RPL_LOGGEDIN) reply.
This works fine on my main computer, but it often fails in the GitHub CI. Here is an excerpt from a successful test:
1663177132.182 1: connects to server.
[SEND] @msgid=+5Cx7SaIkHxW+4lKW+FcKuLfJcCljxGM;time=2022-09-14T17:38:52.202Z :00AFFC916 PRIVMSG #services :chkNS (~chk@localhost) [127.0.0.1] disconnected from the network. (Quit: chkNS) (001)
Success: Created user 2.
1663177132.995 1 -> S: CAP REQ :sasl
1663177132.995 S -> 1: :My.Little.Server CAP * ACK :sasl
1663177132.996 1 -> S: AUTHENTICATE PLAIN
[RECV] :My.Little.Server SASL services.example.org 0019ULV04 H 127.0.0.1 127.0.0.1
[RECV] :My.Little.Server SASL services.example.org 0019ULV04 S PLAIN
[SEND] @msgid=ihCe8sZ28DG89j+XRum0GHyQkA4jZGVZ;time=2022-09-14T17:38:53.005Z SASL My.Little.Server 0019ULV04 C +
1663177133.006 S -> 1: AUTHENTICATE +
1663177133.006 1 -> S: AUTHENTICATE Y29vbEFjY3QAY29vbEFjY3QAc2VzYW1l
[RECV] :My.Little.Server SASL services.example.org 0019ULV04 C Y29vbEFjY3QAY29vbEFjY3QAc2VzYW1l
[SEND] @msgid=4x8EkHkuaaA3Td8ug6hksWKWlpk8HaaK;time=2022-09-14T17:38:53.023Z :00AFFC916 PRIVMSG #services :[127.0.0.1|127.0.0.1] 0019ULV04 identified using SASL for account: coolAcct (PLAIN)
[SEND] @msgid=lHgz1ZsNpSMeCd9slzqAJeR7Mo/64gJJ;time=2022-09-14T17:38:53.023Z :00A SVSLOGIN * 0019ULV04 coolAcct
[SEND] @msgid=4OfIjF6kcKr1ib0Rl5nhccG9ZZvWPuT2;time=2022-09-14T17:38:53.024Z SASL My.Little.Server 0019ULV04 D S
1663177133.064 S -> 1: :My.Little.Server 900 * *!*@127.0.0.1 coolAcct :You are now logged in as coolAcct.
1663177133.064 S -> 1: :My.Little.Server 903 * :SASL authentication successful
1663177133.064 1 -> S: NICK coolNick
1663177133.065 1 -> S: USER myusernam 0 * :My UniqueReal Name
1663177133.065 1 -> S: CAP END
1663177133.065 S -> 1: PING :33A62238
1663177133.065 1 -> S: PONG :33A62238
[info] Client connecting: coolNick (~myusernam@localhost) [127.0.0.1] [vhost: Clk-4D552FD5] [class: clients] [account: coolAcct] [reputation: 0] [security-groups: known-users,tls-and-known-users]
[RECV] :001 REPUTATION 127.0.0.1 0
[RECV] :001 UID coolNick 0 1663177132 ~myusernam localhost 0019ULV04 coolAcct +ix * Clk-4D552FD5 fwAAAQ== :My UniqueReal Name
[SEND] @msgid=CSU0pZMDNQemAq5d/hJNpAgPTJjwU19J;time=2022-09-14T17:38:53.087Z :00AFFC916 PRIVMSG #services :coolNick (~myusernam@localhost) [127.0.0.1] connected to the network (001)
1663177133.108 S -> 1: :My.Little.Server 001 coolNick :Welcome to the ExampleNET IRC Network coolNick!~myusernam@localhost
1663177133.108 S -> 1: :My.Little.Server 002 coolNick :Your host is My.Little.Server, running version UnrealIRCd-6.0.3-git
1663177133.108 S -> 1: :My.Little.Server 003 coolNick :This server was created Mon Mar 28 2022 at 18:43:13 UTC
1663177133.108 S -> 1: :My.Little.Server 004 coolNick My.Little.Server UnrealIRCd-6.0.3-git diopqrstwxzBDGHIRSTWZ beIacdfhiklmnopqrstvzCDGHKLMNOPQRSTVZ
1663177133.108 S -> 1: :My.Little.Server 005 coolNick AWAYLEN=307 BOT=B CASEMAPPING=ascii CHANLIMIT=#:10 CHANMODES=beI,fkL,lH,cdimnprstzCDGKMNOPQRSTVZ CHANNELLEN=32 CHANTYPES=# CHATHISTORY=50 CLIENTTAGDENY=*,-draft/typing,-typing,-draft/reply DEAF=d ELIST=MNUCT EXCEPTS :are supported by this server
1663177133.108 S -> 1: :My.Little.Server 005 coolNick EXTBAN=~,acfjmnpqrtCGOST INVEX KICKLEN=307 KNOCK MAP MAXCHANNELS=10 MAXLIST=b:60,e:60,I:60 MAXNICKLEN=30 MINNICKLEN=0 MODES=12 MONITOR=128 NAMELEN=50 :are supported by this server
1663177133.108 S -> 1: :My.Little.Server 005 coolNick NAMESX NETWORK=ExampleNET NICKLEN=30 PREFIX=(qaohv)~&@%+ QUITLEN=307 SAFELIST SILENCE=15 STATUSMSG=~&@%+ TARGMAX=DCCALLOW:,ISON:,JOIN:,KICK:4,KILL:,LIST:,NAMES:1,NOTICE:1,PART:,PRIVMSG:4,SAJOIN:,SAPART:,TAGMSG:1,USERHOST:,USERIP:,WATCH:,WHOIS:1,WHOWAS:1 TOPICLEN=360 UHNAMES USERIP :are supported by this server
1663177133.109 S -> 1: :My.Little.Server 005 coolNick WALLCHOPS WATCH=128 WATCHOPTS=A WHOX :are supported by this server
1663177133.109 S -> 1: :My.Little.Server 396 coolNick Clk-4D552FD5 :is now your displayed host
1663177133.109 S -> 1: :My.Little.Server 251 coolNick :There are 1 users and 6 invisible on 2 servers
1663177133.109 S -> 1: :My.Little.Server 252 coolNick 6 :operator(s) online
1663177133.109 S -> 1: :My.Little.Server 254 coolNick 3 :channels formed
1663177133.109 S -> 1: :My.Little.Server 255 coolNick :I have 1 clients and 1 servers
1663177133.109 S -> 1: :My.Little.Server 265 coolNick 1 1 :Current local users 1, max 1
1663177133.109 S -> 1: :My.Little.Server 266 coolNick 7 7 :Current global users 7, max 7
1663177133.109 S -> 1: :My.Little.Server 375 coolNick :- My.Little.Server Message of the Day -
1663177133.109 S -> 1: :My.Little.Server 372 coolNick :- 14/9/2022 17:38
1663177133.109 S -> 1: :My.Little.Server 372 coolNick :-
1663177133.109 S -> 1: :My.Little.Server 376 coolNick :End of /MOTD command.
1663177133.109 S -> 1: :coolNick MODE coolNick :+ix
And here is an example of a failure on GitHub:
1663176737.810 1: connects to server.
1663176738.425 1 -> S: CAP REQ :sasl
1663176738.425 S -> 1: :My.Little.Server CAP * ACK :sasl
1663176738.425 1 -> S: AUTHENTICATE PLAIN
1663176738.433 S -> 1: AUTHENTICATE +
1663176738.433 1 -> S: AUTHENTICATE Y29vbEFjY3QAY29vbEFjY3QAc2VzYW1l
1663176738.452 S -> 1: :My.Little.Server 900 * *!*@127.0.0.1 coolAcct :You are now logged in as coolAcct.
1663176738.452 1 -> S: NICK coolNick
1663176738.452 1 -> S: USER myusernam 0 * :My UniqueReal Name
1663176738.452 1 -> S: CAP END
1663176738.452 S -> 1: PING :FCE8B74A
1663176738.452 1 -> S: PONG :FCE8B74A
1663176738.453 S -> 1: :My.Little.Server 001 coolNick :Welcome to the ExampleNET IRC Network coolNick!~myusernam@localhost
1663176738.453 S -> 1: :My.Little.Server 002 coolNick :Your host is My.Little.Server, running version UnrealIRCd-6.0.3
1663176738.453 S -> 1: :My.Little.Server 003 coolNick :This server was created Wed Sep 14 2022 at 17:20:10 UTC
1663176738.453 S -> 1: :My.Little.Server 004 coolNick My.Little.Server UnrealIRCd-6.0.3 diopqrstwxzBDGHIRSTWZ beIacdfhiklmnopqrstvzCDGHKLMNOPQRSTVZ
1663176738.453 S -> 1: :My.Little.Server 005 coolNick AWAYLEN=307 BOT=B CASEMAPPING=ascii CHANLIMIT=#:10 CHANMODES=beI,fkL,lH,cdimnprstzCDGKMNOPQRSTVZ CHANNELLEN=32 CHANTYPES=# CHATHISTORY=50 CLIENTTAGDENY=*,-draft/typing,-typing,-draft/reply DEAF=d ELIST=MNUCT EXCEPTS :are supported by this server
1663176738.453 S -> 1: :My.Little.Server 005 coolNick EXTBAN=~,acfjmnpqrtCGOST INVEX KICKLEN=307 KNOCK MAP MAXCHANNELS=10 MAXLIST=b:60,e:60,I:60 MAXNICKLEN=30 MINNICKLEN=0 MODES=12 MONITOR=128 NAMELEN=50 :are supported by this server
1663176738.453 S -> 1: :My.Little.Server 005 coolNick NAMESX NETWORK=ExampleNET NICKLEN=30 PREFIX=(qaohv)~&@%+ QUITLEN=307 SAFELIST SILENCE=15 STATUSMSG=~&@%+ TARGMAX=DCCALLOW:,ISON:,JOIN:,KICK:4,KILL:,LIST:,NAMES:1,NOTICE:1,PART:,PRIVMSG:4,SAJOIN:,SAPART:,TAGMSG:1,USERHOST:,USERIP:,WATCH:,WHOIS:1,WHOWAS:1 TOPICLEN=360 UHNAMES USERIP :are supported by this server
1663176738.453 S -> 1: :My.Little.Server 005 coolNick WALLCHOPS WATCH=128 WATCHOPTS=A WHOX :are supported by this server
1663176738.453 S -> 1: :My.Little.Server 396 coolNick Clk-4D552FD5 :is now your displayed host
1663176738.453 S -> 1: :My.Little.Server 251 coolNick :There are 1 users and 6 invisible on 2 servers
1663176738.453 S -> 1: :My.Little.Server 252 coolNick 6 :operator(s) online
1663176738.453 S -> 1: :My.Little.Server 254 coolNick 3 :channels formed
1663176738.453 S -> 1: :My.Little.Server 255 coolNick :I have 1 clients and 1 servers
1663176738.453 S -> 1: :My.Little.Server 265 coolNick 1 1 :Current local users 1, max 1
1663176738.453 S -> 1: :My.Little.Server 266 coolNick 7 7 :Current global users 7, max 7
1663176738.453 S -> 1: :My.Little.Server 375 coolNick :- My.Little.Server Message of the Day -
1663176738.453 S -> 1: :My.Little.Server 372 coolNick :- 14/9/2022 17:32
1663176738.453 S -> 1: :My.Little.Server 372 coolNick :-
1663176738.453 S -> 1: :My.Little.Server 376 coolNick :End of /MOTD command.
1663176738.453 S -> 1: :My.Little.Server 906 coolNick :SASL authentication aborted
1663176738.453 S -> 1: :coolNick MODE coolNick :+ix
1663176738.454 S -> 1: :My.Little.Server 903 coolNick :SASL authentication successful
As you can see, 906 (ERR_SASLABORTED) is sent after the MOTD; then 903 (RPL_SASLSUCCESS) is sent shortly after
Both are running on commit 8868473
ValwareIRC commented
this doesn't feel like an issue with Dalek as any information about the NICK or USER command being used isn't visible to services and I don't think there would be any difference made in the SASL flow which could cause this to be caused by Dalek
progval commented
heh, I can't reproduce it anymore