Error Writing to TLS stream

[WebFreak001]

I'm currently experiencing issues trying to do http client calls using vibe.d (current mongo-index branch on #2433, basically ~master) with vibe-core 1.9.1 and openssl 1.1.6+1.0.1g sometimes causes this issue when trying to send a http request:

[main(Dpec) trc] returning HTTPClient connection 0 of 1
[main(Dpec) trc] Socket 11, read 24 bytes: ok
[main(Dpec) trc] --------------------
[main(Dpec) trc] HTTP client request:
[main(Dpec) trc] --------------------
[main(Dpec) trc] GET /search?format=json&addressdetails=1&country=de&q=berlin HTTP/1.1
[main(Dpec) trc] Connection: keep-alive
[main(Dpec) trc] Accept-Encoding: gzip, deflate
[main(Dpec) trc] Host: nominatim.openstreetmap.org
[main(Dpec) trc] --------------------
[main(Dpec) dbg] OpenSSL error at ../vibe.d/tls/vibe/stream/openssl.d:1327: error:80000001:lib(128):func(0):reason(1) (Error writing to underlying stream: Connection closed while writing data.)
[main(Dpec) ERR] object.Exception@../vibe.d/tls/vibe/stream/openssl.d(578): Writing to TLS stream: error:80000001:lib(128):func(0):reason(1) (2147483649)
[main(Dpec) ERR] ----------------
[main(Dpec) ERR] ../vibe.d/tls/vibe/stream/openssl.d:578 @safe void vibe.stream.openssl.throwSSL(immutable(char)[]) [0x55d73034f494]
[main(Dpec) ERR] ../vibe.d/tls/vibe/stream/openssl.d:475 @safe immutable(char)[] vibe.stream.openssl.OpenSSLStream.processSSLError(ulong, immutable(char)[]) [0x55d73034ecee]
[main(Dpec) ERR] ../vibe.d/tls/vibe/stream/openssl.d:445 @safe int vibe.stream.openssl.OpenSSLStream.checkSSLRet(int, immutable(char)[]) [0x55d73034e9df]
[main(Dpec) ERR] ../vibe.d/tls/vibe/stream/openssl.d:397 @safe ulong vibe.stream.openssl.OpenSSLStream.write(const(ubyte[]), eventcore.driver.IOMode) [0x55d73034e760]
[main(Dpec) ERR] /home/webfreak/.dub/packages/vibe-core-1.9.1/vibe-core/source/vibe/core/stream.d:180 @safe void vibe.core.stream.OutputStream.write(const(ubyte[])) [0x55d7303824a2]
[main(Dpec) ERR] ../../.dub/packages/vibe-core-1.9.1/vibe-core/source/vibe/internal/interfaceproxy.d-mixin-302:302 @safe void vibe.internal.interfaceproxy.InterfaceProxy!(vibe.core.stream.Stream).InterfaceProxy.ProxyImpl!(vibe.stream.tls.TLSStream).ProxyImpl.__mixin8.__mixin3.__mixin3.__mixin3.__mixin3.__mixin3.__mixin2.write(void[], const(ubyte[])) [0x55d7302680f7]
[main(Dpec) ERR] ../../.dub/packages/vibe-core-1.9.1/vibe-core/source/vibe/internal/interfaceproxy.d-mixin-191:191 @safe void vibe.internal.interfaceproxy.InterfaceProxy!(vibe.core.stream.Stream).InterfaceProxy.__mixin22.__mixin3.__mixin3.__mixin3.__mixin3.__mixin3.__mixin2.write(const(ubyte[])) [0x55d730259ce1]
[main(Dpec) ERR] ../vibe.d/stream/vibe/stream/wrapper.d:318 @safe void vibe.stream.wrapper.StreamOutputRange!(vibe.internal.interfaceproxy.InterfaceProxy!(vibe.core.stream.Stream).InterfaceProxy, 1024uL).StreamOutputRange.flush() [0x55d7302d03d5]
[main(Dpec) ERR] ../vibe.d/stream/vibe/stream/wrapper.d:312 @safe void vibe.stream.wrapper.StreamOutputRange!(vibe.internal.interfaceproxy.InterfaceProxy!(vibe.core.stream.Stream).InterfaceProxy, 1024uL).StreamOutputRange.__dtor() [0x55d7302d036c]
[main(Dpec) ERR] ../vibe.d/stream/vibe/stream/wrapper.d:310 @trusted void vibe.stream.wrapper.StreamOutputRange!(vibe.internal.interfaceproxy.InterfaceProxy!(vibe.core.stream.Stream).InterfaceProxy, 1024uL).StreamOutputRange.__aggrDtor() [0x55d7302d0784]
[main(Dpec) ERR] ../vibe.d/http/vibe/http/client.d:936 @safe void vibe.http.client.HTTPClientRequest.writeHeader() [0x55d7302aef0c]
[main(Dpec) ERR] ../vibe.d/http/vibe/http/client.d:958 @safe void vibe.http.client.HTTPClientRequest.finalize() [0x55d7302af093]
[main(Dpec) ERR] ../vibe.d/http/vibe/http/client.d:760 @trusted bool vibe.http.client.HTTPClient.doRequest(scope void delegate(vibe.http.client.HTTPClientRequest), ref bool, bool, std.datetime.systime.SysTime).__lambda10() [0x55d7302ae1fb]
[main(Dpec) ERR] ../vibe.d/http/vibe/http/client.d:730 @safe bool vibe.http.client.HTTPClient.doRequest(scope void delegate(vibe.http.client.HTTPClientRequest), ref bool, bool, std.datetime.systime.SysTime) [0x55d7302ada41]
[main(Dpec) ERR] ../vibe.d/http/vibe/http/client.d:620 @safe bool vibe.http.client.HTTPClient.doRequestWithRetry(scope void delegate(vibe.http.client.HTTPClientRequest), bool, out bool, out std.datetime.systime.SysTime) [0x55d7302ad146]
[main(Dpec) ERR] ../vibe.d/http/vibe/http/client.d:544 @trusted void vibe.http.client.HTTPClient.request(scope void delegate(scope vibe.http.client.HTTPClientRequest), scope void delegate(scope vibe.http.client.HTTPClientResponse)) [0x55d7302aca55]
[main(Dpec) ERR] ../vibe.d/http/vibe/http/client.d:108 @safe void vibe.http.client.requestHTTP(vibe.inet.url.URL, void delegate(scope vibe.http.client.HTTPClientRequest), scope void delegate(scope vibe.http.client.HTTPClientResponse), const(vibe.http.client.HTTPClientSettings)) [0x55d7302ab853]
[main(Dpec) ERR] ../vibe.d/http/vibe/http/client.d:98 @safe void vibe.http.client.requestHTTP(immutable(char)[], scope void delegate(scope vibe.http.client.HTTPClientRequest), scope void delegate(scope vibe.http.client.HTTPClientResponse), const(vibe.http.client.HTTPClientSettings)) [0x55d7302ab75f]

the calling code is basically

requestHTTP("https://nominatim.openstreetmap.org/search?format=json&addressdetails=1&country=de&q=Berlin",
            (scope req) {}, (scope res) { ... });

and it happens very randomly (around 5% of the tries) but this doesn't seem to be reproducible in isolation. Also this HTTP request is being performed while there is another HTTP long polling call open and waiting for data. (using tg-d package to be precise)

Do you have any suggestion what could cause this?

If it's something with long polling you want to test, I made a site to test long polling: https://longpolltest.webfreak.org/?t=2 but I couldn't reproduce it in isolation with it yet

[kookman]

I'm having a similar problem, and have isolated to what I think is the cause: I'm using the defaultSettings for HTTPClientSettings on my requestHTTP calls. If there is no activity on a connection for a while and then I attempt to do another call it fails. I suspect the defaultKeepAliveTimeout is way too long and connections are expired by the server. I have now started using custom settings with a much lower timeout to see if this fixes the issue.

[WebFreak001]

good idea! I didn't think about the OpenSSL error message too hard yet but a timeout might be the reason this happens here.

The server tries to Connection: Upgrade, close with Upgrade: h2. In vibe.d it looks like it only cancels if it is == "close" so I think this might be the whole reason: https://github.com/vibe-d/vibe.d/blob/4076c01d438f39c358f976af69241243177c0d14/http/vibe/http/client.d#L1065

It does close it earlier for being not keep-alive too which is probably breaking here: https://github.com/vibe-d/vibe.d/blob/4076c01d438f39c358f976af69241243177c0d14/http/vibe/http/client.d#L758

The connection header may be a comma separated list of tokens which contains header names or keep-alive or close. I found if there is both keep-alive and close it is not defined what to choose from, but I think close is the better use there. It also says a system receiving HTTP/1.0 or lower messages must ignore all the headers specified in the Connection header, but it doesn't say what to do with HTTP/1.1

Still I think iterating over the Connection header and checking for a close token would be the best way to go

[kookman]

Unfortunately setting keepAliveTimeout in HTTPClientSettings did not help. I'm starting to wonder whether the problem is that the check for the underlying TCP connection being still valid in this line: https://github.com/vibe-d/vibe.d/blob/4076c01d438f39c358f976af69241243177c0d14/http/vibe/http/client.d#L638 is somehow passing, despite the fact that it has been closed. I'm going to check whether this is limited to TLS connections or also manifests on simple HTTP connections.

[kookman]

So I've been able to confirm with Wireshark that vibe.d http client is attempting to reuse the connection from the connection pool, despite the fact that the server has closed the keep-alive connection. It then gets a TCP RST back (unsurprisingly) which causes the openssl error message seen above. Now need to understand why the check referred to in my comment above (which seems to be an attempt to prevent re-use of a closed connection) is not preventing this.

[kookman]

Ok. Some further investigation has revealed that the issue I was seeing has been resolved in vibe.d master (I was depending on vibe 0.8.6). The check I was referring to above is working, but IMHO is in the wrong place - hence the existence of the slightly kludgy doRequestWithRetry method. It doesn't appear that the keepAliveTimeout in HTTPClientSettings is honoured correctly. Anyway it works for me now.

[WebFreak001]

well I am using master and this problem only appeared here (though I didn't test this particular app with previous versions yet)