Weird 'StripDirective' object is not iterable error

[cboos]

Found the following traceback in the trac.log for the demo instance for Trac 0.11:

2010-01-08 09:52:35,605 Trac[main] ERROR: Internal Server Error:
Traceback (most recent call last):
  File "/usr/local/virtualenv-0.11/lib/python2.5/site-packages/Trac-0.11.7stable_r8997-py2.5.egg/trac/web/main.py", line 450, in _dispatch_request
    dispatcher.dispatch(req)
  File "/usr/local/virtualenv-0.11/lib/python2.5/site-packages/Trac-0.11.7stable_r8997-py2.5.egg/trac/web/main.py", line 227, in dispatch
    data, content_type)
  File "/usr/local/virtualenv-0.11/lib/python2.5/site-packages/Trac-0.11.7stable_r8997-py2.5.egg/trac/web/chrome.py", line 741, in render_template
    stream = template.generate(**data)
  File "build/bdist.linux-x86_64/egg/genshi/template/base.py", line 519, in generate
    stream = self.stream
  File "build/bdist.linux-x86_64/egg/genshi/template/base.py", line 429, in stream
    self._stream = list(self._prepare(self._stream))
  File "build/bdist.linux-x86_64/egg/genshi/template/base.py", line 480, in _prepare
    for event in tmpl.stream:
  File "build/bdist.linux-x86_64/egg/genshi/template/base.py", line 429, in stream
    self._stream = list(self._prepare(self._stream))
  File "build/bdist.linux-x86_64/egg/genshi/template/base.py", line 458, in _prepare
    for _, cls, value, namespaces, pos in sorted(data[0]):
TypeError: 'StripDirective' object is not iterable

At that time, the Genshi version used was r1092.

Too bad I realized that so late, the access.log files from that period are long gone, so I have no clue which template triggered that error.

[cboos]

Another one:

[pid 8102 1161996624] 2010-06-05 06:58:58,796 Trac[main] ERROR: Internal Server Error: 
Traceback (most recent call last):
  File "build/bdist.linux-x86_64/egg/trac/web/main.py", line 513, in _dispatch_request
    dispatcher.dispatch(req)
  File "build/bdist.linux-x86_64/egg/trac/web/main.py", line 256, in dispatch
    content_type)
  File "build/bdist.linux-x86_64/egg/trac/web/chrome.py", line 812, in render_template
    stream = template.generate(**data)
  File "build/bdist.linux-x86_64/egg/genshi/template/base.py", line 532, in generate
    stream = self.stream
  File "build/bdist.linux-x86_64/egg/genshi/template/base.py", line 442, in stream
    self._stream = list(self._prepare(self._stream))
  File "build/bdist.linux-x86_64/egg/genshi/template/base.py", line 478, in _prepare
    yield kind, (directives, list(substream)), pos
  File "build/bdist.linux-x86_64/egg/genshi/template/base.py", line 478, in _prepare
    yield kind, (directives, list(substream)), pos
  File "build/bdist.linux-x86_64/egg/genshi/template/base.py", line 478, in _prepare
    yield kind, (directives, list(substream)), pos
  File "build/bdist.linux-x86_64/egg/genshi/template/base.py", line 478, in _prepare
    yield kind, (directives, list(substream)), pos
  File "build/bdist.linux-x86_64/egg/genshi/template/base.py", line 478, in _prepare
    yield kind, (directives, list(substream)), pos
  File "build/bdist.linux-x86_64/egg/genshi/template/base.py", line 493, in _prepare
    for event in tmpl.stream:
  File "build/bdist.linux-x86_64/egg/genshi/template/base.py", line 442, in stream
    self._stream = list(self._prepare(self._stream))
  File "build/bdist.linux-x86_64/egg/genshi/template/base.py", line 471, in _prepare
    for _, cls, value, namespaces, pos in sorted(data[0]):
TypeError: 'StripDirective' object is not iterable

From the timing and requests immediately preceding, this could correspond to:

67.195.111.21 trac.edgewall.org - [05/Jun/2010:06:58:28 +0200] "GET /about/timeline?from=2004-02-04T16%3A18%3A03%2B01%3A00&precision=second HTTP/1.0" 200 7518 "-" "Mozilla/5.0 (compatible; Yahoo! Slurp/3.0; http://help.yahoo.com/help/us/ysearch/slurp)"

Which should have returned the /about page.

Anyway, this was right after the morning restart, so this probably corresponds to a race. Immediately after that, there was the Timeout error... no connection I suppose, as we get Timeout daily even without the help of Genshi ;-)

[cboos]

The Template._stream initialization was indeed not thread-safe.

The following change should fix this:

genshi/template/base.py

@@ -16 +16 @@
 from collections import deque
 import os
 from StringIO import StringIO
+try:
+    from threading import RLock
+except ImportError:
+    from dummy_threading import RLock
 import sys
 
 from genshi.core import Attrs, Stream, StreamEventKind, START, TEXT, _ensure
@@ -368 +372 @@
 
     serializer = None
     _number_conv = unicode # function used to convert numbers to event data
+    _stream_lock = RLock()
 
     def __init__(self, source, filepath=None, filename=None, loader=None,
                  encoding=None, lookup='strict', allow_exec=True):
@@ -439 +444 @@
     @property
     def stream(self):
         if not self._prepared:
-            self._stream = list(self._prepare(self._stream))
-            self._prepared = True
+            self._stream_lock.acquire()
+            try:
+                if not self._prepared:
+                    self._stream = list(self._prepare(self._stream))
+                    self._prepared = True
+            finally:
+                self._stream_lock.release()
         return self._stream
 
     def _parse(self, source, encoding):

I used a global lock instead of a lock attached to the instance, for two reasons:

• no headaches with pickling
• avoid the possibility of a deadlock in case of two templates including each other(?)

[cmlenz]

Replying to cboos:

The Template._stream initialization was indeed not thread-safe.

The following change should fix this:

Thanks. Is the double check for self._prepared intentional?

[cboos]

Replying to cmlenz:

Replying to cboos:

The Template._stream initialization was indeed not thread-safe.

The following change should fix this:

Thanks. Is the double check for self._prepared intentional?

Yes, the first check avoids blocking ever again once the stream is "_prepared", the second caters for a possible race condition if two or more threads happen to pass the if not self._prepared test during first time initialization.

There's even a name for this pattern, IIRC, seems to be ​wikipedia:"Double check locking". Now reading this I see many claims that this approach is supposedly broken but here it's different as we're testing a flag set after the assignment to self._stream and Python won't reorder write instructions I suppose... But maybe this question would be worth more digging. Doing only a check when the lock is held would bring us on the safe side, but I would certainly have a non-negligible performance cost (that global lock would have to be acquired on every call to stream) and for no reason if we can effectively rely on _prepared = True to happen after self._stream = list(...).

Reading again on this topic was useful, as it got me wary of using this approach with C++, so thanks for asking ;-)

[cboos]

After reading more on the topic, I'm not that sure anymore about my initial patch. So the safer approach would be:

genshi/template/base.py

@@ -16 +16 @@
 from collections import deque
 import os
 from StringIO import StringIO
+try:
+    from threading import RLock
+except ImportError:
+    from dummy_threading import RLock
 import sys
 
 from genshi.core import Attrs, Stream, StreamEventKind, START, TEXT, _ensure
@@ -368 +372 @@
 
     serializer = None
     _number_conv = unicode # function used to convert numbers to event data
+    _stream_lock = RLock()
 
     def __init__(self, source, filepath=None, filename=None, loader=None,
                  encoding=None, lookup='strict', allow_exec=True):
@@ -438 +443 @@
 
     @property
     def stream(self):
-        if not self._prepared:
-            self._stream = list(self._prepare(self._stream))
-            self._prepared = True
+        self._stream_lock.acquire()
+        try:
+            if not self._prepared:
+                self._stream = list(self._prepare(self._stream))
+                self._prepared = True
+        finally:
+            self._stream_lock.release()
         return self._stream
 
     def _parse(self, source, encoding):

It doesn't seem to have a visible performance impact, at least not when running the test suite. It remains to be seen if this has an effect on a multithreaded Trac under load, but the measuring will not be easy.

[cboos]

As in CPython the GIL ensures there's only one thread executing Python bytecode at a time and that a thread switch occur after a lock release/acquire, I think the first patch (in comment:2) should be safe.

But beyond that, I wonder if there couldn't be a safer and simpler approach, doing the _prepare explicitly after calling the callback(tmpl) in TemplateLoader.load. That would be done under the protection of the TemplateLoader's _lock. I guess the difficulty here is that we can't always assume there's a TemplateLoader involved, right?

[cboos]

... doing the _prepare explicitly after calling the callback(tmpl) in TemplateLoader.load.

By which the fix becomes a one-liner:

genshi/template/loader.py

@@ -236 +236 @@
                                                  filename, encoding=encoding)
                         if self.callback:
                             self.callback(tmpl)
+                        tmpl.stream # call _prepare in a thread-safe way
                         self._cache[cachekey] = tmpl
                         self._uptodate[cachekey] = uptodate
                     finally:

I guess the difficulty here is that we can't always assume there's a TemplateLoader involved, right?

... so we could simply state in the doc that using a Template from multiple threads needs some precautions:

• either the Template is obtained via a TemplateLoader and then it's safe
• or it's managed by hand, in which case the application should take care of preparing it in a thread-safe way, much like the TemplateLoader does

The advantage is that there's no overhead at all when the Template is purely local.

[rjollos]

I find these errors in the trac-hacks.org logs a few times per week.

[hodgestar]

Move to milestone 0.9.