Warning about loading tilt/haml in a non thread-safe way

[msgilligan]

I'm seeing this warning in my Gradle-based project:

WARN: tilt autoloading 'tilt/haml' in a non thread-safe way; explicit require 'tilt/haml' suggested.

The same warning also shows up in this sample project: https://github.com/JGrenier/asciidoclet-sample

I'm using Gradle 2.6.

[msgilligan]

@ysb33r Any ideas on this one?

[mojavelinux]

Give me a moment and I will explain how to test.

[mojavelinux]

The problem here is that Asciidoclet is bundling JRuby 1.7.26, which provides Ruby 1.9.3. That's definitely not going to work with Tilt 2.0.8. It's time to stop bundling.

In fact, the following configuration in gradle/javadoc.gradle is pointless:

asciidoclet "org.asciidoctor:asciidoctorj:1.5.7"

It's not going to use AsciidoctorJ 1.5.7 because AsciidoctorJ (and JRuby) are bundled. You are stuck with what Asciidoclet ships...and that's AsciidoctorJ 1.5.6 and JRuby 1.7.26.

[mojavelinux]

Here are the steps you can follow to find this out.

1. From the root of the concensusj project, switch to the build directory

2. Create the following Gemfile

   source 'https://rubygems.org'
   gem 'tilt'

3. Run Bundler from that directory as follows:

   bundle --path=vendor

4. Open the build/javadoc.gradle file and change the gem-path option to the following (double check that the Ruby version folder is correct)

   options.addStringOption '-gem-path', file('build/vendor/ruby/2.5.0').absolutePath

5. From the root of the concensusj project, switch to the bitcoinj-json directory

6. Run the following Gradle task:

   ../gradlew javadoc

7. The error message will now reveal a path to a file in a local tilt installation. You can modify that script directory and run the Gradle task again

[mojavelinux]

I added the following statement at the line where Tilt fails:

puts RbConfig::CONFIG

Here is what I saw:

{"MAJOR"=>"1", "MINOR"=>"9", "TEENY"=>"3", "ruby_version"=>"1.9", "arch"=>"universal-java1.8",...

[mojavelinux]

For some reason, it does manage to use Asciidoctor 1.5.7.1. I confirmed this by printing the value of Asciidoctor::VERSION. However, this bundling is still not a great situation.

[mojavelinux]

I'm rebuilding Asciidoclet just in case I was using a stale snapshot...

[mojavelinux]

Got it working!

The snapshot of Asciidoclet at https://oss.sonatype.org/content/repositories/snapshots/ is woefully out of date. If you build Asciidoclet locally and use this configuration instead:

repositories {
  mavenLocal()
}

then it works.

However, we still get a lot of warnings from Haml.

paragraph.html.haml:2: warning: instance variable @haml_buffer not initialized

Honestly, I would recommend switching to Slim. I find Slim much more reliable than Haml.

[mojavelinux]

I'm happy to see that Asciidoclet no longer bundles JRuby and AsciidoctorJ, which is :+1:

[ysb33r]

If it is not bundled then it is usually relative easy to convince Gradle to only put the correct versions on dependencies on the classpath that you need.

[msgilligan]

Got it working!

@mojavelinux Did you do a full build of all the modules? I'm seeing errors in the bitcoinj-rpcclient submodule:

Jun 30, 2018 7:25:02 PM org.asciidoctor.internal.JRubyAsciidoctor render
SEVERE: org.jruby.RubyNoMethodError
javadoc: error - In doclet class org.asciidoctor.Asciidoclet,  method start has thrown an exception java.lang.reflect.InvocationTargetException
org.asciidoctor.internal.AsciidoctorCoreException: org.jruby.exceptions.RaiseException: (NoMethodError) asciidoctor: FAILED: <stdin>: Failed to load AsciiDoc document - undefined method `start_with?' for nil:NilClass
        at org.asciidoctor.internal.JRubyAsciidoctor.render(JRubyAsciidoctor.java:341)
        at org.asciidoctor.internal.JRubyAsciidoctor.render(JRubyAsciidoctor.java:448)
        at org.asciidoctor.asciidoclet.AsciidoctorRenderer.render(AsciidoctorRenderer.java:160)
        at org.asciidoctor.asciidoclet.AsciidoctorRenderer.renderTag(AsciidoctorRenderer.java:142)
        at org.asciidoctor.asciidoclet.AsciidoctorRenderer.renderDoc(AsciidoctorRenderer.java:111)
        at org.asciidoctor.asciidoclet.DocletIterator.renderClass(DocletIterator.java:71)
        at org.asciidoctor.asciidoclet.DocletIterator.render(DocletIterator.java:56)
        at org.asciidoctor.Asciidoclet.run(Asciidoclet.java:275)
        at org.asciidoctor.Asciidoclet.start(Asciidoclet.java:268)
        at org.asciidoctor.Asciidoclet.start(Asciidoclet.java:242)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at com.sun.tools.javadoc.DocletInvoker.invoke(DocletInvoker.java:310)
        at com.sun.tools.javadoc.DocletInvoker.start(DocletInvoker.java:189)
        at com.sun.tools.javadoc.Start.parseAndExecute(Start.java:366)
        at com.sun.tools.javadoc.Start.begin(Start.java:219)
        at com.sun.tools.javadoc.Start.begin(Start.java:205)
        at com.sun.tools.javadoc.Main.execute(Main.java:64)
        at com.sun.tools.javadoc.Main.main(Main.java:54)
Caused by: org.jruby.exceptions.RaiseException: (NoMethodError) asciidoctor: FAILED: <stdin>: Failed to load AsciiDoc document - undefined method `start_with?' for nil:NilClass
        at RUBY.parse_section_title(uri:classloader:/gems/asciidoctor-1.5.7.1/lib/asciidoctor/parser.rb:1734)
        at RUBY.initialize_section(uri:classloader:/gems/asciidoctor-1.5.7.1/lib/asciidoctor/parser.rb:1564)
        at RUBY.next_section(uri:classloader:/gems/asciidoctor-1.5.7.1/lib/asciidoctor/parser.rb:290)
        at RUBY.parse(uri:classloader:/gems/asciidoctor-1.5.7.1/lib/asciidoctor/parser.rb:96)
        at RUBY.parse(uri:classloader:/gems/asciidoctor-1.5.7.1/lib/asciidoctor/document.rb:565)
        at RUBY.load(uri:classloader:/gems/asciidoctor-1.5.7.1/lib/asciidoctor.rb:1361)
1 error
        at RUBY.convert(uri:classloader:/gems/asciidoctor-1.5.7.1/lib/asciidoctor.rb:1473)
        at RUBY.convert(<script>:82)

[msgilligan]

Honestly, I would recommend switching to Slim. I find Slim much more reliable than Haml.

How hard is that? @johncarl81

[mojavelinux]

Given that the templates you have are about 1 line each, I'd say it would take minutes.

(That probably wouldn't solve this problem...just the warnings...but I just find Slim to be a better choice in general).

[mojavelinux]

Did you do a full build of all the modules?

I did not.

[mojavelinux]

The start_with? error appears to be a bug in AsciidoctorJ. I'm trying to reproduce, but it's extremely hard to understand.

[mojavelinux]

This is extremely bizarre. It looks like JRuby is failing to exit a while loop even when the condition is false. It starts happening after a few dozen calls to Asciidoctor.

The following code in the Asciidoctor parser is the source of the problem:

while reader.has_more_lines?
  new_section, block_attributes = next_section(reader, document, block_attributes)
  if new_section
    document.assign_numeral new_section
    document.blocks << new_section
  end
end unless options[:header_only]

However, if I write it like this, it works every time:

unless options[:header_only]
  while reader.has_more_lines?
    new_section, block_attributes = next_section(reader, document, block_attributes)
    if new_section
      document.assign_numeral new_section
      document.blocks << new_section
    end
  end
end

It's possible this is being caused by a bad interaction with another library. I can't reproduce it when using JRuby alone.

I can rewrite this logic in core, but it would require another release.

cc: @enebo

[judofyr]

Something very weird is happening here though. If I add this to the top of tilt.rb:

p RUBY_VERSION
p RbConfig::CONFIG

Then I get:

"2.0.0"
{"MAJOR"=>"1", "MINOR"=>"9", "TEENY"=>"3", "ruby_version"=>"1.9", "arch"=>"universal-java1.8", …}

This trips Tilt up because it uses a different compiling technique which only works in Ruby 2.0

[judofyr]

@mojavelinux: And thanks a lot for the steps for running with a locally bundled Tilt. It worked very well!

[mojavelinux]

I was able to workaround this issue in the consensusj project by doing the following.

Create an Asciidoctor patch file at gradle/asciidoctor-patch.rb with the following contents:

module Asciidoctor; class Parser
  def self.parse reader, document, options = {}
    block_attributes = parse_document_header reader, document
    unless options[:header_only]
      while reader.has_more_lines?
        new_section, block_attributes = next_section reader, document, block_attributes
        if new_section
          document.assign_numeral new_section
          document.blocks << new_section
        end
      end
    end
    document
  end
end; end

Load this file into AsciidoctorJ by setting the following javadoc option:

options.addStringOption '-require', "asciidoctor-diagram,${file('gradle/asciidoctor-patch.rb').path}"

I'm not sure how we can load that into Asciidoclet, but it's probably best to just use a patch for now and get it fixed upstream.

[mojavelinux]

This trips Tilt up because it uses a different compiling technique which only works in Ruby 2.0

We're aware. This was one of the problems with how JRuby was configured in an old version of AsciidoctorJ. That's since been fixed. The problem is that the Asciidoclet snapshot was using that old version and hence we were backtracking into that mud.

[mojavelinux]

In the end, the problem reported by @msgilligan in Tilt was in fact cause by using and old and misconfigured version of JRuby / AsciidoctorJ. A newer build of Asciidoclet resolves that problem.

But then we hit another problem in JRuby that seems to be related to memoization of loop (for reasons I can't yet explain). That is not Tilt related. As far as Tilt is concerned, I think we're good.

...except I'd really like to see that @haml_buffer warning resolved. (I see that even in the Asciidoctor test suite).

[judofyr]

Would it be possible to upgrade to Haml 5? They introduced a better public API which causes Tilt to avoid manually setting instance variables.

[enebo]

@mojavelinux can you try running with JRUBY_OPTS=--dev and see if this still fails? you mentioning it works for a while then stops is a classic indication our JIT is not compiling correctly.

[mojavelinux]

@enebo Yep, I can give that a try. Thanks for the tip!

@judofyr We were holding off because Haml 5 requires Ruby 2, but now that we're using JRuby 9, I don't see anything stopping us from going there. @msgilligan we'll need that change in AsciidoctorJ since it bundles haml.

[mojavelinux]

@enebo I set the environment variable and got the same result. It fails after about 25 invocations. But it's possible AsciidoctorJ is modifying the environment, hence nullifying the flag. Is there some way to verify that dev mode is active from a Ruby script?

[enebo]

@mojavelinux can you give me a way to repro this? I do not recall a mechanism to easily dump what our state is at runtime (although hindsight is 20/20 and that is a good idea). Likely if you look for -Djruby in your repo you will see where it is doing stuff. In that case maybe you can add -Djruby.compile.mode=OFF and -Djruby.jit.threshold=-1.

[johncarl81]

Put together a minimal failing example here: https://github.com/johncarl81/asciidoctorjtest

Here's the meat of the code:

        Asciidoctor asciidoctor = JRubyAsciidoctor.create();

        int i = 0;
        try {
            for (; i < 1000; i++) {
                asciidoctor.render("Test", new HashMap<String, Object>());
            }
        } catch (Exception e) {
            System.out.println("Errored after " + i + " iterations.");
            e.printStackTrace();
        }

Which throws an exception around (not deterministicly) 70 iterations for me:

Jul 04, 2018 12:42:03 PM org.asciidoctor.internal.JRubyAsciidoctor render
SEVERE: org.jruby.RubyNoMethodError
org.asciidoctor.internal.AsciidoctorCoreException: org.jruby.exceptions.RaiseException: (NoMethodError) asciidoctor: FAILED: <stdin>: Failed to load AsciiDoc document - undefined method `start_with?' for nil:NilClass
    at org.asciidoctor.internal.JRubyAsciidoctor.render(JRubyAsciidoctor.java:341)
    at org.asciidoctor.Test.main(Test.java:18)
Caused by: org.jruby.exceptions.RaiseException: (NoMethodError) asciidoctor: FAILED: <stdin>: Failed to load AsciiDoc document - undefined method `start_with?' for nil:NilClass
    at RUBY.parse_section_title(uri:classloader:/gems/asciidoctor-1.5.7.1/lib/asciidoctor/parser.rb:1734)
    at RUBY.initialize_section(uri:classloader:/gems/asciidoctor-1.5.7.1/lib/asciidoctor/parser.rb:1564)
    at RUBY.next_section(uri:classloader:/gems/asciidoctor-1.5.7.1/lib/asciidoctor/parser.rb:290)
    at RUBY.parse(uri:classloader:/gems/asciidoctor-1.5.7.1/lib/asciidoctor/parser.rb:96)
    at RUBY.parse(uri:classloader:/gems/asciidoctor-1.5.7.1/lib/asciidoctor/document.rb:565)
    at RUBY.load(uri:classloader:/gems/asciidoctor-1.5.7.1/lib/asciidoctor.rb:1361)
    at RUBY.convert(uri:classloader:/gems/asciidoctor-1.5.7.1/lib/asciidoctor.rb:1473)
    at RUBY.convert(<script>:82)
Errored after 72 iterations.

Hope this helps.

[enebo]

@johncarl81 how do you run that from the command line? I am having issues where it cannot find JRuby or it cannot load asciidoctor from ruby itself.

I can see that asciidoctor will disable JIT and we will not bytecode generate but we do switch between a startup and full interpreter. Seeing the number of iterations differ is likely us starting a full build in a background thread and the replacement is not happening at the same moment. I think -Djruby.jit.background=false will make the error iteration the same and -Djruby.jit.threshold=-1 should remove the error altogether. Once I can run your test (unless you try it) we shall see.

[johncarl81]

@enebo Got a couple ways for you to execute it. First, you can clone the project and run it via Maven. Just run the following command in the project root:

mvn exec:java

If you don't have maven installed, you can download the published snapshot shaded jar from github which I uploaded earlier and run it via Java directly:

java -jar asciidoctorj-test-1.0-SNAPSHOT-shaded.jar

[enebo]

@johncarl81 for some reason your exec:java is not working for me but if I generate with package in your last changes to pom.xml the shaded jar it generates will run. So both my instincts seem to be right:

java -Djruby.jit.background=false -jar target/asciidoctorj-test-1.0-SNAPSHOT-shaded.jar 
Jul 05, 2018 3:15:23 PM org.asciidoctor.internal.JRubyAsciidoctor render
SEVERE: org.jruby.RubyNoMethodError
Errored after 50 iterations.

I get 50 iterations consistently so what we generate when switching to full build is broken. Also if set threshold to -1 then no full build is performed and all is working:

java -Djruby.jit.threshold=-1 -Djruby.jit.background=false -jar target/asciidoctorj-test-1.0-SNAPSHOT-shaded.jar 

So at this point we know we have a bug in full build (which would also occur in JIT itself if it was enabled) and we know what code is doing it. My cursory examination of code in question in its internal representation actually looks ok so next steps is to see how different it looks for real. Perhaps extracting that snippet by itself was inadequate.

[enebo]

Alright this is a bit too much for this issue and I will eventually make one for JRuby itself but I am dumping my latest breakthrough. The gist of the bug is some basic block culling not properly updating a jump operand. Interestingly it may even be fixed in 9.2. So here is a dump from broken version of parse:

:Instructions
2018-07-05T16:27:49.432-05:00 [main] INFO BasicCompilerPassListener : Finished Add Call Protocol Instructions (push/pop of dyn-scope, frame, impl-class values) on scope in 0ms.
2018-07-05T16:27:49.432-05:00 [main] INFO BasicCompilerPassListener : Starting Add Missing Initialization on scope CLASS_METHOD parse[../snippets/parser1.rb:91]
2018-07-05T16:27:49.433-05:00 [main] INFO BasicCompilerPassListener : 
Graph:
BB [1:LBL_6:-1]:>[2,16]
BB [2:LBL_7:-1]:>[3,4,17], <[1]
BB [3:LBL_8:-1]:>[4,17], <[2]
BB [4:LBL_0:13]:>[5,6,17], <[2,3]
BB [5:LBL_9:-1]:>[15,17], <[4]
BB [6:LBL_1:21]:>[8,13,17], <[4]
BB [8:_ITER_BEGIN_0:26]:>[9,10,17], <[6]
BB [9:LBL_10:-1]:>[11,17], <[8]
BB [10:LBL_4:43]:>[11,17], <[8]
BB [11:LBL_5:45]:>[17], <[9,10]
BB [13:LBL_3:48]:>[15,17], <[6]
BB [15:LBL_2:52]:>[16,17], <[5,13]
BB [16:LBL_11:-1]:>[17], <[1,15,17]
BB [17:_GLOBAL_ENSURE_BLOCK__0:-1]:>[16], <[2,3,4,5,6,8,9,10,11,13,15,16]

2018-07-05T16:27:49.433-05:00 [main] INFO BasicCompilerPassListener : 
Instructions[../snippets/parser1.rb#91#parse,IRMethod,AddMissingInitsPass]:
BB [1:LBL_6:-1]
    push_method_frame()
BB [2:LBL_7:-1]
    check_arity(;req: 2, opt: 1, *r: false, kw: false)
    %t_reader_15 = recv_pre_reqd_arg(;i:0)
    %t_document_16 = recv_pre_reqd_arg(;i:1)
    %t_options_17 = recv_opt_arg(;index:0, req: 2, pre: 2)
    bne(LBL_0:13, %t_options_17, %undefined)
BB [3:LBL_8:-1]
    %v_3 = copy({!abs-arg!})
    %t_options_17 = copy(%v_3)
BB [4:LBL_0:13]
    line_num(;n: 92)
    %t_block_attributes_18 = call_2o(%self, %t_reader_15, %t_document_16 ;n:parse_document_header, t:FU, cl:false)
    line_num(;n: 102)
    %v_4 = call_1o(%t_options_17, :'header_only' ;n:[], t:NO, cl:false)
    b_false(LBL_1:21, %v_4)
BB [5:LBL_9:-1]
    jump(LBL_2:52)
BB [6:LBL_1:21]
    line_num(;n: 96)
    %v_7 = call_0o(%t_reader_15 ;n:has_more_lines?, t:NO, cl:false)
    b_false(LBL_3:48, %v_7)
BB [8:_ITER_BEGIN_0:26]
    thread_poll()
    line_num(;n: 97)
    %v_8 = call(%self, %t_reader_15, %t_document_16, %t_block_attributes_18 ;n:next_section, t:FU, cl:false)
    %v_9 = to_ary(%v_8)
    %v_10 = masgn_reqd(%v_9 ;index: 0, pre: -1, post: -1)
    %t_new_section_19 = copy(%v_10)
    line_num(;n: 98)
    b_false(LBL_4:43, %v_10)
BB [9:LBL_10:-1]
    line_num(;n: 99)
    %v_12 = call_1o(%t_document_16, %t_new_section_19 ;n:assign_numeral, t:NO, cl:false)
    line_num(;n: 100)
    %v_13 = call_0o(%t_document_16 ;n:blocks, t:NO, cl:false)
    %v_14 = call_1o(%v_13, %t_new_section_19 ;n:<<, t:NO, cl:false)
    jump(LBL_5:45)
BB [10:LBL_4:43]
BB [11:LBL_5:45]
    jump(_LOOP_BEGIN_0:22)
BB [13:LBL_3:48]
BB [15:LBL_2:52]
    line_num(;n: 104)
    pop_method_frame()
    return(%t_document_16)
BB [16:LBL_11:-1]
BB [17:_GLOBAL_ENSURE_BLOCK__0:-1]
    %v_20 = recv_jruby_exc()
    pop_method_frame()
    throw(%v_20)

------ Rescue block map ------
BB 2 --> BB 17
BB 3 --> BB 17
BB 4 --> BB 17
BB 5 --> BB 17
BB 6 --> BB 17
BB 8 --> BB 17
BB 9 --> BB 17
BB 10 --> BB 17
BB 11 --> BB 17
BB 13 --> BB 17
BB 15 --> BB 17
BB 16 --> BB 17

If you squint and accept this as some weird assembly we can see we do a jump back to beginning of loop with

jump(_LOOP_BEGIN_0:22)

If you look at the method you will see _LOOP_BEGIN is missing! It was removed from combining Basic Blocks but the jump was not updated to what basic block it was combined with. So a) I just need to cherry pick a fix I made on master that I for some reason did not backport b) Something is just different on 9.1 IR that merged too far in 9.2. I will hit this again in the morning but I am very close to solving this.

[mojavelinux]

Thanks for the updates @enebo and thanks for the assist with the sample project @johncarl81! I'm glad to hear you are getting close to solving it. :tada:

[enebo]

@mojavelinux it occurs to me that I may have backported this for 1.7.27 and asciidoc is still use 1.7.26. Maybe update quick and see if it goes away? Otherwise I will figure out in the morning.

[mojavelinux]

I've actually tested with JRuby 9.0.x, 9.1.x, and 9.2.0.0...same issue. AsciidoctorJ actually ships with (actually, links against) different versions of JRuby depending on the version...but 1.5.7 now links against 9.1.x.

[enebo]

@mojavelinux wow I am surprised 9.2.0.0 is broken. I do not see the same output there. Is there some instructions on how to build the whole dist so I can mess with my own jruby snapshot somewhere? In the morning I will isolate what is wrong (oh and I am using master but I know I did not fix any issues with coallescing basic blocks since 9.2.0.0).

[enebo]

@mojavelinux I think this is fixed in 9.1.17.0. At least the minimal example passes in asciidoctorj above. Here is what I did and you can tell me perhaps if I made a mistake. I built master of asciidoctorj which appears as 1.5.8-SNAPSHOT in local maven repo. I change build.gradle to:

  jrubyVersion = '9.1.17.0'

I opened finished jar and I can see parser.rb is still using the while ... end until options check. I rebuild asciidoctortest above and that test app runs fine now.

Maybe the above reduced app exposes a problem fixed by 9.1.17.0 (and 9.2.0.0) and misses the problem which is still broken?

[mojavelinux]

Thanks for testing. I'll give it another shot on my end to confirm.

[mojavelinux]

@msgilligan or @johncarl81 can you verify the result @enebo is getting? If it turns out this is still a problem, perhaps we need a dedicated issue because we've really diverged from $subject.

[johncarl81]

@mojavelinux I've confirmed, running the test program with jruby 9.1.17.0 does not give an error!

[johncarl81]

... perhaps we should upgrade asciidoclet to the latest asciidoctorj as well then.

[mojavelinux]

:+1:

[msgilligan]

So, this will be in the next release? Can I test it in ConsensusJ via a snapshot?

[johncarl81]

Sure, just deployed the snapshot to maven central under 1.5.7-SNAPSHOT.