Skip to content
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.

Sign up for GitHub

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

Jump to bottom

process: check no handle or request is active after bootstrap #26593

Closed
wants to merge 3 commits into from
Closed

process: check no handle or request is active after bootstrap #26593

wants to merge 3 commits into from

Conversation

joyeecheung
Copy link
Member

worker: create per-Environment message port after bootstrap

process: check no handle or request is active after bootstrap

Checklist
  • make -j4 test (UNIX), or vcbuild test (Windows) passes
  • commit message follows commit guidelines

@nodejs-github-bot
Copy link
Collaborator

@joyeecheung build started: https://ci.nodejs.org/blue/organizations/jenkins/node-test-pull-request-lite-pipeline/detail/node-test-pull-request-lite-pipeline/2865/pipeline

@nodejs-github-bot nodejs-github-bot added c++ Issues and PRs that require attention from people who are familiar with C++. lib / src Issues and PRs related to general changes in the lib or src directory. labels Mar 11, 2019
@joyeecheung
Copy link
Member Author

joyeecheung commented Mar 11, 2019 •
edited
Loading

CI: https://ci.nodejs.org/job/node-test-pull-request/21430/
CI: https://ci.nodejs.org/job/node-test-pull-request/21431/

addaleax
addaleax reviewed Mar 12, 2019
View reviewed changes
lib/internal/worker/io.js Outdated Show resolved Hide resolved
lib/internal/process/worker_thread_only.js Show resolved Hide resolved
src/node_worker.cc Outdated Show resolved Hide resolved
src/node.cc Outdated Show resolved Hide resolved
@joyeecheung
Copy link
Member Author

Rebased & addressed reviews: https://ci.nodejs.org/job/node-test-pull-request/21635/

@joyeecheung
Copy link
Member Author

Oddly enough this only fails cctest on Windows:

01:02:40 [ RUN      ] DebugSymbolsTest.BaseObjectPersistentHandle
01:02:41 uv loop at [0000000141470440] has 2 active handles
01:02:41 [0000000000374C50] async
01:02:41 	Close callback: 000000013F5D7700 AES_cbc_encrypt+2780656
01:02:41 	Data: 00000000003C9B30 
01:02:41 [00000000003753D0] async
01:02:41 	Close callback: 000000013F5D7700 AES_cbc_encrypt+2780656
01:02:41 	Data: 00000000003C9C90 
01:02:41 [00000000003754C0] async
01:02:41 	Close callback: 0000000000000000 
01:02:41 	Data: 000000000039D710 
01:02:41 	(First field): 0000000140864E30 node::ArrayBufferAllocator::`vftable'+669432
01:02:41 [000000000042F008] timer
01:02:41 	Close callback: 65702F6C616E7265 
01:02:41 	Data: 1707D11640021241 
01:02:41 [000000000042F0A8] check
01:02:41 	Close callback: 0C02000000060000 
01:02:41 	Data: 000000C0013D1628 
01:02:41 [000000000042F120] idle
01:02:41 	Close callback: 00000000FFFFFFFF 
01:02:41 	Data: 0000000000000000 
01:02:41 [000000000042F198] prepare
01:02:41 	Close callback: 0000000388C20008 
01:02:41 	Data: 2074656700000008 
01:02:41 [000000000042F210] check
01:02:41 	Close callback: F5656D616E207465 
01:02:41 	Data: 0000000005000002 
01:02:41 [0000000000375010] async
01:02:41 	Close callback: 000000013F5D7700 AES_cbc_encrypt+2780656
01:02:41 	Data: 000000000042EE40 
01:02:41 	(First field): 00000000003B6500 
01:02:41 Administrator: Windows PowerShell[4840]: c:\workspace\node-compile-windows\src\node.cc:366: Assertion `(env->event_loop()->active_handles) == (0)' failed.
01:02:41  1: 000000013F6316FF AES_cbc_encrypt+3149295
01:02:41  2: 000000013F5CC476 AES_cbc_encrypt+2734950
01:02:41  3: 000000013F5CCA43 AES_cbc_encrypt+2736435
01:02:41  4: 000000013F5D15AF AES_cbc_encrypt+2755743

I am guessing there's some test case that adds handles to the NodeTestFixture::current_loop shared across the cctests without cleaning them up. Maybe the check can be relaxed a bit to only check for env->req_wrap_queue() and env->handle_wrap_queue() instead of the entire loop - after all, the primary goal is to make sure that when we implement the snapshot, there is no need to worry about restoring any requests or handles back after deserializing the snapshot. It seems fine to me not to assume that the loop may be controlled by someone else e.g. embedders.

@joyeecheung
Copy link
Member Author

joyeecheung commented Mar 18, 2019 •
edited
Loading

Although, the failure does seem rather odd, as I can't think of any test case before DebugSymbolsTest.BaseObjectPersistentHandle that could add active handles to the loop, and the symbolization of PrintLibuvHandleInformation and DumpBacktrace on Windows does not really seem to make sense (there are so many AES_cbc_encrypt but I think we don't even use it at all?)?

@addaleax
Copy link
Member

Maybe the check can be relaxed a bit to only check for env->req_wrap_queue() and env->handle_wrap_queue() instead of the entire loop - after all, the primary goal is to make sure that when we implement the snapshot, there is no need to worry about restoring any requests or handles back after deserializing the snapshot. It seems fine to me not to assume that the loop may be controlled by someone else e.g. embedders.

That sounds good to me, regardless of the cctest failures. I don’t think we can assume that embedders don’t put handles on the loop before us. (I’m not sure, but you may also be able to check that handle_cleanup_queue_ is empty / handle_cleanup_waiting_ and request_waiting_ are 0?)

and the symbolization of PrintLibuvHandleInformation and DumpBacktrace on Windows does not really seem to make sense?

Does that get better with a debug build?

@joyeecheung
Copy link
Member Author

joyeecheung commented Mar 18, 2019 •
edited
Loading

Does that get better with a debug build?

I don't have a Windows machine at hand so don't know for sure, but AFAIR I have not seen this locally on Windows before, maybe that has something to do with our cross-compilation build step...

I’m not sure, but you may also be able to check that handle_cleanup_queue_ is empty / handle_cleanup_waiting_ and request_waiting_ are 0?

I think we don't need to go that far, for one the per-Environment handles (that are unrefed) will just exist and it's easy to restore them as long as they are not active - but I guess we need to find another way to check if they are active, instead of just doing a hard abort.

@joyeecheung
Copy link
Member Author

Relaxed the checks. New CI: https://ci.nodejs.org/job/node-test-pull-request/21647/

@richardlau
Copy link
Member

Does that get better with a debug build?

I don't have a Windows machine at hand so don't know for sure, but AFAIR I have not seen this locally on Windows before, maybe that has something to do with our cross-compilation build step...

Is this helpful?

C:\work\node\github\nodejs>Debug\cctest.exe
[==========] Running 82 tests from 12 test cases.
[----------] Global test environment set-up.
[----------] 14 tests from AliasBufferTest
[ RUN      ] AliasBufferTest.Float64Array
[       OK ] AliasBufferTest.Float64Array (85 ms)
[ RUN      ] AliasBufferTest.SharedArrayBuffer1
[       OK ] AliasBufferTest.SharedArrayBuffer1 (76 ms)
[ RUN      ] AliasBufferTest.SharedArrayBuffer2
[       OK ] AliasBufferTest.SharedArrayBuffer2 (70 ms)
[ RUN      ] AliasBufferTest.SharedArrayBuffer3
[       OK ] AliasBufferTest.SharedArrayBuffer3 (70 ms)
[ RUN      ] AliasBufferTest.SharedArrayBuffer4
[       OK ] AliasBufferTest.SharedArrayBuffer4 (69 ms)
[ RUN      ] AliasBufferTest.OperatorOverloads
[       OK ] AliasBufferTest.OperatorOverloads (68 ms)
[ RUN      ] AliasBufferTest.OperatorOverloadsRefs
[       OK ] AliasBufferTest.OperatorOverloadsRefs (70 ms)
[ RUN      ] AliasBufferTest.Uint8Array
[       OK ] AliasBufferTest.Uint8Array (72 ms)
[ RUN      ] AliasBufferTest.Int8Array
[       OK ] AliasBufferTest.Int8Array (72 ms)
[ RUN      ] AliasBufferTest.Uint16Array
[       OK ] AliasBufferTest.Uint16Array (71 ms)
[ RUN      ] AliasBufferTest.Int16Array
[       OK ] AliasBufferTest.Int16Array (69 ms)
[ RUN      ] AliasBufferTest.Uint32Array
[       OK ] AliasBufferTest.Uint32Array (71 ms)
[ RUN      ] AliasBufferTest.Int32Array
[       OK ] AliasBufferTest.Int32Array (69 ms)
[ RUN      ] AliasBufferTest.Float32Array
[       OK ] AliasBufferTest.Float32Array (69 ms)
[----------] 14 tests from AliasBufferTest (1011 ms total)

[----------] 2 tests from Base64Test
[ RUN      ] Base64Test.Encode
[       OK ] Base64Test.Encode (0 ms)
[ RUN      ] Base64Test.Decode
[       OK ] Base64Test.Decode (0 ms)
[----------] 2 tests from Base64Test (1 ms total)

[----------] 7 tests from DebugSymbolsTest
[ RUN      ] DebugSymbolsTest.BaseObjectPersistentHandle
[       OK ] DebugSymbolsTest.BaseObjectPersistentHandle (285 ms)
[ RUN      ] DebugSymbolsTest.EnvironmentHandleWrapQueue
uv loop at [0000000143DC2FE0] has 1 active handles
[0000000000511660] async
        Close callback: 000000014054E9F0 <lambda_06a6bf8d53050e163fc34251f122c6c
5>::<lambda_invoker_cdecl> [c:\work\node\github\nodejs\src\node_platform.cc]:L28
6
SymGetLineFromAddr64 returned error : 126
SymFromAddr returned error : 126
        Data: 0000000002AE1800
SymGetLineFromAddr64 returned error : 126
SymFromAddr returned error : 126
        (First field): 000000000056F8A0
[0000000000511780] async
SymGetLineFromAddr64 returned error : 126
SymFromAddr returned error : 126
        Close callback: 0000000000000000
SymGetLineFromAddr64 returned error : 126
SymFromAddr returned error : 126
        Data: 0000000003351690
SymGetLineFromAddr64 returned error : 487
        (First field): 0000000142A6CF78 node::PerIsolatePlatformData::`vftable'
[0000000002AE09F0] timer
SymGetLineFromAddr64 returned error : 126
SymFromAddr returned error : 126
        Close callback: CDCDCDCDCDCDCDCD
SymGetLineFromAddr64 returned error : 126
SymFromAddr returned error : 126
        Data: CDCDCDCDCDCDCDCD
[0000000002AE0A90] check
SymGetLineFromAddr64 returned error : 126
SymFromAddr returned error : 126
        Close callback: CDCDCDCDCDCDCDCD
SymGetLineFromAddr64 returned error : 126
SymFromAddr returned error : 126
        Data: CDCDCDCDCDCDCDCD
[0000000002AE0B08] idle
SymGetLineFromAddr64 returned error : 126
SymFromAddr returned error : 126
        Close callback: CDCDCDCDCDCDCDCD
SymGetLineFromAddr64 returned error : 126
SymFromAddr returned error : 126
        Data: CDCDCDCDCDCDCDCD
[0000000002AE0B80] prepare
SymGetLineFromAddr64 returned error : 126
SymFromAddr returned error : 126
        Close callback: CDCDCDCDCDCDCDCD
SymGetLineFromAddr64 returned error : 126
SymFromAddr returned error : 126
        Data: CDCDCDCDCDCDCDCD
[0000000002AE0BF8] check
SymGetLineFromAddr64 returned error : 126
SymFromAddr returned error : 126
        Close callback: CDCDCDCDCDCDCDCD
SymGetLineFromAddr64 returned error : 126
SymFromAddr returned error : 126
        Data: CDCDCDCDCDCDCDCD
[0000000000511F60] async
SymGetLineFromAddr64 returned error : 126
SymFromAddr returned error : 126
        Close callback: CDCDCDCDCDCDCDCD
SymGetLineFromAddr64 returned error : 126
SymFromAddr returned error : 126
        Data: 0000000002AE07B0
SymGetLineFromAddr64 returned error : 126
SymFromAddr returned error : 126
        (First field): 0000000002AEA950
Developer Command Prompt for VS 2017 - Debug\cctest.exe[13256]: c:\work\node\git
hub\nodejs\src\node.cc:366: Assertion `(env->event_loop()->active_handles) == (0
)' failed.
 1: 000000014064F01A node::DumpBacktrace+138 [c:\work\node\github\nodejs\src\deb
ug_utils.cc]:L270
 2: 0000000140524FE7 node::Abort+39 [c:\work\node\github\nodejs\src\node_errors.
cc]:L165
 3: 0000000140524FA0 node::Assert+208 [c:\work\node\github\nodejs\src\node_error
s.cc]:L183
 4: 000000014052C5A4 node::RunBootstrapping+3524 [c:\work\node\github\nodejs\src
\node.cc]:L366
 5: 00000001400BD85B EnvironmentTestFixture::Env::Env+395 [c:\work\node\github\n
odejs\test\cctest\node_test_fixture.h]:L135
 6: 00000001400B908B DebugSymbolsTest_EnvironmentHandleWrapQueue_Test::TestBody+
91 [c:\work\node\github\nodejs\test\cctest\test_node_postmortem_metadata.cc]:L11
0
 7: 0000000140A23941 testing::internal::HandleSehExceptionsInMethodIfSupported<t
esting::Test,void>+49 [c:\work\node\github\nodejs\deps\gtest\src\gtest.cc]:L2349

 8: 0000000140A23760 testing::internal::HandleExceptionsInMethodIfSupported<test
ing::Test,void>+80 [c:\work\node\github\nodejs\deps\gtest\src\gtest.cc]:L2417
 9: 0000000140A0D6E3 testing::Test::Run+179 [c:\work\node\github\nodejs\deps\gte
st\src\gtest.cc]:L2443
10: 0000000140A0E1C0 testing::TestInfo::Run+224 [c:\work\node\github\nodejs\deps
\gtest\src\gtest.cc]:L2616
11: 0000000140A0E936 testing::TestCase::Run+246 [c:\work\node\github\nodejs\deps
\gtest\src\gtest.cc]:L2731
12: 0000000140A14C3B testing::internal::UnitTestImpl::RunAllTests+891 [c:\work\n
ode\github\nodejs\deps\gtest\src\gtest.cc]:L4727
13: 0000000140A23BB1 testing::internal::HandleSehExceptionsInMethodIfSupported<t
esting::internal::UnitTestImpl,bool>+49 [c:\work\node\github\nodejs\deps\gtest\s
rc\gtest.cc]:L2349
14: 0000000140A238E0 testing::internal::HandleExceptionsInMethodIfSupported<test
ing::internal::UnitTestImpl,bool>+80 [c:\work\node\github\nodejs\deps\gtest\src\
gtest.cc]:L2417
15: 0000000140A0F00F testing::UnitTest::Run+255 [c:\work\node\github\nodejs\deps
\gtest\src\gtest.cc]:L4341
16: 0000000142881D42 RUN_ALL_TESTS+34 [c:\work\node\github\nodejs\deps\gtest\inc
lude\gtest\gtest.h]:L2327
17: 0000000142881D05 main+53 [c:\work\node\github\nodejs\deps\gtest\src\gtest_ma
in.cc]:L37
18: 00000001427667D4 invoke_main+52 [d:\agent\_work\1\s\src\vctools\crt\vcstartu
p\src\startup\exe_common.inl]:L79
19: 00000001427666BE __scrt_common_main_seh+302 [d:\agent\_work\1\s\src\vctools\
crt\vcstartup\src\startup\exe_common.inl]:L288
20: 000000014276657E __scrt_common_main+14 [d:\agent\_work\1\s\src\vctools\crt\v
cstartup\src\startup\exe_common.inl]:L331
21: 0000000142766869 mainCRTStartup+9 [d:\agent\_work\1\s\src\vctools\crt\vcstar
tup\src\startup\exe_main.cpp]:L17
SymGetLineFromAddr64 returned error : 487
22: 00000000777F571D BaseThreadInitThunk+13
SymGetLineFromAddr64 returned error : 487
23: 000000007795385D RtlUserThreadStart+29

C:\work\node\github\nodejs>

@joyeecheung
Copy link
Member Author

joyeecheung commented Mar 19, 2019 •
edited
Loading

Is this helpful?

Thanks, that's helpful, looks like there is a race when closing flush_tasks_ with uv_close which is async (that probably explains why there are 2 active handles in the CI but only 1 in your log). I guess there are 2 test cases in total run before DebugSymbolsTest so there can be at most 2 flush_tasks_ that are still pending to be closed. There's probably some intricate ordering that makes it fail on DebugSymbolsTest instead of others..

@joyeecheung
Copy link
Member Author

I am going to land this later today if no objections.

@joyeecheung
Copy link
Member Author

Landed in 927f29d...197dbf6

joyeecheung added a commit that referenced this pull request Mar 19, 2019
@joyeecheung
worker: create per-Environment message port after bootstrap
9868d54 
PR-URL: #26593
Reviewed-By: Gus Caplan <[email protected]>
Reviewed-By: James M Snell <[email protected]>
joyeecheung added a commit that referenced this pull request Mar 19, 2019
@joyeecheung
process: check no handle or request is active after bootstrap
197dbf6 
PR-URL: #26593
Reviewed-By: Gus Caplan <[email protected]>
Reviewed-By: James M Snell <[email protected]>
targos pushed a commit that referenced this pull request Mar 27, 2019
@joyeecheung @targos
worker: create per-Environment message port after bootstrap
4314dbf 
PR-URL: #26593
Reviewed-By: Gus Caplan <[email protected]>
Reviewed-By: James M Snell <[email protected]>
targos pushed a commit that referenced this pull request Mar 27, 2019
@joyeecheung @targos
process: check no handle or request is active after bootstrap
899de0a 
PR-URL: #26593
Reviewed-By: Gus Caplan <[email protected]>
Reviewed-By: James M Snell <[email protected]>
@targos targos mentioned this pull request Mar 27, 2019
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@addaleax addaleax addaleax left review comments

@jasnell jasnell jasnell approved these changes

@devsnek devsnek devsnek approved these changes

Assignees
No one assigned
Labels
c++ Issues and PRs that require attention from people who are familiar with C++. lib / src Issues and PRs related to general changes in the lib or src directory.
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
6 participants
@joyeecheung @nodejs-github-bot @addaleax @richardlau @jasnell @devsnek