Username in use when logging in

[ritty]

We have a problem which we've always experienced since using ES4 regarding issues with logging in. When a user loses connection, sometimes they can't get logged back in. The issue does not go away until we restart the server, which we sometimes do days after the issue first occurs. Trying to evictuser (4.0.7a12) or kickuser results in an error stating the user isn't logged in. So basically, we are always stuck until we restart the server. Any thoughts?

[tcarr]

If evict user doesn't work, then the username isn't really already in use. We noticed a few weeks ago that the default error message when a login fails is username exists. This means that even if the client gets that error message on the failed login attempt, it doesn't nec. mean that there's somebody already logged in with that username. I don't understand why the user wouldn't be able to log on for days. Is this something that you can reproduce? If not, is it something that your own people have verified as happening sometimes? Can the same user who experiences this problem log on using a different username from the same desktop where he can't log in using his usual one, or is he blocked on all usernames? Can somebody else on a different local network log on as the username that isn't working?

The latest ES4 patch is 4.0.7-a13 (http://dev.electrotank.com/archiva/repository/et-public/com/electrotank/electroserver/4.0.7-a13/). It's a simple jar replacement in your installation/server/lib folder, if you are already running 4.0.7-a12. I don't know if this will be any improvement but it's probably worth trying.

What you have reported disturbs me, but at this point we don't have enough information to even start looking into it, and any bugfix for the situation would be done on ES5 if the bug is still also present on ES5.

[jobem]

ritty,

This may or may not be the issue. With certain version of IE (I think IE 7 maybe) the socket will remain open even after you leave the page. You then come back and try to login and it says user is already logged in. That is an IE bug, not an ES bug. But if you close all instances of IE I believe it closes the socket.

Also, if you are using HTTP mode then a user is connected for a certain amount of time even after leaving the page. That is the nature of HTTP mode.

[tcarr]

Good point Jobe. I know that sometimes I think my browser is closed until I check Task Manager and see there's a ghost process of it still running. The next time it happens, ask the user to try rebooting his own desktop to see if that helps.

[ritty]

We can't reproduce it in house as whenever we try to do a disconnect, the server always sees it. However, I can confirm it is happening with various people on various different browsers. This is fairly rare, happens about once a month, but still is an issue.

For the last time this happened (Friday), I tried logging in with the user's account name and sure enough, it would not allow me in. The user and I are, of course, on completely different computers, browsers, networks, etc. I also did a dump of all rooms and users in those rooms (self-developed extension code) and the user did not appear in any. I also tried a force eviction (also in extension code, aside from our normal login extension code which comes from ES wiki) and it responded with user not being logged in.

We are using sockets, not http mode. (This is es4 - is there http mode in es4?)

I'll try a13 and see what happens.

[tcarr]

That is truly strange indeed. It is possible for a user to be logged on and not be in a room, however if the ES4 thinks that the user isn't logged in, but doesn't allow you to log on AS the user, I'm stumped - unless you are doing something with database verification or you have you ES4 set up to ban users for various activities. For example, if you are using language and flooding filters, the default filter settings do have a "kicks before ban". If a user triggers a ban, then that ban is reset when the ES4 is restarted.

[ritty]

Just an FYI...this issue is still occurring in 4.07a13.

[tcarr]

Does your ES4 application ever do any banning of users? Either from a plugin, or using the language or flooding filters? Because that's the only way I know that this could occur.

[ritty]

We do banning, but not through ES4. No language filters or flooding filters are used. However, maybe I'll try to add some sort of unban (never looked into how to do this with ES4) to see if I can do this and if it solves anything.

[tcarr]

Or perhaps we can just figure out how to look up the list of those who are banned, so that you can tell "oh userA can't log in because he's been banned - his fault, not a bug". Do you do the banning using a database, or just tell ES4 to ban somebody?

[ritty]

We do banning via a database. We do no banning via ES4.

[tcarr]

If your banning is solely through the database, then if a user is banned, restarting ES4 won't clear the ban. So that's not the problem. I'm stumped. Unless we can reproduce the problem, we don't have a chance of fixing the bug, assuming it's still a bug in ES5.

[daperson1]

Ah-ha! This seems to be exactly the problem I've been having (And posted in my other thread - whoops).
Also, I believe I can reproduce it, but it's sort of difficult. One of the features of the site we're using ES for is tournaments for the players. This problem occurs for users who are involved in the tournaments almost all the time in the event they simply close their web browser. Tomorrow I'll see if I can identify exactly what it is that's happening in the tournament plugins that's causing this. There is no banning by ES going on at all.

[tcarr]

I doubt that it would be the plugins that are keeping the users marked as logged in. Are your users connecting using HTTP or normal binary? If you can reproduce this enough that we can make it happen on our own servers, we might have a chance of figuring out what the bug is and getting you a workaround.

[daperson1]

Users are connecting with the default binary protocol.
I really have no idea what causes it, but there does seem to be some correlation between our tournament system and this happening (although it does happen to other users, after some tournaments everyone who was in that tournament, all at once, start experiencing this problem). So I guess that something the plugin does causes ES to get stuck? Although I can't think what.
The fact that the isUserLoggedIn function returns true for these users is potentially interesting. Does this return true for users who are connected but not logged in? Can the evict function access users who are connected but not logged in? (Or not in a room?) Do you have these sorts of nauseating details available? I will do some fiddling around with it tomorrow, but it's weird.

[tcarr]

Does your tournament plugin maintain a data structure of User objects, or just user names for keeping track of the users? Any time that users don't get kicked off by evict concerns me, particularly if the ALSO aren't getting kicked off when the client idle timeout period passes. We need to track this down and get it fixed.

[ritty]

Boy I wish I could recreate this at will. In my situation, it only happens to one person, generally when they lose connection for some reason (e.g., closing browser window, ISP hiccup, etc.). This happens about once every two weeks. Usually ghost users are handled fine and just kicked off correctly. Here is my login event handler, maybe I'm doing something wrong...


@Override
public ChainAction executeLogin(LoginContext context) {
String username = context.getUserName();

if ( getApi().isUserLoggedIn( username ) ) {
EsObject obj = new EsObject();
obj.setString( "ReasonForKick", "Second login forces first one off" );
getApi().kickUserFromServer( username, obj );
}
// We return with an OkAndContinue message no matter what.
// If the username was in use, then a UserNameExists error
// will eventually be sent to the client. If we had used
// the Fail error, then the error would be a less descriptive
// LoginEventHandlerFailure
return ChainAction.OkAndContinue;
}

The only thing I can think of is changing the return code.

[tcarr]

If you are using the latest patch version of ES4, then I'd suggest using getApi().evict... rather than getApi().kick..., but other than that it looks good. Evict is better at kicking ghosts off the server than kick is.

We don't need to be able to reproduce it reliably, but we do need to be able to reproduce it in a reasonable time frame, so that we can inspect the server and see if we can figure out why that user didn't get removed.

Do you have a LogoutEventHandler perhaps? Or something complicated going on in a plugin's userExit method which might make that method hang sometimes?

[ritty]

I'll try evict as we are using 4.0.7a13. We don't have any logout event handler. Perhaps we need to add one?

[tcarr]

No you don't need to add a LogoutEventHandler. it just might complicate matters is all.

[daperson1]

Say, I now have 16 users who are doing it all the time on my ES installation. Right now-ish.
Would you be able to derive anything useful if I gave you access to the server?

(That is, I have 16 usernames that now ALWAYS do this. We just ran a test tournament, it crashed, and this happened to every one of the users involved.)

[daperson1]

Ah, also of possible note, this was written to the ES server log when all the users got disconnected from the tournament (16 times)




16:05:51,319 [pool-1-thread-117] ERROR com.electrotank.electroserver4.servers.registry.Ga tewayIoHandler - Exception processing message com.electrotank.electroserver4.messages.internal.I nternalClientDisconnectedMessage@32985ae9
com.electrotank.electroserver4.servers.registry.Me ssagingException: Exception processing message com.electrotank.electroserver4.messages.internal.I nternalClientDisconnectedMessage@32985ae9
at com.electrotank.electroserver4.servers.registry.tr ansactions.TransactionHandlerImpl.processMessage(T ransactionHandlerImpl.java:172)
at com.electrotank.electroserver4.servers.registry.Ga tewayIoHandler.messageReceived(GatewayIoHandler.ja va:139)
at org.apache.mina.common.support.AbstractIoFilterCha in$TailFilter.messageReceived(AbstractIoFilterChai n.java:570)
at org.apache.mina.common.support.AbstractIoFilterCha in.callNextMessageReceived(AbstractIoFilterChain.j ava:299)
at org.apache.mina.common.support.AbstractIoFilterCha in.access$1100(AbstractIoFilterChain.java:53)
at org.apache.mina.common.support.AbstractIoFilterCha in$EntryImpl$1.messageReceived(AbstractIoFilterCha in.java:648)
at org.apache.mina.filter.executor.ExecutorFilter.pro cessEvent(ExecutorFilter.java:219)
at org.apache.mina.filter.executor.ExecutorFilter$Pro cessEventsRunnable.run(ExecutorFilter.java:263)
at java.util.concurrent.ThreadPoolExecutor$Worker.run Task(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run (Unknown Source)
at java.lang.Thread.run(Unknown Source)
Caused by: java.lang.UnsupportedOperationException
at java.util.AbstractList.remove(Unknown Source)
at java.util.AbstractList$Itr.remove(Unknown Source)
at java.util.AbstractCollection.remove(Unknown Source)
at tourneyplugin.TourneyMonitor.userExit(TourneyMonit or.java:119)
at com.electrotank.electroserver4.entities.PluginBrid ge$6.call(PluginBridge.java:178)
at com.electrotank.electroserver4.entities.BaseBridge .withLockAndClassloader(BaseBridge.java:192)
at com.electrotank.electroserver4.entities.PluginBrid ge.withLockAndClassloader(PluginBridge.java:283)
at com.electrotank.electroserver4.entities.PluginBrid ge.userExit(PluginBridge.java:176)
at com.electrotank.electroserver4.entities.managers.R oomManager$1.perform(RoomManager.java:949)
at com.electrotank.electroserver4.entities.managers.R oomManager._leaveRoom(RoomManager.java:990)
at com.electrotank.electroserver4.entities.managers.R oomManager.leaveRoom(RoomManager.java:947)
at com.electrotank.electroserver4.entities.Room.leave (Room.java:599)
at com.electrotank.electroserver4.entities.PeopleImpl .connectedUserDropped(PeopleImpl.java:408)
at com.electrotank.electroserver4.entities.PeopleImpl .clientDropped(PeopleImpl.java:366)
at com.electrotank.electroserver4.servers.registry.tr ansactions.ClientDroppedTransaction.execute(Client DroppedTransaction.java:24)
at com.electrotank.electroserver4.servers.registry.tr ansactions.ClientDroppedTransaction.execute(Client DroppedTransaction.java:9)
at com.electrotank.electroserver4.servers.registry.tr ansactions.TransactionHandlerImpl.processMessage(T ransactionHandlerImpl.java:169)
... 10 more

That said, it points to a line in which I am removing a string from the playerList collection in my plugin, for some odd reason, so this may simply me by own incompetence rather than anything more interesting.

[daperson1]

Ah, and to further clarify, no, we do not store User objects anywhere, we just use username string to track users.
The tournaments, however, do involve a room level plugin moving users to different rooms in that zone (using the createRoom function). I can provide the source if you like? (Longish)

[tcarr]

That error trace might help a lot. Thanks for snagging it. I'm not sure access to your live server would help, because we would need to add logging lines, reproduce the problem, check the log, rinse and repeat.

It would also help if I could see the source code to your plugin. I bet that you have a bug in it that is causing the trouble. This is the line that might mean that the bug is in your own code instead of in ES4:


at tourneyplugin.TourneyMonitor.userExit(TourneyMonit or.java:119)


I'd have to see the code to tell.

[daperson1]

Okay. Behold the two horrible tournament plugins:
http://www.earthnemesis.com/TourneyPlugin.java
This one acts as the Lobby for the tournaments, and is run as a room level plugin attached to a persistent room created for each tournament. Users enter here before the start time, and the plugin, when the time comes, joins them to the appropriate games for each successive round.

http://www.earthnemesis.com/TourneyMonitor.java
And this one runs at the room level in the actual game rooms (where the games for each of the tournament matches are played).

Any and all help would be appreciated. I'm not exactly a master of java :P.
That said, if we can find which bug here is causing the ES API to have a fit in this way then presumably it will facilitate the correction of both problems.
Thanks!

[daperson1]

Also, what logging lines, exactly, would be informative in trying to fix this problem? Since it seems that each failed tournament leads to this problem arising, if you could provide some details of what needs logging I could go and get on with that.

[tcarr]

If it's a bug in ES4, then it's logging lines added to ES4. If it's a bug in your plugin, odds are good I'll spot it in a few minutes. I have them grabbed now and will peek at them.

[tcarr]

I think I found your problem. You are using this data structure, and removing a player during the userExit method.


public List<String> playerList;


That isn't thread safe. What that means is any time that you have two users exiting the room (or entering it) at the same time you are in danger. If your plugin crashes during a userExit or userEnter method, it can cause problems with ES4 cleaning up the room. Instead of using a List<String>, I would recommend either a ConcurrentHashMap or a ConcurrentSkipListSet. They take up a bit more RAM but the concurrency is handled for you so you don't need to worry about race conditions or deadlocks. Another alternative that works if all of these players are in the same room with nobody else in the room is to just use getApi().getUsers() to get the list of users in the room, each time that you need it. If there is info about the players, I just use a ConcurrentHashMap<String, PlayerInfo>, with my own PlayerInfo class that contains all the info about a given player, and the key is the player name.

Any other data structures in your plugin will need to be treated the same way.

See Threading in Plugins (http://www.es-wiki.com/index.php?title=Threading_in_plugins) today (ES4 version but it will poof soon) or the ES5 version (http://www.electrotank.com/docs/es5/manual/threading_in_plugins.htm) of it. I can point you to ES5 examples that handle this correctly but I don't know off the top of my head which ES4 examples do it.

[tcarr]

Looking closer at your userExit method, you have even more problems. You are setting a boolean scoped to the plugin that you want to rely on at a later time. I would think a better solution is to have the boolean part of a PlayerInfo class, and instead of removing the PlayerInfo object immediately when the player leaves, just toggle the boolean. You can remove later or just leave it in the map until it's time to determine the next round of matches. Similarly with the callback ids. You are making callbacks that all share the same callback id variable, so that you can't cancel them all if the room is destroyed.

[daperson1]

I see, thanks. And you think this weirdness with username exists is caused because my plugin causes ES to handle the room's destruction wrongly for these reasons? Surely there must be something somewhat amiss if a username can enter a contradictory state such that isUserLoggedIn is true, and the evict function doesn't function?
In any case, thanks for the pointers - I'll get on to sorting this out. Threading is a continual headache.

[tcarr]

yes, there is something amiss in ES4, but the trigger is that your plugin is throwing an exception at exactly the wrong time, so that the ES4 methods that handle users exiting a room and logging off get deadlocked. I remember hearing discussion about how we were going to separate the extension threads from the ES threads better in ES5, but I haven't peeked at the code to see if it was actually changed.

Yes there's a bug in ES4, because we should be able to evict anyway. Fixing your plugins should prevent this bug from being triggered.

[ritty]

I'm going to try to closely monitor these things and try to get users to report issues more promptly. The last time this happened I do see an error in the logs. An exception was thrown due to too many connections on our mysql server (we've been getting that a lot lately, don't know why as we have plenty) and things went into a dizzying tailspin from there. This was during a room creation phase.

Here's the basic errors just for documentation purposes:


Room created: FTW-Game:fries4guys-205786 Room ID: 1:921 with user fries4guys
Unable to connect to database.com.mysql.jdbc.exceptions.MySQLNonTransie ntConnectionException: Too many connections
22:35:52,536 [pool-1-thread-1089] ERROR com.electrotank.electroserver4.entities.BaseBridge - Error occured calling extension code - Extension: ForTheWin - Name: Manager - Handle: TheManager
java.lang.NullPointerException
22:35:52,598 [pool-1-thread-1089] ERROR TransactionTiming - Exception processing message com.electrotank.electroserver4.messages.client.req uest.ClientInvokePluginRequestMessage@1628d8
java.lang.NullPointerException
22:35:52,598 [pool-1-thread-1089] ERROR com.electrotank.electroserver4.servers.registry.Ga tewayIoHandler - Exception processing message com.electrotank.electroserver4.messages.client.req uest.ClientInvokePluginRequestMessage@1628d8
com.electrotank.electroserver4.servers.registry.Me ssagingException: Exception processing message com.electrotank.electroserver4.messages.client.req uest.ClientInvokePluginRequestMessage@1628d8
22:35:52,601 [pool-1-thread-1088] ERROR com.electrotank.electroserver4.entities.BaseBridge - Error occured calling extension code - Extension: ForTheWin - Name: Game - Handle: Game
java.lang.NullPointerException
22:35:52,614 [pool-1-thread-1088] ERROR TransactionTiming - Exception processing message com.electrotank.electroserver4.messages.internal.I nternalClientDisconnectedMessage@158b8b1
java.lang.NullPointerException
22:35:52,615 [pool-1-thread-1088] ERROR com.electrotank.electroserver4.servers.registry.Ga tewayIoHandler - Exception processing message com.electrotank.electroserver4.messages.internal.I nternalClientDisconnectedMessage@158b8b1
com.electrotank.electroserver4.servers.registry.Me ssagingException: Exception processing message com.electrotank.electroserver4.messages.internal.I nternalClientDisconnectedMessage@158b8b1

For now I'll trap the exception and just not create the game if it happens. It does look like my userexit routine is thread safe, but, of course, threads are the most annoying things ever, so who knows for sure.

[tcarr]

If an exception is thrown during creation or destruction of a room, and particularly during a userExit, there is a small chance that RoomManager's data structures will get out of sync. It looks like the kick and evict methods are checking one data structure (that has the connection details) which is the one that the ES4 checks regularly for the client idle timeout, but isUserLoggedIn checks the other one.

I don't know how long it's going to take us to determine the best way to fix this. I suggested just adding a few lines to the evict method, but the main ES4/ES5 developer wants to take a closer look at RoomManager first to make it more bulletproof.