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
fix unhandledrejection for rollback of non managed transaction #3665
Conversation
Somehow connected with switches between bluebird <-> native promises |
Agreed, and I suspect that knex/test/integration/builder/additional.js Line 863 in 77df705
Both of these are implemented in terms of
|
lib/transaction.js
Outdated
@@ -195,7 +195,7 @@ class Transaction extends EventEmitter { | |||
|
|||
value = new Error(`Transaction rejected with non-error: ${value}`); | |||
} | |||
this._rejecter(value); | |||
setImmediate(() => this._rejecter(value)); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I just tried out your fix, but I'm still observing the problem within this test case:
knex/test/integration/builder/additional.js
Line 863 in 77df705
it('.timeout(ms, {cancel: true}) should throw error if cancellation cannot acquire connection', function() { |
Here's a sample of my output:
% DB="mysql mysql2" KNEX_TEST_TIMEOUT=60000 ./node_modules/.bin/mocha --exit -t 10000 test/index.js
sqlite does not support inserting default values. Set the `useNullAsDefault` flag to hide this warning. (see docs http://knexjs.org/#Builder-insert).
sqlite does not support inserting default values. Set the `useNullAsDefault` flag to hide this warning. (see docs http://knexjs.org/#Builder-insert).
sqlite does not support inserting default values. Set the `useNullAsDefault` flag to hide this warning. (see docs http://knexjs.org/#Builder-insert).
Integration Tests
mysql | mysql
Additional
Unhandled rejection: KnexTimeoutError: Knex: Timeout acquiring a connection. The pool is probably full. Are you missing a .transacting(trx) call?
at /Users/brianlauber/Documents/src/knex/lib/client.js:351:30
From previous event:
at Client_MySQL.acquireConnection (/Users/brianlauber/Documents/src/knex/lib/client.js:348:15)
at Client_MySQL.cancelQuery (/Users/brianlauber/Documents/src/knex/lib/dialects/mysql/index.js:175:32)
at /Users/brianlauber/Documents/src/knex/lib/runner.js:177:37
From previous event:
at Runner.query (/Users/brianlauber/Documents/src/knex/lib/runner.js:169:13)
at /Users/brianlauber/Documents/src/knex/lib/runner.js:41:23
at /Users/brianlauber/Documents/src/knex/lib/runner.js:261:24
From previous event:
at Runner.ensureConnection (/Users/brianlauber/Documents/src/knex/lib/runner.js:259:8)
at Runner.run (/Users/brianlauber/Documents/src/knex/lib/runner.js:27:12)
at Raw.Target.then (/Users/brianlauber/Documents/src/knex/lib/interface.js:15:43)
at Context.<anonymous> (/Users/brianlauber/Documents/src/knex/test/integration/builder/additional.js:908:10)
at callFn (/Users/brianlauber/Documents/src/knex/node_modules/mocha/lib/runnable.js:395:21)
at Test.Runnable.run (/Users/brianlauber/Documents/src/knex/node_modules/mocha/lib/runnable.js:382:7)
at Runner.runTest (/Users/brianlauber/Documents/src/knex/node_modules/mocha/lib/runner.js:541:10)
at /Users/brianlauber/Documents/src/knex/node_modules/mocha/lib/runner.js:667:12
at next (/Users/brianlauber/Documents/src/knex/node_modules/mocha/lib/runner.js:450:14)
at /Users/brianlauber/Documents/src/knex/node_modules/mocha/lib/runner.js:460:7
at next (/Users/brianlauber/Documents/src/knex/node_modules/mocha/lib/runner.js:362:14)
at Immediate.<anonymous> (/Users/brianlauber/Documents/src/knex/node_modules/mocha/lib/runner.js:428:5)
at processImmediate (internal/timers.js:439:21) {
name: 'KnexTimeoutError'
}
✓ .timeout(ms, {cancel: true}) should throw error if cancellation cannot acquire connection (5135ms)
mysql | mysql2
Additional
Unhandled rejection: KnexTimeoutError: Knex: Timeout acquiring a connection. The pool is probably full. Are you missing a .transacting(trx) call?
at /Users/brianlauber/Documents/src/knex/lib/client.js:351:30
From previous event:
at Client_MySQL2.acquireConnection (/Users/brianlauber/Documents/src/knex/lib/client.js:348:15)
at Client_MySQL2.cancelQuery (/Users/brianlauber/Documents/src/knex/lib/dialects/mysql/index.js:175:32)
at /Users/brianlauber/Documents/src/knex/lib/runner.js:177:37
From previous event:
at Runner.query (/Users/brianlauber/Documents/src/knex/lib/runner.js:169:13)
at /Users/brianlauber/Documents/src/knex/lib/runner.js:41:23
at /Users/brianlauber/Documents/src/knex/lib/runner.js:261:24
From previous event:
at Runner.ensureConnection (/Users/brianlauber/Documents/src/knex/lib/runner.js:259:8)
at Runner.run (/Users/brianlauber/Documents/src/knex/lib/runner.js:27:12)
at Raw.Target.then (/Users/brianlauber/Documents/src/knex/lib/interface.js:15:43)
at Context.<anonymous> (/Users/brianlauber/Documents/src/knex/test/integration/builder/additional.js:908:10)
at callFn (/Users/brianlauber/Documents/src/knex/node_modules/mocha/lib/runnable.js:395:21)
at Test.Runnable.run (/Users/brianlauber/Documents/src/knex/node_modules/mocha/lib/runnable.js:382:7)
at Runner.runTest (/Users/brianlauber/Documents/src/knex/node_modules/mocha/lib/runner.js:541:10)
at /Users/brianlauber/Documents/src/knex/node_modules/mocha/lib/runner.js:667:12
at next (/Users/brianlauber/Documents/src/knex/node_modules/mocha/lib/runner.js:450:14)
at /Users/brianlauber/Documents/src/knex/node_modules/mocha/lib/runner.js:460:7
at next (/Users/brianlauber/Documents/src/knex/node_modules/mocha/lib/runner.js:362:14)
at Immediate.<anonymous> (/Users/brianlauber/Documents/src/knex/node_modules/mocha/lib/runner.js:428:5)
at processImmediate (internal/timers.js:439:21) {
name: 'KnexTimeoutError'
}
✓ .timeout(ms, {cancel: true}) should throw error if cancellation cannot acquire connection (5125ms)
2 passing (10s)
Unhandled rejections: 2
{
reason: KnexTimeoutError: Knex: Timeout acquiring a connection. The pool is probably full. Are you missing a .transacting(trx) call?
at /Users/brianlauber/Documents/src/knex/lib/client.js:351:30
From previous event:
at Client_MySQL.acquireConnection (/Users/brianlauber/Documents/src/knex/lib/client.js:348:15)
at Client_MySQL.cancelQuery (/Users/brianlauber/Documents/src/knex/lib/dialects/mysql/index.js:175:32)
at /Users/brianlauber/Documents/src/knex/lib/runner.js:177:37
From previous event:
at Runner.query (/Users/brianlauber/Documents/src/knex/lib/runner.js:169:13)
at /Users/brianlauber/Documents/src/knex/lib/runner.js:41:23
at /Users/brianlauber/Documents/src/knex/lib/runner.js:261:24
From previous event:
at Runner.ensureConnection (/Users/brianlauber/Documents/src/knex/lib/runner.js:259:8)
at Runner.run (/Users/brianlauber/Documents/src/knex/lib/runner.js:27:12)
at Raw.Target.then (/Users/brianlauber/Documents/src/knex/lib/interface.js:15:43)
at Context.<anonymous> (/Users/brianlauber/Documents/src/knex/test/integration/builder/additional.js:908:10)
at callFn (/Users/brianlauber/Documents/src/knex/node_modules/mocha/lib/runnable.js:395:21)
at Test.Runnable.run (/Users/brianlauber/Documents/src/knex/node_modules/mocha/lib/runnable.js:382:7)
at Runner.runTest (/Users/brianlauber/Documents/src/knex/node_modules/mocha/lib/runner.js:541:10)
at /Users/brianlauber/Documents/src/knex/node_modules/mocha/lib/runner.js:667:12
at next (/Users/brianlauber/Documents/src/knex/node_modules/mocha/lib/runner.js:450:14)
at /Users/brianlauber/Documents/src/knex/node_modules/mocha/lib/runner.js:460:7
at next (/Users/brianlauber/Documents/src/knex/node_modules/mocha/lib/runner.js:362:14)
at Immediate.<anonymous> (/Users/brianlauber/Documents/src/knex/node_modules/mocha/lib/runner.js:428:5)
at processImmediate (internal/timers.js:439:21) {
name: 'KnexTimeoutError'
}
}
{
reason: KnexTimeoutError: Knex: Timeout acquiring a connection. The pool is probably full. Are you missing a .transacting(trx) call?
at /Users/brianlauber/Documents/src/knex/lib/client.js:351:30
From previous event:
at Client_MySQL2.acquireConnection (/Users/brianlauber/Documents/src/knex/lib/client.js:348:15)
at Client_MySQL2.cancelQuery (/Users/brianlauber/Documents/src/knex/lib/dialects/mysql/index.js:175:32)
at /Users/brianlauber/Documents/src/knex/lib/runner.js:177:37
From previous event:
at Runner.query (/Users/brianlauber/Documents/src/knex/lib/runner.js:169:13)
at /Users/brianlauber/Documents/src/knex/lib/runner.js:41:23
at /Users/brianlauber/Documents/src/knex/lib/runner.js:261:24
From previous event:
at Runner.ensureConnection (/Users/brianlauber/Documents/src/knex/lib/runner.js:259:8)
at Runner.run (/Users/brianlauber/Documents/src/knex/lib/runner.js:27:12)
at Raw.Target.then (/Users/brianlauber/Documents/src/knex/lib/interface.js:15:43)
at Context.<anonymous> (/Users/brianlauber/Documents/src/knex/test/integration/builder/additional.js:908:10)
at callFn (/Users/brianlauber/Documents/src/knex/node_modules/mocha/lib/runnable.js:395:21)
at Test.Runnable.run (/Users/brianlauber/Documents/src/knex/node_modules/mocha/lib/runnable.js:382:7)
at Runner.runTest (/Users/brianlauber/Documents/src/knex/node_modules/mocha/lib/runner.js:541:10)
at /Users/brianlauber/Documents/src/knex/node_modules/mocha/lib/runner.js:667:12
at next (/Users/brianlauber/Documents/src/knex/node_modules/mocha/lib/runner.js:450:14)
at /Users/brianlauber/Documents/src/knex/node_modules/mocha/lib/runner.js:460:7
at next (/Users/brianlauber/Documents/src/knex/node_modules/mocha/lib/runner.js:362:14)
at Immediate.<anonymous> (/Users/brianlauber/Documents/src/knex/node_modules/mocha/lib/runner.js:428:5)
at processImmediate (internal/timers.js:439:21) {
name: 'KnexTimeoutError'
}
}
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Q: what problem is this line intended to fix?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Unhandled rejection Error: Transaction rejected with non-error: undefined
from https://travis-ci.org/knex/knex/jobs/650139383?utm_medium=notification&utm_source=github_status
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
All troubles are going from
const trx = await knex.transaction();
trx.select()
// ...blablabla...
await trx.executionPromise
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Gotcha. Have you been able to recreate this error after #3666 was merged? (The link you provided looks like it's from a Travis-CI run that is 5 days old)
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
k -- just got back, so I'll try recreating the issue in the next few minutes.
One other thing I noticed: it appears that some test cases will "fail" if you omit a specific database from the DB="..."
environment variable. For instance: you will observe "failures" if you run the tests via:
DB="mysql mysql2" KNEX_TEST_TIMEOUT=60000 ./node_modules/.bin/mocha --exit -t 10000 test/index.js
However, these are not actually failures in the Knex library itself. It's actually a problem w/ the way the test cases are written. More specifically: the test cases are referencing data that is only available when "sqlite3"
is specified within DB="..."
. (BTW: I'm going to create a separate issue for this)
So, with this in mind: what command are you running to kick off the tests? It might provide some insight into why the tests are failing.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
@kibertoad can you help with explanation, how .executionPromise should work?
executionPromise must be awaited immediately, or after transaction commit/rollback?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
mocha ./test/unit/knex.js --grep "^knex rejects execution promise if there was a manual rollback and transaction is set to reject$"
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
@maximelkin executionPromise is a way to expose state of transaction to the user, so that he can e. g. handle the rollback or proceed with the rest of the flow after commit has happened. Having that in mind, I'd say that it should be awaited after transaction commit/rollback.
Maybe we need to rename the field to make it more explicit, e. g. transactionPromise.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
@maximelkin : I've been able to recreate the failure locally using the command-line you provided. I've identified a few suspicious sections of code, but so far none of them seem to directly impact this specific issue.
For example: take a look at the following:
Lines 228 to 233 in 7288608
return (this._previousSibling | |
? this._previousSibling.catch(() => {}) | |
: Promise.resolve() | |
).then(function() { | |
return connection; | |
}); |
These lines seem strange for at least 2 reasons:
- There is a
.catch(()=> {})
statement, which might be hiding other bugs. (More specifically: it might be causing Node to overlook some "unresolved promises". This will require some more investigation to confirm this) - The conditional logic seems to be largely unnecessary. In particular,
this._previousSibling
should always be defined thanks to the following lines in the constructor:
Lines 124 to 128 in 7288608
this._previousSibling = Bluebird.resolve(true); | |
if (outerTx) { | |
if (outerTx._lastChild) this._previousSibling = outerTx._lastChild; | |
outerTx._lastChild = this._promise; | |
} |
But yeah: so far, these oddities don't seem to have any direct impact on the issue you're observing.
cc: @kibertoad
$ node
this is case of 2 unhandled rejections |
@maximelkin Is this still useful with #3666 merged? |
@kibertoad partially - need to revert lib/dialects/mysql/index.js |
Third unhandled rejection is disappear, I will re-read code again later, because don't understand why |
70edb3b
to
8be47f4
Compare
8be47f4
to
ba69919
Compare
// todo^ is this true? | ||
transactor.executionPromise = transactor.executionPromise.catch((err) => { | ||
throw err; | ||
}); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Hmm... I suspect that this isn't actually addressing the underlying race condition. Instead, it is just adding a slight delay in the event processing queue, which makes the race condition less likely to occur.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Yes, this change is wrong too
@maximelkin + @kibertoad : Here's a new piece of info that might help w/ the investigation. First, here is the stacktrace that is attached to the "unresolved promise":
I modified the test case so that it prints out the stacktrace for the exception that it catches. Interestingly, the value that gets printed changes depending upon whether or not the "unresolved promise" occurred. When the "unresolved promise" occurs, the test case prints the following stacktrace:
Notice that this appears to contain the "unresolved promise" stacktrace as a subcomponent. In contrast, here is what gets printed when the "unresolved promise" does NOT occur:
As you can see, it matches the stacktrace that would have been included in the "unresolved promise". So: I don't have any specific conclusions related to this yet. But, I suspect that this will help pinpoint the source of the race condition. |
@maximelkin + @kibertoad : Update on my "different stacktraces" message (#3665 (comment)) Looks like that might have been a false alarm. It was a quirk in the console output that caused it to look like a really long stacktrace. In reality, the error was actually getting printed from 2 different places. (Which is why there the weird disconnect in the middle of the stacktrace) |
@maximelkin + @kibertoad : FYI -- I created another PR for you to look at over here: It was initially intended as a minor code cleanup; however, it might have inadvertently fixed the race condition as well. |
No description provided.