sci-mathematics/sage-7.5.1[doc] - AssertionError: len(context) = 1

[gagern]

After downgrading sphinx to 1.4.4::sage-on-gentoo in response to #450, I encounter a different error while building the documentation:

[developer] writing output... [100%] workflows
[developer] Exception occurred:
[developer] File "/usr/lib64/python2.7/site-packages/docutils/writers/_html_base.py", line 671, in depart_document
[developer] assert not self.context, 'len(context) = %s' % len(self.context)
[developer] AssertionError: len(context) = 1
[developer] The full traceback has been saved in /var/tmp/portage/sci-mathematics/sage-7.5.1/temp/sphinx-err-q1SBB8.log, if you want to report 
the issue to the developers.
[developer] Please also report this if it was a user error, so that a better error message can be provided next time.
[developer] A bug report can be filed in the tracker at <https://github.com/sphinx-doc/sphinx/issues>. Thanks!
Error building the documentation.
Traceback (most recent call last):
  File "sage_setup/docbuild/__main__.py", line 2, in <module>
    main()
  File "/var/tmp/portage/sci-mathematics/sage-7.5.1/work/sage-7.5.1/src-python2_7/sage_setup/docbuild/__init__.py", line 1667, in main
    builder()
  File "/var/tmp/portage/sci-mathematics/sage-7.5.1/work/sage-7.5.1/src-python2_7/sage_setup/docbuild/__init__.py", line 324, in _wrapper
    build_many(build_other_doc, L)
  File "/var/tmp/portage/sci-mathematics/sage-7.5.1/work/sage-7.5.1/src-python2_7/sage_setup/docbuild/__init__.py", line 252, in build_many
    ret = x.get(99999)
  File "/usr/lib64/python2.7/multiprocessing/pool.py", line 567, in get
    raise self._value
OSError: [developer] Exception occurred:

The mentioned log file contains

# Sphinx version: 1.4.4
# Python version: 2.7.12 (CPython)
# Docutils version: 0.13.1 release
# Jinja2 version: 2.9.4
# Last messages:
#   writing output... [ 65%] sagenb/following_latest
#   writing output... [ 69%] sagenb/forking_hell
#   writing output... [ 73%] sagenb/github_development
#   writing output... [ 76%] sagenb/index
#   writing output... [ 80%] sagenb/maintainer_workflow
#   writing output... [ 84%] sagenb/patching
#   writing output... [ 88%] sagenb/set_up_fork
#   writing output... [ 92%] trac
#   writing output... [ 96%] walk_through
#   writing output... [100%] workflows
# Loaded extensions:
#   sphinx.ext.graphviz (1.4.4) from /usr/lib64/python2.7/site-packages/sphinx/ext/graphviz.pyc
#   sphinx.ext.inheritance_diagram (1.4.4) from /usr/lib64/python2.7/site-packages/sphinx/ext/inheritance_diagram.pyc
#   matplotlib.sphinxext.plot_directive (unknown version) from /usr/lib64/python2.7/site-packages/matplotlib/sphinxext/plot_directive.pyc
#   sphinx.ext.extlinks (1.4.4) from /usr/lib64/python2.7/site-packages/sphinx/ext/extlinks.pyc
#   inventory_builder (unknown version) from /var/tmp/portage/sci-mathematics/sage-7.5.1/work/sage-7.5.1/src-python2_7/sage_setup/docbuild/ext/inventory_builder.py
#   sage_autodoc (1.4.4) from /var/tmp/portage/sci-mathematics/sage-7.5.1/work/sage-7.5.1/src-python2_7/sage_setup/docbuild/ext/sage_autodoc.py
#   alabaster (0.7.9) from /usr/lib64/python2.7/site-packages/alabaster/__init__.pyc
#   sphinx.ext.todo (1.4.4) from /usr/lib64/python2.7/site-packages/sphinx/ext/todo.pyc
#   sphinx.ext.mathjax (1.4.4) from /usr/lib64/python2.7/site-packages/sphinx/ext/mathjax.pyc
#   multidocs (unknown version) from /var/tmp/portage/sci-mathematics/sage-7.5.1/work/sage-7.5.1/src-python2_7/sage_setup/docbuild/ext/multidocs.py
Traceback (most recent call last):
  File "/usr/lib64/python2.7/site-packages/sphinx/cmdline.py", line 244, in main
    app.build(opts.force_all, filenames)
  File "/usr/lib64/python2.7/site-packages/sphinx/application.py", line 298, in build
    self.builder.build_update()
  File "/usr/lib64/python2.7/site-packages/sphinx/builders/__init__.py", line 251, in build_update
    'out of date' % len(to_build))
  File "/usr/lib64/python2.7/site-packages/sphinx/builders/__init__.py", line 322, in build
    self.write(docnames, list(updated_docnames), method)
  File "/usr/lib64/python2.7/site-packages/sphinx/builders/__init__.py", line 360, in write
    self._write_serial(sorted(docnames), warnings)
  File "/usr/lib64/python2.7/site-packages/sphinx/builders/__init__.py", line 368, in _write_serial
    self.write_doc(docname, doctree)
  File "/usr/lib64/python2.7/site-packages/sphinx/builders/html.py", line 446, in write_doc
    self.docwriter.write(doctree, destination)
  File "/usr/lib64/python2.7/site-packages/docutils/writers/__init__.py", line 80, in write
    self.translate()
  File "/usr/lib64/python2.7/site-packages/sphinx/writers/html.py", line 47, in translate
    self.document.walkabout(visitor)
  File "/usr/lib64/python2.7/site-packages/docutils/nodes.py", line 187, in walkabout
    visitor.dispatch_departure(self)
  File "/usr/lib64/python2.7/site-packages/docutils/nodes.py", line 1895, in dispatch_departure
    return method(node)
  File "/usr/lib64/python2.7/site-packages/docutils/writers/_html_base.py", line 671, in depart_document
    assert not self.context, 'len(context) = %s' % len(self.context)
AssertionError: len(context) = 1

That error message appears to indicate some inbalance while traversing the document using a visitor. I couldn't reproduce the problem on the command line because I couldn't get the build started:

# cd /var/tmp/portage/sci-mathematics/sage-7.5.1/work/sage-7.5.1/src-python2_7
# python2.7 sage_setup/docbuild/__main__.py --no-pdf-links all html
Traceback (most recent call last):
  File "sage_setup/docbuild/__main__.py", line 1, in <module>
    from sage_setup.docbuild import main
ImportError: No module named sage_setup.docbuild

Not sure how the ebuild does this differently; even importing the environment didn't make this succeed. So I tried ebuild …/sage-7.5.1.ebuild compile. This does seem to do a lot of that doc-building over again, instead of just picking up where the former run left off. By chance I spotted an error message which did not prevent the build from continuing:

Exception in thread Thread-4:
Traceback (most recent call last):
  File "/usr/lib64/python2.7/threading.py", line 801, in __bootstrap_inner
    self.run()
  File "/usr/lib64/python2.7/threading.py", line 754, in run
    self.__target(*self.__args, **self.__kwargs)
  File "/usr/lib64/python2.7/multiprocessing/pool.py", line 326, in _handle_workers
    pool._maintain_pool()
  File "/usr/lib64/python2.7/multiprocessing/pool.py", line 230, in _maintain_pool
    self._repopulate_pool()
  File "/usr/lib64/python2.7/multiprocessing/pool.py", line 223, in _repopulate_pool
    w.start()
  File "/usr/lib64/python2.7/multiprocessing/process.py", line 130, in start
    self._popen = Popen(self)
  File "/usr/lib64/python2.7/multiprocessing/forking.py", line 121, in __init__
    self.pid = os.fork()
OSError: [Errno 12] Cannot allocate memory

The Sage build appears to consume several gigabytes of memory. OK, I did have a Sage computation running which consumed some 9G of memory. I'm not sure whether the fact that this command failed got handled by not creating more threads, or whether this causes part of the documentation to be missing unnoticed. Or whether this is the reason that my sage build appears to be hung now… So I started the build from scratch, and can reproduce the AssertionError. Strange!

[gagern]

Apparently I found out how to run the build:

cd /var/tmp/portage/sci-mathematics/sage-7.5.1/work/sage-7.5.1/src-python2_7
bash
. ../../../temp/environment
PYTHONPATH="$PWD/build/lib:$PWD" python2 sage_setup/docbuild/__main__.py --no-pdf-links all html

This does reproduce both the building of documentation in what appears to be from scratch and the eventual assertion error. By the way, I see my build running on 5 processes, with 2.5G of resident memory each. Do we really need this much memory? If so, we should probably have the ebuild check it's available (like other heavy duty builds do, e.g. webkit, chromium, libre office iirc). Otherwise we might want to (provide a way to) tone this down a bit, at the expense of longer build times.

OK, I hacked into my /usr/lib64/python2.7/site-packages/docutils/writers/_html_base.py and replaced the context object with a logging version. That enabled me to identify the actual cause of the problem. Sphinx versions prior to 1.5.1 are incompatible with docutils 0.13.1. The breaking change on the docutils side is that they no longer uses the context stack for images. The resulting problem on the sphinx side was reported as sphinx-doc/sphinx#3212 and fixed in sphinx-doc/sphinx#3217.

So the sphinx ebuild should be updated to depend on docutils prior to 0.13. I can write a pull request for this. I'll also open a Gentoo bug report (or pull request) to this effect, since ebuilds from the main portage tree appear to be affected as well.

[kiwifb]

Thanks for that work. The memory consumption for building the documentation is a known issue in sage upstream. We don't really have a clue. But that is an argument for me providing pre-built documentation - and making it the default option - that I had forgotten.

[gagern]

Ah yes, pre-build information would be an adequate solution to the memory consumption issue. The way I see this, the sphinx build maintains some 2G worth of information in its in-memory data structures from reading the sources, and it maintains a pool of workers forked from a process with this much memory consumption so they each get a copy of all that bulk. There has to be a control somewhere to tune the number of workers. Likely somewhere in multiprocessing.

Anyway, my build now made it to the install phase, so things seem to work now. I haven't decided whether I want a bug report for Gentoo main tree, or a pull request backporting the fixes like I did in #452, or just a pull request to express the incompatibility. Probably the last one, I guess.

[jdemeyer]

The memory consumption for building the documentation is a known issue in sage upstream

Sage doesn't have much control about that. We talked about this issue with grand-upstream (sphinx). It is possible to reduce the memory somewhat (by deleting some caches), but that would only gain a few hundred MB of memory. In the end, you need the whole documentation of Sage in memory at some point, and due to the inefficient data structures used by grand-grand-upstream (docutils), this needs a lot of memory.

[kiwifb]

@gagern have you any idea about https://groups.google.com/forum/#!msg/sage-packaging/4W6Lui3Dvyg/Lbg6IGHYBQAJ ? I ask in case you have seen it while debugging.

[gagern]

@jdemeyer: My concern was because the ebuild sets SAGE_NUM_THREADS, so there are typically several processes with this much memory. But after some investigation it looks as though forked processes use copy on write on a per-page level, so unless children modify large portions of heap memory, having that much memory assigned shouldn't be a problem. Next time I run this, I should check how much shared pages these processes have.

@kiwifb: You mean that AttributeError: 'BuildEnvironment' object has no attribute 'citations'? I haven't encountered that. Feels like it might have the same cause as #450. I meant to use my local git clone of plain vanilla Sage to git bisect this for different versions of sphinx, but didn't get that far due to duplicate symbols in mpir:

mpn/.libs/addmul_2.o: In function `__gmpn_addmul_2':
addmul_2.as:(.text+0x0): multiple definition of `__gmpn_addmul_2'
mpn/.libs/redc_2.o:…/sage/local/var/tmp/sage/build/mpir-2.7.2/src/mpn/redc_2.c:38: first defined here
collect2: error: ld returned 1 exit status

[kiwifb]

On 25/01/2017, at 23:40, Martin von Gagern ***@***.***> wrote: mpn/.libs/addmul_2.o: In function `__gmpn_addmul_2': addmul_2.as:(.text+0x0): multiple definition of `__gmpn_addmul_2' mpn/.libs/redc_2.o:…/sage/local/var/tmp/sage/build/mpir-2.7.2/src/mpn/redc_2.c:38: first defined here collect2: error: ld returned 1 exit status

Looks like https://bugs.gentoo.org/show_bug.cgi?id=604764 to me. Since you are on ~arch you would have the nasty version of sed. I don’t remember a matching issue on trac but there should be.

[gagern]

Indeed, it's sed! I've changed the install script to modify the sed invocations in configure, and now it compiles happily. Thanks!