View Issue Details

IDProjectCategoryView StatusLast Update
0001393unrealircdpublic2015-05-23 21:09
ReporterthiloAssigned Tosyzop 
PrioritynormalSeveritymajorReproducibilityunable to reproduce
Status resolvedResolutionfixed 
Product Version 
Target VersionFixed in Version3.4-alpha3 
Summary0001393: Duplicate users problem, ircd not sending quit correctly on logoff?
DescriptionI had watched this problem for quite some time now:
Especially when servers are rejoined after a netsplit, the ircd does not seem to correctly log off users from the network, but simply show a second client connecting. I recently discovered this problem again on an Unreal 3.2 beta18 server, the additional information features a log of the messages services had to handle.
I removed the lines that did not have to do anything with our case here. I am afraid, the screen I ran the services in did not have any more lines in the buffer, I cannot scroll up in the history.

The interesting part is, that services change the nick back using SVSNICK after issuing a kill command for the ghost, the ghost "Ping Timeouts" before the kill can be active, and then the SVSNICK works ... but after this procedure is done, services will never receive a quit or nick command from the irc server for this nick, but just a second user with the same nick comes online.
Additional Information
[Nov 26 22:31:40 2003] debug: Sent: :NickServ . DooM :Ghost command used by Sonderzeichen3.
[Nov 26 22:31:40 2003] debug: Sent: :NickServ B Sonderzeichen3 :Ghost with your nick has been killed, your nick will now be automatically changed to the ghosted nick.
[Nov 26 22:31:40 2003] debug: Sent: :NickServ SVSNICK Sonderzeichen3 DooM :1069882300
[...]
[Nov 26 22:31:40 2003] debug: Received: :DooM , :Ping timeout
[...]
Nov 26 22:31:41 2003] debug: Received: :Sonderzeichen3 & DooM 1069882435
[Nov 26 22:31:41 2003] debug: Sonderzeichen3 changed nick to DooM
[Nov 26 22:31:41 2003] debug: Sent: :NickServ n DooM +r 0
[...]
[Nov 26 22:31:44 2003] debug: Received: :DooM AA space-922D287.dip0.t-ipconnect.de
[Nov 26 22:31:44 2003] debug: Received: & DooM 2 1069882440 Sain7 p508E0230.dip0.t-ipconnect.de sunflower.de.eu.spacetronix.net 0 +ix space-922D287.dip0.t-ipconnect.de :Phoenix DooM
[Nov 26 22:31:44 2003] Duplicate user DooM already exists! This is a heavy error and should NOT happen!

Program received signal SIGINT, Interrupt.
[Switching to Thread 1024 (LWP 21383)]
0x4005a781 in kill () from /lib/libc.so.6
(gdb)

[...]

[Nov 26 22:31:44 2003] debug: Received: :DooM AA space-922D287.dip0.t-ipconnect.de
[Nov 26 22:31:44 2003] debug: Received: & DooM 2 1069882440 Sain7 p508E0230.dip0.t-ipconnect.de sunflower.de.eu.spacetronix.net 0 +ix space-922D287.dip0.t-ipconnect.de :Phoenix DooM
TagsNo tags attached.
3rd party modules

Activities

syzop

2003-11-28 19:46

administrator   ~0004152

I (or codemastr) will take a look at it soon. Looks interresting/complcated ;).

codemastr

2003-11-28 19:56

reporter   ~0004154

The interesting part is, that services change the nick back using SVSNICK after issuing a kill command for the ghost, the ghost "Ping Timeouts" before the kill can be active, and then the SVSNICK works ... but after this procedure is done, services will never receive a quit or nick command from the irc server for this nick, but just a second user with the same nick comes online.

Could you explain that in more detail? I have no idea what you are trying to say.

syzop

2003-11-28 20:01

administrator   ~0004155

*try to "visualise" it a bit, -> is sent, <- is received*
-> Kill DooM (Ghost command used)
-> SVSNICK Sonderzeichen3 -> DooM
<- Quits: Doom (Ping timeout) <=== it quited before the kill, shouldn't be a problem.
<- Nickchange: Sonderzeichen3 -> DooM <=== so the SVSNICK was processed correctly
--snip--
<- New user DooM.....

So what he says is that there was no quit msg for 'DooM' (which was previously Sonderzeichen3).
Of course I'm unable to validate that since this log was cut.

thilo

2003-11-28 21:12

reporter   ~0004157

Syzop: correct. I can assure you, that nothing indicating DooM ever quit or changed nick in the logs was cut.

thilo

2003-11-28 21:20

reporter   ~0004158

Maybe i should still mention, that all this happened in a very short amount of time of about 4 seconds, like i said, rejoined servers.

Rocko

2003-11-28 22:55

reporter   ~0004160

Last edited: 2003-11-28 22:58

I don't know if it helps, but the following is from the IRCd side:

[22:31:39] *** (s) *** Notice -- Client connecting at sunflower.de.eu.spacetronix.net: Sonderzeichen3 (Sain7@p508E0230.dip0.t-ipconnect.de)
[..]
[22:31:40] *** (s) *** Notice -- Client connecting at sunflower.de.eu.spacetronix.net: Pimp32 (~Pimp32@adsl-65-69-129-203.dsl.rcsntx.swbell.net)
[22:31:40] *** (s) *** Notice -- Client connecting at sunflower.de.eu.spacetronix.net: Waggytai (~Waggytai@82-38-129-211.cable.ubr02.hali.blueyonder.co.uk)
[22:31:40] *** (s) *** Notice -- Client exiting at sunflower.de.eu.spacetronix.net: DooM!Sain7@p508E0230.dip0.t-ipconnect.de (Ping timeout)
[22:31:40] *** (s) *** Notice -- Client connecting at sunflower.de.eu.spacetronix.net: boyke (boyke@D57647F6.kabel.telenet.be)
[22:31:40] *** (s) *** Notice -- Client connecting at sunflower.de.eu.spacetronix.net: Macaway (~you@port-212-202-204-67.reverse.qdsl-home.de)
[22:31:40] *** (s) *** Notice -- Received KILL message for DooM!Sain7@space-922D287.dip0.t-ipconnect.de from services.spacetronix.net Path: services!NickServ (Ghost command used by Sonderzeichen3)
[22:31:40] *** (s) *** Notice -- Client exiting at sunflower.de.eu.spacetronix.net: DooM!Sain7@p508E0230.dip0.t-ipconnect.de (Killed (NickServ (Ghost command used by Sonderzeichen3)))
[22:31:41] *** (s) *** Notice -- Client exiting at sunflower.de.eu.spacetronix.net: Quacks!Quacks@pD9EE3EBC.dip.t-dialin.net (Ping timeout)
[22:31:43] *** (s) *** Notice -- Client connecting on port 6667: Ender (~mbey@vulture080.csn.tu-chemnitz.de) [clients]
[22:31:43] *** (s) *** Notice -- Client connecting at sunflower.de.eu.spacetronix.net: pu (~pu@pD9537F14.dip.t-dialin.net)
[22:31:44] *** (s) *** Notice -- Client connecting at sunflower.de.eu.spacetronix.net: DooM (Sain7@p508E0230.dip0.t-ipconnect.de)

[Edit] You see, that the Ping Timeout and SVSKILL was in the same second.

bearbeitet am: 11-28-03 22:58

thilo

2003-11-29 00:22

reporter   ~0004161

hmm, judging by this, services never received the ghost-KILL message for the user.

syzop

2003-11-29 04:01

administrator   ~0004164

yeah that's ok, coz they saw the quit. But the thing is... I don't see a quit in the paste from rocko either (??).

thilo

2003-11-29 13:40

reporter   ~0004166

well:

[22:31:39] *** (s) *** Notice -- Client connecting at sunflower.de.eu.spacetronix.net: Sonderzeichen3 (Sain7@p508E0230.dip0.t-ipconnect.de)


[22:31:40] *** (s) *** Notice -- Client exiting at sunflower.de.eu.spacetronix.net: DooM!Sain7@p508E0230.dip0.t-ipconnect.de (Ping timeout)

Then some user/client must have changed his nick to DooM, because in the same second another kill message appears:

[22:31:40] *** (s) *** Notice -- Received KILL message for DooM!Sain7@space-922D287.dip0.t-ipconnect.de from services.spacetronix.net Path: services!NickServ (Ghost command used by Sonderzeichen3)
 [22:31:40] *** (s) *** Notice -- Client exiting at sunflower.de.eu.spacetronix.net: DooM!Sain7@p508E0230.dip0.t-ipconnect.de (Killed (NickServ (Ghost command used by Sonderzeichen3)))

[22:31:44] *** (s) *** Notice -- Client connecting at sunflower.de.eu.spacetronix.net: DooM (Sain7@p508E0230.dip0.t-ipconnect.de)
 

And services _only_ saw Doom's Ping timeout quit, but not the kill happening. When DooM reconnected, the problem with the double-users appeared.

syzop

2003-11-29 15:58

administrator   ~0004167

Oh I didn't notice even the double-user-connect thing was within the X seconds... That changes stuff...

looks like:
1. Services is SENDING a kill and svsnick
2. DooM ping timeout
3. user changes nick to DooM
4. Kill ARRIVED/RECEIVED for DooM (but it's the wrong DooM! ;p)
5. blabla

Or at least something like that, but... I'll look at it at some later time.

codemastr

2003-11-29 17:37

reporter   ~0004169

This seems like the kind of problem that Numeric Nickname (NN) would fix. Then you don't have to worry about kill chasing or anything like that.

stskeeps

2007-04-27 06:08

reporter   ~0013855

Bump. Still an issue i presume?

driew

2010-04-15 11:10

reporter   ~0016072

Last edited: 2010-04-15 11:27

This to me looks like a services bug really.
It's an interesting race-condition. But services shouldn't send an svsnick immediately chasing the kill, it should instead, send an svsnick after it gets the QUIT response from the server; otherwise it's assuming too much.

Basically what I see happening:
1. Services sends a kill, following an immediate svsnick
-- Lag between services and IRCD here. (This was following a netsplit, so a sync is in progress)
2. IRCD sends services a QUIT for DooM with a ping timeout
3. User /nick's to DooM, either by a WATCH or a script seeing the QUIT Ping Timeout
I say this because the NICK timestamps don't match, the returning nick from the server should match the timestamp sent in the SVSNICK (as acptr->lastnick is set to whatever SVSNICK sends, while a /nick DooM, from the client, will show the last NICK sent to the server [most likely the original client registration])
[Nov 26 22:31:40 2003] debug: Sent: :NickServ SVSNICK Sonderzeichen3 DooM :1069882300
[Nov 26 22:31:41 2003] debug: Received: :Sonderzeichen3 & DooM 1069882435

This also seems to suggest there is some sort of ts desync..

An example of what they should look like using anope, and svsnick, versus a client using /nick:
[Apr 15 04:14:56.349536 2010] OperServ: not_psadmin: svsnick killduck killduck2
[Apr 15 04:14:56.372444 2010] debug: Sent: :OperServ NOTICE not_psadmin :The nick killduck is now being changed to killduck2.
[Apr 15 04:14:56.372874 2010] debug: Sent: :OperServ GLOBOPS :not_psadmin used SVSNICK to change killduck to killduck2
[Apr 15 04:14:56.373440 2010] debug: Sent: SVSNICK killduck killduck2 :1271322896
[Apr 15 04:14:56.439565 2010] debug: Received: :killduck NICK killduck2 1271322896
[Apr 15 04:14:56.439807 2010] debug: killduck changes nick to killduck2

[Apr 15 04:17:03.811713 2010] debug: Received: NICK killduck 2 1271323022 regan gamma.client patience.server 0 +iwx PurpleSurge-C265131B.client RyfQxQ== :Real Name
[Apr 15 04:17:03.811800 2010] debug: new user: killduck
[Apr 15 04:17:07.158946 2010] debug: Received: :killduck NICK killduck2 1271323026
[Apr 15 04:17:07.159029 2010] debug: killduck changes nick to killduck2
[Apr 15 04:17:08.078925 2010] debug: Received: :killduck2 NICK killduck3 1271323027
[Apr 15 04:17:08.079012 2010] debug: killduck2 changes nick to killduck3

So looking at what was processed above:
The SVSNICK was sent for:
Wed Nov 26 21:31:40 2003

While the /nick that was actually processed was done on:
Wed Nov 26 21:33:55 2003

-- Now the IRCD gets the commands from services
4. IRCD processes the prior kill on the NEW DooM
5. IRCD can't process the svsnick since Sonderzeichen3 doesn't exist, so it's ignored
6. Services doesn't get a QUIT response to it's prior KILL
I suspect there is some missing output, that services didn't process here:
[Nov 26 22:31:41 2003] debug: Sent: :NickServ n DooM +r 0
[...]
Since, according to the "IRCD Side" provided by Rocko, the IRCD sent out a QUIT.

7. The New DooM that just got killed, reconnects because he's like "WTF? I just got ghosted on my new nick" (more like, client reconnect. but still)
8. Services freaks out since it never processed the QUIT for it's earlier KILL (maybe it ignores the QUIT due to the KILL and SVSNICK?

I don't see how in any way this is an IRCD bug, and I would bet that it's a services bug, combined with some timesync issues.
I would be curious to know exactly what version of services is in use, to see if I can reproduce it.

syzop

2015-05-23 21:08

administrator   ~0018334

As it's a race condition & nick-based, this should be fixed with SID support now. If all ends support it, of course. And all commands use it.

Issue History

Date Modified Username Field Change
2003-11-28 13:21 thilo New Issue
2003-11-28 19:46 syzop Note Added: 0004152
2003-11-28 19:56 codemastr Note Added: 0004154
2003-11-28 20:01 syzop Note Added: 0004155
2003-11-28 21:12 thilo Note Added: 0004157
2003-11-28 21:20 thilo Note Added: 0004158
2003-11-28 22:55 Rocko Note Added: 0004160
2003-11-28 22:56 Rocko Note Edited: 0004160
2003-11-28 22:58 Rocko Note Edited: 0004160
2003-11-29 00:22 thilo Note Added: 0004161
2003-11-29 04:01 syzop Note Added: 0004164
2003-11-29 13:40 thilo Note Added: 0004166
2003-11-29 15:58 syzop Note Added: 0004167
2003-11-29 17:37 codemastr Note Added: 0004169
2007-04-27 06:08 stskeeps Note Added: 0013855
2007-04-27 06:08 stskeeps Status new => feedback
2010-04-15 11:10 driew Note Added: 0016072
2010-04-15 11:11 driew Note Edited: 0016072
2010-04-15 11:27 driew Note Edited: 0016072
2015-05-23 21:08 syzop Note Added: 0018334
2015-05-23 21:08 syzop Status feedback => resolved
2015-05-23 21:08 syzop Fixed in Version => 3.4-alpha3
2015-05-23 21:08 syzop Resolution open => fixed
2015-05-23 21:08 syzop Assigned To => syzop