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.

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:

/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?

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.

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

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 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...

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:

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 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.

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 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.

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 cool! Yeah this should help

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 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).

@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 great. Just reopen with details if you find anything.

Looking good! Thanks @enebo!