Bluebird remove return, reflect, fromCallback #3483

maximelkin · 2019-10-15T20:23:20Z

No description provided.

kibertoad · 2019-10-15T21:48:49Z

It seems to be failing on Node 12 consistently.

maximelkin · 2019-10-15T22:00:51Z

Hm, strange errors, I will research this

maximelkin · 2019-10-15T22:09:46Z

So error got passed through try-catch, really strange

Error: This socket has been ended by the other party
    at Socket.writeAfterFIN [as write] (net.js:441:14)
    at Connection.write (/home/travis/build/knex/knex/node_modules/mysql2/lib/connection.js:217:17)
    at Connection.writePacket (/home/travis/build/knex/knex/node_modules/mysql2/lib/connection.js:262:12)
    at Quit.start (/home/travis/build/knex/knex/node_modules/mysql2/lib/commands/quit.js:24:16)
    at Quit.execute (/home/travis/build/knex/knex/node_modules/mysql2/lib/commands/command.js:39:22)
    at Connection.handlePacket (/home/travis/build/knex/knex/node_modules/mysql2/lib/connection.js:408:32)
    at Connection.addCommand (/home/travis/build/knex/knex/node_modules/mysql2/lib/connection.js:430:12)
    at Connection.end (/home/travis/build/knex/knex/node_modules/mysql2/lib/connection.js:796:26)
    at internal/util.js:278:30
    at new Promise (<anonymous>)
    at bound end (internal/util.js:277:12)
    at Client_MySQL2.destroyRawConnection (/home/travis/build/knex/knex/lib/dialects/mysql/index.js:85:20)

maximelkin · 2019-10-16T01:11:43Z

connection.end called after last command fail, which cleared all events, so 'error' event emitted to nowhere and emitted as unhandled error

maximelkin · 2019-10-16T11:20:11Z

nodejs/node#24111

maximelkin · 2019-10-16T11:25:43Z

Before node12

connection.end called
also error emit in 1) synchroniously
catch
finally (removeAllListeners)

Was

connection.end called (process.nextTick error triggered because closed)
Bluebird.catch
error emitted
Bluebird.finally (removeAllListeners)

Now

connection.end (process.nextTick error triggered)
catch (e) {}
finally {} (removeAllListeners)
error emitted

Bluebird solution worked because of additional microtask from .catch?

maximelkin · 2019-10-16T14:26:48Z

@kibertoad have you any ideas to resolve this?

kibertoad · 2019-10-16T15:22:22Z

@maximelkin Can we add additional listener to catch the error when it is thrown asynchronously?

maximelkin · 2019-10-16T16:44:08Z

@kibertoad can this trigger leaks? When to unsubscribe this listener?

maximelkin · 2019-10-16T18:30:19Z

7069ce5 <- here removeAllListeners added

maximelkin · 2019-10-21T20:02:10Z

@kibertoad that do you think?

elhigu

Dropping that removeAllListeners call seems wrong.

lib/dialects/mysql/index.js

elhigu · 2019-10-22T15:01:32Z

lib/dialects/mysql/index.js

+      return await end();
+    } catch (err) {
+      connection.__knex__disposed = err;
+    }


Is that finally removeAllListeners really unnecessary? Is there test somewhere, which fails if connection has listeners after disposal?

I run knex-stress-test for a some minutes (with process.memoryUsage().heapUsed logging)
memory usage is stable, so no leak introduced

Sounds promising. Did you try it with both mysql and mysql2 drivers?

Though if that listener removal is not necessary, shouldn't this function just return end() and leave it to caller to set __knex__disposed like in every other driver 🤔

One more thing... if that Error: This socket has been ended by the other party is now not leaked, I suppose that error is still happening, but it is ignored somewhere (by existence of some event handler maybe). So when it is ignored how does that get recorded to connection.__knex__disposed or does it even matter...

Also I'm pretty confused how is it possible that error is leaking and where that leak is happening exactly (stack trace showed lib/dialects/mysql/index.js:85:20, but then it should have been handled by caller's error handler). And when it is leaked why caller's error handling is not catching it? That was an async function after all.

This is a part of really fundamental functionality of knex and may cause hard to catch failures for huge user base if it is not working properly.I would really like to understand the problem properly before trying to patch it.

Can I easily reproduce the original error to investigate it a bit more? Did it happen in some very specific test or every time?

Install 12 node
Add finally block with removeAllListeners
run test "#2321 dead connections are not evicted from pool"

lib/dialects/oracle/index.js

lib/dialects/postgres/index.js

lib/dialects/sqlite3/index.js

lib/transaction.js

maximelkin · 2019-10-22T21:15:37Z

Dropping that removeAllListeners call seems wrong.

@elhigu why?

elhigu · 2019-10-23T06:02:44Z

Dropping that removeAllListeners call seems wrong.

@elhigu why?

Because its addition didn't look like an accident and there was not proper investigation done, if it can be removed or not.

maximelkin · 2019-10-24T22:50:42Z

As temporal solution we can add delay before removeAllListeners, so it would work like before

kibertoad · 2019-10-25T06:37:23Z

@maximelkin I believe https://lodash.com/docs/4.17.14#defer does exactly this?

maximelkin · 2019-10-25T10:30:31Z

@kibertoad yes

maximelkin · 2019-10-25T10:31:38Z

But i still think what we should review removeAllListeners usage, maybe in separate issue

But with defer, to match all behavior

maximelkin · 2019-10-25T12:46:48Z

@elhigu @kibertoad done

maximelkin closed this Oct 15, 2019

maximelkin reopened this Oct 15, 2019

elhigu requested changes Oct 22, 2019

View changes

maxeljkin added 5 commits Oct 22, 2019

refactor(bluebird): remove Bluebird.return usage

5bf71c0

refactor(bluebird): remove Bluebird.reflect usage

bba264a

refactor(bluebird): remove Bluebird.fromCallback usage

01b3b64

fix(mysql): remove unsubscription for connection

cb5eff3

refactor: replace bind with arrow function

3269fb1

maximelkin force-pushed the bluebird_cleanup branch from d7e428a to 3269fb1 Compare Oct 22, 2019

fix(mysql): return back removeAllListeners

c0204b5

But with defer, to match all behavior

maximelkin closed this Oct 25, 2019

maximelkin reopened this Oct 25, 2019

kibertoad approved these changes Oct 25, 2019

View changes

kibertoad merged commit 03ecbee into knex:master Oct 25, 2019
1 check passed

maximelkin deleted the bluebird_cleanup branch Oct 25, 2019

daniellockyer mentioned this pull request Mar 31, 2020

Update dependency knex to v0.20.13 TryGhost/Ghost#11295

Merged

1 task

Bluebird remove return, reflect, fromCallback #3483

Bluebird remove return, reflect, fromCallback #3483

maximelkin commented Oct 15, 2019

kibertoad commented Oct 15, 2019

maximelkin commented Oct 15, 2019

maximelkin commented Oct 15, 2019

maximelkin commented Oct 16, 2019

maximelkin commented Oct 16, 2019

maximelkin commented Oct 16, 2019 •

edited

maximelkin commented Oct 16, 2019

kibertoad commented Oct 16, 2019

maximelkin commented Oct 16, 2019

maximelkin commented Oct 16, 2019

maximelkin commented Oct 21, 2019

elhigu left a comment

elhigu Oct 22, 2019

maximelkin Oct 22, 2019

elhigu Oct 23, 2019

elhigu Oct 23, 2019

maximelkin Oct 23, 2019

maximelkin commented Oct 22, 2019

elhigu commented Oct 23, 2019

maximelkin commented Oct 24, 2019

kibertoad commented Oct 25, 2019

maximelkin commented Oct 25, 2019

maximelkin commented Oct 25, 2019

maximelkin commented Oct 25, 2019

Bluebird remove return, reflect, fromCallback #3483

Bluebird remove return, reflect, fromCallback #3483

Conversation

maximelkin commented Oct 15, 2019

kibertoad commented Oct 15, 2019

maximelkin commented Oct 15, 2019

maximelkin commented Oct 15, 2019

maximelkin commented Oct 16, 2019

maximelkin commented Oct 16, 2019

maximelkin commented Oct 16, 2019 • edited

maximelkin commented Oct 16, 2019

kibertoad commented Oct 16, 2019

maximelkin commented Oct 16, 2019

maximelkin commented Oct 16, 2019

maximelkin commented Oct 21, 2019

elhigu left a comment

elhigu Oct 22, 2019

Choose a reason for hiding this comment

maximelkin Oct 22, 2019

Choose a reason for hiding this comment

elhigu Oct 23, 2019

Choose a reason for hiding this comment

elhigu Oct 23, 2019

Choose a reason for hiding this comment

maximelkin Oct 23, 2019

Choose a reason for hiding this comment

maximelkin commented Oct 22, 2019

elhigu commented Oct 23, 2019

maximelkin commented Oct 24, 2019

kibertoad commented Oct 25, 2019

maximelkin commented Oct 25, 2019

maximelkin commented Oct 25, 2019

maximelkin commented Oct 25, 2019

maximelkin commented Oct 16, 2019 •

edited