NPE in SFSUserManager.addUser

[guycoleman]

For load testing I run hundreds of clients in the same process against the same server.

Occasionally this exception turns up:

Code: Select all

java.lang.NullPointerException
	at sfs2x.client.entities.managers.SFSUserManager.addUser(SFSUserManager.java:89)
	at sfs2x.client.entities.SFSRoom.addUser(SFSRoom.java:331)
	at sfs2x.client.controllers.system.ResUserEnterRoom.handleResponse(ResUserEnterRoom.java:32)
	at sfs2x.client.controllers.SystemController.handleMessage(SystemController.java:104)
	at sfs2x.client.core.SFSProtocolCodec.dispatchRequest(SFSProtocolCodec.java:144)
	at sfs2x.client.core.SFSProtocolCodec.onPacketRead(SFSProtocolCodec.java:50)
	at sfs2x.client.core.SFSIOHandler.handlePacketData(SFSIOHandler.java:281)
	at sfs2x.client.core.SFSIOHandler.onDataRead(SFSIOHandler.java:130)
	at sfs2x.client.bitswarm.BitSwarmClient.onSocketData(BitSwarmClient.java:357)
	at sfs2x.client.bitswarm.BitSwarmClient.access$200(BitSwarmClient.java:26)
	at sfs2x.client.bitswarm.BitSwarmClient$3.dispatch(BitSwarmClient.java:105)
	at sfs2x.client.core.EventDispatcher.dispatchEvent(EventDispatcher.java:52)
	at sfs2x.client.core.sockets.TCPSocketLayer.callOnData(TCPSocketLayer.java:144)
	at sfs2x.client.core.sockets.TCPSocketLayer.handleBinaryData(TCPSocketLayer.java:138)
	at sfs2x.client.core.sockets.TCPSocketLayer.access$700(TCPSocketLayer.java:23)
	at sfs2x.client.core.sockets.TCPSocketLayer$NettyIOHandler.messageReceived(TCPSocketLayer.java:273)
	at org.jboss.netty.channel.SimpleChannelHandler.handleUpstream(SimpleChannelHandler.java:100)
	at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)
	at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:559)
	at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:274)
	at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:261)
	at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:351)
	at org.jboss.netty.channel.socket.nio.NioWorker.processSelectedKeys(NioWorker.java:282)
	at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:202)
	at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108)
	at org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockProofWorker.java:44)
	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
	at java.lang.Thread.run(Thread.java:662)

I'm afraid I can't supply a better bug report - it only happens occasionally.

[ThomasLund]

I'll take a look. What kind of data are you sending?

/Thomas

[ThomasLund]

Hmmm - very interesting. That shouldnt happen more or less. Either the smartfoxserver client instance is null (hardly when you are running code inside it) or the logger is null.

Lines 88-90 are:

Code: Select all

		if (usersById.containsKey(user.getId())) {
			smartFox.getLogger().warn("Unexpected: duplicate user in UserManager: " + user);
		}

So first up seems you are adding duplicate users. But the NPE is thrown in the logger warning line.

Can you give more info? Did you do anything to the logger (so it might return null) or otherwise?

/Thomas

[guycoleman]

The clients generally log into a zone, make a few zone level requests to get available games etc then join a game room. Once in the game room they will send a request to spin a slot machine game every 5-30s. If the server gets overloaded the clients can start getting disconnected, timing out etc.

Nope, I'm not doing anything strange with the logger or the client. There shouldn't be duplicate users but I suppose occasionally there could be. During the tests it's possible the client machine has very high CPU usage - could the client side state get confused if it takes a long time for the client to process an incoming message?

Like I said, it only turns up occasionally during load testing so it's not a big issue for us.

[ThomasLund]

Right right - very weird. And the duplicate user itself should not cause this.

Will dig a bit deeper - see if I somehow can reproduce it. If not, then its going to be hard to fix. Are there any other hints written in the log files?

/Thomas

[guycoleman]

No, nothing strange in the log files that I can see.

I think it is to do with duplicate users though. I hacked together a quick test with a simple java client that simply joined a room. The room had USER_ENTER_EVENT enabled.

I then made an extension request which did nothing except fire several user enter room events using ResponseAPI:

Code: Select all

getParentExtension().getApi().getResponseAPI().notifyUserEnterRoom(user, room);
getParentExtension().getApi().getResponseAPI().notifyUserEnterRoom(user, room);
getParentExtension().getApi().getResponseAPI().notifyUserEnterRoom(user, room);

This is enough to cause the NPE in the java client for me. Is it possible that line 89 always throws NPE?

[ThomasLund]

I'll run some tests and fix it if so! Would definitely explain why the code looks innocent and fails.

Thanks!

/Thomas

[ThomasLund]

Tried to repro directly in the API code without luck. Tracing through things also show no obvious mistakes or uninitialized things.

So I've added defensive coding and checking for nulls before using the smartfox instance and the logger - so that the error doesnt trigger in whatever weird case that this happens.

Part of next update

/Thomas