Unhandled 'error' event #76

valeriansaliou · 2013-05-10T07:56:40Z

Hello,

I upgraded Jappix.com to latest NXB v0.7.3 from NPM + node v0.6.12, and it appears it is sometimes crashing with the following bug (repeated 2 times there):

Error: 3072534224:error:14077438:SSL routines:SSL23_GET_SERVER_HELLO:tlsv1 alert internal error:s23_clnt.c:741:

    at CleartextStream._puller (tls.js:501:24)
    at CleartextStream._pull (tls.js:432:19)
    at SecurePair.cycle (tls.js:727:20)
    at EncryptedStream.write (tls.js:130:13)
    at Socket.ondata (stream.js:38:26)
    at Socket.emit (events.js:67:17)
    at TCP.onread (net.js:372:14)

events.js:48
        throw arguments[1]; // Unhandled 'error' event
                       ^
Error: 3072566992:error:14077438:SSL routines:SSL23_GET_SERVER_HELLO:tlsv1 alert internal error:s23_clnt.c:741:

    at CleartextStream._puller (tls.js:501:24)
    at CleartextStream._pull (tls.js:432:19)
    at SecurePair.cycle (tls.js:727:20)
    at EncryptedStream.write (tls.js:130:13)
    at Socket.ondata (stream.js:38:26)
    at Socket.emit (events.js:67:17)
    at TCP.onread (net.js:372:14)

The text was updated successfully, but these errors were encountered:

dhruvbird · 2013-05-11T04:34:00Z

@valeriansaliou Any idea which host(s) this happened for (do you have debug logs enabled)? It seems to be a TLS connection to the upstream xmpp server that is causing problems.

dhruvbird · 2013-05-11T04:37:24Z

@valeriansaliou By any chance, did you update openssl on that box?
https://bugs.launchpad.net/ubuntu/+source/openssl/+bug/986147

valeriansaliou · 2013-05-11T19:31:25Z

This cannot happen with jappix.com and anonymous.jappix.com since they are defined as "non-TLS hosts" in NXB configuration file. I can enable debug logs but I'm afraid the event we're looking for will get lost in a junk of messages.

About OpenSSL, I'm running OpenSSL 1.0.1e 11 Feb 2013 from Debian 7 Wheezy official repos. System is up-to-date.

dhruvbird · 2013-05-12T09:15:34Z

Sorry, so I just realized that node.js comes bundles with openssl and it uses its own version rather than the system default.

Can you try running (from within the node.js_source_dir/deps/openss/)

node-v0.6.17/deps/openssl$ cat README.chromium  | grep Version

dhruvbird · 2013-05-12T09:18:26Z

Will try and send you a patch that enables logging only for TLS initiation. That might narrow the problem down.

dhruvbird · 2013-05-12T09:25:42Z

@valeriansaliou Can you try running https://github.com/dhruvbird/node-xmpp-bosh/tree/log_TLS_initiation with --logging=WARN and let me know what you see.

valeriansaliou · 2013-05-12T09:55:05Z

Thanks Dhruv! BTW, I'm running node v0.6.21 (latest one of the 0.6 branch).

OpenSSL version is 0.9.8o (result from the cat you gave me on my current node sources).

I'll run this with WARN logging, the log result may take up to a few hours since it doesn't crash a lot (3-4 times a day only - at very random intervals).

valeriansaliou · 2013-05-12T10:01:43Z

One side question: I'm using NPM, any way to update/reinstall NXB from NPM using this log_TLS_initiation branch? (just as ROR does with Gems that are directly fetched from Github).

dhruvbird · 2013-05-15T04:55:11Z

So, you can install everything normally from npm, and just apply the diff using this command:

$ cd node-xmpp-bosh-git-directory
$ git pull --rebase
$ git checkout -b log_TLS_initiation --track origin/log_TLS_initiation
$ git diff master # Will show you the changes

It's just a single line change, so you can copy the file over in your npm install directory (i.e. wherever npm has installed NXB).

valeriansaliou · 2013-05-15T05:41:06Z

Done. I'll report you the WARN trace when I'll get one. Thanks ;)

BTW, not in the topic but is that normal that the BOSH send me back this:

<body xmlns="http://jabber.org/protocol/httpbind" message="Timed out"/>

When the wait maximum time has come? I mean, I was getting a blank message with the previous NXB version I was using:

<body xmlns="http://jabber.org/protocol/httpbind">

dhruvbird · 2013-05-15T14:29:21Z

@valeriansaliou Thanks for reporting this actually! :)

And yes, we added "message" to some of the responses for better debugability so that when we see logs, it's easier to see what's been happening.

valeriansaliou · 2013-05-15T14:34:55Z

Okay, that's fine. An user of our server thought something went wrong and asked me why he always got this.

BTW, here's the crash log I got 12 minutes ago (crashed 2 times in 14 hours):

Restoring old listeners
Restore::event: connect
Remove all listeners for event: connect
Restore::event: error
Remove all listeners for event: error
Restore::event: timeout
Remove all listeners for event: timeout
[2013-05-15 14:20:28.355] [WARN] [xmpp-proxy.js:XMPPProxy._starttls:143] - startTLS to billard-aktuell.de requested
Restoring old listeners
Restore::event: connect
Remove all listeners for event: connect
Restore::event: error
Remove all listeners for event: error
Restore::event: timeout
Remove all listeners for event: timeout
[2013-05-15 14:20:31.178] [WARN] [xmpp-proxy.js:XMPPProxy._starttls:143] - startTLS to billard-aktuell.de requested
Restoring old listeners
Restore::event: connect
Remove all listeners for event: connect
Restore::event: error
Remove all listeners for event: error
Restore::event: timeout
Remove all listeners for event: timeout
[2013-05-15 14:20:36.637] [WARN] [xmpp-proxy.js:XMPPProxy._starttls:143] - startTLS to billard-aktuell.de requested
+----------------------------------------------------------------------------------------------------------------------+
| Starting BOSH server 'v0.7.3' on 'http://:::5280/^\/http-bind(\/+)?$/' at 'Wed May 15 2013 16:21:02 GMT+0200 (CEST)' |
+----------------------------------------------------------------------------------------------------------------------+
+---------------------------------------------------------------------------------------------------+
| Starting WEBSOCKET server 'v0.7.3' on ws://:::5280' at 'Wed May 15 2013 16:21:02 GMT+0200 (CEST)' |
+---------------------------------------------------------------------------------------------------+
Restoring old listeners
Restore::event: connect
Remove all listeners for event: connect
Restore::event: error
Remove all listeners for event: error
Restore::event: timeout
Remove all listeners for event: timeout
Restoring old listeners
Restore::event: connect
Remove all listeners for event: connect

And the associated error:

events.js:48
        throw arguments[1]; // Unhandled 'error' event
                       ^
Error: 3072362192:error:14077438:SSL routines:SSL23_GET_SERVER_HELLO:tlsv1 alert internal error:s23_clnt.c:741:

    at CleartextStream._puller (tls.js:501:24)
    at CleartextStream._pull (tls.js:432:19)
    at SecurePair.cycle (tls.js:727:20)
    at EncryptedStream.write (tls.js:130:13)
    at Socket.ondata (stream.js:38:26)
    at Socket.emit (events.js:67:17)
    at TCP.onread (net.js:372:14)

The crash occurred exactly on 2013-05-15 14:20:36.637.

dhruvbird · 2013-05-18T18:14:08Z

@valeriansaliou I tried reproducing the crash by connecting to billard-aktuell.de by connecting to it in a loop and doing a starttls, but both node-v0.6.17 and node-v0.6.21 seem to not crash. Do you know if this crash happens only for this host?

valeriansaliou · 2013-05-19T00:01:30Z

@dhruvbird not sure it only happens on this host, but I have checked my logs and it seems to be recurrent (checked 3 different crashes, and the same domain comes out everytime).

Also, the crash actually happens one time over a hundred. I have many TLS logs for this host, but not that many crash after the TLS log.

dhruvbird · 2013-05-19T02:31:10Z

@valeriansaliou I've pushed out a commit to try and see if the TLS module is emitting an error event after emitting a close event (that could explain why the error event is unhandled). You should be able to apply it on top of current npm (v0.7.4).
Commit is on branch: https://github.com/dhruvbird/node-xmpp-bosh/tree/log_TLS_initiation

valeriansaliou · 2013-05-19T09:22:09Z

Logging started. I will report you subsequent crashes. ;)

valeriansaliou · 2013-05-19T18:36:57Z

Got this now:

From bosh.err:

events.js:48
        throw arguments[1]; // Unhandled 'error' event
                       ^
Error: 3072407248:error:14077438:SSL routines:SSL23_GET_SERVER_HELLO:tlsv1 alert internal error:s23_clnt.c:741:

    at CleartextStream._puller (tls.js:501:24)
    at CleartextStream._pull (tls.js:432:19)
    at SecurePair.cycle (tls.js:727:20)
    at EncryptedStream.write (tls.js:130:13)
    at Socket.ondata (stream.js:38:26)
    at Socket.emit (events.js:67:17)
    at TCP.onread (net.js:372:14)

From bosh.log:

starttls::onclose() -> 547
starttls::onclose() -> 550
starttls::onclose() -> 416
starttls::onclose() -> 552
+----------------------------------------------------------------------------------------------------------------------+
| Starting BOSH server 'v0.7.4' on 'http://:::5280/^\/http-bind(\/+)?$/' at 'Sun May 19 2013 13:21:01 GMT+0200 (CEST)' |
+----------------------------------------------------------------------------------------------------------------------+
+---------------------------------------------------------------------------------------------------+
| Starting WEBSOCKET server 'v0.7.4' on ws://:::5280' at 'Sun May 19 2013 13:21:01 GMT+0200 (CEST)' |
+---------------------------------------------------------------------------------------------------+
starttls::onclose() -> 24
starttls::onclose() -> 25
starttls::onclose() -> 27

I also got some WARN that I assume are normal (apart from the crash, those WARN came maybe half an hour before it happened, unrelated):

starttls::onclose() -> 68
starttls::onclose() -> 69
starttls::onclose() -> 70
[2013-05-19 09:24:29.337] [WARN] [lookup-service.js:give_up_trying_to_connect:118] - Giving up connection attempts to [email protected]
starttls::onclose() -> 71
starttls::onclose() -> 72
[2013-05-19 09:24:36.061] [WARN] [lookup-service.js:give_up_trying_to_connect:118] - Giving up connection attempts to [email protected]
starttls::onclose() -> 73
starttls::onclose() -> 74
[2013-05-19 09:25:08.118] [WARN] [lookup-service.js:give_up_trying_to_connect:118] - Giving up connection attempts to hotmail.com
starttls::onclose() -> 63
[2013-05-19 09:25:31.320] [WARN] [lookup-service.js:give_up_trying_to_connect:118] - Giving up connection attempts to [email protected]
starttls::onclose() -> 75
starttls::onclose() -> 76
starttls::onclose() -> 77
[2013-05-19 09:25:57.199] [WARN] [lookup-service.js:give_up_trying_to_connect:118] - Giving up connection attempts to https://jappix.com/
starttls::onclose() -> 78
starttls::onclose() -> 79

dhruvbird · 2013-05-20T07:17:52Z

@valeriansaliou I see a lot of onclose() calls, but no onerror() calls. Were any onerror() calls logged for this duration?

valeriansaliou · 2013-05-20T08:47:36Z

Yeah, actually there's one:

starttls::onerror() -> 29

valeriansaliou · 2013-05-20T08:49:35Z

Check your emails BTW ;)

valeriansaliou · 2013-05-28T16:05:52Z

After restarting my XMPPd today, I noticed NXB crashed just some milliseconds after the restart, the first time in 3 days it did not crash.

Same error log as before.

I do think this is only due to an unhandled error type on socket drop/close, that may have been introduced in nodejs 0.6.21 (well, the last one from 0.6 branch, not sure it is 21). Adding the error handler should do the trick, right?

dhruvbird · 2013-05-29T15:19:07Z

I tried adding the error handler in the patch I sent, but it doesn't seem to help. Will need some more investigation.

valeriansaliou · 2013-05-29T16:07:50Z

Oh, I updated NXB to v0.7.4 in between. I was thinking you did not change anything else than logging. Sorry for the misunderstanding.

I'm re-adding your changes to my running v0.7.4, and keep you up-to-date in a week about whether it crashed or not.

dhruvbird · 2013-05-29T16:53:55Z

Link to node.js group post: https://groups.google.com/forum/?fromgroups#!topic/nodejs/5XxHhuia-lw

valeriansaliou · 2013-05-29T20:00:39Z

Mhh so you suggest I give a try to nodejs v0.10?

I got some strange issues with my proxy server on front of NXB when first testing with node v0.10 but this may be linked to the fact I was changing a lot of things on the server, so I might have messed up my mind. The issue was that I started to get blank proxied pages after a while. Not a 500 error, blank pages. But anyway I can retry.

Will node v0.10 be more clear on the error message or fix the whole issue?

dhruvbird · 2013-05-30T03:19:52Z

Okay, so there were some bug-fixes on an external starttls module that my very old code didn't have.
I've pushed those changes here: https://github.com/dhruvbird/node-xmpp-bosh/tree/log_TLS_initiation
Please could you run from that branch and let me know if that fixes the crash?

valeriansaliou · 2013-05-30T04:25:44Z

Thanks @dhruvbird ;)

I have updated Node to v0.10.8 (it's said it's 2 times faster on I/O than the 0.6 branch I was using).
NXB from log_TLS_initiation branch is now running, I'll report you any further error.

dhruvbird · 2013-05-30T04:30:06Z

@valeriansaliou Cool - were you able to it to work for ipv6 addresses?

valeriansaliou · 2013-05-30T04:53:47Z

Absolutely. A telnet on IPv6 :5280 can be opened and my lighttpd frontend proxies on local loopback IPv6 sockets anyway ;)

valeriansaliou · 2013-05-30T05:22:53Z

Mhh, crashed after an hour (running very well on latest Node version before crash):

From bosh.err:

node: ../src/node_crypto.cc:975: void node::crypto::Connection::ClearError(): Assertion `handle_->Get(String::New("error"))->BooleanValue() == false' failed.

It seem to be related to the error we previously had.

This time, the crash followed an overactivity kick from myself. I generated a lot of traffic on my account session, getting a lot of vCards at the same time, and should have been kicked. Instead NXB crashed.

Note that it's really weird I got something coming from node_crypto.css, which is a TLS lib as I understand, but I was not using a TLS c2s connection since connections to my local loopback are set to be plain text (in NXB config file, no TLS domains).

dhruvbird · 2013-05-30T05:37:15Z

@valeriansaliou The error seems helpful. I'll post on google groups and see if something comes out of it.

Are you sure the config file was being used? nxb prints out the config. options in debug (or maybe trace) mode.

valeriansaliou · 2013-05-30T05:49:20Z

@dhruvbird great. I'm in FATAL for now, but config is actually used, otherwise NXB won't be listening on an IPv6 socket ;)

valeriansaliou · 2013-05-30T07:02:47Z

Downgrading to v0.8.23, v0.10.x is causing blank pages after w/o making NXB crash (and no error log). I assume this is an HTTP server bug.

valeriansaliou · 2013-05-30T11:20:54Z

Now with v0.8.23 it looks like I don't get blank page issue, but still crashing. Crashes gives that error trace log:

assert.js:102
throw new assert.AssertionError({
^
AssertionError: handle != self._handle
at Object.afterConnect as oncomplete

Seems to match v0.10 error log.

By the way, I got some WARNs during NXB install using NPM, that some piece of third party software were deprecated:

npm WARN unmet dependency /usr/local/lib/node_modules/npm/node_modules/fstream-npm/node_modules/fstream-> ignore requires inherits@'~1.0.0' but will load
npm WARN unmet dependency /usr/local/lib/node_modules/npm/node_modules/fstream-npm/node_modules/inherits,
npm WARN unmet dependency which is version 2.0.0

Otherwise the rest seems to be okay. Related to a stream package, may be related to the crash?

ghost assigned dhruvbird May 10, 2013

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Unhandled 'error' event #76

Unhandled 'error' event #76

valeriansaliou commented May 10, 2013

dhruvbird commented May 11, 2013

dhruvbird commented May 11, 2013

valeriansaliou commented May 11, 2013

dhruvbird commented May 12, 2013

dhruvbird commented May 12, 2013

dhruvbird commented May 12, 2013

valeriansaliou commented May 12, 2013

valeriansaliou commented May 12, 2013

dhruvbird commented May 15, 2013

valeriansaliou commented May 15, 2013

dhruvbird commented May 15, 2013

valeriansaliou commented May 15, 2013

dhruvbird commented May 18, 2013

valeriansaliou commented May 19, 2013

dhruvbird commented May 19, 2013

valeriansaliou commented May 19, 2013

valeriansaliou commented May 19, 2013

dhruvbird commented May 20, 2013

valeriansaliou commented May 20, 2013

valeriansaliou commented May 20, 2013

valeriansaliou commented May 28, 2013

dhruvbird commented May 29, 2013

valeriansaliou commented May 29, 2013

dhruvbird commented May 29, 2013

valeriansaliou commented May 29, 2013

dhruvbird commented May 30, 2013

valeriansaliou commented May 30, 2013

dhruvbird commented May 30, 2013

valeriansaliou commented May 30, 2013

valeriansaliou commented May 30, 2013

dhruvbird commented May 30, 2013

valeriansaliou commented May 30, 2013

valeriansaliou commented May 30, 2013

valeriansaliou commented May 30, 2013

Unhandled 'error' event #76

Unhandled 'error' event #76

Comments

valeriansaliou commented May 10, 2013

dhruvbird commented May 11, 2013

dhruvbird commented May 11, 2013

valeriansaliou commented May 11, 2013

dhruvbird commented May 12, 2013

dhruvbird commented May 12, 2013

dhruvbird commented May 12, 2013

valeriansaliou commented May 12, 2013

valeriansaliou commented May 12, 2013

dhruvbird commented May 15, 2013

valeriansaliou commented May 15, 2013

dhruvbird commented May 15, 2013

valeriansaliou commented May 15, 2013

dhruvbird commented May 18, 2013

valeriansaliou commented May 19, 2013

dhruvbird commented May 19, 2013

valeriansaliou commented May 19, 2013

valeriansaliou commented May 19, 2013

dhruvbird commented May 20, 2013

valeriansaliou commented May 20, 2013

valeriansaliou commented May 20, 2013

valeriansaliou commented May 28, 2013

dhruvbird commented May 29, 2013

valeriansaliou commented May 29, 2013

dhruvbird commented May 29, 2013

valeriansaliou commented May 29, 2013

dhruvbird commented May 30, 2013

valeriansaliou commented May 30, 2013

dhruvbird commented May 30, 2013

valeriansaliou commented May 30, 2013

valeriansaliou commented May 30, 2013

dhruvbird commented May 30, 2013

valeriansaliou commented May 30, 2013

valeriansaliou commented May 30, 2013

valeriansaliou commented May 30, 2013