Skip to content

Investigate flaky test-worker-syntax-error-file #22762

Closed
Closed
Investigate flaky test-worker-syntax-error-file#22762
Labels
flaky-testIssues and PRs involving tests that fail intermittently in CI.workerIssues and PRs related to the worker_threads module and Worker API.

Description

@Trott
Trott
opened on Sep 8, 2018
  • Version: 11.0.0-pre (master)
  • Platform: win10 vs2017
  • Subsystem: test worker

https://ci.nodejs.org/job/node-test-binary-windows/19875/COMPILED_BY=vs2017,RUNNER=win10,RUN_SUBSET=3/console

01:14:51 not ok 518 parallel/test-worker-syntax-error-file
01:14:51   ---
01:14:51   duration_ms: 0.211
01:14:51   severity: fail
01:14:51   exitcode: 1
01:14:51   stack: |-
01:14:51     Mismatched <anonymous> function calls. Expected exactly 1, actual 0.
01:14:51         at Object.mustCall (c:\workspace\node-test-binary-windows\test\common\index.js:312:10)
01:14:51         at Object.<anonymous> (c:\workspace\node-test-binary-windows\test\parallel\test-worker-syntax-error-file.js:13:24)
01:14:51         at Module._compile (internal/modules/cjs/loader.js:689:30)
01:14:51         at Object.Module._extensions..js (internal/modules/cjs/loader.js:700:10)
01:14:51         at Module.load (internal/modules/cjs/loader.js:599:32)
01:14:51         at tryModuleLoad (internal/modules/cjs/loader.js:538:12)
01:14:51         at Function.Module._load (internal/modules/cjs/loader.js:530:3)
01:14:51         at Function.Module.runMain (internal/modules/cjs/loader.js:742:12)
01:14:51         at startup (internal/bootstrap/node.js:270:19)
01:14:51   ...

@nodejs/workers

Activity

  1. Trott
    added
    flaky-testIssues and PRs involving tests that fail intermittently in CI.
    on Sep 8, 2018
  2. addaleax
    added
    workerIssues and PRs related to the worker_threads module and Worker API.
    on Sep 8, 2018

  3. addaleax commented on Sep 9, 2018

    @addaleax
    addaleax
    on Sep 9, 2018
    Member

    I have a hard time attempting to reproduce this… do people on @nodejs/platform-windows have more luck on Windows?

  4. bzoz commented on Sep 13, 2018

    @bzoz
    bzoz
    on Sep 13, 2018
    Contributor

    Cannot reproduce on Win10

  5. joyeecheung commented on Sep 19, 2018

    @joyeecheung
    joyeecheung
    on Sep 19, 2018
    Member

    Not exactly sure but this seems to be related:

    Reason parallel/test-worker-syntax-error
    Type JS_TEST_FAILURE
    Failed PR 2 (#22843, #22239)
    Appeared test-azure_msft-win10-x64-3, test-rackspace-win2012r2-x64-1
    First CI https://ci.nodejs.org/job/node-test-pull-request/17202/
    Last CI https://ci.nodejs.org/job/node-test-pull-request/17215/
    Example 
    not ok 521 parallel/test-worker-syntax-error
  ---
  duration_ms: 0.195
  severity: fail
  exitcode: 1
  stack: |-
    Mismatched <anonymous> function calls. Expected exactly 1, actual 0.
        at Object.mustCall (c:\workspace\node-test-binary-windows\test\common\index.js:310:10)
        at Object.<anonymous> (c:\workspace\node-test-binary-windows\test\parallel\test-worker-syntax-error.js:12:24)
        at Module._compile (internal/modules/cjs/loader.js:693:30)
        at Object.Module._extensions..js (internal/modules/cjs/loader.js:704:10)
        at Module.load (internal/modules/cjs/loader.js:603:32)
        at tryModuleLoad (internal/modules/cjs/loader.js:542:12)
        at Function.Module._load (internal/modules/cjs/loader.js:534:3)
        at Function.Module.runMain (internal/modules/cjs/loader.js:746:12)
        at startup (internal/bootstrap/node.js:270:19)
  ...
  6. refack
    added a commit that references this issue on Sep 19, 2018

    test: mark some tests as flaky

    311e72f
  7. targos
    added a commit that references this issue on Sep 20, 2018

    test: mark some tests as flaky

    079760f

  8. Trott commented on Oct 24, 2018

    @Trott
    Trott
    on Oct 24, 2018
    MemberAuthor

    https://ci.nodejs.org/job/node-test-commit-linux/22621/nodes=centos7-64-gcc6/console

    22:48:52 not ok 2016 parallel/test-worker-syntax-error-file
22:48:52   ---
22:48:52   duration_ms: 0.343
22:48:52   severity: fail
22:48:52   exitcode: 1
22:48:52   stack: |-
22:48:52     Mismatched <anonymous> function calls. Expected exactly 1, actual 0.
22:48:52         at Object.mustCall (/home/iojs/build/workspace/node-test-commit-linux/nodes/centos7-64-gcc6/test/common/index.js:306:10)
22:48:52         at Object.<anonymous> (/home/iojs/build/workspace/node-test-commit-linux/nodes/centos7-64-gcc6/test/parallel/test-worker-syntax-error-file.js:13:24)
22:48:52         at Module._compile (internal/modules/cjs/loader.js:707:30)
22:48:52         at Object.Module._extensions..js (internal/modules/cjs/loader.js:718:10)
22:48:52         at Module.load (internal/modules/cjs/loader.js:605:32)
22:48:52         at tryModuleLoad (internal/modules/cjs/loader.js:544:12)
22:48:52         at Function.Module._load (internal/modules/cjs/loader.js:536:3)
22:48:52         at Function.Module.runMain (internal/modules/cjs/loader.js:760:12)
22:48:52         at startup (internal/bootstrap/node.js:304:19)
22:48:52   ...

  9. refack commented on Nov 19, 2018

    @refack
    refack
    on Nov 19, 2018
    Contributor

    AIX
    https://ci.nodejs.org/job/node-test-commit-aix/nodes=aix61-ppc64/18988/
    https://ci.nodejs.org/computer/test-osuosl-aix61-ppc64_be-2/

    Mismatched <anonymous> function calls. Expected exactly 1, actual 0.
    at Object.mustCall (/home/iojs/build/workspace/node-test-commit-aix/nodes/aix61-ppc64/test/common/index.js:312:10)
    at Object.<anonymous> (/home/iojs/build/workspace/node-test-commit-aix/nodes/aix61-ppc64/test/parallel/test-worker-syntax-error.js:12:24)
    at Module._compile (internal/modules/cjs/loader.js:722:30)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:733:10)
    at Module.load (internal/modules/cjs/loader.js:620:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:560:12)
    at Function.Module._load (internal/modules/cjs/loader.js:552:3)
    at Function.Module.runMain (internal/modules/cjs/loader.js:775:12)
    at startup (internal/bootstrap/node.js:300:19)

  10. addaleax commented on Feb 3, 2019

    @addaleax
    addaleax
    on Feb 3, 2019
    Member

    Couldn't reproduce this in 10000 runs on either x64 Linux or x64 Windows.

  11. Trott commented on Feb 3, 2019

    @Trott
    Trott
    on Feb 3, 2019
    MemberAuthor

    ncu-ci walk commit isn't pulling this up. I'm going to close this, but feel free to re-open if there's reason to believe it's still a bug. There's a good chance other fixes that have landed have also fixed this.

  12. Trott
    closed this as completedon Feb 3, 2019
  13. Trott
    reopened this on Apr 29, 2019

  14. Trott commented on Apr 29, 2019

    @Trott
    Trott
    on Apr 29, 2019
    MemberAuthor

    It's back.

    https://ci.nodejs.org/job/node-test-commit-linux/27284/nodes=centos7-64-gcc6/console

    test-rackspace-centos7-x64-1

    00:13:00 not ok 2142 parallel/test-worker-syntax-error-file
00:13:00   ---
00:13:00   duration_ms: 0.487
00:13:00   severity: fail
00:13:00   exitcode: 1
00:13:00   stack: |-
00:13:00     Mismatched <anonymous> function calls. Expected exactly 1, actual 0.
00:13:00         at Object.mustCall (/home/iojs/build/workspace/node-test-commit-linux/nodes/centos7-64-gcc6/test/common/index.js:339:10)
00:13:00         at Object.<anonymous> (/home/iojs/build/workspace/node-test-commit-linux/nodes/centos7-64-gcc6/test/parallel/test-worker-syntax-error-file.js:12:24)
00:13:00         at Module._compile (internal/modules/cjs/loader.js:759:30)
00:13:00         at Object.Module._extensions..js (internal/modules/cjs/loader.js:770:10)
00:13:00         at Module.load (internal/modules/cjs/loader.js:628:32)
00:13:00         at Function.Module._load (internal/modules/cjs/loader.js:555:12)
00:13:00         at Function.Module.runMain (internal/modules/cjs/loader.js:824:10)
00:13:00         at internal/main/run_main_module.js:17:11
00:13:00   ...

  15. addaleax commented on Apr 29, 2019

    @addaleax
    addaleax
    on Apr 29, 2019
    Member

    @Trott I don’t think this can be fixed without somebody logging into the CI machines and figuring out where one can get a reasonable reproduction rate, and then work on that machine

    (Debug logs might also be helpful, esp. NODE_DEBUG_NATIVE=message,worker)

  16. Trott commented on Apr 29, 2019

    @Trott
    Trott
    on Apr 29, 2019
    MemberAuthor

    Was able to replicate it on test-rackspace-centos7-x64-1 with ./tools/test.py -J --repeat 1000 test/parallel/test-worker-syntax-error-file.js in /home/iojs/build/workspace/node-test-commit-linux/nodes/centos7-64-gcc6. Had to get through about 200 runs before it failed.

    Running it prefaced with NODE_DEBUG_NATIVE=message,worker generates this output upon failure:

    === release test-worker-syntax-error-file ===                   
Path: parallel/test-worker-syntax-error-file
Mismatched <anonymous> function calls. Expected exactly 1, actual 0.
    at Object.mustCall (/home/iojs/build/workspace/node-test-commit-linux/nodes/centos7-64-gcc6/test/common/index.js:339:10)
    at Object.<anonymous> (/home/iojs/build/workspace/node-test-commit-linux/nodes/centos7-64-gcc6/test/parallel/test-worker-syntax-error-file.js:12:24)
    at Module._compile (internal/modules/cjs/loader.js:759:30)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:770:10)
    at Module.load (internal/modules/cjs/loader.js:628:32)
    at Function.Module._load (internal/modules/cjs/loader.js:555:12)
    at Function.Module.runMain (internal/modules/cjs/loader.js:824:10)
    at internal/main/run_main_module.js:17:11
Worker (0:2) Creating new worker instance with thread id 1
MessagePort (0:3) Created message port
Worker (0:2) Preparation for worker 1 finished
MessagePort (0:3) Start receiving messages
MessagePort (0:3) Start receiving messages
MessagePort (0:6) Created message port
MessagePort (0:7) Created message port
MessagePort (0:6) Start receiving messages
MessagePort (0:7) Closing message port, data set = 1
MessagePort (0:6) Start receiving messages
MessagePort (0:7) MessagePort::OnClose()
Worker (0:2) Creating isolate for worker with id 1
Worker (0:2) Starting worker with id 1
Worker (0:2) Created Environment for worker with id 1
MessagePort (1:2) Created message port
Worker (0:2) Created message port for worker 1
MessagePort (1:2) Start receiving messages
MessagePort (1:2) Start receiving messages
Worker (0:2) Loaded environment for worker 1
MessagePort (1:2) Running MessagePort::OnMessage()
MessagePort (1:2) MessagePort has message, receiving = 1
MessagePort (1:3) Created message port
MessagePort (0:3) Adding message to incoming queue
MessagePort (0:3) Running MessagePort::OnMessage()
MessagePort (0:3) MessagePort has message, receiving = 1
MessagePort (0:3) MessagePort has message, receiving = 1
MessagePort (0:3) Adding message to incoming queue
Worker (0:2) Worker 1 called Exit(1)
Worker (0:2) Exiting thread for worker 1 with exit code 1
MessagePort (1:2) Closing message port, data set = 1
MessagePort (1:2) Closing message port, data set = 1
MessagePort (1:3) Closing message port, data set = 1
MessagePort (1:3) MessagePort::OnClose()
MessagePort (1:2) MessagePort::OnClose()
MessagePort (0:3) Closing message port, data set = 1
MessagePort (0:6) Running MessagePort::OnMessage()
MessagePort (0:6) MessagePort has message, receiving = 1
MessagePort (0:6) Closing message port, data set = 1
MessagePort (0:6) MessagePort::OnClose()
MessagePort (0:3) MessagePort::OnClose()
Worker (0:2) Worker 1 thread stops
Worker (0:2) Worker 1 dispose isolate
Worker (0:2) Worker 1 destroyed
Command: out/Release/node /home/iojs/build/workspace/node-test-commit-linux/nodes/centos7-64-gcc6/test/parallel/test-worker-syntax-error-file.js

  17. addaleax commented on Apr 29, 2019

    @addaleax
    addaleax
    on Apr 29, 2019
    Member

    @Trott Thanks, that’s definitely helpful.

    MessagePort (0:3) Closing message port, data set = 1

    For some reasons, it seems the internal message port on the parent side closes prematurely, before the drainMessagePort() call in the onexit handler runs. I don’t understand why this happens – the message port should be closed because the sibling in the child thread closes, but that should only happen after releasing all currently pending messages.

    @Trott Do you think you could run this with this extra debugging patch + post failure output again? I’m not sure if it helps, but it could confirm that a) we close the message port with a message still pending and b) help figure out why the message port is being closed in this way to begin with.

    diff --git a/src/node_messaging.cc b/src/node_messaging.cc
index 77ed959477f2..37f0080f9c46 100644
--- a/src/node_messaging.cc
+++ b/src/node_messaging.cc
@@ -516,6 +516,7 @@ void MessagePort::TriggerAsync() {
 
 void MessagePort::Close(v8::Local<v8::Value> close_callback) {
   Debug(this, "Closing message port, data set = %d", static_cast<int>(!!data_));
+  DumpBacktrace(stderr);
 
   if (data_) {
     // Wrap this call with accessing the mutex, so that TriggerAsync()
@@ -640,7 +641,8 @@ bool MessagePort::IsSiblingClosed() const {
 }
 
 void MessagePort::OnClose() {
-  Debug(this, "MessagePort::OnClose()");
+  Debug(this, "MessagePort::OnClose() with %zd pending messages",
+        (ssize_t)(data_ ? data_->incoming_messages_.size() : -1));
   if (data_) {
     data_->owner_ = nullptr;
     data_->Disentangle();

  18. Trott commented on Apr 30, 2019

    @Trott
    Trott
    on Apr 30, 2019
    MemberAuthor

    @addaleax Here's the output with your patch:

    === release test-worker-syntax-error-file ===                   
Path: parallel/test-worker-syntax-error-file
Mismatched <anonymous> function calls. Expected exactly 1, actual 0.
    at Object.mustCall (/home/iojs/build/workspace/node-test-commit-linux/nodes/centos7-64-gcc6/test/common/index.js:339:10)
    at Object.<anonymous> (/home/iojs/build/workspace/node-test-commit-linux/nodes/centos7-64-gcc6/test/parallel/test-worker-syntax-error-file.js:12:24)
    at Module._compile (internal/modules/cjs/loader.js:759:30)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:770:10)
    at Module.load (internal/modules/cjs/loader.js:628:32)
    at Function.Module._load (internal/modules/cjs/loader.js:555:12)
    at Function.Module.runMain (internal/modules/cjs/loader.js:824:10)
    at internal/main/run_main_module.js:17:11
Worker (0:2) Creating new worker instance with thread id 1
MessagePort (0:3) Created message port
Worker (0:2) Preparation for worker 1 finished
MessagePort (0:3) Start receiving messages
MessagePort (0:3) Start receiving messages
MessagePort (0:6) Created message port
MessagePort (0:7) Created message port
MessagePort (0:6) Start receiving messages
MessagePort (0:7) Closing message port, data set = 1
 1: 0x9d1c42 node::worker::Message::Serialize(node::Environment*, v8::Local<v8::Context>, v8::Local<v8::Value>, v8::Local<v8::Value>, v8::Local<v8::Object>) [out/Release/node]
 2: 0x9d2037 node::worker::MessagePort::PostMessage(node::Environment*, v8::Local<v8::Value>, v8::Local<v8::Value>) [out/Release/node]
 3: 0x9d252c node::worker::MessagePort::PostMessage(v8::FunctionCallbackInfo<v8::Value> const&) [out/Release/node]
 4: 0xb8c926  [out/Release/node]
 5: 0xb8e839 v8::internal::Builtin_HandleApiCall(int, unsigned long*, v8::internal::Isolate*) [out/Release/node]
 6: 0x1a84022  [out/Release/node]
MessagePort (0:6) Start receiving messages
MessagePort (0:7) MessagePort::OnClose() with -1 pending messages
Worker (0:2) Creating isolate for worker with id 1
Worker (0:2) Starting worker with id 1
Worker (0:2) Created Environment for worker with id 1
MessagePort (1:2) Created message port
Worker (0:2) Created message port for worker 1
MessagePort (1:2) Start receiving messages
MessagePort (1:2) Start receiving messages
Worker (0:2) Loaded environment for worker 1
MessagePort (1:2) Running MessagePort::OnMessage()
MessagePort (1:2) MessagePort has message, receiving = 1
MessagePort (1:3) Created message port
MessagePort (0:3) Adding message to incoming queue
MessagePort (0:3) Running MessagePort::OnMessage()
MessagePort (0:3) MessagePort has message, receiving = 1
MessagePort (0:3) MessagePort has message, receiving = 1
MessagePort (0:3) Adding message to incoming queue
Worker (0:2) Worker 1 called Exit(1)
Worker (0:2) Exiting thread for worker 1 with exit code 1
MessagePort (1:2) Closing message port, data set = 1
 1: 0x9d0d4e node::worker::MessagePort::Close(v8::Local<v8::Value>) [out/Release/node]
 2: 0xa19338  [out/Release/node]
 3: 0xa1dc36 node::worker::Worker::Run() [out/Release/node]
 4: 0xa1e19c  [out/Release/node]
 5: 0x7fa13e1c3dd5  [/lib64/libpthread.so.0]
 6: 0x7fa13deecead clone [/lib64/libc.so.6]
MessagePort (1:2) Closing message port, data set = 1
 1: 0x9d0d4e node::worker::MessagePort::Close(v8::Local<v8::Value>) [out/Release/node]
 2: 0x932db5 node::Environment::CleanupHandles() [out/Release/node]
 3: 0x93304b node::Environment::RunCleanup() [out/Release/node]
 4: 0xa1938f  [out/Release/node]
 5: 0xa1dc36 node::worker::Worker::Run() [out/Release/node]
 6: 0xa1e19c  [out/Release/node]
 7: 0x7fa13e1c3dd5  [/lib64/libpthread.so.0]
 8: 0x7fa13deecead clone [/lib64/libc.so.6]
MessagePort (1:3) Closing message port, data set = 1
 1: 0x9d0d4e node::worker::MessagePort::Close(v8::Local<v8::Value>) [out/Release/node]
 2: 0x932db5 node::Environment::CleanupHandles() [out/Release/node]
 3: 0x93304b node::Environment::RunCleanup() [out/Release/node]
 4: 0xa1938f  [out/Release/node]
 5: 0xa1dc36 node::worker::Worker::Run() [out/Release/node]
 6: 0xa1e19c  [out/Release/node]
 7: 0x7fa13e1c3dd5  [/lib64/libpthread.so.0]
 8: 0x7fa13deecead clone [/lib64/libc.so.6]
MessagePort (1:3) MessagePort::OnClose() with 0 pending messages
MessagePort (1:2) MessagePort::OnClose() with 2 pending messages
Worker (0:2) Worker 1 thread stops
Worker (0:2) Worker 1 dispose isolate
MessagePort (0:3) Closing message port, data set = 1
 1: 0x9d392b node::worker::MessagePort::OnMessage() [out/Release/node]
 2: 0xae597f  [out/Release/node]
 3: 0xaf7228  [out/Release/node]
 4: 0xae62bb uv_run [out/Release/node]
 5: 0x9cdabc node::NodeMainInstance::Run() [out/Release/node]
 6: 0x964041 node::Start(int, char**) [out/Release/node]
 7: 0x7fa13de113d5 __libc_start_main [/lib64/libc.so.6]
 8: 0x902655  [out/Release/node]
MessagePort (0:6) Running MessagePort::OnMessage()
MessagePort (0:6) MessagePort has message, receiving = 1
MessagePort (0:6) Closing message port, data set = 1
 1: 0x9d392b node::worker::MessagePort::OnMessage() [out/Release/node]
 2: 0xae597f  [out/Release/node]
 3: 0xaf7228  [out/Release/node]
 4: 0xae62bb uv_run [out/Release/node]
 5: 0x9cdabc node::NodeMainInstance::Run() [out/Release/node]
 6: 0x964041 node::Start(int, char**) [out/Release/node]
 7: 0x7fa13de113d5 __libc_start_main [/lib64/libc.so.6]
 8: 0x902655  [out/Release/node]
MessagePort (0:6) MessagePort::OnClose() with 0 pending messages
MessagePort (0:3) MessagePort::OnClose() with 1 pending messages
Worker (0:2) Worker 1 destroyed
  19. addaleax
    added a commit that references this issue on May 14, 2019

    worker: use special message as MessagePort close command

    489d500
  20. addaleax
    closed this as completedin 6019060on May 17, 2019
  21. targos
    added a commit that references this issue on May 18, 2019

    worker: use special message as MessagePort close command

    e004d42
  22. sjarmak
    added a commit that references this issue on Jul 27, 2026

    worker: use special message as MessagePort close command

    6019060
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    flaky-testIssues and PRs involving tests that fail intermittently in CI.workerIssues and PRs related to the worker_threads module and Worker API.

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions