Enhance logs from Asciidoctor

[ggrossetie]

Here's an example while processing hundreds of documents:

juin 18, 2020 8:25:15 AM  
AVERTISSEMENT: <stdin>: line 38: list item index: expected 1, got 2
juin 18, 2020 8:25:15 AM  
AVERTISSEMENT: <stdin>: line 68: list item index: expected 1, got 3
juin 18, 2020 8:25:18 AM  
INFOS: possible invalid reference: index-configuration-limitations-element-size-calculations
juin 18, 2020 8:25:18 AM  
AVERTISSEMENT: <stdin>: line 63: list item index: expected 1, got 3
juin 18, 2020 8:25:18 AM  
AVERTISSEMENT: <stdin>: line 70: list item index: expected 1, got 4
juin 18, 2020 8:25:19 AM  
AVERTISSEMENT: <stdin>: line 49: list item index: expected 1, got 3
juin 18, 2020 8:25:19 AM  
AVERTISSEMENT: <stdin>: line 67: list item index: expected 1, got 4
juin 18, 2020 8:25:19 AM  
AVERTISSEMENT: <stdin>: line 81: list item index: expected 1, got 5
juin 18, 2020 8:25:19 AM  
AVERTISSEMENT: <stdin>: line 84: list item index: expected 2, got 6
juin 18, 2020 8:25:19 AM  
AVERTISSEMENT: <stdin>: line 98: list item index: expected 1, got 7

As mentioned by Dan, Asciidoctor only processes a single file, the assumption is that it's the file you are processing. But when processing a collection of files, I think we can enhance the warning message:

https://twitter.com/mojavelinux/status/1261400540249915393

Also I'm not sure if the full date is necessary in this context and maybe we could print it on the same line?

Here's a proposal:

> articles/an-approach-to-parsing-the-query-log.adoc
08:25:15 - WARN - line 38: list item index: expected 1, got 2 
08:25:17 - WARN - line 68: list item index: expected 1, got 3

> articles/tls-ssl-configuration-for-specific-ciphers.adoc
08:25:18 - INFO - possible invalid reference: index-configuration-limitations-element-size-calculations

> articles/a-method-to-replicate-a-causal-cluster-to-new-hardware-with-minimum-downtime.adoc
08:25:18 - line 63: list item index: expected 1, got 3
08:25:18 - line 70: list item index: expected 1, got 4

> articles/how-to-install-neo4j-in-a-disconnected-environment.adoc
08:25:19 - WARN - line 49: list item index: expected 1, got 3
08:25:19 - WARN - line 67: list item index: expected 1, got 4
08:25:19 - WARN - line 81: list item index: expected 1, got 5
08:25:19 - WARN - line 84: list item index: expected 2, got 6
08:25:19 - WARN - line 98: list item index: expected 1, got 7

[abelsromero]

If it helps giving ideas...we had the same problem in the maven plugin and added this option: https://github.com/asciidoctor/asciidoctor-maven-plugin#user-content-loghandler-configuration. Just register a LogHandler to capture messages: https://github.com/asciidoctor/asciidoctor-maven-plugin/blob/master/src/main/java/org/asciidoctor/maven/log/MemoryLogHandler.java and then process them according to the configuration.

2 things to add:

• The next logical step once you see the errors is providing a way to fail the build.
• Missing attributes will still not show unless the attribute is set https://asciidoctor.org/docs/user-manual/#missing-attribute.

[ggrossetie]

Actually if I do not use a Preprocessor then I get the file names instead of <stdin>:

juin 22, 2020 11:39:23 AM /home/guillaume/workspace/neo4j/knowledge-base-public/build/.asciidoctorGems/gems/asciidoctor-2.0.10/lib/asciidoctor/parser.rb parse_list
AVERTISSEMENT: an-approach-to-parsing-the-query-log.adoc: line 105: list item index: expected 1, got 2
juin 22, 2020 11:39:24 AM  
AVERTISSEMENT: tls-ssl-configuration-for-specific-ciphers.adoc: line 38: list item index: expected 1, got 2
juin 22, 2020 11:39:24 AM  
AVERTISSEMENT: tls-ssl-configuration-for-specific-ciphers.adoc: line 68: list item index: expected 1, got 3
juin 22, 2020 11:39:25 AM  
INFOS: possible invalid reference: index-configuration-limitations-element-size-calculations
juin 22, 2020 11:39:25 AM  
AVERTISSEMENT: configure-neo4j-operate-on-privileged-ports.adoc: line 63: list item index: expected 1, got 3
juin 22, 2020 11:39:25 AM  
AVERTISSEMENT: configure-neo4j-operate-on-privileged-ports.adoc: line 70: list item index: expected 1, got 4
juin 22, 2020 11:39:26 AM  
AVERTISSEMENT: a-method-to-replicate-a-causal-cluster-to-new-hardware-with-minimum-downtime.adoc: line 49: list item index: expected 1, got 3
juin 22, 2020 11:39:26 AM  
AVERTISSEMENT: a-method-to-replicate-a-causal-cluster-to-new-hardware-with-minimum-downtime.adoc: line 67: list item index: expected 1, got 4
juin 22, 2020 11:39:26 AM  
AVERTISSEMENT: a-method-to-replicate-a-causal-cluster-to-new-hardware-with-minimum-downtime.adoc: line 81: list item index: expected 1, got 5
juin 22, 2020 11:39:26 AM  
AVERTISSEMENT: a-method-to-replicate-a-causal-cluster-to-new-hardware-with-minimum-downtime.adoc: line 84: list item index: expected 2, got 6
juin 22, 2020 11:39:26 AM  
AVERTISSEMENT: a-method-to-replicate-a-causal-cluster-to-new-hardware-with-minimum-downtime.adoc: line 98: list item index: expected 1, got 7

It still a bit hard to parse/read but that's better!

For reference, I was doing:

class FooterPreprocessor < Asciidoctor::Extensions::Preprocessor
  use_dsl

  FOOTER_LINES = File.readlines(File.join(File.dirname(__FILE__), 'footer_text.adoc')).map(&:chomp)

  def process(document, reader)
    lines = reader.lines
    lines.push(*FOOTER_LINES)
    # do not forget to retrieve the cursor from the document and pass it to the constructor,
    # otherwise an "<stdin>" cursor will be used!
    Asciidoctor::Reader.new lines, document.reader.cursor
  end
end

Also I don't really get the first line: juin 22, 2020 11:39:23 AM /home/guillaume/workspace/neo4j/knowledge-base-public/build/.asciidoctorGems/gems/asciidoctor-2.0.10/lib/asciidoctor/parser.rb parse_list :thinking:

I will investigate...

If it helps giving ideas...we had the same problem in the maven plugin and added this option: asciidoctor/asciidoctor-maven-plugin#user-content-loghandler-configuration. Just register a LogHandler to capture messages: asciidoctor/asciidoctor-maven-plugin:src/main/java/org/asciidoctor/maven/log/MemoryLogHandler.java@master and then process them according to the configuration.

Thanks @abelsromero for your input. I believe that we are already doing just that but we do not transform/enhance the logs.

2 things to add: The next logical step once you see the errors is providing a way to fail the build.

Yes, we've added a failure level option to configure (similar to what the CLI provides).

Missing attributes will still not show unless the attribute is set asciidoctor.org/docs/user-manual/#missing-attribute.

:+1:

[ysb33r]

@Mogztter The logic for dealing with log messages is in ExecutorBase.getLogHandler (jvm/src/main/groovy/org/asciidoctor/gradle/remote).

[ggrossetie]

@ysb33r Got it! I will try to put together a pull request :+1:

How do we feel about i18n in logs? Personally I hate it because it makes it harder to create tooling when you don't know for sure if the log level will be warn, avertissement, atención or cuidado :laughing:

[ysb33r]

I assume for build tooling that the output is in English as it is not for end-consumers. Maybe a strange view as I've been involved in localisation for years. Anyhow, asciidoctorj deals with the log level as an enum, so you don't have to worry about parsing atención.

If people iare concerned about the output language, we can always provide a feature for setting the locale in ExecutorBase

[ggrossetie]

I assume for build tooling that the output is in English as it is not for end-consumers. Maybe a strange view as I've been involved in localisation for years. Anyhow, asciidoctorj deals with the log level as an enum, so you don't have to worry about parsing atención. If people iare concerned about the output language, we can always provide a feature for setting the locale in ExecutorBase

:+1:

When using inProcess ProcessMode.IN_PROCESS or inProcess ProcessMode.OUT_OF_PROCESS the output is cleaner:

an-approach-to-parsing-the-query-log.adoc: line 105: list item index: expected 1, got 2
tls-ssl-configuration-for-specific-ciphers.adoc: line 38: list item index: expected 1, got 2
tls-ssl-configuration-for-specific-ciphers.adoc: line 68: list item index: expected 1, got 3
configure-neo4j-operate-on-privileged-ports.adoc: line 63: list item index: expected 1, got 3
configure-neo4j-operate-on-privileged-ports.adoc: line 70: list item index: expected 1, got 4
a-method-to-replicate-a-causal-cluster-to-new-hardware-with-minimum-downtime.adoc: line 49: list item index: expected 1, got 3
a-method-to-replicate-a-causal-cluster-to-new-hardware-with-minimum-downtime.adoc: line 67: list item index: expected 1, got 4
a-method-to-replicate-a-causal-cluster-to-new-hardware-with-minimum-downtime.adoc: line 81: list item index: expected 1, got 5
a-method-to-replicate-a-causal-cluster-to-new-hardware-with-minimum-downtime.adoc: line 84: list item index: expected 2, got 6
a-method-to-replicate-a-causal-cluster-to-new-hardware-with-minimum-downtime.adoc: line 98: list item index: expected 1, got 7

I believe that's because we are using the built-in Gradle logger (based on Lo4j?). But when using the default mode inProcess ProcessMode.JAVA_EXEC we are using println:

https://github.com/asciidoctor/asciidoctor-gradle-plugin/blob/48aa5e493f99ece5e49b567907b2d44e90bf93a2/jvm/src/main/groovy/org/asciidoctor/gradle/remote/AsciidoctorJavaExec.groovy#L119-L121

The documentation says that by default the Asciidoctor conversions are in-process:

inProcess - Specifies whether Asciidoctor conversions should be run in-process or out-of-process. Default: true (in-process).

But I guess this part is outdated? As far as I know we are now using JAVA_EXEC by default right?

https://github.com/asciidoctor/asciidoctor-gradle-plugin/blob/48aa5e493f99ece5e49b567907b2d44e90bf93a2/jvm/src/main/groovy/org/asciidoctor/gradle/jvm/AbstractAsciidoctorTask.groovy#L81

[ysb33r]

I should fix that, because for Gradle 6.x+ I think we can safely run in process as classpath leakage has been resolved.

[ggrossetie]

I'm not sure anymore if we should change something because the two main issues are solved now that I'm using the inProcess ProcessMode.IN_PROCESS and that I fixed my Preprocessor extension.

On second thought, grouping the logs per file name might not be such a good idea as having all the information on the same line has benefits.

In short, I'm fine with the output when using inProcess ProcessMode.IN_PROCESS or inProcess ProcessMode.OUT_OF_PROCESS :smile:

I should fix that, because for Gradle 6.x+ I think we can safely run in process as classpath leakage has been resolved.

:+1: