From 008a813be7fba88b9d7b53e52ae08013c71dd956 Mon Sep 17 00:00:00 2001 From: Pau Ruiz Safont Date: Tue, 1 Oct 2024 12:53:32 +0100 Subject: [PATCH 1/6] http-lib: add backtrace to logs on connection without response Signed-off-by: Pau Ruiz Safont --- ocaml/libs/http-lib/http_client.ml | 10 +++++++++- 1 file changed, 9 insertions(+), 1 deletion(-) diff --git a/ocaml/libs/http-lib/http_client.ml b/ocaml/libs/http-lib/http_client.ml index 8e8c5cd2d44..5cb67212bcc 100644 --- a/ocaml/libs/http-lib/http_client.ml +++ b/ocaml/libs/http-lib/http_client.ml @@ -177,6 +177,11 @@ let response_of_fd_exn fd = (Astring.String.cuts ~sep:"\n" buf) ) +(* Use a different logging brand, the one used by {D} is ignore in the default + configuration. This allows to have visibility of an issue that interrupts + storage migrations. *) +module L = Debug.Make (struct let name = __MODULE__ end) + (** [response_of_fd fd] returns an optional Http.Response.t record *) let response_of_fd ?(use_fastpath = false) fd = try @@ -188,7 +193,10 @@ let response_of_fd ?(use_fastpath = false) fd = | Unix.Unix_error (_, _, _) as e -> raise e | e -> - D.debug "%s: returning no response because of the exception: %s" + Backtrace.is_important e ; + let bt = Backtrace.get e in + Debug.log_backtrace e bt ; + L.debug "%s: returning no response because of the exception: %s" __FUNCTION__ (Printexc.to_string e) ; None From ed961460921468f16791472b8bf35cb90e886e00 Mon Sep 17 00:00:00 2001 From: Pau Ruiz Safont Date: Fri, 4 Oct 2024 14:05:15 +0100 Subject: [PATCH 2/6] http-lib: convert bash script to cram tests Gives more flexibility in tests. Now the results from the client aren't printed, but weren't important to pass the test anyway. Signed-off-by: Pau Ruiz Safont --- ocaml/libs/http-lib/client_server_test.sh | 11 ----------- ocaml/libs/http-lib/dune | 6 +----- ocaml/libs/http-lib/test_client_server.t | 7 +++++++ 3 files changed, 8 insertions(+), 16 deletions(-) delete mode 100644 ocaml/libs/http-lib/client_server_test.sh create mode 100644 ocaml/libs/http-lib/test_client_server.t diff --git a/ocaml/libs/http-lib/client_server_test.sh b/ocaml/libs/http-lib/client_server_test.sh deleted file mode 100644 index 601ed257f99..00000000000 --- a/ocaml/libs/http-lib/client_server_test.sh +++ /dev/null @@ -1,11 +0,0 @@ -#!/bin/bash - -set -eux - -trap 'kill $(jobs -p)' EXIT - -./test_server.exe & -sleep 1 - -./test_client.exe - diff --git a/ocaml/libs/http-lib/dune b/ocaml/libs/http-lib/dune index ead0f1d19f6..d4e22f7d3c5 100644 --- a/ocaml/libs/http-lib/dune +++ b/ocaml/libs/http-lib/dune @@ -133,14 +133,10 @@ ) ) -(rule - (alias runtest) +(cram (package xapi) (deps test_client.exe test_server.exe - client_server_test.sh ) - (action (run bash client_server_test.sh)) ) - diff --git a/ocaml/libs/http-lib/test_client_server.t b/ocaml/libs/http-lib/test_client_server.t new file mode 100644 index 00000000000..12ac42da6c8 --- /dev/null +++ b/ocaml/libs/http-lib/test_client_server.t @@ -0,0 +1,7 @@ +== Bring server up + $ trap 'kill $(jobs -p)' EXIT + $ ./test_server.exe & + $ sleep 1 + +== Normal + $ ./test_client.exe > /dev/null From 3bef65f8b7948992825c68a0deff098ace7ce8b1 Mon Sep 17 00:00:00 2001 From: Pau Ruiz Safont Date: Fri, 4 Oct 2024 18:21:41 +0100 Subject: [PATCH 3/6] http-lib: prepare test client for more commands Current behaviour for displaying stats is done with the --perf parameter Signed-off-by: Pau Ruiz Safont --- ocaml/libs/http-lib/test_client.ml | 50 +++++++++++------------- ocaml/libs/http-lib/test_client_server.t | 4 +- 2 files changed, 25 insertions(+), 29 deletions(-) diff --git a/ocaml/libs/http-lib/test_client.ml b/ocaml/libs/http-lib/test_client.ml index 041e08b0db4..4bc7f2a3e16 100644 --- a/ocaml/libs/http-lib/test_client.ml +++ b/ocaml/libs/http-lib/test_client.ml @@ -4,12 +4,15 @@ open Safe_resources let user_agent = "test_client" -(* To do: - 1. test with and without SSL - 2. test with n parallel threads - 3. make sure xapi still works - 4. make xapi able to read stats -*) +let ip = ref "127.0.0.1" + +let port = ref 8080 + +let use_ssl = ref false + +let use_fastpath = ref false + +let use_framing = ref false let with_connection ip port f = let inet_addr = Unix.inet_addr_of_string ip in @@ -108,30 +111,10 @@ let sample n f = done ; !p -let _ = - let ip = ref "127.0.0.1" in - let port = ref 8080 in - let use_ssl = ref false in - let use_fastpath = ref false in - let use_framing = ref false in - Arg.parse - [ - ("-ip", Arg.Set_string ip, "IP to connect to") - ; ("-p", Arg.Set_int port, "port to connect") - ; ("-fast", Arg.Set use_fastpath, "use HTTP fastpath") - ; ("-frame", Arg.Set use_framing, "use HTTP framing") - ; ("--ssl", Arg.Set use_ssl, "use SSL rather than plaintext") - ] - (fun x -> Printf.fprintf stderr "Ignoring unexpected argument: %s\n" x) - "A simple test HTTP client" ; +let perf () = let use_fastpath = !use_fastpath in let use_framing = !use_framing in let transport = if !use_ssl then with_stunnel else with_connection in - (* - Printf.printf "Overhead of timing: "; - let overhead = sample 10 (fun () -> per_nsec 1. (fun () -> ())) in - Printf.printf "%s ops/sec\n" (Normal_population.to_string overhead); -*) Printf.printf "1 thread non-persistent connections: " ; let nonpersistent = sample 1 (fun () -> @@ -183,3 +166,16 @@ let _ = ) in Printf.printf "%s RPCs/sec\n%!" (Normal_population.to_string thread_persistent) + +let () = + Arg.parse + [ + ("-ip", Arg.Set_string ip, "IP to connect to") + ; ("-p", Arg.Set_int port, "port to connect") + ; ("-fast", Arg.Set use_fastpath, "use HTTP fastpath") + ; ("-frame", Arg.Set use_framing, "use HTTP framing") + ; ("--ssl", Arg.Set use_ssl, "use SSL rather than plaintext") + ; ("--perf", Arg.Unit perf, "Collect performance stats") + ] + (fun x -> Printf.fprintf stderr "Ignoring unexpected argument: %s\n" x) + "A simple test HTTP client" diff --git a/ocaml/libs/http-lib/test_client_server.t b/ocaml/libs/http-lib/test_client_server.t index 12ac42da6c8..21dc6762de1 100644 --- a/ocaml/libs/http-lib/test_client_server.t +++ b/ocaml/libs/http-lib/test_client_server.t @@ -1,7 +1,7 @@ == Bring server up $ trap 'kill $(jobs -p)' EXIT $ ./test_server.exe & - $ sleep 1 + $ sleep 0.1 == Normal - $ ./test_client.exe > /dev/null + $ ./test_client.exe --perf > /dev/null From d8bd9f233b86c2ef8dec1279ce515e579986da5c Mon Sep 17 00:00:00 2001 From: Pau Ruiz Safont Date: Mon, 7 Oct 2024 15:56:53 +0100 Subject: [PATCH 4/6] http-libs: add test about error logging While this does not exercise the exact error that can happen in long migrations, it gets logged in a similar way. There's no easy way to trigger the issue, the best chance is to send a malformed response to trigger a Parse_error. I did modify the code in http_client and verified that current code can produce the logging, with backtraces successfully, when set up properly (like in the test client) Signed-off-by: Pau Ruiz Safont --- ocaml/libs/http-lib/dune | 2 ++ ocaml/libs/http-lib/test_client.ml | 39 ++++++++++++++++++++++++ ocaml/libs/http-lib/test_client_server.t | 9 ++++++ ocaml/libs/http-lib/test_server.ml | 4 +++ 4 files changed, 54 insertions(+) diff --git a/ocaml/libs/http-lib/dune b/ocaml/libs/http-lib/dune index d4e22f7d3c5..cc5bec51648 100644 --- a/ocaml/libs/http-lib/dune +++ b/ocaml/libs/http-lib/dune @@ -113,6 +113,8 @@ safe-resources stunnel threads.posix + xapi-backtrace + xapi-log xapi-stdext-pervasives xapi-stdext-unix ) diff --git a/ocaml/libs/http-lib/test_client.ml b/ocaml/libs/http-lib/test_client.ml index 4bc7f2a3e16..43b4eb84e5e 100644 --- a/ocaml/libs/http-lib/test_client.ml +++ b/ocaml/libs/http-lib/test_client.ml @@ -167,6 +167,44 @@ let perf () = in Printf.printf "%s RPCs/sec\n%!" (Normal_population.to_string thread_persistent) +let send_close_conn ~use_fastpath ~use_framing keep_alive s = + try + Http_client.rpc ~use_fastpath s + (Http.Request.make ~frame:use_framing ~version:"1.1" ~keep_alive + ~user_agent ~body:"hello" Http.Get "/close_conn" + ) (fun response s -> + match response.Http.Response.content_length with + | Some l -> + let _ = Unixext.really_read_string s (Int64.to_int l) in + Printf.printf "Received a response with %Ld bytes.\n" l ; + exit 1 + | None -> + Printf.printf "Need a content length\n" ; + exit 1 + ) + with Unix.Unix_error (Unix.ECONNRESET, "read", "") as e -> + Backtrace.is_important e ; + let bt = Backtrace.get e in + Debug.log_backtrace e bt + +let ( let@ ) f x = f x + +let logerr () = + (* Send a request to the server to close connection instead of replying with + an http request, force the error to be logged *) + Printexc.record_backtrace true ; + Debug.log_to_stdout () ; + Debug.set_level Syslog.Debug ; + let use_fastpath = !use_fastpath in + let use_framing = !use_framing in + let transport = if !use_ssl then with_stunnel else with_connection in + let call () = + let@ () = Backtrace.with_backtraces in + let@ s = transport !ip !port in + send_close_conn ~use_fastpath ~use_framing false s + in + match call () with `Ok () -> () | `Error (_, _) -> () + let () = Arg.parse [ @@ -176,6 +214,7 @@ let () = ; ("-frame", Arg.Set use_framing, "use HTTP framing") ; ("--ssl", Arg.Set use_ssl, "use SSL rather than plaintext") ; ("--perf", Arg.Unit perf, "Collect performance stats") + ; ("--logerr", Arg.Unit logerr, "Test log on error") ] (fun x -> Printf.fprintf stderr "Ignoring unexpected argument: %s\n" x) "A simple test HTTP client" diff --git a/ocaml/libs/http-lib/test_client_server.t b/ocaml/libs/http-lib/test_client_server.t index 21dc6762de1..2d862d29c81 100644 --- a/ocaml/libs/http-lib/test_client_server.t +++ b/ocaml/libs/http-lib/test_client_server.t @@ -5,3 +5,12 @@ == Normal $ ./test_client.exe --perf > /dev/null + +== Expect to log after a closed connection + $ ./test_client.exe --logerr > result + $ grep "ECONNRESET" result -c + 1 + $ grep "backtrace" result -c + 11 + $ grep "Called from" result -c + 8 diff --git a/ocaml/libs/http-lib/test_server.ml b/ocaml/libs/http-lib/test_server.ml index a1f703042ee..2cae4f4ba5f 100644 --- a/ocaml/libs/http-lib/test_server.ml +++ b/ocaml/libs/http-lib/test_server.ml @@ -80,6 +80,10 @@ let _ = ) ) ) ; + (* Forces a protocol error by closing the connection without sending a + proper http reponse code *) + Server.add_handler server Http.Get "/close_conn" + (FdIO (fun _ _ _ -> raise End_of_file)) ; let ip = "0.0.0.0" in let inet_addr = Unix.inet_addr_of_string ip in let addr = Unix.ADDR_INET (inet_addr, !port) in From cda61943ef4031dd84cc0bed381f24568886f1c7 Mon Sep 17 00:00:00 2001 From: Pau Ruiz Safont Date: Wed, 9 Oct 2024 14:19:33 +0100 Subject: [PATCH 5/6] http-lib: use let@ for perf testing of the client No functional difference Signed-off-by: Pau Ruiz Safont --- ocaml/libs/http-lib/test_client.ml | 52 ++++++++++++------------------ 1 file changed, 21 insertions(+), 31 deletions(-) diff --git a/ocaml/libs/http-lib/test_client.ml b/ocaml/libs/http-lib/test_client.ml index 43b4eb84e5e..b8ca7a1ad18 100644 --- a/ocaml/libs/http-lib/test_client.ml +++ b/ocaml/libs/http-lib/test_client.ml @@ -111,59 +111,51 @@ let sample n f = done ; !p +let ( let@ ) f x = f x + let perf () = let use_fastpath = !use_fastpath in let use_framing = !use_framing in let transport = if !use_ssl then with_stunnel else with_connection in Printf.printf "1 thread non-persistent connections: " ; let nonpersistent = - sample 1 (fun () -> - per_nsec 1. (fun () -> - transport !ip !port (one ~use_fastpath ~use_framing false) - ) - ) + let@ () = sample 1 in + let@ () = per_nsec 1. in + transport !ip !port (one ~use_fastpath ~use_framing false) in Printf.printf "%s RPCs/sec\n%!" (Normal_population.to_string nonpersistent) ; Printf.printf "1 thread non-persistent connections (query): " ; let nonpersistent_query = - sample 1 (fun () -> - per_nsec 1. (fun () -> - transport !ip !port (query ~use_fastpath ~use_framing false) - ) - ) + let@ () = sample 1 in + let@ () = per_nsec 1. in + transport !ip !port (query ~use_fastpath ~use_framing false) in Printf.printf "%s RPCs/sec\n%!" (Normal_population.to_string nonpersistent_query) ; Printf.printf "10 threads non-persistent connections: " ; let thread_nonpersistent = - sample 1 (fun () -> - threads 10 (fun () -> - per_nsec 5. (fun () -> - transport !ip !port (one ~use_fastpath ~use_framing false) - ) - ) - ) + let@ () = sample 1 in + let@ () = threads 10 in + let@ () = per_nsec 5. in + transport !ip !port (one ~use_fastpath ~use_framing false) in Printf.printf "%s RPCs/sec\n%!" (Normal_population.to_string thread_nonpersistent) ; Printf.printf "1 thread persistent connection: " ; let persistent = - sample 1 (fun () -> - transport !ip !port (fun s -> - per_nsec 1. (fun () -> one ~use_fastpath ~use_framing true s) - ) - ) + let@ () = sample 1 in + let@ s = transport !ip !port in + let@ () = per_nsec 1. in + one ~use_fastpath ~use_framing true s in Printf.printf "%s RPCs/sec\n%!" (Normal_population.to_string persistent) ; Printf.printf "10 threads persistent connections: " ; let thread_persistent = - sample 1 (fun () -> - threads 10 (fun () -> - transport !ip !port (fun s -> - per_nsec 5. (fun () -> one ~use_fastpath ~use_framing true s) - ) - ) - ) + let@ () = sample 1 in + let@ () = threads 10 in + let@ s = transport !ip !port in + let@ () = per_nsec 5. in + one ~use_fastpath ~use_framing true s in Printf.printf "%s RPCs/sec\n%!" (Normal_population.to_string thread_persistent) @@ -187,8 +179,6 @@ let send_close_conn ~use_fastpath ~use_framing keep_alive s = let bt = Backtrace.get e in Debug.log_backtrace e bt -let ( let@ ) f x = f x - let logerr () = (* Send a request to the server to close connection instead of replying with an http request, force the error to be logged *) From 4f8644106598af03993c44a6289a43dca72f4975 Mon Sep 17 00:00:00 2001 From: Pau Ruiz Safont Date: Wed, 9 Oct 2024 14:29:26 +0100 Subject: [PATCH 6/6] http-lib: make perf shorter Taking measurements in practice doesn't lead to improved accuracy. Also change the tests so more than one sample is collected and can know how noisy the measurements really are. Here's an example of a run, including the result before the change: ``` $ ./test_client.exe --perf - 1 thread non-persistent connections: 4896.0 +/- 0.0 RPCs/sec - 1 thread non-persistent connections (query): 4811.0 +/- 0.0 RPCs/sec - 10 threads non-persistent connections: 7175.0 +/- 0.0 RPCs/sec - 1 thread persistent connection: 16047.0 +/- 0.0 RPCs/sec - 10 threads persistent connections: 7713.0 +/- 0.0 RPCs/sec + 1 thread non-persistent connections: 5042.0 +/- 247.5 RPCs/sec + 1 thread non-persistent connections (query): 5173.0 +/- 216.0 RPCs/sec + 10 threads non-persistent connections: 7678.0 +/- 2241.2 RPCs/sec + 1 thread persistent connection: 21814.0 +/- 2124.6 RPCs/sec + 10 threads persistent connections: 10154.0 +/- 2461.9 RPCs/sec ``` Signed-off-by: Pau Ruiz Safont --- ocaml/libs/http-lib/test_client.ml | 30 +++++++++++++++--------------- 1 file changed, 15 insertions(+), 15 deletions(-) diff --git a/ocaml/libs/http-lib/test_client.ml b/ocaml/libs/http-lib/test_client.ml index b8ca7a1ad18..eada0811a42 100644 --- a/ocaml/libs/http-lib/test_client.ml +++ b/ocaml/libs/http-lib/test_client.ml @@ -117,44 +117,44 @@ let perf () = let use_fastpath = !use_fastpath in let use_framing = !use_framing in let transport = if !use_ssl then with_stunnel else with_connection in - Printf.printf "1 thread non-persistent connections: " ; + Printf.printf "1 thread non-persistent connections: " ; let nonpersistent = - let@ () = sample 1 in - let@ () = per_nsec 1. in + let@ () = sample 10 in + let@ () = per_nsec 0.1 in transport !ip !port (one ~use_fastpath ~use_framing false) in Printf.printf "%s RPCs/sec\n%!" (Normal_population.to_string nonpersistent) ; - Printf.printf "1 thread non-persistent connections (query): " ; + Printf.printf "1 thread non-persistent connections (query): " ; let nonpersistent_query = - let@ () = sample 1 in - let@ () = per_nsec 1. in + let@ () = sample 10 in + let@ () = per_nsec 0.1 in transport !ip !port (query ~use_fastpath ~use_framing false) in Printf.printf "%s RPCs/sec\n%!" (Normal_population.to_string nonpersistent_query) ; - Printf.printf "10 threads non-persistent connections: " ; + Printf.printf "10 threads non-persistent connections: " ; let thread_nonpersistent = - let@ () = sample 1 in + let@ () = sample 10 in let@ () = threads 10 in - let@ () = per_nsec 5. in + let@ () = per_nsec 0.1 in transport !ip !port (one ~use_fastpath ~use_framing false) in Printf.printf "%s RPCs/sec\n%!" (Normal_population.to_string thread_nonpersistent) ; - Printf.printf "1 thread persistent connection: " ; + Printf.printf "1 thread persistent connection: " ; let persistent = - let@ () = sample 1 in + let@ () = sample 10 in let@ s = transport !ip !port in - let@ () = per_nsec 1. in + let@ () = per_nsec 0.1 in one ~use_fastpath ~use_framing true s in Printf.printf "%s RPCs/sec\n%!" (Normal_population.to_string persistent) ; - Printf.printf "10 threads persistent connections: " ; + Printf.printf "10 threads persistent connections: " ; let thread_persistent = - let@ () = sample 1 in + let@ () = sample 10 in let@ () = threads 10 in let@ s = transport !ip !port in - let@ () = per_nsec 5. in + let@ () = per_nsec 0.1 in one ~use_fastpath ~use_framing true s in Printf.printf "%s RPCs/sec\n%!" (Normal_population.to_string thread_persistent)