Redirect Asciidoctor logging to Java Util Logging #643

robertpanzer · 2018-05-05T14:29:29Z

This is the version of #641 for the master branch.
In addition to only the changes from that PR I had to also pull in some more classes that didn't exist yet on master, i.e. Cursor/CursorImpl and RubyObjectWrapper.

I also changed the test to programmatically configure and register a Handler, the Maven plugin should be able to do just that as well.

Additionally I bumped the version of Java to 7 "officially" so that I don't have to downgrade some of the imported code. We're already relying on Java 7 now anyway.

mojavelinux · 2018-05-06T01:16:53Z

👍

I think this is an essential addition for 1.5.7, primarily for the build tools that use it.

robertpanzer · 2018-05-06T14:20:10Z

Changed the PR to first send notifications to observers of type org.asciidoctor.log.LogHandler.
To log these entries there is a forwarder to JUL that is automatically registered.

@abelsromero Does this better meet your expectations?
https://github.com/asciidoctor/asciidoctorj/pull/643/files#diff-02a16085d35ef59ce9c6978d303db990R83

abelsromero · 2018-05-06T18:25:02Z

This works wonders! This really makes it really easy to handle the log from a build tool. And I can see the gradle plugin using registerLogHandler with a closure also.
But I found a bug in the Cursor class. getFile fails when he error is reported from an uri include. There's a class cast exception, I suppose cause the object is not a RubyString. I could fix it doing this this.getProperty("file").toString() instead of getString("file").

Btw, I added a couple of silly comments to the code.

abelsromero · 2018-05-06T18:25:52Z

asciidoctorj-core/src/main/java/org/asciidoctor/log/internal/JavaLogger.java

@@ -84,68 +79,46 @@ public IRubyObject add(final ThreadContext threadContext, final IRubyObject[] ar
      progname = args[2].asJavaString();


this is marked as unused in my IDE

abelsromero · 2018-05-06T18:26:37Z

asciidoctorj-core/src/main/java/org/asciidoctor/log/LogHandler.java

@@ -0,0 +1,8 @@
+package org.asciidoctor.log;
+
+import org.asciidoctor.ast.Cursor;


unused import

abelsromero · 2018-05-06T18:28:24Z

asciidoctorj-core/src/main/java/org/asciidoctor/log/internal/JULLogHandler.java

+                mapSeverity(logRecord.getSeverity()),
+                logRecord.getCursor() != null ? logRecord.getCursor().toString() + ": " + logRecord.getMessage() : logRecord.getMessage());
+
+        julLogRecord.setSourceClassName(logRecord.getSourceFileName());


cursor is not captured here.
I fixed it locally adding julLogRecord.setParameters(new Object[] { logRecord.getCursor() });

I added this below.
(Just mentioning the obvious here so that I remember that I already handled this comment)

robertpanzer · 2018-05-06T18:34:35Z

Thanks for the feedback! This is exactly what I needed! :)
I was thinking about no longer storing the Cursor in the JUL LogRecord, but maybe it makes sense to still do that.
I’ll implement your comments tomorrow.

(And thanks a lot again!)

abelsromero · 2018-05-06T19:06:00Z

I was thinking about no longer storing the Cursor in the JUL LogRecord,

It's still not 100% user friendly. But it's nice to have it if it can be done easily. We just need to document it clearly.

robertpanzer · 2018-05-09T14:18:17Z

@abelsromero Is this now in a usable state for you?
If yes I would merge it and then try to do a 1.5.7 release of AsciidoctorJ.

abelsromero · 2018-05-09T21:18:32Z

There are some other conversations about possible features. Its fine for me, but I'd wait a bit more asciidoctor/asciidoctor-maven-plugin#261 (comment) Wdyt?

…

On Wed, May 9, 2018, 4:18 PM Robert Panzer ***@***.***> wrote: @abelsromero <https://github.com/abelsromero> Is this now in a usable state for you? If yes I would merge it and then try to do a 1.5.7 release of AsciidoctorJ. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#643 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AFg2oTyrC2WziYbtAOO5SYW0YMM1GFknks5twvqxgaJpZM4TzqGL> .

robertpanzer · 2018-05-10T13:20:54Z

Sure, np.
If you have some more requirements just let me know.
From the current state of the discussion in this issue I couldn't see any direct additional requirements.

mojavelinux · 2018-05-11T09:44:02Z

@robertpanzer @abelsromero Truly great work on this you two! I'm impressed!

mojavelinux · 2018-05-11T09:47:14Z

There's a class cast exception, I suppose cause the object is not a RubyString. I could fix it doing this this.getProperty("file").toString() instead of getString("file").

Sorry about that. Sometimes file or dir is a URI. This is internal information that is leaking out. When I create the log records, I should probably .to_s them. For now, you can just do so on the Java side.

abelsromero · 2018-05-11T10:47:51Z

If you have some more requirements just let me know.

I only see interesting the option to register via SPI.

robertpanzer · 2018-05-11T10:55:58Z

You mean to register an Observer automatically if it is declared in a file META-INF/services/org.asciidoctor.log.LogHandler?
Sounds good.

robertpanzer · 2018-05-12T12:53:41Z

@mojavelinux Regarding asciidoctor/asciidoctor-gradle-plugin#233 (comment) Do you think it would make sense to always run with the verbose option when not running from the CLI? This way you would only configure the amount of logging in your logging framework.

The CLI overrides $VERBOSE anyway to true or nil.

abelsromero · 2018-05-12T14:30:28Z

Apologies for the silly question, but I don't get the purpose of verbose.

From the command info Verbosely print processing information and configuration file checks to stderr., I assume messages are sent to stdout by default. But, they are always sent to stderr, with and without --verbose.
That's running directly the gem in Windows.

robertpanzer · 2018-05-31T15:35:22Z

I think the default log device is stderr:
https://github.com/asciidoctor/asciidoctor/blob/d15bc65a942a8d3b186eab6e038bfc000c4d48f5/lib/asciidoctor/logging.rb#L85

In my opinion it would make sense to always log these warnings independently of a verbose setting, at least when running embedded in the Maven or Gradle plugin.
Wdyt?

abelsromero · 2018-05-31T15:51:17Z

I am reading back my comment and I see it was horrible. What I meant was that I don't see any difference when using --verbose and not using it.

robertpanzer · 2018-05-31T16:37:14Z

Thanks for the clarification :)

So would it make sense then to always enable this verbose flag to see those warnings?

abelsromero · 2018-06-01T06:07:45Z

So would it make sense then to always enable this verbose flag to see those warnings?

I'd vote for yes.

On other topics, have you consider the option to register using SPI? (asking this I feel like when my manager comes in late Friday with a new requirement to implement)

robertpanzer · 2018-06-01T07:17:46Z

:) No worries!

I considered adding an SPI and I already developed it (if I understood you correctly that it should be possible to register an Observer via the java.util.ServiceLoader mechanism).
I just forgot to push my changes :-(
But now they should be here as well.

robertpanzer · 2018-06-13T08:15:55Z

To go ahead I am planning to always set the $VERBOSE global variable.
In my opinion it really makes sense to always get information about invalid references.

When testing it I just stumbled over that the warning is logged without a context.
@mojavelinux Would it make sense to add the context and give the user information about where the invalid reference is located in the sources?

robertpanzer · 2018-06-16T15:26:12Z

Updated the PR to always set $VERBOSE=true and therefore always log invalid refs.
Imo users will always be interested in seeing this.

abelsromero · 2018-06-16T18:45:19Z

Updated the PR to always set $VERBOSE=true and therefore always log invalid refs.
Imo users will always be interested in seeing this.

I second that!

robertpanzer · 2018-06-19T08:44:07Z

I'll merge for now.
Additional comments can be implemented in follow-up PRs.

mojavelinux · 2018-10-15T03:29:11Z

To go ahead I am planning to always set the $VERBOSE global variable.
In my opinion it really makes sense to always get information about invalid references.

We've decided to go the other way on this. $VERBOSE is not something that should be set by default. The fact that it is linked to the invalid references warning is only because those warnings are not always accurate. In that regard, we should think of it more like "debug mode". But $VERBOSE does reveal programming errors, so it can be useful for other reasons. But certainly no something we want to enable by default.

Redirect Asciidoctor logging to Java Util Logging

4684464

robertpanzer mentioned this pull request May 5, 2018

Redirect Asciidoctor logging to Java Util Logging #641

Closed

Send asciidoctor log entries as notifications and forward these to JUL

b6571c8

abelsromero reviewed May 6, 2018

View reviewed changes

robertpanzer added 2 commits May 7, 2018 08:02

Implement review comments

74de172

Make toString conversion explicit in CursorImpl

cc7ef02

Allow to provide LogHandlers as Services via java.util.ServiceLoader.

50dec40

Fix test issues due to different execution order in Gradle

8227db1

robertpanzer mentioned this pull request Jun 16, 2018

Add plugin mechanism for Loggers #657

Merged

Always set $VERBOSE to true and enable logging of invalid refs.

a04f2cf

robertpanzer force-pushed the loggers-master branch from 21d0ff5 to a04f2cf Compare June 18, 2018 07:28

robertpanzer merged commit f8c08a7 into asciidoctor:master Jun 19, 2018

abelsromero mentioned this pull request Jun 20, 2018

Fail on warnings asciidoctor/asciidoctor-maven-plugin#261

Closed

mojavelinux mentioned this pull request Jun 29, 2018

Allow verbose mode to be programmatically changed asciidoctor/asciidoctor-gradle-plugin#233

Closed

ysb33r mentioned this pull request Jun 30, 2018

Tracking 2.0.0 Development asciidoctor/asciidoctor-gradle-plugin#240

Closed

28 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Redirect Asciidoctor logging to Java Util Logging #643

Redirect Asciidoctor logging to Java Util Logging #643

robertpanzer commented May 5, 2018

mojavelinux commented May 6, 2018

robertpanzer commented May 6, 2018

abelsromero commented May 6, 2018

abelsromero May 6, 2018

abelsromero May 6, 2018

abelsromero May 6, 2018

robertpanzer May 30, 2018

robertpanzer commented May 6, 2018

abelsromero commented May 6, 2018

robertpanzer commented May 9, 2018

abelsromero commented May 9, 2018 via email

robertpanzer commented May 10, 2018

mojavelinux commented May 11, 2018

mojavelinux commented May 11, 2018

abelsromero commented May 11, 2018

robertpanzer commented May 11, 2018

robertpanzer commented May 12, 2018

abelsromero commented May 12, 2018

robertpanzer commented May 31, 2018

abelsromero commented May 31, 2018

robertpanzer commented May 31, 2018

abelsromero commented Jun 1, 2018

robertpanzer commented Jun 1, 2018

robertpanzer commented Jun 13, 2018

robertpanzer commented Jun 16, 2018

abelsromero commented Jun 16, 2018

robertpanzer commented Jun 19, 2018

mojavelinux commented Oct 15, 2018

		@@ -84,68 +79,46 @@ public IRubyObject add(final ThreadContext threadContext, final IRubyObject[] ar
		progname = args[2].asJavaString();

		@@ -0,0 +1,8 @@
		package org.asciidoctor.log;

		import org.asciidoctor.ast.Cursor;

Redirect Asciidoctor logging to Java Util Logging #643

Redirect Asciidoctor logging to Java Util Logging #643

Conversation

robertpanzer commented May 5, 2018

mojavelinux commented May 6, 2018

robertpanzer commented May 6, 2018

abelsromero commented May 6, 2018

abelsromero May 6, 2018

Choose a reason for hiding this comment

abelsromero May 6, 2018

Choose a reason for hiding this comment

abelsromero May 6, 2018

Choose a reason for hiding this comment

robertpanzer May 30, 2018

Choose a reason for hiding this comment

robertpanzer commented May 6, 2018

abelsromero commented May 6, 2018

robertpanzer commented May 9, 2018

abelsromero commented May 9, 2018 via email

robertpanzer commented May 10, 2018

mojavelinux commented May 11, 2018

mojavelinux commented May 11, 2018

abelsromero commented May 11, 2018

robertpanzer commented May 11, 2018

robertpanzer commented May 12, 2018

abelsromero commented May 12, 2018

robertpanzer commented May 31, 2018

abelsromero commented May 31, 2018

robertpanzer commented May 31, 2018

abelsromero commented Jun 1, 2018

robertpanzer commented Jun 1, 2018

robertpanzer commented Jun 13, 2018

robertpanzer commented Jun 16, 2018

abelsromero commented Jun 16, 2018

robertpanzer commented Jun 19, 2018

mojavelinux commented Oct 15, 2018