After 2.9.0 upgrade: IllegalStateException: AsyncContext

[rewb0rn]

Hey Lapo,

did you read my last post? Could there be a connection between the exceptions and SFS running on 2nd IP with Jetty binding to both IPs? Any plans to provide a config setting to bind Jetty to a specific IP like we could with SFS 2.7.0?

Thanks,
Ruben

[htbn_hoang]

Lapo,

Cause we have several application servers on same VPS, and all of them require port 80, we use haproxy to dispatch request to corresponding application server. It does not manipulate / alter anything.

This is the same setup (except OS - gentoo -> CentOS) we used with 2.8.5 and they were good.

[Lapo]

Hey Lapo,

did you read my last post? Could there be a connection between the exceptions and SFS running on 2nd IP with Jetty binding to both IPs? Any plans to provide a config setting to bind Jetty to a specific IP like we could with SFS 2.7.0?

You can still do the same, by editing the file: lib/jetty/etc/jetty-http.xml

Add your IP address at this line:

<Set name="host"><Property name="jetty.host" default="1.2.3.4"/></Set>

Hope it helps

[rewb0rn]

Okay I bound jetty to the correct IP again, but the IllegalStateExceptions are still thrown.. Any other ideas are welcome..

[Lapo]

Which IllegalStateException exactly?
In your opening post you showed two.

thanks

[rewb0rn]

Sorry my bad. The logs are floated with these exceptions, they occur every couple of seconds:

Code: Select all

28 Aug 2014 | 15:27:43,833 | WARN  | SocketWriter-3 | bitswarm.core.SocketWriter |     | Problems in SocketWriter main loop, Thread: Thread[SocketWriter-3,5,main]
28 Aug 2014 | 15:27:43,834 | 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)

28 Aug 2014 | 15:27:46,783 | WARN  | SocketWriter-3 | bitswarm.core.SocketWriter |     | Problems in SocketWriter main loop, Thread: Thread[SocketWriter-3,5,main]
28 Aug 2014 | 15:27:46,784 | 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)

28 Aug 2014 | 15:27:50,487 | WARN  | SocketWriter-1 | bitswarm.core.SocketWriter |     | Problems in SocketWriter main loop, Thread: Thread[SocketWriter-1,5,main]
28 Aug 2014 | 15:27:50,487 | WARN  | SocketWriter-1 | 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)

[Lapo]

It's difficult to say what this is all about because it's not part of our codebase, but it comes from the Jetty library.
I gave a quick look at the source code of the class indicated by the stack trace and it seems that the error is caused by an unexpected state of the connection, although the message itself is rather cryptic.

This may suggest that messages that are sent asynchronously to a client that is already disconnected may cause this error to appear while in reality it does no harm. It's just an hypothesis and above all we haven't seen this error before. Neither in our local tests, nor in our online tests. So it may be due to a similar specific condition due to the asynch nature of the communication.

Have you tried connecting with your own client via BlueBox and see if the same error is generate? It would be interesting to see if you could cause the error to show up and see if it's a byproduct of a disconnection or if it really affects the user's connection.

Thanks

[rewb0rn]

Hello,

I made some changes and I noticed that changing the port in lib/jetty/etc/jetty-http.xml does not affect the http port shown the admin panel under server configurator -> web server after a restart. Is this a different setting? Where can I persist the jetty port other than manually in the admin panel?

Thanks,
Ruben

[Lapo]

Under start.d/
Files: http.ini and https.ini

cheers

[rewb0rn]

Thanks,

so I moved to a completely fresh server with Ubuntu 12.04. This time it is a VM with only one IP, before it was a dedicated machine with 2 IPs. The problem still persists, I receive said exception in the logs every couple of seconds when there is traffic on the server. This time I can provide detailed migration steps, maybe you have an idea or time to reproduce the issue:

- I installed munin, fail2ban and denyhosts on the machine
- I installed SFS2X-2.9.0 and executed these steps:
-----------------------------------------
copy extension to SFS2X/extensions
copy zone files to SFS2X/zones (multiple zones share one extension, but I dont think this would cause the issue?)
copy wordsFile.txt to SFS2X/config

change ulimit: vim /etc/security/limits.conf
root soft nofile 20000
root hard nofile 60000
reboot machine

setup SFS2X in SFS2X/config/server.xml
<socket address="[IP]" port="80" type="TCP"/>
<socket address="[IP]" port="9933" type="TCP"/>
<socket address="[IP]" port="80" type="UDP"/>

<adminUser>
<login>[USER]</login>
<password>[PW]</password>
</adminUser>

<userMaxIdleTime>1200</userMaxIdleTime>
<useDebugMode>false</useDebugMode>

setup jetty in SFS2X/lib/jetty/start.d/http.ini (port and host)

setup logger in SFS2X/config/log4f.properties
log4j.appender.fileAppender.DatePattern ='.'yyyy-MM-dd

log4j.category.com.smartfoxserver=WARN,fileAppender
log4j.category.org.apache=WARN,fileAppender
log4j.category.org.apache.http=WARN,fileAppender
log4j.category.org.eclipse.jetty=WARN,fileAppender
log4j.category.bootLogger=DEBUG,bootFileAppender
log4j.category.sfs2x=WARN,fileAppender
log4j.category.Extensions=WARN,fileAppender
log4j.category.hsqldb.db=WARN,fileAppender
log4j.category.jndi=WARN,fileAppender

start server and login to admin panel
add license and restart
----------------------------------

Let me know if that helps.
Thanks,
Ruben

[Lapo]

Do you still have the proxy in front of the server?
Does this exception correlate with any problem on the client activity? Have you tried connecting via BlueBox and see if there's any problem?

We need a way to reproduce the problem in order to investigate. If you have any other clues please let me know.

[rewb0rn]

Hey Lapo,

I never had any proxy set up, that was htbn_hoang. I can connect to BlueBox just fine, I have no problems to play the game through BlueBox and I am not aware of any user complaints related to this.

Cheers,
Ruben

[Lapo]

Hey Lapo,

I never had any proxy set up, that was htbn_hoang. I can connect to BlueBox just fine, I have no problems to play the game through BlueBox and I am not aware of any user complaints related to this.

Ok. When testing your game/app locally do you also see the same error(s)?

Thanks

[rewb0rn]

Hi Lapo,

I wrote a simple bot that logs into my zone, joins a game and plays until the end and then repeats. Testing with 50 of those bots simulatenously through Bluebox, I am unable to reproduce the exception on my windows machine. However, when I test on one of the Ubuntu machines, I can produce several of those exceptions. They do not occur on every action and so far seem to pop up randomly.

[Lapo]

Thanks for the update. Pretty weird behavior. Oddly enough all of our tests are run under Linux but we haven't seen any of those errors in our test sessions.
We'll investigate some more.