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.

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

Linux: nsfw watcher crashes when inotify limit reached #131957

Closed
bpasero opened this issue Aug 31, 2021 · 5 comments
Closed

Linux: nsfw watcher crashes when inotify limit reached #131957

bpasero opened this issue Aug 31, 2021 · 5 comments
Assignees
Labels
bug Issue identified by VS Code Team member as probable bug file-watcher File watcher freeze-slow-crash-leak VS Code crashing, performance, freeze and memory leak issues insiders-released Patch has been released in VS Code Insiders linux Issues with VS Code on Linux verified Verification succeeded

Comments

@bpasero
Copy link
Member

bpasero commented Aug 31, 2021

Steps:

  • configure /etc/sysctl.conf by adding fs.inotify.max_user_watches=4096
  • save file (as admin), restart OS
  • open a .code-workspace that has more than 1 large folder in it (so that nsfw is used), e.g. open vscode
  • notice in devtools this error is reported:
3963:0831/080714.882510:INFO:CONSOLE(206)] "%c  ERR color: #f33 [File Watcher (nsfw)] terminated unexpectedly and is restarted again...", source: vscode-file://vscode-app/home/parallels/GitDevelopment/monaco/out/vs/platform/log/common/log.js (206)
terminate called after throwing an instance of 'Napi::Error'
  what():  Inotify limit reached

I am positive this used to work in a way that we could catch the error and show it to the user via this code:

process.on('uncaughtException', (e: Error | string) => {
// Specially handle ENOSPC errors that can happen when
// the watcher consumes so many file descriptors that
// we are running into a limit. We only want to warn
// once in this case to avoid log spam.
// See https://github.com/microsoft/vscode/issues/7950
if (e === 'Inotify limit reached' && !this.enospcErrorLogged) {
this.enospcErrorLogged = true;
this.error('Inotify limit reached (ENOSPC)');
}
});

But that is no longer the case it seems.

@bpasero bpasero added freeze-slow-crash-leak VS Code crashing, performance, freeze and memory leak issues linux Issues with VS Code on Linux file-watcher File watcher labels Aug 31, 2021
@bpasero bpasero changed the title Linux: nsfw watcher crashes when inotify limit reached Linux: nsfw watcher crashes when inotify limit reached Aug 31, 2021
@deepak1556
Copy link
Collaborator

Root issue is similar to #111288 and #106399

Lets try building the native module with NODE_API_SWALLOW_UNTHROWABLE_EXCEPTIONS nodejs/node-addon-api#975 and see if it helps.

@deepak1556
Copy link
Collaborator

deepak1556 commented Sep 7, 2021

Crash reason:  SIGABRT
Crash address: 0x3e800002d24
Process uptime: not available

Thread 0 (crashed)
 0  libc.so.6!__GI_raise [raise.c : 51 + 0x0]
    rax = 0x0000000000000000   rdx = 0x0000000000000000
    rcx = 0x00007efdf36b57d5   rbx = 0x00007efdf1d4f6c0
    rsi = 0x00007fffef8d3b80   rdi = 0x0000000000000002
    rbp = 0x00001407ea483140   rsp = 0x00007fffef8d3b80
     r8 = 0x0000000000000000    r9 = 0x00007fffef8d3b80
    r10 = 0x0000000000000008   r11 = 0x0000000000000246
    r12 = 0x00001407ea25b180   r13 = 0x00007efdec300ed6
    r14 = 0x0000000000000000   r15 = 0x00001407ea206500
    rip = 0x00007efdf36b57d5
    Found by: given as instruction pointer in context
 1  libc.so.6!__GI_abort [abort.c : 79 + 0xa]
    rbx = 0x00007efdf1d4f6c0   rbp = 0x00001407ea483140
    rsp = 0x00007fffef8d3ca0   r12 = 0x00001407ea25b180
    r13 = 0x00007efdec300ed6   r14 = 0x0000000000000000
    r15 = 0x00001407ea206500   rip = 0x00007efdf369e895
    Found by: call frame info
 2  libstdc++.so.6!__gnu_cxx::__verbose_terminate_handler() [clone .cold] + 0x5d
    rbx = 0x00007efdf383d5e0   rbp = 0x00001407ea483140
    rsp = 0x00007fffef8d3dd0   r12 = 0x00001407ea25b180
    r13 = 0x00007efdec300ed6   r14 = 0x0000000000000000
    r15 = 0x00001407ea206500   rip = 0x00007efdf2b30941
    Found by: call frame info
 3  libstdc++.so.6!__cxxabiv1::__terminate(void (*)()) + 0xc
    rbx = 0x00001407ea347680   rbp = 0x00001407ea347660
    rsp = 0x00007fffef8d3e00   r12 = 0x00007efdec326bb8
    r13 = 0x00007efdec300ed6   r14 = 0x0000000000000000
    r15 = 0x00001407ea206500   rip = 0x00007efdf2b3c32c
    Found by: call frame info
 4  libstdc++.so.6!std::terminate() [eh_terminate.cc : 58 + 0xd]
    rbx = 0x00001407ea347680   rbp = 0x00001407ea347660
    rsp = 0x00007fffef8d3e10   r12 = 0x00007efdec326bb8
    r13 = 0x00007efdec300ed6   r14 = 0x0000000000000000
    r15 = 0x00001407ea206500   rip = 0x00007efdf2b3c397
    Found by: call frame info
 5  libstdc++.so.6!__cxa_throw [eh_throw.cc : 95 + 0x5]
    rbx = 0x00001407ea347680   rbp = 0x00001407ea347660
    rsp = 0x00007fffef8d3e20   r12 = 0x00007efdec326bb8
    r13 = 0x00007efdec300ed6   r14 = 0x0000000000000000
    r15 = 0x00001407ea206500   rip = 0x00007efdf2b3c649
    Found by: call frame info
 6  nsfw.node!Napi::Function::Call(napi_value__*, unsigned long, napi_value__* const*) const [napi-inl.h : 2224 + 0x41]
    rbx = 0x00001407ea347680   rbp = 0x00007fffef8d3ea0
    rsp = 0x00007fffef8d3e40   r12 = 0x00001407ea57d760
    r13 = 0x0000000000000000   r14 = 0x0000000000000000
    r15 = 0x00001407ea206500   rip = 0x00007efdec3010fa
    Found by: call frame info
 7  nsfw.node!Napi::Function::Call(napi_value__*, std::initializer_list<napi_value__*> const&) const [napi-inl.h : 2210 + 0x31]
    rbx = 0x00007fffef8d3fc8   rbp = 0x00007fffef8d3ee0
    rsp = 0x00007fffef8d3eb0   r12 = 0x00001407ea57d760
    r13 = 0x0000000000000000   r14 = 0x0000000000000000
    r15 = 0x00001407ea206500   rip = 0x00007efdec30101c
    Found by: call frame info
 8  nsfw.node!Napi::Function::Call(std::initializer_list<napi_value__*> const&) const [napi-inl.h : 2195 + 0x46]
    rbx = 0x00001407ea57d760   rbp = 0x00007fffef8d3f20
    rsp = 0x00007fffef8d3ef0   r12 = 0x00001407ea57d760
    r13 = 0x0000000000000000   r14 = 0x0000000000000000
    r15 = 0x00001407ea206500   rip = 0x00007efdec300fd4
    Found by: call frame info
 9  nsfw.node!NSFW::pollForEvents()::{lambda(Napi::Env(Napi::Env, Napi::Function), Napi::Function)#1}::operator() const [NSFW.cpp : 272 + 0x39]
    rbx = 0x00001407ea57d760   rbp = 0x00007fffef8d3fe0
    rsp = 0x00007fffef8d3f30   r12 = 0x00001407ea57d760
    r13 = 0x0000000000000000   r14 = 0x0000000000000000
    r15 = 0x00001407ea206500   rip = 0x00007efdec2fda7c
    Found by: call frame info
10  nsfw.node!void std::__invoke_impl<void, NSFW::pollForEvents()::{lambda(Napi::Env&, Napi::Function)#1}, Napi::Env, Napi::Function>(std::__invoke_other, NSFW::pollForEvents()::{lambda(Napi::Env&, Napi::Function)#1}, Napi::Env&&, Napi::Function) [invoke.h : 60 + 0x45]
    rbx = 0x00007fffef8d40b0   rbp = 0x00007fffef8d4020
    rsp = 0x00007fffef8d3ff0   r12 = 0x00001407ea57d760
    r13 = 0x0000000000000000   r14 = 0x0000000000000000
    r15 = 0x00001407ea206500   rip = 0x00007efdec2ff562
    Found by: call frame info
11  nsfw.node!_ZSt10__invoke_rIvRZN4NSFW13pollForEventsEvEUlN4Napi3EnvENS1_8FunctionEE_JS2_S3_EENSt9enable_ifIXsrSt6__and_IJSt7is_voidIT_ESt14__is_invocableIT0_JDpT1_EEEE5valueES9_E4typeEOSC_DpOSD_ [invoke.h : 153 + 0x38]
    rbx = 0x00007fffef8d40c0   rbp = 0x00007fffef8d4060
    rsp = 0x00007fffef8d4030   r12 = 0x00007fffef8d40b0
    r13 = 0x0000000000000000   r14 = 0x0000000000000000
    r15 = 0x00001407ea206500   rip = 0x00007efdec2ff2b6
    Found by: call frame info
12  nsfw.node!std::_Function_handler<void (Napi::Env, Napi::Function), NSFW::pollForEvents()::{lambda(Napi::Env, Napi::Function)#1}>::_M_invoke(std::_Any_data const&, Napi::Env&&, Napi::Function&&) [std_function.h : 291 + 0x38]
    rbx = 0x00007fffef8d40c0   rbp = 0x00007fffef8d40a0
    rsp = 0x00007fffef8d4070   r12 = 0x00007fffef8d40b0
    r13 = 0x0000000000000000   r14 = 0x0000000000000000
    r15 = 0x00001407ea206500   rip = 0x00007efdec2ff01b
    Found by: call frame info
13  nsfw.node!std::function<void (Napi::Env, Napi::Function)>::operator()(Napi::Env, Napi::Function) const [std_function.h : 622 + 0x35]
    rbx = 0x00007efdec2fefcc   rbp = 0x00007fffef8d40e0
    rsp = 0x00007fffef8d40b0   r12 = 0x00007fffef8d40b0
    r13 = 0x0000000000000000   r14 = 0x0000000000000000
    r15 = 0x00001407ea206500   rip = 0x00007efdec3040f9
    Found by: call frame info
14  nsfw.node!Napi::ThreadSafeFunction::CallJS(napi_env__*, napi_value__*, void*, void*) [napi-inl.h : 5570 + 0x45]
    rbx = 0x00001407ea57d780   rbp = 0x00007fffef8d4170
    rsp = 0x00007fffef8d40f0   r12 = 0x00001407ea2102c0
    r13 = 0x0000000000000000   r14 = 0x0000000000000000
    r15 = 0x00001407ea206500   rip = 0x00007efdec3030d3
    Found by: call frame info
15  code-oss!v8impl::(anonymous namespace)::ThreadSafeFunction::AsyncCb(uv_async_s*) [node_api.cc : 338 + 0xe]
    rbx = 0x00001407ea57d780   rbp = 0x00007fffef8d4220
    rsp = 0x00007fffef8d4180   r12 = 0x00001407ea2102c0
    r13 = 0x0000000000000000   r14 = 0x0000000000000000
    r15 = 0x00001407ea206500   rip = 0x000055c1a630d584
    Found by: call frame info
16  code-oss!uv__async_io [async.c : 163 + 0x5]
    rbx = 0x0000000000000000   rbp = 0x00007fffef8d4670
    rsp = 0x00007fffef8d4230   r12 = 0x00001407ea2103b0
    r13 = 0x00001407ea210348   r14 = 0x000055c1a6af9ee0
    r15 = 0x000055c1a6afa098   rip = 0x000055c1a0453d1e
    Found by: call frame info
17  code-oss!uv__io_poll [linux-core.c : 462 + 0x5]
    rbx = 0x000055c1a6afa0b0   rbp = 0x00007fffef8d7790
    rsp = 0x00007fffef8d4680   r12 = 0x0000000000000001
    r13 = 0x00007fffef8d4680   r14 = 0x0000000000000000
    r15 = 0x0000000000000001   rip = 0x000055c1a0462533
    Found by: call frame info
18  code-oss!uv_run [core.c : 385 + 0x8]
    rbx = 0x00007fffef8d7700   rbp = 0x00007fffef8d7800
    rsp = 0x00007fffef8d77a0   r12 = 0x000055c19f6e8f90
    r13 = 0x000055c1a6af9f30   r14 = 0x000055c1a6af9f01
    r15 = 0x000055c1a6af9ee0   rip = 0x000055c1a04540e1
    Found by: call frame info
19  code-oss!electron::NodeMain(int, char**) [node_main.cc : 253 + 0x7]
    rbx = 0x00001407ea2200a0   rbp = 0x00007fffef8d7af0
    rsp = 0x00007fffef8d7810   r12 = 0x0000018400000000
    r13 = 0x00001407ea230800   r14 = 0x00001407ea349b80
    r15 = 0x00001407ea229810   rip = 0x000055c1a05c9f63
    Found by: call frame info
20  code-oss!main [electron_main.cc : 297 + 0xb]
    rbx = 0x00007fffef8d7b00   rbp = 0x00007fffef8d7bf0
    rsp = 0x00007fffef8d7b00   r12 = 0x00007fffef8d7b00
    r13 = 0x0000000000000000   r14 = 0x00007fffef8d7ce8
    r15 = 0x0000000000000003   rip = 0x000055c1a0464bd1
    Found by: call frame info

@deepak1556
Copy link
Collaborator

Issue is different from originally thought to be #131957 (comment)

JS callback from nsfw https://github.com/Axosoft/nsfw/blob/e8a6e953b5ec4ed09b1e73cea944fcfc6149ea3e/src/NSFW.cpp#L272 can throw via https://github.com/nodejs/node-addon-api/blob/da2e754a021e418a3ca36f3c10ea134c9541959f/napi-inl.h#L2217-L2225 because the default JS error callback throws https://github.com/Axosoft/nsfw/blob/e8a6e953b5ec4ed09b1e73cea944fcfc6149ea3e/js/src/index.js#L63 leading to the above crash. There are couple of fixes for this,

  1. On our side, we can provide our own errorCallback in the NSFW constructor https://github.com/Axosoft/nsfw/blob/e8a6e953b5ec4ed09b1e73cea944fcfc6149ea3e/index.d.ts#L64 so basically it will allow us to replace

    process.on('uncaughtException', (e: Error | string) => {
    // Specially handle ENOSPC errors that can happen when
    // the watcher consumes so many file descriptors that
    // we are running into a limit. We only want to warn
    // once in this case to avoid log spam.
    // See https://github.com/microsoft/vscode/issues/7950
    if (e === 'Inotify limit reached' && !this.enospcErrorLogged) {
    this.enospcErrorLogged = true;
    this.error('Inotify limit reached (ENOSPC)');
    }
    });
    while also fixing the above crash.

  2. On the native module side, catch the exception from C++ side and rethrow it

diff --git a/src/NSFW.cpp b/src/NSFW.cpp
index abd0bb0..d83e5b3 100644
--- a/src/NSFW.cpp
+++ b/src/NSFW.cpp
@@ -269,7 +269,11 @@ void NSFW::pollForEvents() {
         const std::string &error = mInterface->getError();
         mErrorCallback.NonBlockingCall([error](Napi::Env env, Napi::Function jsCallback) {
           Napi::Value jsError = Napi::Error::New(env, error).Value();
-          jsCallback.Call({ jsError });
+          try {
+            jsCallback.Call({ jsError });
+          } catch (const Napi::Error& e) {
+            e.ThrowAsJavaScriptException();
+          }
         });
         mRunning = false;
         break;

@deepak1556
Copy link
Collaborator

I can try upstreaming 2) in the next debt week but 1) should unblock us for #132483

@bpasero bpasero added the bug Issue identified by VS Code Team member as probable bug label Sep 7, 2021
@bpasero bpasero closed this as completed in 6e5ffbd Sep 7, 2021
@bpasero bpasero self-assigned this Sep 7, 2021
@bpasero bpasero added this to the September 2021 milestone Sep 7, 2021
@bpasero
Copy link
Member Author

bpasero commented Sep 7, 2021

1 works 👍

@lramos15 lramos15 added the verified Verification succeeded label Sep 29, 2021
@github-actions github-actions bot locked and limited conversation to collaborators Oct 22, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
bug Issue identified by VS Code Team member as probable bug file-watcher File watcher freeze-slow-crash-leak VS Code crashing, performance, freeze and memory leak issues insiders-released Patch has been released in VS Code Insiders linux Issues with VS Code on Linux verified Verification succeeded
Projects
Archived in project
Development

No branches or pull requests

4 participants
@bpasero @deepak1556 @lramos15 and others