Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Address ECONNRESET in issue #118 #165

Open
wants to merge 4 commits into
base: master
Choose a base branch
from
Open
Show file tree
Hide file tree
Changes from 2 commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
4 changes: 4 additions & 0 deletions dream.opam
Original file line number Diff line number Diff line change
Expand Up @@ -55,6 +55,7 @@ depends: [
"conf-libev" {os != "win32"}
"cstruct" {>= "6.0.0"}
"dune" {>= "2.7.0"} # --instrument-with.
"emile"
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

AFAIK Dream should not depend on emile at all. What is your setup in some more detail, and what did you observe that caused adding emile here?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I generally use esy to build ocaml projects, almost as a force of habit. I believe I was building "everything", including tests, examples, etc. and esy was complaining about emile. I went back with a new switch and ran the opam install --deps-only ./dream.opam --with-test which worked. I will pull back this dependency from the PR.

"fmt" {>= "0.8.7"} # `Italic.
"graphql_parser"
"graphql-lwt"
Expand All @@ -64,9 +65,12 @@ depends: [
"lwt_ssl"
"logs" {>= "0.5.0"}
"magic-mime"
"mimic"
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This should be moved to dream-mirage.opam, which does seem to depend directly on mimic (and the dependency is not listed). Does this work with your setup if it is moved?

"mirage-clock"
"mirage-crypto" {>= "0.8.1"} # AES-256-GCM.
"mirage-crypto-rng" {>= "0.8.0"} # Signature of initialize.
"mirage-time"
"mirage-stack"
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

These should probably also be moved to dream-mirage.opam.

"multipart_form" {>= "0.3.0"}
"ocaml" {>= "4.08.0"}
"ssl" {>= "0.5.8"} # Ssl.get_negotiated_alpn_protocol.
Expand Down
1 change: 1 addition & 0 deletions dune-project
Original file line number Diff line number Diff line change
@@ -1 +1,2 @@
(lang dune 2.7)
(cram enable)
70 changes: 38 additions & 32 deletions src/http/error_handler.ml
Original file line number Diff line number Diff line change
Expand Up @@ -117,40 +117,46 @@ let customize template (error : Dream.error) =

(* First, log the error. *)

let log_handler condition (error : Dream.error) =
let client =
match error.client with
| None -> ""
| Some client -> " (" ^ client ^ ")"
in

let layer =
match error.layer with
| `TLS -> ["TLS" ^ client]
| `HTTP -> ["HTTP" ^ client]
| `HTTP2 -> ["HTTP/2" ^ client]
| `WebSocket -> ["WebSocket" ^ client]
| `App -> []
in

let description, backtrace =
match condition with
| `String string -> string, ""
| `Exn exn ->
let backtrace = Printexc.get_backtrace () in
Printexc.to_string exn, backtrace
in

let message = String.concat ": " (layer @ [description]) in

select_log error.severity (fun log ->
log ?request:error.request "%s" message);
backtrace |> Dream__middleware.Log.iter_backtrace (fun line ->
select_log error.severity (fun log ->
log ?request:error.request "%s" line))
in
begin match error.condition with
| `Response _ -> ()
| `String _ | `Exn _ as condition ->

let client =
match error.client with
| None -> ""
| Some client -> " (" ^ client ^ ")"
in

let layer =
match error.layer with
| `TLS -> ["TLS" ^ client]
| `HTTP -> ["HTTP" ^ client]
| `HTTP2 -> ["HTTP/2" ^ client]
| `WebSocket -> ["WebSocket" ^ client]
| `App -> []
in

let description, backtrace =
match condition with
| `String string -> string, ""
| `Exn exn ->
let backtrace = Printexc.get_backtrace () in
Printexc.to_string exn, backtrace
in

let message = String.concat ": " (layer @ [description]) in

select_log error.severity (fun log ->
log ?request:error.request "%s" message);
backtrace |> Dream__middleware.Log.iter_backtrace (fun line ->
select_log error.severity (fun log ->
log ?request:error.request "%s" line))
(* TODO is this the right place to handle lower level connection resets? *)
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm not yet sure where this should be handled. Going to discuss a bit in #118, and do some research.

| `Exn (Unix.Unix_error (Unix.ECONNRESET, _, _)) ->
let condition = `String "Connection Reset at Client" in
let severity = `Info in
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@hannesm Would it be fine for your use case if the errors were reported as warnings, as already done for most other client errors?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

sure. at the same time with an operations view, I'd expect if warning and error level occur, I should check the log and look how to fix the issues. OTOH if a random client resets the TCP connection or sends a malformed request, that should be on the informational level. but eventually that should be discussed in a different issue and applied uniformally.

log_handler condition {error with condition; severity}
| `String _ | `Exn _ as condition -> log_handler condition error
end;

(* If Dream will not send a response for this error, we are done after
Expand Down
2 changes: 2 additions & 0 deletions test/cram/dune
Original file line number Diff line number Diff line change
@@ -0,0 +1,2 @@
(cram
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Rather than a cram test, could this be done using an in-process expect test? It seems like that approach would be more portable, as it wouldn't depend on Unix commands, and could be a bit less awkward, since it wouldn't require any complex shell command lines (everything would be kept in OCaml code).

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I spent some time today on this, I wanted to report back and see if you have any thoughts on a different approach.

Short answer is that it is possible, but without modifying Dream itself to add test hooks into the http module, quite ugly.

I have a successful expect test which does 3 things:

  1. Spins up a server on an open port using Dream.serve with a stop promise.
  2. Continually runs a "reset client" which tries to connect to the server. If it connects, it immediately closes the socket fd which causes an RST packet to be sent to the server. It then resolves the stop promise.
  3. Those two promises race against a third timeout promise - if the "reset client" doesn't resolve the stop promise in 4 seconds, the whole thing gets torn down.

A few things I don't like:

  • The test has to ignore SIGPIPE since closing the fd the way it does signals a closed pipe.
  • There is a timer since there's a potential the server can get stuck due to other failures, causing the test to stall indefinitely.
  • Since the server actually binds to an open TCP port, and we don't know when that binding succeeds, there's retry logic in the "reset client." This is kind of painful.

Reviewing the expect tests got me thinking: how useful would it be to offer a test capability to be able to inject errors at various points in Dream's request processing cycle to validate their behaviors?

Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

how useful would it be to offer a test capability to be able to inject errors at various points in Dream's request processing cycle to validate their behaviors?

Potentially very useful. I have a big project/roadmap category for making Dream apps (and probably Dream itself) really testable. But it's in the queue behind several other things.

I think it's fine then to use a cram test. If really good programmatic Dream testing materializes, I can change the test to use that later, if necessary.

(applies_to :whole_subtree))
6 changes: 6 additions & 0 deletions test/cram/http/dune
Original file line number Diff line number Diff line change
@@ -0,0 +1,6 @@
(executable
(name econnreset)
(libraries dream))

(cram
(deps %{exe:econnreset.exe}))
49 changes: 49 additions & 0 deletions test/cram/http/econnreset.ml
Original file line number Diff line number Diff line change
@@ -0,0 +1,49 @@
(* This file is part of Dream, released under the MIT license. See LICENSE.md
for details, or visit https://github.com/aantron/dream.

Copyright 2021 Anton Bachin *)

let serve port =
print_endline "server mode";
Dream.run ~greeting:false ~port (fun _ -> Unix.sleepf 10.0; Dream.html "Hello")

let client port =
print_endline "client mode";
let open Unix in
let fd = socket PF_INET6 SOCK_STREAM 0 in
(* force the client to send a TCP RST packet if it fails during connection *)
setsockopt_optint fd SO_LINGER (Some 0);
let _ = connect fd (ADDR_INET (inet6_addr_loopback, port)) in
ignore @@ failwith "sending RST"

let print_open_port () =
let open Unix in
let fd = socket PF_INET6 SOCK_STREAM 0 in
bind fd (ADDR_INET (inet6_addr_loopback, 0));

begin match getsockname fd with
| ADDR_INET (_, port) -> Printf.printf "%d\n" port
| _ -> failwith "Invalid Socket response"
end;

exit 0

let () =
let server = ref(false) in
let port = ref(-1) in
let usage = "Test for ECONNRESET errors being reported" in
Arg.parse [
"-p", Set_int port, "sets the port to listen on or connect to, if not specified, prints an available TCP port and exits";
"-s", Set server, "enables the server on port [port], if not set sends a TCP RST on [port]"
] (fun _ -> ()) usage;

let port = !port in

(* see if we need to print an open port or validate the port *)
if port = -1 then print_open_port ()
else if port > 65535 || port < 1025
then failwith "Port argument (-p) must set and be between 1025-65535";

if !server then serve port
else client port

19 changes: 19 additions & 0 deletions test/cram/http/issue_118_econnreset.t
Original file line number Diff line number Diff line change
@@ -0,0 +1,19 @@
Start a Dream server

$ export PORT=$(./econnreset.exe)
$ ./econnreset.exe -s -p "${PORT}" &> test.log &
$ export PID=$!
$ sleep 1

Force a connection reset - will log a few errors

$ ./econnreset.exe -p "${PORT}"

Does the log contain an error line for the ECONNRESET? An error code of [1] is "good", meaning no line was found.

$ kill "${PID}"
$ cat test.log | grep 'ERROR' | grep 'ECONNRESET'

Does the log contain an info line with custom string for the ECONNRESET?

$ cat test.log | grep 'INFO' | grep 'Connection Reset at Client' | wc -l