After 2.9.0 upgrade: IllegalStateException: AsyncContext

[rewb0rn]

Hello,

after upgrading the SFS to v2.9.0 I have seen 2 huge user drops today. Once from 1,000 CCU to 650 CCU, the 2nd from 600 CCU to 250 CCU, happening within 20 minutes. The logs show these exceptions from time to time, but not in the same magnitude I see users disconnecting:

Code: Select all

11 Aug 2014 | 23:33:05,144 | WARN  | SFSWorker:Ext:20 | controllers.v290.ExtensionReqController |     | com.smartfoxserver.v2.exceptions.SFSExtensionException: Extension Request refused. Sender is not a User: { Id: 42385, Type: DEFAULT, Logged: No, IP: XX.XX.XX.XX:XXXXX }
	com.smartfoxserver.v2.controllers.v290.ExtensionReqController.processRequest(ExtensionReqController.java:93)
	com.smartfoxserver.v2.controllers.v290.ExtensionReqController$1.run(ExtensionReqController.java:68)
	java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
	java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
	java.lang.Thread.run(Unknown Source)


11 Aug 2014 | 23:36:49,440 | WARN  | SFSWorker:Sys:2 | controllers.v290.SystemReqController |     | java.lang.IllegalStateException: Sender ( User Name: UGE, Id: 31546, Priv: 0, Sess: XX.XX.XX.XX:XXXXX )  is not joined the target room [ Room: gr19737, Id: 23276, Group: default, isGame: false ]
	com.smartfoxserver.v2.api.SFSApi.sendPublicMessage(SFSApi.java:1093)
	com.smartfoxserver.v2.api.SFSApi.sendPublicMessage(SFSApi.java:1150)
	com.smartfoxserver.v2.controllers.system.GenericMessage.executePublicMessage(GenericMessage.java:249)
	com.smartfoxserver.v2.controllers.system.GenericMessage.execute(GenericMessage.java:122)
	com.smartfoxserver.v2.controllers.v290.SystemReqController.processRequest(SystemReqController.java:157)
	com.smartfoxserver.v2.controllers.v290.SystemReqController.enqueueRequest(SystemReqController.java:114)
	com.smartfoxserver.bitswarm.io.protocols.AbstractProtocolCodec.dispatchRequestToController(AbstractProtocolCodec.java:39)
	com.smartfoxserver.v2.protocol.SFSProtocolCodec.dispatchRequest(SFSProtocolCodec.java:125)
	com.smartfoxserver.v2.protocol.SFSProtocolCodec.onPacketRead(SFSProtocolCodec.java:90)
	com.smartfoxserver.v2.protocol.binary.BinaryIoHandler$1.run(BinaryIoHandler.java:525)
	java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
	java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
	java.lang.Thread.run(Unknown Source)

11 Aug 2014 | 23:49:43,681 | WARN  | SocketWriter-1 | bitswarm.core.SocketWriter |     | java.lang.IllegalStateException: AsyncContext#dispath s=ASYNCWAIT i=false a=DISPATCH
	org.eclipse.jetty.server.HttpChannelState.dispatch(HttpChannelState.java:352)
	org.eclipse.jetty.server.AsyncContextState.dispatch(AsyncContextState.java:114)
	org.eclipse.jetty.continuation.Servlet3Continuation.resume(Servlet3Continuation.java:139)
	sfs2x.bluebox.v3.data.BBClient.enqueueMessage(BBClient.java:80)
	com.smartfoxserver.bitswarm.core.SocketWriter.processBlueBoxSession(SocketWriter.java:242)
	com.smartfoxserver.bitswarm.core.SocketWriter.processSessionQueue(SocketWriter.java:208)
	com.smartfoxserver.bitswarm.core.SocketWriter.run(SocketWriter.java:181)
	java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
	java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
	java.lang.Thread.run(Unknown Source)

Any idea what might be the reason for this? User drops appear to be caused by users disconnecting manually because the game does not work, this is not clear yet. The extension does not catch any exceptions, I only see the above exceptions in the smartfox.log. I will schedule a server restart for tonight but I want to ask anyway. This is happening on our live system and causing damage to our credibility.

[Lapo]

Hi,
the first two errors simply mean that some clients that are not logged in are sending requests which in turn are refused by the server (because they aren't logged in).
You should make sure in your client code that if the login has failed, users shouldn't be able to interact with controls that send requests to the server.

As regards the last error, I am haven't seen this one before, it seems BlueBox related but I can't say exactly what might be causing it, at the moment. I should know more details and how to reproduce it.

User drops appear to be caused by users disconnecting manually because the game does not work, this is not clear yet.

What did you find that suggests users are disconnecting manually?

As regards the multiple disconnections there are several areas to investigate.
From the SmartFox side:

1) Make sure your "Dropped Out" packets stats doesn't exceed 10-15% (AdminTool > Dashboard)
2) Keep an eye on the System Queues in the Dashboard, they should be consistently empty, meaning that no extra work is piling up.

You should also investigate your hosting provider and check if their bandwidth is sufficient to handle the traffic or if they are having any network issues.

[rewb0rn]

Thanks for the reply Lapo. I restarted the server already so I can not say what were the numbers of dropped packets. Currently (800 CCU) it looks good with only 3% dropped packages. Also I had the logging set to INFO, with up to 1500 CCU that is a lot of logging, maybe that was the reason for undesired behavior. I changed it to WARN now.

For the morning the server looks stable, currently all 4 graphs in the dashboard are on 0% load, it is a really powerful machine.

I still get a lot of these java.lang.IllegalStateException: AsyncContext#dispath s=DISPATCHED i=false a=null exceptions and I have never seen them before in the SFS 2.7.0. But you are right, it looks like it's only BlueBox. Still there are a lot of those exceptions, ca. 2 per minute. I googled it but didnt't find any hints. Maybe it's related to an incompatible version of Java or Jetty?

I wouldn't expect the reason with the provider because it was working without flaw before the SFS2X update 3 days ago. I think a wrong config or some other problem is more likely in this case. I will report later today or tomorrow if there were any problems.

[Lapo]

Thanks for the reply Lapo. I restarted the server already so I can not say what were the numbers of dropped packets. Currently (800 CCU) it looks good with only 3% dropped packages. Also I had the logging set to INFO, with up to 1500 CCU that is a lot of logging, maybe that was the reason for undesired behavior. I changed it to WARN now.

No, logging has nothing to with it.

I still get a lot of these java.lang.IllegalStateException: AsyncContext#dispath s=DISPATCHED i=false a=null exceptions and I have never seen them before in the SFS 2.7.0. But you are right, it looks like it's only BlueBox. Still there are a lot of those exceptions, ca. 2 per minute. I googled it but didnt't find any hints. Maybe it's related to an incompatible version of Java or Jetty?

How many BlueBox clients do you have approximately? You can check the from the AdminTool

Thanks

[rewb0rn]

Right now there are 9 users logged in through BlueBox against 900 CCU in total. Does SFS2X 2.9 require a specific version of the Java jdk for my extension to compile against? Maybe there is an incompatibility between the jdk I use for compilation and the Java runtime on the live server?

[Lapo]

9 users should really be of no concern. Maybe some of these users are having network issues. If you want you can send me the address of your game/application and we can test from here, just to see how it works for us.

Does SFS2X 2.9 require a specific version of the Java jdk for my extension to compile against? Maybe there is an incompatibility between the jdk I use for compilation and the Java runtime on the live server?

No it doesn't. Additionally compilation errors would cause very prominent errors as soon as the Extension is loaded, and the Extension itself would not be working at all.

What is not clear is if every user is having problems with the BlueBox connection, which I wouldn't expect, or if it's more like bad connection issue from the client side popping up every now and then.

Cheers

[rewb0rn]

Thanks Lapo,

as of now the server seems to be stable. Looks like a clean restart helped, and I still could imagine the loads of logs were blocking the HDD and ultimately led to threadblocking / user drops.

Anyway the exceptions remain but I was able to play the game through Bluebox. Also the exceptions are continous, there are no times when there are more or less exceptions. They are evenly spread over the last 24 hours every couple of seconds (and my games are mostly played by german players, so there is less traffic early morning). You can test the game yourself if you like: https://apps.facebook.com/skatpalast/

[Lapo]

Do the same exception appear on your test servers?
I ask because from your description it sounds as if every user connected via BlueBox is generating exceptions...

As regards massive logging causing slow downs. This is hard to believe for 9 BlueBox users, unless you had thousands of exceptions per user per second, and it wouldn't be enough anyways.
Also while the system might consume extra CPU while logging tens of thousands of messages per second, that would be pretty much all it would happen. It's not that some extra CPU usage automatically causes disconnections. The first symptom instead could be a slow down of the general server responsiveness, but you had to have the CPU almost fully taken. Is it the case?

Finally, as I have already mentioned, the "Sender XYZ is not joined the target room" exception is essentially caused by the client that is not correctly handling the Join Room error. If the User is not joined in a Room the client interface shouldn't allow him to try and send a Public Message, which in turn would not cause the error.

You can easily fix the problem by properly handling the ROOM_JOIN_ERROR event.

I will check your game as soon as possible.

cheers

[rewb0rn]

Sorry I think my last post was unclear. The message logging was set to INFO for the whole server. That means I got a lot of status logs with up to 1,500 users, not only for Bluebox users.

You are right about the Join Room error, but in my last post I was only talking about the IllegalStateException that seems to be happening inside the Bluebox. It's the only exception that is happening all the time, apparently independent of traffic on the server. I will check the test server soon.

Cheers

[htbn_hoang]

Hi,

I got the same error after upgrading to 2.9. We have 7190 errors after ~23 hours. CCU max: 1188, CCU Avg: 729.

Code: Select all

13 Aug 2014 | 20:44:52,364 | WARN  | SocketWriter-3 | bitswarm.core.SocketWriter |     | Problems in SocketWriter main loop, Thread: Thread[SocketWriter-3,5,main]
13 Aug 2014 | 20:44:52,365 | WARN  | SocketWriter-3 | bitswarm.core.SocketWriter |     | java.lang.IllegalStateException: AsyncContext#dispath s=ASYNCWAIT i=false a=DISPATCH
	org.eclipse.jetty.server.HttpChannelState.dispatch(HttpChannelState.java:352)
	org.eclipse.jetty.server.AsyncContextState.dispatch(AsyncContextState.java:114)
	org.eclipse.jetty.continuation.Servlet3Continuation.resume(Servlet3Continuation.java:139)
	sfs2x.bluebox.v3.data.BBClient.enqueueMessage(BBClient.java:80)
	com.smartfoxserver.bitswarm.core.SocketWriter.processBlueBoxSession(SocketWriter.java:242)
	com.smartfoxserver.bitswarm.core.SocketWriter.processSessionQueue(SocketWriter.java:208)
	com.smartfoxserver.bitswarm.core.SocketWriter.run(SocketWriter.java:181)
	java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
	java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
	java.lang.Thread.run(Unknown Source)

Code: Select all

13 Aug 2014 | 20:44:21,178 | WARN  | SocketWriter-3 | bitswarm.core.SocketWriter |     | Problems in SocketWriter main loop, Thread: Thread[SocketWriter-3,5,main]
13 Aug 2014 | 20:44:21,181 | WARN  | SocketWriter-3 | bitswarm.core.SocketWriter |     | java.lang.IllegalStateException: AsyncContext#dispath s=DISPATCHED i=false a=null
	org.eclipse.jetty.server.HttpChannelState.dispatch(HttpChannelState.java:352)
	org.eclipse.jetty.server.AsyncContextState.dispatch(AsyncContextState.java:114)
	org.eclipse.jetty.continuation.Servlet3Continuation.resume(Servlet3Continuation.java:139)
	sfs2x.bluebox.v3.data.BBClient.enqueueMessage(BBClient.java:80)
	com.smartfoxserver.bitswarm.core.SocketWriter.processBlueBoxSession(SocketWriter.java:242)
	com.smartfoxserver.bitswarm.core.SocketWriter.processSessionQueue(SocketWriter.java:208)
	com.smartfoxserver.bitswarm.core.SocketWriter.run(SocketWriter.java:181)
	java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
	java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
	java.lang.Thread.run(Unknown Source)

If you need any other information, please let me know.

[htbn_hoang]

Hi, me again,

I've found 2 new errors. Maybe they relate to this issue.

Code: Select all

13 Aug 2014 | 16:08:40,752 | WARN  | SocketWriter-2 | bitswarm.core.SocketWriter |     | java.lang.IllegalStateException
	org.eclipse.jetty.continuation.Servlet3Continuation.resume(Servlet3Continuation.java:137)
	sfs2x.bluebox.v3.data.BBClient.enqueueMessage(BBClient.java:80)
	com.smartfoxserver.bitswarm.core.SocketWriter.processBlueBoxSession(SocketWriter.java:242)
	com.smartfoxserver.bitswarm.core.SocketWriter.processSessionQueue(SocketWriter.java:208)
	com.smartfoxserver.bitswarm.core.SocketWriter.run(SocketWriter.java:181)
	java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
	java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
	java.lang.Thread.run(Unknown Source)

Code: Select all

13 Aug 2014 | 18:25:15,982 | WARN  | qtp340967256-1603 | jetty.servlet.ServletHandler |     | /BlueBox/BlueBox.do
java.lang.IllegalStateException
	at org.eclipse.jetty.continuation.Servlet3Continuation.resume(Servlet3Continuation.java:137)
	at sfs2x.bluebox.v3.data.BBClient.setSuspendedRequest(BBClient.java:224)
	at sfs2x.bluebox.v3.BlueBox.handlePollingRequest(BlueBox.java:216)
	at sfs2x.bluebox.v3.BlueBox.doPost(BlueBox.java:123)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:717)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1644)
	at org.eclipse.jetty.websocket.server.WebSocketUpgradeFilter.doFilter(WebSocketUpgradeFilter.java:164)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1615)
	at sfs2x.bluebox.v3.SessionFilter.doFilter(SessionFilter.java:124)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1615)
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:550)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:568)
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:221)
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1110)
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:479)
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:183)
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1044)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
	at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:199)
	at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:109)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)
	at org.eclipse.jetty.server.Server.handle(Server.java:459)
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:281)
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:232)
	at org.eclipse.jetty.io.AbstractConnection$1.run(AbstractConnection.java:505)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:607)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:536)
	at java.lang.Thread.run(Unknown Source)

BR

[Lapo]

I have no idea. Two errors can simply indicate a network issue from the client side.
Not that all server side errors indicate an actual problem, they may just show a temporary issue with a specific client or in a specific context.

On the other hand If you find frequent exceptions of the same type it would be worth investigating. If that's the case please open a new thread so that we can treat each case individually.

Thanks

[rewb0rn]

Hey Lapo I sent you a private message.

I just deployed the SFS 2.9.0 on my test server and noticed something odd: I am using 2 IP addresses on each of my machines. The first was used by the apache web server on ports 80 and 443, the 2nd IP is used by the Smartfox on port 80 for regular connections and port 443 for Jetty (Bluebox).

On my Smartfox live server, the first IP is actually not used at all, because no apache is running. On my testserver however, the first IP is used by the apache on both ports 80 and 443. Now when I set up Jetty on the test server to use port 443 and I restart the server, I get these errors:

Code: Select all

14 Aug 2014 | 19:09:30,260 | WARN  | main | util.component.AbstractLifeCycle |     | FAILED ServerConnector@3b9ec8ff{HTTP/1.1}{0.0.0.0:443}: java.net.BindException: Address already in use
java.net.BindException: Address already in use
	at sun.nio.ch.Net.bind0(Native Method)
	at sun.nio.ch.Net.bind(Unknown Source)
	at sun.nio.ch.Net.bind(Unknown Source)
	at sun.nio.ch.ServerSocketChannelImpl.bind(Unknown Source)
	at sun.nio.ch.ServerSocketAdaptor.bind(Unknown Source)
	at org.eclipse.jetty.server.ServerConnector.open(ServerConnector.java:279)
	at org.eclipse.jetty.server.AbstractNetworkConnector.doStart(AbstractNetworkConnector.java:80)
	at org.eclipse.jetty.server.ServerConnector.doStart(ServerConnector.java:218)
	at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:69)
	at org.eclipse.jetty.server.Server.doStart(Server.java:336)
	at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:69)
	at org.eclipse.jetty.xml.XmlConfiguration$1.run(XmlConfiguration.java:1250)
	at java.security.AccessController.doPrivileged(Native Method)
	at org.eclipse.jetty.xml.XmlConfiguration.main(XmlConfiguration.java:1174)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
	at java.lang.reflect.Method.invoke(Unknown Source)
	at org.eclipse.jetty.start.Main.invokeMain(Main.java:297)
	at org.eclipse.jetty.start.Main.start(Main.java:724)
	at org.eclipse.jetty.start.Main.main(Main.java:103)
	at com.smartfoxserver.v2.http.JettyServer.start(JettyServer.java:35)
	at com.smartfoxserver.v2.SmartFoxServer.start(SmartFoxServer.java:295)
	at com.smartfoxserver.v2.Main.main(Main.java:27)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
	at java.lang.reflect.Method.invoke(Unknown Source)
	at com.exe4j.runtime.LauncherEngine.launch(Unknown Source)
	at com.install4j.runtime.launcher.Launcher.main(Unknown Source)
14 Aug 2014 | 19:09:30,261 | WARN  | main | util.component.AbstractLifeCycle |     | FAILED org.eclipse.jetty.server.Server@7ca90a8f: java.net.BindException: Address already in use
java.net.BindException: Address already in use
	at sun.nio.ch.Net.bind0(Native Method)
	at sun.nio.ch.Net.bind(Unknown Source)
	at sun.nio.ch.Net.bind(Unknown Source)
	at sun.nio.ch.ServerSocketChannelImpl.bind(Unknown Source)
	at sun.nio.ch.ServerSocketAdaptor.bind(Unknown Source)
	at org.eclipse.jetty.server.ServerConnector.open(ServerConnector.java:279)
	at org.eclipse.jetty.server.AbstractNetworkConnector.doStart(AbstractNetworkConnector.java:80)
	at org.eclipse.jetty.server.ServerConnector.doStart(ServerConnector.java:218)
	at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:69)
	at org.eclipse.jetty.server.Server.doStart(Server.java:336)
	at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:69)
	at org.eclipse.jetty.xml.XmlConfiguration$1.run(XmlConfiguration.java:1250)
	at java.security.AccessController.doPrivileged(Native Method)
	at org.eclipse.jetty.xml.XmlConfiguration.main(XmlConfiguration.java:1174)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
	at java.lang.reflect.Method.invoke(Unknown Source)
	at org.eclipse.jetty.start.Main.invokeMain(Main.java:297)
	at org.eclipse.jetty.start.Main.start(Main.java:724)
	at org.eclipse.jetty.start.Main.main(Main.java:103)
	at com.smartfoxserver.v2.http.JettyServer.start(JettyServer.java:35)
	at com.smartfoxserver.v2.SmartFoxServer.start(SmartFoxServer.java:295)
	at com.smartfoxserver.v2.Main.main(Main.java:27)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
	at java.lang.reflect.Method.invoke(Unknown Source)
	at com.exe4j.runtime.LauncherEngine.launch(Unknown Source)
	at com.install4j.runtime.launcher.Launcher.main(Unknown Source)
14 Aug 2014 | 19:09:30,264 | WARN  | SFS2X ShutdownHook | v2.core.SFSShutdownHook |     | SFS2X is shutting down. The process may take a few seconds..

That means Jetty tries to bind to the wrong IP (the one that is used by apache). A quick test turns out that on my live server, Jetty actually binds to BOTH IPs. I can enter both IPs on the browser to connect to the admin tool. Could this be a reason for the exceptions we are seeing? @htbn_hoang Can you confirm that you also use 2 IPs on your server?

In any case, Jetty should be configurable to bind to a specific IP again. In some scenarios (with apache) Bluebox would not be accessible.

[htbn_hoang]

@Lapo, if they do not relate to this issue, just forget it.
@rewb0rn, we have only 1 IP for our server.

Here is some detail of our setup (on same server), hope it help:
- OS: CentOS 7
- Oracle JDK 8
- 2 Tomcat 8 instances
- SmartFox 2.9 instance
- haproxy 1.5 (forward BlueBox request to SmartFox)

[Lapo]

- haproxy 1.5 (forward BlueBox request to SmartFox)

Interesting, I hope this one is not causing the BlueBox to fail.
What does it do?
Would it be possible to bypass it?

I ask because the BlueBox uses HTTP continuations and I can't be sure that something in between client and server is not interfering...