From 175ce28bb74ada84b7e73e7b2fa49534e075b50a Mon Sep 17 00:00:00 2001
From: Philip Monk <phil@pcmonk.me>
Date: Fri, 11 Dec 2020 16:45:13 -0800
Subject: [PATCH] ames: tag verb printfs

---
 pkg/arvo/sys/vane/ames.hoon | 48 +++++++++++++++++++++++--------------
 1 file changed, 30 insertions(+), 18 deletions(-)

diff --git a/pkg/arvo/sys/vane/ames.hoon b/pkg/arvo/sys/vane/ames.hoon
index 1fd73d759..b7f4d42f7 100644
--- a/pkg/arvo/sys/vane/ames.hoon
+++ b/pkg/arvo/sys/vane/ames.hoon
@@ -1373,7 +1373,7 @@
         |.  ^-  tape
         =/  sndr  [our our-life.channel]
         =/  rcvr  [ship her-life.channel]
-        "plea {<sndr^rcvr^bone^vane.plea^path.plea>}"
+        "plea {<sndr^rcvr^bone=bone^vane.plea^path.plea>}"
     ::
     abet:(on-memo:(make-peer-core peer-state channel) bone plea %plea)
   ::  +on-take-wake: receive wakeup or error notification from behn
@@ -2197,11 +2197,12 @@
         ?.  ?=([%hear * * ok=%.n] task)
           ::  fresh boon; give message to client vane
           ::
-          %-  (trace msg.veb |.("boon {<her.channel^bone -.task>}"))
+          %-  (trace msg.veb |.("boon {<her.channel^bone=bone -.task>}"))
           peer-core
         ::  we previously crashed on this message; notify client vane
         ::
-        %-  (trace msg.veb |.("crashed on boon {<her.channel^bone -.task>}"))
+        %-  %+  trace  msg.veb
+            |.("crashed on boon {<her.channel^bone=bone -.task>}")
         boon-to-lost
       ::  +boon-to-lost: convert all boons to losts
       ::
@@ -2219,7 +2220,7 @@
       ++  on-sink-nack-trace
         |=  [=message-num message=*]
         ^+  peer-core
-        %-  (trace msg.veb |.("nack trace {<her.channel^bone>}"))
+        %-  (trace msg.veb |.("nack trace {<her.channel^bone=bone>}"))
         ::
         =+  ;;  =naxplanation  message
         ::  ack nack-trace message (only applied if we don't later crash)
@@ -2236,7 +2237,7 @@
       ++  on-sink-plea
         |=  [=message-num message=*]
         ^+  peer-core
-        %-  (trace msg.veb |.("plea {<her.channel^bone>}"))
+        %-  (trace msg.veb |.("plea {<her.channel^bone=bone>}"))
         ::  is this the first time we're trying to process this message?
         ::
         ?.  ?=([%hear * * ok=%.n] task)
@@ -2346,7 +2347,8 @@
     ::  ignore duplicate message acks
     ::
     ?:  (lth message-num current.state)
-      %-  (trace snd.veb |.("duplicate done {<current.state message-num>}"))
+      %-  %+  trace  snd.veb
+          |.("duplicate done {<current=current.state message-num=message-num>}")
       message-pump
     ::  ignore duplicate and future acks
     ::
@@ -2659,7 +2661,7 @@
                     =(0 (mod counter.metrics.state 20))
                 ==
               same
-            (trace snd.veb |.("{<[fragment-num show:gauge]>}"))
+            (trace snd.veb |.("send: {<[fragment=fragment-num show:gauge]>}"))
         ::  .resends is backward, so fold backward and emit
         ::
         =.  packet-pump
@@ -2718,7 +2720,7 @@
     =-  =.  metrics.state  metrics.-
         =.  live.state     live.-
         ::
-        %-  (trace snd.veb |.("done {<message-num^show:gauge>}"))
+        %-  (trace snd.veb |.("done {<message-num=message-num^show:gauge>}"))
         (fast-resend-after-ack message-num `fragment-num`0)
     ::
     ^+  [metrics=metrics.state live=live.state]
@@ -2949,7 +2951,8 @@
     ::  ignore messages from far future; limit to 10 in progress
     ::
     ?:  (gte seq (add 10 last-acked.state))
-      %-  (trace odd.veb |.("future %hear {<seq^last-acked.state>}"))
+      %-  %+  trace  odd.veb
+          |.("future %hear {<seq=seq^last-acked=last-acked.state>}")
       message-sink
     ::
     =/  is-last-fragment=?  =(+(fragment-num) num-fragments)
@@ -2959,12 +2962,13 @@
       ?.  is-last-fragment
         ::  single packet ack
         ::
-        %-  (trace rcv.veb |.("send dupe ack {<seq^fragment-num>}"))
+        %-  %+  trace  rcv.veb
+            |.("send dupe ack {<seq=seq^fragment-num=fragment-num>}")
         (give %send seq %& fragment-num)
       ::  whole message (n)ack
       ::
       =/  ok=?  !(~(has in nax.state) seq)
-      %-  (trace rcv.veb |.("send dupe message ack {<seq>} ok={<ok>}"))
+      %-  (trace rcv.veb |.("send dupe message ack {<seq=seq>} ok={<ok>}"))
       (give %send seq %| ok lag=`@dr`0)
     ::  last-acked<seq<=last-heard; heard message, unprocessed
     ::
@@ -2978,15 +2982,18 @@
         %-  %+  trace  rcv.veb
             |.  ^-  tape
             =/  data
-              :*  her.channel  seq
-                  fragment-num  num-fragments
+              :*  her.channel  seq=seq
+                  fragment-num=fragment-num  num-fragments=num-fragments
                   la=last-acked.state  lh=last-heard.state
               ==
             "hear last in-progress {<data>}"
         message-sink
       ::  ack all other packets
       ::
-      %-  (trace rcv.veb |.("send ack-1 {<seq^fragment-num^num-fragments>}"))
+      %-  %+  trace  rcv.veb  |.
+          =/  data
+            [seq=seq fragment-num=fragment-num num-fragments=num-fragments]
+          "send ack-1 {<data>}"
       (give %send seq %& fragment-num)
     ::  last-heard<seq<10+last-heard; this is a packet in a live message
     ::
@@ -3009,10 +3016,12 @@
     ?:  already-heard-fragment
       ?:  is-last-fragment
         %-  %+  trace  rcv.veb  |.
-            =/  data  [her.channel seq last-heard.state last-acked.state]
+            =/  data
+              [her.channel seq=seq lh=last-heard.state la=last-acked.state]
             "hear last dupe {<data>}"
         message-sink
-      %-  (trace rcv.veb |.("send dupe ack {<her.channel^seq^fragment-num>}"))
+      %-  %+  trace  rcv.veb
+          |.("send dupe ack {<her.channel^seq=seq^fragment-num=fragment-num>}")
       (give %send seq %& fragment-num)
     ::  new fragment; store in state and check if message is done
     ::
@@ -3027,7 +3036,10 @@
     ::  ack any packet other than the last one, and continue either way
     ::
     =?  message-sink  !is-last-fragment
-      %-  (trace rcv.veb |.("send ack-2 {<seq^fragment-num^num-fragments>}"))
+      %-  %+  trace  rcv.veb  |.
+          =/  data
+            [seq=seq fragment-num=fragment-num num-fragments=num-fragments]
+          "send ack-2 {<data>}"
       (give %send seq %& fragment-num)
     ::  enqueue all completed messages starting at +(last-heard.state)
     ::
@@ -3050,7 +3062,7 @@
     =.  live-messages.state  (~(del by live-messages.state) seq)
     ::
     %-  %+  trace  msg.veb
-        |.("hear {<her.channel>} {<seq>} {<num-fragments.u.live>}kb")
+        |.("hear {<her.channel>} {<seq=seq>} {<num-fragments.u.live>}kb")
     =/  message=*  (assemble-fragments [num-fragments fragments]:u.live)
     =.  message-sink  (enqueue-to-vane seq message)
     ::