When the remote peer hangs up, a stash of errors are reported (on the error level in the log)

[hannesm]

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.)

[aantron]

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.

[aantron]

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.

[pm-mck]

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.

[hannesm]

A similar observation is Unix.Unix_error(Unix.ETIMEDOUT, "read", "") with a similar stack (Lwt_unix.shutdown & Gluten_lwt_unix.Io.close(fun)).

[yawaramin]

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.