Collect producing a directory tree but no files with `example-rust` #30

divagant-martian · 2022-06-24T17:44:17Z

I'm trying to get individual log files for each node in a rust test plan, however using testground collect --runner=local:docker RUN_ID produces a directory structure consistent with the number of nodes, but each node is empty. The logs I've tried to get are in the form of println!s, tracing::info and client.record_message

Here is the diff over example-rust. My use case is unrelated to example-rust or to the specific data I'm logging in this case, it just serves for reproducibility. The pingpong testcase in the network plan works just fine

diff --git a/plans/example-rust/Cargo.toml b/plans/example-rust/Cargo.toml
index 8fbea07..f14ea58 100644
--- a/plans/example-rust/Cargo.toml
+++ b/plans/example-rust/Cargo.toml
@@ -17,4 +17,6 @@ serde = { version = "1", features = [ "derive" ] }
 serde_json = "1"
 thiserror = "1"
 tokio = { version = "1", default-features = false, features = ["sync", "rt-multi-thread", "macros", "net"] }
-testground = "0.2.0"
\ No newline at end of file
+testground = "0.2.0"
+tracing = "0.1.35"
+tracing-subscriber = { version = "0.3.11", features = ["env-filter"] }
diff --git a/plans/example-rust/Dockerfile b/plans/example-rust/Dockerfile
index 42173f2..b48e134 100644
--- a/plans/example-rust/Dockerfile
+++ b/plans/example-rust/Dockerfile
@@ -17,4 +17,6 @@ RUN cd ./plan/ && cargo build --release && cargo install --path .
 FROM debian:bullseye-slim
 COPY --from=builder /usr/local/cargo/bin/testplan /usr/local/bin/testplan
 EXPOSE 6060
-ENTRYPOINT ["testplan"]
\ No newline at end of file
+
+ENV RUST_LOG=debug
+ENTRYPOINT ["testplan"]
diff --git a/plans/example-rust/src/main.rs b/plans/example-rust/src/main.rs
index bf71d42..d477f61 100644
--- a/plans/example-rust/src/main.rs
+++ b/plans/example-rust/src/main.rs
@@ -4,6 +4,10 @@ const LISTENING_PORT: u16 = 1234;
 
 #[tokio::main]
 async fn main() -> Result<(), Box<dyn std::error::Error>> {
+    if let Ok(env_filter) = tracing_subscriber::EnvFilter::try_from_default_env() {
+        tracing_subscriber::fmt().with_env_filter(env_filter).init();
+    }
+
     let (client, _run_parameters) = testground::client::Client::new().await?;
     client.wait_network_initialized().await?;
 
@@ -15,6 +19,9 @@ async fn main() -> Result<(), Box<dyn std::error::Error>> {
         .addr
         .ip();
 
+    tracing::info!("Local addr: {}", local_addr);
+    client.record_message(format!("Local addr: {}", local_addr));
+
     match local_addr {
         std::net::IpAddr::V4(addr) if addr.octets()[3] == 2 => {
             println!("Test instance, listening for incoming connections.");

run the daemon

$ testground daemon

then in the testground folder

$ testground plan import --from plans/example-rust

then I run by

$ testground run single --plan=example-rust --testcase=tcp-connect --builder=docker:generic --runner=local:docker --instances=2

in the daemon terminal the plan runs correctly

Then try to get the log files with

$ testground collect --runner=local:docker RUN_ID
#...
# Jun 24 17:40:58.552984	INFO	created file: caqvc74c8i2pjq3ftevg.tgz
$ tree $TESTGROUND_HOME/data/outputs/local_docker/example-rust/RUN_ID
# $TESTGROUND_HOME/data/outputs/local_docker/example-rust/RUN_ID/
# └── single
#     ├── 0
#     └── 1
# 
# 3 directories, 0 files

There are some errors at the end of the run, which I not know if they are related or not. Full output is here

Jun 24 17:57:43.086939	INFO	build completed	{"default_tag": "6798957eba77:latest", "took": "1m15s"}
Jun 24 17:57:43.134576	INFO	got docker image id	{"image_id": "0e11cf0bedda"}
Jun 24 17:57:43.134644	INFO	tagging image	{"image_id": "0e11cf0bedda", "tag": "example-rust:0e11cf0bedda"}
Jun 24 17:57:43.145242	INFO	build succeeded	{"plan": "example-rust", "groups": ["single"], "builder": "docker:generic", "artifact": "0e11cf0bedda"}
Jun 24 17:57:43.145320	INFO	performing healthcheck on runner
Jun 24 17:57:43.171483	INFO	healthcheck: ok
Jun 24 17:57:43.171557	INFO	starting run	{"run_id": "caqvlisc8i2pjq3ftf00", "plan": "example-rust", "case": "tcp-connect", "runner": "local:docker", "instances": 2}
Jun 24 17:57:43.199375	INFO	creating container	{"runner": "local:docker", "run_id": "caqvlisc8i2pjq3ftf00", "name": "tg-example-rust-tcp-connect-caqvlisc8i2pjq3ftf00-single-0"}
Jun 24 17:57:43.343660	INFO	creating container	{"runner": "local:docker", "run_id": "caqvlisc8i2pjq3ftf00", "name": "tg-example-rust-tcp-connect-caqvlisc8i2pjq3ftf00-single-1"}
Jun 24 17:57:43.393016	INFO	starting containers	{"runner": "local:docker", "run_id": "caqvlisc8i2pjq3ftf00", "count": 2}
Jun 24 17:57:43.393131	INFO	starting container	{"runner": "local:docker", "run_id": "caqvlisc8i2pjq3ftf00", "id": "7ec05d3c8f17b04d3dceb344ad09aabe330415f77e295513e4ddc6585da921bf", "group": "single", "group_index": 1}
Jun 24 17:57:43.393123	INFO	starting container	{"runner": "local:docker", "run_id": "caqvlisc8i2pjq3ftf00", "id": "29c7eaa1c6c3b84e44b785fad4c7ca5ec4a563c6afde48fdeb3442b11099566f", "group": "single", "group_index": 0}
Jun 24 17:57:44.191087	INFO	0.7979s      OTHER << sidecar      >> Jun 24 17:57:44.190683	INFO	resolved route to host	{"host": "testground-redis", "ip": "192.18.0.3"}
Jun 24 17:57:44.191219	INFO	0.7981s      OTHER << sidecar      >> Jun 24 17:57:44.190979	INFO	resolved route to host	{"host": "testground-sync-service", "ip": "192.18.0.4"}
Jun 24 17:57:44.191401	INFO	0.7983s      OTHER << sidecar      >> Jun 24 17:57:44.191244	INFO	resolved route to host	{"host": "testground-influxdb", "ip": "192.18.0.6"}
Jun 24 17:57:44.191619	INFO	0.7984s    MESSAGE << sidecar      >> InfluxDB unavailable; no metrics will be dispatched: no InfluxDB URL in $INFLUXDB_URL env var
Jun 24 17:57:44.195079	INFO	0.8019s      OTHER << sidecar      >> Jun 24 17:57:44.194100	INFO	successfully resolved route to host	{"container_id": "29c7eaa1c6c3b84e44b785fad4c7ca5ec4a563c6afde48fdeb3442b11099566f"}
Jun 24 17:57:44.195174	INFO	0.8021s      OTHER << sidecar      >> Jun 24 17:57:44.194568	INFO	external routing disabled
Jun 24 17:57:44.195199	INFO	0.8021s      OTHER << sidecar      >> Jun 24 17:57:44.194640	INFO	waiting for all networks to be ready	{"sidecar": true, "run_id": "caqvlisc8i2pjq3ftf00"}
Jun 24 17:57:44.243369	INFO	started containers	{"runner": "local:docker", "run_id": "caqvlisc8i2pjq3ftf00", "count": 2}
Jun 24 17:57:44.244697	INFO	0.8513s    MESSAGE << sidecar      >> InfluxDB unavailable; no metrics will be dispatched: no InfluxDB URL in $INFLUXDB_URL env var
Jun 24 17:57:44.246981	INFO	0.8539s      OTHER << sidecar      >> Jun 24 17:57:44.246716	INFO	successfully resolved route to host	{"container_id": "7ec05d3c8f17b04d3dceb344ad09aabe330415f77e295513e4ddc6585da921bf"}
Jun 24 17:57:44.247427	INFO	0.8543s      OTHER << sidecar      >> Jun 24 17:57:44.247111	INFO	external routing disabled
Jun 24 17:57:44.247457	INFO	0.8543s      OTHER << sidecar      >> Jun 24 17:57:44.247181	INFO	waiting for all networks to be ready	{"sidecar": true, "run_id": "caqvlisc8i2pjq3ftf00"}
Jun 24 17:57:44.247899	INFO	0.8548s      OTHER << sidecar      >> Jun 24 17:57:44.247679	INFO	all networks ready	{"sidecar": true, "run_id": "caqvlisc8i2pjq3ftf00"}
Jun 24 17:57:44.248121	INFO	0.8550s      OTHER << sidecar      >> Jun 24 17:57:44.247966	INFO	all networks ready	{"sidecar": true, "run_id": "caqvlisc8i2pjq3ftf00"}
Jun 24 17:57:44.248489	INFO	0.8554s      OTHER << single[001] (7ec05d) >> 2022-06-24T17:57:44.248125Z  INFO testplan: Local addr: 16.1.0.2
Jun 24 17:57:44.248541	INFO	0.8554s      OTHER << single[000] (29c7ea) >> 2022-06-24T17:57:44.248125Z  INFO testplan: Local addr: 16.1.0.3
Jun 24 17:57:44.248559	INFO	0.0000s    MESSAGE << single[001] (7ec05d) >> Local addr: 16.1.0.2
Jun 24 17:57:44.248609	INFO	0.8555s      OTHER << single[001] (7ec05d) >> Test instance, listening for incoming connections.
Jun 24 17:57:44.248610	INFO	0.0000s    MESSAGE << single[000] (29c7ea) >> Local addr: 16.1.0.3
Jun 24 17:57:44.248639	INFO	0.8555s      OTHER << single[000] (29c7ea) >> Test instance, connecting to listening instance.
Jun 24 17:57:44.248953	INFO	0.8558s      OTHER << single[000] (29c7ea) >> Established outbound TCP connection.
Jun 24 17:57:44.248980	INFO	0.8559s      OTHER << single[001] (7ec05d) >> Established inbound TCP connection.
Jun 24 17:57:44.249004	INFO	0.8557s         OK << single[000] (29c7ea) >> 
Jun 24 17:57:44.249030	INFO	0.8557s         OK << single[001] (7ec05d) >> 
Jun 24 17:57:44.249317	INFO	0.8562s      OTHER << single[000] (29c7ea) >> Done!
Jun 24 17:57:44.249376	INFO	0.8563s      OTHER << single[000] (29c7ea) >> 2022-06-24T17:57:44.249066Z DEBUG testground::background: Client command sender dropped. Background task shutting down.    
Jun 24 17:57:44.249549	INFO	0.8564s      OTHER << single[001] (7ec05d) >> Done!
Jun 24 17:57:44.303727	INFO	deleting containers	{"runner": "local:docker", "run_id": "caqvlisc8i2pjq3ftf00", "ids": ["29c7eaa1c6c3b84e44b785fad4c7ca5ec4a563c6afde48fdeb3442b11099566f", "7ec05d3c8f17b04d3dceb344ad09aabe330415f77e295513e4ddc6585da921bf"]}
Jun 24 17:57:44.303798	INFO	deleting container	{"runner": "local:docker", "run_id": "caqvlisc8i2pjq3ftf00", "id": "7ec05d3c8f17b04d3dceb344ad09aabe330415f77e295513e4ddc6585da921bf"}
Jun 24 17:57:44.303803	INFO	deleting container	{"runner": "local:docker", "run_id": "caqvlisc8i2pjq3ftf00", "id": "29c7eaa1c6c3b84e44b785fad4c7ca5ec4a563c6afde48fdeb3442b11099566f"}
Jun 24 17:57:45.142549	INFO	run finished with outcome = success (single:2/2)	{"run_id": "caqvlisc8i2pjq3ftf00", "plan": "example-rust", "case": "tcp-connect", "runner": "local:docker", "instances": 2}
Jun 24 17:57:45.146584	INFO	worker completed task	{"worker_id": 1, "task_id": "caqvlisc8i2pjq3ftf00"}
Jun 24 17:57:45.146965	INFO	1.7538s INCOMPLETE << sidecar      >> 
2022-06-24 12:57:45.146965268 -0500 -05 m=+4044.045969251 write error: write $TESTGROUND_HOME/data/daemon/caqvlisc8i2pjq3ftf00.out: file already closed

The text was updated successfully, but these errors were encountered:

mxinden · 2022-06-27T07:32:50Z

sdk-rust does not persist the logs. As far as I can tell, the testground daemon won't do so for us either (right @laurentsenta?).

I am guessing sdk-go itself explicitly persists the logs?

laurentsenta · 2022-06-27T08:52:21Z

True, at the moment testground doesn't capture logs, it expects the SDK to do so,
https://github.com/testground/sdk-go/blob/d78f61eccaa37b0d941f98650bce5dbb8fd7b7f1/runtime/runenv_logger.go#L28-L30

We created testground/testground#1355 to track this

ackintosh · 2023-01-14T14:43:18Z

I'm feeling pain on this issue. If we run a test plan with docker:local runner we can see the outputs from nodes on testground daemon console, but with cluster:k8s runner we can not. (There are not the outputs from nodes in the result of kubectl logs deployment/testground-daemon testground-daemon)

ackintosh · 2023-01-16T05:24:12Z

Making sdk-rust persist the logs same as sdk-go might make sense for the time being?

I would file a PR if that's fine with you. 🙂

laurentsenta · 2023-01-16T09:46:21Z

That makes sense to me; thanks for looking into this,
I'll make sure we eventually prioritize that logging ticket and simplify the SDKs :)

ackintosh · 2023-02-02T06:54:43Z

@laurentsenta I have filed #45, please have a look when you have time. 🙂

laurentsenta mentioned this issue Jun 27, 2022

EPIC: Clarify and Simplify logging testground/testground#1355

Open

ackintosh mentioned this issue Jan 21, 2023

Write events to run.out #45

Merged

ackintosh mentioned this issue Feb 22, 2023

Update dependencies sigp/gossipsub-testground#13

Merged

4 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Collect producing a directory tree but no files with `example-rust` #30

Collect producing a directory tree but no files with `example-rust` #30

divagant-martian commented Jun 24, 2022 •

edited

mxinden commented Jun 27, 2022

laurentsenta commented Jun 27, 2022

ackintosh commented Jan 14, 2023 •

edited

ackintosh commented Jan 16, 2023 •

edited

laurentsenta commented Jan 16, 2023

ackintosh commented Feb 2, 2023

Collect producing a directory tree but no files with example-rust #30

Collect producing a directory tree but no files with example-rust #30

Comments

divagant-martian commented Jun 24, 2022 • edited

mxinden commented Jun 27, 2022

laurentsenta commented Jun 27, 2022

ackintosh commented Jan 14, 2023 • edited

ackintosh commented Jan 16, 2023 • edited

laurentsenta commented Jan 16, 2023

ackintosh commented Feb 2, 2023

Collect producing a directory tree but no files with `example-rust` #30

Collect producing a directory tree but no files with `example-rust` #30

divagant-martian commented Jun 24, 2022 •

edited

ackintosh commented Jan 14, 2023 •

edited

ackintosh commented Jan 16, 2023 •

edited