Adding a new tag with empty string as the definition parameter causes maas-cli to hang

[Diogo Matsubara]

$ maas-cli maas tags new name=foobar23 comment='foo bar' definition=' '

Note the two whitespace in the definition argument. This command hangs and doesn't return

[Jeroen T. Vermeulen (jtv)]

I can reproduce this in a packaged installation, but not in a dev branch.

[Jeroen T. Vermeulen (jtv)]

The region controller's Apache logs the API call, but then the operation gets stuck on the server side before the call even gets to TagsHandler. It's not the space that does it, or even the “new”: same thing happens for “maas-cli maas tags list” for example.

Apache's error.log shows this for each API call:

«
[error] [client 10.0.0.99] Premature end of script headers: wsgi.py
[alert] (2)No such file or directory: mod_wsgi (pid=12345): Unable to change working directory to '/home/maas'.
»

Indeed there is no /home/maas. Creating it (owned by maas:maas of course) fixes the “maas-cli maas tags list” but the tag-creation command still hangs — as long as the space is there. If I leave out the space, the API considers that a missing argument and errors out immediately.

[Jeroen T. Vermeulen (jtv)]

A note of caution. The wsgi process eventually times out and dies, to get replaced by a fresh one. But while you've got each of the wsgi processes hanging, further experiments may be misleading because you get timeouts caused by earlier calls, not by whatever you're doing in the experiment. Avoid interrupting hanging calls with ctrl-C; let it time out first so you don't fall into this trap.

Each call that dies in this way logs “Premature end of script headers: wsgi.py” in the Apache error log.

[Jeroen T. Vermeulen (jtv)]

And so it was still only the whitespace definition that got stuck, and the call did reach TagsHandler after all.

With that lesson learned, I now see the call get stuck in TagForm.clean_definition, at:

    etree.XPath(definition)

—even though the exact same call run in a bare python interpreter instantly produces the expected lxml.etree.XPathSyntaxError. (The “cleaned” version of the definition is still the original string of whitespace).

Execution goes into machine code at this point. When I run just this line in a python interpreter, strace shows no system calls at all before the call starts generating a backtrace.

[Jeroen T. Vermeulen (jtv)]

I get the same problem when I submit other malformed tag definitions. Looking through the lxml source I find myself suspecting the logging code.

[Jeroen T. Vermeulen (jtv)]

There is no busy-waiting: the lxml call is properly waiting. Here's what I get when I strace the application at this point:

31418 futex(0xb93c0248, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
31417 <... select resumed> ) = 0 (Timeout)
31417 futex(0xb93c0248, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
31416 <... select resumed> ) = 0 (Timeout)

(The last line, and the <unfinished> before it, only seem to appear when the process times out).

The lxml code has some locking that only happens when threading is enabled, so that may explain why I didn't see this when I straced just the call in a python interpreter. The wsgi process does indeed run with threads, and if what we see here is multiple threads vying for the same lock, there may be a deadlock condition.

[Jeroen T. Vermeulen (jtv)]

It may be this: https://techknowhow.library.emory.edu/blogs/branker/2010/07/30/django-lxml-wsgi-and-python-sub-interpreter-magic

[Jeroen T. Vermeulen (jtv)]

Yup, that seems to be the problem. Applying one of the suggested workarounds from the article stops the lockups.