RuntimeError: XML queue overflow

[funbaker]

Im trying to run the following program, using the pyvo library:

import pyvo

svc = pyvo.dal.TAPService("http://tapvizier.u-strasbg.fr/TAPVizieR/tap")
with svc.submit_job(
    """SELECT raj2000, dej2000, w1mag, w2mag, w3mag, w4mag
        FROM "II/328/allwise"
        WHERE 1=CONTAINS(
                      POINT('ICRS', raj2000, dej2000),
                      CIRCLE('ICRS', 10, 20, 0.25))"""
) as job:
    try:
        job.run()
        job.wait()
        res = job.fetch_result()
    except Exception as e:
        # uri pointing to the votable file
        print(job.result_uri)
        raise

which results in the following error:

Traceback (most recent call last):
  File "bugreport.py", line 14, in <module>
    res = job.fetch_result()
  File "/pyvo/pyvo/dal/tap.py", line 761, in fetch_result
    _votableparse(response.raw.read), self.result_uri,
  File "/pyvo/pyvo/dal/query.py", line 1528, in _votableparse
    config=config, pos=(1, 1), version=version).parse(iterator, config)
  File "/virtualenv/local/lib/python2.7/site-packages/astropy/io/votable/tree.py", line 3393, in parse
    iterator, tag, data, config, pos)
  File "/virtualenv/local/lib/python2.7/site-packages/astropy/io/votable/tree.py", line 3322, in _add_resource
    resource.parse(self, iterator, config)
  File "/virtualenv/local/lib/python2.7/site-packages/astropy/io/votable/tree.py", line 3147, in parse
    iterator, tag, data, config, pos)
  File "/virtualenv/local/lib/python2.7/site-packages/astropy/io/votable/tree.py", line 3104, in _add_table
    table.parse(iterator, config)
  File "/virtualenv/local/lib/python2.7/site-packages/astropy/io/votable/tree.py", line 2397, in parse
    iterator, colnumbers, fields, config)
  File "/virtualenv/local/lib/python2.7/site-packages/astropy/io/votable/tree.py", line 2474, in _parse_tabledata
    for start, tag, data, pos in iterator:
RuntimeError: XML queue overflow in endElement.  This most likely indicates an internal bug.

Versions:
astropy: 1.3
numpy: 1.12.0
python: 2.7.12 (same with 3.5.2)

[pllim]

Please attach the actual table file and also confirm that it actually follows VO standards. astropy.io.votable is not guaranteed to work if the table does not conform to standards.

[funbaker]

Heres the table file
bugreport.xml.zip

astropy.io.votable.validate only throws those two warnings:

6: W35: 'value' attribute required for INFO elements
                <INFO name="QUERY"><![CDATA[SELECT raj2000, dej2000...
                ^

11: W27: COOSYS deprecated in VOTable 1.2
                <COOSYS ID="coosys_FK5" system="eq_FK5" equinox="20...

Well, i know there is also something not right with the arraysize parameter...

[pllim]

Not sure what pyvo is doing but using the latest dev version of Astropy, I am able to load the table successfully. Can you check on your side with Astropy 1.3? If you can run the following fine, then you should file an issue on the pyvo side instead.

>>> import astropy
>>> astropy.__version__
'2.0.dev17886'
>>> from astropy.table import Table
>>> tab = Table.read('bugreport.xml', format='votable')
WARNING: W35: bugreport.xml:6:2: W35: 'value' attribute required for INFO elements [astropy.io.votable.tree]
WARNING: W27: bugreport.xml:11:2: W27: COOSYS deprecated in VOTable 1.2 [astropy.io.votable.tree]
>>> tab
<Table masked=True length=2538>
RAJ2000 [1] DEJ2000 [1] W1mag [1] W2mag [1] W3mag [1] W4mag [1]
    deg         deg        mag       mag       mag       mag   
  float64     float64    float32   float32   float32   float32 
----------- ----------- --------- --------- --------- ---------
 10.0500458   19.757055    16.848    16.346    12.221     8.998
 10.0415944  19.7670545    17.392    16.644    12.406     8.571
 10.0108147   19.755775    17.256    17.096    12.559     8.948
  9.9922353  19.7511416    17.648    16.553     12.17     8.218
  9.9816437  19.7507113    16.164    16.015     12.39     9.044
  9.9866186  19.7557493    16.118    16.394    12.597     8.919
        ...         ...       ...       ...       ...       ...
  9.9856502  20.2367117     17.02    17.337    11.966     8.859
  9.9935504  20.2470238    16.491    16.713    12.547     8.966
  9.9855978  20.2464858    16.885    16.466    12.585     8.992
  9.9689587  20.2405518    16.836     16.37    12.616     8.839
  9.9558873  20.2455505    17.222     17.25    12.724     9.119
  9.9633682  20.2460298    15.724    15.676    12.602     8.868

[funbaker]

Reading from a local file works fine indeed.

PyVO is doing some complicated stuff involving a custom config and calling astropy internal methods manually, so i reduced that part to

from astropy.io.votable import parse
return parse(source)

where source is a file-like object returned by the requests library.
Same result.

Parsing from the local file-obj works fine, so i wrote the return value of both read calls into separate files and ran diff -u over them
(i don't know why they are different at all, except for the query info element caused by indentation.
Maybe because Firefox processes the xml before saving):

c1.xml: local
c2.xml: remote

--- c1.xml	2017-02-20 10:53:57.640852489 +0100
+++ c2.xml	2017-02-20 10:53:57.640852489 +0100
@@ -1,19 +1,19 @@
 <?xml version="1.0" encoding="UTF-8"?>
 <VOTABLE version="1.2" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="http://www.ivoa.net/xml/VOTable/v1.2" xmlns="http://www.ivoa.net/xml/VOTable/v1.2">
 	<RESOURCE type="results">
-		<INFO name="QUERY_STATUS" value="OK"/>
+		<INFO name="QUERY_STATUS" value="OK" />
 		<INFO name="PROVIDER" value="TAPVizieR">VizieR TAP service.</INFO>
 		<INFO name="QUERY"><![CDATA[SELECT raj2000, dej2000, w1mag, w2mag, w3mag, w4mag
-        FROM "II/328/allwise"
-        WHERE 1=CONTAINS(
-                      POINT('ICRS', raj2000, dej2000),
-                      CIRCLE('ICRS', 10, 20, 0.25))]]></INFO>
-		<COOSYS ID="coosys_FK5" system="eq_FK5" equinox="2000.0"/>
+            FROM "II/328/allwise"
+            WHERE 1=CONTAINS(
+                POINT('ICRS', raj2000, dej2000),
+                CIRCLE('ICRS', 10, 20, 0.25))]]></INFO>
+		<COOSYS ID='coosys_FK5' system='eq_FK5' equinox='2000.0'/>
 		<TABLE>
-			<FIELD ID="RAJ2000" name="RAJ2000" datatype="double" arraysize="1" ucd="pos.eq.ra;meta.main" unit="deg" ref="coosys_FK5">
+			<FIELD ID="RAJ2000" name="RAJ2000" datatype="double" arraysize="1" ucd="pos.eq.ra;meta.main" unit="deg" ref='coosys_FK5'>
 <DESCRIPTION>Right ascension (J2000)</DESCRIPTION>
 </FIELD>
-			<FIELD ID="DEJ2000" name="DEJ2000" datatype="double" arraysize="1" ucd="pos.eq.dec;meta.main" unit="deg" ref="coosys_FK5">
+			<FIELD ID="DEJ2000" name="DEJ2000" datatype="double" arraysize="1" ucd="pos.eq.dec;meta.main" unit="deg" ref='coosys_FK5'>
 <DESCRIPTION>Declination (J2000)</DESCRIPTION>
 </FIELD>
 			<FIELD ID="W1mag" name="W1mag" datatype="float" arraysize="1" ucd="phot.mag;em.IR.3-4um" unit="mag">
@@ -1963,7 +1963,7 @@
 <TR><TD>10.0950335</TD><TD>20.1427539</TD><TD>15.965</TD><TD>16.082</TD><TD>12.216</TD><TD>8.443</TD></TR>
 <TR><TD>10.0992395</TD><TD>20.1429400</TD><TD>17.393</TD><TD>16.631</TD><TD>12.238</TD><TD>8.979</TD></TR>
 <TR><TD>10.0881509</TD><TD>20.1455762</TD><TD>17.568</TD><TD>17.097</TD><TD>12.246</TD><TD>8.542</TD></TR>
-<TR><TD>10.0989969</TD><TD>20.1507476</TD><TD>17.024</TD><TD>16.382</TD><TD>12.019</TD><TD/></TR>
+<TR><TD>10.0989969</TD><TD>20.1507476</TD><TD>17.024</TD><TD>16.382</TD><TD>12.019</TD><TD></TD></TR>
 <TR><TD>10.0790436</TD><TD>20.1435568</TD><TD>17.399</TD><TD>16.651</TD><TD>12.041</TD><TD>8.678</TD></TR>
 <TR><TD>10.0688502</TD><TD>20.1414011</TD><TD>16.059</TD><TD>15.948</TD><TD>12.554</TD><TD>8.711</TD></TR>
 <TR><TD>10.0898150</TD><TD>20.1589132</TD><TD>17.083</TD><TD>17.048</TD><TD>12.432</TD><TD>8.542</TD></TR>
@@ -2573,4 +2573,4 @@
 			</DATA>
 		</TABLE>
 	</RESOURCE>
-</VOTABLE>
\ Kein Zeilenumbruch am Dateiende. # no newline at file end
+</VOTABLE>

If i would guess, i'd say it has something to do with <TD/> vs <TD></TD>

[pllim]

I am not sure what can be fixed on Astropy side in this case. Any suggestion?

[sladen]

The circumstances when the bug occurs are quite specific: >=816 rows and >=4 columns are required (the contents of the columns do not matter, eg.: raj2000, raj2000, raj2000, raj2000 repeated). It only occurs with the _fast_iterparse() code path—not with the _slow_iterparse() codepath. The diff necessary to upset the XML parser is minimal:

--- cached_result.votable.xml.circle.815.good	2017-02-24 17:10:35.881331402 +0100
+++ cached_result.votable.xml.circle.816.bad	2017-02-24 17:10:20.821371217 +0100
@@ -4,6 +4,6 @@
 SELECT
-  TOP 815
+  TOP 816
   raj2000, dej2000, w1mag, w2mag
   FROM "II/328/allwise"
   WHERE 1=CONTAINS(POINT('ICRS', raj2000, dej2000), CIRCLE('ICRS', 0, 0, 0.149))
 ]]></INFO>
@@ -840,2 +840,3 @@
 <TR><TD>359.9752481</TD><TD>0.1319479</TD><TD>17.120</TD><TD>17.008</TD></TR>
+<TR><TD>359.9583354</TD><TD>0.1323975</TD><TD>16.736</TD><TD>16.755</TD></TR>
 				</TABLEDATA>

Core of debug harness:

adql_query = """
SELECT
  TOP {:d}
  raj2000, dej2000, w1mag, w2mag
  FROM "II/328/allwise"
  WHERE 1=CONTAINS(POINT('ICRS', raj2000, dej2000), CIRCLE('ICRS', 0, 0, 0.149))
""".format((815, 816)[not use_safe_number_of_results])
…
def main():
    …
    if use_local_file:
        # always works
        f = open(local_filename, 'r')
    else:
        # doesn't work when using _fast_iterparse
        keep_gzip = dump_votable_xml_gzip
        f = functools.partial(response.raw.read, decode_content=not keep_gzip)

    if use_slow_and_reliable:
        # always works
        iterable = iter(astropy.utils.xml.iterparser._slow_iterparse(f))
    else:
        # doesn't work when using 'response.raw.read'
        iterable = iter(astropy.utils.xml.iterparser._fast_iterparse(f))

The following tarball contains a test harness (bug-5824-test-harness.py), the gzip-streams returned from the remote server (*.votable.xml.gz), the uncompressed streams for 815/816 rows (*.votable.xml), and the textual diff (bug-5824-top815-top816.diff):

• bug-5824-20170224.tar.gz

[pllim]

Thank you for the detailed info. So, looks like a bug in the C parser.

[sladen]

The underlying trigger is that this TAP provider returns Gzip-compressed data (a good thing). From this response, the requested number of bytes (eg. 8192) are ingested by response.raw.read() which then provides transparent decompression. The uncompressed contents are usually different in length: ~5‒10 times larger in the common case, but can also be shorter than the compressed input in extreme circumstances. The nature of compression means that it is necessary to fully read the headers (eg. Huffman tables) before any useful plain-text decompressed data can begin to be decoded—eg. so read(1) will return zero for the first couple of hundred calls until the Gzip headers have been walked over.

There are three lengths involved:

• self->buffersize (defaults to 16384 in IterParser_init(), can be overridden, clamped to the range 1kB < buffersize < 16MB
• self->queue_size (set to buffersize / 2 == 8192 in IterParser_init(). This is what overflows.
• buflen is the result of calling response.raw.read() with the value of self->buffersize, so expected to be <= 16384, but isn't in this case.

The presumptions are that:

• an under-read (less than the requested number of bytes) always indicates the last block, and so setting self->done = 1. This means that situations of network buffering etc cannot be handled.
• an over-read (more than the requested number of bytes) is not anticipated, and not checked for. The entire read() result is fed to XML_Parse() verbatim, which then repeatedly calls the handlers startElement() and endElement() while self->queue_write_idx < self->queue_size, at which point the queue overflow is detected and the RuntimeError is raised.

IterParser_next() initiates XML_Parse() to parse data and fill the queue, and also initiates the dequeuing (it is an iterator). However the XML_Parse() doesn't know when to stop eating, and will try to process the whole buffer passed to it, even if some of the handlers detect that the queue is full. This is why at the moment the handlers simply raise the exception.

There are several possible solutions; the most ideal would probably be to have the handlers yield back to IterParser_next() so that de-queueing can begin, and only carry on when there is space. Another option would be to buffer the input to cope with overflow (uncompressed data larger than requested), but it is still the case that with chunking/network streams/pipes/compression/buffering there will still be some variance and underflow would not be handled. A further option would be to dynamically realloc() the self->queue to the returned buflen/2 before continuing.

There are also some kludges in the short term, to workaround the immediate symptom without curing/fixing the underlying problems: one is to pass a larger buffersize to IterParser_init() on setup.

Are there any preferences/thoughts about which style of fix would be most appropriate for the upstream codebase?

[pllim]

I am going to c/c the following maintainers for utils and table for their inputs: @eteq , @bsipocz , @taldcroft , @mhvk

[sladen]

Following tarball contains bug-5824-underflow-overflow.py (84 lines) and corresponding testcase-512tags.votable.xml.gz (230 bytes) which allow emulating a series of network buffering/decompression read underflow/overflow situations without network access or remote services:

• bug-5824-20170308.tar.gz

(This is to enable patch validation).

[sladen]

Initial patch that consolidates the logic and extends the the queue/queue_size when returned buflen > buffersize.

(This does not fix the EOF detection on non-regular files that was discovered in the process).

[pllim]

@sladen , do you intend to submit an official PR?

[sladen]

@pllim, done!

[pllim]

#5869 is merged, so grabbing the latest dev should fix your problem here. Otherwise, it will be in 1.3.2 release. Thank you!