Create (or use an existing) message (logging) facility

[mojavelinux]

We'll need to be able to report warnings (and other messages) to the user. Rather than printing these to stdout, we should pass them through a message facility which can queue them, print them with styling, etc.

[abstractj]

Hi guys, I had this issue during the fixes to AeroGear site https://issues.jboss.org/browse/AEROGEAR-1021. Debugging gets harder when you have a bunch of files, initially I was trying to do something like:

puts "asciidoctor: WARNING: #{section.name} line #{reader.lineno + 1}: section title out of sequence: "

But that doesn't work correctly, I was in a rush to fix this issue so few shell script skills rescued me. But would be nice if we could add something like a logger for debugging.

[mojavelinux]

Even if we just collected the warnings so they could be collected from the API and logged by a consumer would be helpful, especially for extensions.

[mojavelinux]

The urgency for this change has increased now that we realize AsciidoctorJ has to use some serious hacks to reroute messages going to stdout and stderr to a logging layer. See asciidoctor/asciidoctorj@5c1b27d.

[mojavelinux]

I'm pretty strongly in favor of using a custom logging layer because we're going to need to give the integration a lot of flexibility and we want something lightweight and easy to implement. (Having said that, I will still consider the lightest possible logger solution).

[lordofthejars]

Ok then now I will leave asciidoctorj redirecting streams to logger, until this issue is fixed.

[jirutka]

What do you think about using core’s Logger? It seems that it’s quite flexible and extensible.

[mojavelinux]

That has come up before, perhaps in an IRC chat. I'm not opposed to using Logger. I've just been conditioned to dislike default Logger implementations based on the disaster in the Java ecosystem. If Logger provides the flexibility we need, then it's definitely worth prototyping a solution that uses it.

Keep in mind we didn't have a Logger originally because...we'll, the processor wasn't doing sophisticated things back then :) Now, we need a proper facility for handling messages...so we're on the market for the cleanest solution.

[mojavelinux]

One of the things I definitely want to do when we switch to the Logger interface is remove the need to hard code the application name with the message. The message formatter should allow us to insert this context into the message.

For an example of what I'm talking about, see https://github.com/asciidoctor/asciidoctor/blob/master/lib/asciidoctor/parser.rb#L275

[lordofthejars]

Yes logger interface may be an option, for example we Can create a ruby
class which fits the Logger interface so from Asciidoctorj point of view we
won t need to do anything, rather than passing an instance of Logger into
ruby code, like we do in converters or extensions
El dt., 6 de gen., 2015 a les 7.50 Dan Allen [email protected] va
escriure:

One of the things I definitely want to do when we switch to the Logger
interface is remove the need to hard code the application name with the
message. The message formatter should allow us to insert this context into
the message.

For an example of what I'm talking about, see
https://github.com/asciidoctor/asciidoctor/blob/master/lib/asciidoctor/parser.rb#L275

—
Reply to this email directly or view it on GitHub
#44 (comment)
.

[jirutka]

That has come up before, perhaps in an IRC chat.

Is there any other IRC channel than #asciidoctor on FreeNode? I’m here almost all the time, but I’ve never seen there any core dev. :(

I've just been conditioned to dislike default Logger implementations based on the disaster in the Java ecosystem.

JUL is indeed disaster, but Ruby is not Java and not every default logging facility is bad as in Java! It’s absolutely incomparable.

Keep in mind we didn't have a Logger originally because...we'll, the processor wasn't doing sophisticated things back then :)

I understand that.

Well, I’ll look at it and send some suggestion how it can be possibly done.

[mojavelinux]

Is there any other IRC channel than #asciidoctor on FreeNode? I’m here almost all the time, but I’ve never seen there any core dev. :(

I should have said "a long time ago on IRC" because I haven't been there for awhile. While IRC would be ideal for real-time communication, I find that the issue tracker + mailinglist is about all I can handle. Otherwise, my productivity just plummets.

[ecki]

+1 for AsciidoctorJ (Java Extension), maybe the logging is not that important (i.e. Can use System.out), but a position (context) object is needed. And unless you always want to sourcemap on it should also work without (at least with reduced precision)

[mojavelinux]

The position is really a separate issue. That comes down to how the parser works. The focus here is to put the log messages into a place that an integration can use. Putting messages directly to stdout makes them hard to control, hard to find, and hard to filter.

[mojavelinux]

I'm happy to say that I almost have a PR for this change ready.

I've decided to use the default Logger in Ruby, but hear me out as to why. It's very important that the Asciidoctor processor not have any mandatory dependencies. This makes integrations and transpiling simpler. But, it doesn't mean you can't integrate the logger of your choice. It's all in the design.

All we really need to accomplish here is to differentiate between a message coming from the processor and a message coming from anywhere else in the Ruby runtime. That's the main problem with using the warn function for logging. It's all jumbled up. If we route messages through a logger that was created in Asciidoctor, then it's clear that those messages are coming from Asciidoctor. And you don't have to parse the message to get the level (and perhaps other context).

So the main change we have to make here is to invoke logger.warn or logger.error instead of warn. And that's our hook.

The question is, how is that hook handled? Well, by default, we'll stick a default logger in there to respond to the call and route the message somewhere (probably stderr). But if you want to intercept these messages with your own logger, you just replace the logger singleton. As long as the object you provide responds to the methods on the Logger interface (namely debug, info, warn, error, fatal), then Asciidoctor is none the wiser about how you handle the messages. That's why I think the default Logger is sufficient. Or perhaps I should say we can abstract away that choice.

Here's the logging infrastructure I'm proposing:

module Asciidoctor
class Logger < ::Logger
  def initialize *args
    super
    self.progname = 'asciidoctor'
    self.formatter = BasicFormatter.new
    self.level = WARN
  end

  class BasicFormatter < ::Logger::Formatter
    SEVERITY_MAPPING = { 'WARN' => 'WARNING', 'FATAL' => 'FAILED' }

    def call severity, _, progname, msg
      %(#{progname}: #{SEVERITY_MAPPING[severity] || severity}: #{msg}\n)
    end
  end
end

module LoggerManager
  @logger_class = Logger
  class << self
    attr_accessor :logger_class

    def logger
      @logger ||= (@logger_class.new $stderr)
    end

    def logger= logger
      @logger = logger
    end
  end
end

module Logging
  def self.included into
    class << into
      private
      def logger
        LoggerManager.logger
      end
    end
  end

  private
  def logger
    LoggerManager.logger
  end
end
end

Now to make the logger available to any class or module, I just need to include the Logging module.

module Asciidoctor
module Parser
  include Logging
  ...
end
end

There are two ways to set your own logger. Before the singleton is created (you've required asciidoctor but not used it yet), you can set the logger class.

LoggerManager.logger_class = MyLoggerClass

After the singleton has been created, or if you just want to set the instance directly, you assign it to the logger property:

LoggerManager.logger = MyLoggerClass.new

I'm also working on adding a :logger option to the load/convert API methods. This will overwrite the singleton, but we'll assume you understand that is what is going to happen. (Because of how Asciidoctor is currently implemented, I can't pass a per-instance logger through the processor).

[mojavelinux]

Related to this change is #2657, which proposes to store messages that pertain to the document on the document object itself. These messages could still get routed to the logger, but they'll be more accessible (no need to parse the log messages). They can be used by a client to determine if the document has any errors or warnings.

[mojavelinux]

I don't think messages produced directly by the CLI (outside of the call to the processor) should go to the log (or, at least, not all of them, such as the usage statement). This would be unconventional for a CLI. Instead, these messages will still get routed directly to stdout and stderr. Now that we have a logging infrastructure in place, we can handle any exceptions to this decision on a case-by-case basis.

[mojavelinux]

After I got the logging infrastructure set up, I took a closer look at the messages themselves. Many messages include information about the location in the AsciiDoc document where the problem occurs. This location is represented by a path and line number in the message (e.g., document.adoc: line 5: ...).

While we could just leave this information embedded in the message string, it's as valuable as the reason itself. So I think we should make it more accessible. Asciidoctor is also dropping some important information. When Asciidoctor reports a message that includes a path and line number, it actually knows the absolute file and directory as well. We should make this information available too.

When we have more information than just the message itself, instead of logging a string, I propose that we log an object. Fortunately, the built-in logger in Ruby allows this.

Since we already use the term "source_location" in the API, it's logical and consistent to also use this to pass information about the source of the message to the logger too. Here's what I propose:

logger.error :text => 'parts must have at least one section', :source_location => reader.cursor

This is great since we're now able to pass information about the source of the message to the logger. And the default logger can format the message in the traditional way:

asciidoctor: ERROR: document.adoc: line 5: parts must have a least one section

However, this extra information is not so nice for custom loggers (unless they provide a custom formatter too). For example, let's assume we want to use the built-in logger in Ruby:

Asciidoctor.convert_file 'document.adoc', logger: (Logger.new $stderr)

Now the message looks like this:

E, [<datetime> #27994]  ERROR -- : {:text=>"parts must have a least one section", :source_location=>#<Asciidoctor::Reader::Cursor:0x0000000001b1ae80 @file="/docs/document.adoc", @dir="/docs", @path="document.adoc", @lineno=5>}

Yikes!

But there's an easy way to fix this. There's a contract in Ruby's logger that it will coerce the message object to a string by calling inspect on it. So all we need to do is override the inspect method to have it automatically format in the default way.

To make this a bit easier, I propose introducing a helper method named enrich_message that can be used when logging the message. This method accepts the text as the first argument, then a Hash which provides additional context, such as :source_location. It then weaves in a module that overrides the inspect method.

logger.error enrich_message 'parts must have at least one section', :source_location => reader.cursor

Now the message is automatically formatted by the built-in logger.

W, [<datetime> #27994]  ERROR -- : document.adoc: line 5: parts must have a least one section

Of course, you can still format the message however you want by passing a custom formatter to your logger. All we're talking about here is just doing something with the message nice by default (and for the test suite).

[mojavelinux]

And it's in!

[jmini]

This is nice, thank you for this feature.

Can the logger infrastructure be accessed from an AsciidoctorJ extension?
Have you an example/pointer somewhere?

[ggrossetie]

@jmini https://github.com/asciidoctor/asciidoctorj#logs-handling-api

[robertpanzer]

Can the logger infrastructure be accessed from an AsciidoctorJ extension?

That's actually a good point.
While it's possible to receive the log entries that Asciidoctor logs, it's not possible yet for an extension to log using the same Logger that Asciidoctor is using.
I agree that it would make sense to expose this to extensions as well.
@jmini: Can you please open an issue for AsciidoctorJ?

[jmini]

@Mogztter, @robertpanzer thank you both for your answer. I have opened asciidoctor/asciidoctorj#737