Logging in Flex/Air: Filters behaving badly...

I'm a firm believer in diagnostics - in .NET land I just can't live without log4net. The mx.logging.* namespace in Flex 3 appears to give us some similar functionality (I'm talking about restricting loggers to certain "categories" here) but without the lovely configuration framework of log4net.

In an app we're writing at the moment, I was seeing some wierd behaviour. Basically, the logging targets were just not obeying their filters, meaning every message was getting written everywhere. Not good. At all.

So I did some digging and found two things that surprised me:

1. Setting a level on a target will call Log.addTarget() - probably prematurely

When stepping through the source code of the Flex logging framework, I found this bit of code in AbstractTarget:

public function set level(value:int):void
{
 // A change of level may impact
 // the target level for Log.
 Log.removeTarget(this);
 _level = value;
 Log.addTarget(this);
}

This highlighted line is the culprit. The contents of the addTarget method set up logging restrictions based on the value of the filters array. This has two consequences. Firstly, if you follow Adobe's guidelines you'll end up running through the addTarget code twice, once when you set the level, and once when you actually call Log.addTarget yourself - not awful, but not great either - lots of loops, which gets bad when you've got a lot of Loggers.

The other consequence was the cause of my pain...

2. You have to set your filters before you set your level

Yep. That's right, the following code is bad:

//BAD CODE, DON'T USE
var target : TraceTarget = new TraceTarget();
target.level = level; //This should not come first.
target.filters = filters; //This is pretty much ignored

Here's why:

1. The default value of target.filters is ["*"], which will means the target listens to log messages from every logger.
2. When you set target.level, Log.addTarget is called, and all the filter magic happens. Except that you haven't set the filters yet. So it uses the default value ["*"], and your filter listens to everything. This was what was happening in our code.

So, the correct code should be:

var target : TraceTarget = new TraceTarget();
target.filters = [com.mydomain.myproject.MyClass,mx.rpc.*]; //Set first
target.level = level; // set second.

In this example, a TraceTarget is created which will only listen to Loggers that have a category that is equal to "com.mydomain.myproject.MyClass" or begins with "mx.rpc". It is not at all obvious, but you the above code will also start Logging, as setting target.level also calls Log.addTarget().

The observant among you may have noticed that if Adobe improve the behaviour of setting target.level in the future, you may find that your logging stops because addTarget never gets called. If you're worried about that, you can do the following:

var target : TraceTarget = new TraceTarget();
target.filters = [com.mydomain.myproject.MyClass,mx.rpc.*];
Log.addTarget(target); //honours the filters
// setting target.level will
// remove the target, then add it again.
target.level = level;

Still inefficient, but at least it is future proof. I hope that helps somebody, somewhere...