So near but so far...

Newbie Posts : 2 Join date : 2012-04-04 Location : UK

I have checked out the code from SVN and it's taken me a lot of fiddling and reading posts on here to get things mostly working...
I've got the server running, the master server running and the client authenticating to the master server. I've got a web server with the jsp files running.
The problem is, it gets right up to the point where the client is about to enter the world, and fails to connect to the server.

It seems that the server is not listening despite saying I can log in.

There are some errors in the log file relating to the login manager which I guess is the most likely culprit but I don't know how to resolve them.
Please could someone take a look at this log and maybe give me some tips? (or let me know if I'm looking in the wrong place?)
http://pastebin.com/et37VTLn

On the client side the error is:
Exception: WARN Failed to connect to login server at 127.0.0.1:5040 - System.Net.Sockets.SocketException: No connection could be made because the target machine actively refused it 127.0.0.1:5040

Thanks!

Hi,
It sounds like either the UID and PWD for the Database or your LOGIN are not correct.
Do you see in the server log where it parses your UID and PWD? Or does it not make it that far?
It def. picks up your LOCAL IP and port so that looks good, it just seems to be failing on the authentication piece.
Can you paste in as code the server side log and the client side?
Regards,
Lou

Newbie Posts : 2 Join date : 2012-04-04 Location : UK

I don't think it's that... it seems to be authenticating fine:

Code:: DEBUG [2012-04-05 09:07:57,137] pool-1-thread-1 MasterServer.handleAuth: username len=4
DEBUG [2012-04-05 09:07:57,137] pool-1-thread-1 MasterServer.handleAuth: login username=test
DEBUG [2012-04-05 09:07:57,142] pool-1-thread-1 dataLen=36
DEBUG [2012-04-05 09:07:57,147] pool-1-thread-1 data=AAAABHRlc3QAAAABAAAAFBa/o15Jm8eFQRKGW+ld5z33X/L/
DEBUG [2012-04-05 09:07:57,147] pool-1-thread-1 password=test
DEBUG [2012-04-05 09:07:57,148] pool-1-thread-1 authResponse=kOiw3YvoyYBN2MBI/mMzO6dnojw=
DEBUG [2012-04-05 09:07:57,148] pool-1-thread-1 authenticator=F+5nCXaJGCdHIVR4mSX0kRyMkUk=
DEBUG [2012-04-05 09:07:57,148] pool-1-thread-1 SocketHandler: closed socket: Socket[addr=/127.0.0.1,port=52167,localport=9005]
DEBUG [2012-04-05 09:08:01,245] pool-1-thread-1 cookie=-1 version=1
DEBUG [2012-04-05 09:08:01,246] pool-1-thread-1 MasterServer.handleAuth: username len=4
DEBUG [2012-04-05 09:08:01,246] pool-1-thread-1 MasterServer.handleAuth: login username=test
DEBUG [2012-04-05 09:08:01,247] pool-1-thread-1 dataLen=36
DEBUG [2012-04-05 09:08:01,247] pool-1-thread-1 data=AAAABHRlc3QAAAABAAAAFJdyn3O0bPeEIo7vAvHe70dKvSXn
DEBUG [2012-04-05 09:08:01,247] pool-1-thread-1 password=test
DEBUG [2012-04-05 09:08:01,247] pool-1-thread-1 authResponse=xc1DRo5dQxuvrO85TkRrn7QZOKI=
DEBUG [2012-04-05 09:08:01,247] pool-1-thread-1 authenticator=xc1DRo5dQxuvrO85TkRrn7QZOKI=
DEBUG [2012-04-05 09:08:01,252] pool-1-thread-1 putPropertyMap: account_id=1, account_name=test
DEBUG [2012-04-05 09:08:01,267] pool-1-thread-1 MVByteBuffer.reallocate: size=512 requested=131 newSize=512
DEBUG [2012-04-05 09:08:01,267] pool-1-thread-1 tokenLen=131 token=AQEAAAAGbWFzdGVyAAAAAAAAAAIAAAAAAAAADAAAATaBjZSgGAAAAAIAAAAKYWNjb3VudF9pZAMA
AAABAAAADGFjY291bnRfbmFtZQEAAAAEdGVzdDAsAhQ8WjVOidJSkfy+PiIgfcz3m3xjHAIUbN41
gBDB3qptARMM6EThxQ0HGwE=
DEBUG [2012-04-05 09:08:01,268] pool-1-thread-1 tokenLen=131 token=AQEAAAAGbWFzdGVyAAAAAAAAAAIAAAAAAAAADAAAATaBjZSgGAAAAAIAAAAKYWNjb3VudF9pZAMA
AAABAAAADGFjY291bnRfbmFtZQEAAAAEdGVzdDAsAhQ8WjVOidJSkfy+PiIgfcz3m3xjHAIUbN41
gBDB3qptARMM6EThxQ0HGwE=
DEBUG [2012-04-05 09:08:01,268] pool-1-thread-1 SocketHandler: closed socket: Socket[addr=/127.0.0.1,port=52168,localport=9005]
DEBUG [2012-04-05 09:08:01,309] RDPServer masterserver: new incoming connection: RDP(/127.0.0.1:5294)
DEBUG [2012-04-05 09:08:01,317] RDPCallback masterserver: got name resolution request
DEBUG [2012-04-05 09:08:01,317] RDPCallback masterserver.resolvename: looking up worldName sampleworld
DEBUG [2012-04-05 09:08:01,319] RDPCallback masterverse.resolvename: resolved worldName sampleworld to 127.0.0.1:5040
DEBUG [2012-04-05 09:08:01,319] RDPCallback masterverse.resolvename: patcher for worldName sampleworld at http://localhost:7070/examples/jsp/website/update/patcher/world_patcher.html with media at: http://localhost:7070/examples/jsp/website/update/update/sampleworld/
DEBUG [2012-04-05 09:08:01,319] RDPCallback MVByteBuffer.reallocate: size=41 requested=120 newSize=164
DEBUG [2012-04-05 09:08:01,319] RDPCallback MVByteBuffer.reallocate: size=164 requested=193 newSize=328
DEBUG [2012-04-05 09:08:10,653] RDPServer RDPServer.processExistingConnection: got reset packet for con RDP(/127.0.0.1:5294)
DEBUG [2012-04-05 09:08:10,653] RDPServer Masterserver: connection reset

The database connection seems fine too:

Code:: DEBUG [2012-04-05 11:29:39,122] main com.mysql.jdbc.Driver driver loaded
DEBUG [2012-04-05 11:29:39,122] main Database: starting keepalive
DEBUG [2012-04-05 11:29:39,123] main Engine, connecting to 127.0.0.1user = root passwd=
DEBUG [2012-04-05 11:29:39,123] main *** url = jdbc:mysql://127.0.0.1/multiverse username = root password =
INFO [2012-04-05 11:29:39,532] main connected to database
DEBUG [2012-04-05 11:29:39,533] main Reading namespaces from the database
DEBUG [2012-04-05 11:29:39,534] main Read 15 namespaces from the database

The issue seems to be that the world server is never listening on port 5040 - the port isn't even open in netstat Sad

Should there be a line in the log "listening on port 5040" somewhere?

Now that I have a master server setup working I've reached the same problem.

The world server starts, everything says its running, but sockets are only listening on ports 9005 and 9010. Nothing on 5040 and 5050. There is no firewall on my system and I'm root. Anyone know which script or bit of code actually starts the port 5040 listen or have any troubleshooting hints?

More detail for my error case:

This is on an Ubuntu 10.04 system and I'm using Java 1.6.0_31 and the source from trunk.

MySQL is version 5.1.62 and the mySQL connector is version 5.1.20. There are no database errors at any point and everything looks to be fine with database access. The master server can also use the database fine.

netstat -l shows that port 9005 and 9010 are listening but not 5040 and 5050.

Looking at the server logs shows some interesting things.

domain.out has no exceptions.

Every other file has an exception for MessageTypeFilter not being serializable and being unable to serialize NULL. This appears to be non-fatal because things keep going, but it shows up all over.

There are two "sendRPC: no message recipients for type" exception messages: one for mv.REGISTER_INSTANCE_TEMPLATE in instance.out and one for mv.REGISTER_TEMPLATE in login_manager.out. These seem a bit ugly, but not idea how severe they are.

There are also some very scary-looking exceptions that say "could not load and/or activate class" for calls to registerPlugin() calls in mobserver.out, login_manager.out, and combat.out. Here's what registerPlugin calls fail:

combat.out: multiverse.mars.plugins.CombatPlugin in sampleworld/combat.py line 236, multiverse.mars.plugins.GroupPlugin in common/groupplugin.py line 13

login_manager.out: multiverse.mars.plugins.MarsLoginPlugin in common/login_manager.py line 37

The common/login_manager.py file has some keys in it. I can't tell whether they're supposed to match anything external to the file.

mobserver.out: multiverse.mars.plugins.QuestPlugin in common/questplugin.py line 13, multiverse.mars.plugins.TrainerPlugin in common/trainerplugin.py line 13, multiverse.servers.MobManagerPlugin in common/mobserver.py line 16.

None of these three files have anything that could be considered real code -- just some imports and a call to registerPlugin().

I don't know much about the MARS and Python portions of Multiverse yet so I have no idea whether these are severe problems that have to be fixed in code, or just obvious configuration screwups on my part.

The master server is running on the same box and works fine.

port 5040 and 5050 are used by the game server and not the master server
usually run using multiverse.sh

For the MessageTypeFilter are you getting something like this:
MarshallingRuntime.unmarshalSerializable

otherwise there might be a problem with your worldmessages/mvmessages

Can you try posting the output of this command:
grep ERROR *.out
in you MV_HOME/logs/WORLD_ID folder

That might help figure out the problem

Searching for ERROR turned up this:

Code:: MarshallingRuntime.initializeBatch: type num file '../config/common/typenumbers.txt' does not exist!

It shows up 18 times. The other errors are just logging the exceptions.

Here's what the MessageTypeFilter exception throws:

Code:: ERROR [2012-06-07 16:23:44,349] main Exception during marshalSerializable of object multiverse.msgsys.SubscribeMessage@1c7c4c of class multiverse.msgsys.SubscribeMessage; writing null value java.io.NotSerializableException: multiverse.msgsys.MessageTypeFilter
at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1164)
at java.io.ObjectOutputStream.defaultWriteFields(ObjectOutputStream.java:1518)
at java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1483)
at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1400)
at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1158)
at java.io.ObjectOutputStream.writeObject(ObjectOutputStream.java:330)
at multiverse.server.marshalling.MarshallingRuntime.serialHelper(MarshallingRuntime.java:638)
at multiverse.server.marshalling.MarshallingRuntime.marshalSerializable(MarshallingRuntime.java:624)
at multiverse.server.marshalling.MarshallingRuntime.marshalObject(MarshallingRuntime.java:159)
at multiverse.msgsys.Message.toBytes(Message.java:84)
at multiverse.msgsys.MessageAgent.sendMessageToList(MessageAgent.java:1119)
at multiverse.msgsys.MessageAgent.createSubscription(MessageAgent.java:655)
at multiverse.msgsys.MessageAgent.createSubscription(MessageAgent.java:541)
at multiverse.server.engine.EnginePlugin.activate(EnginePlugin.java:212)
at multiverse.server.engine.Engine.registerPlugin(Engine.java:636)
at multiverse.server.engine.Engine.registerPlugin(Engine.java:620)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.python.core.PyReflectedFunction.__call__(Unknown Source)
at org.python.core.PyReflectedFunction.__call__(Unknown Source)
at org.python.core.PyObject.__call__(Unknown Source)
at org.python.core.PyObject.invoke(Unknown Source)
at org.python.pycode._pyx3.f$0(../config/common/login_manager.py:37)
at org.python.pycode._pyx3.call_function(../config/common/login_manager.py)
at org.python.core.PyTableCode.call(Unknown Source)
at org.python.core.PyCode.call(Unknown Source)
at org.python.core.Py.runCode(Unknown Source)
at multiverse.server.engine.ScriptManager.runPYFile(ScriptManager.java:181)
at multiverse.server.engine.ScriptManager.runFile(ScriptManager.java:94)
at multiverse.server.engine.Engine.processPostScripts(Engine.java:527)
at multiverse.server.engine.Engine.main(Engine.java:382)
ERROR [2012-06-07 16:23:44,349] main Exception during marshalSerializable of null; writing null value java.lang.RuntimeException: MarshallingRuntime.serialHelper: null is not Serializable
at multiverse.server.marshalling.MarshallingRuntime.serialHelper(MarshallingRuntime.java:637)
at multiverse.server.marshalling.MarshallingRuntime.marshalSerializable(MarshallingRuntime.java:626)
at multiverse.server.marshalling.MarshallingRuntime.marshalObject(MarshallingRuntime.java:159)
at multiverse.msgsys.Message.toBytes(Message.java:84)
at multiverse.msgsys.MessageAgent.sendMessageToList(MessageAgent.java:1119)
at multiverse.msgsys.MessageAgent.createSubscription(MessageAgent.java:655)
at multiverse.msgsys.MessageAgent.createSubscription(MessageAgent.java:541)
at multiverse.server.engine.EnginePlugin.activate(EnginePlugin.java:212)
at multiverse.server.engine.Engine.registerPlugin(Engine.java:636)
at multiverse.server.engine.Engine.registerPlugin(Engine.java:620)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.python.core.PyReflectedFunction.__call__(Unknown Source)
at org.python.core.PyReflectedFunction.__call__(Unknown Source)
at org.python.core.PyObject.__call__(Unknown Source)
at org.python.core.PyObject.invoke(Unknown Source)
at org.python.pycode._pyx3.f$0(../config/common/login_manager.py:37)
at org.python.pycode._pyx3.call_function(../config/common/login_manager.py)
at org.python.core.PyTableCode.call(Unknown Source)
at org.python.core.PyCode.call(Unknown Source)
at org.python.core.Py.runCode(Unknown Source)
at multiverse.server.engine.ScriptManager.runPYFile(ScriptManager.java:181)
at multiverse.server.engine.ScriptManager.runFile(ScriptManager.java:94)
at multiverse.server.engine.Engine.processPostScripts(Engine.java:527)
at multiverse.server.engine.Engine.main(Engine.java:382)

I found a copy of typenumbers.txt in the server_20120322.zip file download.

Putting the text file in config/common caused the file errors and most of the exceptions go away. The important thing is that I was able to get as far as the character creation gazebo.

When creating a character I get the "No default instance" message. Looks like a separate configuration thing I'll need to dig into... but it appears to be well-documented as far as I can tell.

For now I'll add that typenumbers.txt file to config/common in trunk. Thank you for the suggestion on searching for ERROR instead of Exception. Smile

My saga continues here with the "no default instance" issue:

https://multiverse.forumotion.co.uk/t204-unknown-column-run_id-in-field-list-causes-no-default-instance-error#1092