logging tab entries organized around the rules that are selected

[b1conrad]

[From Phil] Realizing that not every line in a log entry is associated with a specific rule, how much work do you think if would be to have a sub entry on each log entry in the logging tab that shows a rule? So, for a given event, I could see how a specific rule reacted without having to sort it out from the log entries myself? Or at least the rule the log entry is coming from more easily seen. For example, right now klog and log entries show the rid, but it’s inside a structure, but not the rule. I’d rather see something like

18:45:40.011Z [klog] io.picolabs.wovyn.emitter:raise_emitter_event | Heartbeat period: 20

Currently it shows

18:45:40.011Z [klog] Heartbeat period:  {"rid":"io.picolabs.wovyn.emitter","val":20}

Which is visually harder to parse and makes me look back in the log to see what rule this was in.

More often than not, I’m running down list of entries, looking for a specific rule

18:45:40.014Z [debug] rule selected {"rid":"io.picolabs.wovyn.router","rule_name":"receive_heartbeat"}

And have to look for rule selected then look right to rule_name, then scroll some more, etc.

I think it would be nice if the rule name were the core organizing principle since that’s what developers care about mostly.

Was the right rule selected, did it fire, and what log messages did it produce?

[b1conrad]

I think those are all good ideas. I don't know how much work it might be. There is also a lot of redundancy, with too many lines labelled "event added to schedule" (one for each ruleset installed in the pico, and identical except for the rid). This gives us more information than we had in v0, in that we get to see what order the rulesets are considered in. But it's not accurate because it is not the event that is added to the schedule, but selected rules (to your point). Also we once had a line for every raised event, but we don't any more.

[b1conrad]

[From Phil] The wording is off on the lines you’re talking about as well. Events are not added to the schedule. They are queued and then considered. As each event is considered, rules are added to the schedule.

[b1conrad]

Looks like some of this comes from the pico-framework here. That's where logging information is emitted.

Still looking for where the entries for the Logging tab are formatted...

[b1conrad]

This changes the formatting of [klog] and the "rule selected" lines, but the rule name isn't available to also display it in the [klog] line:

+++ b/packages/pico-engine-ui/src/components/PicoTabs/Logging.tsx
@@ -36,6 +36,12 @@ function logDetailsToHuman(entry: any): string {
       )}`;
     }
   }
+  if (entry.msg === "rule selected") {
+    return `${entry.rid}:${entry.rule_name}`;
+  }
+  if (entry.level === "klog") {
+    return `${entry.val || "null"}`;
+  }
   const other = Object.assign({}, entry);
   delete other.time;
   delete other.level;

[b1conrad]

With that change, the two lines are easier to read:

22:39:36.260Z [debug] event added to schedule {"rid":"klog","event":{"eci":"ckjajkqlr003cjz2r42xn2brq","domain":"klog","name":"need_msg","data":{"attrs":{"msg":"coucou","_headers":{"host":"localhost:3000","connection":"keep-alive","content-length":"16","sec-ch-ua":"\"Google Chrome\";v=\"87\", \" Not;A Brand\";v=\"99\", \"Chromium\";v=\"87\"","sec-ch-ua-mobile":"?0","user-agent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36","content-type":"application/json; charset=utf-8","accept":"*/*","origin":"http://localhost:3000","sec-fetch-site":"same-origin","sec-fetch-mode":"cors","sec-fetch-dest":"empty","referer":"http://localhost:3000/","accept-encoding":"gzip, deflate, br","accept-language":"en-US,en;q=0.9,ko;q=0.8,fr;q=0.7,ig;q=0.6"}}},"time":1609281576258}}
22:39:36.262Z [debug] rule selected klog:show_klog
22:39:36.262Z [klog] msg coucou

Compared to without those changes:

23:42:42.275Z [debug] rule selected {"rid":"klog","rule_name":"show_klog"}
23:42:42.275Z [klog] msg {"rid":"klog"}

[b1conrad]

This is a major change in the look of the Logging tab, so it needs to be reviewed.