When the remote peer hangs up, a stash of errors are reported (on the error level in the log)
Opened this issue · 5 comments
We are running Dream for https://builds.robur.coop on a FreeBSD 12.2 machine. This works smoothly, and the footprint looks much smaller than our previous opium-based server.
One downside of dream (we're using the latest release - see https://builds.robur.coop/job/builder-web-freebsd/build/4b2a96cd-c922-4ee9-a786-475f49878562/f/opam-switch for the full set of opam packages we're using) is that client connection errors are reported in the log:
Jul 8 13:07:46 <daemon.notice> 192.168.42.4 daemon[42523]: 08.07.21 13:07:46.179 dream.http ERROR HTTP (192.168.0.6:39544): Unix.Unix_error(Unix.ECONNRESET, "read", "")
Jul 8 13:07:46 <daemon.notice> 192.168.42.4 daemon[42523]: 08.07.21 13:07:46.179 dream.http ERROR Raised by primitive operation at Lwt_unix.shutdown in file "src/unix/lwt_unix.cppo.ml", line 1677, characters 2-38
Jul 8 13:07:46 <daemon.notice> 192.168.42.4 daemon[42523]: 08.07.21 13:07:46.179 dream.http ERROR Called from Gluten_lwt_unix.Io.close.(fun) in file "src/vendor/gluten/lwt-unix/gluten_lwt_unix.ml", line 49, characters 10-47
Jul 8 13:07:46 <daemon.notice> 192.168.42.4 daemon[42523]: 08.07.21 13:07:46.179 dream.http ERROR Called from Lwt.Sequential_composition.catch in file "src/core/lwt.ml", line 2023, characters 16-20
Jul 8 13:07:46 <daemon.notice> 192.168.42.4 daemon[42523]: 08.07.21 13:07:46.180 dream.http ERROR Error handler raised: Failure("cannot write to closed writer")
Jul 8 13:07:46 <daemon.notice> 192.168.42.4 daemon[42523]: 08.07.21 13:07:46.180 dream.http ERROR Raised at Stdlib.failwith in file "stdlib.ml", line 29, characters 17-33
Jul 8 13:07:46 <daemon.notice> 192.168.42.4 daemon[42523]: 08.07.21 13:07:46.180 dream.http ERROR Called from Faraday.writable_exn in file "lib/faraday.ml" (inlined), line 191, characters 4-44
Jul 8 13:07:46 <daemon.notice> 192.168.42.4 daemon[42523]: 08.07.21 13:07:46.180 dream.http ERROR Called from Faraday.write_gen in file "lib/faraday.ml", line 234, characters 2-16
Jul 8 13:07:46 <daemon.notice> 192.168.42.4 daemon[42523]: 08.07.21 13:07:46.180 dream.http ERROR Called from Httpaf__Serialize.write_response in file "src/vendor/httpaf/lib/serialize.ml", line 65, characters 2-25
Jul 8 13:07:46 <daemon.notice> 192.168.42.4 daemon[42523]: 08.07.21 13:07:46.180 dream.http ERROR Called from Httpaf__Serialize.Writer.write_response in file "src/vendor/httpaf/lib/serialize.ml" (inlined), line 121, characters 4-37
Jul 8 13:07:46 <daemon.notice> 192.168.42.4 daemon[42523]: 08.07.21 13:07:46.180 dream.http ERROR Called from Httpaf__Server_connection.set_error_and_handle.(fun) in file "src/vendor/httpaf/lib/server_connection.ml", line 191, characters 10-47
Jul 8 13:07:46 <daemon.notice> 192.168.42.4 daemon[42523]: 08.07.21 13:07:46.180 dream.http ERROR Called from Dream__http__Error_handler.httpaf.(fun) in file "src/http/error_handler.ml", line 374, characters 17-39
Jul 8 13:07:46 <daemon.notice> 192.168.42.4 daemon[42523]: 08.07.21 13:07:46.180 dream.http ERROR Called from Lwt.Sequential_composition.catch in file "src/core/lwt.ml", line 2023, characters 16-20
This are logs reported via syslog to a syslog sink, that's why there are multiple headers.
Curious whether this only happens on FreeBSD, or on other systems as well when the client resets the connection before the HTTP request-response is done? It would be great to have an informational message about the connection reset, and keep the errors for actual server errors (at the moment, it is hard to derive anything from the number or errors reported via Logs, since a single connection reset (e.g. a port scanner or a TCP connection that is immediately reset) leads to 13 error message.
(On FreeBSD, you can use telnet/socat and tcpdrop to provoke a connection reset -- on Linux you may use tcpkill to reset the connection.)
I haven't had a chance to look into this, whether it occurs on other systems, etc. However, it is indeed the Dream convention that, by default, client-side errors are reported as warnings, while server-side errors are reported as errors. This might need special-casing on top of that, but for sure these shouldn't be ERRORs, at least.
It looks like an unhandled ECONNRESET exception is being treated as a server-side error, which in a way, it is (an error within Dream itself, for not handling the exception more intelligently). I expect this occurs on all platforms.
Hi @aantron - I took a stab at a simple fix for this. #165
One other thing to note, I had to add https://github.com/dinosaure/paf-le-chien/pull/41/files to the paf
submodule to let this compile successfully.
A similar observation is Unix.Unix_error(Unix.ETIMEDOUT, "read", "")
with a similar stack (Lwt_unix.shutdown & Gluten_lwt_unix.Io.close(fun)).
I am able to reproduce this on macOS Monterrey 12.0.1, by running an HTTP load testing tool against dream, e.g.
# From https://github.com/wg/wrk
wrk -c 10 -d 10s -t 4 http://localhost:8080
Error:
08.12.21 22:45:54.007 dream.http ERROR HTTP (::1:54719): Unix.Unix_error(Unix.ECONNRESET, "read", "")
This is on OCaml 4.13.1.
On 4.12.0+domains
, dream is exiting with Bus error: 10
after a few requests.