Better Debugging output?

[VynceMontgomery]

Trying to use ScribusGeneratorCLI, I got the following opaque error message (snippet shows last non-error output as well):
15:10:31 - ScribusGenerator - INFO: source document consumes 9 data record(s). 15:10:32 - ScribusGenerator - ERROR: error: Traceback (most recent call last): File "/Applications/Scribus.app/Contents/share/scribus/scripts/ScribusGenerator-master/ScribusGeneratorCLI.py", line 148, in <module> generator.run() File "/Applications/Scribus.app/Contents/share/scribus/scripts/ScribusGenerator-master/ScribusGeneratorBackend.py", line 170, in run outputElt = ET.fromstring(outContent) File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/xml/etree/ElementTree.py", line 1300, in XML parser.feed(text) File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/xml/etree/ElementTree.py", line 1642, in feed self._raiseerror(v) File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/xml/etree/ElementTree.py", line 1506, in _raiseerror raise err ParseError: not well-formed (invalid token): line 1, column 113456
The cause was the same as #80 (needs XML escaping) but figuring that out was not trivial because the output doesn't tell me what it's about to try to do.

.

[VynceMontgomery]

another debugging output that would be useful: I had a variable called %VAR_show_foo% but i accidentally named the column has_foo. it would be nice if variables that were asked for and not supplied were collated for output, like
'INFO: No variables found for show_foo, show_bar, max_quux'

[berteh]

I like the idea to gather unreplaced variables.
This magic should happen around l.519 in ScribusBackend.py, if you wanna have a look... maybe by recording the content of "line" before it is cleaned, and extracting the variables names from it in those cases where d is positive... but I can't get re.findall() result to print as a string in the logging.info call, any clue ?
B.

        # remove (& trim) any (unused) %VAR_\w*% like string.
        if (clean):
            line_bak = line
            if (CONST.REMOVE_CLEANED_ELEMENT_PREFIX):
                (line, d) = re.subn('\s*[,;-]*\s*%VAR_\w*?%\s*', '', line)
            else:
                (line, d) = re.subn('\s*%VAR_\w*?%\s*', '', line)
            if (d > 0):
				unknown_vars = ', '.join(re.findall('\s*%VAR_(\w)*?%\s*', '\1 ', line_bak))
				logging.info("cleaned unknown variables: %s" % unknown_vars)
            (line, d) = re.subn('\s*%s\w*\s*' %
                                CONST.NEXT_RECORD, '', line)

[VynceMontgomery]

I don't know python well, but from a design standpoint i think it might be better to separately record:
(a) substitution names requested by the template
(b) columns provided in the data
(c) successful substitutions made.

This provides flexibility in how they are reported. For instance, the normal output might just say how many names were used in the template and not supplied; the debugging output could say what names were requested and not supplied; and the verbose output could say, if anything was not supplied, what names were in the data that weren't used by the template. (e.g., "No data provided for %VAR_quux%, %VAR_fooBar%. Unused columns include: count, foo-bar, fooBaz, quuux.")

That said, looking at your sample code, the '\1 ' looks suspect, as the format for re.findall() is PATTERN, STRING, [FLAGS]. Also, since you have grouped (\w) the return value will be a "list of groups" which might mean they are not immediately stringifiable; I'm not sure, and the documentation is IMO unclear on the matter.