Long-lived application occasionally dies with SIG_PIPE when calling httpclient.request

[niv]

Our serverside application, currently on 0.18, does http the occasional http request to the Google APIs. Sometimes, I think, google closes the connection on us and the application dies with SIG_PIPE:

...
keyprovision_google.nim(66) getAccessToken
keyprovision_google.nim(30) requestJson
keyprovision_google.nim(71) :anonymous
httpclient.nim(1196)     request
httpclient.nim(1181)     requestAux
httpclient.nim(1031)     parseResponse
httpclient.nim(883)      close
net.nim(866)             close
SIGPIPE: Pipe closed.

Of course, the http request() is wrapped into try/except; that does not catch the signal however.

This is running on nim 0.18 (I can't try 0.19 yet, porting it is significant effort due to libraries used), and in a docker container on Linux.

I found this thread: https://forum.nim-lang.org/t/4417, but that didn't really help. The httpclient is already configured to use a reasonable timeout (3s).

I'm fairly certain this is because Google is closing the kept-alive connection in the background; but I'm hesitant to add Connection: Close (or otherwise close the connection on our end) unless that's the only way to solve this.

[dom96]

huh, it's SIGPIPE'ing on a close. Interesting, it appears to be OpenSSL's fault: https://github.com/nim-lang/Nim/blob/v0.18.0/lib/pure/net.nim#L866.

Anyway, please follow the advice here: https://stackoverflow.com/a/108192/492186. As a workaround you can ignore all SIGPIPEs in your program, as a proper fix I guess we need to set some OpenSSL flag or something.

[niv]

Heya dom96, I tried that, like so:

from posix import signal, SIG_PIPE, SIG_IGN
signal(SIG_PIPE, SIG_IGN)

It seemed to have worked for a good while, but today it fell over with this (one exception per line):

Broken pipe Additional info: IO error has occurred in the BIO layer; will retry
not isClosed(socket) Cannot `send` on a closed socket; will retry
Broken pipe Additional info: IO error has occurred in the BIO layer; not retrying anymore

All future requests then also failed on the assert not isClosed and I had to bump the process to get functionality back.

[dom96]

Hrm, would be nice to get stack traces for those exceptions. I'm guessing httpclient doesn't handle the socket getting closed correctly.

…

On Tue, 11 Dec 2018 at 09:12, niv ***@***.***> wrote: Heya dom96, I tried that, like so: from posix import signal, SIG_PIPE, SIG_IGNsignal(SIG_PIPE, SIG_IGN) It seemed to have worked for a good while, but today it fell over with this (one exception per line): Broken pipe Additional info: IO error has occurred in the BIO layer; will retry not isClosed(socket) Cannot `send` on a closed socket; will retry Broken pipe Additional info: IO error has occurred in the BIO layer; not retrying anymore All future requests then also failed on the assert not isClosed and I had to bump the process to get functionality back. — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#9867 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAPDe--Q2uRyV0armpnf40XAprhuK5nDks5u33b6gaJpZM4ZCheN> .

[niv]

Ah, sorry. Don't have those anymore.

I've also added workaround code now that force-closes the httpclient after reach request chain, so that the production process doesn't hang itself.

[endragor]

This is a double-close issue that I'm also seeing in production. It's not an OpenSSL issue, as the error sometimes is not (pkey.ident == 0) Descriptor 26 is not registered in the selector! and sometimes it's an OpenSSL crash, caused by double-free, like in the OP's case. Ignoring SIGPIPE or other such signals is not an option as the app will continue working in a corrupted state, which you do not want - better to crash early and restart.

On Socket/AsyncSocket level there is no checking for whether the socket was already closed, and it seems that under some condition httpclient.request may close the socket after a failure occurred without setting connected field to false. By glancing at the code I'm not yet sure where exactly this happens.

The code on which the error occurs looks like this:

var httpClient = newAsyncHttpClient(userAgent = ctx.userAgent)
# headers omitted
let respFuture = httpClient.request(ctx.endpoint, httpMethod = HttpPOST, body = reqBody)
yield respFuture
if respFuture.failed:
  httpClient.close() # Double close here!
  raise respFuture.readError()

A simple fix would be to add connected field to Socket/AsyncSocket objects to avoid any double-close issues. But the httpclient issue should also be fixed.

[endragor]

So apparently the scenario is this:

1. Server disconnects, leaving the client's underlying OS socket in disconnected state.
2. AsyncHttpClient calls socket.close(), where SslShutdown errors out (due to the disconnected socket) and so close() raises. This leaves AsyncHttpClient in connected state, since it doesn't handle exceptions from socket.close().
3. close() is called again and SslShutdown/SSLFree is called for the second time on invalid pointer, corrupting the memory.

So either socket.close() should be made to never raise or else any code that calls it must handle the exceptions. If it raises, it should clean up the state as much as possible (e.g. set sslHandle to nil after freeing it and not use it if it's already nil).

SSL_shutdown can be made to always succeed by calling SSL_CTX_set_quiet_shutdown, according to the SSL_shutdown documentation.

[endragor]

Another important line from SSL_shutdown() doc:

Note that SSL_shutdown() must not be called if a previous fatal error has occurred on a connection i.e. if SSL_get_error() has returned SSL_ERROR_SYSCALL or SSL_ERROR_SSL.

So we should also track whether a fatal error occurred on the connection and not call SSL_shutdown in such case. If the above condition is violated, SSL_shutdown may raise even if SSL_CTX_set_quiet_shutdown() was called.

[dom96]

close() is called again and SslShutdown/SSLFree

This implies that the original exception raised by SslShutdown is getting caught somewhere, if so where?

[endragor]

It results in a failed future returned from request(). Regardless, AsyncHttpClient.close() is expected to be always safe to call, and here it gets in a state where calling it results in a crash or corrupted memory.

[jorisbontje]

@dom96 Here is a stack trace for this issue with nim 1.0.4 and SIG_PIPE ignored (per niv's comments):

Got exception ref 0x7f0485be2098 --> [errorCode = 32,
parent = nil,
name = 0x5597fa08ce9a"OSError",
msg = 0x7f0485be12d8"Broken pipe\10"
"Additional info: \"IO error has occurred in the BIO layer\"",
trace = 0x7f04841c6048@[[procname = 0x5597fa0956f5"eos_watcher_rpc",
line = 239,
filename = 0x5597fa095328"/root/eos-watcher/eos_watcher_rpc.nim"], [procname = 0x5597fa095673"main",
line = 206,
filename = 0x5597fa095328"/root/eos-watcher/eos_watcher_rpc.nim"], [procname = 0x5597fa095468"get_block",
line = 174,
filename = 0x5597fa095328"/root/eos-watcher/eos_watcher_rpc.nim"], [procname = 0x5597fa09157b"request",
line = 932,
filename = 0x5597fa091110"/root/.choosenim/toolchains/nim-1.0.4/lib/pure/httpclient.nim"], [procname = 0x5597fa09157b"request",
line = 907,
filename = 0x5597fa091110"/root/.choosenim/toolchains/nim-1.0.4/lib/pure/httpclient.nim"], [procname = 0x5597fa09154a"requestAux",
line = 892,
filename = 0x5597fa091110"/root/.choosenim/toolchains/nim-1.0.4/lib/pure/httpclient.nim"], [procname = 0x5597fa09150a"parseResponse",
line = 770,
filename = 0x5597fa091110"/root/.choosenim/toolchains/nim-1.0.4/lib/pure/httpclient.nim"], [procname = 0x5597fa091500"parseBody",
line = 678,
filename = 0x5597fa091110"/root/.choosenim/toolchains/nim-1.0.4/lib/pure/httpclient.nim"], [procname = 0x5597fa09140e"recvFull",
line = 608,
filename = 0x5597fa091110"/root/.choosenim/toolchains/nim-1.0.4/lib/pure/httpclient.nim"], [procname = 0x5597fa0911a7"close",
line = 563,
filename = 0x5597fa091110"/root/.choosenim/toolchains/nim-1.0.4/lib/pure/httpclient.nim"], [procname = 0x5597fa08f3bb"close",
line = 900,
filename = 0x5597fa08f118"/root/.choosenim/toolchains/nim-1.0.4/lib/pure/net.nim"], [procname = 0x5597fa08f2d9"socketError",
line = 735,
filename = 0x5597fa08f118"/root/.choosenim/toolchains/nim-1.0.4/lib/pure/net.nim"], [procname = 0x5597fa08cea2"raiseOSError",
line = 94,
filename = 0x5597fa08cd98"/root/.choosenim/toolchains/nim-1.0.4/lib/pure/includes/oserr.nim"]],
raiseId = 0,
up = ref 0x7f0485be2098]
 with message Broken pipe
Additional info: "IO error has occurred in the BIO layer"
Sleeping for 60 seconds...
/root/eos-watcher/eos_watcher_rpc.nim(239) eos_watcher_rpc
/root/eos-watcher/eos_watcher_rpc.nim(206) main
/root/eos-watcher/eos_watcher_rpc.nim(174) get_block
/root/.choosenim/toolchains/nim-1.0.4/lib/pure/httpclient.nim(932) request
/root/.choosenim/toolchains/nim-1.0.4/lib/pure/httpclient.nim(907) request
/root/.choosenim/toolchains/nim-1.0.4/lib/pure/httpclient.nim(886) requestAux
/root/.choosenim/toolchains/nim-1.0.4/lib/pure/net.nim(1349) send
/root/.choosenim/toolchains/nim-1.0.4/lib/pure/net.nim(1334) send
/root/.choosenim/toolchains/nim-1.0.4/lib/system/assertions.nim(27) failedAssertImpl
/root/.choosenim/toolchains/nim-1.0.4/lib/system/assertions.nim(20) raiseAssert
/root/.choosenim/toolchains/nim-1.0.4/lib/system/fatal.nim(39) sysFatal
Error: unhandled exception: /root/.choosenim/toolchains/nim-1.0.4/lib/pure/net.nim(1334, 9) `not socket.isClosed` Cannot `send` on a closed socket [AssertionError]
Error: execution of an external program failed: '/root/eos-watcher/eos_watcher_rpc '

[zedeus]

This (closing httpclient) is causing my web service with thousands of users to occasionally crash, sometimes more often than others. I tried @endragor's suggestions but it didn't seem to help. Error messages like this:

*** Error in `./nitter': free(): invalid pointer: 0x0000558d1c889a00 ***
*** Error in `./nitter': double free or corruption (!prev): 0x000055b56f28ef20 ***

INFO Jester is making jokes at http://0.0.0.0:5000
Traceback (most recent call last)
/home/zed/src/dev/nim/nitter/src/nitter.nim(33) nitter
/home/zed/src/dev/nim/jester/jester.nim(508) serve
/home/zed/.choosenim/toolchains/nim-#devel/lib/pure/asyncdispatch.nim(1879) runForever
/home/zed/.choosenim/toolchains/nim-#devel/lib/pure/asyncdispatch.nim(1574) poll
/home/zed/.choosenim/toolchains/nim-#devel/lib/pure/asyncdispatch.nim(1348) runOnce
/home/zed/.choosenim/toolchains/nim-#devel/lib/pure/asyncdispatch.nim(210) processPendingCallbacks
/home/zed/.choosenim/toolchains/nim-#devel/lib/pure/asyncmacro.nim(34) fetchHtmlNimAsyncContinue
/home/zed/src/dev/nim/nitter/src/api/utils.nim(34) fetchHtmlIter
/home/zed/.choosenim/toolchains/nim-#devel/lib/pure/httpclient.nim(580) close
/home/zed/.choosentm/toolchains/nim-#devel/lib/pure/asyncnet.nim(697) close
SIGSEGV: Illegal storage access. (Attempt to read from nil?)

[dom96]

I'd give it another try after my openssl changes (#13919 ), this seems to be somewhat related so it's possible it was fixed.

[endragor]

That PR doesn't seem to affect this bug. The bug is not about OpenSSL, it's about Nim code on higher level - namely:

1. AsyncHttpClient
2. Usage of SSL_shutdown - it may error out in situations which are expected for the code that uses it, so it should be handled.

See my old comments here - I pinpointed where the problems are.