KeyError: <SassRule <RuleAncestry ()>, 0 props> Failure

[Joshua Harlow]

Seeing a new gate failure that causes tempest to fail:

http://logs.openstack.org/49/107549/11/check/check-tempest-dsvm-postgres-full/2c0808c/logs/testr_results.html.gz

[Mon Jul 21 04:24:17.823759 2014] [:error] [pid 20477:tid 140176873875200] Internal Server Error: /
[Mon Jul 21 04:24:17.823869 2014] [:error] [pid 20477:tid 140176873875200] Traceback (most recent call last):
[Mon Jul 21 04:24:17.823909 2014] [:error] [pid 20477:tid 140176873875200] File "/usr/local/lib/python2.7/dist-packages/django/core/handlers/base.py", line 112, in get_response
[Mon Jul 21 04:24:17.823971 2014] [:error] [pid 20477:tid 140176873875200] response = wrapped_callback(request, *callback_args, **callback_kwargs)
[Mon Jul 21 04:24:17.824036 2014] [:error] [pid 20477:tid 140176873875200] File "/usr/local/lib/python2.7/dist-packages/django/views/decorators/vary.py", line 36, in inner_func
[Mon Jul 21 04:24:17.824071 2014] [:error] [pid 20477:tid 140176873875200] response = func(*args, **kwargs)
[Mon Jul 21 04:24:17.824131 2014] [:error] [pid 20477:tid 140176873875200] File "/opt/stack/new/horizon/openstack_dashboard/wsgi/../../openstack_dashboard/views.py", line 45, in splash
[Mon Jul 21 04:24:17.824208 2014] [:error] [pid 20477:tid 140176873875200] return shortcuts.render(request, 'splash.html', {'form': form})
[Mon Jul 21 04:24:17.824446 2014] [:error] [pid 20477:tid 140176873875200] File "/usr/local/lib/python2.7/dist-packages/django/shortcuts/__init__.py", line 53, in render
[Mon Jul 21 04:24:17.824611 2014] [:error] [pid 20477:tid 140176873875200] return HttpResponse(loader.render_to_string(*args, **kwargs),
[Mon Jul 21 04:24:17.824776 2014] [:error] [pid 20477:tid 140176873875200] File "/usr/local/lib/python2.7/dist-packages/django/template/loader.py", line 169, in render_to_string
[Mon Jul 21 04:24:17.824807 2014] [:error] [pid 20477:tid 140176873875200] return t.render(context_instance)
[Mon Jul 21 04:24:17.824891 2014] [:error] [pid 20477:tid 140176873875200] File "/usr/local/lib/python2.7/dist-packages/django/template/base.py", line 140, in render
[Mon Jul 21 04:24:17.824924 2014] [:error] [pid 20477:tid 140176873875200] return self._render(context)
[Mon Jul 21 04:24:17.824956 2014] [:error] [pid 20477:tid 140176873875200] File "/usr/local/lib/python2.7/dist-packages/django/template/base.py", line 134, in _render
[Mon Jul 21 04:24:17.825061 2014] [:error] [pid 20477:tid 140176873875200] return self.nodelist.render(context)
[Mon Jul 21 04:24:17.825091 2014] [:error] [pid 20477:tid 140176873875200] File "/usr/local/lib/python2.7/dist-packages/django/template/base.py", line 840, in render
[Mon Jul 21 04:24:17.825124 2014] [:error] [pid 20477:tid 140176873875200] bit = self.render_node(node, context)
[Mon Jul 21 04:24:17.825212 2014] [:error] [pid 20477:tid 140176873875200] File "/usr/local/lib/python2.7/dist-packages/django/template/debug.py", line 78, in render_node
[Mon Jul 21 04:24:17.825272 2014] [:error] [pid 20477:tid 140176873875200] return node.render(context)
[Mon Jul 21 04:24:17.825304 2014] [:error] [pid 20477:tid 140176873875200] File "/usr/local/lib/python2.7/dist-packages/django/template/loader_tags.py", line 155, in render
[Mon Jul 21 04:24:17.825431 2014] [:error] [pid 20477:tid 140176873875200] return self.render_template(self.template, context)
[Mon Jul 21 04:24:17.825554 2014] [:error] [pid 20477:tid 140176873875200] File "/usr/local/lib/python2.7/dist-packages/django/template/loader_tags.py", line 137, in render_template
[Mon Jul 21 04:24:17.825589 2014] [:error] [pid 20477:tid 140176873875200] output = template.render(context)
[Mon Jul 21 04:24:17.825756 2014] [:error] [pid 20477:tid 140176873875200] File "/usr/local/lib/python2.7/dist-packages/django/template/base.py", line 140, in render
[Mon Jul 21 04:24:17.825784 2014] [:error] [pid 20477:tid 140176873875200] return self._render(context)
[Mon Jul 21 04:24:17.825838 2014] [:error] [pid 20477:tid 140176873875200] File "/usr/local/lib/python2.7/dist-packages/django/template/base.py", line 134, in _render
[Mon Jul 21 04:24:17.825895 2014] [:error] [pid 20477:tid 140176873875200] return self.nodelist.render(context)
[Mon Jul 21 04:24:17.825987 2014] [:error] [pid 20477:tid 140176873875200] File "/usr/local/lib/python2.7/dist-packages/django/template/base.py", line 840, in render
[Mon Jul 21 04:24:17.826034 2014] [:error] [pid 20477:tid 140176873875200] bit = self.render_node(node, context)
[Mon Jul 21 04:24:17.826062 2014] [:error] [pid 20477:tid 140176873875200] File "/usr/local/lib/python2.7/dist-packages/django/template/debug.py", line 78, in render_node
[Mon Jul 21 04:24:17.826116 2014] [:error] [pid 20477:tid 140176873875200] return node.render(context)
[Mon Jul 21 04:24:17.826200 2014] [:error] [pid 20477:tid 140176873875200] File "/usr/local/lib/python2.7/dist-packages/compressor/templatetags/compress.py", line 149, in render
[Mon Jul 21 04:24:17.826407 2014] [:error] [pid 20477:tid 140176873875200] return self.render_compressed(context, self.kind, self.mode, forced=forced)
[Mon Jul 21 04:24:17.826542 2014] [:error] [pid 20477:tid 140176873875200] File "/usr/local/lib/python2.7/dist-packages/compressor/templatetags/compress.py", line 108, in render_compressed
[Mon Jul 21 04:24:17.826611 2014] [:error] [pid 20477:tid 140176873875200] rendered_output = self.render_output(compressor, mode, forced=forced)
[Mon Jul 21 04:24:17.826654 2014] [:error] [pid 20477:tid 140176873875200] File "/usr/local/lib/python2.7/dist-packages/compressor/templatetags/compress.py", line 121, in render_output
[Mon Jul 21 04:24:17.826750 2014] [:error] [pid 20477:tid 140176873875200] return compressor.output(mode, forced=forced)
[Mon Jul 21 04:24:17.826806 2014] [:error] [pid 20477:tid 140176873875200] File "/usr/local/lib/python2.7/dist-packages/compressor/css.py", line 51, in output
[Mon Jul 21 04:24:17.826908 2014] [:error] [pid 20477:tid 140176873875200] ret.append(subnode.output(*args, **kwargs))
[Mon Jul 21 04:24:17.827069 2014] [:error] [pid 20477:tid 140176873875200] File "/usr/local/lib/python2.7/dist-packages/compressor/css.py", line 53, in output
[Mon Jul 21 04:24:17.827102 2014] [:error] [pid 20477:tid 140176873875200] return super(CssCompressor, self).output(*args, **kwargs)
[Mon Jul 21 04:24:17.827136 2014] [:error] [pid 20477:tid 140176873875200] File "/usr/local/lib/python2.7/dist-packages/compressor/base.py", line 285, in output
[Mon Jul 21 04:24:17.827252 2014] [:error] [pid 20477:tid 140176873875200] output = '\\n'.join(self.filter_input(forced))
[Mon Jul 21 04:24:17.827293 2014] [:error] [pid 20477:tid 140176873875200] File "/usr/local/lib/python2.7/dist-packages/compressor/base.py", line 224, in filter_input
[Mon Jul 21 04:24:17.827408 2014] [:error] [pid 20477:tid 140176873875200] for hunk in self.hunks(forced):
[Mon Jul 21 04:24:17.827445 2014] [:error] [pid 20477:tid 140176873875200] File "/usr/local/lib/python2.7/dist-packages/compressor/base.py", line 200, in hunks
[Mon Jul 21 04:24:17.827473 2014] [:error] [pid 20477:tid 140176873875200] precompiled, value = self.precompile(value, **options)
[Mon Jul 21 04:24:17.827547 2014] [:error] [pid 20477:tid 140176873875200] File "/usr/local/lib/python2.7/dist-packages/compressor/base.py", line 264, in precompile
[Mon Jul 21 04:24:17.827610 2014] [:error] [pid 20477:tid 140176873875200] return True, filter.input(**kwargs)
[Mon Jul 21 04:24:17.827644 2014] [:error] [pid 20477:tid 140176873875200] File "/usr/local/lib/python2.7/dist-packages/django_pyscss/compressor.py", line 30, in input
[Mon Jul 21 04:24:17.827668 2014] [:error] [pid 20477:tid 140176873875200] relative_to=self.relative_to)
[Mon Jul 21 04:24:17.827710 2014] [:error] [pid 20477:tid 140176873875200] File "/usr/local/lib/python2.7/dist-packages/scss/__init__.py", line 438, in compile
[Mon Jul 21 04:24:17.827735 2014] [:error] [pid 20477:tid 140176873875200] return self.Compilation(*args, **kwargs)
[Mon Jul 21 04:24:17.827794 2014] [:error] [pid 20477:tid 140176873875200] File "/usr/local/lib/python2.7/dist-packages/django_pyscss/scss.py", line 188, in Compilation
[Mon Jul 21 04:24:17.827819 2014] [:error] [pid 20477:tid 140176873875200] self.apply_extends()
[Mon Jul 21 04:24:17.827877 2014] [:error] [pid 20477:tid 140176873875200] File "/usr/local/lib/python2.7/dist-packages/scss/util.py", line 111, in wrapper
[Mon Jul 21 04:24:17.827902 2014] [:error] [pid 20477:tid 140176873875200] return func(*args, **kwargs)
[Mon Jul 21 04:24:17.828017 2014] [:error] [pid 20477:tid 140176873875200] File "/usr/local/lib/python2.7/dist-packages/scss/__init__.py", line 1398, in apply_extends
[Mon Jul 21 04:24:17.828282 2014] [:error] [pid 20477:tid 140176873875200] self.rules.sort(key=lambda rule: min(rule_dependencies[rule]))
[Mon Jul 21 04:24:17.828319 2014] [:error] [pid 20477:tid 140176873875200] File "/usr/local/lib/python2.7/dist-packages/scss/__init__.py", line 1398, in <lambda>
[Mon Jul 21 04:24:17.828377 2014] [:error] [pid 20477:tid 140176873875200] self.rules.sort(key=lambda rule: min(rule_dependencies[rule]))
[Mon Jul 21 04:24:17.828406 2014] [:error] [pid 20477:tid 140176873875200] KeyError: <SassRule <RuleAncestry ()>, 0 props>

[Gary W. Smith (gary-w-smith)]

This error is coming from the scss compiler and is likely due to an error in one of horizon's scss files. The scss files have undergone substantial changes since this bug was reported, including the bootstrap update (https://review.openstack.org/#/c/107042/). Closing this bug since it is likely no longer relevant. Please reopen if it happens again.

[Gary W. Smith (gary-w-smith)]

Searching through logstash.openstack.org with the query:
message:"KeyError" AND tags:"horizon_error.txt"
reveals that this, and several variations of it, is still an ongoing problem. The specific error message varies a lot, so it does not appear to be hitting the same problem every time. Also, the build status of this job, check-tempest-dsvm-postgres-full, is almost always SUCCESS despite this error.

[Akihiro Motoki (amotoki)]

According to logstash query, it hit 50 hits in last 2 days (67 hits in last 7 days).
It means 3hits/day increases to 25 hits/day. It is a significant change.
We should investigate it more.

http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOlwiS2V5RXJyb3I6IDxTYXNzUnVsZSA8UnVsZUFuY2VzdHJ5XCIgYW5kIGZpbGVuYW1lOlwibG9ncy9ob3Jpem9uLWVycm9yLnR4dFwiIiwiZmllbGRzIjpbXSwib2Zmc2V0IjowLCJ0aW1lZnJhbWUiOiI2MDQ4MDAiLCJncmFwaG1vZGUiOiJjb3VudCIsInRpbWUiOnsidXNlcl9pbnRlcnZhbCI6MH0sInN0YW1wIjoxNDEwMzM0MDM0NjA1fQ==

message:"KeyError: <SassRule <RuleAncestry" and filename:"logs/horizon-error.txt"

[Akihiro Motoki (amotoki)]

To raise an attention, set target to Juno-RC1 and priority to High.
If it is temporary, we can lower the priority.

[Gary W. Smith (gary-w-smith)]

Some other info about this problem:
- showing the build_status in logstash reveals that the build often succeeds despite this error, so this error is not necessarily the cause of the build failures
- this bug rarely (never?) appears when running locally with run_tests.sh
- unlike running horizon with run_tests.sh, the build system runs horizon from apache configured with 3 processes, so the horizon log shows 3 copies of some of the messages as it starts. The problem is occurring during the scss compilation, and the intermittent nature of this bug suggests a race condition between multiple concurrent compilations process might be the problem.
- the django compressor tries to avoid re-parsing files that it has already processed, and may be confused by multiple concurrent compiles (See also http://django-compressor.readthedocs.org/en/latest/behind-the-scenes/ and http://stackoverflow.com/questions/11114679/django-compressor-not-regenerating-compressed-css)

[Joe Gordon (jogo)]

This bug doesn't always cause failures because not every call to horizon in the tempest test can cause the tempest test to fail.

[Doug Fish (drfish)]

I've found a fairly consistent recreation scenario for the dev environment:

End the dev server if it is running. Restart it:
./run_server.sh --runserver 0.0.0.0:8081
in a separate window on the same VM fire off 2 simultaneous requests:
curl http://localhost:8081 & curl http://localhost:8081

[Doug Fish (drfish)]

and by "./run_server.sh" I actually mean "./run_tests.sh". Oops!

[Nolan Brubaker (nolan-brubaker)]

I'm also able to reliably get SassRule exceptions, however I had to use a short script to generate enough requests to get the timing issues to happen on my devstack VM: https://gist.github.com/nrb/66da8398f34cfcd458f1

[Sean Dague (sdague)]

Yeh, this is a pretty fundamental problem. I think there needs to be some kind of safe caching pushed into pyscss otherwise this is going to be somewhat disasterous.

[Doug Fish (drfish)]

FWIW I explored the approach of fixing the threading problem (rather than avoiding it). I don't think we can make the work in Horizon itself. My work ended up here: https://github.com/Kronuz/pyScss/pull/304

[Doug Fish (drfish)]

I didn't realize we could pull in a version of pyscss so late! Once we get the version associated with https://bugs.launchpad.net/horizon/+bug/1370137 we'll pick up the change I provided above and this will be fixed.

[Doug Fish (drfish)]

Problem hasn't recurred since 9/18. I think we should declare this fixed.

http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOlwiS2V5RXJyb3I6IDxTYXNzUnVsZVwiIGFuZCBmaWxlbmFtZTpcImxvZ3MvaG9yaXpvbi1lcnJvci50eHRcIiIsImZpZWxkcyI6W10sIm9mZnNldCI6MCwidGltZWZyYW1lIjoiY3VzdG9tIiwiZ3JhcGhtb2RlIjoiY291bnQiLCJ0aW1lIjp7ImZyb20iOiIyMDE0LTA5LTE5VDE3OjQ0OjAyKzAwOjAwIiwidG8iOiIyMDE0LTA5LTIyVDE3OjQ0OjAyKzAwOjAwIiwidXNlcl9pbnRlcnZhbCI6IjAifSwic3RhbXAiOjE0MTE0MDc5ODQ5Njd9