Assertion `err == 1 || err == 5' failed. (v0.10.0)

[chandlerprall]

Updated node from 0.8.8 to 0.10.0 on our staging server and I have now seen this error come through a few times, killing the node process.

node: ../src/node_crypto.cc:935: int node::crypto::Connection::HandleSSLError(const char*, int, node::crypto::Connection::ZeroStatus): Assertion err == 1 || err == 5' failed.`

Setup: running HTTP and HTTPS on two ports as a combination Express / SocketIO.

According to #1719 this may be caused by non-HTTPS traffic being sent to the HTTP port? I cannot reliably replicate the issue in any way but I'll test ideas presented.

[bnoordhuis]

Can you compile a debug version of node (make BUILDTYPE=Debug) and turn on core dumps (ulimit -c unlimited) or run node in gdb (gdb --args out/Debug/node script.js)? When you hit the assertion, type backtrace full in gdb and post the stack trace here, please.

[matbee-eth]

I'm also getting this error. I'll post the core dump when I can..

[indutny]

Can someone of you guys try applying this patch, rebuilding node and running your applications once again?

diff --git a/src/node_crypto.cc b/src/node_crypto.cc
index afe4566..b53eb03 100644
--- a/src/node_crypto.cc
+++ b/src/node_crypto.cc
@@ -916,7 +916,7 @@ int Connection::HandleSSLError(const char* func, int rv, ZeroStatus zs) {

   int err = SSL_get_error(ssl_, rv);

-  if (err == SSL_ERROR_NONE) {
+  if (err == SSL_ERROR_NONE || err == SSL_ERROR_ZERO_RETURN) {
     return 0;

   } else if (err == SSL_ERROR_WANT_WRITE) {

[bnoordhuis]

If checking for SSL_ERROR_ZERO_RETURN fixes it, does that indicate we call:

1. HandleSSLError() somewhere with kZeroIsAnError instead of kZeroIsNotAnError, or
2. SSL_read() or SSL_write() one time too many?

[indutny]

Not only...

            if ((s->shutdown & SSL_RECEIVED_SHUTDOWN) &&
                (s->s3->warn_alert == SSL_AD_CLOSE_NOTIFY))
                return(SSL_ERROR_ZERO_RETURN);

That's for SSL3.

But first I want to know if that's what is really happening here.

[chandlerprall]

Sorry for the delay, was traveling Thursday and over the weekend and am struggling with the gdb dump.

Applied the patch @indutny supplied and the process will now enter a state where it sits on 100% CPU usage. Will dig into this again in a few hours and try to get a good gdb dump.

[indutny]

Can you sudo strace -p <pid> your process at this time of 100% CPU usage?

[chandlerprall]

@indutny

bunch of this, repeated:

futex(0x7f29140008c8, FUTEX_WAKE_PRIVATE, 1) = 1
gettimeofday({1363627677, 787628}, NULL) = 0
gettimeofday({1363627677, 802941}, NULL) = 0
gettimeofday({1363627677, 803253}, NULL) = 0
gettimeofday({1363627677, 803332}, NULL) = 0
gettimeofday({1363627677, 803973}, NULL) = 0
gettimeofday({1363627677, 804050}, NULL) = 0
gettimeofday({1363627677, 804262}, NULL) = 0
futex(0x7f29140008c8, FUTEX_WAKE_PRIVATE, 1) = 1
gettimeofday({1363627677, 830200}, NULL) = 0
gettimeofday({1363627677, 830590}, NULL) = 0
gettimeofday({1363627677, 830689}, NULL) = 0
gettimeofday({1363627677, 832502}, NULL) = 0
gettimeofday({1363627677, 832592}, NULL) = 0
gettimeofday({1363627677, 832919}, NULL) = 0
futex(0x7f29140008c8, FUTEX_WAKE_PRIVATE, 1) = 1
gettimeofday({1363627677, 990795}, NULL) = 0
gettimeofday({1363627677, 991435}, NULL) = 0
gettimeofday({1363627677, 991544}, NULL) = 0
gettimeofday({1363627677, 992780}, NULL) = 0
gettimeofday({1363627677, 992888}, NULL) = 0
gettimeofday({1363627677, 993238}, NULL) = 0
futex(0x7f29140008c8, FUTEX_WAKE_PRIVATE, 1) = 1

[indutny]

wow, ok.

Can I ask you to connect to it using gdb: sudo gdb -p <pid> and run bt full?

[chandlerprall]

Hmm, looking like any custom builds I do (with or without your patch) are killing the CPU. Trying to get a functioning build going again.

[chandlerprall]

Looks like the load I was putting on the Debug version was killing the CPU. Dropped the Release binary in and saw normal usage.

Now back to trying the patch.

[chandlerprall]

It looks like the patch prevents the error. I usually see it within 5 minutes but the patched version has been running for a few hours now.

[bnoordhuis]

Not only...

      if ((s->shutdown & SSL_RECEIVED_SHUTDOWN) &&
           (s->s3->warn_alert == SSL_AD_CLOSE_NOTIFY))
           return(SSL_ERROR_ZERO_RETURN);

That's for SSL3.

I know openssl does that, Fedor. :-)

That's why I asked if we're calling SSL_read() too often. When openssl sees a close notify alert, it sets the SSL_RECEIVED_SHUTDOWN flag. We have a ReceivedShutdown() method in node_crypto.cc that checks for exactly that condition but I don't think it's used anymore.

From a performance perspective that's probably a good thing (less function calls == better) but it makes me wonder if it's possible to DoS a TLS server that way: send a close notify alert but keep the connection open. That stops the openssl SSL object from getting freed at no cost to the attacker.

[indutny]

Erm... I'm quite sure that without any incoming/outgoing data no reads/writes will happen. Also, calling SSL_read/BIO_read when there're no data is quite cheap and should not cause any DoS.

[indutny]

But I agree that we should handle this case instead of ignoring it. I'll think a bit about it today and will let you know.

[indutny]

@chandlerprall can I ask you to test one more patch, please: indutny@964fe02 ?

[chandlerprall]

@indutny Would you like it run with or without the previous patch as well?

[chandlerprall]

Rolled back previous patch and applied indutny/node@964fe02 and all seems to be running well. Will update this thread if anything changes/errors.

[matbee-eth]

Has this patch been verified to fix the issue?

[chandlerprall]

Been running fine for a week now, no errors at all.

[jeff-minard-ck]

FYI: I applied this path on top of 0.10.1 because we were getting the same error. It has since abated and we've seen no loss in functionality otherwise.

[indutny]

With slight changes, landed in 4580be0