From 6e59ce786bc346b0aad1e1e4777e8d160ed122fd Mon Sep 17 00:00:00 2001
From: Ben Schofield <47790940+Benjscho@users.noreply.github.com>
Date: Mon, 11 Dec 2023 12:32:45 -0800
Subject: [PATCH] Add documentation on using tracing (#155)

Add some documentation on how to use the tracing level of turmoil to see
individual packet flow between clients. This uses the axum-example,
since that is already instrumented with a tracing-subscriber.
---
 src/lib.rs | 37 +++++++++++++++++++++++++++++++++++--
 1 file changed, 35 insertions(+), 2 deletions(-)

diff --git a/src/lib.rs b/src/lib.rs
index 1c8ee7d..5f6711e 100644
--- a/src/lib.rs
+++ b/src/lib.rs
@@ -60,9 +60,42 @@
 //! # Tracing
 //!
 //! The `tracing` crate is used to emit important events during the lifetime of
-//! a simulation.
+//! a simulation. To enable traces, your tests must install a
+//! [`tracing-subscriber`](https://docs.rs/tracing-subscriber/latest/tracing_subscriber/).
+//! The log level of turmoil can be configured using `RUST_LOG=turmoil=info`.
 //!
-//! This can be configured using `RUST_LOG=turmoil=info`.
+//! Turmoil can provide a full packet level trace of the events happening in a
+//! simulation by passing `RUST_LOG=turmoil=trace`. This is really useful
+//! when you are unable to identify why some unexpected behaviour is happening
+//! and you need to know which packets are reaching where.
+//!
+//! To see this in effect, you can run the axum example with the following
+//! command:
+//!
+//! ```bash
+//! RUST_LOG=INFO,turmoil=TRACE cargo run -p axum-example
+//! ```
+//!
+//! You can see the TCP packets being sent and delivered between the server
+//! and the client:
+//!
+//! ```bash
+//! ...
+//! 2023-11-29T20:23:43.276745Z TRACE node{name="server"}: turmoil: Send src=192.168.0.1:9999 dst=192.168.0.2:49152 protocol=TCP [0x48, 0x54, 0x54, 0x50, 0x2F, 0x31, 0x2E, 0x31, 0x20, 0x32, 0x30, 0x30, 0x20, 0x4F, 0x4B, 0xD, 0xA, 0x63, 0x6F, 0x6E, 0x74, 0x65, 0x6E, 0x74, 0x2D, 0x74, 0x79, 0x70, 0x65, 0x3A, 0x20, 0x74, 0x65, 0x78, 0x74, 0x2F, 0x70, 0x6C, 0x61, 0x69, 0x6E, 0x3B, 0x20, 0x63, 0x68, 0x61, 0x72, 0x73, 0x65, 0x74, 0x3D, 0x75, 0x74, 0x66, 0x2D, 0x38, 0xD, 0xA, 0x63, 0x6F, 0x6E, 0x74, 0x65, 0x6E, 0x74, 0x2D, 0x6C, 0x65, 0x6E, 0x67, 0x74, 0x68, 0x3A, 0x20, 0x31, 0x30, 0xD, 0xA, 0x64, 0x61, 0x74, 0x65, 0x3A, 0x20, 0x57, 0x65, 0x64, 0x2C, 0x20, 0x32, 0x39, 0x20, 0x4E, 0x6F, 0x76, 0x20, 0x32, 0x30, 0x32, 0x33, 0x20, 0x32, 0x30, 0x3A, 0x32, 0x33, 0x3A, 0x34, 0x33, 0x20, 0x47, 0x4D, 0x54, 0xD, 0xA, 0xD, 0xA, 0x48, 0x65, 0x6C, 0x6C, 0x6F, 0x20, 0x66, 0x6F, 0x6F, 0x21]
+//! 2023-11-29T20:23:43.276834Z DEBUG turmoil::sim: step 43
+//! 2023-11-29T20:23:43.276907Z DEBUG turmoil::sim: step 44
+//! 2023-11-29T20:23:43.276981Z DEBUG turmoil::sim: step 45
+//! 2023-11-29T20:23:43.277039Z TRACE node{name="client"}: turmoil: Delivered src=192.168.0.1:9999 dst=192.168.0.2:49152 protocol=TCP [0x48, 0x54, 0x54, 0x50, 0x2F, 0x31, 0x2E, 0x31, 0x20, 0x32, 0x30, 0x30, 0x20, 0x4F, 0x4B, 0xD, 0xA, 0x63, 0x6F, 0x6E, 0x74, 0x65, 0x6E, 0x74, 0x2D, 0x74, 0x79, 0x70, 0x65, 0x3A, 0x20, 0x74, 0x65, 0x78, 0x74, 0x2F, 0x70, 0x6C, 0x61, 0x69, 0x6E, 0x3B, 0x20, 0x63, 0x68, 0x61, 0x72, 0x73, 0x65, 0x74, 0x3D, 0x75, 0x74, 0x66, 0x2D, 0x38, 0xD, 0xA, 0x63, 0x6F, 0x6E, 0x74, 0x65, 0x6E, 0x74, 0x2D, 0x6C, 0x65, 0x6E, 0x67, 0x74, 0x68, 0x3A, 0x20, 0x31, 0x30, 0xD, 0xA, 0x64, 0x61, 0x74, 0x65, 0x3A, 0x20, 0x57, 0x65, 0x64, 0x2C, 0x20, 0x32, 0x39, 0x20, 0x4E, 0x6F, 0x76, 0x20, 0x32, 0x30, 0x32, 0x33, 0x20, 0x32, 0x30, 0x3A, 0x32, 0x33, 0x3A, 0x34, 0x33, 0x20, 0x47, 0x4D, 0x54, 0xD, 0xA, 0xD, 0xA, 0x48, 0x65, 0x6C, 0x6C, 0x6F, 0x20, 0x66, 0x6F, 0x6F, 0x21]
+//! 2023-11-29T20:23:43.277097Z TRACE node{name="client"}: turmoil: Recv src=192.168.0.1:9999 dst=192.168.0.2:49152 protocol=TCP [0x48, 0x54, 0x54, 0x50, 0x2F, 0x31, 0x2E, 0x31, 0x20, 0x32, 0x30, 0x30, 0x20, 0x4F, 0x4B, 0xD, 0xA, 0x63, 0x6F, 0x6E, 0x74, 0x65, 0x6E, 0x74, 0x2D, 0x74, 0x79, 0x70, 0x65, 0x3A, 0x20, 0x74, 0x65, 0x78, 0x74, 0x2F, 0x70, 0x6C, 0x61, 0x69, 0x6E, 0x3B, 0x20, 0x63, 0x68, 0x61, 0x72, 0x73, 0x65, 0x74, 0x3D, 0x75, 0x74, 0x66, 0x2D, 0x38, 0xD, 0xA, 0x63, 0x6F, 0x6E, 0x74, 0x65, 0x6E, 0x74, 0x2D, 0x6C, 0x65, 0x6E, 0x67, 0x74, 0x68, 0x3A, 0x20, 0x31, 0x30, 0xD, 0xA, 0x64, 0x61, 0x74, 0x65, 0x3A, 0x20, 0x57, 0x65, 0x64, 0x2C, 0x20, 0x32, 0x39, 0x20, 0x4E, 0x6F, 0x76, 0x20, 0x32, 0x30, 0x32, 0x33, 0x20, 0x32, 0x30, 0x3A, 0x32, 0x33, 0x3A, 0x34, 0x33, 0x20, 0x47, 0x4D, 0x54, 0xD, 0xA, 0xD, 0xA, 0x48, 0x65, 0x6C, 0x6C, 0x6F, 0x20, 0x66, 0x6F, 0x6F, 0x21]
+//! 2023-11-29T20:23:43.277324Z  INFO client: axum_example: Got response: Response { status: 200, version: HTTP/1.1, headers: {"content-type": "text/plain; charset=utf-8", "content-length": "10", "date": "Wed, 29 Nov 2023 20:23:43 GMT"}, body: b"Hello foo!" }
+//! ...
+//! ```
+//!
+//! Here the server is sending a response, before it is delivered to, and
+//! received by the client. Note that there are three steps to each packet
+//! trace in turmoil. We see `Send` when a packet is sent from one address
+//! to another. The packet is then `Delivered` to its destination, and when
+//! the destination reads the packet it is `Recv`'d.
 //!
 //! # Feature flags
 //!