Wednesday, February 4, 2009

AppEngine dev_appserver logging

For some weird reason I cannot debug on dev_appserver. My breakpoints are simply ignored. So I placed logging code in troublesome places. By default, dev_appserver sets the root logger level to INFO. If run with -d option, it's DEBUG, and it logs all environment for every request. I tried to set the root level to WARNING or higher, but it was either ignored or made logger totally silent. So the best option I found is to leave the root level to INFO and to use module loggers for application-specific DEBUG messages. In the __main__ function I added the following lines:
logger=logging.getLogger("my")
logger.setLevel(logging.DEBUG)
Every module has to get its own logger like this:
# module engine.py
import logging

logger=logging.getLogger("my.engine")
Because of the dot separator my.engine logger inherits the configuration of my logger, so DEBUG messages are printed on the console.

I also did not find the correct way to add handlers to my logger, because if I change the logger initialization like this:

logger=logging.getLogger("my")
logger.setLevel(logging.DEBUG)
ch=logging.StreamHandler()
logger.addHandler(ch)
It adds a new handler for every request, so each message is printed many times. Of course, it's possible to remove the handler after run_wsgi_app call, but it looked weird to add and immediately remove the handler every time. If you know a better way to configure logging with dev_appengine, please let me know.

Sunday, February 1, 2009

Scriptaculous and AJAX

I started with a task which seemed to be typical when script.aculo.us is used with Prototype Ajax.Request. The old content nicely disappears with one of scriptaculous effects, AJAX request is sent and when result is available it appears with another effect. Let's use Effect.SlideUp and Effect.SlideDown for these effects, and <div id='main_div'> for the content. Straight-forward solution looks like this:
new Effect.SlideUp('main_div', {
      afterFinish: function () {
        new Ajax.Request(url, {
            method:'get',
            onSuccess: function(transport){
              $('main_div').innerHTML=transport.responseText;
              new Effect.SlideDown('main_div');
            }
          })
      }
    });
Failure handling is omitted for brevity. This solution works, but has a significant problem: the request is sent only after the slide up effect is finished, so the user waits more than necessary. I wanted to send the AJAX request immediately, so the response might be ready when the slide up is finished. But it's impossible to know which will finish first.
My next try was to start slide up and immediately send the request, like this:
    new Effect.SlideUp('main_div');
    new Ajax.Request(url,
    {
        method:'get',
        onSuccess: function(transport){
             $('main_div').innerHTML=transport.responseText;
             new Effect.SlideDown('main_div', {queue: 'end'});
        }
    });
Unfortunately, it did not work correctly. If the response comes before the slide up vanished the main_div, it will be replaced with the new content for a moment, then disappear and come nicely with the slide down effect. So the problem here is that replacing the content and slide down must start only when both slide up and the AJAX are finished. I ended up with the following:
    var hideEffectComplete=false;
    var ajaxResult=null;
    new Effect.SlideUp('main_div', {
        afterFinish: function () {
            complete=true;
            if (ajaxResult != null) {
                $('main_div').innerHTML=ajaxResult;
                new Effect.SlideDown('main_div');
            }
        }
    });
    new Ajax.Request(url,
    {
        method:'get',
        onSuccess: function(transport){
          ajaxResult=transport.responseText;
          if (hideEffectComplete) {
             $('main_div').innerHTML=ajaxResult;
             new Effect.SlideDown('main_div');
          }
        }
    });
It works better, but it's long, ugly and redundant. Also it makes problems when a user makes a few actions fast, things are just messed up. Does anybody have a better idea how to synchronize AJAX and script.aculo.us?