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.

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

Possible incompatibility with Sorcerer in 9.1.9.0 + 9.1.10.0 #4629

Closed
aviflax opened this Issue May 26, 2017 · 17 comments

Comments

Projects
None yet
3 participants
@aviflax

aviflax commented May 26, 2017

Environment

Provide at least:

  • JRuby version:
    • jruby 9.1.10.0 (2.3.3) 2017-05-25 b09c48a Java HotSpot(TM) 64-Bit Server VM 25.131-b11 on 1.8.0_131-b11 +jit [darwin-x86_64]
  • Operating system and platform:
    • Darwin Avis-Imprudence.local 16.6.0 Darwin Kernel Version 16.6.0: Fri Apr 14 16:21:16 PDT 2017; root:xnu-3789.60.24~6/RELEASE_X86_64 x86_64

Description

I’m having a problem with JRuby 9.1.9.0 and 9.1.10.0; when I run my test suite, I get a bunch of output like this before my tests run:

syntax error, unexpected end-of-file

irrecoverable syntax error at end-of-file
Exception `Sorcerer::Resource::NotSexpError' at /Users/pavi/.rbenv/versions/jruby-9.1.10.0/lib/ruby/gems/shared/gems/sorcerer-1.0.2/lib/sorcerer/resource.rb:77 - Not an S-EXPER: nil
syntax error, unexpected end-of-file

…I might get 8 or 9 of these print out if I run a small test file, and ~100 if I run my entire test suite.

Clearly the exception is happening in Sorcerer, and looking at my Gemfile.lock it’s clear that Sorcerer is being used by given_core which is used by minitest-given — together those two gems provide the testing DSL I’m using and adapt the DSL to minitest, which I’m using to run the tests.

The thing is, none of these gems have changed for a good while. The most recent change was to given_core which I upgraded in my project back in early March. So it seems that the cause of the problem is some change in JRuby, in either 9.1.9.0 or 9.1.10.0, as when I run my test suite with the same exact code and the same exact Gemfile.lock and everything, but on JRuby 9.1.8.0 or 9.1.7.0, I don’t see this output. (In fact my project has used every version of JRuby since 9.0.5.0 — I try to keep up with releases — and this is the first time I’ve seen this problem.)

I apologize I can’t supply any test code to reproduce; I’m hoping the stack trace above might be enough of a clue to at least start looking into this.

(Any chance this might be related to #4574?)

Thank you!

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius May 28, 2017

Member

So these errors are not breaking your suite, is that correct?

Unfortunately the trace you provided is too general for us to really figure this out. It may be related to #4574 or it may not.

It's possible we "fixed" something that was swallowing error output and now it shows up. It's possible there's actually a bug we introduced. I'm not sure.

Member

headius commented May 28, 2017

So these errors are not breaking your suite, is that correct?

Unfortunately the trace you provided is too general for us to really figure this out. It may be related to #4574 or it may not.

It's possible we "fixed" something that was swallowing error output and now it shows up. It's possible there's actually a bug we introduced. I'm not sure.

@aviflax

This comment has been minimized.

Show comment
Hide comment
@aviflax

aviflax May 30, 2017

So these errors are not breaking your suite, is that correct?

Correct. But they just make me worry about some possible regression somewhere that’s breaking something that I don’t have proper test coverage of.

Unfortunately the trace you provided is too general for us to really figure this out. It may be related to #4574 or it may not.

I’ve tried to create a small isolated test file that would reproduce the problem but so far I’ve had no success.

But I have been able to produce a full stack trace:

Full stack trace
/Users/pavi/.rbenv/versions/jruby-9.1.10.0/lib/ruby/gems/shared/gems/sorcerer-1.0.2/lib/sorcerer/resource.rb:77:in `resource'
	/Users/pavi/.rbenv/versions/jruby-9.1.10.0/lib/ruby/gems/shared/gems/sorcerer-1.0.2/lib/sorcerer/resource.rb:35:in `source'
	/Users/pavi/.rbenv/versions/jruby-9.1.10.0/lib/ruby/gems/shared/gems/sorcerer-1.0.2/lib/sorcerer.rb:4:in `source'
	/Users/pavi/.rbenv/versions/jruby-9.1.10.0/lib/ruby/gems/shared/gems/given_core-3.8.0/lib/given/line_extractor.rb:36:in `complete_sexp?'
	/Users/pavi/.rbenv/versions/jruby-9.1.10.0/lib/ruby/gems/shared/gems/given_core-3.8.0/lib/given/line_extractor.rb:32:in `incomplete?'
	/Users/pavi/.rbenv/versions/jruby-9.1.10.0/lib/ruby/gems/shared/gems/given_core-3.8.0/lib/given/line_extractor.rb:26:in `extract_lines_from'
	/Users/pavi/.rbenv/versions/jruby-9.1.10.0/lib/ruby/gems/shared/gems/given_core-3.8.0/lib/given/line_extractor.rb:12:in `line'
	/Users/pavi/.rbenv/versions/jruby-9.1.10.0/lib/ruby/gems/shared/gems/given_core-3.8.0/lib/given/extensions.rb:255:in `Then'
	test/unit/test_data_services.rb:62:in `block in (root)'
	org/jruby/RubyModule.java:2833:in `module_eval'
	/Users/pavi/.rbenv/versions/jruby-9.1.10.0/lib/ruby/gems/shared/gems/minitest-5.10.2/lib/minitest/spec.rb:83:in `describe'
	test/unit/test_data_services.rb:60:in `block in (root)'
	org/jruby/RubyModule.java:2833:in `module_eval'
	/Users/pavi/.rbenv/versions/jruby-9.1.10.0/lib/ruby/gems/shared/gems/minitest-5.10.2/lib/minitest/spec.rb:83:in `describe'
	test/unit/test_data_services.rb:57:in `block in (root)'
	org/jruby/RubyModule.java:2833:in `module_eval'
	/Users/pavi/.rbenv/versions/jruby-9.1.10.0/lib/ruby/gems/shared/gems/minitest-5.10.2/lib/minitest/spec.rb:83:in `describe'
	test/unit/test_data_services.rb:56:in `block in (root)'
	org/jruby/RubyModule.java:2833:in `module_eval'
	/Users/pavi/.rbenv/versions/jruby-9.1.10.0/lib/ruby/gems/shared/gems/minitest-5.10.2/lib/minitest/spec.rb:83:in `describe'
	test/unit/test_data_services.rb:11:in `<main>'

Does that help?

aviflax commented May 30, 2017

So these errors are not breaking your suite, is that correct?

Correct. But they just make me worry about some possible regression somewhere that’s breaking something that I don’t have proper test coverage of.

Unfortunately the trace you provided is too general for us to really figure this out. It may be related to #4574 or it may not.

I’ve tried to create a small isolated test file that would reproduce the problem but so far I’ve had no success.

But I have been able to produce a full stack trace:

Full stack trace
/Users/pavi/.rbenv/versions/jruby-9.1.10.0/lib/ruby/gems/shared/gems/sorcerer-1.0.2/lib/sorcerer/resource.rb:77:in `resource'
	/Users/pavi/.rbenv/versions/jruby-9.1.10.0/lib/ruby/gems/shared/gems/sorcerer-1.0.2/lib/sorcerer/resource.rb:35:in `source'
	/Users/pavi/.rbenv/versions/jruby-9.1.10.0/lib/ruby/gems/shared/gems/sorcerer-1.0.2/lib/sorcerer.rb:4:in `source'
	/Users/pavi/.rbenv/versions/jruby-9.1.10.0/lib/ruby/gems/shared/gems/given_core-3.8.0/lib/given/line_extractor.rb:36:in `complete_sexp?'
	/Users/pavi/.rbenv/versions/jruby-9.1.10.0/lib/ruby/gems/shared/gems/given_core-3.8.0/lib/given/line_extractor.rb:32:in `incomplete?'
	/Users/pavi/.rbenv/versions/jruby-9.1.10.0/lib/ruby/gems/shared/gems/given_core-3.8.0/lib/given/line_extractor.rb:26:in `extract_lines_from'
	/Users/pavi/.rbenv/versions/jruby-9.1.10.0/lib/ruby/gems/shared/gems/given_core-3.8.0/lib/given/line_extractor.rb:12:in `line'
	/Users/pavi/.rbenv/versions/jruby-9.1.10.0/lib/ruby/gems/shared/gems/given_core-3.8.0/lib/given/extensions.rb:255:in `Then'
	test/unit/test_data_services.rb:62:in `block in (root)'
	org/jruby/RubyModule.java:2833:in `module_eval'
	/Users/pavi/.rbenv/versions/jruby-9.1.10.0/lib/ruby/gems/shared/gems/minitest-5.10.2/lib/minitest/spec.rb:83:in `describe'
	test/unit/test_data_services.rb:60:in `block in (root)'
	org/jruby/RubyModule.java:2833:in `module_eval'
	/Users/pavi/.rbenv/versions/jruby-9.1.10.0/lib/ruby/gems/shared/gems/minitest-5.10.2/lib/minitest/spec.rb:83:in `describe'
	test/unit/test_data_services.rb:57:in `block in (root)'
	org/jruby/RubyModule.java:2833:in `module_eval'
	/Users/pavi/.rbenv/versions/jruby-9.1.10.0/lib/ruby/gems/shared/gems/minitest-5.10.2/lib/minitest/spec.rb:83:in `describe'
	test/unit/test_data_services.rb:56:in `block in (root)'
	org/jruby/RubyModule.java:2833:in `module_eval'
	/Users/pavi/.rbenv/versions/jruby-9.1.10.0/lib/ruby/gems/shared/gems/minitest-5.10.2/lib/minitest/spec.rb:83:in `describe'
	test/unit/test_data_services.rb:11:in `<main>'

Does that help?

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius May 30, 2017

Member

It helps, but you might be able to do more digging that would help more. It looks like at that point in the code, the @sexp is nil. If you can trace back to where that nil comes in (someone constructing this Resource object with a nil sexp somewhere else) we can get closer to the root.

My guess is that there's something about the source processing this does that fails on JRuby, but instead of a hard error it's propagating a nil s-expression this far, and so we get the trace you provided. Unfortunately that doesn't show us how the nil sexp is getting created. Hopefully you can track that down with a little debugging.

Member

headius commented May 30, 2017

It helps, but you might be able to do more digging that would help more. It looks like at that point in the code, the @sexp is nil. If you can trace back to where that nil comes in (someone constructing this Resource object with a nil sexp somewhere else) we can get closer to the root.

My guess is that there's something about the source processing this does that fails on JRuby, but instead of a hard error it's propagating a nil s-expression this far, and so we get the trace you provided. Unfortunately that doesn't show us how the nil sexp is getting created. Hopefully you can track that down with a little debugging.

@aviflax

This comment has been minimized.

Show comment
Hide comment
@aviflax

aviflax Jun 14, 2017

The issue is still present in 9.1.11.0. I hope to do some deeper debugging soon.

aviflax commented Jun 14, 2017

The issue is still present in 9.1.11.0. I hope to do some deeper debugging soon.

@aviflax

This comment has been minimized.

Show comment
Hide comment
@aviflax

aviflax Jun 14, 2017

I just noticed another difference in the outcomes when running my test suite.

With JRuby 9.1.8.0:

  • all my tests pass
  • I get none of that error output from Sorcerer
  • SimpleCov reports 98.56% coverage

With 9.1.9.0–9.1.11.0:

  • all my tests pass
  • I do get that error output from Sorcerer
  • SimpleCov reports 81.82% coverage
    • It also highlights, as it’s configured to do, that coverage on one of my source files in particular has dropped below my minimum threshold.
    • So comparing the coverage reports for that file on the different versions of JRuby might give me a pointer to what’s going on.

aviflax commented Jun 14, 2017

I just noticed another difference in the outcomes when running my test suite.

With JRuby 9.1.8.0:

  • all my tests pass
  • I get none of that error output from Sorcerer
  • SimpleCov reports 98.56% coverage

With 9.1.9.0–9.1.11.0:

  • all my tests pass
  • I do get that error output from Sorcerer
  • SimpleCov reports 81.82% coverage
    • It also highlights, as it’s configured to do, that coverage on one of my source files in particular has dropped below my minimum threshold.
    • So comparing the coverage reports for that file on the different versions of JRuby might give me a pointer to what’s going on.
@enebo

This comment has been minimized.

Show comment
Hide comment
@enebo

enebo Jun 14, 2017

Member

@aviflax yeah doubly interesting that I made 2 changes in line output for source between .10 and .11 but your coverage didn't change. They should not have been visible changes in this regard (one was an optimization and one was a correctness fix for uncommon syntax) but still happy to not see those cloud your problem more.

Let us know when you find out more and we will help as we can...

Member

enebo commented Jun 14, 2017

@aviflax yeah doubly interesting that I made 2 changes in line output for source between .10 and .11 but your coverage didn't change. They should not have been visible changes in this regard (one was an optimization and one was a correctness fix for uncommon syntax) but still happy to not see those cloud your problem more.

Let us know when you find out more and we will help as we can...

@aviflax

This comment has been minimized.

Show comment
Hide comment
@aviflax

aviflax Jun 14, 2017

Hmm well I’m not sure I directly and specifically compared the coverage numbers between .10 and .11… I think I just assumed that .9, .10, and .11 were all the same — let me check… OK, I just ran the suite on .10 and got a different result: 96.09%.

So, to summarize:

Version Coverage
.8 98.56%
.9 96.09%
.10 96.09%
.11 95.26%

And it looks like I made an error when above I reported coverage of 81.82% for .11 — that’s actually the coverage level for that specific file that Simplecov reported had dropped below the threshold. My minimum threshold is 90%, so this means that on .8 this file (which just defines a bunch of contracts using Contracts.ruby) has >= 90% coverage while on .11 it has 81.82%.

FWIW… I’m really not sure what this means. HTH!

aviflax commented Jun 14, 2017

Hmm well I’m not sure I directly and specifically compared the coverage numbers between .10 and .11… I think I just assumed that .9, .10, and .11 were all the same — let me check… OK, I just ran the suite on .10 and got a different result: 96.09%.

So, to summarize:

Version Coverage
.8 98.56%
.9 96.09%
.10 96.09%
.11 95.26%

And it looks like I made an error when above I reported coverage of 81.82% for .11 — that’s actually the coverage level for that specific file that Simplecov reported had dropped below the threshold. My minimum threshold is 90%, so this means that on .8 this file (which just defines a bunch of contracts using Contracts.ruby) has >= 90% coverage while on .11 it has 81.82%.

FWIW… I’m really not sure what this means. HTH!

@enebo

This comment has been minimized.

Show comment
Hide comment
@enebo

enebo Jun 14, 2017

Member

@aviflax thanks for the data. The specific fix for .11 was that when we had an fcall ('foo' not 'b.foo') and its arguments spanned lines we would erroneously say the fcall happened on the line of its last argument and not the line where 'foo' is. I would have thought if anything this would have increased coverage since we are generating more line info than before not less?

I do wonder if my optimization maybe is the issue. If we had a case where we had n lines of consecutive line_num instrs we would only emit the last one since no exception could trigger until after that sequence. The problem with this logic is our line_num and trace instrs are tied to the same logic so perhaps I still need to emit n trace instrs so coverage reports empty lines are doing something? I guess I will need to look into that.

Member

enebo commented Jun 14, 2017

@aviflax thanks for the data. The specific fix for .11 was that when we had an fcall ('foo' not 'b.foo') and its arguments spanned lines we would erroneously say the fcall happened on the line of its last argument and not the line where 'foo' is. I would have thought if anything this would have increased coverage since we are generating more line info than before not less?

I do wonder if my optimization maybe is the issue. If we had a case where we had n lines of consecutive line_num instrs we would only emit the last one since no exception could trigger until after that sequence. The problem with this logic is our line_num and trace instrs are tied to the same logic so perhaps I still need to emit n trace instrs so coverage reports empty lines are doing something? I guess I will need to look into that.

@aviflax

This comment has been minimized.

Show comment
Hide comment
@aviflax

aviflax Jun 14, 2017

Glad to be of some help. This is all a bit over my head but I would love to help however I can to get to the bottom of this issue (the symptom being the nil passed into Sorcerer and/or the error message that either doesn’t happen in .8 or is suppressed in .8 — this is not yet clear) so I can have enough confidence in recent releases to upgrade. I count ~70 fixes so far post .8 so I’m eager to upgrade!

aviflax commented Jun 14, 2017

Glad to be of some help. This is all a bit over my head but I would love to help however I can to get to the bottom of this issue (the symptom being the nil passed into Sorcerer and/or the error message that either doesn’t happen in .8 or is suppressed in .8 — this is not yet clear) so I can have enough confidence in recent releases to upgrade. I count ~70 fixes so far post .8 so I’m eager to upgrade!

@enebo

This comment has been minimized.

Show comment
Hide comment
@enebo

enebo Jun 14, 2017

Member

@aviflax yeah the coverage numbers and the nil are likely to be unrelated but since you mentioned the numbers it will make me look at that part a bit closer since it is something I can examine. If you can isolate the nil issue a bit more we can tackle that.

Member

enebo commented Jun 14, 2017

@aviflax yeah the coverage numbers and the nil are likely to be unrelated but since you mentioned the numbers it will make me look at that part a bit closer since it is something I can examine. If you can isolate the nil issue a bit more we can tackle that.

@aviflax

This comment has been minimized.

Show comment
Hide comment
@aviflax

aviflax Jul 5, 2017

I’ve made a little progress on the “syntax error, unexpected end-of-file” etc errors.

When I run this in irb:

require ‘ripper'
Ripper::SexpBuilder.new('Then do').parse

with JRuby 9.1.8.0, the second expression returns nil and nothing is printed

with JRuby 9.1.9.0–9.1.11.0, the second expression returns nil but the error message is printed:

~/dev/my_project $ irb
irb(main):001:0> require 'ripper'
=> true
irb(main):002:0> Ripper::SexpBuilder.new('Then do').parse
syntax error, unexpected end-of-file

irrecoverable syntax error at end-of-file
=> nil
irb(main):003:0> 

So… I don’t want to jump to conclusions, but since Ripper is part of the Ruby stdlib rather than a third-party dependency, I would think that this difference in behavior would have to be caused by some change in JRuby — a change that was first released in 9.1.9.0.

Is that maybe enough to go on to investigate this further?

Thanks!

aviflax commented Jul 5, 2017

I’ve made a little progress on the “syntax error, unexpected end-of-file” etc errors.

When I run this in irb:

require ‘ripper'
Ripper::SexpBuilder.new('Then do').parse

with JRuby 9.1.8.0, the second expression returns nil and nothing is printed

with JRuby 9.1.9.0–9.1.11.0, the second expression returns nil but the error message is printed:

~/dev/my_project $ irb
irb(main):001:0> require 'ripper'
=> true
irb(main):002:0> Ripper::SexpBuilder.new('Then do').parse
syntax error, unexpected end-of-file

irrecoverable syntax error at end-of-file
=> nil
irb(main):003:0> 

So… I don’t want to jump to conclusions, but since Ripper is part of the Ruby stdlib rather than a third-party dependency, I would think that this difference in behavior would have to be caused by some change in JRuby — a change that was first released in 9.1.9.0.

Is that maybe enough to go on to investigate this further?

Thanks!

@enebo

This comment has been minimized.

Show comment
Hide comment
@enebo

enebo Jul 6, 2017

Member

@aviflax cool! Yeah this should help

Member

enebo commented Jul 6, 2017

@aviflax cool! Yeah this should help

@aviflax

This comment has been minimized.

Show comment
Hide comment
@aviflax

aviflax Jul 14, 2017

Sorry to be a bother, but I’m just wondering if there’s any chance this Ripper behavior might be investigated any time soon? I’m eager to get my app back on the latest JRuby… thanks!

aviflax commented Jul 14, 2017

Sorry to be a bother, but I’m just wondering if there’s any chance this Ripper behavior might be investigated any time soon? I’m eager to get my app back on the latest JRuby… thanks!

@enebo enebo added this to the JRuby 9.1.13.0 milestone Aug 16, 2017

@enebo enebo closed this in 53748e3 Aug 16, 2017

enebo added a commit that referenced this issue Aug 16, 2017

Fixes #4629. Possible incompatibility with Sorcerer in 9.1.9.0 + 9.1.…
…10.0.

I am a big dope.  Errant println removed!

@enebo enebo added the regression label Aug 16, 2017

@enebo

This comment has been minimized.

Show comment
Hide comment
@enebo

enebo Aug 16, 2017

Member

@aviflax Can you verify you see no more poor output? I feel fairly embarrassed that I had an errant println I was using for debugging in there. So that explains the mysterious output (which only occurred in some syntax error scenarios).

Member

enebo commented Aug 16, 2017

@aviflax Can you verify you see no more poor output? I feel fairly embarrassed that I had an errant println I was using for debugging in there. So that explains the mysterious output (which only occurred in some syntax error scenarios).

@aviflax

This comment has been minimized.

Show comment
Hide comment
@aviflax

aviflax Aug 17, 2017

@enebo no worries — happens to the best of us! Thanks so much for following up! I’ll try to test today once I look into building JRuby from source.

aviflax commented Aug 17, 2017

@enebo no worries — happens to the best of us! Thanks so much for following up! I’ll try to test today once I look into building JRuby from source.

@enebo

This comment has been minimized.

Show comment
Hide comment
@enebo

enebo Aug 17, 2017

Member

@aviflax great. Just reopen with details if you find anything.

Member

enebo commented Aug 17, 2017

@aviflax great. Just reopen with details if you find anything.

@aviflax

This comment has been minimized.

Show comment
Hide comment
@aviflax

aviflax Aug 17, 2017

Looking good! Thanks @enebo!

aviflax commented Aug 17, 2017

Looking good! Thanks @enebo!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment