Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Stackoverflow error in reader.rb in Asciidoctor 2.0.17 #4368

Closed
ahus1 opened this issue Oct 14, 2022 · 17 comments
Closed

Stackoverflow error in reader.rb in Asciidoctor 2.0.17 #4368

ahus1 opened this issue Oct 14, 2022 · 17 comments
Assignees
@mojavelinux
Labels
bug v2.0.19 Issues resolved in the 2.0.19 release
Milestone
v2.0.x

Comments

@ahus1
Copy link
Contributor

ahus1 commented Oct 14, 2022

A user of the AsciiDoc plugin for IntelliJ reported anonymously the following exception via the Sentry error reporter.

I don't know the input that caused this, still I hope this stack trace reals helpful information.

Looking at the classes this happens with Asciidoctor 2.0.17.

java.lang.StackOverflowError: null
    at org.jruby.internal.runtime.methods.CompiledIRMethod.call(CompiledIRMethod.java:139)
    at org.jruby.ir.runtime.IRRuntimeHelpers.instanceSuper(IRRuntimeHelpers.java:1229)
    at uri_3a_classloader_3a_.gems.asciidoctor_minus_2_dot_0_dot_17.lib.asciidoctor.reader.invokeSuper0:peek_line(uri:classloader:/gems/asciidoctor-2.0.17/lib/asciidoctor/reader.rb:652)
    at uri_3a_classloader_3a_.gems.asciidoctor_minus_2_dot_0_dot_17.lib.asciidoctor.reader.RUBY$method$peek_line$0(uri:classloader:/gems/asciidoctor-2.0.17/lib/asciidoctor/reader.rb:652)
    at org.jruby.internal.runtime.methods.CompiledIRMethod.call(CompiledIRMethod.java:139)
    at org.jruby.internal.runtime.methods.CompiledIRMethod.call(CompiledIRMethod.java:149)
    at org.jruby.internal.runtime.methods.MixedModeIRMethod.call(MixedModeIRMethod.java:148)
    at org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:210)
    at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:142)
    at uri_3a_classloader_3a_.gems.asciidoctor_minus_2_dot_0_dot_17.lib.asciidoctor.reader.invokeOther15:peek_line(uri:classloader:/gems/asciidoctor-2.0.17/lib/asciidoctor/reader.rb:137)
    at uri_3a_classloader_3a_.gems.asciidoctor_minus_2_dot_0_dot_17.lib.asciidoctor.reader.RUBY$method$peek_line$0(uri:classloader:/gems/asciidoctor-2.0.17/lib/asciidoctor/reader.rb:137)
    at org.jruby.internal.runtime.methods.CompiledIRMethod.call(CompiledIRMethod.java:139)
    at org.jruby.internal.runtime.methods.MixedModeIRMethod.call(MixedModeIRMethod.java:112)
    at org.jruby.ir.runtime.IRRuntimeHelpers.instanceSuper(IRRuntimeHelpers.java:1229)
    at uri_3a_classloader_3a_.gems.asciidoctor_minus_2_dot_0_dot_17.lib.asciidoctor.reader.invokeSuper0:peek_line(uri:classloader:/gems/asciidoctor-2.0.17/lib/asciidoctor/reader.rb:652)
    at uri_3a_classloader_3a_.gems.asciidoctor_minus_2_dot_0_dot_17.lib.asciidoctor.reader.RUBY$method$peek_line$0(uri:classloader:/gems/asciidoctor-2.0.17/lib/asciidoctor/reader.rb:652)
@mojavelinux
Copy link
Member

In order to address this, I need a sample document. Without that, I have no way to develop or verify a fix.

@ahus1
Copy link
Contributor Author

ahus1 commented Oct 14, 2022

Ok, then I'll close this issue as I won't be able to retrieve it as this is not available from the automatic error report.

@ahus1 ahus1 closed this as completed Oct 14, 2022
@ahus1 ahus1 closed this as not planned Won't fix, can't repro, duplicate, stale Oct 14, 2022
@ggrossetie
Copy link
Member

It looks like an infinite loop between:

asciidoctor/lib/asciidoctor/reader.rb

Line 137 in 102f364

(process_line @lines[-1]) || peek_line

and:

asciidoctor/lib/asciidoctor/reader.rb

Line 652 in 102f364

if (line = super)

I can reproduce it using the following document (in Intellij IDEA):

ifeval::[2 > 3]
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
endif::[]

data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data
data

@ggrossetie ggrossetie reopened this Oct 15, 2022
@ggrossetie
Copy link
Member

ggrossetie commented Oct 15, 2022 •
edited

Using the Asciidoctor Browser Extension, I get a weird error:

crbug/1173575, non-JS module files deprecated.

Though, it seems to run fine in Asciidoctor (Ruby)

You need to add more lines in the ifeval block but eventually you will get a SystemStackError:

asciidoctor test.adoc --trace
/home/guillaume/.rvm/gems/ruby-3.1.2/gems/asciidoctor-2.0.17/lib/asciidoctor/reader.rb:763:in `shift': stack level too deep (SystemStackError)
	from /home/guillaume/.rvm/gems/ruby-3.1.2/gems/asciidoctor-2.0.17/lib/asciidoctor/reader.rb:866:in `process_line'
	from /home/guillaume/.rvm/gems/ruby-3.1.2/gems/asciidoctor-2.0.17/lib/asciidoctor/reader.rb:137:in `peek_line'
	from /home/guillaume/.rvm/gems/ruby-3.1.2/gems/asciidoctor-2.0.17/lib/asciidoctor/reader.rb:652:in `peek_line'
	from /home/guillaume/.rvm/gems/ruby-3.1.2/gems/asciidoctor-2.0.17/lib/asciidoctor/reader.rb:137:in `peek_line'
	from /home/guillaume/.rvm/gems/ruby-3.1.2/gems/asciidoctor-2.0.17/lib/asciidoctor/reader.rb:652:in `peek_line'
	from /home/guillaume/.rvm/gems/ruby-3.1.2/gems/asciidoctor-2.0.17/lib/asciidoctor/reader.rb:137:in `peek_line'
	from /home/guillaume/.rvm/gems/ruby-3.1.2/gems/asciidoctor-2.0.17/lib/asciidoctor/reader.rb:652:in `peek_line'
	from /home/guillaume/.rvm/gems/ruby-3.1.2/gems/asciidoctor-2.0.17/lib/asciidoctor/reader.rb:137:in `peek_line'
	 ... 9343 levels...
	from /home/guillaume/.rvm/gems/ruby-3.1.2/bin/asciidoctor:25:in `load'
	from /home/guillaume/.rvm/gems/ruby-3.1.2/bin/asciidoctor:25:in `<main>'
	from /home/guillaume/.rvm/gems/ruby-3.1.2/bin/ruby_executable_hooks:22:in `eval'
	from /home/guillaume/.rvm/gems/ruby-3.1.2/bin/ruby_executable_hooks:22:in `<main>'

And we get more or less the same error in Asciidoctor.js:

/home/guillaume/.npm/_npx/e386896ea5de8ec0/node_modules/asciidoctor-opal-runtime/src/opal.js:6995
      $post_args = Opal.slice.call(arguments, 0, arguments.length);
                              ^

RangeError: Maximum call stack size exceeded
    at Arguments.slice (<anonymous>)
    at String.$String_end_with$ques$32 (/home/guillaume/.npm/_npx/e386896ea5de8ec0/node_modules/asciidoctor-opal-runtime/src/opal.js:6995:31)
    at constructor.$$process_line (/home/guillaume/.npm/_npx/e386896ea5de8ec0/node_modules/@asciidoctor/core/dist/node/asciidoctor.js:14119:67)
    at constructor.$$peek_line (/home/guillaume/.npm/_npx/e386896ea5de8ec0/node_modules/@asciidoctor/core/dist/node/asciidoctor.js:13331:37)
    at Opal.send (/home/guillaume/.npm/_npx/e386896ea5de8ec0/node_modules/asciidoctor-opal-runtime/src/opal.js:1671:19)
    at constructor.$$peek_line (/home/guillaume/.npm/_npx/e386896ea5de8ec0/node_modules/@asciidoctor/core/dist/node/asciidoctor.js:13894:29)
    at constructor.$$peek_line (/home/guillaume/.npm/_npx/e386896ea5de8ec0/node_modules/@asciidoctor/core/dist/node/asciidoctor.js:13331:87)
    at Opal.send (/home/guillaume/.npm/_npx/e386896ea5de8ec0/node_modules/asciidoctor-opal-runtime/src/opal.js:1671:19)
    at constructor.$$peek_line (/home/guillaume/.npm/_npx/e386896ea5de8ec0/node_modules/@asciidoctor/core/dist/node/asciidoctor.js:13894:29)
    at constructor.$$peek_line (/home/guillaume/.npm/_npx/e386896ea5de8ec0/node_modules/@asciidoctor/core/dist/node/asciidoctor.js:13331:87)

@ggrossetie ggrossetie added the bug label Oct 15, 2022
@mojavelinux
Copy link
Member

If I try that document with Asciidoctor (core), I don't see any problems. Can you submit a test to demonstrate the problem? And if so, do you have any idea why it might be happening (if it is happening in core?).

@ggrossetie
Copy link
Member

Add a few thousand lines in the ifeval block, you should be able to reproduce it using Ruby 3.1.2 and Asciidoctor 2.0.17. I think GitHub will prevent me from adding a comment with such file.

@ggrossetie
Copy link
Member

test.txt

$ asciidoctor -v
Asciidoctor 2.0.17 [https://asciidoctor.org]
Runtime Environment (ruby 3.1.2p20 (2022-04-12 revision 4491bb740a) [x86_64-linux]) (lc:UTF-8 fs:UTF-8 in:UTF-8 ex:UTF-8)

$ asciidoctor --trace test.txt
/home/guillaume/.rvm/gems/ruby-3.1.2/gems/asciidoctor-2.0.17/lib/asciidoctor/reader.rb:763:in `shift': stack level too deep (SystemStackError)
	from /home/guillaume/.rvm/gems/ruby-3.1.2/gems/asciidoctor-2.0.17/lib/asciidoctor/reader.rb:866:in `process_line'
	from /home/guillaume/.rvm/gems/ruby-3.1.2/gems/asciidoctor-2.0.17/lib/asciidoctor/reader.rb:137:in `peek_line'
	from /home/guillaume/.rvm/gems/ruby-3.1.2/gems/asciidoctor-2.0.17/lib/asciidoctor/reader.rb:652:in `peek_line'
	from /home/guillaume/.rvm/gems/ruby-3.1.2/gems/asciidoctor-2.0.17/lib/asciidoctor/reader.rb:137:in `peek_line'
	from /home/guillaume/.rvm/gems/ruby-3.1.2/gems/asciidoctor-2.0.17/lib/asciidoctor/reader.rb:652:in `peek_line'
	from /home/guillaume/.rvm/gems/ruby-3.1.2/gems/asciidoctor-2.0.17/lib/asciidoctor/reader.rb:137:in `peek_line'
	from /home/guillaume/.rvm/gems/ruby-3.1.2/gems/asciidoctor-2.0.17/lib/asciidoctor/reader.rb:652:in `peek_line'
	from /home/guillaume/.rvm/gems/ruby-3.1.2/gems/asciidoctor-2.0.17/lib/asciidoctor/reader.rb:137:in `peek_line'
	 ... 9343 levels...
	from /home/guillaume/.rvm/gems/ruby-3.1.2/bin/asciidoctor:25:in `load'
	from /home/guillaume/.rvm/gems/ruby-3.1.2/bin/asciidoctor:25:in `<main>'
	from /home/guillaume/.rvm/gems/ruby-3.1.2/bin/ruby_executable_hooks:22:in `eval'
	from /home/guillaume/.rvm/gems/ruby-3.1.2/bin/ruby_executable_hooks:22:in `<main>'

@ggrossetie
Copy link
Member

do you have any idea why it might be happening

I believe this is the recursive call between peek_line methods that produces a huge stack.

@mojavelinux
Copy link
Member

Okay, I see it now. If the contents of the ifeval is big enough, we hit the stack level depth limit in Ruby.

This seems to be one of those academic problems that would never happen in the real world. And we are able to rely on the interpreter to prevent abuse if this is the result of an attack. We expect it to fail because it is asking the program to do something unreasonable.

@mojavelinux
Copy link
Member

FYI, the exact number of lines it fails in Ruby 3.2.1 is 4666.

@mojavelinux
Copy link
Member

Okay, I understand what's going on. To find the next line to process, the reader uses recursion. There are recursion limits in Ruby. Hence why we run out of stack.

The fix (I think) would be to switch to a while loop in the case that process_line returns nil. That would short-circuit the recursive calls and allow the reader to find the next line to process.

@ggrossetie
Copy link
Member

FYI, the exact number of lines it fails in Ruby 3.2.1 is 4666.

(4)666 😈 😈 😈 😈

@ahus1
Copy link
Contributor Author

ahus1 commented Oct 15, 2022

Thank you @Mogztter for creating a snippet to reproduce it! I assume this is happening to a user when editing a document with a non-closing ifeval ... most of them will be non-closing while you're still typing them in your IDE.

@mojavelinux
Copy link
Member

It's not about whether ifeval is open or closed. The logic the processor uses to find the next line to process is recursive. And there are recursive limits in Ruby. (We've actually hit this before). The user was pushing the processor to the extreme because it can only happen if they had more than 4666 lines inside the ifeval.

@mojavelinux
Copy link
Member

...but I see what you're saying. If you open a very large document, then add ifeval at the top, then it's like you've enclosed the whole document in ifeval. So it's more likely to happen while editing then in the finished document.

I'm going to take a shot at unwrapping this recursive call. But if someone else has an idea, then please give it a go.

mojavelinux added a commit to mojavelinux/asciidoctor that referenced this issue Oct 17, 2022
@mojavelinux
resolves asciidoctor#4368 redo loop rather than using recursion to lo…
0c7aa83 
…cate next line to process
@mojavelinux
Copy link
Member

So the situation is that the stack limit equates to the number of lines Asciidoctor can process in a preprocessor conditional that evaluates to false. The mistake was to use recursion for this scenario. I have submitted a proposed change to replays the current loop until a line is found, thus avoiding the overhead of a stack.

mojavelinux added a commit to mojavelinux/asciidoctor that referenced this issue Oct 18, 2022
@mojavelinux
resolves asciidoctor#4368 redo loop rather than using recursion to lo…
ba75fbb 
…cate next line to process
@mojavelinux mojavelinux self-assigned this Oct 20, 2022
@mojavelinux mojavelinux modified the milestones: v2.0.x, v2.1.x Oct 20, 2022
mojavelinux added a commit to mojavelinux/asciidoctor that referenced this issue Oct 21, 2022
@mojavelinux
resolves asciidoctor#4368 redo loop rather than using recursion to lo…
1749920 
…cate next line to process
mojavelinux added a commit to mojavelinux/asciidoctor that referenced this issue Oct 21, 2022
@mojavelinux
resolves asciidoctor#4368 redo loop rather than using recursion to lo…
fd422d5 
…cate next line to process
@mojavelinux
Copy link
Member

Thanks @ahus1 for making us aware of this problem and thanks to @Mogztter for demonstrating how it can be reproduced. Nice team work!

mojavelinux added a commit that referenced this issue Apr 18, 2023
@mojavelinux
backport fix for #4368 use while loop rather than recursion to locate…
5625ad9 
… next line to process
@mojavelinux mojavelinux modified the milestones: v2.1.x, v2.0.x Apr 18, 2023
@mojavelinux mojavelinux added the v2.0.19 Issues resolved in the 2.0.19 release label Apr 18, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@mojavelinux mojavelinux

Labels
bug v2.0.19 Issues resolved in the 2.0.19 release
Projects
None yet
Milestone
v2.0.x
Development

No branches or pull requests
3 participants
@mojavelinux @ggrossetie @ahus1