Log file, line and column information to enable better debugging of source files

[jkrenzer]

Hi!

To make pandoc's errors and warnings regarding syntax or media easier to inspect in IDEs or to generate links to problematic source-code, I would like to suggest to also log the processed file, line and column in the source where the problem was encounterd.

This way, other tools could make dealing with these problems much easier for the user, especially when complex and big documents are involved. Currently we are using CI to produce our reports with pandoc. Spelling and markdown-linting is already well integrated in the IDE we use, but debugging e.g. missing media or broken LaTeX math still requires some search effort as the whole documents structure consists of tens of docs with 20-30 screen pages each. Of course I can watch for pandoc's errors and grep or tree-search for the problematic expression but it would be much faster to integrate pandoc's logs with the problem interface of the IDE.

For this to work, one needs information on file, line and column of the problem additional to the already provided message and severity information. I would strongly suggest to at least add this information to the output generated by pandoc's --log=FILE. Regarding the CLI logging output a good representation and if to hide this feature behind a flag might be some topics to think about.

Thanks for your thoughts on this!

Jörn

[jgm]

We do include source positions when possible (e.g. for parse errors).
But if the error comes from the writer, then the problem is that it just doesn't know the original source position -- the input of the writer is a Pandoc AST.

[jgm]

Indeed, there might not even be a source! You can construct the AST programatically instead of generating it by parsing a source.

[jkrenzer]

We do include source positions when possible (e.g. for parse errors). But if the error comes from the writer, then the problem is that it just doesn't know the original source position -- the input of the writer is a Pandoc AST.

Mh, it seems this is not always the case as for an error in math I get the following or is this conversion only done by the writers?

Minimal example test.md:

$1 \€ 3$

Invocation command:

pandoc --log test.log.json test.md

Yields as test.log.json:

[
    {
        "type": "CouldNotConvertTeXMath",
        "verbosity": "WARNING",
        "contents": "1 \\€ 3",
        "message": "1 \\€ 3\n     ^\nunexpected control sequence \\€\nexpecting \"%\", \"\\\\label\", \"\\\\tag\", \"\\\\nonumber\" or whitespace"
    }
]

Indeed, there might not even be a source! You can construct the AST programatically instead of generating it by parsing a source.

Yes, I agree. But I think this could be reflected in the report. Don't get me wrong, it is not about grabbing the information from thin air for case were they do not apply.

Basically it is exactly catching parsing-errors in input files (maybe we could give the special source file "-" for stdin) and other common writing errors like not locatable media files. These are common when writing a big document and something that can be quite tiresome to debug for many users.

As for writers not knowing about the whereabouts of the original source code (which would need some major additions) it would already help if there would be at least an INFO message stating the currently processed input files to pandoc. Then one would have at least a list of suspects in the context of the log messages, which one could then present or search for offending contents on side of an IDE plugin.

This would be much easier as one just would have to read the json log to get all information from pandoc's view and not to somehow parse the pandoc command line and hope there is not some filter introducing extra files.

On a sidenote: Do you happen to know if a pandoc rendering process started from a lua filter does append it's messages to the log-file of the parent? If so, it would be even more worthwile to have an informative message each time source or media files are being processed by pandoc. This way the logs could be easily analyzed to get hold of all dependencies pulled into a document as long as the filters use pandoc's functionalityfor doing so. I think this as far as we can get on catching file dependencies introduced by filters automatically.

[jgm]

That error comes from the writer. The math is stored in TeX format in the AST, and the writer tries to convert it to the desired format (using the texmath library). At this point we no longer have source location information.

it would already help if there would be at least an INFO message stating the currently processed input files to pandoc

Even this is not possible by the time we get to the writer. The input may come from several different files, but at this point we just have a single unified AST.

if a pandoc rendering process started from a lua filter does append it's messages to the log-file of the parent

Hm, I'm not entirely sure actually. @tarleb ?

[tarleb]

Messages from pandoc.write etc are added to the main log. Try with

local doc = pandoc.Pandoc(pandoc.Math('InlineMath', [[\foo]]))
print('Before:', PANDOC_STATE.log)
pandoc.write(doc, 'html')
print('After:', PANDOC_STATE.log)

Use pandoc.log.silence(pandoc.write, doc, 'html') to prevent that; the log messages will be the first return value of that call.

[jkrenzer]

Messages from pandoc.write etc are added to the main log. Try with

local doc = pandoc.Pandoc(pandoc.Math('InlineMath', [[\foo]]))
print('Before:', PANDOC_STATE.log)
pandoc.write(doc, 'html')
print('After:', PANDOC_STATE.log)

Use pandoc.log.silence(pandoc.write, doc, 'html') to prevent that; the log messages will be the first return value of that call.

@tarleb Thanks for the insight!

Even this is not possible by the time we get to the writer. The input may come from several different files, but at this point we just have a single unified AST.

@jgm Ok, sorry I think I did not make myself clear in this regard. What I actually mean with the informative log entry on processing files is, that we just write a message on invocation of a process which basically contains PANDOC_STATE.input_files for this subprocess. So on the CLI this would be the input files given by the user, on a call from a filter (if possible, I did not check) the files given to the pandoc invocation.

This way we could educated-guess the input files for the following log messages. Assuming, that files are processed in order, it would also be possbile to search files in the same order for offending expressions and probably get the right locations. This might not work out in all edge cases as our asumptions may not always be right, but I'd expect this will be good enough to cover many cases in daily work.

For everything more accurate I guess we would need correlation information attached to the AST in some kind. This might be a thing for the future to also enable using pandoc to render e.g. a side-by-side view of two formats and correlate locations. But this is a totally different (and quite big) beast and not what I itended with this suggestion here.

[jgm]

What I actually mean with the informative log entry on processing files is, that we just write a message on invocation of a process which basically contains PANDOC_STATE.input_files for this subprocess. So on the CLI this would be the input files given by the user, on a call from a filter (if possible, I did not check) the files given to the pandoc invocation.

Perhaps you could suggest this in an issue. I'd have to think about it; it adds a bit of clutter and it's not really clear to me why it's needed, since you'd have to know the input files to issue the pandoc command in the first place, and this information could easily be recovered in a script.