Application intermittent crashed with SIGSEGV signal.

[RomanBurunkov]

Hello,

I use net-ping 1.2.1(node-raw-socket 1.6.0) in my app with node 8 on Debian based system.

I found out that from time to time my node app crashes with SIGSEGV and generates core file.
I tried to check it, but don't have much experience in that.

But it looks like crashes related to the node-raw-socket, because it crashes right after performing something related to the node-raw-socket.

Here is llnode stack trace:

(llnode) v8 bt
 * thread #1: tid = 0, 0x0000000000a52486 node`v8::Object::Get(v8::Local<v8::Value>) + 22, name = 'node', stop reason = signal SIGSEGV
  * frame #0: 0x0000000000a52486 node`v8::Object::Get(v8::Local<v8::Value>) + 22
    frame #1: 0x00007f94c38f00bc raw.node`raw::SocketWrap::HandleIOEvent(int, int) + 508
    frame #2: 0x00000000014244b8 node`??? + 952
    frame #3: 0x0000000001412d86 node`uv_run + 342
    frame #4: 0x00000000008d433d node`node::Start(uv_loop_s*, int, char const* const*, int, char const* const*) + 1197
    frame #5: 0x00000000008cc7fd node`node::Start(int, char**) + 365
    frame #6: 0x00007f94c5b17830 libc.so.6`__libc_start_main(main=(node`main), argc=4, argv=0x00007ffc4a33f8d8, init=<unavailable>, fini=<unavailable>, rtld_fini=<unavailable>, stack_end=0x00007ffc4a33f8c8) + 240 at libc-start.c:291
    frame #7: 0x000000000089b0b1 node`_start + 41

0x00007f94c38f00bc raw.node`raw::SocketWrap::HandleIOEvent(int, int) + 508

JS ping closure function:

var genPing = (host, cbSuccess, cbError, reqTimeout, logFunc)=>{
  reqTimeout = (reqTimeout || 2)*1000;
  return ()=>{
    var session   = netPing.createSession({
      packetSize : 64,
      retries    : 2,
      timeout    : reqTimeout,
    });
    session.on('error', (error)=>{
      logFunc(error.toString());
      cbError(error.toString());
      session.close();
    });

    session.pingHost(host, (error, target, sent, rcvd)=>{
      session.close();
      if(error) {
        cbError(error.toString());
        return;
      }
      var rtt = rcvd - sent;
      if(typeof rtt !== 'number' || rtt !== rtt) rtt = 0;
      cbSuccess({status:'ok', result:'ok', data:rtt});
    });
  };
}

[RomanBurunkov]

Today I've got one more crash with the same trace:

(llnode) v8 bt
 * thread #1: tid = 0, 0x0000000000a5247a node`v8::Object::Get(v8::Local<v8::Value>) + 10, name = 'node', stop reason = signal SIGSEGV
  * frame #0: 0x0000000000a5247a node`v8::Object::Get(v8::Local<v8::Value>) + 10
    frame #1: 0x00007f07c4b1f0bc raw.node`raw::SocketWrap::HandleIOEvent(int, int) + 508
    frame #2: 0x00000000014244b8 node`??? + 952
    frame #3: 0x0000000001412d86 node`uv_run + 342
    frame #4: 0x00000000008d433d node`node::Start(uv_loop_s*, int, char const* const*, int, char const* const*) + 1197
    frame #5: 0x00000000008cc7fd node`node::Start(int, char**) + 365
    frame #6: 0x00007f07c6d46830 libc.so.6`__libc_start_main(main=(node`main), argc=4, argv=0x00007ffc6858ca98, init=<unavailable>, fini=<unavailable>, rtld_fini=<unavailable>, stack_end=0x00007ffc6858ca88) + 240 at libc-start.c:291
    frame #7: 0x000000000089b0b1 node`_start + 41

[RomanBurunkov]

I've change my ping function code and got another result. In this case I've got SIGAB:

(llnode) v8 bt
 * thread #1: tid = 0, 0x00007effe99a7428 libc.so.6`__GI_raise(sig=6) + 56 at raise.c:54, name = 'node', stop reason = signal SIGABRT
  * frame #0: 0x00007effe99a7428 libc.so.6`__GI_raise(sig=6) + 56 at raise.c:54
    frame #1: 0x00007effe99a902a libc.so.6`__GI_abort + 362 at abort.c:89
    frame #2: 0x00007effe999fbd7 libc.so.6`__assert_fail_base(fmt="", assertion=<unavailable>, file=<unavailable>, line=<unavailable>, function=<unavailable>) + 279 at assert.c:92
    frame #3: 0x00007effe999fc82 libc.so.6`__GI___assert_fail(assertion=<unavailable>, file=<unavailable>, line=<unavailable>, function=<unavailable>) + 66 at assert.c:101
    frame #4: 0x000000000141b0a9 node`uv_poll_stop + 121
    frame #5: 0x00007effe77662cd raw.node`raw::SocketWrap::Pause(Nan::FunctionCallbackInfo<v8::Value> const&) + 701
    frame #6: 0x00007effe7765a25 raw.node`Nan::imp::FunctionCallbackWrapper(v8::FunctionCallbackInfo<v8::Value> const&) + 133
    frame #7: 0x0000000000a5fd83 node`v8::internal::FunctionCallbackArguments::Call(void (*)(v8::FunctionCallbackInfo<v8::Value> const&)) + 403
    frame #8: 0x0000000000ad6f2c node`??? + 332
    frame #9: 0x0000000000ad7b7f node`v8::internal::Builtin_HandleApiCall(int, v8::internal::Object**, v8::internal::Isolate*) + 175
    frame #10: 0x00001b86303042fd <exit>
    frame #11: 0x00001b86303bd1d6 Socket.pauseRecv(this=0x00000963ceae5391:<Object: Socket>) at /home/kradministrator/node/node_modules/raw-socket/index.js:115:39 fn=0x00001d78ea8c4f91
    frame #12: 0x00001b86303bd1d6 Session.reqRemove(this=0x00000963ceae0eb9:<Object: Session>, 0x00003483989682d9:<String: "228">) at /home/kradministrator/node/node_modules/net-ping/index.js:394:40 fn=0x00001d78ea8c61f1
    frame #13: 0x00001b86303bd1d6 Session.flush(this=0x00000963ceae0eb9:<Object: Session>, 0x000001126a46c679:<unknown>) at /home/kradministrator/node/node_modules/net-ping/index.js:125:36 fn=0x00001d78ea8c5e91
    frame #14: 0x00001b86303bd1d6 Session.onSocketClose(this=0x00000963ceae0eb9:<Object: Session>) at /home/kradministrator/node/node_modules/net-ping/index.js:243:44 fn=0x00001d78ea8c5fb1
    frame #15: 0x00001b86304a1dd1 emit(this=0x00000963ceae5391:<Object: Socket>, 0x00002ac9ebe0b7a9:<String: "close">) at events.js:156:44 fn=0x00003dfff56bb9d9
    frame #16: 0x00001b86303bd1d6 Socket.onClose(this=0x00000963ceae5391:<Object: Socket>) at /home/kradministrator/node/node_modules/raw-socket/index.js:74:37 fn=0x00001d78ea8c4e71
    frame #17: 0x00001b86304a1dd1 emit(this=0x00000963ceae5581:<Object: SocketWrap>, 0x000001126a46c659:<String: "close">) at events.js:156:44 fn=0x00003dfff56bb9d9
    frame #18: 0x00001b8630304239 <internal>
    frame #19: 0x00001b8630304101 <entry>
    frame #20: 0x0000000000d6f76a node`v8::internal::Execution::Call(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*) + 266
    frame #21: 0x0000000000a42713 node`v8::Function::Call(v8::Local<v8::Context>, v8::Local<v8::Value>, int, v8::Local<v8::Value>*) + 355
    frame #22: 0x0000000000a51141 node`v8::Function::Call(v8::Local<v8::Value>, int, v8::Local<v8::Value>*) + 65
    frame #23: 0x00007effe7769707 raw.node`raw::SocketWrap::CloseSocket() + 279
    frame #24: 0x00007effe7769899 raw.node`raw::SocketWrap::Close(Nan::FunctionCallbackInfo<v8::Value> const&) + 121
    frame #25: 0x00007effe7765a25 raw.node`Nan::imp::FunctionCallbackWrapper(v8::FunctionCallbackInfo<v8::Value> const&) + 133
    frame #26: 0x0000000000a5fd83 node`v8::internal::FunctionCallbackArguments::Call(void (*)(v8::FunctionCallbackInfo<v8::Value> const&)) + 403
    frame #27: 0x0000000000ad6f2c node`??? + 332
    frame #28: 0x0000000000ad7b7f node`v8::internal::Builtin_HandleApiCall(int, v8::internal::Object**, v8::internal::Isolate*) + 175
    frame #29: 0x00001b86303042fd <exit>
    frame #30: 0x00001b86303bd1d6 Socket.close(this=0x00000963ceae5391:<Object: Socket>) at /home/kradministrator/node/node_modules/raw-socket/index.js:65:35 fn=0x00001d78ea8c4de1
    frame #31: 0x00001b86303bd1d6 Session.close(this=0x00000963ceae0eb9:<Object: Session>) at /home/kradministrator/node/node_modules/net-ping/index.js:106:36 fn=0x00001d78ea8c5db9
    frame #32: 0x00001b86303bd1d6 session.pingHost(this=0x000001126a40c9c1:<Object: Object>, 0x000001126a46c4d9:<Object: RequestTimedOutError>, 0x00000963ceae0e91:<String: "10.4.2.41">, 0x000001126a430ae1:<JSDate: 1528473883717.000000>, 0x000001126a46c5c9:<JSDate: 1528473889718.000000>) at /home/kradministrator/node/utils/getdata.js:63:28 fn=0x000001126a40c979
    frame #33: 0x00001b86303bd1d6 Session.onTimeout(this=0x00000963ceae0eb9:<Object: Session>, 0x000001126a40c9c1:<Object: Object>) at /home/kradministrator/node/node_modules/net-ping/index.js:333:40 fn=0x00001d78ea8c60d1
    frame #34: 0x00001b86303bd1d6 ontimeout(this=0x00000d08497822d1:<undefined>, 0x000001126a45a781:<Object: Timeout>) at timers.js:98:18 fn=0x00003d444a62a729
    frame #35: 0x00001b8630495026 listOnTimeout(this=0x000001126a45a839:<Object: Timer>) at timers.js:98:18 fn=0x00003d444a62a5c1
    frame #36: 0x00001b8630304239 <internal>
    frame #37: 0x00001b8630304101 <entry>
    frame #38: 0x0000000000d6f76a node`v8::internal::Execution::Call(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*) + 266
    frame #39: 0x0000000000a42713 node`v8::Function::Call(v8::Local<v8::Context>, v8::Local<v8::Value>, int, v8::Local<v8::Value>*) + 355
    frame #40: 0x00000000008c6f11 node`node::InternalMakeCallback(node::Environment*, v8::Local<v8::Object>, v8::Local<v8::Function>, int, v8::Local<v8::Value>*, node::async_context) + 177
    frame #41: 0x00000000008a3398 node`node::AsyncWrap::MakeCallback(v8::Local<v8::Function>, int, v8::Local<v8::Value>*) + 120
    frame #42: 0x000000000094fdbf node`??? + 127
    frame #43: 0x00000000014216ac node`??? + 92
    frame #44: 0x0000000001412cc2 node`uv_run + 146
    frame #45: 0x00000000008d433d node`node::Start(uv_loop_s*, int, char const* const*, int, char const* const*) + 1197
    frame #46: 0x00000000008cc7fd node`node::Start(int, char**) + 365
    frame #47: 0x00007effe9992830 libc.so.6`__libc_start_main(main=(node`main), argc=4, argv=0x00007ffddcdba288, init=<unavailable>, fini=<unavailable>, rtld_fini=<unavailable>, stack_end=0x00007ffddcdba278) + 240 at libc-start.c:291
    frame #48: 0x000000000089b0b1 node`_start + 41

And the following errors in stderr:

node: ../deps/uv/src/unix/poll.c:109: uv_poll_stop: Assertion `!(((handle)->flags & (UV_CLOSING | UV_CLOSED)) != 0)' failed.
node: ../deps/uv/src/unix/poll.c:109: uv_poll_stop: Assertion `!(((handle)->flags & (UV_CLOSING | UV_CLOSED)) != 0)' failed.
node: ../deps/uv/src/unix/poll.c:109: uv_poll_stop: Assertion `!(((handle)->flags & (UV_CLOSING | UV_CLOSED)) != 0)' failed.
node: ../deps/uv/src/unix/poll.c:109: uv_poll_stop: Assertion `!(((handle)->flags & (UV_CLOSING | UV_CLOSED)) != 0)' failed.

Changed ping function:

var genPing = (host, cbSuccess, cbError, reqTimeout, logFunc)=>{
  reqTimeout = (reqTimeout || 2)*1000;
  var session   = netPing.createSession({
    packetSize : 64,                  //размер пакета для пинга
    retries    : 2,                   //количество попыток
    timeout    : reqTimeout,          //Таймаут для пинга
    sessionId  : utils.randInterval({ //Id сессии, случайное число от 1 до 65535
      min: 1,
      max: 65535
    })
  });

  session.on('error', (error)=>{
    logFunc(error.toString());
    cbError(error.toString());
    session.close();
  });

  return ()=>{
    session.pingHost(host, (error, target, sent, rcvd)=>{
      if(error) {
        session.close();
        cbError(error.toString());
        return;
      }

      var rtt = rcvd - sent;
      if(typeof rtt !== 'number' || rtt !== rtt) rtt = 0;
      cbSuccess({status:'ok', result:'ok', data:rtt});
    });
  };
}

[stephenwvickers]

Hi,

I've am quite busy with work at the moment which is why I haven't be able to look at this properly yet.

Until I do the only thing I can advise at this point is that I have seen similar issues in the past when the session.close() is called multiple times.

Apologies

Steve

[RomanBurunkov]

@stephenwvickers , thanks for an advice.
I've checked available documentation but didn't find any details whether it is able to check that session was closed. And if it was closed, do I need to create a new one?

Thanks, Roman.

[stephenwvickers]

The way it is supposed to be used is by creating a session once and then using to do all your ping work, I.e. never close it just keep using it.

[RomanBurunkov]

Thank you Steve, I'll remove all session.close and try whether it helps.