Stored procedure problem causing strange behaviour

Richard van Harten · Post by **Richard van Harten** » 02 Nov 2009, 06:42

Hello,

After receiving our Smartfox license we are trying to deploy into the real world. We are however experiencing some rather strange problems:

After some amount of time ( or after some executions we are not sure ) we are getting a 'FUNCTION x does not exist' from the database on a stored procedure when we use executeCommand on the DBManager. The function is beyond any doubt there.

On top of that, after such error the whole Smartfox server does still accepts connections from the XMLSocket inside the Smartfox client but doesn't respond anymore on the first verChk command from any client during a period of around 2 minutes.

This behaviour very strange and unpredictable, any help solving this problem would be greatly appreciated!

Post by **Lapo** » 02 Nov 2009, 09:09

Hi,
as regards the database issue it is very difficult to help without knowing what DB do you use, and seeing your code etc...

Please provide as many details as possible. See here:
http://forums.smartfoxserver.com/viewtopic.php?t=3307

Richard van Harten · Post by **Richard van Harten** » 02 Nov 2009, 09:41

1.
OS: redhat2.6.18-128.7.1.el5xen
MySQL 5.0.77
SmartFoxServer :1.66
JVM: 1.6.0_13

2. See first post

3.
- We call the procedure when handling the login
- Goes wrong sometime, if so:
- Smartfox does accept connections but does not respond to verchk command

4.

Code: Select all

[SWF] C:\Files\eccky\sources\Deployed\Simpletest\bin-debug\Simpletest.swf - 724.020 bytes after decompression
socket connected
[Sending]: <msg t='sys'><body action='verChk' r='0'><ver v='157' /></body></msg>

[ RECEIVED ]: <cross-domain-policy><allow-access-from domain='*' to-ports='9339' /></cross-domain-policy>, (len: 91)

Post by **Lapo** » 02 Nov 2009, 09:47

The fact that it goes wrong seems to depend on the database, not on SmartFox, unless your stored procedure invocation is done dynamically... in which case there could be a problem in your server side code.

Is there any way that you can reproduce the problem at will?
Is this happening with larger traffic only?
Can you report the exception that you get?
Also it would be great if you could send us a thread-dump of the JVM when the problem happens.
The thread dump in the console can be done by hitting ctrl+break (Windows) or sending kill -SIGQUIT to the process (under Linux/Unix)

Additionally if you run Java6 you could use a visual tool such as VisualVM to analyze what's going on:

https://visualvm.dev.java.net
https://visualvm.dev.java.net/description.html

Richard van Harten · Post by **Richard van Harten** » 02 Nov 2009, 10:05

The problem only seems to occur when we are trying with more than 2-3 persons. We'll try to make that dump after we tried a different mysql version.

The procedure itself is very simple:

Code: Select all

CREATE  PROCEDURE `LoginServer`(pUserName VARCHAR(128),pPassword VARCHAR(128),OUT pSuccess BIT)
BEGIN
  DECLARE theSum  INT DEFAULT -1;
  DECLARE theUid INT DEFAULT -1;
  SELECT COUNT(uid) INTO theSum FROM OnlineUser WHERE uid=pUserName AND sessionId=pPassword;
  IF (theSum = 1) THEN
    SET pSuccess = 1;
  ELSE
    SET pSuccess = 0;
  END IF;
END

This is the function handling the login:

Code: Select all

ex.trace(cmd);
		LinkedList ll = new LinkedList();
		CallableStatement cs;
		boolean ok = false;
		User newUser = null;
		String nick = ieo.getParam("nick");
		String pass = ieo.getParam("pass");
		String StrZone = ieo.getParam("zone");
		SocketChannel chan = (SocketChannel) ieo.getObject("chan");
		ex.helper.getSecretKey(chan);
		ActionscriptObject res = new ActionscriptObject();
		res.put(ex.CMD_STR,"CMD_LOGIN");		
		try
		{
			ex.trace("userName:"+nick+" password:"+pass);
			if (nick.equals("") || pass.equals("")){
				throw new LoginException("User name and password should not be empty");
			}else{
				if (!ex.con.isClosed()){
					String zoneName = ex.dbm.whichZone(nick);
					if (zoneName.length()>0){
						throw new LoginException(nick+" already login on "+zoneName);
					}
					
					cs = ex.con.prepareCall("call LoginServer(?,?,?)");
					cs.setString(1, nick);
					cs.setString(2, pass);
					cs.registerOutParameter(3, java.sql.Types.BIT);
					cs.execute();
					if (cs.getBoolean(3)){
						newUser = ex.helper.canLogin(nick, pass, chan, ex.currZone);
						int uid = newUser.getUserId();
						res.put("success", true);
						res.put("id", String.valueOf(uid));
						res.put("name", newUser.getName());
						cs = ex.con.prepareCall("call UpdateUserStatus(?,?,?,?)");
						cs.setInt(1, uid);
						cs.setString(2, nick);
						cs.setString(3, StrZone);
						cs.registerOutParameter(4, java.sql.Types.BIT);
						cs.execute();
						if (!cs.getBoolean(4)){
							throw new Exception("Executing UpdateUserStatus was failed. ");
						}
						ok = true;
						
						ActionscriptObject info = new ActionscriptObject();
						cs = ex.con.prepareCall("call GetBuddylist(?)");
						cs.setInt(1, uid);
						ResultSet rs = cs.executeQuery();
						info.put("success", true);
						info.put(ex.CMD_STR, "CMD_BUDDY_REFRESH");
						while (rs.next()){
							String buid = rs.getString("uid");
							ex.dbm.sendMsgToClient(buid, info);
						}		
					}else{
						throw new LoginException("User "+nick+" login was failed. ");
					}						
				}else{
					throw new Exception("database connection has closed!");
				}
			}
		}catch (Exception le){
			res.put("success", false);
			res.put("error", le.getMessage());
			ex.warning(cmd,"An error was occured:"+le.getMessage());	
			le.printStackTrace();
		}
		ll.add(chan);
		ex.sendResponse(res, -1, null, ll);
		if (ok)
			ex.helper.sendRoomList(chan);

The missing function error:

Code: Select all

INFO   | jvm 1    | 2009/11/01 19:57:22 | com.mysql.jdbc.exceptions.jdbc4.MySQLSyntaxErrorException: FUNCTION GetEcckyData does not exist
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at com.mysql.jdbc.Util.handleNewInstance(Util.java:406)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at com.mysql.jdbc.Util.getInstance(Util.java:381)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1031)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:957)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3376)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3308)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1837)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1961)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2537)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2466)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at com.mysql.jdbc.StatementImpl.executeQuery(StatementImpl.java:1383)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at com.mysql.jdbc.DatabaseMetaData.getCallStmtParameterTypes(DatabaseMetaData.java:1570)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at com.mysql.jdbc.DatabaseMetaData.getProcedureOrFunctionColumns(DatabaseMetaData.java:4109)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at com.mysql.jdbc.DatabaseMetaData.getProcedureColumns(DatabaseMetaData.java:4046)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at com.mysql.jdbc.CallableStatement.determineParameterTypes(CallableStatement.java:808)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at com.mysql.jdbc.CallableStatement.<init>(CallableStatement.java:612)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at com.mysql.jdbc.JDBC4CallableStatement.<init>(JDBC4CallableStatement.java:46)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at sun.reflect.GeneratedConstructorAccessor15.newInstance(Unknown Source)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at com.mysql.jdbc.Util.handleNewInstance(Util.java:406)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at com.mysql.jdbc.CallableStatement.getInstance(CallableStatement.java:513)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at com.mysql.jdbc.ConnectionImpl.parseCallableStatement(ConnectionImpl.java:3856)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at com.mysql.jdbc.ConnectionImpl.prepareCall(ConnectionImpl.java:3927)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at com.mysql.jdbc.ConnectionImpl.prepareCall(ConnectionImpl.java:3901)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at org.apache.commons.dbcp.DelegatingConnection.prepareCall(DelegatingConnection.java:212)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at org.apache.commons.dbcp.PoolingDriver$PoolGuardConnectionWrapper.prepareCall(PoolingDriver.java:328)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at com.veltive.eccky.DBManager.getEcckyData(DBManager.java:125)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at com.veltive.eccky.GetEcckyInfo.doPost(GetEcckyInfo.java:58)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:502)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:389)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:181)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:765)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:417)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:230)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at org.mortbay.jetty.handler.HandlerCollection.handle(HandlerCollection.java:114)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at org.mortbay.jetty.Server.handle(Server.java:324)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:535)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at org.mortbay.jetty.HttpConnection$RequestHandler.content(HttpConnection.java:880)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:747)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:218)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:404)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:409)
INFO   | jvm 1    | 2009/11/01 19:57:22 | 	at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool.java:451)
INFO   | jvm 1    | 2009/11/01 19:57:30 | 19:57:30.497 - [ INFO ] > getEcckyData(f438b4e623c489f3)
INFO   | jvm 1    | 2009/11/01 19:58:50 | 19:58:50.340 - [ WARNING ] > Sending mail was failed!
INFO   | jvm 1    | 2009/11/01 19:58:50 | com.mysql.jdbc.exceptions.jdbc4.MySQLSyntaxErrorException: FUNCTION LoginServer does not exist
INFO   | jvm 1    | 2009/11/01 19:58:50 | 	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
INFO   | jvm 1    | 2009/11/01 19:58:50 | 	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
INFO   | jvm 1    | 2009/11/01 19:58:50 | 	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
INFO   | jvm 1    | 2009/11/01 19:58:50 | 	at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
INFO   | jvm 1    | 2009/11/01 19:58:50 | 	at com.mysql.jdbc.Util.handleNewInstance(Util.java:406)
INFO   | jvm 1    | 2009/11/01 19:58:50 | 	at com.mysql.jdbc.Util.getInstance(Util.java:381)
INFO   | jvm 1    | 2009/11/01 19:58:50 | 	at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1031)
INFO   | jvm 1    | 2009/11/01 19:58:50 | 	at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:957)
INFO   | jvm 1    | 2009/11/01 19:58:50 | 	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3376)
INFO   | jvm 1    | 2009/11/01 19:58:50 | 	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3308)
INFO   | jvm 1    | 2009/11/01 19:58:50 | 	at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1837)
INFO   | jvm 1    | 2009/11/01 19:58:50 | 	at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1961)
INFO   | jvm 1    | 2009/11/01 19:58:50 | 	at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2537)
INFO   | jvm 1    | 2009/11/01 19:58:50 | 	at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2466)
INFO   | jvm 1    | 2009/11/01 19:58:50 | 	at com.mysql.jdbc.StatementImpl.executeQuery(StatementImpl.java:1383)
INFO   | jvm 1    | 2009/11/01 19:58:50 | 	at com.mysql.jdbc.DatabaseMetaData.getCallStmtParameterTypes(DatabaseMetaData.java:1570)
INFO   | jvm 1    | 2009/11/01 19:58:50 | 	at com.mysql.jdbc.DatabaseMetaData.getProcedureOrFunctionColumns(DatabaseMetaData.java:4109)
INFO   | jvm 1    | 2009/11/01 19:58:50 | 	at com.mysql.jdbc.DatabaseMetaData.getProcedureColumns(DatabaseMetaData.java:4046)
INFO   | jvm 1    | 2009/11/01 19:58:50 | 	at com.mysql.jdbc.CallableStatement.determineParameterTypes(CallableStatement.java:808)
INFO   | jvm 1    | 2009/11/01 19:58:50 | 	at com.mysql.jdbc.CallableStatement.<init>(CallableStatement.java:612)
INFO   | jvm 1    | 2009/11/01 19:58:50 | 	at com.mysql.jdbc.JDBC4CallableStatement.<init>(JDBC4CallableStatement.java:46)
INFO   | jvm 1    | 2009/11/01 19:58:50 | 	at sun.reflect.GeneratedConstructorAccessor15.newInstance(Unknown Source)
INFO   | jvm 1    | 2009/11/01 19:58:50 | 	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
INFO   | jvm 1    | 2009/11/01 19:58:50 | 	at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
INFO   | jvm 1    | 2009/11/01 19:58:50 | 	at com.mysql.jdbc.Util.handleNewInstance(Util.java:406)
INFO   | jvm 1    | 2009/11/01 19:58:50 | 	at com.mysql.jdbc.CallableStatement.getInstance(CallableStatement.java:513)
INFO   | jvm 1    | 2009/11/01 19:58:50 | 	at com.mysql.jdbc.ConnectionImpl.parseCallableStatement(ConnectionImpl.java:3856)
INFO   | jvm 1    | 2009/11/01 19:58:50 | 	at com.mysql.jdbc.ConnectionImpl.prepareCall(ConnectionImpl.java:3927)
INFO   | jvm 1    | 2009/11/01 19:58:50 | 	at com.mysql.jdbc.ConnectionImpl.prepareCall(ConnectionImpl.java:3901)
INFO   | jvm 1    | 2009/11/01 19:58:50 | 	at org.apache.commons.dbcp.DelegatingConnection.prepareCall(DelegatingConnection.java:212)
INFO   | jvm 1    | 2009/11/01 19:58:50 | 	at org.apache.commons.dbcp.PoolingDriver$PoolGuardConnectionWrapper.prepareCall(PoolingDriver.java:328)
INFO   | jvm 1    | 2009/11/01 19:58:50 | 	at UserLoginSFS.execute(UserLoginSFS.java:39)
INFO   | jvm 1    | 2009/11/01 19:58:50 | 	at com.veltive.eccky.EcckyExtension.handleInternalEvent(EcckyExtension.java:185)
INFO   | jvm 1    | 2009/11/01 19:58:50 | 	at it.gotoandplay.smartfoxserver.controllers.MessageHandler.dispatchEvent(MessageHandler.java:147)
INFO   | jvm 1    | 2009/11/01 19:58:50 | 	at it.gotoandplay.smartfoxserver.controllers.SystemHandler.handleLoginRequest(SystemHandler.java:482)
INFO   | jvm 1    | 2009/11/01 19:58:50 | 	at it.gotoandplay.smartfoxserver.controllers.SystemHandler.processEvent(SystemHandler.java:221)
INFO   | jvm 1    | 2009/11/01 19:58:50 | 	at it.gotoandplay.smartfoxserver.controllers.SystemHandler.run(SystemHandler.java:146)
INFO   | jvm 1    | 2009/11/01 19:58:50 | 	at java.lang.Thread.run(Thread.java:619)

Post by **Lapo** » 02 Nov 2009, 13:11

Whenever you get a direct JDBC connection from the DbManager you will need to explicitly call the close() method when you're done. This is because otherwise the connection will not return to the database connection pool.
I don't see a close() call in your code. Are you aware of this?

Thanks

Richard van Harten · Post by **Richard van Harten** » 03 Nov 2009, 05:40

Yes it is called elsewhere, surely this can not be the cause of this kind of problem anyway? We downgraded our MySQL from 5.0.77 to 5.0.75 which somehow seems to have lessen the problems. We only got 1 occurance this morning after a flawless test yesterday evening. After that the problem did not show itself anymore. Can it be somehow related to inactivity of the server ?

Post by **Lapo** » 03 Nov 2009, 07:16

Usually the inactivity is signaled via a "broken pipe" error. The message you have reported seems unrelated... although I am no MySQL expert.

Richard van Harten · Post by **Richard van Harten** » 18 Nov 2009, 10:53

Hi,

Sorry for the late reply, we downgraded our MySQL to 5.0.75, also changed the database character set among other small things. Things seem to be fixed now. We are not entirely sure these things are what fixed it, but for those encountering similar problems it might be worth a try.