'pdf_source_code_should_be_highlighted' fail (Windows 7)

[abelsromero]

I have detected some weird behavior with the tests in 'asciidoctorj-pdf' sub-module. I suspect it may have something to do with my environment.

When running ./gradlew.sh clean test in the parent project from shell (babun) or the equivalent gradlew.nat com CMD, the test 'pdf_source_code_should_be_highlighted' with the error:

org.asciidoctor.internal.AsciidoctorCoreException: org.jruby.exceptions.RaiseException: (RuntimeError) asciidoctor: FAILED: required gem 'rouge' is not installed. Processing aborted.
    at org.asciidoctor.internal.JRubyAsciidoctor.renderFile(JRubyAsciidoctor.java:345)
    at org.asciidoctor.internal.JRubyAsciidoctor.renderFile(JRubyAsciidoctor.java:434)
    at org.asciidoctor.internal.JRubyAsciidoctor.convertFile(JRubyAsciidoctor.java:554)
    at org.asciidoctor.WhenBackendIsPdf.pdf_source_code_should_be_highlighted(WhenBackendIsPdf.jav

I checked and the 1.10.1 gem is installed.

When running the test from IntelliJ, I need to run jRubyPrepare first, which is more or less OK. But then both test in WhenBackendIsPdf fail with the message.

org.jruby.exceptions.RaiseException: (LoadError) load error: psych -- java.lang.NoSuchMethodError: org.jruby.gen.org$jruby$ext$psych$PsychParser$POPULATOR.populateMethod(Lorg/jruby/internal/runtime/methods/JavaMethod;ILjava/lang/String;ZLorg/jruby/internal/runtime/methods/CallConfiguration;ZLjava/lang/Class;Ljava/lang/String;Ljava/lang/Class;[Ljava/lang/Class;)V

    at org.jruby.RubyKernel.require(org/jruby/RubyKernel.java:956)
    at RUBY.require(uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rubygems/core_ext/kernel_require.rb:55)
    at RUBY.<main>(uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/yaml.rb:6)
    at org.jruby.RubyKernel.require(org/jruby/RubyKernel.java:956)

Now, the best part, placing the tests in 'itest' sub-module makes both test work in IntelliJ (after manually executin jrubyPrepare) but running from the shell reproduced the same error as the first case (shell execution). Also, I validated the PDF and it gets correctly generated.

Any idea?

[robertpanzer]

Yes, I also experienced this behaviour at home on Windows.

This also makes the appveyor tests fail on asciidoctorj 1.6.0. (See https://ci.appveyor.com/project/asciidoctor/asciidoctorj/build/480#L2068 )

I could imagine that Gradle (and maybe IntelliJ as well) somehow uses different class loaders for loading the tests. And locating gems in JRuby seems to heavily depend on the class loader.

Maybe we should move this test from the asciidoctorj-pdf module to the itest module.

Am 26.09.2016 um 17:41 schrieb Abel Salgado Romero notifications@github.com:

I have detected some weird behavior with the tests in 'asciidoctorj-pdf' sub-module. I suspect it may have something to do with my environment.

When running ./gradlew.sh clean test in the parent project from shell (babun) or the equivalent gradlew.nat com CMD, the test 'pdf_source_code_should_be_highlighted' with the error:

org.asciidoctor.internal.AsciidoctorCoreException: org.jruby.exceptions.RaiseException: (RuntimeError) asciidoctor: FAILED: required gem 'rouge' is not installed. Processing aborted. at org.asciidoctor.internal.JRubyAsciidoctor.renderFile(JRubyAsciidoctor.java:345) at org.asciidoctor.internal.JRubyAsciidoctor.renderFile(JRubyAsciidoctor.java:434) at org.asciidoctor.internal.JRubyAsciidoctor.convertFile(JRubyAsciidoctor.java:554) at org.asciidoctor.WhenBackendIsPdf.pdf_source_code_should_be_highlighted(WhenBackendIsPdf.jav I checked and the 1.10.1 gem is installed.

When running the test from IntelliJ, I need to run jRubyPrepare first, which is more or less OK. But then both test in WhenBackendIsPdf fail with the message.

org.jruby.exceptions.RaiseException: (LoadError) load error: psych -- java.lang.NoSuchMethodError: org.jruby.gen.org$jruby$ext$psych$PsychParser$POPULATOR.populateMethod(Lorg/jruby/internal/runtime/methods/JavaMethod;ILjava/lang/String;ZLorg/jruby/internal/runtime/methods/CallConfiguration;ZLjava/lang/Class;Ljava/lang/String;Ljava/lang/Class;[Ljava/lang/Class;)V

at org.jruby.RubyKernel.require(org/jruby/RubyKernel.java:956)
at RUBY.require(uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rubygems/core_ext/kernel_require.rb:55)
at RUBY.<main>(uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/yaml.rb:6)
at org.jruby.RubyKernel.require(org/jruby/RubyKernel.java:956)

Now, the best part, placing the tests in 'itest' sub-module makes both test work in IntelliJ (after manually executin jrubyPrepare) but running from the shell reproduced the same error as the first case (shell execution). Also, I validated the PDF and it gets correctly generated.

Any idea?

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/robertpanzer/asciidoctorj-pdf/issues/3, or mute the thread https://github.com/notifications/unsubscribe-auth/ABHBjv7i0qAsg9wR0xyLSAoewu1MjkFBks5qt-eogaJpZM4KGrYb.

[abelsromero]

I could imagine that Gradle (and maybe IntelliJ as well) somehow uses different class loaders for loading the tests.

Sure, but why rouge fails? For instance I tried to add the gem as "required" and it also failed, however, "requiring" prawn did not fails.

Maybe we should move this test from the asciidoctorj-pdf module to the itest module.

The project just packages the gems, so it makes sense to me that all tests should be in itest so that we test the artifact. If you agree I'll move them, also, I'd migrate it to spock for consistency.

[robertpanzer]

It probably makes sense to file an issue for JRuby, maybe they can find sth here. And with the smaller repo I am also more comfortable with that, instead of throwing the whole asciidoctorj repo at them and saying: please check why the build fails on Windows.

I also can't tell why it is rouge now, before JRuby 9.1.5.0 it was actually prawn that failed 😂

[abelsromero]

Just confirmed that it DOES work well from both shell and IntelliJ on MacOS.

[headius]

The LoadError indicates that IntelliJ is picking up the wrong psych jar version. It's a version mismatch. I can't tell you more because I'm not sure how IntelliJ sets up the environment for your test run.

The RuntimeError seems to be due to not having gem locations set up properly for the gradle test run. If the gems are installed in the usual location under a standard JRuby install, you'll want to set jruby.home properly. If they're somewhere else on the filesystem, the env vars GEM_HOME and GEM_ROOT will be useful. If they're packed into the jar, there's a few ways to get them to look either like a real gem (by locating them in a specific directory hierarchy in the jar) or as a vendored library (which you would not activate with gem "blahblah" but instead just require).

I think I will close the JRuby bug for now, since the inconsistency is likely due to IntelliJ subprocess/test logic, but I'm happy to help get this working smoothly in both places for y'all :-)

[abelsromero]

If they're packed into the jar, there's a few ways to get them to look either like a real gem (by locating them in a specific directory hierarchy in the jar) or as a vendored library (which you would not activate with gem "blahblah" but instead just require).

I think that's the case we are chasing here (anyone correct me if I am wrong). The aim is to provide a Java wrapper for those not using Ruby. So it would be expected that not GEM_* vars are set. Ideally we'd like to fully isolate the Jar from any ruby environment, is that possible? or in other words, how can we prioritise the gems in the jar? If not possible, I imagine that if someone is using Ruby we may still find some unexpected behaviour, but in that case if we understand the logic we can document it.

[headius]

If the gems are being explicitly activated using gem "whatever" then you'd need to package them in the jar with a jar-specific gem root/home. I don't remember how to do that but I believe @mkristian or @codefinger would know the answer off the top of their heads.

If they're not explicitly activated, then you could just vendor them into lib, or vendor into some other in-jar location and add that location to the load path at boot.

[mkristian]

@abelsromero packing gem inside a jar can be done like this to root of your jar (or classloader)

/specifications/my-123.gemspec
/gems/my-123/*

this jruby adds the root of the classloader to Gem::Specification.dirs, i.e. rubygems will find installed gems there. if you want to have your gems work in an OSGi environment it might (not always) be needed to add directory info inside your jar: /specifications/.jrubydir with the content of ls -1 specifications or use jruby -S generate_dir_info local/path/to/gems before packing local/path/to/gems

[robertpanzer]

Hi @mkristian,

we're using the jruby-gradle-plugin to "install" the required gems into a directory structure below build/main/resources/gems. I simply assume that it does the job right. These directory structures are packaged into jars.

The major difference between the scenario where it works and where it doesn't work is:

It works when everything is packaged in jars, i.e. asciidoctorj.jar and asciidoctorj-pdf.jar. This is tested in the itest submodule, where it uses asciidoctorj and asciidoctorj-pdf as a jar. asciidoctorj.jar contains the code that issues the require 'rouge'. rouge is packaged in the asciidoctorj-pdf.jar.

It does not work however when the same test is run as a unit test in asciidoctorj-pdf. Here the gems that make up everything that is needed for asciidoctorj-pdf, like prawn and rouge are still located as unpackaged content in the directory tree. asciidoctor itself is still packaged as a jar in asciidoctorj.jar and contains the asciidoctor gem and some other base gems. The strange thing though is that prawn is apparently available while rouge is not.

[mkristian]

sorry for the wrong track, yes jruby-gradle-plugin does pack the gems the right way.

is it possible to add a system property jruby.debug.loadService=true and see the output of it (might be a bit long)

this log will show where rubygems is looking for prawn.rb and where it finds rouge.rb

[abelsromero]

At risk of making a fool of myself but with great interest in understanding how jruby works and fix this, I am going to say that_the debug is not fully working for me, I fear I am missing something, The system property did not initially work (dunno why): I tried with jruby.debug.loadService and debug.loadService and also tried adding a log4j configuration, but nothing. Even when I get logs from other libraries no from jruby. I could however enable it with this instructions https://github.com/jruby/jruby/wiki/ConfiguringJRuby, but I only get traces in stdout during gradle jrubyPrepare task, not during the test execution. Here is an example:

:asciidoctorj-pdf:jrubyPrepare2016-09-27T11:52:17.210+02:00 [main] INFO LoadService : trying builtinLib: jruby.rb
2016-09-27T11:52:17.244+02:00 [main] INFO LoadService : found builtinLib: jruby.rb
2016-09-27T11:52:17.245+02:00 [main] INFO LoadService : trying builtinLib: java.rb
2016-09-27T11:52:17.246+02:00 [main] INFO LoadService : found builtinLib: java.rb
2016-09-27T11:52:17.558+02:00 [main] INFO LoadService : trying builtinLib: jruby/java.rb
2016-09-27T11:52:17.559+02:00 [main] INFO LoadService : trying fileResource: uri:classloader:/META-INF/jruby.home/lib/ruby/2.3/site_ruby/jruby/java.rb
2016-09-27T11:52:17.559+02:00 [main] INFO LoadService : trying fileResource: uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/jruby/java.rb
2016-09-27T11:52:17.560+02:00 [main] INFO LoadService : trying fileResource: ./jruby/java.rb
2016-09-27T11:52:17.560+02:00 [main] INFO LoadService : trying fileResource: uri:classloader:/jruby/java.rb
2016-09-27T11:52:17.561+02:00 [main] INFO LoadService : found fileResource: uri:classloader:/jruby/java.rb
2016-09-27T11:52:17.818+02:00 [main] INFO LoadService : trying builtinLib: jruby/java/java_utilities.rb
2016-09-27T11:52:17.818+02:00 [main] INFO LoadService : trying fileResource: uri:classloader:/META-INF/jruby.home/lib/ruby/2.3/site_ruby/jruby/java/java_utilities.rb
2016-09-27T11:52:17.819+02:00 [main] INFO LoadService : trying fileResource: uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/jruby/java/java_utilities.rb
2016-09-27T11:52:17.820+02:00 [main] INFO LoadService : trying fileResource: ./jruby/java/java_utilities.rb
2016-09-27T11:52:17.820+02:00 [main] INFO LoadService : trying fileResource: uri:classloader:/jruby/java/java_utilities.rb
2016-09-27T11:52:17.821+02:00 [main] INFO LoadService : found fileResource: uri:classloader:/jruby/java/java_utilities.rb
2016-09-27T11:52:17.833+02:00 [main] INFO LoadService : trying builtinLib: jruby/java/core_ext.rb

Seeing where it is looking for the gems is exactly what I wanted, for that I scanned the classpath and the gems are there, so I'd like to see exactly where jruby is doing.

[mkristian]

it is a matter of setting this property when running the tests. maybe use a .jrubyrc file works:

$ jruby --properties
# These properties can be used to alter runtime behavior for perf or compatibility.
# Specify them by passing -X<property>=<value>
#   or if passing directly to Java, -Djruby.<property>=<value>
#   or put <property>=<value> in .jrubyrc
#
# This dump is a valid .jrubyrc file of current settings. Uncomment and modify
# settings to customize.

i.e.

debug.loadService=true

or maybe it is an issue where the output goes.

[abelsromero]

use a .jrubyrc file

The file is what I used. I suspect there's something in Asciidoctor or AsciidoctorJ that is blocking or redirecting the output because I run this example https://github.com/jruby/jruby/blob/master/core/src/test/java/org/jruby/embed/IsolatedScriptingContainerTest.java#L38 and it works fine. I'll keep digging, right now I've seen that IntellJ adds runtime maven dependencies to the classpath, which makes that both jruby 1.7.x (runtime in AsciidoctorJ) and jruby 9.x (compile here) are loaded. Sadly adding an explicit exclude for the first did not fix the problems.

[robertpanzer]

@mkristian Here is the build output of the failing build on Windows.

testoutput_win10.txt

Very strange that it says it found files of the gem...

2016-10-01T20:01:19.925+02:00 [Test worker] INFO LoadService : trying fileResource: uri:classloader:/gems/rouge-1.10.1/lib/cgi/escape.jar
    2016-10-01T20:01:19.925+02:00 [Test worker] INFO LoadService : trying fileResource: uri:classloader:/META-INF/jruby.home/lib/ruby/2.3/site_ruby/cgi/escape.jar
    2016-10-01T20:01:19.925+02:00 [Test worker] INFO LoadService : trying fileResource: uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/cgi/escape.jar
    2016-10-01T20:01:19.925+02:00 [Test worker] INFO LoadService : trying fileResource: ./cgi/escape.jar
    2016-10-01T20:01:19.925+02:00 [Test worker] INFO LoadService : trying fileResource: uri:classloader:/cgi/escape.jar
    2016-10-01T20:01:19.925+02:00 [Test worker] INFO LoadService : trying jarExtension: cgi/escape
    2016-10-01T20:01:22.502+02:00 [Test worker] INFO LoadService : trying builtinLib: uri:classloader:/gems/rouge-1.10.1/lib/rouge/regex_lexer.rb
    2016-10-01T20:01:22.502+02:00 [Test worker] INFO LoadService : trying fileResource: uri:classloader:/gems/rouge-1.10.1/lib/rouge/regex_lexer.rb
    2016-10-01T20:01:22.502+02:00 [Test worker] INFO LoadService : found fileResource: uri:classloader:/gems/rouge-1.10.1/lib/rouge/regex_lexer.rb
    2016-10-01T20:01:22.502+02:00 [Test worker] INFO LoadService : trying builtinLib: uri:classloader:/gems/rouge-1.10.1/lib/rouge/template_lexer.rb
    2016-10-01T20:01:22.502+02:00 [Test worker] INFO LoadService : trying fileResource: uri:classloader:/gems/rouge-1.10.1/lib/rouge/template_lexer.rb
    2016-10-01T20:01:22.502+02:00 [Test worker] INFO LoadService : found fileResource: uri:classloader:/gems/rouge-1.10.1/lib/rouge/template_lexer.rb
    2016-10-01T20:01:22.534+02:00 [Test worker] INFO LoadService : trying builtinLib: uri:classloader:/gems/rouge-1.10.1/lib/rouge/lexers/apache.rb
    2016-10-01T20:01:22.534+02:00 [Test worker] INFO LoadService : trying fileResource: uri:classloader:/gems/rouge-1.10.1/lib/rouge/lexers/apache.rb
    2016-10-01T20:01:22.534+02:00 [Test worker] INFO LoadService : found fileResource: uri:classloader:/gems/rouge-1.10.1/lib/rouge/lexers/apache.rb
    Okt 01, 2016 8:01:23 PM org.asciidoctor.internal.JRubyAsciidoctor renderFile
    SCHWERWIEGEND: (RuntimeError) asciidoctor: FAILED: required gem 'rouge' is not installed. Processing aborted.

[robertpanzer]

For reference here is the output of a successful test run on a Mac:

testoutput_mac.txt

[abelsromero]

I've been also testing on my side and got more or less the same conclusion.

I am trying to make some sense from the fact that the rouge gem is not found when running from the shell, and I am assuming that the gem is not found. However when I run the test with ./gradlew test, I see the following line:

2016-10-01T19:02:22.035+02:00 [Test worker] INFO LoadService : found fileResource: uri:classloader:/gems/rouge-1.10.1/lib/rouge.rb

Also I have noticed that the system (I assume) tries to load the gem twice because the line trying builtinLib: rouge.rb appears twice (see ouput-shell.txt for the full log). Anothe thing to support that is that debugging LoadService class I got to a point in which an exception was thrown with the message "no such file to load -- rouge", but in class InterpreserEngine (l:204) it is ignored. Not sure if this is relevant or expected, but when I tried to see the details enabling "ir.debug" it basically created so much log that it was inpractical.

Another test I did was to manually delete the rouge files from the build folder too see what happes. The results were consistent to me, in that case the test (from IntelliJ) failed as expected and in the logs no "found...rouge" message was found.

Here are my files: output-idea.txt output-shell.txt

[mkristian]

@robertpanzer from you log file (windwos) I see following found and loaded files:

   2016-10-01T20:01:17.987+02:00 [Test worker] INFO LoadService : found fileResource: uri:classloader:/gems/asciidoctor-pdf-1.5.0.alpha.13/lib/asciidoctor-pdf/rouge_ext.rb
    2016-10-01T20:01:19.785+02:00 [Test worker] INFO LoadService : found fileResource: uri:classloader:/gems/rouge-1.10.1/lib/rouge.rb
    2016-10-01T20:01:19.800+02:00 [Test worker] INFO LoadService : found fileResource: uri:classloader:/gems/rouge-1.10.1/lib/rouge/version.rb
    2016-10-01T20:01:19.800+02:00 [Test worker] INFO LoadService : found fileResource: uri:classloader:/gems/rouge-1.10.1/lib/rouge/util.rb
    2016-10-01T20:01:19.800+02:00 [Test worker] INFO LoadService : found fileResource: uri:classloader:/gems/rouge-1.10.1/lib/rouge/text_analyzer.rb
    2016-10-01T20:01:19.800+02:00 [Test worker] INFO LoadService : found fileResource: uri:classloader:/gems/rouge-1.10.1/lib/rouge/token.rb
    2016-10-01T20:01:19.831+02:00 [Test worker] INFO LoadService : found fileResource: uri:classloader:/gems/rouge-1.10.1/lib/rouge/lexer.rb
    2016-10-01T20:01:19.847+02:00 [Test worker] INFO LoadService : found fileResource: uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/cgi.rb
    2016-10-01T20:01:19.863+02:00 [Test worker] INFO LoadService : found fileResource: uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/cgi/core.rb
    2016-10-01T20:01:19.894+02:00 [Test worker] INFO LoadService : found fileResource: uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/cgi/cookie.rb
    2016-10-01T20:01:19.910+02:00 [Test worker] INFO LoadService : found fileResource: uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/cgi/util.rb
    2016-10-01T20:01:22.502+02:00 [Test worker] INFO LoadService : found fileResource: uri:classloader:/gems/rouge-1.10.1/lib/rouge/regex_lexer.rb
    2016-10-01T20:01:22.502+02:00 [Test worker] INFO LoadService : found fileResource: uri:classloader:/gems/rouge-1.10.1/lib/rouge/template_lexer.rb
    2016-10-01T20:01:22.534+02:00 [Test worker] INFO LoadService : found fileResource: uri:classloader:/gems/rouge-1.10.1/lib/rouge/lexers/apache.rb

not sure which code and how this code determines whether rouge gem is loaded or not. but it looks very much that rubygems found rouge and added the path of the gem to the load_path.

[robertpanzer]

Seems like Asciidoctor swallows the original reason for the load error. After adding a few puts I got this:

org.asciidoctor.WhenBackendIsPdf > pdf_source_code_should_be_highlighted STANDARD_OUT
    Got LoadError load error: rouge -- java.lang.NullPointerException: charset
    org/jruby/RubyKernel.java:956:in `require'
    uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rubygems/core_ext/kernel_require.rb:133:in `require'
    uri:classloader:/gems/polyglot-0.3.5/lib/polyglot.rb:65:in `require'
    uri:classloader:/gems/asciidoctor-pdf-1.5.0.alpha.13/lib/asciidoctor-pdf/rouge_ext.rb:2:in `<main>'
    org/jruby/RubyKernel.java:956:in `require'
    uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rubygems/core_ext/kernel_require.rb:1:in `(root)'
    uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rubygems/core_ext/kernel_require.rb:55:in `require'
    uri:classloader:/gems/polyglot-0.3.5/lib/polyglot.rb:65:in `require'
    uri:classloader:/gems/asciidoctor-1.5.4/lib/asciidoctor/helpers.rb:24:in `require_library'
    uri:classloader:/gems/asciidoctor-pdf-1.5.0.alpha.13/lib/asciidoctor-pdf/converter.rb:1027:in `convert_listing_or_literal'
    uri:classloader:/gems/asciidoctor-pdf-1.5.0.alpha.13/lib/asciidoctor-pdf/converter.rb:103:in `convert'
    uri:classloader:/gems/asciidoctor-1.5.4/lib/asciidoctor/abstract_block.rb:71:in `block in convert'
    org/jruby/RubyArray.java:2492:in `map'
    uri:classloader:/gems/asciidoctor-1.5.4/lib/asciidoctor/abstract_block.rb:80:in `content'
    uri:classloader:/gems/asciidoctor-1.5.4/lib/asciidoctor/abstract_block.rb:80:in `content'
    uri:classloader:/gems/asciidoctor-pdf-1.5.0.alpha.13/lib/asciidoctor-pdf/converter.rb:119:in `convert_content_for_block'
    uri:classloader:/gems/asciidoctor-pdf-1.5.0.alpha.13/lib/asciidoctor-pdf/converter.rb:358:in `convert_section'
    uri:classloader:/gems/asciidoctor-pdf-1.5.0.alpha.13/lib/asciidoctor-pdf/converter.rb:103:in `convert'
    uri:classloader:/gems/asciidoctor-1.5.4/lib/asciidoctor/abstract_block.rb:71:in `block in convert'
    org/jruby/RubyArray.java:2492:in `map'
    uri:classloader:/gems/asciidoctor-1.5.4/lib/asciidoctor/abstract_block.rb:80:in `content'
    uri:classloader:/gems/asciidoctor-1.5.4/lib/asciidoctor/abstract_block.rb:80:in `content'
    uri:classloader:/gems/asciidoctor-1.5.4/lib/asciidoctor/document.rb:1104:in `content'
    uri:classloader:/gems/asciidoctor-pdf-1.5.0.alpha.13/lib/asciidoctor-pdf/converter.rb:119:in `convert_content_for_block'
    uri:classloader:/gems/asciidoctor-pdf-1.5.0.alpha.13/lib/asciidoctor-pdf/converter.rb:177:in `convert_document'
    uri:classloader:/gems/asciidoctor-pdf-1.5.0.alpha.13/lib/asciidoctor-pdf/converter.rb:103:in `convert'
    uri:classloader:/gems/asciidoctor-1.5.4/lib/asciidoctor/document.rb:1044:in `convert'
    uri:classloader:/gems/asciidoctor-1.5.4/lib/asciidoctor.rb:1503:in `convert'
    uri:classloader:/gems/asciidoctor-1.5.4/lib/asciidoctor.rb:1576:in `convert_file'

But due to my limited Ruby knowledge I am currently not able to analyze this. @mojavelinux: Do you have an idea about this?

Line numbers in helpers.rb are a bit off due to the puts statements that I added.

[mojavelinux]

@mkristian Nailed it. This is a simple problem that we always let bite us. AsciidoctorJ is not loading JRuby in isolation. If you run the test suite while another Ruby environment with installed gems active (e.g., rvm use 2.3), JRuby will get those gems mixed up with the ones from the jar file and :boom:.

I think we need to make it so that users have to go out of their way to load AsciidoctorJ with a dependency on system gems (or a custom gem path). It should be isolated by default and it is still not.

[mojavelinux]

Here's the real error:

org.jruby.exceptions.RaiseException: (LoadError) no such file to load -- thread_safe/jruby_cache_backend

Which comes after all these warnings:

    Ignoring executable-hooks-1.3.2 because its extensions are not built.  Try: gem pristine executable-hooks --version 1.3.2
    Ignoring ffi-1.9.10 because its extensions are not built.  Try: gem pristine ffi --version 1.9.10
    Ignoring gem-wrappers-1.2.7 because its extensions are not built.  Try: gem pristine gem-wrappers --version 1.2.7
    Ignoring mathematical-1.5.12 because its extensions are not built.  Try: gem pristine mathematical --version 1.5.12
    Ignoring nokogiri-1.6.7.1 because its extensions are not built.  Try: gem pristine nokogiri --version 1.6.7.1
    Ignoring posix-spawn-0.3.11 because its extensions are not built.  Try: gem pristine posix-spawn --version 0.3.11
    Ignoring prawn-gmagick-0.0.8 because its extensions are not built.  Try: gem pristine prawn-gmagick --version 0.0.8
    Ignoring therubyracer-0.12.2 because its extensions are not built.  Try: gem pristine therubyracer --version 0.12.2
    Ignoring yajl-ruby-1.2.1 because its extensions are not built.  Try: gem pristine yajl-ruby --version 1.2.1

That's a tell-tale sign the gems are completely mixed up and it's going to fail in spectacular ways.

[mojavelinux]

Btw, you can fix this by starting with:

rvm use system

(Of course, even then you can run into problems if there are gems installed on the system that JRuby can't use...and an attempt is made to load one of them).

[robertpanzer]

Ok.... I wasn't even aware that a Ruby is installed on my pretty naked Windows machine. We are seeing the same problem on AsciidoctorJ in the asciidoctorj-pdf submodule: https://ci.appveyor.com/project/asciidoctor/asciidoctorj/build/480#L2066

(And makes me wonder why it works when loading asciidoctor-pdf and rouge from a jar instead of an exploded dir)

Am Sonntag, 2. Oktober 2016 schrieb Dan Allen :

Here's the real error:

org.jruby.exceptions.RaiseException: (LoadError) no such file to load -- thread_safe/jruby_cache_backend

Which comes after all these warnings:

Ignoring executable-hooks-1.3.2 because its extensions are not built.  Try: gem pristine executable-hooks --version 1.3.2
Ignoring ffi-1.9.10 because its extensions are not built.  Try: gem pristine ffi --version 1.9.10
Ignoring gem-wrappers-1.2.7 because its extensions are not built.  Try: gem pristine gem-wrappers --version 1.2.7
Ignoring mathematical-1.5.12 because its extensions are not built.  Try: gem pristine mathematical --version 1.5.12
Ignoring nokogiri-1.6.7.1 because its extensions are not built.  Try: gem pristine nokogiri --version 1.6.7.1
Ignoring posix-spawn-0.3.11 because its extensions are not built.  Try: gem pristine posix-spawn --version 0.3.11
Ignoring prawn-gmagick-0.0.8 because its extensions are not built.  Try: gem pristine prawn-gmagick --version 0.0.8
Ignoring therubyracer-0.12.2 because its extensions are not built.  Try: gem pristine therubyracer --version 0.12.2
Ignoring yajl-ruby-1.2.1 because its extensions are not built.  Try: gem pristine yajl-ruby --version 1.2.1

That's a tell-tale sign the gems are completely mixed up and it's going to fail in spectacular ways.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/robertpanzer/asciidoctorj-pdf/issues/3#issuecomment-250993833, or mute the thread https://github.com/notifications/unsubscribe-auth/ABHBjpIALe2xqB497WMpmLi3uiDOK5REks5qwBTBgaJpZM4KGrYb .

[mojavelinux]

Btw, this traces back to something I've observed using the AsciidoctorJ 1.6.0 alpha. Asciidoctor.Factory.create() still does not load JRuby in isolation. To avoid confusion, that really needs to be the default. It should only use external gems if the gem path is specified explicitly. Remember, that means AsciidoctorJ must forcefully unset the environment variables (as it does currently when you pass (String) null).

[mojavelinux]

(And makes me wonder why it works when loading asciidoctor-pdf and rouge from a jar instead of an exploded dir)

I think that just gets into internal details about how JRuby handles a situation that is not isolated. It's going to be highly dependent on what it is able to locate and in what order. But the fact that it is looking is the real problem.

[robertpanzer]

Asciidoctor.Factory.create() still does not load JRuby in isolation.

Good tip, I'll try that.

[mojavelinux]

...in fact, I'd go so far as to say I think we need to change this default even for AsciidoctorJ 1.5.x. Loading JRuby with a dependency on system gems only causes us problems and no one should be relying on it anyway. There's just no circumstance I can think of where that should be the default.

[robertpanzer]

I am completely d'accord with changing the default of Asciidoctor.Factory.create() to explicitely pass a null GEM_PATH and I'll create PR's for master and asciidoctorj-1.6.0.

I tried changing the call of Asciidoctor.Factory.create() to Asciidoctor.Factory.create((String) null) in the test case as we do in the AsciidoctorInvoker which is used from the CLI. But no luck :-( Still the same NullPointerException from polyglot.rb.

[mojavelinux]

Still the same NullPointerException from polyglot.rb.

polyglot.rb is a smokescreen. The only reason that path comes up is because it patches require for an unrelated reason. The real source of the error is the native require.

To get to the real error, you can monkeypatch / edit the Helpers.require_library method in helpers.rb and print the backtrace of the LoadError.

[mojavelinux]

If I pass (String) null to the create() method in the test, then the tests pass for me (if they don't, and I have an active C Ruby environment, then they fail). How are you running the tests?

[mojavelinux]

(There's a slight possibility that our code to put JRuby in isolation is not working correctly on Windows).

[robertpanzer]

That's what I did and it gave me the NPE from polyglot. I added the backtrack in a comment above.

The test only fails on Windows. I have Win 10 and Abel is using Win 7 afaik. I have no issues on Mac with an installed Ruby 2.0.0.

[mojavelinux]

Again, we shouldn't be mentioning polyglot as that is just going to confuse the conversation. The problem is with require.

With the other issues cleared up, there's a possibility that there's something rouge loads which JRuby is not happy about (specifically on Windows)...and that is unrelated to Asciidoctor/AsciidoctorJ.

[mojavelinux]

Can you create a test that loads AsciidoctorJ, then does a low-level require of rouge?

[robertpanzer]

Sure. Will do that tomorrow. I was just mentioning it because it was what I got after uncovering the initial error that rouge is simply not there.

[mojavelinux]

Gotcha.

Btw, we should be using Rouge 2. Can you update to 2.0.6? It doesn't impose any additional requirements, so it should be safe to move (and the tests pass).

[abelsromero]

You have done a lot of progress.

I have Win 10 and Abel is using Win 7 afaik.

I have been testing with Win7 and Win 8.1. I alse deleted my ruby installations and gems to avoid interferences, that fixed the initial psych issue. When @robertpanzer pushes the test I can test them on my systems also.

[robertpanzer]

Even with upgrading rouge to 2.0.6 I have no luck. But I added a test in #4 that reveals the next nested problem related to psych (here we are again at Abel's error he observed in IntelliJ):

org.jruby.exceptions.RaiseException: (LoadError) load error: rouge -- java.lang.NullPointerException: charset
    at org.jruby.RubyKernel.require(org/jruby/RubyKernel.java:956)
    at RUBY.require(uri:classloader:/META-INF/jruby.home/lib/ruby/stdlib/rubygems/core_ext/kernel_require.rb:133)
    at RUBY.<main>(<script>:1)
Caused by: java.lang.NullPointerException: charset
    at java.io.InputStreamReader.<init>(InputStreamReader.java:115)
    at org.jruby.ext.psych.PsychParser.readerFor(PsychParser.java:165)
    at org.jruby.ext.psych.PsychParser.parse(PsychParser.java:177)
    at org.jruby.ext.psych.PsychParser$INVOKER$i$parse.call(PsychParser$INVOKER$i$parse.gen)
    at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:358)
...

I have no clue about how psych works and what it is exactly (other than that it is a yaml parser which has native deps on MRI and is therefore delivered in JRuby). But it seems like yaml.getReadEncoding() in PsychParser returns null because the last:

            Encoding enc = (yaml instanceof RubyIO)
                ? ((RubyIO)yaml).getReadEncoding()
                : UTF8Encoding.INSTANCE;
            Charset charset = enc.getCharset(); // Line 165

But what makes me completely doubt everything is that I can't find PsychParser in jruby 9.1.5.0. It's only available in JRuby 1.7.25. The runtime dependency for jruby-complete should be lifted to 9.1.5.0 and I also see this error if I exclude org.jruby from the transitive deps of asciidoctorj.

So to sum it up: I have not the slightest clue what is happening here and feel like a complete fool. I have no idea where this impl from PsychParser is coming from.

[mojavelinux]

The way yaml is implemented and loaded in Ruby is weird. It's always an oddball. That's because it's sort of a gem and sort of not a gem.

Having a test is the first step to getting somewhere. We just need to be patient.

It's appears that Rouge's lexer for Apache (lib/rouge/lexers/apache.rb) requires yaml, so that's where yaml comes into the picture.

There's a chance this has to do with the default encoding settings of the system. When we hit those, it's almost always on Windows since the default encoding in Windows is not often UTF-8. So we might have to consider it has to do with international Windows (though you did say it fails in AppVeyor too, which is US).

[mojavelinux]

For the record, Asciidoctor PDF uses safe_yaml, not yaml, so that's why it is Rouge that triggers this and not Asciidoctor PDF.

[mojavelinux]

In JRuby, native components are written in Java and shipped in a jar file (native doesn't mean C code, it just means not Ruby code). You can find PsychParser in lib/ruby/stdlib/psych.jar. Here's the source: https://github.com/ruby/psych/blob/v2.0.17/ext/java/PsychParser.java

[mojavelinux]

It makes sense why it hits this method because the yaml in the Apache lexer is read in from an IO object. See https://github.com/jneen/rouge/blob/b8a2c9df24817b28303f9aad449524fdd7261416/lib/rouge/lexers/apache.rb#L16

That's the line that is likely failing as it gets run when the file is required.

[mojavelinux]

...so you might be able to reproduce the issue even without requiring rouge.

[robertpanzer]

Yes, you're right. I'm getting the same error with this little snippet:

    Asciidoctor asciidoctor = Asciidoctor.Factory.create((String) null);
    JRubyRuntimeContext.get().evalScriptlet("require 'yaml'");
    JRubyRuntimeContext.get().evalScriptlet("::YAML.load(File.open('...\\asciidoctorj-pdf\\asciidoctorj-pdf\\build\\resources\\main\\gems\\rouge-2.0.6\\lib\\rouge\\lexers\\apache\\keywords.yml'))");

(And also if I don't initialize Asciidoctor but take the global JRuby runtime via Ruby.getGlobalRuntime().)

[mkristian]

looks like a bug in JRuby or PsychParser:

there is a NPE in PsychParser because of this Charset charset = enc.getCharset(); returns null and later the assumption is that this is not null. or is the problem in the ruby_io implementation of JRuby that it returns an Encoding which does not return a Charset.

just reading through this thread and adding my thoughts.

[robertpanzer]

Tried to reproduce this error in an empty project only depending on jruby-complete 9.1.5.0. But there it works. :-( No idea if sth is inconsistent in our setup of gems that makes YAML parsing fail from an exploded dir.

[mojavelinux]

I found the issue. It's a bug in rouge. I'll submit a patch upstream.

Btw:

asciidoctor: FAILED: required gem 'rouge' is not installed. Processing aborted.

That doesn't always indicate that the gem isn't available. It just means the gem failed to load. If it's not available, that's one cause. But if the gem has a bug in it and can't load, then that's another possible cause. And it is the case here.

The problem in Rouge is the following line in the apache.rb lexer:

::YAML.load(::File.open('...'))

There are two problems here. First, load expects a string, not a file handle. It works with some YAML implementations, but not the one in JRuby. The second is that this leaves the file open...which is generally bad. The first is to replace this call with ::YAML.load_file. I'll be submitting a patch to rouge shortly.

[mojavelinux]

We could try to work around this by monkeypatching YAML.load, but that feels wrong to me. I think we should just track the fix upstream in rouge. See https://github.com/jneen/rouge/issues/661.

[mojavelinux]

I believe this is now resolved. @robertpanzer can you bump rouge to 3.3.0 for the beta.1 release?

[robertpanzer]

Rouge should already be on 3.3.0 with 1.5.0-alpha.18:

https://github.com/asciidoctor/asciidoctorj-pdf/blob/d71c460f697ad9bc83a58f111e1b2ad270de1cc5/build.gradle#L51

[mojavelinux]

Nice! Then I'm confident this issue is closed.

If it comes up again, please reopen (or better yet, create a new issue).