Regression: Error: async hook stack has become corrupted (actual: 2, expected: 0)

[gabrielschulhof]

#32933 seems to have introduced the following error:

Error: async hook stack has become corrupted (actual: 2, expected: 0)
 1: 0x9acb5a node::InternalCallbackScope::~InternalCallbackScope() [node]
 2: 0x9daf50 node::Environment::RunTimers(uv_timer_s*) [node]
 3: 0x13f5912  [node]
 4: 0x13f8c32 uv_run [node]
 5: 0xa911d4 node::NodeMainInstance::Run() [node]
 6: 0xa163ff node::Start(int, char**) [node]
 7: 0x7fc2d065bf43 __libc_start_main [/lib64/libc.so.6]
 8: 0x9ab01e _start [node]

The error is produced by building the following add-on:

#include <stdio.h>
#include <assert.h>
#include <node_api.h>

static void delete_me(napi_env env, void* data, void* hint) {
  napi_status status;
  napi_value string;
  napi_value error;
  napi_ref ref;

  fprintf(stderr, "delete_me\n");

  status = napi_create_string_utf8(env,
                                   "Finalizer exception",
                                   NAPI_AUTO_LENGTH,
                                   &string);
  assert(status == napi_ok);

  status = napi_create_error(env, NULL, string, &error);                                   
  assert(status == napi_ok);

  status = napi_create_reference(env, error, 1, &ref);
  assert(status == napi_ok);

  status = napi_throw(env, error);
  assert(status == napi_ok);

  status = napi_delete_reference(env, ref);
  assert(status == napi_ok);
}

static napi_value CreateException(napi_env env, napi_callback_info info) {
  napi_value ret;

  napi_status status = napi_create_external(env, NULL, delete_me, NULL, &ret);
  assert(status == napi_ok);

  return ret;
}

NAPI_MODULE_INIT() {
  napi_value result;

  napi_status status = napi_create_function(env,
                                          "createException",
                                          NAPI_AUTO_LENGTH,
                                          CreateException,
                                          NULL,
                                          &result);
  assert(status == napi_ok);

  return result;
}

const assert = require('assert');
let x = require('bindings')('test_external_napi')();
x = null;
const interval = setInterval(() => {
  console.log("setInterval firing");
  try {
    global.gc();
  } catch (anException) {
    assert(anException.message.match(/Finalizer exception/));
    clearInterval(interval);
  }
}, 100);

Tested with and without --expose-gc:

# Without --expose-gc
for ((Nix = 0; Nix < 20; Nix++)); do node ./index.js ; done
# With --expose-gc
for ((Nix = 0; Nix < 20; Nix++)); do node --expose-gc ./index.js ; done

Expected output for with --expose-gc – none
Expected output for without --expose-gc (repeated 20 times):

assert.js:385
    throw err;
    ^

AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value:

  assert(anException.message.match(/Finalizer exception/))

    at Timeout._onTimeout (/home/nix/node/test-external/index.js:9:5)
    at listOnTimeout (internal/timers.js:551:17)
    at processTimers (internal/timers.js:494:7) {
  generatedMessage: true,
  code: 'ERR_ASSERTION',
  actual: null,
  expected: true,
  operator: '=='
}

The latter is expected because the thrown error is about global.gc() missing from global not about the error thrown from the native code, so its anException.message will not match the regex.

A git bisect performed manually reveals that #32933 seems to have introduced some instability in the correct functioning of the above add-on:

s) Dies sometimes, works as expected the rest of the time
✓) Works as expected
1) Above error when running with --expose-gc
2) Above error when running without --expose-gc

              ,--- result with --expose-gc
             /  ,--- result without --expose-gc
            /  /
         / [1][s] 99f0404646 doc: specify encoding in text/html examples
         | ... (172 commits)
         | [✓][s] a2b1b92e30 test: AsyncLocalStorage works with thenables
         | ... (40 commits)
         | [s][s] 8ef86a920c quic: fix clang warning
         | ... (40 commits)
         | [1][2] d7d79f2163 quic: avoid memory fragmentation issue
         | ... (92 commits)
         | [1][2] 74ca960aac lib: initial experimental AbortController imple...
         | [✓][2] 3e2a300710 src: use ToLocal in SafeGetenv
         | ... (24 commits)
         | [✓][2] b1704e4347 meta: fix a typo in the flaky test template
         | ... (24 commits)
unstable | [✓][2] e3b54b4d1c wasi: allow WASI stdio to be configured
         | ... (4 commits)
         | [✓][2] cd9bc20cb4 doc: add --experimental-top-level-await to man ...
         | [✓][2] 4bdab881b8 console: name console functions appropriately
         | [1][2] 87629d7e7c console: mark special console properties as non...
         | [1][2] b61249e32d console: remove dead code
         | ... (2 commits)
         | [1][2] 54e5c36e73 build: fix GetCurrentThreadStackLimits error on...
         | ... (17 commits)
         | [1][2] 54b36e401d fs: reimplement read and write streams using st...
         | ... (20 commits)
         | [1][2] 6443ab9595 module: deprecate module.parent
         | ... (126 commits)
         | [1][2] 5bb4d01fbe doc: add note about clientError writable handling
         | ... (171 commits)
         \ [1][2] c15a27cab3 stream: don't wait for close on legacy streams
         / [✓][✓] f5c11a1a0a stream: don't emit finish after close
         | [✓][✓] 9f14584f2a deps: update archs files for OpenSSL-1.1.1g
         | [ ][ ] 5509c6355c deps: upgrade openssl sources to 1.1.1g
         | [✓][✓] 58682d823a tls: add highWaterMark option for connect
         | ... (3 commits)
         | [✓][✓] 53b8133656 doc: avoid tautology in README
         | ... (9 commits)
         | [✓][✓] 654c0ace7b src: fix compiler warnings in node_http2.cc
  stable | ... (18 commits)
         | [✓][✓] 01e158c600 doc: remove repeated word in modules.md
         | ... (36 commits)
         | [✓][✓] e231e1a0d8 src: elevate v8 namespaces
         | ... (74 commits)
         | [✓][✓] 203776fb71 build: fix LINT_MD_NEWER assignment
         | ... (149 commits)
         | [✓][✓] 8ec533d890 benchmark: use let instead of var in tls
         | ... (299 commits)
         \ [✓][✓] 67d45fb298 2020-03-04 Version 13.10.1 (Current)

Tested on my laptop (Fedora 30 x64).

[gabrielschulhof]

I will try to reduce the C code needed for reproduction. In particular, the napi_create_ref/napi_delete_ref is being performed by node-addon-api for napi_values created with napi_create_error. For each code reduction I will re-test the commitids tested above.

[gabrielschulhof]

This being N-API I did not recompile the addon for each commit.

[devsnek]

@gabrielschulhof totally off topic, what is that bisect ui from?

[gabrielschulhof]

@devsnek created by hand using text editor 🙂

[gabrielschulhof]

@devsnek I started with

git log --oneline HEAD~1...master | sed 's/^/[ ][ ] ' >> ~/async_hook.corruption.txt

[devsnek]

@gabrielschulhof very nice 👏

[gabrielschulhof]

@devsnek then

git log --oneline cb8898c48f~...de877c5781 | wc -l
git log --oneline 74ca960aac~1...99f0404646  | head -n 174 | tail -n 1
# Where 174 is one half of what `wc -l` gave you
Check that out, run the test, fill the checkboxes.

[gabrielschulhof]

That was just an example. Obviously the commitid range for the two commands has to be the same 😀

[gabrielschulhof]

OK, it may not have been #32933. Bisect goes on.

[gabrielschulhof]

s) Dies sometimes
x) Node.js fails to build
✓) Works as expected
1) Dies with above error when running with --expose-gc
2) Dies with above error when running without --expose-gc

           ,--- running with --expose-gc
          /  ,--- running without --expose-gc
         /  /
        / [s][s] 99f0404646 doc: specify encoding in text/html examples
        | ... (172 commits)
        | [✓][s] a2b1b92e30 test: AsyncLocalStorage works with thenables
        | ... (40 commits)
        | [s][s] 8ef86a920c quic: fix clang warning
        | ... (40 commits)
        | [1][2] d7d79f2163 quic: avoid memory fragmentation issue
        | ... (91 commits)
        | [1][2] 74ca960aac lib: initial experimental AbortController implementation
        | [✓][2] 3e2a300710 src: use ToLocal in SafeGetenv
        | ... (24 commits)
        | [✓][2] b1704e4347 meta: fix a typo in the flaky test template
        | ... (24 commits)
        | [✓][2] e3b54b4d1c wasi: allow WASI stdio to be configured
        | ... (4 commits)
        | [✓][2] cd9bc20cb4 doc: add --experimental-top-level-await to man page
        | [✓][2] 4bdab881b8 console: name console functions appropriately
        | [1][2] 87629d7e7c console: mark special console properties as non-enumerable
        | [1][2] b61249e32d console: remove dead code
        | ... (2 commits)
        | [1][2] 54e5c36e73 build: fix GetCurrentThreadStackLimits error on Windows on Arm
        | ... (17 commits)
        | [1][2] 54b36e401d fs: reimplement read and write streams using stream.construct
unstable| ... (20 commits)
        | [1][2] 6443ab9595 module: deprecate module.parent
        | ... (126 commits)
        | [1][2] 5bb4d01fbe doc: add note about clientError writable handling
        | --- begin 32831
        | [ ][ ] 0ddae48b88 test: stop testing --interpreted-frames-native-stack for s390x
        | [ ][ ] aa01fcae49 test: fix test-zlib-unused-weak on V8 8.2
        | [1][2] d1156d0d2f test: rename FinalizationGroup to FinalizationRegistry
        | [1][2] f945c54aa6 deps: V8: cherry-pick 74d50c5063b3
        | [ ][ ] ae7e45c031 deps: V8: cherry-pick e29c62b74854
        | [ ][ ] 7baaab014b deps: V8: cherry-pick 3f8dc4b2e5ba
        | [ ][ ] 56bdec44a8 deps: V8: cherry-pick e1eac1b16c96
        | [ ][ ] 0d50ba5d48 deps: fix V8 8.3 on SmartOS
        | [x][x] 54ae041309 deps: patch V8 to run on Xcode 8
        | [x][x] e9a6ba0a4c deps: V8: silence irrelevant warnings
        | [x][x] 32be677f49 deps: make v8.h compatible with VS2015
        | [x][x] 9dfaf49b84 deps: V8: forward declaration of `Rtl*FunctionTable`
        | [ ][ ] 55f7ae6386 deps: V8: patch register-arm64.h
        | [ ][ ] 6b5ea2efa2 deps: patch V8 to run on older XCode versions
        | [ ][ ] c3866a1b3e deps: V8: un-cherry-pick bd019bd
        | [ ][ ] a48928836a deps: update V8 dtrace & postmortem metadata
        | [ ][ ] db0ed118d8 tools: update V8 gypfiles for V8 8.3
        | [x][x] 308900faef src: update NODE_MODULE_VERSION to 84
        | [ ][ ] 37abad4340 build: reset embedder string to "-node.0"
        \ [x][x] 1d6adf7432 deps: update V8 to 8.3.110.9
        / [✓][✓] aee36a0447 src: delete unused variables to resolve compile time print warning
        | --- end 32831
        | [✓][✓] cfec30fef3 deps: update to ICU 67.1
        | ... (20 commits)
        | [✓][✓] 1aa491a88f http2: add `bytesWritten` test for `Http2Stream`
        | ... (42 commits)
        | [✓][✓] c81e5f699e doc: mark assert.CallTracker experimental
        | ... (85 commits)
        | [✓][✓] c15a27cab3 stream: don't wait for close on legacy streams
        | [✓][✓] f5c11a1a0a stream: don't emit finish after close
        | [✓][✓] 9f14584f2a deps: update archs files for OpenSSL-1.1.1g
        | [ ][ ] 5509c6355c deps: upgrade openssl sources to 1.1.1g
        | [✓][✓] 58682d823a tls: add highWaterMark option for connect
  stable| ... (3 commits)
        | [✓][✓] 53b8133656 doc: avoid tautology in README
        | ... (9 commits)
        | [✓][✓] 654c0ace7b src: fix compiler warnings in node_http2.cc
        | ... (18 commits)
        | [✓][✓] 01e158c600 doc: remove repeated word in modules.md
        | ... (36 commits)
        | [✓][✓] e231e1a0d8 src: elevate v8 namespaces
        | ... (74 commits)
        | [✓][✓] 203776fb71 build: fix LINT_MD_NEWER assignment
        | ... (149 commits)
        | [✓][✓] 8ec533d890 benchmark: use let instead of var in tls
        | ... (299 commits)
        \ [✓][✓] 67d45fb298 2020-03-04 Version 13.10.1 (Current)

Looks like moving to V8 8.3.110.9 introduced the instability (in #32831).

[gabrielschulhof]

The problem also exists if we remove napi_create_reference/napi_delete_reference:

#include <stdio.h>
#include <assert.h>
#include <node_api.h>

static void delete_me(napi_env env, void* data, void* hint) {
  napi_status status;
  napi_value string;
  napi_value error;

  fprintf(stderr, "delete_me\n");

  status = napi_create_string_utf8(env,
                                   "Finalizer exception",
                                   NAPI_AUTO_LENGTH,
                                   &string);
  assert(status == napi_ok);

  status = napi_create_error(env, NULL, string, &error);                                   
  assert(status == napi_ok);

  status = napi_throw(env, error);
  assert(status == napi_ok);
}

static napi_value CreateException(napi_env env, napi_callback_info info) {
  napi_value ret;

  napi_status status = napi_create_external(env, NULL, delete_me, NULL, &ret);
  assert(status == napi_ok);

  return ret;
}

NAPI_MODULE_INIT() {
  napi_value result;

  napi_status status = napi_create_function(env,
                                          "createException",
                                          NAPI_AUTO_LENGTH,
                                          CreateException,
                                          NULL,
                                          &result);
  assert(status == napi_ok);

  return result;
}

[gabrielschulhof]

The code can be reduced to

#include <stdio.h>
#include <assert.h>
#include <node_api.h>

static void delete_me(napi_env env, void* data, void* hint) {
  fprintf(stderr, "delete_me\n");
  napi_status status = napi_throw_error(env, NULL, "Finalizer exception");
  assert(status == napi_ok);
}

static napi_value CreateException(napi_env env, napi_callback_info info) {
  napi_value ret;
  napi_status status = napi_create_external(env, NULL, delete_me, NULL, &ret);
  assert(status == napi_ok);
  return ret;
}

NAPI_MODULE_INIT() {
  napi_value result;
  napi_status status = napi_create_function(env,
                                          "createException",
                                          NAPI_AUTO_LENGTH,
                                          CreateException,
                                          NULL,
                                          &result);
  assert(status == napi_ok);
  return result;
}