From a75852d643515372e08155356202f70565ddb5f6 Mon Sep 17 00:00:00 2001 From: David Li Date: Fri, 26 Feb 2021 07:35:13 -0500 Subject: [PATCH 1/2] ARROW-11717: [Integration] report debug logs for failing Flight case --- dev/archery/archery/integration/tester_cpp.py | 6 +++++- dev/archery/archery/integration/util.py | 9 +++++++-- 2 files changed, 12 insertions(+), 3 deletions(-) diff --git a/dev/archery/archery/integration/tester_cpp.py b/dev/archery/archery/integration/tester_cpp.py index d35c9550e58..fce94d2b659 100644 --- a/dev/archery/archery/integration/tester_cpp.py +++ b/dev/archery/archery/integration/tester_cpp.py @@ -113,4 +113,8 @@ def flight_request(self, port, json_path=None, scenario_name=None): if self.debug: log(' '.join(cmd)) - run_cmd(cmd) + # ARROW-11717: try to get more debug info from a flaky case + run_cmd(cmd, extra_env_vars={ + "GRPC_VERBOSITY": "debug", + "GRPC_TRACE": "all", + }) diff --git a/dev/archery/archery/integration/util.py b/dev/archery/archery/integration/util.py index a4c4982ecb3..816d6ca42c9 100644 --- a/dev/archery/archery/integration/util.py +++ b/dev/archery/archery/integration/util.py @@ -131,12 +131,17 @@ def frombytes(o): return o -def run_cmd(cmd): +def run_cmd(cmd, extra_env_vars=None): if isinstance(cmd, str): cmd = cmd.split(' ') + env = os.environ.copy() + if extra_env_vars: + env.update(**extra_env_vars) + try: - output = subprocess.check_output(cmd, stderr=subprocess.STDOUT) + output = subprocess.check_output(cmd, env=env, + stderr=subprocess.STDOUT) except subprocess.CalledProcessError as e: # this avoids hiding the stdout / stderr of failed processes sio = io.StringIO() From 433d08199edd82d33b1e8eeca6e0bf6cbc05fbe9 Mon Sep 17 00:00:00 2001 From: David Li Date: Fri, 26 Feb 2021 15:13:02 -0500 Subject: [PATCH 2/2] DO NOT MERGE: log server-side actions too --- dev/archery/archery/integration/tester_rust.py | 9 +++++++-- rust/integration-testing/Cargo.toml | 1 + .../src/bin/flight-test-integration-server.rs | 1 + 3 files changed, 9 insertions(+), 2 deletions(-) diff --git a/dev/archery/archery/integration/tester_rust.py b/dev/archery/archery/integration/tester_rust.py index bca80ebae3c..8fa27529ab5 100644 --- a/dev/archery/archery/integration/tester_rust.py +++ b/dev/archery/archery/integration/tester_rust.py @@ -81,9 +81,11 @@ def flight_server(self, scenario_name=None): cmd = cmd + ["--scenario", scenario_name] if self.debug: log(' '.join(cmd)) + env = os.environ.copy() + env["RUST_LOG"] = "debug" server = subprocess.Popen(cmd, - stdout=subprocess.PIPE, - stderr=subprocess.PIPE) + env=env, + stdout=subprocess.PIPE) try: output = server.stdout.readline().decode() if not output.startswith("Server listening on localhost:"): @@ -97,6 +99,9 @@ def flight_server(self, scenario_name=None): yield port finally: server.kill() + out, err = server.communicate() + log(out) + log(err) server.wait(5) def flight_request(self, port, json_path=None, scenario_name=None): diff --git a/rust/integration-testing/Cargo.toml b/rust/integration-testing/Cargo.toml index 12564c74f14..90bd1db785c 100644 --- a/rust/integration-testing/Cargo.toml +++ b/rust/integration-testing/Cargo.toml @@ -34,6 +34,7 @@ arrow = { path = "../arrow" } arrow-flight = { path = "../arrow-flight" } async-trait = "0.1.41" clap = "2.33" +env_logger = "0.8.3" futures = "0.3" hex = "0.4" prost = "0.7" diff --git a/rust/integration-testing/src/bin/flight-test-integration-server.rs b/rust/integration-testing/src/bin/flight-test-integration-server.rs index b1b280743c3..d6a3d82091b 100644 --- a/rust/integration-testing/src/bin/flight-test-integration-server.rs +++ b/rust/integration-testing/src/bin/flight-test-integration-server.rs @@ -24,6 +24,7 @@ type Result = std::result::Result; #[tokio::main] async fn main() -> Result { + env_logger::init(); #[cfg(feature = "logging")] tracing_subscriber::fmt::init();