Thursday, 28 August 2008

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...

10 comments:

  1. good stuff adam, I had a few problems with the flex logging classes too. Take a look at thunderbolt, works on top of the flex logging or just as3 if you prefer and logs to Firebug including drilldown for objects and relevant level colours and icons inside firebugs console view.

    ReplyDelete
  2. Hey Rich! I know of Thunderbolt, we are using the rather swanky Console to view our logging output...

    To use the "targets" feature though, you still have to use the Flex logging classes I think, which still leaves with the above problem...

    Ta!

    ReplyDelete
  3. I have no idea what you are talking about, but you have lovely hair!

    ReplyDelete
  4. thanks a lot for this. using Flex SDK 3.4 and the problem is still there. should file a bug to Adobe

    ReplyDelete
  5. You can now vote for this bug here: https://bugs.adobe.com/jira/browse/SDK-22666

    ReplyDelete
  6. Just a shame Thunderbolt doesn't work on Windows because of the locked text file issue :(

    ReplyDelete
  7. Thanks Jan, have voted for it...

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

    Saved my day. Totally bogus that you have to do it in that order and they don't put big *HEY LOOK HERE, DO THIS IN THIS ORDER OR YOU'RE SCREWED* comments all over the docs.

    ReplyDelete
  9. You sir, are God. Or at least a minor deity. Nice stuff.

    ReplyDelete