From cb91ed46fe2262e35bf515c9544f1287dbd28473 Mon Sep 17 00:00:00 2001
From: Georgios Konstantopoulos <me@gakonst.com>
Date: Fri, 7 Feb 2020 18:07:32 +0200
Subject: [PATCH] fix: trace incoming packet responses (#623)

* fix: trace incoming packet responses

* fix(node): remove extra in_current_span call

* docs(logging): add info about logging
---
 crates/ilp-node/src/instrumentation/trace.rs |  2 +-
 crates/ilp-node/src/node.rs                  |  3 +-
 docs/logging.md                              | 48 ++++++++++++++++++++
 3 files changed, 50 insertions(+), 3 deletions(-)
 create mode 100644 docs/logging.md

diff --git a/crates/ilp-node/src/instrumentation/trace.rs b/crates/ilp-node/src/instrumentation/trace.rs
index 7f886c52c..fa578336a 100644
--- a/crates/ilp-node/src/instrumentation/trace.rs
+++ b/crates/ilp-node/src/instrumentation/trace.rs
@@ -38,7 +38,7 @@ pub async fn trace_incoming<A: Account>(
     );
     let _details_scope = details_span.enter();
 
-    next.handle_request(request).in_current_span().await
+    trace_response(next.handle_request(request).in_current_span().await)
 }
 
 /// Add tracing context when the incoming request is
diff --git a/crates/ilp-node/src/node.rs b/crates/ilp-node/src/node.rs
index 3ecd60096..f836fd951 100644
--- a/crates/ilp-node/src/node.rs
+++ b/crates/ilp-node/src/node.rs
@@ -391,8 +391,7 @@ impl InterledgerNode {
             if #[cfg(feature = "monitoring")] {
                 let outgoing_service_fwd = outgoing_service
                     .clone()
-                    .wrap(trace_forwarding)
-                    .in_current_span();
+                    .wrap(trace_forwarding);
             } else {
                 let outgoing_service_fwd = outgoing_service.clone();
             }
diff --git a/docs/logging.md b/docs/logging.md
new file mode 100644
index 000000000..2edad286c
--- /dev/null
+++ b/docs/logging.md
@@ -0,0 +1,48 @@
+# Logging
+
+Logs are created via the `tracing` crates. We define various _scopes_ depending on the operation we want to trace at various debug levels. The log level can be set via the `RUST_LOG` environment variable, and via the `/tracing-level` at runtime by the node operator.
+
+For each request we track various information depending on the error log lvel:
+- **Incoming**:
+    - `ERROR`:
+        - `request.id`: a randomly generated uuid for that specific request
+        - `prepare.destination`: the destination of the prepare packet inside the request
+        - `prepare.amount`: the amount in the prepare packet inside the request
+        - `from.id`: the request sender's account uuid
+    - `DEBUG`:
+        - `from.username`: the request sender's username
+        - `from.ilp_address`: the request sender's ilp address
+        - `from.asset_code`: the request sender's asset code
+        - `from.asset_scale`: the request sender's asset scale
+- **Forwarding** (this is shown when an incoming request is turned into an outgoing request and is being forwarded to a peer):
+    - `ERROR`:
+        - `prepare.amount`: the amount in the prepare packet inside the request
+        - `from.id`: the request sender's account uuid
+    - `DEBUG`:
+        - `to.username`: the request receiver's username
+        - `to.ilp_address`: the request receiver's ilp address
+        - `to.asset_code`: the request receiver's asset code
+        - `to.asset_scale`: the request receiver's asset scale
+- **Outgoing**: 
+    - `ERROR`:
+        - `request.id`: a randomly generated uuid for that specific request
+        - `prepare.destination`: the destination of the prepare packet inside the request
+        - `from.id`: the request sender's account uuid
+        - `to.id`: the request receiver's account uuid
+    - `DEBUG`:
+        - `from.username`: the request sender's username
+        - `from.ilp_address`: the request sender's ilp address
+        - `from.asset_code`: the request sender's asset code
+        - `from.asset_scale`: the request sender's asset scale
+        - `to.username`: the request receiver's username
+        - `to.ilp_address`: the request receiver's ilp address
+        - `to.asset_code`: the request receiver's asset code
+        - `to.asset_scale`: the request receiver's asset scale
+
+Then, depending on the response received for the request, we add additional information to that log:
+- `Fulfill`: We add a scope `"result = fulfill"` at the `DEBUG` level
+    - `fulfillment`: the fulfill packet's fulfillment condition
+- `Reject`: We add a scope `"result = "reject"` at the INFO level
+    - `reject.code`: the reject packet's error code field
+    - `reject.message`: the reject packet's message field
+    - `reject.triggered_by`: the reject packet's triggered_by field
\ No newline at end of file