connection issue : session created/dropped but login failed

[moranil]

we have recently facing issue that smartfox server stops connecting
users after some network glitches, even admin console login does not success.

It does not seems related to connection issue reported in forum, where custom login is
used.

hardware: 16 core server machine using only one core at any time.
software: SFS2x rc3, using custom login, have set setThreadPoolSize to 5.
-less than 50 users were connected, this problem is seen recently.
-our client once logged in sends keepalive msg to server(zone extension) every 5 seconds.
-force logout is enabled.
-we have implemented auto reconnect if sfs HRC does not success(session idle timeout 20sec)
-we create new sfs object and try to autologin to server after disconnection is detected
-auto login giveup after 4 retries.

Problem:
(see logs at http://filebin.ca/7ca0foOuU3Y/smartfox.txt)
(alternate : http://pastebin.com/8MbjBRw2 )

-04 Jul 2012 14:06:54 : everything was correct.
-04 Jul 2012 14:07:09 : no logs for about 15 seconds
-04 Jul 2012 14:07:09 : UserReconnectionTry event received by server for different users

-04 Jul 2012 14:07:11 : it received user login request and detected that user is already loggedin so disconnecting
previous instance, but in logs it disconnected the new sessions

User already logged in. Disconnecting previous instance : ( User Name: pankak, Id: 525, Priv: 0, Sess: 180.148.43.229:3942 )
Session removed: { Id: 835, Type: DEFAULT, Logged: Yes, IP: 180.148.43.229:3942 }
User: pankak was disconnected.
Login in, { Zone: PkKingZone }, ( User Name: pankak, Id: 534, Priv: 0, Sess: 180.148.43.229:3941 )

-04 Jul 2012 14:07:12 : UserReconnectionSuccess event received for few users

04 Jul 2012 14:08:52,182 : session created
04 Jul 2012 14:08:52,254 : session removed

after this condition, we try to login, but login does not success,
all it shows that session is being created, removed, but does not perform the login.
some of the session are being dropped at the same time they are created.

even admin consol login not working, have to restart the smartfox server.

attaching the smartfox.txt(.txt attachement not allowed??)
(see logs at http://filebin.ca/7ca0foOuU3Y/smartfox.txt)
http://pastebin.com/8MbjBRw2

[Lapo]

Question, are you using a custom login handler?
If so the first thing to check is that you really close the database connections. If you don't this is the first problem that can happen.
So please do check that and when the problem occurs please perform a thread dump.
http://forums.smartfoxserver.com/viewto ... 18&t=14458

[moranil]

Thanks for the reply.

yes we are using custom login handler( using hibernate ). and hibernate session is being closed.
sessions are created /closed but login handler is not being called when this occurs. This happened on our server twice yesterday.

does having custom login, also explain why we were not able to login to admin console?
is there any know issue related to this that have been fixed in smartfox 2x final.(we are still using 2x RC3)?
we were trying to reproduce this problem but not able to?

second time it occured after few minutes of server restart.
will take thread dump if the problem occurs.

it seems that smartfox stopped firing timer /scheduled event

Server OS: CentOs, 16 core CPU, 16GB RAM, smartfox, mysql, apache on same server, only 50 users connected

[Lapo]

does having custom login, also explain why we were not able to login to admin console?

Yes it does

is there any know issue related to this that have been fixed in smartfox 2x final.(we are still using 2x RC3)?

So many things have been fixed, added and improved since RC3, please make sure to update.
If the problem will persist after the update please provide the thread dump

[moranil]

we have same problem again. here is the thread dump (blocked threads only)

2012-07-26 16:00:27
Full thread dump Java HotSpot(TM) Server VM (17.0-b16 mixed mode):

"RMI TCP Connection(4)-127.0.0.1" daemon prio=10 tid=0xb6acbc00 nid=0x1d89 runnable [0x6e032000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(Unknown Source)
at java.io.BufferedInputStream.fill(Unknown Source)
at java.io.BufferedInputStream.read(Unknown Source)
- locked <0x772503b0> (a java.io.BufferedInputStream)
at java.io.FilterInputStream.read(Unknown Source)
at sun.rmi.transport.tcp.TCPTransport.handleMessages(Unknown Source)
at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(Unknown Source)
at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)



"com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#1" daemon prio=10 tid=0x72260400 nid=0x4eea in Object.wait() [0x7045c000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x76acbc58> (a com.mchange.v2.async.ThreadPoolAsynchronousRunner)
at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:534)
- locked <0x76acbc58> (a com.mchange.v2.async.ThreadPoolAsynchronousRunner)


"pool-1-thread-5" prio=10 tid=0x08d44400 nid=0xaea in Object.wait() [0x6e3fe000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x76acdb10> (a com.mchange.v2.resourcepool.BasicResourcePool)
at com.mchange.v2.resourcepool.BasicResourcePool.prelimCheckoutResource(BasicResourcePool.java:579)
- locked <0x76acdb10> (a com.mchange.v2.resourcepool.BasicResourcePool)
at com.mchange.v2.resourcepool.BasicResourcePool.checkoutResource(BasicResourcePool.java:477)
at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:525)
at com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getConnection(AbstractPoolBackedDataSource.java:128)
at org.hibernate.connection.C3P0ConnectionProvider.getConnection(C3P0ConnectionProvider.java:56)
at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:423)
at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:144)
at org.hibernate.jdbc.JDBCContext.connection(JDBCContext.java:119)
at org.hibernate.transaction.JDBCTransaction.begin(JDBCTransaction.java:57)
at org.hibernate.impl.SessionImpl.beginTransaction(SessionImpl.java:1326)
at db.util.CpUserAccountUtil.startTransaction(CpUserAccountUtil.java:609)
at extensions.games.main.UserLoginHandler.handleServerEvent(UserLoginHandler.java:71)
at com.smartfoxserver.v2.extensions.SFSExtension.handleServerEvent(SFSExtension.java:242)
at com.smartfoxserver.v2.entities.managers.SFSExtensionManager.dispatchEvent(SFSExtensionManager.java:760)
at com.smartfoxserver.v2.entities.managers.SFSExtensionManager.dispatchZoneLevelEvent(SFSExtensionManager.java:685)
at com.smartfoxserver.v2.entities.managers.SFSExtensionManager.handleServerEvent(SFSExtensionManager.java:878)
at com.smartfoxserver.v2.core.SFSEventManager$SFSEventRunner.run(SFSEventManager.java:64)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)

"pool-1-thread-4" prio=10 tid=0x6ed10400 nid=0xae9 in Object.wait() [0x6e55c000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x76acdb10> (a com.mchange.v2.resourcepool.BasicResourcePool)
at com.mchange.v2.resourcepool.BasicResourcePool.prelimCheckoutResource(BasicResourcePool.java:579)
- locked <0x76acdb10> (a com.mchange.v2.resourcepool.BasicResourcePool)
at com.mchange.v2.resourcepool.BasicResourcePool.checkoutResource(BasicResourcePool.java:477)
at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:525)
at com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getConnection(AbstractPoolBackedDataSource.java:128)
at org.hibernate.connection.C3P0ConnectionProvider.getConnection(C3P0ConnectionProvider.java:56)
at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:423)
at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:144)
at org.hibernate.jdbc.JDBCContext.connection(JDBCContext.java:119)
at org.hibernate.transaction.JDBCTransaction.begin(JDBCTransaction.java:57)
at org.hibernate.impl.SessionImpl.beginTransaction(SessionImpl.java:1326)
at db.util.CpUserAccountUtil.startTransaction(CpUserAccountUtil.java:609)
at extensions.games.main.UserLoginHandler.handleServerEvent(UserLoginHandler.java:71)
at com.smartfoxserver.v2.extensions.SFSExtension.handleServerEvent(SFSExtension.java:242)
at com.smartfoxserver.v2.entities.managers.SFSExtensionManager.dispatchEvent(SFSExtensionManager.java:760)
at com.smartfoxserver.v2.entities.managers.SFSExtensionManager.dispatchZoneLevelEvent(SFSExtensionManager.java:685)
at com.smartfoxserver.v2.entities.managers.SFSExtensionManager.handleServerEvent(SFSExtensionManager.java:878)
at com.smartfoxserver.v2.core.SFSEventManager$SFSEventRunner.run(SFSEventManager.java:64)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)


"SocketAcceptor-1" prio=10 tid=0x6ed68800 nid=0x6e3 runnable [0x6e918000]
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
at sun.nio.ch.EPollArrayWrapper.poll(Unknown Source)
at sun.nio.ch.EPollSelectorImpl.doSelect(Unknown Source)
at sun.nio.ch.SelectorImpl.lockAndDoSelect(Unknown Source)
- locked <0x76ea8320> (a sun.nio.ch.Util$1)
- locked <0x76ea8310> (a java.util.Collections$UnmodifiableSet)
- locked <0x76ea7ef8> (a sun.nio.ch.EPollSelectorImpl)
at sun.nio.ch.SelectorImpl.select(Unknown Source)
at sun.nio.ch.SelectorImpl.select(Unknown Source)
at com.smartfoxserver.bitswarm.core.SocketAcceptor.acceptLoop(SocketAcceptor.java:175)
at com.smartfoxserver.bitswarm.core.SocketAcceptor.run(SocketAcceptor.java:154)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)


"Thread-5" daemon prio=10 tid=0x70d72000 nid=0x6b9 waiting on condition [0x70cad000]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at org.apache.commons.vfs.impl.DefaultFileMonitor.run(DefaultFileMonitor.java:404)
at java.lang.Thread.run(Unknown Source)

[Lapo]

Hi, I have already replied via email.
Let's avoid double posts.
Thanks

[moranil]

[Update]
after debug it was found that the connection pool of db got struck sometimes.
change log for c3p0 library shows that there were some deadlock in older version.
after upgrading the c3p0 and mysql connector/j the issue was not seen again.

[Lapo]

Excellent!