search

DalekIRC / Dalek-Services

IRC Services with WordPress integration. Have everything your way!
GNU General Public License v3.0
12 stars 6 forks source link

Client sending CAP END between receiving 900 and 903 may cause temporary auth failure #36

Closed progval closed 2 years ago

progval commented 2 years ago

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 8868473ad1ee03c56aac1e6a7f85ed11b8cb2ef7

ValwareIRC commented 2 years ago

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 2 years ago

heh, I can't reproduce it anymore