Internal transaction state corruption with latest jruby

[kalenp]

I'm working on a large project which is upgrading from JRuby 9.3 to 9.4. We are seeing some unexpected test failures and I'm trying to determine whether they are an issue with JRuby or Sequel, and also what sort of scenarios could lead to the result we're seeing.

The error we're getting is

NoMethodError: undefined method `[]' for nil:NilClass
    .gem/gems/sequel-5.86.0/lib/sequel/database/transactions.rb:227:in `block in transaction'
    .gem/gems/sequel-5.86.0/lib/sequel/connection_pool/threaded.rb:92:in `hold'
    .gem/gems/sequel-5.86.0/lib/sequel/database/connecting.rb:283:in `synchronize'
    .gem/gems/sequel-5.86.0/lib/sequel/database/transactions.rb:197:in `transaction'
    .gem/gems/sequel-5.86.0/lib/sequel/model/base.rb:1954:in `checked_transaction'
    .gem/gems/sequel-5.86.0/lib/sequel/model/base.rb:1500:in `block in save'
    .gem/gems/sequel-5.86.0/lib/sequel/model/base.rb:1940:in `checked_save_failure'
    .gem/gems/sequel-5.86.0/lib/sequel/model/base.rb:1500:in `save'
    ... (application code) ...

Looking at the source, it doesn't appear like this should be a valid state for Sequel to get into. Either _conn(trans) is nil, which shouldn't be because we've already checked already_in_transaction?, or the list of savepoints is empty. The second doesn't seem possible based on my reading, but is harder to verify.

Do you have any insight as to whether this is a legit bug in Sequel (eg. empty savepoints list due to missed locking or incorrect error handling) or might we be looking at a JRuby issue, since we didn't see this before upgrading to 9.4. We thought this might be related to jruby/jruby#8585, but we're testing with the latest version which includes a fix for this issue.

[jeremyevans]

This shouldn't happen. As you pointed out, Sequel already checks _trans(conn) in already_in_transaction?, so the only explanation is something is deleting the conn entry from the Database's @transactions between the two calls. @transactions is a compare by identity hash, so that should rule out connection objects that are not identical but compare equal. I assume if you had the situation where two separate threads were issued the same connection object (which could also explain this), you would have much larger issues than this.

If this is reproducible on JRuby 9.4 but not on JRuby 9.3, with the same Sequel version, I would suspect a bug in JRuby. If you have an self-contained example that reproduces for you, I'll definitely examine it and see if I can reproduce the issue. If this is an issue with Sequel, be assured it will be fixed with the highest priority.

[janko]

There is an open issue where the JRuby's database connection object wasn't considered identical with itself. So, when Sequel started using compare_by_identity for the transactions hash, that caused a regression. However, I experienced this in sequel-activerecord_connection, and the bug only seemed to have manifested when combined with activerecord-jdbc-adapter, which is of course not the case when using Sequel directly.

Anyway, I just wanted to post it here in case it's a possible lead. I would recommend at least trying to turn off compare_by_identity, and seeing if you're still getting the error:

DB.instance_variable_set(:@transactions, {})

[jeremyevans]

Thanks for posting that. That would definitely explain the issue, and certainly appears to be a JRuby (or possibly activerecord-jdbc-adapter) bug.

@kalenp Are you using activerecord-jdbc-adapter by chance?

[jeremyevans]

I've decided to add a :compare_connections_by_identity Database option so you can disable the use of compare_by_identity on the transactions hash to work around this issue. It will be in tomorrow's release.

[kalenp]

Thanks for the pointer on the other issue. Unfortunately, it doesn't appear to be what I'm running into. I have caught this in a debugger (after it raises) and _stack is an empty array, so it's _stack.last[:auto_savepoint] which is raising. We're not using activerecord-jdbc-adapter and looking at the connections managed in the ThreadedConnectionPool, it appears to be managing that correctly.

Since we aren't seeing this on JRuby 9.3, I'm working on the assumption that it's a JRuby issue at this point and am working with the maintainers there to see what we can come up with.

[headius]

@janko Thank you for bringing that issue back to mind! Having a second look at it now, I realized it may be related to the object wrappers that JRuby uses to allow Java objects to flow through Ruby code, and I have added a comment describing how to determine if this is actually the situation and what can be done to mitigate the issue: jruby/jruby#8224 (comment)

@kalenp @jeremyevans In this case, if this is the same root cause, it should be testable by reverting to the old logic using the JRuby setting I describe in my comment. If the key to any of these internal hashes is a Java object and the hash is comparing by identity, it very well could be the same issue. However, I would expect to see that hash fill up with several of these object wrappers rather than a suddenly empty when one of these references should be present.

[kalenp]

It looks like this is coming from our test fixtures which kill any background threads after the test has completed. When these background threads are running queries with Sequel, this can result in the internal state being corrupted. Since Thread.kill is generally discouraged, I don't expect this to be fully robust in the face of this behavior, but I did find a couple places where global state is temporarily inconsistent and can lead to problems if interrupted before it can sync itself up again.

The first is here: https://github.com/jeremyevans/sequel/blob/5.86.0/lib/sequel/database/transactions.rb#L455-L459 This causes the originally reported issue. transaction_finished? will pop the savepoint from the tranaction before the transaction is deleted from the @transactions array. If the thread is killed in this window, the transaction will remain in the array and the next time the connection is used, it will appear as though there is already a transaction in progress, but there are no savepoints associated with it.

The second is here: https://github.com/jeremyevans/sequel/blob/5.86.0/lib/sequel/connection_pool/threaded.rb#L212 In this case, the @allocated hash expects to map Thread -> Connection. But it may temporarily have the value true within it. I no longer have the exact backtrace for this one, but I believe that it later failed when calling close() on the connection, but it's actually true.close(), which of course doesn't exist.

It appears that both of these could be mitigated, and I was able to improve the robustness of my test case by tweaking them, but I wasn't sure if there were any unintended side effects from the changes. So just reporting the details here for your information in case you want to address them.

[headius]

Note that these problems would likely also affect CRuby, since even without parallel execution you can see thread interrupts happen at almost any time. The Ruby way to fix this would be liberal use of Thread.handle_interrupt, which allows disabling interrupts within a given scope, but it is a very difficult API to use correctly and can result in unkillable threads if not managed properly.

This is yet another example of why asynchronous Thread#kill and Thread#raise are inherently unsafe in Ruby.

[kalenp]

On our end, we've mitigated this by giving the background threads a chance to shutdown gracefully (checking status in the main event loop) and then only killing them after a timeout. This appears to have reduced the frequency of Thread#kill calls enough that it no longer blocks our CI. It's still a mystery to me why this occurred more with JRuby 9.4 vs 9.3 but as with any race condition, slight timing changes are everything.

[jeremyevans]

There is basically nothing you can do in Ruby to ensure correct behavior if you are using Thread#kill. If you are using Thread#kill in an application using Sequel, it's up to you to handle all necessary state cleanup caused by usage of killed thread. That being said, I'm willing to consider non-invasive changes to improve behavior in this case.

The connection pools should disconnect connections belonging to dead threads, it shouldn't issue them to other threads, since it checks Thread#alive?: https://github.com/jeremyevans/sequel/blob/5.86.0/lib/sequel/connection_pool/threaded.rb#L204 .

However, I think what happens is the connection is returned to the pool because the thread isn't dying immediately, it's still running through ensure blocks. Treating aborting threads as disconnect errors may possibly solve it. However, maybe that has issues. If the connection is currently in use when you call Thread#kill, trying to disconnect it could cause problems, potentially segfaults in CRuby depending on the database driver.

The true.close issue can probably be handled fairly easily, by checking where conn == true.

Can you try the following patch and let me know if it helps?

diff --git a/lib/sequel/connection_pool.rb b/lib/sequel/connection_pool.rb
index 6940eef9f..cedd15877 100644
--- a/lib/sequel/connection_pool.rb
+++ b/lib/sequel/connection_pool.rb
@@ -128,12 +128,12 @@ class Sequel::ConnectionPool
   # Remove the connection from the pool.  For threaded connections, this should be
   # called without the mutex, because the disconnection may block.
   def disconnect_connection(conn)
-    db.disconnect_connection(conn)
+    db.disconnect_connection(conn) unless conn == true
   end
 
   # Whether the given exception is a disconnect exception.
   def disconnect_error?(exception)
-    exception.is_a?(Sequel::DatabaseDisconnectError) || db.send(:disconnect_error?, exception, OPTS)
+    exception.is_a?(Sequel::DatabaseDisconnectError) || db.send(:disconnect_error?, exception, OPTS) || Thread.current.status == "aborting"
   end
   
   # Return a new connection by calling the connection proc with the given server name,