forums.smartfoxserver.com

Occasionally, request handlers registered with addRequestHandler() do not fore. A scenario under which we have this was like follows
1. Client logs in and sends a message
2. Server receives the message but fails to forward to registered request handler
3. A built in timer we have in the client notices that there is no response and eventually logs the client out.

The logs below capture what is happening. Normally, message on the server result in calls to com.smartfoxserver.v2.controllers.ExtensionController but
that just does not happen here.

In the normal run below (we include only the server log) you see the login at 22:10:07,408 then we send a message of type 3 at 22:10:07,444. At 22:10:07,445 we see logging from v2.controllers.ExtensionController and then from our handler (jewelsx2.sfs2x.TimingHandler).

In the abnormal run, we see log in at 22:10:13,833 followed by our message of type 3 at 22:10:13,932. However, we don't see any logging from ExtensionController nor do we see logging from our handler. Two seconds later, a logout is observed as the client times out.

Your help is appreciated!



*** NORMAL RUN ***

=================================================================================
Server log :
26 Oct 2012 | 22:10:07,408 | DEBUG | com.smartfoxserver.v2.controllers.SystemController-1 | v2.controllers.SystemController | | {IN}: Login
26 Oct 2012 | 22:10:07,408 | DEBUG | com.smartfoxserver.v2.controllers.SystemController-1 | v2.controllers.SystemController | | {IN}: Login
26 Oct 2012 | 22:10:07,409 | INFO | com.smartfoxserver.v2.controllers.SystemController-1 | v2.api.SFSApi | | User login: { Zone: JewelsX2 }, ( User Name: u9, Id: 2, Priv: 0, Sess: 69.196.158.220:36438 ) , T
ype: FlashPlayer:PlugIn:WIN 11,3,300,271
26 Oct 2012 | 22:10:07,409 | INFO | com.smartfoxserver.v2.controllers.SystemController-1 | v2.api.SFSApi | | User login: { Zone: JewelsX2 }, ( User Name: u9, Id: 2, Priv: 0, Sess: 69.196.158.220:36438 ) , T
ype: FlashPlayer:PlugIn:WIN 11,3,300,271
26 Oct 2012 | 22:10:07,409 | DEBUG | com.smartfoxserver.v2.controllers.SystemController-1 | v2.protocol.SFSProtocolCodec | | {OUT}: Login
26 Oct 2012 | 22:10:07,409 | DEBUG | com.smartfoxserver.v2.controllers.SystemController-1 | v2.protocol.SFSProtocolCodec | | {OUT}: Login
26 Oct 2012 | 22:10:07,409 | DEBUG | com.smartfoxserver.v2.controllers.SystemController-1 | protocol.binary.BinaryIoHandler | | Binary size: 77
80 00 4A 12 00 03 00 01 61 03 00 01 00 01 63 02 ..J.....a.....c.
00 00 01 70 12 00 06 00 02 72 6C 11 00 00 00 02 ...p.....rl.....
7A 6E 08 00 08 4A 65 77 65 6C 73 58 32 00 02 72 zn...JewelsX2..r
73 03 00 00 00 02 75 6E 08 00 02 75 39 00 02 69 s.....un...u9..i
64 04 00 00 00 02 00 02 70 69 03 00 00 d.......pi...

26 Oct 2012 | 22:10:07,409 | DEBUG | com.smartfoxserver.v2.controllers.SystemController-1 | protocol.binary.BinaryIoHandler | | Binary size: 77
80 00 4A 12 00 03 00 01 61 03 00 01 00 01 63 02 ..J.....a.....c.
00 00 01 70 12 00 06 00 02 72 6C 11 00 00 00 02 ...p.....rl.....
7A 6E 08 00 08 4A 65 77 65 6C 73 58 32 00 02 72 zn...JewelsX2..r
73 03 00 00 00 02 75 6E 08 00 02 75 39 00 02 69 s.....un...u9..i
64 04 00 00 00 02 00 02 70 69 03 00 00 d.......pi...

26 Oct 2012 | 22:10:07,444 | DEBUG | SocketReader | protocol.binary.BinaryIoHandler | | Binary size: 44
80 00 29 12 00 03 00 01 70 12 00 03 00 01 72 04 ..).....p.....r.
FF FF FF FF 00 01 70 12 00 00 00 01 63 08 00 01 ......p.....c...
33 00 01 63 02 01 00 01 61 03 00 0D 3..c....a...

26 Oct 2012 | 22:10:07,444 | DEBUG | SocketReader | protocol.binary.BinaryIoHandler | | Binary size: 44
80 00 29 12 00 03 00 01 70 12 00 03 00 01 72 04 ..).....p.....r.
FF FF FF FF 00 01 70 12 00 00 00 01 63 08 00 01 ......p.....c...
33 00 01 63 02 01 00 01 61 03 00 0D 3..c....a...

26 Oct 2012 | 22:10:07,444 | DEBUG | SocketReader | protocol.binary.BinaryIoHandler | | STATE: WAIT_NEW_PACKET
26 Oct 2012 | 22:10:07,444 | DEBUG | SocketReader | protocol.binary.BinaryIoHandler | | STATE: WAIT_NEW_PACKET
26 Oct 2012 | 22:10:07,444 | DEBUG | SocketReader | protocol.binary.BinaryIoHandler | | NORMAL SIZED PACKET: 41
26 Oct 2012 | 22:10:07,444 | DEBUG | SocketReader | protocol.binary.BinaryIoHandler | | NORMAL SIZED PACKET: 41
26 Oct 2012 | 22:10:07,445 | DEBUG | SocketReader | protocol.binary.BinaryIoHandler | | <<< PACKET COMPLETE >>>
26 Oct 2012 | 22:10:07,445 | DEBUG | SocketReader | protocol.binary.BinaryIoHandler | | <<< PACKET COMPLETE >>>
26 Oct 2012 | 22:10:07,445 | DEBUG | SocketReader | v2.protocol.SFSProtocolCodec | |
(short) a: 13
(byte) c: 1
(sfs_object) p:
(int) r: -1
(utf_string) c: 3
(sfs_object) p:
26 Oct 2012 | 22:10:07,445 | DEBUG | SocketReader | v2.protocol.SFSProtocolCodec | |
(short) a: 13
(byte) c: 1
(sfs_object) p:
(int) r: -1
(utf_string) c: 3
(sfs_object) p:






26 Oct 2012 | 22:10:07,445 | DEBUG | com.smartfoxserver.v2.controllers.ExtensionController-2 | v2.controllers.ExtensionController | | [Req Type: (Tcp), Prt: { NORMAL }, Sender: { Id: 3, Type: DEFAULT, Logged: Yes, IP: 69.196.158.220:36438 }]
26 Oct 2012 | 22:10:07,445 | DEBUG | com.smartfoxserver.v2.controllers.ExtensionController-2 | v2.controllers.ExtensionController | | [Req Type: (Tcp), Prt: { NORMAL }, Sender: { Id: 3, Type: DEFAULT, Logged: Yes, IP: 69.196.158.220:36438 }]
26 Oct 2012 | 22:10:07,446 | DEBUG | com.smartfoxserver.v2.controllers.ExtensionController-2 | v2.controllers.ExtensionController | |
(int) r: -1
(utf_string) c: 3
(sfs_object) p:




26 Oct 2012 | 22:10:07,446 | DEBUG | com.smartfoxserver.v2.controllers.ExtensionController-2 | v2.controllers.ExtensionController | |
(int) r: -1
(utf_string) c: 3
(sfs_object) p:




26 Oct 2012 | 22:10:07,446 | DEBUG | com.smartfoxserver.v2.controllers.ExtensionController-2 | jewelsx2.sfs2x.TimingHandler | | handleClientRequest in
26 Oct 2012 | 22:10:07,446 | DEBUG | com.smartfoxserver.v2.controllers.ExtensionController-2 | jewelsx2.sfs2x.TimingHandler | | .. handleClientRequest sync in
26 Oct 2012 | 22:10:07,446 | DEBUG | com.smartfoxserver.v2.controllers.ExtensionController-2 | v2.protocol.SFSProtocolCodec | | {OUT}: CallExtension
26 Oct 2012 | 22:10:07,446 | DEBUG | com.smartfoxserver.v2.controllers.ExtensionController-2 | v2.protocol.SFSProtocolCodec | | {OUT}: CallExtension
26 Oct 2012 | 22:10:07,446 | DEBUG | com.smartfoxserver.v2.controllers.ExtensionController-2 | protocol.binary.BinaryIoHandler | | Binary size: 48
80 00 2D 12 00 03 00 01 61 03 00 0D 00 01 63 02 ..-.....a.....c.
01 00 01 70 12 00 02 00 01 63 08 00 01 33 00 01 ...p.....c...3..
70 12 00 01 00 01 62 05 00 00 01 3A 9F 20 07 D6 p.....b....:....


*** ABNORMAL RUN ***

=================================================================================
Client log :
9@18:10:13,844: SFS:info: Login { Message id: 1 }
{ Dump: }

(short) pi: 0
(short) rs: 0
(sfs_array) rl:


(utf_string) zn: JewelsX2
(int) id: 3
(utf_string) un: u9

9@18:10:13,857: SFS:info: Object going out:
(sfs_object) p:
(int) r: -1
(sfs_object) p:


(utf_string) c: 3

(byte) c: 1
(short) a: 13

9@18:10:13,858: SFS:info: Data written: Binary Size: 41
12 00 03 00 01 70 12 00 03 00 01 72 04 FF FF FF .....p.....r....
FF 00 01 70 12 00 00 00 01 63 08 00 01 33 00 01 ...p.....c...3..
63 02 01 00 01 61 03 00 0D c....a...

9@18:10:15,879: Client times out here

9@18:10:15,889: SFS:info: Object going out:
(sfs_object) p:


(byte) c: 0
(short) a: 2

9@18:10:15,890: SFS:info: Data written: Binary Size: 20
12 00 03 00 01 70 12 00 00 00 01 63 02 00 00 01 .....p.....c....
61 03 00 02 a...

9@18:10:15,891: JewelsServer::logout out
9@18:10:15,921: SFS:info: Data Read: Binary Size: 38
80 00 23 12 00 03 00 01 61 03 00 02 00 01 63 02 ..#.....a.....c.
00 00 01 70 12 00 01 00 02 7A 6E 08 00 08 4A 65 ...p.....zn...Je
77 65 6C 73 58 32 welsX2
9@18:10:15,924: SFS:debug: Handling New Packet
9@18:10:15,930: SFS:debug: Handling Header Size. Size: 37 (small)
9@18:10:15,931: SFS:debug: Handling Data: 35, previous state: 0/35
9@18:10:15,932: SFS:debug: <<< Packet Complete >>>
9@18:10:15,933: SFS:info: Logout { Message id: 2 }
{ Dump: }

(utf_string) zn: JewelsX2

==================================================

Sever log:

26 Oct 2012 | 22:10:12,183 | DEBUG | SocketReader | smartfoxserver.v2.SmartFoxServer | | []
26 Oct 2012 | 22:10:13,833 | INFO | SocketReader | bitswarm.sessions.DefaultSessionManager | | Session created: { Id: 4, Type: DEFAULT, Logged: No, IP: 69.196.158.220:12635 } on Server port: 81 <---> 12635
26 Oct 2012 | 22:10:13,845 | DEBUG | SocketReader | protocol.binary.BinaryIoHandler | | Binary size: 78
80 00 4B 12 00 03 00 01 70 12 00 02 00 03 61 70 ..K.....p.....ap
69 08 00 05 31 2E 31 2E 31 00 02 63 6C 08 00 23 i...1.1.1..cl..#
46 6C 61 73 68 50 6C 61 79 65 72 3A 50 6C 75 67 FlashPlayer:Plug
49 6E 3A 57 49 4E 20 31 31 2C 33 2C 33 30 30 2C In:WIN.11,3,300,
32 37 31 00 01 63 02 00 00 01 61 03 00 00 271..c....a...

26 Oct 2012 | 22:10:13,845 | DEBUG | SocketReader | protocol.binary.BinaryIoHandler | | Binary size: 78
80 00 4B 12 00 03 00 01 70 12 00 02 00 03 61 70 ..K.....p.....ap
69 08 00 05 31 2E 31 2E 31 00 02 63 6C 08 00 23 i...1.1.1..cl..#
46 6C 61 73 68 50 6C 61 79 65 72 3A 50 6C 75 67 FlashPlayer:Plug
49 6E 3A 57 49 4E 20 31 31 2C 33 2C 33 30 30 2C In:WIN.11,3,300,
32 37 31 00 01 63 02 00 00 01 61 03 00 00 271..c....a...

26 Oct 2012 | 22:10:13,845 | DEBUG | SocketReader | protocol.binary.BinaryIoHandler | | STATE: WAIT_NEW_PACKET
26 Oct 2012 | 22:10:13,845 | DEBUG | SocketReader | protocol.binary.BinaryIoHandler | | STATE: WAIT_NEW_PACKET
26 Oct 2012 | 22:10:13,845 | DEBUG | SocketReader | protocol.binary.BinaryIoHandler | | NORMAL SIZED PACKET: 75
26 Oct 2012 | 22:10:13,845 | DEBUG | SocketReader | protocol.binary.BinaryIoHandler | | NORMAL SIZED PACKET: 75
26 Oct 2012 | 22:10:13,846 | DEBUG | SocketReader | protocol.binary.BinaryIoHandler | | <<< PACKET COMPLETE >>>
26 Oct 2012 | 22:10:13,846 | DEBUG | SocketReader | protocol.binary.BinaryIoHandler | | <<< PACKET COMPLETE >>>
26 Oct 2012 | 22:10:13,846 | DEBUG | SocketReader | v2.protocol.SFSProtocolCodec | |
(short) a: 0
(byte) c: 0
(sfs_object) p:
(utf_string) cl: FlashPlayer:PlugIn:WIN 11,3,300,271
(utf_string) api: 1.1.1




26 Oct 2012 | 22:10:13,846 | DEBUG | SocketReader | v2.protocol.SFSProtocolCodec | |
(short) a: 0
(byte) c: 0
(sfs_object) p:
(utf_string) cl: FlashPlayer:PlugIn:WIN 11,3,300,271
(utf_string) api: 1.1.1

26 Oct 2012 | 22:10:13,846 | DEBUG | com.smartfoxserver.v2.controllers.SystemController-1 | v2.controllers.SystemController | | {IN}: Handshake
26 Oct 2012 | 22:10:13,846 | DEBUG | com.smartfoxserver.v2.controllers.SystemController-1 | v2.controllers.SystemController | | {IN}: Handshake
26 Oct 2012 | 22:10:13,846 | DEBUG | com.smartfoxserver.v2.controllers.SystemController-1 | v2.protocol.SFSProtocolCodec | | {OUT}: Handshake
26 Oct 2012 | 22:10:13,846 | DEBUG | com.smartfoxserver.v2.controllers.SystemController-1 | v2.protocol.SFSProtocolCodec | | {OUT}: Handshake
26 Oct 2012 | 22:10:13,847 | DEBUG | com.smartfoxserver.v2.controllers.SystemController-1 | protocol.binary.BinaryIoHandler | | Binary size: 80
80 00 4D 12 00 03 00 01 61 03 00 00 00 01 63 02 ..M.....a.....c.
00 00 01 70 12 00 03 00 02 74 6B 08 00 20 38 36 ...p.....tk...86
36 36 33 64 63 33 64 32 33 63 33 31 64 66 65 38 663dc3d23c31dfe8
63 64 30 36 64 36 66 31 63 37 37 63 38 38 00 02 cd06d6f1c77c88..
63 74 04 00 00 04 00 00 02 6D 73 04 00 7A 12 00 ct.......ms..z..

26 Oct 2012 | 22:10:13,847 | DEBUG | com.smartfoxserver.v2.controllers.SystemController-1 | protocol.binary.BinaryIoHandler | | Binary size: 80
80 00 4D 12 00 03 00 01 61 03 00 00 00 01 63 02 ..M.....a.....c.
00 00 01 70 12 00 03 00 02 74 6B 08 00 20 38 36 ...p.....tk...86
36 36 33 64 63 33 64 32 33 63 33 31 64 66 65 38 663dc3d23c31dfe8
63 64 30 36 64 36 66 31 63 37 37 63 38 38 00 02 cd06d6f1c77c88..
63 74 04 00 00 04 00 00 02 6D 73 04 00 7A 12 00 ct.......ms..z..

26 Oct 2012 | 22:10:13,888 | DEBUG | SocketReader | protocol.binary.BinaryIoHandler | | Binary size: 54
80 00 33 12 00 03 00 01 70 12 00 03 00 02 70 77 ..3.....p.....pw
08 00 00 00 02 75 6E 08 00 02 75 39 00 02 7A 6E .....un...u9..zn
08 00 08 4A 65 77 65 6C 73 58 32 00 01 63 02 00 ...JewelsX2..c..
00 01 61 03 00 01 ..a...

26 Oct 2012 | 22:10:13,888 | DEBUG | SocketReader | protocol.binary.BinaryIoHandler | | Binary size: 54
80 00 33 12 00 03 00 01 70 12 00 03 00 02 70 77 ..3.....p.....pw
08 00 00 00 02 75 6E 08 00 02 75 39 00 02 7A 6E .....un...u9..zn
08 00 08 4A 65 77 65 6C 73 58 32 00 01 63 02 00 ...JewelsX2..c..
00 01 61 03 00 01 ..a...

26 Oct 2012 | 22:10:13,888 | DEBUG | SocketReader | protocol.binary.BinaryIoHandler | | STATE: WAIT_NEW_PACKET
26 Oct 2012 | 22:10:13,888 | DEBUG | SocketReader | protocol.binary.BinaryIoHandler | | STATE: WAIT_NEW_PACKET
26 Oct 2012 | 22:10:13,888 | DEBUG | SocketReader | protocol.binary.BinaryIoHandler | | NORMAL SIZED PACKET: 51
26 Oct 2012 | 22:10:13,888 | DEBUG | SocketReader | protocol.binary.BinaryIoHandler | | NORMAL SIZED PACKET: 51
26 Oct 2012 | 22:10:13,889 | DEBUG | SocketReader | protocol.binary.BinaryIoHandler | | <<< PACKET COMPLETE >>>
26 Oct 2012 | 22:10:13,889 | DEBUG | SocketReader | protocol.binary.BinaryIoHandler | | <<< PACKET COMPLETE >>>
26 Oct 2012 | 22:10:13,889 | DEBUG | SocketReader | v2.protocol.SFSProtocolCodec | |
(short) a: 1
(byte) c: 0
(sfs_object) p:
(utf_string) zn: JewelsX2
(utf_string) un: u9
(utf_string) pw:

26 Oct 2012 | 22:10:13,889 | DEBUG | SocketReader | v2.protocol.SFSProtocolCodec | |
(short) a: 1
(byte) c: 0
(sfs_object) p:
(utf_string) zn: JewelsX2
(utf_string) un: u9
(utf_string) pw:



26 Oct 2012 | 22:10:13,889 | DEBUG | com.smartfoxserver.v2.controllers.SystemController-1 | v2.controllers.SystemController | | {IN}: Login
26 Oct 2012 | 22:10:13,889 | DEBUG | com.smartfoxserver.v2.controllers.SystemController-1 | v2.controllers.SystemController | | {IN}: Login
26 Oct 2012 | 22:10:13,889 | INFO | com.smartfoxserver.v2.controllers.SystemController-1 | v2.api.SFSApi | | User login: { Zone: JewelsX2 }, ( User Name: u9, Id: 3, Priv: 0, Sess: 69.196.158.220:12635 ) , Type: FlashPlayer:PlugIn:WIN 11,3,300,271
26 Oct 2012 | 22:10:13,889 | INFO | com.smartfoxserver.v2.controllers.SystemController-1 | v2.api.SFSApi | | User login: { Zone: JewelsX2 }, ( User Name: u9, Id: 3, Priv: 0, Sess: 69.196.158.220:12635 ) , Type: FlashPlayer:PlugIn:WIN 11,3,300,271
26 Oct 2012 | 22:10:13,890 | DEBUG | com.smartfoxserver.v2.controllers.SystemController-1 | v2.protocol.SFSProtocolCodec | | {OUT}: Login
26 Oct 2012 | 22:10:13,890 | DEBUG | com.smartfoxserver.v2.controllers.SystemController-1 | v2.protocol.SFSProtocolCodec | | {OUT}: Login
26 Oct 2012 | 22:10:13,890 | DEBUG | com.smartfoxserver.v2.controllers.SystemController-1 | protocol.binary.BinaryIoHandler | | Binary size: 77
80 00 4A 12 00 03 00 01 61 03 00 01 00 01 63 02 ..J.....a.....c.
00 00 01 70 12 00 06 00 02 72 6C 11 00 00 00 02 ...p.....rl.....
7A 6E 08 00 08 4A 65 77 65 6C 73 58 32 00 02 72 zn...JewelsX2..r
73 03 00 00 00 02 75 6E 08 00 02 75 39 00 02 69 s.....un...u9..i
64 04 00 00 00 03 00 02 70 69 03 00 00 d.......pi...

26 Oct 2012 | 22:10:13,890 | DEBUG | com.smartfoxserver.v2.controllers.SystemController-1 | protocol.binary.BinaryIoHandler | | Binary size: 77
80 00 4A 12 00 03 00 01 61 03 00 01 00 01 63 02 ..J.....a.....c.
00 00 01 70 12 00 06 00 02 72 6C 11 00 00 00 02 ...p.....rl.....
7A 6E 08 00 08 4A 65 77 65 6C 73 58 32 00 02 72 zn...JewelsX2..r
73 03 00 00 00 02 75 6E 08 00 02 75 39 00 02 69 s.....un...u9..i
64 04 00 00 00 03 00 02 70 69 03 00 00 d.......pi...

26 Oct 2012 | 22:10:13,931 | DEBUG | SocketReader | protocol.binary.BinaryIoHandler | | Binary size: 44
80 00 29 12 00 03 00 01 70 12 00 03 00 01 72 04 ..).....p.....r.
FF FF FF FF 00 01 70 12 00 00 00 01 63 08 00 01 ......p.....c...
33 00 01 63 02 01 00 01 61 03 00 0D 3..c....a...

26 Oct 2012 | 22:10:13,931 | DEBUG | SocketReader | protocol.binary.BinaryIoHandler | | Binary size: 44
80 00 29 12 00 03 00 01 70 12 00 03 00 01 72 04 ..).....p.....r.
FF FF FF FF 00 01 70 12 00 00 00 01 63 08 00 01 ......p.....c...
33 00 01 63 02 01 00 01 61 03 00 0D 3..c....a...

26 Oct 2012 | 22:10:13,931 | DEBUG | SocketReader | protocol.binary.BinaryIoHandler | | STATE: WAIT_NEW_PACKET
26 Oct 2012 | 22:10:13,931 | DEBUG | SocketReader | protocol.binary.BinaryIoHandler | | STATE: WAIT_NEW_PACKET
26 Oct 2012 | 22:10:13,931 | DEBUG | SocketReader | protocol.binary.BinaryIoHandler | | NORMAL SIZED PACKET: 41
26 Oct 2012 | 22:10:13,931 | DEBUG | SocketReader | protocol.binary.BinaryIoHandler | | NORMAL SIZED PACKET: 41
26 Oct 2012 | 22:10:13,932 | DEBUG | SocketReader | protocol.binary.BinaryIoHandler | | <<< PACKET COMPLETE >>>
26 Oct 2012 | 22:10:13,932 | DEBUG | SocketReader | protocol.binary.BinaryIoHandler | | <<< PACKET COMPLETE >>>
26 Oct 2012 | 22:10:13,932 | DEBUG | SocketReader | v2.protocol.SFSProtocolCodec | |
(short) a: 13
(byte) c: 1
(sfs_object) p:
(int) r: -1
(utf_string) c: 3
(sfs_object) p:

26 Oct 2012 | 22:10:13,932 | DEBUG | SocketReader | v2.protocol.SFSProtocolCodec | |
(short) a: 13
(byte) c: 1
(sfs_object) p:
(int) r: -1
(utf_string) c: 3
(sfs_object) p:


26 Oct 2012 | 22:10:15,963 | DEBUG | SocketReader | protocol.binary.BinaryIoHandler | | Binary size: 23
80 00 14 12 00 03 00 01 70 12 00 00 00 01 63 02 ........p.....c.
00 00 01 61 03 00 02 ...a...

26 Oct 2012 | 22:10:15,963 | DEBUG | SocketReader | protocol.binary.BinaryIoHandler | | Binary size: 23
80 00 14 12 00 03 00 01 70 12 00 00 00 01 63 02 ........p.....c.
00 00 01 61 03 00 02 ...a...

26 Oct 2012 | 22:10:15,963 | DEBUG | SocketReader | protocol.binary.BinaryIoHandler | | STATE: WAIT_NEW_PACKET
26 Oct 2012 | 22:10:15,963 | DEBUG | SocketReader | protocol.binary.BinaryIoHandler | | STATE: WAIT_NEW_PACKET
26 Oct 2012 | 22:10:15,963 | DEBUG | SocketReader | protocol.binary.BinaryIoHandler | | NORMAL SIZED PACKET: 20
26 Oct 2012 | 22:10:15,963 | DEBUG | SocketReader | protocol.binary.BinaryIoHandler | | NORMAL SIZED PACKET: 20
26 Oct 2012 | 22:10:15,963 | DEBUG | SocketReader | protocol.binary.BinaryIoHandler | | <<< PACKET COMPLETE >>>
26 Oct 2012 | 22:10:15,963 | DEBUG | SocketReader | protocol.binary.BinaryIoHandler | | <<< PACKET COMPLETE >>>
26 Oct 2012 | 22:10:15,963 | DEBUG | SocketReader | v2.protocol.SFSProtocolCodec | |
(short) a: 2
(byte) c: 0
(sfs_object) p:

26 Oct 2012 | 22:10:15,963 | DEBUG | SocketReader | v2.protocol.SFSProtocolCodec | |
(short) a: 2
(byte) c: 0
(sfs_object) p:

26 Oct 2012 | 22:10:15,963 | DEBUG | com.smartfoxserver.v2.controllers.SystemController-1 | v2.controllers.SystemController | | {IN}: Logout
26 Oct 2012 | 22:10:15,963 | DEBUG | com.smartfoxserver.v2.controllers.SystemController-1 | v2.controllers.SystemController | | {IN}: Logout
26 Oct 2012 | 22:10:15,964 | INFO | com.smartfoxserver.v2.controllers.SystemController-1 | v2.entities.SFSZone | | User: u9 was disconnected.
26 Oct 2012 | 22:10:15,964 | INFO | com.smartfoxserver.v2.controllers.SystemController-1 | v2.entities.SFSZone | | User: u9 was disconnected.
26 Oct 2012 | 22:10:15,965 | DEBUG | com.smartfoxserver.v2.controllers.SystemController-1 | v2.protocol.SFSProtocolCodec | | {OUT}: Logout
26 Oct 2012 | 22:10:15,965 | DEBUG | com.smartfoxserver.v2.controllers.SystemController-1 | v2.protocol.SFSProtocolCodec | | {OUT}: Logout
26 Oct 2012 | 22:10:15,965 | DEBUG | com.smartfoxserver.v2.controllers.SystemController-1 | protocol.binary.BinaryIoHandler | | Binary size: 38
80 00 23 12 00 03 00 01 61 03 00 02 00 01 63 02 ..#.....a.....c.
00 00 01 70 12 00 01 00 02 7A 6E 08 00 08 4A 65 ...p.....zn...Je
77 65 6C 73 58 32 welsX2

26 Oct 2012 | 22:10:15,965 | DEBUG | com.smartfoxserver.v2.controllers.SystemController-1 | protocol.binary.BinaryIoHandler | | Binary size: 38
80 00 23 12 00 03 00 01 61 03 00 02 00 01 63 02 ..#.....a.....c.
00 00 01 70 12 00 01 00 02 7A 6E 08 00 08 4A 65 ...p.....zn...Je
77 65 6C 73 58 32 welsX2

26 Oct 2012 | 22:10:15,965 | INFO | com.smartfoxserver.v2.controllers.SystemController-1 | v2.api.SFSApi | | User logout: { Zone: JewelsX2 }, ( User Name: u9, Id: 3, Priv: 0, Sess: 69.196.158.220:12635 ) , Type: FlashPlayer:PlugIn:WIN 11,3,300,271, SessionLen: 2076
26 Oct 2012 | 22:10:15,965 | INFO | com.smartfoxserver.v2.controllers.SystemController-1 | v2.api.SFSApi | | User logout: { Zone: JewelsX2 }, ( User Name: u9, Id: 3, Priv: 0, Sess: 69.196.158.220:12635 ) , Type: FlashPlayer:PlugIn:WIN 11,3,300,271, SessionLen: 2076
26 Oct 2012 | 22:10:15,966 | INFO | pool-1-thread-1 | Extensions | | {JewelsGame}: JewelsGame: user u9 left the server
26 Oct 2012 | 22:10:42,200 | INFO | SocketReader | bitswarm.sessions.DefaultSessionManager | | Session removed: { Id: 4, Type: DEFAULT, Logged: No, IP: 69.196.158.220:12635 }

All of the above was observed under 2.2.3
Thank you

Hi,

What OS and architecture are you running?
Is the server under some heavy load or running out of threads? That would explain why it didn't fire the requestHandler.
When do you send that message to the server? after you receive the LOGIN event?

And please do post SFS2X related questions on the SFS2X Questions forums, the Server-side Extension development forum is for SFS1X.
Thanks

Server is running CentOS 5, 64bit. There is no load at all on the server, only one request was running.

The scenario was:
1. Login (OK)
2. Send extension message - no response for 2 seconds
3. Client notices two second timeout and logs out.

Thank you,

How is your ClientRequestHandler? Do you have any Database call or something that could be hanging the thread?

The handler doesn't do anything other than report the local time on the server.

However, we know the handler isn't being called at all. We put a logging statement in the very first line of the handler and it isn't printing.

In the normal run you can see this line:
26 Oct 2012 | 22:10:07,446 | DEBUG | com.smartfoxserver.v2.controllers.ExtensionController-2 | jewelsx2.sfs2x.TimingHandler | | handleClientRequest in

In the abnormal line you will find no such line.

We were able to resolve this issue and I wanted to document our finding for everyone's benefit.

@rjgtav suggested above that our handler was taking too long to respond and hanging the thread. Although this wasn't true for this particular handler, it was in fact true for a different handler which was hanging on a connection attempt to a down server.

One hint that the problem was with totally different thread was that the game worked exactly 3 times and then stopped. The size our our thread pool is 3. The fourth game had no thread to work with since the first 3 games had their cleanup threads hung.

So thanks to @rjgtav for setting us in the right direction.

Glad it worked

Yes, usually, when a handler stops being called, is because there are no threads available. While you could simply increase the thread count, if you're running out of threads, that's because probably something is hanging it, like an offline server in your case. Another common cause for thread hanging is when the database connection pool fills up because the developer forgot to correctly close the connections and return them to the pool.