View Issue Details
| ID | Project | Category | View Status | Date Submitted | Last Update |
|---|---|---|---|---|---|
| 0001393 | unreal | ircd | public | 2003-11-28 13:21 | 2015-05-23 21:09 |
| Reporter | thilo | Assigned To | syzop | ||
| Priority | normal | Severity | major | Reproducibility | unable to reproduce |
| Status | resolved | Resolution | fixed | ||
| Fixed in Version | 3.4-alpha3 | ||||
| Summary | 0001393: Duplicate users problem, ircd not sending quit correctly on logoff? | ||||
| Description | I 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 | ||||
| Tags | No tags attached. | ||||
| 3rd party modules | |||||
|
|
I (or codemastr) will take a look at it soon. Looks interresting/complcated ;). |
|
|
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. |
|
|
*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. |
|
|
Syzop: correct. I can assure you, that nothing indicating DooM ever quit or changed nick in the logs was cut. |
|
|
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. |
|
|
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 ([email protected]) [..] [22:31:40] *** (s) *** Notice -- Client connecting at sunflower.de.eu.spacetronix.net: Pimp32 ([email protected]) [22:31:40] *** (s) *** Notice -- Client connecting at sunflower.de.eu.spacetronix.net: Waggytai ([email protected]) [22:31:40] *** (s) *** Notice -- Client exiting at sunflower.de.eu.spacetronix.net: [email protected] (Ping timeout) [22:31:40] *** (s) *** Notice -- Client connecting at sunflower.de.eu.spacetronix.net: boyke ([email protected]) [22:31:40] *** (s) *** Notice -- Client connecting at sunflower.de.eu.spacetronix.net: Macaway ([email protected]) [22:31:40] *** (s) *** Notice -- Received KILL message for [email protected] 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: [email protected] (Killed (NickServ (Ghost command used by Sonderzeichen3))) [22:31:41] *** (s) *** Notice -- Client exiting at sunflower.de.eu.spacetronix.net: [email protected] (Ping timeout) [22:31:43] *** (s) *** Notice -- Client connecting on port 6667: Ender ([email protected]) [clients] [22:31:43] *** (s) *** Notice -- Client connecting at sunflower.de.eu.spacetronix.net: pu ([email protected]) [22:31:44] *** (s) *** Notice -- Client connecting at sunflower.de.eu.spacetronix.net: DooM ([email protected]) [Edit] You see, that the Ping Timeout and SVSKILL was in the same second. bearbeitet am: 11-28-03 22:58 |
|
|
hmm, judging by this, services never received the ghost-KILL message for the user. |
|
|
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 (??). |
|
|
well: [22:31:39] *** (s) *** Notice -- Client connecting at sunflower.de.eu.spacetronix.net: Sonderzeichen3 ([email protected]) [22:31:40] *** (s) *** Notice -- Client exiting at sunflower.de.eu.spacetronix.net: [email protected] (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 [email protected] 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: [email protected] (Killed (NickServ (Ghost command used by Sonderzeichen3))) [22:31:44] *** (s) *** Notice -- Client connecting at sunflower.de.eu.spacetronix.net: DooM ([email protected]) And services _only_ saw Doom's Ping timeout quit, but not the kill happening. When DooM reconnected, the problem with the double-users appeared. |
|
|
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. |
|
|
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. |
|
|
Bump. Still an issue i presume? |
|
|
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. |
|
|
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. |
| 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 |
|
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 |
|
Note Added: 0004169 | |
| 2007-04-27 06:08 |
|
Note Added: 0013855 | |
| 2007-04-27 06:08 |
|
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 |
