Exception Getting Hidden

[kevglass]

As I’m developing now and again I make some huge mistake that causes either the client or server to die, and hence I get a fail over. However, the exception causing this is being hidden. It doesn’t come out client side or on the server log.

I believe Endolf has also seen this behaviour.

This one is a real problem at the moment, it makes debugging stuff really really difficult

Kev

[Jeff]

@kevglass

As I’m developing now and again I make some huge mistake that causes either the client or server to die, and hence I get a fail over. However, the exception causing this is being hidden. It doesn’t come out client side or on the server log.

I believe Endolf has also seen this behaviour.

This one is a real problem at the moment, it makes debugging stuff really really difficult

Kev

Hmm. Okay I’ll look into it,. Can you give me examples on both side of what exceptions are getting swollowed? I usually see mine in the sevrer logs from my server apps. On the client I havent really run into much in the way of exceptions so Im less sure whats going on but Ill look.

Note though that if you can kill the server from app code, I really need to knwo what you are doing 'cause as long as you are following the basic GLC rules you shouldn’t be able to do that. Thats bad server behavior…

JK

[kevglass]

Ok, I had a silly one earlier - I was loading a image/sprite and I got the file name wrong. In my code this throws a RuntimeException (we can debate whether thats a good idea later :)) when the file can’t be found. This exception occured on the client when the game windows was lazily loaded as you enter the arena. This caused a hiccup but the exception was completely lost.

Can you tell me what the callback was that this called by?

My guess is that this ias actually in tge Matchmaker API, which is the last thing we did. I was pretty careful in the base level APIs
of this.

The common one as always is the NPE tho. During developing the first bit I had an NPE client side that was in the join channel notification thread.

On the client? Ill take a look…

This caused a failOver() and then some additional errors on the server about already being joined to a channel. Which in turn caused the my client to get booted off the server. The NPE itself wasn’t seen anywhere - in the end I debugged it by adding a catch throwable around all the code I’d added recently

Endolf might have another one,

Thanskj gusy this is all very helpful.

i DID take a l;ook at the server and on the higher level this shouldnt be ahppening, but ist possible deep in some of our util classes there are some bad catches…

I’ll take this as a P1 to do a general scrub…

JK
Kev

[Jeff]

I tarced your exception abck, kev.

Its cause its a RUntimeException

It actually IS getting reported but ist using the Java logging mechanism.

If you enable that yo uwill probably be much happier.

Logging shoudl alrady be happingin on the server, so check the log files. Its possible it may have to do with level of logging.

JK

[kevglass]

Not sure what happened above ?

Anyway, where would I find this log - all the log from the server being spat out to console and its not in there.

I can’t see any logs being produced client side (apart form my own - which is bespoke and entirely seperate).

Couldn’t quite understand the post above - are you saying I need to turn some Java Logging API logging on or up a level or something?

Kev

[Jeff]

@kevglass

Not sure what happened above ?

Anyway, where would I find this log - all the log from the server being spat out to console and its not in there.

On the server side I need to know the details of that exception, we’re talking client ehre cause thats what you hgavce me to trace.

I can’t see any logs being produced client side (apart form my own - which is bespoke and entirely seperate).

Couldn’t quite understand the post above - are you saying I need to turn some Java Logging API logging on or up a level or something?

Kev

Yup, Ive suggested we add that to all the examples. There is a logging API built into the j2SE paltform. See java.util.logging.*

I beliebe BattleBoard client enables it if you want an example.

Edit: i take it back, the BattleBoard uses itsown logger… Il lfind the detaisl for you… hang ona mo…

[Jeff]

Okay, someone else did the logging stuff in the SDk but wehat I get from the docs is this shoudl getyou ALL logged messages

import java.util.logging.*;

StreamHandler streamHandler =new StreamHandler(System.out,new SimpleFormatter());
streamHandler.setLevel(Level.FINEST);
Logger log = Logger.getLogger(""); // get root logger
log.addHandler(streamHandler);

I haevnt tested this, this is just from the Javadocs. Im searchign our code abse for an exampel at the moment.

Edit: I think we probably need a doc on how logging is used in Darkstar with some proper examples. Ive brought thsi up with the dev team…

[kevglass]

I’ve just given that a quick try by adding that logging setup in and causing an explcit exception - no sign of anything new logging wise (although I do see log messages client side when the connection to the server fails).

Is it potentionally a named logger?

Kev

[Jeff]

@kevglass

I’ve just given that a quick try by adding that logging setup in and causing an explcit exception - no sign of anything new logging wise (although I do see log messages client side when the connection to the server fails).

Is it potentionally a named logger?

Kev

It is a named logger but i THOGUHT the root logger ("") would get messages from all the loggers. But as I say its new to me.

The name of this particualr logger is com.sun.gi.utils.nio

[Jeff]

You might also try Level.ALL…

[Jeff]

Okay use ConsoleHandler rather then StreamHandler. Its simpler and you dont have to set the formatter.

But you still want to set level.ALL

[kevglass]

Needed one of these:

		log.setLevel(Level.ALL);

on the log as well as the stream handler. I’ve now got pages and pages of logs to dig through No sign of the exception yet tho.

Its being thrown throught the joinedChannel() callback on com.sun.gi.comm.users.client.ClientConnectionManagerListener btw.

Kev

[kevglass]

Ok, found it!

I know you can specify all this logging stuff in a file (maybe its worth providing a config file with SGS?) but programatically this is what I ended up using:

		// turn on detailed logging
		StreamHandler streamHandler = new ConsoleHandler();
		streamHandler.setLevel(Level.ALL);
		streamHandler.setFilter(new Filter() {
			public boolean isLoggable(LogRecord record) {
				if (record.getLoggerName().startsWith("com.sun.gi")) {
					return true;
				}
				return false;
			}
		});
		
		Logger log = Logger.getLogger(""); // get root logger
		log.setLevel(Level.ALL);
		log.addHandler(streamHandler);

The exception comes out on FINEST on the logger com.sun.gi.utils.nio.NIOSocketManager. Mine looked like this:

03-Apr-2006 21:21:22 com.sun.gi.comm.users.protocol.impl.BinaryPktProtocol packetReceived
FINER: Recieved op: JOINED_CHAN
03-Apr-2006 21:21:22 com.sun.gi.comm.users.protocol.impl.BinaryPktProtocol packetReceived
FINER: DataSize: 35
03-Apr-2006 21:21:23 com.sun.gi.utils.nio.NIOSocketManager handleRead
FINER: THROW
java.lang.RuntimeException: Unable to load image: res/broke-turret.gif
	at org.newdawn.tank.client.Util.loadImage(Util.java:20)

I think this type of exception is way more important than FINER - infact, I’d probably put this up at ERROR - at least WARNING.

Kev

[Jeff]

Fair enough, Ill put it on the lsit., Thats James’ baby-- the low level TCPIp code. I tend to agree thatm, sicen we dont actually know WHAT caused it, it shoudl probably be higher.

[kevglass]

Excellent! Finding this stuff out is going to make it much easier

One other thing, just out of interest why does a client side failure cause a fail over? I mean it could be something else thats a side effect or something but just seemed wierd in my head.

Kev

[Jeff]

Its becasue its being handled WAY deep in the comm code for receiving stuff from Nio, which is assuming if it see a runtime error it must be that the connection is garbaged.

Arguably we should insulate ourselves better but it IMO it IS your fault for throwing a RuntimeError into our system. You shoudl be catching and handling your own exceptions.

[Jeff]

I believe you cna set the logging level on the server with properties. Illask James and Dan to document al lthat.

[kevglass]

Fair point Unfortunately, NPEs are pretty common during development (at least when its me they are :)).

I’m just surprised the client can effectively cause a failOver() if it wants. Could be a bit open to malicious mod-the-client, kill-the-server type things.

TBH, from a purely practical point of view I have the logging now, doesn’t matter to me !
Kev

[Jeff]

@kevglass

Fair point Unfortunately, NPEs are pretty common during development (at least when its me they are :)).

I’m just surprised the client can effectively cause a failOver() if it wants. Could be a bit open to malicious mod-the-client, kill-the-server type things.

Good point. Ill make a note that we shoudl make sure all our callbacks are better warded.

Just causing the client to fail over isnt effecting the server is it?

[kevglass]

You know I’m not sure anymore - the server does seem to dump out a whole bunch of SEVERE type messages but I’m not sure it really hurts anything. Just get a few of these:

SEVERE: attempt to queue task for unknown uid UUID(1144124372925:7198165972062275152)

but the server doesn’t seem to go down or anything.

Kev