next »

[Stefan1200]

Using B3 pre 1.1.4 on a Debian Urban Terror Server. The problem is that B3 sometimes mix up client IDs on chatlines. Approx. 2 times the day the bot choose the wrong client ID for a chatline, even censor penalties are saved with the wrong client id and will punish the wrong player on to many warnings. The choosen client id seems to be random, because today one client got chatlines saved from three different players. I saw this, because the chatlogger plugin also save the names of the players. This players also got wrong aliases saved they never had.

Here is one example from the log, -=GF=-kilroy and -=GF=-Z0d1ak was playing at the same time, both are registered with B3, have different GUIDs, but B3 mix up the client ID one time with one chat line:

090130 22:14:58   VERBOSE   PoweradminurtPlugin: Client variable teamtime set to: 1233350098
090130 22:14:58   CONSOLE   0:43 ClientBegin: 4
090130 22:15:00   DEBUG   PoweradminurtPlugin: Checking for idle Spectators
090130 22:15:00   VERBOSE   RCON sending (127.0.0.1:27960) say ^0(^2b3^0)^7: ^7^3Visit our german homepage: www.german-fighters.com and player
090130 22:15:00   CONSOLE   0:45 say: 0 -=GF=-Z0d1ak: TEAMS
090130 22:15:00   VERBOSE   Client Found: -=GF=-kilroy
090130 22:15:00   DEBUG   Storage: getClientAlias <b3.clients.Alias object at 0xb6561a0c>
090130 22:15:00   DEBUG   Storage: setClientAlias <b3.clients.Alias object at 0xb6561a0c>
090130 22:15:00   DEBUG   Storage: setClientAlias data {'time_edit': 1233350100, 'num_used': 2, 'alias': '-=GF=-kilroy', 'client_id': 405, 'time_add': 1232998704, 'id': 112}
090130 22:15:00   BOT       New alias for 405: -=GF=-kilroy
090130 22:15:00   VERBOSE   Queueing event Client Name Change -=GF=-Z0d1ak
090130 22:15:00   VERBOSE   Queueing event Say TEAMS
090130 22:15:00   VERBOSE   Parsing Event: Client Name Change: PoweradminurtPlugin
090130 22:15:00   VERBOSE   Parsing Event: Say: AdminPlugin
090130 22:15:00   DEBUG   AdminPlugin: OnSay handle 5:"TEAMS"
090130 22:15:00   DEBUG   AdminPlugin: Handle command !teams
090130 22:15:00   VERBOSE   PoweradminurtPlugin: Checking for balancing

here a chatline from -=GF=-kilroy which seems to be right:

090130 22:02:03   CONSOLE   10:23 say: 0 -=GF=-kilroy: gg
090130 22:02:03   VERBOSE   Client Found: -=GF=-kilroy
090130 22:02:03   VERBOSE   Queueing event Client Name Change -=GF=-kilroy
090130 22:02:03   VERBOSE   Queueing event Say gg

Log from UrT Server:

  0:00 ClientConnect: 0
  0:00 ClientUserinfo: 0 \ip\87.245.11.154:40894\name\-=GF=-kilroy\password\***\racered\2\raceblue\2\rate\20000\ut_timenudge\0\cg_rgb\128 128 128\cg_predictitems\0\cg_physics\1\gear\GcAAUTR\snaps\20\model\sarge\headmodel\sarge\team_model\james\team_headmodel\*james\color1\4\color2\5\handicap\100\sex\male\cl_anonymous\0\teamtask\0\cl_guid\01DF9B1AEBED8DB681BC46879355E9F0\weapmodes\00000110220000020002
  0:00 ClientUserinfoChanged: 0 n\-=GF=-kilroy\t\2\r\2\tl\0\f0\\f1\\f2\\a0\0\a1\0\a2\255
  0:00 ClientConnect: 2
  0:00 ClientUserinfo: 2 \ip\85.244.1.7:27960\challenge\-362837979\qport\14840\protocol\68\name\-=GF=-Z0d1ak\password\***\racered\2\raceblue\2\rate\8000\ut_timenudge\0\cg_rgb\0 0 0\cg_predictitems\0\cg_physics\1\gear\FZAORWA\cl_anonymous\0\sex\male\handicap\100\color2\5\color1\4\team_headmodel\*james\team_model\james\headmodel\sarge\model\sarge\snaps\20\teamtask\0\cl_guid\5B98C0DE065573DE3D7F1CDA18BF1166\weapmodes\00000110220000020002
  0:00 ClientUserinfoChanged: 2 n\-=GF=-Z0d1ak\t\1\r\2\tl\0\f0\\f1\\f2\\a0\0\a1\255\a2\0
[...]
  0:22 ClientBegin: 0
[...]
  0:45 say: 0 -=GF=-Z0d1ak: TEAMS
  0:45 ClientBegin: 2

What is going wrong? The most time anything is working right. This bug occure only 2-3 times a day, but after a while it will completly mix up the database (aliases, chatlog and maybe the penalties table).

[Anubis]

+1 I've seen it 3 times on our server...

[Stefan1200]

Nobody has an idea? The problem is, many plugins goes wild with this bug. PoweradminURT tempban people, because it says to two different players at the same time:

No offensive, potentially offensive, or annoying names

The funny thing is poweradminurt tempban two players at the same time, but both make nothing wrong. This happend many times a day.

Sometimes censor penalties are written to the wrong userid, which also can result in a tempban (for the wrong guy, of course).

I don't want to give up and disable B3, but if I get no help I have no other chance.
If you need more informations, please feel free to ask me.

[Bakes]

Ouch!
I'm sorry, but I know little about UrT, so forgive me, but i'm sure others can help you.

[flinkaflenkaflrsk]

never seen this on mine. But I think I am running 1.1.4 so its not applicable

[Stefan1200]

never seen this on mine. But I think I am running 1.1.4 so its not applicable

You have a newer version than pre 1.1.4 of December 23, 2008? Where you got them?
On my server runs the newest version from http://github.com/BigBrotherBot/big-brother-bot/tree/master

Maybe this is wrong? It is an old version?

[Bakes]

no, you have the newest version.
Pre 1.1.4 means that it's been prepared for it; it's done, but not released.

[xlr8or]

I can't find any events in my logs like this. Can you line up some more of these events for comparison?

Do the gamers also have the same client.cid? Do they connect from within a LAN environment? Stuff like that and all other details is important to know.

[Stefan1200]

No, the client_id's are all unique.

No, the wrong player B3 choose is totaly different, but it is only a currently playing player.
For example:
6 Players on the Server:
PlayerA
PlayerB
PlayerC
PlayerD
PlayerE
PlayerF

The following happend sometimes (one or two times every day) on our UrT (Debian Linux Rootserver) server:

• PlayerA say: [****]ing idiot (this is just an example, it can be even every other chatline)
  
• B3 pick up the client ID from PlayerD
  
• B3 write a new alias for PlayerD with the name of PlayerA in the database.
  
• The plugin PoweradminURT thinks something is wrong with the PlayerD AND PlayerA, because the same player seems to be online twice and create a WARNING Penalty for both players.
  
• The plugin censor write down a warning penalty for PlayerD because of the word idiot. (only if the chatline from PlayerA is on the censor list, of course)
  
• Every second times this whole thing occure, PoweradminURT produce another two warnings after some minutes, which result in a tempban for both players because of too many warnings.

And is it really random who B3 chooses wrong, the player has only to be playing on the server at this time.
It is also possible that the two players playing from two different countries. So a no for your LAN theories.

Another B3 log:

090207 21:45:50   CONSOLE   0:14 ClientBegin: 0
090207 21:45:50   CONSOLE   0:14 ClientDisconnect: 19
090207 21:45:50   VERBOSE   Queueing event Client Disconnect 19
090207 21:45:50   VERBOSE   Parsing Event: Client Disconnect: TkPlugin
090207 21:45:50   VERBOSE   Parsing Event: Client Disconnect: CtimePlugin
090207 21:45:50   DEBUG   CtimePlugin: CTIME LEFT:
090207 21:45:50   DEBUG   CtimePlugin: CTIME LEFT: Player:pars^7 played this time: 401 sec
090207 21:45:50   DEBUG   CtimePlugin: CTIME LEFT: Player:pars^7 played this time: 0:6:41
090207 21:45:50   VERBOSE   Parsing Event: Client Disconnect: PoweradminurtPlugin
090207 21:45:50   CONSOLE   0:14 ClientBegin: 9
090207 21:45:52   CONSOLE   0:16 ClientBegin: 11
090207 21:45:53   CONSOLE   0:17 ClientBegin: 17
090207 21:45:54   CONSOLE   0:18 ClientBegin: 8
090207 21:45:54   CONSOLE   0:18 say: 0 -=GF=-KaroTTe: !xlrstats
090207 21:45:54   VERBOSE   Client Found: -=GF=-Flashkilla
090207 21:45:54   DEBUG   Storage: getClientAlias <b3.clients.Alias object at 0xb669fdac>
090207 21:45:54   DEBUG   Storage: setClientAlias <b3.clients.Alias object at 0xb669fdac>
090207 21:45:54   DEBUG   Storage: setClientAlias data {'time_edit': 1234039554, 'num_used': 1, 'alias': '-=GF=-Flashkilla', 'client_id': 441, 'time_add': 1234038046, 'id': 42}
090207 21:45:55   BOT       New alias for 441: -=GF=-Flashkilla
090207 21:45:55   VERBOSE   Queueing event Client Name Change -=GF=-KaroTTe
090207 21:45:55   VERBOSE   Queueing event Say !xlrstats
090207 21:45:55   VERBOSE   Parsing Event: Client Name Change: PoweradminurtPlugin
090207 21:45:55   VERBOSE   Parsing Event: Say: AdminPlugin
090207 21:45:55   DEBUG   AdminPlugin: OnSay handle 5:"!xlrstats"
090207 21:45:55   DEBUG   AdminPlugin: Handle command !xlrstats
090207 21:45:55   VERBOSE   RCON sending (127.0.0.1:27960) tell 0 ^0(^2b3^0)^7: ^3[pm]^7 ^3XLR Stats: ^7-=GF=-KaroTTe^7 ^7: K ^2881 ^7D ^3472 ^7TK ^18 ^7Ratio ^51.87 ^7Skill ^31591.40
090207 21:45:55   CONSOLE   0:18 ClientBegin: 13
090207 21:45:55   VERBOSE   Parsing Event: Say: SpamcontrolPlugin
090207 21:45:55   VERBOSE   Parsing Event: Say: ChatloggerPlugin
090207 21:45:55   DEBUG   ChatloggerPlugin: ALL, 441, -=GF=-KaroTTe, !xlrstats
090207 21:45:55   DEBUG   ChatloggerPlugin: query: INSERT INTO chatlog (msg_time, msg_type, client_id, client_name, client_team, msg) VALUES (1234039555, "ALL", 441, "-=GF=-KaroTTe", 2, "!xlrstats")
090207 21:45:55   DEBUG   ChatloggerPlugin: rowcount: 1, id:29404
090207 21:45:55   VERBOSE   Parsing Event: Say: CensorPlugin
090207 21:45:55   CONSOLE   0:19 ClientBegin: 14
090207 21:45:57   CONSOLE   0:21 ClientBegin: 5
090207 21:46:00   VERBOSE   RCON sending (127.0.0.1:27960) status
090207 21:46:00   VERBOSE   RCON: More data to read in socket
090207 21:46:01   ERROR   getPlayerList() = Line did not match :map: ut4_subway
090207 21:46:01   ERROR   getPlayerList() = Line did not match :num score ping name            lastmsg address               qport rate
090207 21:46:01   ERROR   getPlayerList() = Line did not match :--- ----- ---- --------------- ------- --------------------- ----- -----
090207 21:46:01   VERBOSE   StatusPlugin: Building XML status
090207 21:46:01   DEBUG   StatusPlugin: Writing XML status to status.xml
090207 21:46:01   DEBUG   PoweradminurtPlugin: Checking for idle Spectators
090207 21:46:01   DEBUG   PoweradminurtPlugin: Checking Names
090207 21:46:01   CONSOLE   0:25 ClientUserinfo: 13 \ip\78.52.193.200:27960\name\-=GF=-KaroTTe\password\***\racered\3\raceblue\1\rate\25000\ut_timenudge\0\cg_rgb\0 0 0\funred\pbeard,mohwkbk,patch\funblue\ninja,shades,ponybl\cg_predictitems\0\cg_physics\1\gear\GeAARUV\cl_anonymous\0\sex\male\handicap\100\color2\5\color1\4\team_headmodel\*james\team_model\james\headmodel\sarge\model\sarge\snaps\20\teamtask\0\cl_guid\FA7017F262E89EF464EF9C301164695F\weapmodes\00000110220000020002
090207 21:46:01   VERBOSE   Parsed user info {'racered': '3', 'ip': '78.52.193.200', 'sex': 'male', 'rate': '25000', 'cg_predictitems': '0', 'headmodel': 'sarge', 'port': '27960', 'team_model': 'james', 'cl_anonymous': '0', 'funred': 'pbeard,mohwkbk,patch', 'weapmodes': '00000110220000020002', 'cl_guid': 'FA7017F262E89EF464EF9C301164695F', 'funblue': 'ninja,shades,ponybl', 'snaps': '20', 'cg_rgb': '0 0 0', 'gear': 'GeAARUV', 'handicap': '100', 'team': -1, 'color1': '4', 'color2': '5', 'password': 'wargf', 'cg_physics': '1', 'teamtask': '0', 'name': '-=GF=-KaroTTe', 'cid': '13', 'team_headmodel': '*james', 'ut_timenudge': '0', 'raceblue': '1', 'model': 'sarge'}
090207 21:46:01   VERBOSE   Queueing event Client Team Change -1
090207 21:46:01   VERBOSE   Queueing event Client Name Change -=GF=-KaroTTe
090207 21:46:01   VERBOSE   Parsing Event: Client Team Change: PoweradminurtPlugin
090207 21:46:01   VERBOSE   PoweradminurtPlugin: Client variable teamtime set to: 1234039561
090207 21:46:01   VERBOSE   188 cid changed from 13 to 13
090207 21:46:01   VERBOSE   Parsing Event: Client Name Change: PoweradminurtPlugin
090207 21:46:01   CONSOLE   0:25 ClientUserinfoChanged: 13 n\-=GF=-KaroTTe\t\1\r\3\tl\0\f0\pbeard\f1\mohwkbk\f2\patch\a0\0\a1\255\a2\168
090207 21:46:01   VERBOSE   Parsed user info {'f0': 'pbeard', 'f1': 'mohwkbk', 'f2': 'patch', 'name': '-=GF=-KaroTTe', 'cid': '13', 'n': '-=GF=-KaroTTe', 'a1': '255', 'a0': '0', 'tl': '0', 'r': '3', 't': '1', 'team': 2, 'a2': '168'}
090207 21:46:01   VERBOSE   Queueing event Client Name Change -=GF=-KaroTTe
090207 21:46:01   VERBOSE   188 cid changed from 13 to 13
090207 21:46:01   VERBOSE   Queueing event Client Team Change 2
090207 21:46:01   VERBOSE   Parsing Event: Client Name Change: PoweradminurtPlugin
090207 21:46:01   VERBOSE   Parsing Event: Client Team Change: PoweradminurtPlugin
090207 21:46:01   VERBOSE   PoweradminurtPlugin: Client variable teamtime set to: 1234039561
[...]
090207 21:50:04   DEBUG   PoweradminurtPlugin: Warning Players
090207 21:50:04   DEBUG   Storage: setClientPenalty data {'time_edit': 1234039804, 'keyword': '', 'time_expire': 1234043404, 'admin_id': 0, 'reason': '^7No offensive, potentially offensive, or annoying names', 'inactive': 0, 'data': '', 'client_id': 188, 'duration': 60.0, 'time_add': 1234039804, 'type': 'Warning'}
090207 21:50:04   VERBOSE   RCON sending (127.0.0.1:27960) say ^0(^2b3^0)^7: ^1WARNING^7 (^32^7): -=GF=-KaroTTe^7^7, ^7No offensive, potentially offensive, or annoying names
090207 21:50:04   DEBUG   Storage: setClientPenalty data {'time_edit': 1234039804, 'keyword': '', 'time_expire': 1234043404, 'admin_id': 0, 'reason': '^7No offensive, potentially offensive, or annoying names', 'inactive': 0, 'data': '', 'client_id': 441, 'duration': 60.0, 'time_add': 1234039804, 'type': 'Warning'}
090207 21:50:04   DEBUG   PoweradminurtPlugin: No players to warn
090207 21:50:04   DEBUG   PoweradminurtPlugin: No players to warn
090207 21:50:04   DEBUG   PoweradminurtPlugin: No players to warn
090207 21:50:04   DEBUG   PoweradminurtPlugin: No players to warn
090207 21:50:05   VERBOSE   RCON sending (127.0.0.1:27960) say ^0(^2b3^0)^7: ^1WARNING^7 (^32^7): -=GF=-KaroTTe^7^7, ^7No offensive, potentially offensive, or annoying names
[...]
090207 21:51:01   CONSOLE   5:25 say: 13 -=GF=-KaroTTe: oups
090207 21:51:01   VERBOSE   Client Found: -=GF=-KaroTTe
090207 21:51:01   VERBOSE   Queueing event Client Name Change -=GF=-KaroTTe
[...]
090207 21:52:04   DEBUG   Storage: setClientPenalty data {'time_edit': 1234039924, 'keyword': '', 'time_expire': 1234043524, 'admin_id': 0, 'reason': '^7No offensive, potentially offensive, or annoying names', 'inactive': 0, 'data': '', 'client_id': 188, 'duration': 60.0, 'time_add': 1234039924, 'type': 'Warning'}
090207 21:52:04   VERBOSE   RCON sending (127.0.0.1:27960) say ^0(^2b3^0)^7: ^1WARNING^7 (^33^7): -=GF=-KaroTTe^7^7, ^7No offensive, potentially offensive, or annoying names
090207 21:52:04   DEBUG   Storage: getClientPenalties <b3.clients.Client object at 0xb4e39f8c>
090207 21:52:04   DEBUG   Storage: setClientPenalty data {'time_edit': 1234039924, 'keyword': '', 'time_expire': 1234043524, 'admin_id': 0, 'reason': '^7No offensive, potentially offensive, or annoying names', 'inactive': 0, 'data': '', 'client_id': 441, 'duration': 60.0, 'time_add': 1234039924, 'type': 'Warning'}
090207 21:52:04   DEBUG   Storage: getClientPenalties <b3.clients.Client object at 0xb5e503ec>
090207 21:52:05   VERBOSE   RCON sending (127.0.0.1:27960) say ^0(^2b3^0)^7: ^7^1ALERT^7: -=GF=-KaroTTe^7^7 auto-kick from warnings if not cleared (^33^7) ^7No
090207 21:52:07   VERBOSE   RCON sending (127.0.0.1:27960) say ^0(^2b3^0)^7: ^3>^7offensive, potentially offensive, or annoying names
[...]
090207 21:52:08   VERBOSE   RCON sending (127.0.0.1:27960) say ^0(^2b3^0)^7: ^1WARNING^7 (^33^7): -=GF=-KaroTTe^7^7, ^7No offensive, potentially offensive, or annoying names
090207 21:52:09   VERBOSE   RCON sending (127.0.0.1:27960) say ^0(^2b3^0)^7: ^7^1ALERT^7: -=GF=-KaroTTe^7^7 auto-kick from warnings if not cleared (^33^7) ^7No

-=GF=-KaroTTe (client id: 188) and -=GF=-Flashkilla (client id: 441) are two different players, both are registered and was currently playing on the server.
Both had two different IP's and GUID's and living with many kilometers distance .
Some minutes later both players got a tempban because of PowerAdminURT (thinks it was the same players with same names).

Log from UrT Server:

  0:00 ClientConnect: 0
  0:00 ClientUserinfo: 0 \ip\91.61.158.223:27960\name\-=GF=- Flashkilla\password\***\racered\0\raceblue\0\rate\8000\ut_timenudge\0\cg_rgb\128 128 128\cg_predictitems\0\cg_physics\1\gear\GMAARWU\cl_anonymous\0\sex\male\handicap\100\color2\5\color1\4\team_headmodel\*james\team_model\james\headmodel\sarge\model\sarge\snaps\20\teamtask\0\cl_guid\7BC6C22A44F0D933BDE0F1D5932ED351\weapmodes\00000110220000020002
  0:00 ClientUserinfoChanged: 0 n\-=GF=-Flashkilla\t\1\r\0\tl\0\f0\\f1\\f2\\a0\0\a1\0\a2\255
[...]
  0:00 ClientConnect: 13
  0:00 ClientUserinfo: 13 \ip\78.52.193.200:27960\name\-=GF=-KaroTTe\password\***\racered\3\raceblue\1\rate\25000\ut_timenudge\0\cg_rgb\0 0 0\funred\pbeard,mohwkbk,patch\funblue\ninja,shades,ponybl\cg_predictitems\0\cg_physics\1\gear\GeAARWV\cl_anonymous\0\sex\male\handicap\100\color2\5\color1\4\team_headmodel\*james\team_model\james\headmodel\sarge\model\sarge\snaps\20\teamtask\0\cl_guid\FA7017F262E89EF464EF9C301164695F\weapmodes\00000110220000020002
  0:00 ClientUserinfoChanged: 13 n\-=GF=-KaroTTe\t\1\r\3\tl\0\f0\pbeard\f1\mohwkbk\f2\patch\a0\0\a1\255\a2\168
[...]
  0:14 ClientBegin: 0
[...]
  0:18 say: 0 -=GF=-KaroTTe: !xlrstats
  0:18 ClientBegin: 13
[...]
  0:58 Kill: 0 5 15: -=GF=-Flashkilla killed JohnnyCrash by UT_MOD_DEAGLE
[...]
  1:07 Kill: 13 9 12: -=GF=-KaroTTe killed chrish by UT_MOD_KNIFE

That is interesting, in the urban terror server log you can see, that -=GF=-KatoTTe was prefixed with the ID 0, this is the ID from -=GF=-Flashkilla. The next line from both players (the kill lines) have the right ID. I am almost sure that this is the problem, but the big question is: Why?

I hope this informations help.

[Stefan1200]

I updated my last post with many informations in the last hour.

I updated also my starting post of this thread and added the UrT server logfile showing the same problem like in the last post.

[xlr8or]

Does it always happen to players starting with "-=GF=-"?

[Stefan1200]

Does it always happen to players starting with "-=GF=-"?

No, I think this bug occure because of the wrong server client ID 0 in the server log's say line.

Do you see this? Same error was in the log of my starting post (I updated the starting post also today). The Urban Terror server writes server client ID 0 in the say line, because the ClientBegin line for this client comes later. And I think the B3 ioUrT Parser works with this server client ID's.

[Stefan1200]

I posted this urban terror bug in the official urban terror forums. It is a known bug, look here:
http://forums.urbanterror.net/index.php/topic,14362.0.html

Is a workaround for B3 possible?

[Courgette]

workaround => b3 should ignore ClientConnect lines

[xlr8or]

I agree, the clientConnect line doesn´t contribute anything. I´ll fix it to ignore the event.
The rest will have to wait untill UrT 4.2 is released.