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

Regression in 9.1.15.0 with some ensure blocks being executed twice #4895

Closed
jeremyevans opened this issue Dec 14, 2017 · 8 comments
Closed

Regression in 9.1.15.0 with some ensure blocks being executed twice #4895

jeremyevans opened this issue Dec 14, 2017 · 8 comments
Milestone
JRuby 9.1.16.0

Comments

@jeremyevans
Copy link
Contributor

Environment

jruby 9.1.15.0 (2.3.3) 2017-12-07 929fde8 OpenJDK 64-Bit Server VM 25.144-b01 on 1.8.0_144-b01 +jit [OpenBSD-x86_64]
OpenBSD testcurrent.bsa.ca.gov 6.2 GENERIC.MP#0 amd64

This example requires the sequel gem, as I have not been able to create a reproducible example that doesn't require it.

Expected Behavior

CRuby

$ ruby -v bin/sequel -E 'mock://postgres' -c "DB.transaction{DB.transaction(:savepoint=>true){raise}}"
ruby 2.4.2p198 (2017-09-14 revision 59899) [x86_64-openbsd]
/home/billg/sequel/lib/sequel/dataset/query.rb:84: warning: statement not reached
I, [2017-12-13T16:38:22.728394 #45752]  INFO -- : (0.000011s) BEGIN
I, [2017-12-13T16:38:22.730132 #45752]  INFO -- : (0.000008s) SAVEPOINT autopoint_1
I, [2017-12-13T16:38:22.730787 #45752]  INFO -- : (0.000007s) ROLLBACK TO SAVEPOINT autopoint_1
I, [2017-12-13T16:38:22.732320 #45752]  INFO -- : (0.000007s) ROLLBACK
Error: RuntimeError: (eval):1:in `block (2 levels) in <main>'
bin/sequel:234:in `eval'

JRuby 9.1.14.0

$ jruby -v bin/sequel -E 'mock://postgres' -c "DB.transaction{DB.transaction(:savepoint=>true){raise}}"
jruby 9.1.14.0 (2.3.3) 2017-11-08 2176f24 OpenJDK 64-Bit Server VM 25.144-b01 on 1.8.0_144-b01 +jit [OpenBSD-x86_64]
/home/billg/sequel/lib/sequel/dataset/query.rb:84: warning: statement not reached
I, [2017-12-13T16:43:28.752250 #1564]  INFO -- : (0.004420s) BEGIN
I, [2017-12-13T16:43:28.760987 #1564]  INFO -- : (0.000206s) SAVEPOINT autopoint_1
I, [2017-12-13T16:43:28.762779 #1564]  INFO -- : (0.000184s) ROLLBACK TO SAVEPOINT autopoint_1
I, [2017-12-13T16:43:28.765266 #1564]  INFO -- : (0.000187s) ROLLBACK
Error: RuntimeError:
(eval):1:in `block in (root)'

Actual Behavior

JRuby 9.1.15.0

$ jruby -v bin/sequel -E 'mock://postgres' -c "DB.transaction{DB.transaction(:savepoint=>true){raise}}"
jruby 9.1.15.0 (2.3.3) 2017-12-07 929fde8 OpenJDK 64-Bit Server VM 25.144-b01 on 1.8.0_144-b01 +jit [OpenBSD-x86_64]
2017-12-13T16:38:28.468-08:00 [main] WARN Ruby : Warning: not setting network stack system property because socket subsystem may already be booted.If you need this option please set it manually as a JVM property.
Use JAVA_OPTS=-Djava.net.preferIPv4Stack=true OR prepend -J as a JRuby option.
/home/billg/sequel/lib/sequel/dataset/query.rb:84: warning: statement not reached
I, [2017-12-13T16:38:29.674784 #70824]  INFO -- : (0.003391s) BEGIN
I, [2017-12-13T16:38:29.683151 #70824]  INFO -- : (0.000193s) SAVEPOINT autopoint_1
I, [2017-12-13T16:38:29.684773 #70824]  INFO -- : (0.000179s) ROLLBACK TO SAVEPOINT autopoint_1
Error: NoMethodError: undefined method `[]' for nil:NilClass
/home/billg/sequel/lib/sequel/database/transactions.rb:420:in `savepoint_level'

To make sure it isn't an OpenBSD specific issue, I also tested on Windows:

>c:\jruby-9.1.15.0\bin\jruby -v bin\sequel -E 'mock://postgres' -c "DB.transaction{DB.transaction(:savepoint=>true){raise}}"
jruby 9.1.15.0 (2.3.3) 2017-12-07 929fde8 Java HotSpot(TM) 64-Bit Server VM 25.131-b11 on 1.8.0_131-b11 +jit [mswin32-x86_64]
L:/sequel/lib/sequel/dataset/query.rb:84: warning: statement not reached
I, [2017-12-13T16:48:30.526000 #10708]  INFO -- : (0.000000s) BEGIN
I, [2017-12-13T16:48:30.542000 #10708]  INFO -- : (0.000000s) SAVEPOINT autopoint_1
I, [2017-12-13T16:48:30.542000 #10708]  INFO -- : (0.000000s) ROLLBACK TO SAVEPOINT autopoint_1
Error: NoMethodError: undefined method `[]' for nil:NilClass
L:/sequel/lib/sequel/database/transactions.rb:420:in `savepoint_level'

From some puts debugging I have found that an ensure block (https://github.com/jeremyevans/sequel/blob/5.3.0/lib/sequel/database/transactions.rb#L227) is being executed twice during the same method call when it should only be executed once.

This bug breaks Sequel when trying to use savepoints with JRuby 9.1.15.0.
@enebo enebo added this to the JRuby 9.1.16.0 milestone Dec 14, 2017
@enebo
Copy link
Member

enebo commented Dec 14, 2017

@jeremyevans and this definitely was not also broken for 9.1.14.0? When we process ensures we duplicate their bodies on each exception path internally and this bug looks like we might be duplicating something which has duplicated ensure already :(

@jeremyevans
Copy link
Contributor Author

Yes, definitely sure it worked on 9.1.14.0, see the 2nd code block in the expected behavior section of the original report. I made sure to use -v so you can see the ruby version of each command ran.

@headius
Copy link
Member

headius commented Dec 14, 2017

Well at least we have a good place to start looking! I don't have pgsql set up on this machine at the moment, but it should be possible to bisect between 9.1.14 and 9.1.15 (only a hundred or so commits?).

@jeremyevans
Copy link
Contributor Author

No need to setup pgsql, I'm using the mock adapter that doesn't actually do a database connection. Just checking out the sequel repository or installing the sequel gem will be enough. This should reproduce with a gem install:

jruby -S gem install sequel
jruby -S sequel 'mock://postgres' -c "DB.transaction{DB.transaction(:savepoint=>true){raise}}"

@enebo
Copy link
Member

enebo commented Dec 14, 2017

I am guessing this nesting should just be extractable as a simple test case. Knowing we copy ensure block bodies makes guessing at the cause really easy :)

@enebo
Copy link
Member

enebo commented Jan 5, 2018 •
edited
Loading

NOTE: This is not actually a reproduction against master but against a local tree. I am leaving it as an illustration though since the description below is what must be happening (just not with this exact code).

Ok this is fallout from fixing #4865. Here is a reduced snippet:

  begin
    raise ArgumentError("DDDD")
  ensure
    begin
    ensure
      puts "EERRRRR"
    end
  end

This will print out EERRRRR twice. Tracing through execution the raise occurs goes to a reasonable rescue ip (fairly positive it is correct cloned contents of both ensures). Then it goes to a throw instr because we are done executing the ensure and it needs to raise out to the next outer method.............

HOWEVER, the rescuePC stack is dirty at this point because of the original raise (the raise jumps over an exc_end_region). So the interpreter catches the raise and then consults the dirty stack which then decides to go down a copy of the inner ensure. That finishes popping the stack and we exit having did an extra tour through the inner ensure.

@enebo
Copy link
Member

enebo commented Jan 5, 2018

One thought is since the first time that print displays we are in UNRESCUED_REGION we could just nuke the rescuepc stack at that point?

headius added a commit that referenced this issue Jan 9, 2018
@headius
Temporarily exclude tests failing due to rescue breakage. #4895
c4e7e5b
@enebo enebo closed this as completed in 2a26055 Jan 9, 2018
enebo added a commit that referenced this issue Jan 9, 2018
@enebo
Remove tests which work because of fix for #4895
0d7d15e
@enebo
Copy link
Member

enebo commented Jan 9, 2018

My commit message explains what changed and why I am reasonably confident about this fix. As an aside we basically did this new solution originally but instead of making a simple array of ints we would store it as a field on every instr (which was heavy enough we moved away from that). set on primitive array is quite a bit faster than a method call setting a field so this is no doubt quicker.

@flash-gordon flash-gordon mentioned this issue Feb 3, 2018
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
JRuby 9.1.16.0
Development

No branches or pull requests
3 participants
@jeremyevans @headius @enebo