LevelDown version > `5.0.2` with PouchDB => MacOS crash with MaxListenersExceededWarning (once called more than once) #686

danielweck · 2019-10-13T16:42:03Z

As reported in PouchDB:
pouchdb/pouchdb#7819
pouchdb/pouchdb#7825
pouchdb/pouchdb#7848

I narrowed-down the bug to the leveldown transition from version 5.0.2 to 5.0.3 (ALL other package versions are latest, currently levelup = 4.3.2, pouchdb-adapter-leveldb = 7.1.1, pouchdb-adapter-leveldb = 7.1.1, etc.)

In other words, ONLY leveldown needs to be pinned to version 5.0.2. In my case, the package.json looks like:

  "optionalDependencies": {
    "leveldown": "5.0.2",
    "pouchdb-adapter-leveldb": "^7.1.1"
  },
  "resolutions": {
    "leveldown": "5.0.2"
  }

LevelDown diff between version 5.0.2 and 5.0.3:
v5.0.2...v5.0.3

Note my app stacktrace:

Uncaught Exception:
Error: once called more than once
    at /project/node_modules/pouchdb-core/node_modules/pouchdb-utils/lib/index.js:88:13
    at /project/node_modules/argsarray/index.js:14:18
    at /project/node_modules/pouchdb-core/lib/index.js:769:14
    at /project/dist/node_modules/pouchdb-adapter-leveldb-core/lib/index.js:350:18
    at /project/dist/node_modules/argsarray/index.js:14:18
    at /project/dist/node_modules/pouchdb-adapter-leveldb-core/lib/index.js:429:16
    at /project/dist/node_modules/sublevel-pouchdb/lib/index.js:243:9
    at /project/dist/node_modules/sublevel-pouchdb/lib/index.js:74:13

So, I am not certain that the problem actually stems from the leveldown implementation, but I thought I'd post this here as well as in the PouchDB issue tracker, just in case somebody here has a clue as to why the leveldown code change introduced in version 5.0.3 trips the PouchDB LevelDB adapter.

I should point out that my app is built with Electron version 6.0.12 (NodeJS 12), but I had the exact same problem with earlier Electron/NodeJS versions. LevelDown is built with npm rebuild --runtime=electron --target=6.0.12 --disturl=https://atom.io/download/atom-shell --build-from-source.

Thank you!

The text was updated successfully, but these errors were encountered:

vweevers · 2019-10-13T17:00:15Z

I also doubt it's an issue in leveldown. Could you share a code snippet, to reproduce the issue?

Some notes:

I don't recommend pinning to 5.0.2; that version suffers from segfaults
sublevel-pouchdb is outdated, as it was forked from level-sublevel which is no longer maintained and is known to have several compatibility issues with latest level* modules. The preferred solution is now subleveldown.

danielweck · 2019-10-13T17:09:11Z

Thanks for the quick feedback / tips! :)

danielweck · 2019-10-13T17:34:31Z

Regarding sublevel-pouchdb (thanks for spotting this in the stacktrace!), I posted a separate issue to enquire with the PouchDB devs:
pouchdb/pouchdb#7929

vweevers · 2019-10-14T09:00:21Z

@danielweck Let's keep the discussion in a single thread; reposting a comment in multiple issues (pouchdb/pouchdb#7819 (comment), pouchdb/pouchdb#7825 (comment), pouchdb/pouchdb#7848 (comment)) doesn't help to fix it sooner. Only makes it harder to follow. Thanks!

vweevers · 2019-10-14T09:01:05Z

I'm unable to reproduce on any version of leveldown (tried 5.0.2, 5.0.3. 5.3.0).

danielweck · 2019-10-14T09:07:09Z

I felt it was necessary to revive the closed PouchDB issues, so that developers who encountered the problem would get the "heads-up" and report back about their findings.

Naturally, I hate duplication too, so I would rather be able to focus on a single comment thread.

danielweck · 2019-10-14T09:11:36Z

This "MaxListenersExceededWarning" MacOS-specific definitely needs a minimal repro test-case.
I am not sure what triggers this, I was hoping that the stack trace posted at the top of this comment thread would provide some clues.

I suspect that the issue filed here for leveldown can safely be closed, because the problem probably arises from how PouchDB integrates it. However I am very grateful for your replies, which have helped on multiple levels already.

Cheers.

vweevers · 2019-10-14T09:21:24Z

My money would be on sublevel-pouchdb. If y'all need help feel free to ask (more specific) questions!

danielweck · 2019-10-14T09:28:53Z

Thanks :)

vweevers · 2019-10-14T12:42:34Z

I got curious and was able to reproduce running this on a mac.

Somehow, because there are two leveldown packages in the node_modules tree, the native binding is calling callbacks twice. At least for db.open(..., callback) and db.batch(..., callback).

I was also able to reproduce outside of pouchdb. I will push a repro to GitHub once I confirm it's really a leveldown bug. It's quite strange.

In the case of pouchdb, the reason it only happens when you installed stuff with yarn is that yarn does not deduplicate two dependencies with the ranges leveldown: ^5.0.0 and leveldown: 5.0.2, while npm does. I.e. npm will install 5.0.2 in the top-level node_modules, because 5.0.2 satisfies both leveldown: ^5.0.0 and leveldown: 5.0.2.

So it might not be the version that matters (maybe all of 5.x has a bug), but that two versions are loaded side by side.

danielweck · 2019-10-14T12:58:24Z

Note that our project uses the Npm CLI, not Yarn.
While searching for answers, I used 'npm ls leveldown' and I double-checked 'node_modules/leveldown/package.json', to ensure that the NodeJS module resolution elected the expected package.
In our case, we have to be even more careful because the Electron app bundle can organise the native NodeJS plugins inside the ASAR archive's node_module folder, or externally. Plus, we don't use the leveldown prebuilts, yet they are automatically included in the node_modules folder hierarchy so we must make sure that the NodeJS runtime does not pick them up (ref. "bindings").

vweevers · 2019-10-14T13:00:11Z

Note that our project uses the Npm CLI, not Yarn.

OK. Could you share the output of npm ls leveldown?

vweevers · 2019-10-14T13:15:46Z

Repro: https://github.com/vweevers/yarn-macos-pouchdb-error/tree/without-pouchdb

cc @ralphtheninja

vweevers · 2019-10-14T13:27:42Z

Might have something to do with node-gyp-build, which loads leveldown and which we upgraded in 5.1.0 - using a different loading algorithm from then on. Edit: nope, both instances of node-gyp-build load a distinct and correct *.node prebuild.

So how can these two addons end up sharing state? 🤔

vweevers · 2019-10-14T14:34:30Z

Dependency-free repro: https://github.com/vweevers/yarn-macos-pouchdb-error/tree/low-level

danielweck · 2019-10-14T15:03:17Z

Dependency-free repro: https://github.com/vweevers/yarn-macos-pouchdb-error/tree/low-level

node --version
=>
v10.16.3

node index.js
=>

OK
/xx/yarn-macos-pouchdb-error/index.js:10
      if (calls++) throw new Error('Called too many times')
                         ^

Error: Called too many times
    at /xx/yarn-macos-pouchdb-error/index.js:10:26

danielweck · 2019-10-14T15:04:26Z

OK. Could you share the output of npm ls leveldown?

npm --version
=>
6.12.0

npm ls leveldown
=>

├── [email protected] 
└─┬ [email protected]
  ├─┬ [email protected]
  │ └── [email protected]  deduped
  └── [email protected]  deduped

danielweck · 2019-10-14T15:06:31Z

Follow-up:

package.json
=>


  "dependencies": {
    ...
    "pouchdb-core": "^7.1.1",
    "pouchdb-find": "^7.1.1",
    "pouchdb-quick-search": "^1.3.0",
    ...
  },
  "devDependencies": {
    ...
    "@types/pouchdb-core": "^7.0.4",
    ...
    "pouchdb-adapter-memory": "^7.1.1",
    ...
  },
  "optionalDependencies": {
    "leveldown": "5.0.2",
    "pouchdb-adapter-leveldb": "^7.1.1"
  },
  "resolutions": {
    "leveldown": "5.0.2"
  }

vweevers · 2019-10-14T15:56:23Z

Added the ability (to the low-level branch) to test different versions side by side: node index.js <version a> <version b>. It loads A, loads B, then opens B. When A and B are the same it creates a copy, in order to test loading two addons with the same version.

The problematic version seems to be 5.0.2.

Command	Result
`node index.js 5.3.0 5.0.2`	Callback called too many times
`node index.js 5.3.0 5.0.3`	OK
`node index.js 5.0.2 5.3.0`	Callback not called
`node index.js 5.0.3 5.3.0`	OK
`node index.js 5.0.2 5.0.2`	OK
`node index.js 5.0.3 5.0.3`	OK
`node index.js 5.3.0 5.3.0`	OK
`node index.js 5.0.3 5.0.2`	Callback called too many times
`node index.js 5.0.2 5.0.3`	Callback not called

vweevers · 2019-10-14T16:11:15Z

I lack the (mac) tools and skills to figure this out, so I suggest sending a PR to pouchdb to update leveldown to the latest version (and if they're open to it, unlocking the version range to e.g. ^5.3.0).

ralphtheninja · 2019-10-14T17:48:51Z

@vweevers The problem seems to be related to callbacks in general, right? Maybe it's related to the functionality in BaseWorker() or PriorityWorker().

ralphtheninja · 2019-10-14T18:06:39Z

@vweevers There is a pattern between "newer version" vs "older version" above. Note that the version pairs

5.3.0 / 5.0.2 too many
5.0.2 / 5.3.0 not called

behave exactly the same as

5.0.3 / 5.0.2 too many
5.0.2 / 5.0.3 not called

I'm betting you'll get the same result if you replace 5.3.0 with 5.2.0 or any other version over 5.0.3.

I'm thinking it could be related to different class function memory layout, given that we have changed a bit how some methods are pure virtual, adding DoComplete() we might end up in a weird situation because we're loading libraries dynamically and maybe messing around with function address space. I'm guessing very hand wavy here.

danielweck · 2019-10-14T18:32:22Z

It looks like you are on the right track! :)

Meanwhile, I have found a better workaround that does not require pinning to version 5.0.2. Instead I can just use the latest version (^5.3.0) but I must make sure to delete the de-duped leveldown NPM package (./node_modules/pouchdb-adapter-leveldb/node_modules/leveldown, which contains build/Release/leveldown.node).
It's that simple :)
Thanks for putting me on this track!

…code level during NPM install, precompiled binaries of NodeJS plugins were loaded several times (Fixes #496 Also see Level/leveldown#686 )

vweevers · 2019-10-14T18:52:23Z

The problem seems to be related to callbacks in general, right?

@ralphtheninja Yeah. I first noticed the problem on db.batch() (which uses PriorityWorker), then I tried out db.open() (which uses BaseWorker) and saw the same.

Where do we go from here? Test more versions and combinations? Even if only 5.0.2 turns out to have the problem, it's a severe problem. If we don't figure it out, it might bite us later. But I have no idea how to further investigate this.

ralphtheninja · 2019-10-14T19:41:02Z

Where do we go from here? Test more versions and combinations? Even if only 5.0.2 turns out to have the problem, it's a severe problem. If we don't figure it out, it might bite us later. But I have no idea how to further investigate this.

We sleep on it.

vweevers · 2019-10-18T08:04:47Z

Updated the low-level branch to build from source so we can use debug builds.

vweevers · 2019-10-18T09:05:11Z

lldb node
(lldb) breakpoint set --method DoComplete
(lldb) process launch -- index.js 5.3.0 5.0.2
Process 27762 launched: '/Users/user914131/.nvm/versions/node/v12.12.0/bin/node' (x86_64)
Load /Users/user914131/yarn-macos-pouchdb-error/node_modules/ld530/build/Debug/leveldown.node
Load /Users/user914131/yarn-macos-pouchdb-error/node_modules/ld502/build/Debug/leveldown.node
Open 5.0.2

First breaks on 5.3.0 (should not happen):

Process 27762 stopped
* thread #1, queue = 'com.apple.main-thread', stop reason = breakpoint 1.1
    frame #0: 0x0000000102d08580 leveldown.node`BaseWorker::DoComplete(this=0x0000000102f00c50) at binding.cc:301:9
   298 	  }
   299 	
   300 	  void DoComplete () {
-> 301 	    if (status_.ok()) {
   302 	      return HandleOKCallback();
   303 	    }
   304 	
Target 0: (node) stopped.
(lldb) bt
* thread #1, queue = 'com.apple.main-thread', stop reason = breakpoint 1.1
  * frame #0: 0x0000000102d08580 leveldown.node`BaseWorker::DoComplete(this=0x0000000102f00c50) at binding.cc:301:9
    frame #1: 0x0000000102d08504 leveldown.node`BaseWorker::Complete(env=0x0000000102f00120, status=napi_ok, data=0x0000000102f00c50) at binding.cc:295:11
    frame #2: 0x000000010005d9a3 node`(anonymous namespace)::uvimpl::Work::AfterThreadPoolWork(int) + 151
    frame #3: 0x00000001008915d2 node`uv__work_done + 178
    frame #4: 0x0000000100894cba node`uv__async_io + 334
    frame #5: 0x00000001008a5677 node`uv__io_poll + 1739
    frame #6: 0x0000000100895146 node`uv_run + 336
    frame #7: 0x00000001000b48a4 node`node::NodeMainInstance::Run() + 458
    frame #8: 0x000000010005b728 node`node::Start(int, char**) + 294
    frame #9: 0x00007fff64f443d5 libdyld.dylib`start + 1

Then on 5.0.2:

(lldb) continue
Process 27762 resuming
Process 27762 stopped
* thread #1, queue = 'com.apple.main-thread', stop reason = breakpoint 1.2
    frame #0: 0x0000000104807540 leveldown.node`BaseWorker::DoComplete(this=0x0000000102f00c50) at binding.cc:294:9
   291 	  }
   292 	
   293 	  virtual void DoComplete () {
-> 294 	    if (status_.ok()) {
   295 	      return HandleOKCallback();
   296 	    }
   297 	
Target 0: (node) stopped.
(lldb) bt
* thread #1, queue = 'com.apple.main-thread', stop reason = breakpoint 1.2
  * frame #0: 0x0000000104807540 leveldown.node`BaseWorker::DoComplete(this=0x0000000102f00c50) at binding.cc:294:9
    frame #1: 0x0000000102d08519 leveldown.node`BaseWorker::Complete(env=0x0000000102f00120, status=napi_ok, data=0x0000000102f00c50) at binding.cc:296:11
    frame #2: 0x000000010005d9a3 node`(anonymous namespace)::uvimpl::Work::AfterThreadPoolWork(int) + 151
    frame #3: 0x00000001008915d2 node`uv__work_done + 178
    frame #4: 0x0000000100894cba node`uv__async_io + 334
    frame #5: 0x00000001008a5677 node`uv__io_poll + 1739
    frame #6: 0x0000000100895146 node`uv_run + 336
    frame #7: 0x00000001000b48a4 node`node::NodeMainInstance::Run() + 458
    frame #8: 0x000000010005b728 node`node::Start(int, char**) + 294
    frame #9: 0x00007fff64f443d5 libdyld.dylib`start + 1

vweevers · 2019-10-18T11:35:48Z

On any combination of versions, I found that node calls BaseWorker::Complete of the first loaded addon, regardless of which one is being opened.

@ralphtheninja Can that have anything to do with the fact that BaseWorker::Complete is static?

ralphtheninja · 2019-10-18T13:03:07Z

@vweevers It sounds like it could have something to do with this. I'm thinking we'd like to namespace the functions somehow so they are considered different, if that makes sense. Now it's like they are calling each other. Maybe there is a way to modify the code for this or pass some flag to the linker when building the .so/.dylib/.dll.

cc @oleavr Any ideas?

vweevers · 2019-10-18T13:39:26Z

Atm the symbols don't have unique names. Is that it?

$ objdump --syms node_modules/ld502/build/Debug/leveldown.node | grep -i complete
0000000000007530 lw    F __TEXT,__text	__ZN10BaseWorker10DoCompleteEv
0000000000008170 lw    F __TEXT,__text	__ZN14PriorityWorker10DoCompleteEv
00000000000076a0 gw    F __TEXT,__text	__ZN10BaseWorker8CompleteEP10napi_env__11napi_statusPv
000000000004b680 gw    F __TEXT,__text	__ZNSt3__127__insertion_sort_incompleteIRPFbPN7leveldb12FileMetaDataES3_EPS3_EEbT0_S8_T_
$ objdump --syms node_modules/ld503/build/Debug/leveldown.node | grep -i complete
00000000000075b0 gw    F __TEXT,__text	__ZN10BaseWorker10DoCompleteEv
0000000000007520 gw    F __TEXT,__text	__ZN10BaseWorker8CompleteEP10napi_env__11napi_statusPv
000000000004b650 gw    F __TEXT,__text	__ZNSt3__127__insertion_sort_incompleteIRPFbPN7leveldb12FileMetaDataES3_EPS3_EEbT0_S8_T_

vweevers · 2019-10-18T14:04:03Z

Repro without leveldown: https://github.com/vweevers/yarn-macos-pouchdb-error/tree/worker-test

Expected output:

$ node index.js 
addon_b execute
addon_b complete
callback

Actual:

$ node index.js 
addon_a execute
addon_a complete
callback

I'll see if adding a namespace (macro) fixes it.

vweevers · 2019-10-18T15:00:37Z

This works:

#define CONCAT_(a,b) a##b
#define CONCAT(a,b) CONCAT_(a,b)
#define NS CONCAT(NODE_GYP_MODULE_NAME,VERSION)

namespace NS {
  // ..
}

This way symbols get prefixed with a versioned namespace.

Better yet, use random bytes, hex-encoded, so it always produces valid identifiers.

Closes #686.

Ref #686, #687.

danielweck · 2019-10-21T16:43:25Z

FYI, I have updated leveldown to version 5.4.0, the problem persists (to solve it, I just delete the ./node_modules/pouchdb-adapter-leveldb/node_modules/leveldown folder so that only the top-level package ./node_modules/leveldown remains)

Ref #686, #687.

vweevers · 2019-10-26T07:56:57Z

Fixed in 5.4.1.

danielweck mentioned this issue Oct 13, 2019

Outdated sublevel-pouchdb dependency should be superceded by subleveldown? pouchdb/pouchdb#7929

Closed

vweevers closed this as completed Oct 14, 2019

vweevers reopened this Oct 14, 2019

vweevers added bug Something isn't working help wanted Extra attention is needed labels Oct 14, 2019

This comment has been minimized.

Sign in to view

vweevers added a commit that referenced this issue Oct 18, 2019

Produce a unique namespace at compile time

07eba03

Closes #686.

vweevers mentioned this issue Oct 18, 2019

Produce a unique namespace at compile time #687

Closed

vweevers added a commit that referenced this issue Oct 19, 2019

Try out -fvisibility=hidden for mac

0969552

Ref #686, #687.

vweevers mentioned this issue Oct 19, 2019

Hide symbols for mac with -fvisibility=hidden #688

Merged

vweevers closed this as completed in #688 Oct 21, 2019

vweevers added a commit that referenced this issue Oct 21, 2019

Hide symbols on mac with -fvisibility=hidden (#688)

b263d80

Ref #686, #687.

LevelDown version > 5.0.2 with PouchDB => MacOS crash with MaxListenersExceededWarning (once called more than once) #686

LevelDown version > 5.0.2 with PouchDB => MacOS crash with MaxListenersExceededWarning (once called more than once) #686

Comments

danielweck commented Oct 13, 2019

vweevers commented Oct 13, 2019 • edited Loading

danielweck commented Oct 13, 2019

danielweck commented Oct 13, 2019

vweevers commented Oct 14, 2019

vweevers commented Oct 14, 2019

danielweck commented Oct 14, 2019

danielweck commented Oct 14, 2019

vweevers commented Oct 14, 2019

danielweck commented Oct 14, 2019

vweevers commented Oct 14, 2019

danielweck commented Oct 14, 2019

vweevers commented Oct 14, 2019

vweevers commented Oct 14, 2019

vweevers commented Oct 14, 2019 • edited Loading

vweevers commented Oct 14, 2019

danielweck commented Oct 14, 2019 • edited Loading

danielweck commented Oct 14, 2019

danielweck commented Oct 14, 2019 • edited Loading

vweevers commented Oct 14, 2019 • edited Loading

vweevers commented Oct 14, 2019

ralphtheninja commented Oct 14, 2019 • edited Loading

ralphtheninja commented Oct 14, 2019

danielweck commented Oct 14, 2019 • edited Loading

vweevers commented Oct 14, 2019

ralphtheninja commented Oct 14, 2019

vweevers commented Oct 18, 2019

This comment has been minimized.

vweevers commented Oct 18, 2019 • edited Loading

vweevers commented Oct 18, 2019

ralphtheninja commented Oct 18, 2019 • edited Loading

vweevers commented Oct 18, 2019

vweevers commented Oct 18, 2019

vweevers commented Oct 18, 2019 • edited Loading

danielweck commented Oct 21, 2019

vweevers commented Oct 26, 2019

LevelDown version > `5.0.2` with PouchDB => MacOS crash with MaxListenersExceededWarning (once called more than once) #686

LevelDown version > `5.0.2` with PouchDB => MacOS crash with MaxListenersExceededWarning (once called more than once) #686

vweevers commented Oct 13, 2019 •

edited

Loading

vweevers commented Oct 14, 2019 •

edited

Loading

danielweck commented Oct 14, 2019 •

edited

Loading

danielweck commented Oct 14, 2019 •

edited

Loading

vweevers commented Oct 14, 2019 •

edited

Loading

ralphtheninja commented Oct 14, 2019 •

edited

Loading

danielweck commented Oct 14, 2019 •

edited

Loading

vweevers commented Oct 18, 2019 •

edited

Loading

ralphtheninja commented Oct 18, 2019 •

edited

Loading

vweevers commented Oct 18, 2019 •

edited

Loading