Xcode and iPhone simulator: The application won’t launch

This is another migration issue from iOS 3.x to iOS 4.x projects.

The application does not launch in XCode when running Simulator – Debug. Instead it dies (SIGABRT) before entering main().

#0     0x91a02ef6 in __kill
#1     0x91a02ee8 in kill$UNIX2003
#2     0x91a9562d in raise
#3     0x91aab6e4 in abort
#4     0x0245e8c9 in __springboard_unimplemented
#5     0x0246d6b2 in mcount
#6     0x00002298 in main at main.m:11

The answer lies here. mcount() function is profiling function. Profiling is available only on iPhone device build. The setting “Generate Profile Code” somehow gets into foobar state when you migrate the project from older XCode. Note the setting is present under both Project and Target settings so you might need to fix it under the both sections.

Read our blog  Subscribe mFabrik blog in a reader Follow us on Twitter Mikko Ohtamaa on LinkedIn

Debugging Plone with Eclipse and PyDev remote debugger

Plone is a very heavy Python CMS containing thousands of modules. PyDev is Python extension for Eclipse IDE. Plone doesn’t run very well in PyDev debug mode:

• Debug mode is many times slower than normal Python execution
• At least on  some Linux system OS limitations prevent proper running [1]

But you can still use Eclipse and PyDev remote debugger to debug your software.

• All communications happen over sockets so you can debug software running on test server besides local machine
• Downsite is that you need to manually place pydevd.settrace() call to your code instead of just right clicking the line and choosing Set Breakpoint from menu

In both cases you need to use a custom non-forking Plone launch script from Plone and Eclipse tutorial which prevents Zope to escape itself into a child process and keeps the debug process information intact.

PyDev Extension remote debugger

Note that you need the commercial PyDev Extension license, this does not work with the basic plug-in. Free evaluation trial available. Get it here.

Benefits

• GUI stepping support
• Inspect Python run-time environment and variables using GUI
• Better integration with Eclipse console

Setting up local remote debugger

0. Install Eclipse. Do a local install, do not trust your Linux distribution package installation. http://johnpaulett.com/2009/06/26/install-eclipse-galileo-3-5-on-ubuntu-jaunty-9-04/

1. Set up idelauncher.py for your Zope application server

2. Right-click your project in Eclipse. Put pydevd in your PyDev – PYTHONPATH -> External libraries. Mine (local Eclipse 3.5 install) is /home/moo/eclipse3.5/plugins/org.pyhon.pydev.debug.XXX/pysrc

3. Switch to Eclipse Debug perspective. Start pydevd server by clicking the icon with a bug and P letter.

3. Start your Plone instance / unit tests idelauncher.py using Run (play icon – not debug). The debug server stays active even if you terminate the application launcher run.

4. When your code runs to *import pydevd ; pydevd.settrace()* (no underscore in settrace()) you should be able to start examining your site in the debugger

Now you can

• Examine and edit local variables in Variables view
• Execute Python console commands
• Examine different threads (kind of pointless with Plone…)

Note: Python console behaves funnily. You need to enter the commands to Console -> Display selected console (computer icon) -> Debug server view and output will appear  Console -> Display selected console (computer icon) -> your launcher name view.

Remote debugging not enabled

The following exception means that your pydevd server is not running. Click the P bug icon before running the launcher.

Traceback (most recent call last):
  File "/home/moo/eclipse3.5/plugins/org.python.pydev.debug_1.4.7.2843/pysrc/pydevd.py", line 624, in trace_dispatch
    return dbFrame.trace_dispatch(frame, event, arg)
  File "/home/moo/eclipse3.5/plugins/org.python.pydev.debug_1.4.7.2843/pysrc/pydevd_frame.py", line 107, in trace_dispatch
    raise
  File "/home/moo/eclipse3.5/plugins/org.python.pydev.debug_1.4.7.2843/pysrc/pydevd_frame.py", line 102, in trace_dispatch
    self.doWaitSuspend(thread, frame, event, arg)
  File "/home/moo/eclipse3.5/plugins/org.python.pydev.debug_1.4.7.2843/pysrc/pydevd_frame.py", line 25, in doWaitSuspend
    self._args[0].doWaitSuspend(*args, **kwargs)
  File "/home/moo/eclipse3.5/plugins/org.python.pydev.debug_1.4.7.2843/pysrc/pydevd.py", line 532, in doWaitSuspend
    def doWaitSuspend(self, thread, frame, event, arg): #@UnusedVariable
  File "/home/moo/eclipse3.5/plugins/org.python.pydev.debug_1.4.7.2843/pysrc/pydevd.py", line 539, in doWaitSuspend
    self.writer.addCommand(cmd)

Pydevd and Linux Resource temporarily unavailable

[1] I get the following Resource temporarily unavailable traceback when I try to run PyDev debugger against Plone – I tried to pindown the reason using strace, but no luck. Applies both for unit testing and for the actual instance launch.

Installing PloneLanguageTool ... done (0.174s)
Running Products.SitsHospital.tests.rememberbase.RememberProfileLayer tests:
  Set up Products.PloneTestCase.layer.ZCML
Traceback (most recent call last):
...
  File "/home/moo/sits/parts/zope2/lib/python/zope/testing/testrunner.py", line 688, in setup_layer
    setup_layer(base, setup_layers)
  File "/home/moo/sits/parts/zope2/lib/python/zope/testing/testrunner.py", line 692, in setup_layer
    layer.setUp()
  File "/home/moo/sits/parts/plone/PloneTestCase/layer.py", line 17, in setUp
...
  File "/usr/lib/python2.4/xml/sax/xmlreader.py", line 123, in parse
    self.feed(buffer)
  File "/usr/lib/python2.4/xml/sax/expatreader.py", line 207, in feed
    self._parser.Parse(data, isFinal)
  File "/usr/lib/python2.4/xml/sax/expatreader.py", line 348, in end_element_ns
    self._cont_handler.endElementNS(pair, None)
  File "/home/moo/sits/parts/zope2/lib/python/zope/configuration/xmlconfig.py", line 349, in endElementNS
    self.context.end()
  File "/home/moo/sits/parts/zope2/lib/python/zope/configuration/config.py", line 544, in end
    self.stack.pop().finish()
  File "/home/moo/sits/parts/zope2/lib/python/zope/configuration/config.py", line 692, in finish
    actions = self.handler(context, **args)
  File "/home/moo/sits/parts/plone/PlacelessTranslationService/patches.py", line 27, in compile_translations
    func(*args, **kwargs)
  File "/home/moo/sits/eggs/zope.i18n-3.7.0-py2.4.egg/zope/i18n/zcml.py", line 57, in registerTranslations
    for language in os.listdir(path):
zope.configuration.xmlconfig.ZopeXMLConfigurationError: File "/home/moo/sits/parts/instance/etc/site.zcml", line 5.2-5.37
    ZopeXMLConfigurationError: File "/home/moo/sits/parts/zope2/lib/python/Products/Five/configure.zcml", line 6.2-6.30
    ZopeXMLConfigurationError: File "/home/moo/sits/parts/zope2/lib/python/Products/Five/i18n.zcml", line 24.4-24.52
    OSError: [Errno 11] Resource temporarily unavailable: '/home/moo/sits/parts/zope2/lib/python/zope/app/locales'

Plone, KSS, Javascript, field validation and the cup of WTF

Knowledge does hurt. Today I had my sweet cup of WTF. We are developing a medical database based on Plone 3.1. It uses very advanced AJAX framework called KSS – basically you can avoid the pain of writing pure Javascript by crafting special CSS like stylesheets which bind server-side Python code to any Javascript event. This makes AJAX programming a joy. You can easily combine server-side logic with user interface events, like field validation.

Well… then there was an error. KSS validation was not working for the text fields on a certain pages…. or it did sometimes. We were not sure. This is so called Heisenbug. I armed myself with sleepy eyes, Firebug and a lot of energy drinks.

I saw a KSS error in the Firebug log window and failed HTTP POST in the server logs.

Invalid request.

The parameter, value, was omitted from the request.

Looks like the field value was not properly posted for the field validation.

The first thing was locate the error and get function traceback for the messy situation. Unfortunately Firefox Javascript engine or Firebug cannot show tracebacks properly… the grass is so much greener on the other side of the fence. So I had to manually search through the codebase by manually plotting console.log() calls here and there.

Finally I thought I pinpointed the cause of the failure. By shaking finger (excitement, tireness and all that extra caffeinen from energy drinks), I opened the Javascript file just to realize why Javascript is utterly utterly shitty and why no sane person wants to do low level Javascript development. If ECMA standard committee had been clever and had been able to enforce anything long time ago, the following piece could be replaced with one function call.

fo.getValueOfFormElement = function(element) {
    // Returns the value of the form element / or null
    // First: update the field in case an editor is lurking
    // in the background
    this.fieldUpdateRegistry.doUpdate(element);
    if (element.disabled) {
        return null;
    }
    // Collect the data
    if (element.selectedIndex != undefined) {
        // handle single selects first
        if(!element.multiple) {
                if (element.selectedIndex < 0) {
                    value="";
                } else {
                    var option = element.options[element.selectedIndex];
                    // on FF and safari, option.value has the value
                    // on IE, option.text needs to be used
                    value = option.value || option.text;
                }
        // Now process selects with the multiple option set
        } else {
            var value = [];
            for(i=0; i<element.options.length; i++) {
                var option = element.options[i];
                if(option.selected) {
                    // on FF and safari, option.value has the value
                    // on IE, option.text needs to be used
                    value.push(option.value || option.text);
                }
            }
        }
    // Safari 3.0.3 no longer has "item", instead it works
    // with direct array access []. Although other browsers
    // seem to support this as well, we provide checking
    // in both ways. (No idea if item is still needed.)
    } else if (typeof element.length != 'undefined' &&
        ((typeof element[0] != 'undefined' &&
        element[0].type == "radio") ||
        (typeof element.item(0) != 'undefined' &&
        element.item(0).type == "radio"))) {
        // element really contains a list of input nodes,
        // in this case.
        var radioList = element;
        value = null;
        for (var i=0; i < radioList.length; i++) {
            var radio = radioList[i] || radioList.item(i);
            if (radio.checked) {
                value = radio.value;
            }
        }
    } else if (element.type == "radio" || element.type == "checkbox") {
        if (element.checked) {
           value = element.value;
        } else {
            value = null;
        }
    } else if ((element.tagName.toLowerCase() == 'textarea')
               || (element.tagName.toLowerCase() == 'input' &&
                    element.type != 'submit' && element.type != 'reset')
              ) {
        value = element.value;
    } else {
        value = null;
    }
    return value;
};

It turned out that the element in this case was an empty list of radio buttons. When you are tab keying through a radio button group without any value selected, like in the case a content object is just created, KSS validation is triggered even though there is no value in any of the radio buttons. This makes KSS think the value is null and it does not properly handle the situation. This does not cause any user visible effects unless you have Javascript debugging on (Firebug + debugging mode in Plone’s Javascript registry).

But this was not the bug I was looking for. It was just masking the original bug, because I had an empty radio button group next to the text field whose validation was not correctly done. More server side debugging…

I inserted some funky debug prints to Archetypes.Field.validate_validators():

validate_validators()

Calling validators:(('isEmptyNoError', V_SUFFICIENT), ('validDecRange03', V_REQUIRED))

We can see that not triggered validator, validDecRange03, is still with us. Then I add more debug prints to see where things go wrong, this time to to Products.validation.chain.__call__.

Calling validators:(('isEmptyNoError', V_SUFFICIENT), ('validDecRange03', V_REQUIRED))
Name:isEmptyNoError value:234234234234234234234234234232342342342344534232342344234534554 result:True

Ok – we have a case here. isEmptyNoError validator is executed before our custom validator. Since this validator is flagged as “sufficient” other validators are not evaluated. I think this has not been the case before and our validator have worked properly… maybe there was API change in Plone 3.1 which broke the things?

After digging and digging and digging I found this 4 years old bug. Let’s open the famous isEmptyNoError source code in Products.validation.validators.EmptyValidator:

class EmptyValidator:
    __implements__ = IValidator

    def __init__(self, name, title='', description='', showError=True):
        self.name = name
        self.title = title or name
        self.description = description
        self.showError = showError

    def __call__(self, value, *args, **kwargs):
        isEmpty  = kwargs.get('isEmpty', False)
        instance = kwargs.get('instance', None)
        field    = kwargs.get('field', None)

        # XXX: This is a temporary fix. Need to be fixed right for AT 2.0
        #      content_edit / BaseObject.processForm() calls
        #      widget.process_form a second time!
        if instance and field:
            widget  = field.widget
            request = getattr(instance, 'REQUEST', None)
            if request and request.form:
                form   = request.form
                result = widget.process_form(instance, field, form,
                                             empty_marker=_marker,
                                             emptyReturnsMarker=True)
                if result is _marker or result is None:
                    isEmpty = True

        if isEmpty:
            return True
        elif value == '' or value is None:
            return True
        else:
            if getattr(self, 'showError', False):
                return ("Validation failed(%(name)s): '%(value)s' is not empty." %
                       { 'name' : self.name, 'value': value})
            else:
                return False

There is my WTF. Or XXX – thanks for the kisses. My guess is that because KSS validation is executed in special context, the magical REQUEST might not be there. The “is sufficient” validator fails because of the some sort of god forgotten magic and thus all custom validators fail in KSS when the field is not required.

The workaround: I add my own greetings to the code:

        # XXX: This is a temporary fix. Need to be fixed right for AT 2.0
        #      content_edit / BaseObject.processForm() calls
        #      widget.process_form a second time!
        if instance and field:
            widget  = field.widget
            request = getattr(instance, 'REQUEST', None)

            # XXX: Whatever this all does, it does not work for KSS validation
            # requests and we should ignore this
            if "fieldname" in request:
              return False

            if request and request.form:
                form   = request.form
                result = widget.process_form(instance, field, form,
                                             empty_marker=_marker,
                                             emptyReturnsMarker=True)
                if result is _marker or result is None:
                    isEmpty = True

If Zope 3 drives you smoking Plone 3 drives me drinking. No wonder newbies steer away from Plone – if you hadn’t been armed with 8 years of web development experience you would never have figured out what’s going on with such a simple thing as adding a custom validator. A comment added to the bug tracker.

Debugging Django memory leak with TrackRefs and Guppy

I run Django in a standalone long-running application (video encoding server). It leaked memory severely. By using htop, one was seeing two gigabytes reserved for /usr/bin/python after a while. Before starting the debugging session, I had no faintest idea what could be the cause of the problem. Django is robust technology – this kind of things haven’t happened for me before. Since I was running Django in standalone mode, I suspected that some query cache does not get cleared. But random poking around the source code didn’t give any clues.

It was time to do some serious memory debugging for Python.

Python as is doesn’t leak memory, since it’s garbage collected virtual machine. All “leaks” are design problems in the application logic.I found a good primer here what’s going inside Python’s memory management.

First I tried this nice TrackRefs class from Zope. It relies on Python’s own in-interpreter functions to monitor objects.

class TrackRefs:
    """Object to track reference counts across test runs."""

    def __init__(self, limit=40):
        self.type2count = {}
        self.type2all = {}
        self.limit = limit

    def update(self):
        obs = sys.getobjects(0)
        type2count = {}
        type2all = {}
        for o in obs:
            all = sys.getrefcount(o)

            if type(o) is str and o == '<dummy key>':
                # avoid dictionary madness
                continue
            t = type(o)
            if t in type2count:
                type2count[t] += 1
                type2all[t] += all
            else:
                type2count[t] = 1
                type2all[t] = all

        ct = [(type2count[t] - self.type2count.get(t, 0),
               type2all[t] - self.type2all.get(t, 0),
               t)
              for t in type2count.iterkeys()]
        ct.sort()
        ct.reverse()
        printed = False

        logger.debug("----------------------")
        logger.debug("Memory profiling")
        i = 0
        for delta1, delta2, t in ct:
            if delta1 or delta2:
                if not printed:
                    logger.debug("%-55s %8s %8s" % ('', 'insts', 'refs'))
                    printed = True

                logger.debug("%-55s %8d %8d" % (t, delta1, delta2))

                i += 1
                if i >= self.limit:
                    break 

        self.type2count = type2count
        self.type2all = type2all

You need to have Python compiled in debug mode to have sys.getobjects() method. Luckily this beefed up Python binary is availalble from Ubuntu’s stock repository:

sudo apt-get install python-dbg python-mysqldb-dbg

Note that native Python extensions don’t work unless they are specifically compiled against the Python debug build (python-mysqldb-dbg)..

Then I add TrackRefs to my main loop:

    def run(self):

        self.running = True

        logger.info("Started worker " + self.get_worker_id_string())

        # Memory leak tracking
        tracker = TrackRefs()

        while self.running:

            self.mark_for_download()

            self.process_downloads()

            self.process_encodings()

            tracker.update() # Dump memory here

            time.sleep(settings.WORKER_POLL_DELAY)

And after running a while I start getting interesting results:

7956 [2008-03-07 02:59:28,767] INFO Jobs needing sources to download 0
7956 [2008-03-07 02:59:28,768] DEBUG Processable jobs: 0
7956 [2008-03-07 02:59:29,754] DEBUG ----------------------
7956 [2008-03-07 02:59:29,754] DEBUG Memory profiling
7956 [2008-03-07 02:59:29,754] DEBUG                                                            insts     refs
7956 [2008-03-07 02:59:29,754] DEBUG <type 'int'>                                                 150   137406
7956 [2008-03-07 02:59:29,755] DEBUG <type 'tuple'>                                               117   130211
7956 [2008-03-07 02:59:29,755] DEBUG <type 'dict'>                                                  5     8331
7956 [2008-03-07 02:59:29,755] DEBUG <type 'str'>                                                   3    27643
7956 [2008-03-07 02:59:29,755] DEBUG <type 'unicode'>                                               3     4606
7956 [2008-03-07 02:59:29,755] DEBUG <type 'list'>                                                  3     3492
7956 [2008-03-07 02:59:29,756] DEBUG <type 'frame'>                                                 1      962
7956 [2008-03-07 02:59:29,756] DEBUG <type 'cell'>                                                  0    12948
7956 [2008-03-07 02:59:29,756] DEBUG <type 'function'>                                              0     9479

Woah! Who reserved 130 000 ints and tuples? No wonder that soon python gulps 1 gigabytes of memory. Since this is the only number which grows during the main loop cycling and there is no references to classes or objects debugging becomes a bit more difficult. I need to try to cross-reference the difficult tuple objects.

This didn’t go well – with gc.get_referrers() recurive parsing I got some results (example below). But it became soom clearthat debug references from the system itself was impossible: the memory debugging code will always create nasty cyclic references to the system, since it needs to track the objects. I gave up. There had to be something better.

9154 [2008-03-07 04:05:23,571] DEBUG /var/lib/python-support/python2.5/MySQLdb/connections.pyc
9154 [2008-03-07 04:05:23,571] DEBUG <type 'function'>
9154 [2008-03-07 04:05:23,572] DEBUG defaulterrorhandler
9154 [2008-03-07 04:05:23,572] DEBUG <type 'function'>
9154 [2008-03-07 04:05:23,572] DEBUG string_literal
9154 [2008-03-07 04:05:23,572] DEBUG <type 'function'>
9154 [2008-03-07 04:05:23,573] DEBUG unicode_literal
9154 [2008-03-07 04:05:23,573] DEBUG <type 'function'>
9154 [2008-03-07 04:05:23,573] DEBUG string_decoder
9154 [2008-03-07 04:05:23,573] DEBUG <type 'function'>
9154 [2008-03-07 04:05:23,573] DEBUG __exit__
9154 [2008-03-07 04:05:23,574] DEBUG <type 'function'>
9154 [2008-03-07 04:05:23,574] DEBUG begin
9154 [2008-03-07 04:05:23,574] DEBUG <type 'function'>
9154 [2008-03-07 04:05:23,574] DEBUG __init__
9154 [2008-03-07 04:05:23,574] DEBUG <type 'function'>
9154 [2008-03-07 04:05:23,575] DEBUG show_warnings

There was: Guppy. Thank you Sverker Nilsson! You saved my day.

Since the API of Guppy is a little eccentric, here are some examples for you:

# init heapy
heapy = guppy.hpy()

# Print memory statistics
def update():
  print heapy.heap()

# Print relative memory consumption since last sycle
def update():
   print heapy.heap()
   heapy.setref()

# Print relative memory consumption w/heap traversing
def update()
    print heapy.heap().get_rp(40)
    heapy.setref()

With heapy.heap() ; heapy.setref() I got this output:

Partition of a set of 12 objects. Total size = 3544 bytes.
 Index  Count   %     Size   % Cumulative  % Kind (class / dict of class)
     0      3  25     2244  63      2244  63 unicode
     1      2  17      708  20      2952  83 types.FrameType
     2      3  25      432  12      3384  95 dict (no owner)
     3      3  25      120   3      3504  99 str
     4      1   8       40   1      3544 100 list

One adds get_rp() travelsal magic and everything becomes clear:

Reference Pattern by <[dict of] class>.
 0: _ --- [-] 14 (dict (no owner) | list | str | types.FrameType | types.Gene...
 1: a      [-] 3 dict (no owner): 0x8c11f34*2, 0x8c1bd54*2, 0x8c1f854*2
 2: aa ---- [-] 1 list: 0x833c504*18
 3: a3       [-] 1 dict of django.db.backends.mysql.base.DatabaseWrapper: 0x8...
 4: a4 ------ [-] 1 dict (no owner): 0x83a65d4*2
 5: a5         [R] 1 guppy.heapy.heapyc.RootStateType: 0xb787c7a8L
 6: a3b ----- [-] 1 django.db.backends.mysql.base.DatabaseWrapper: 0x8356a34
 7: a3ba       [S] 7 dict of module: ..db, ..models, ..query, ..transaction...
 8: b ---- [S] 1 types.FrameType: <<lambda> at 0x8b16ecc>
 9: c      [-] 2 list: 0x833c504*18, 0xb7dafe6cL*5
<Type e.g. '_.more' for more.>

What there could in DatabaseWrapper object which is growing and growing… query debugger. Django keeps track of all queries for debugging purposes (connection.queries). This list is reseted at the end of HTTP request. But in standalone mode, there are no requests. So you need to manually reset to queries list after each working cycle.

        while self.running:

            self.mark_for_download()

            self.process_downloads()

            self.process_encodings()

            tracker.update()

            time.sleep(settings.WORKER_POLL_DELAY)

            # Clear database connection ad reset query debugger
            # between cycles to make sure that
            # related resources get released
            reset_queries()
            connection.close()

            print str(connection.queries)

But even after this fix, I got increase in tuple and int usage when monitoring with TrackRefs. But when I run heapy.heap() alone, there is no increase. So the tuple and int consumption must have been caused by TrackRef, sys.getobjects, gc, etc. magic itself.