Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

feat(swingset): slogfile visualization: PlantUML, causeway (WIP) #3624

Draft
wants to merge 45 commits into
base: master
Choose a base branch
from

Conversation

dckc
Copy link
Member

@dckc dckc commented Aug 7, 2021

@warner , @erights ,

This runs to completion in the case of chain-1.slog.gz that I got from @warner , but causeway complains about the output:

Uncaught Error: conflicting Sent for message: kp1167
    at makeMessageGraph (makeMessageGraph.js:78)
    at makeCausewayModel (makeCausewayModel.js:25)
    at makeModel (causalityGrid.js:195)
    at causalityGrid.js:203
    at Object.collect (causalityGrid.js:24)
    at XMLHttpRequest.request.onreadystatechange (causalityGrid.js:100)

I ran zcat chain-1.slog.gz | node slog-to-causeway.mjs >chain1.log and put chain-1.log in (my checked out copy) of https://github.com/cocoonfx/causeway/tree/master/src/js/com/teleometry/causeway/purchase_example/workers/log

Then I made this tweak to point at it:

diff --git a/src/js/com/teleometry/causalityGrid.js b/src/js/com/teleometry/causalityGrid.js
index 2e033f2..e350439 100644
--- a/src/js/com/teleometry/causalityGrid.js
+++ b/src/js/com/teleometry/causalityGrid.js
@@ -218,3 +218,3 @@ var showTracelog;
     //cg_logfiles = [ 'causeway/purchase_example/workers/log/V8-workers.log' ];
-    cg_logfiles = [ 'causeway/purchase_example/workers/log/FF-workers.log' ];
+    cg_logfiles = [ 'causeway/purchase_example/workers/log/chain1.log' ];
     //cg_logfiles = [ 'causeway/purchase_example/workers/log/JSC-workers.log' ];
@@ -237,3 +237 @@ var showTracelog;
 })();

and then visited causalityGrid.html in a vs-code live server.

cc @kriskowal @michaelfig @FUDCo @katelynsills

@dckc
Copy link
Member Author

dckc commented Aug 27, 2021

The slog-to-diagram script on this branch does an alternative rendering.

For example, see the sequence diagram for #3760

@dckc
Copy link
Member Author

dckc commented Sep 23, 2021

While working with @Chris-Hibbert on governance, I find myself wishing for this Causeway integration often. Just after @erights asked if something similar to recent work on the XS console (#3856) could be used to get stack traces in the REPL, I found myself looking at a rather un-helpful [TypeError: ?: no function] with no stack while working on the governance demo (#3869). p.s. that probably results from calling a method on a promise where I should have used E(..).foo()

Today I talked with @warner about adding message sequence numbers in kernel delivery objects to facilitate correlating send syscalls with deliveries (and resolve syscalls with notifications). (cf. #6501)

We puzzled over FF-workers.log some, along with mainBuyer.js but didn't reach a full understanding.

I didn't manage to work Causeway's Trace Log Format docs into the discussion.

Setting this aside again, for now...

@dckc
Copy link
Member Author

dckc commented Oct 4, 2021

Somewhat related: #2885 around deep stacks

more directly on target: #1864

@dckc dckc force-pushed the slog-to-causeway branch from 33b99c4 to a923083 Compare October 14, 2021 00:46
@dckc
Copy link
Member Author

dckc commented Oct 17, 2021

progress!

Some causal links aren't quite hooked up right, but lots of stuff is working:

image

image

image

notes to self:

~/projects/agoric/agoric-sdk/packages/treasury
22:28 connolly@jambox$ SLOGFILE=$PWD/t2.slog yarn test test/swingsetTests/governance/test-governance.js 

connolly@jambox:~/projects/agoric/testnet-load-generator$ node slog-to-causeway.mjs <t2.slog >t2.log

connolly@jambox:~/projects/agoric/causeway/src/js/com/teleometry/causeway/purchase_example/workers/log$ ln -s ~/projects/agoric/testnet-load-generator/t2.log

@dckc dckc force-pushed the slog-to-causeway branch from 797ced8 to 31edf64 Compare October 26, 2021 16:49
@dckc
Copy link
Member Author

dckc commented Oct 26, 2021

represent promise resolution just like message delivery

After more study of examples, I realized they don't use anything fancy to represent promise resolution. Just .Sent and .Got just like message delivery.

Now it all seems to work pretty well.

vatAdmin device is a bit magic

The newVatCallback and meterCrossedThreshold methods in the vatAdmin vat are delivered as usual but not sent by send syscalls. slog-to-causeway.mjs treats them as causally unrelated.

@dckc
Copy link
Member Author

dckc commented Oct 26, 2021

A couple examples are working pretty well:

The @@ error dialog is safe to ignore.

Copy link
Contributor

@Chris-Hibbert Chris-Hibbert left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Causeway is an interesting tool. It would be nice to be able to make use of it. Some questions from glancing at the code....


import './types.js';

const { freeze } = Object;
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

how is freeze different from harden?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

freeze is part of the JS standard library. I was avoiding dependencies on the Agoric platform while building this tool.

Substantively: freeze isn't recursive.

const { freeze } = Object;

/**
* @typedef { |
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What does @typedef { | Something } mean?

oh, it's only used on line 17, so it expands to

@typedef {
org.ref_send.log.
org.ref_send.log.Something
} LogClassT

Should the first entry end in a bare dot? Nope, from the def'n on line 20, it looks like the empty case shouldn't be included. Does @typedef drop it, or is this a mistake?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The leading | in @typedef { | Something } is a little like the trailing , in const x = [1,2,3,]. It's ignored.

But line breaking rules in typescript-in-jsdoc are weird, and the declaration breaks without it.

class: [LogClass.Got, LogClass.Event],
anchor,
message,
trace: { calls: [{ name: text, source: '@@' }] },
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What does '@@' do? It looks like you expect the source location to be substituted, but I couldn't find any JS doc saying that's the case.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

'@@' means "I don't have a source file name, but the causeway code ignores this whole node unless it has something here, so I'll stick some arbitrary marker for now."

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Perhaps '<unknown-source>'. I’ve used this pattern elsewhere to improve error messages like JSON parse errors for a file with a name that defaults to '<unknown-something>'.

@dckc dckc force-pushed the slog-to-causeway branch from 3c128ee to 720f534 Compare March 10, 2022 04:24
@dckc
Copy link
Member Author

dckc commented Mar 10, 2022

@arirubinstein for reference, https://github.com/Agoric/agoric-sdk/blob/slog-to-causeway/packages/SwingSet/misc-tools/slog-to-diagram.mjs is the tool that I used to make that .puml sequence diagram out of bootstrap and starting the RUN protocol.

Usage is as in the Makefile in https://gist.github.com/dckc/c300327762d1fa128580c1399e0ae41f

to generate the input slog file, use SLOGFILE=/tmp/f1 agoric start and / or SOLO_SLOGFILE=/tmp/f2 agoric start.

@dckc dckc added logging devex developer experience labels May 15, 2022
@dckc dckc force-pushed the slog-to-causeway branch from f351c56 to d993a17 Compare May 16, 2022 01:08
dckc added 25 commits August 24, 2022 21:18
 - sort by time
 - number by elapsed time within a block
  - show promise resolution state
  - add @startuml , @enduml
 - handle lack of block time markers, e.g. in testing
 - make some fields optional
 - use SentIf / condition for promise resolution

problem: conflicting Sent for message Rkp41, Rkp42
two resolve syscalls with the same deliveryNum
this provokes causeway to show stuff
 - don't add { text} on .Got so that vat,turn is shown
 - add ko, kp, body.length detail to .Send
 - log about unknonwn tags
 - handle / skip missing dInfo / dr[2]
 - handle / skip negative t
@dckc dckc force-pushed the slog-to-causeway branch from 49272a6 to 2ee9664 Compare August 25, 2022 05:08
@dckc dckc changed the title feat(swingset): convert slogfile to causeway format (WIP) feat(swingset): slogfile visualization: PlantUML, causeway (WIP) Jul 16, 2024
@dckc
Copy link
Member Author

dckc commented Aug 23, 2024

inter-vat message visualization service

@toliaqat as discussed, it would be nice to wrap this half-baked code (or anything that does a similar job) as a service of sorts:

  1. Use datadog to select a time interval of interest
  2. extracts CSV
  3. drop CSV on this service
  4. service produces .svg diagram

slog.svg is an example I generated today.

Makefile shows how I did it. It belongs in agoric-sdk/packages/SwingSet/misc-tools. When I invoke it, it uses yq to get a .slog from the CSV, etc.:

agoric-sdk/packages/SwingSet/misc-tools$ make
yq -p csv -o json -I=0 '.[] | .Message' extract-2024-08-23T16_12_20.185Z.csv | tac | \
        jq -c 'select((.time >= 1724425557.382605 - 2) and (.time <= 1724425559.071834))' >requested-interval.slog
node slog-to-diagram.mjs <requested-interval.slog >requested-interval.puml
syscall tag unknown: vatstoreGet
syscall tag unknown: subscribe
syscall tag unknown: vatstoreSet
type unknown: console
type unknown: notify
syscall tag unknown: vatstoreDelete
syscall tag unknown: vatstoreGetNextKey
syscall tag unknown: invoke
??? t < 0 0
no source for { ref: 'Rkp13858960' }
# https://plantuml.com/command-line
java -jar plantuml-1.2022.7.jar -tsvg requested-interval.puml

agoric-sdk/packages/SwingSet/misc-tools$ ls -ltr extract-2024-08-23T16_12_20.185Z.csv requested-interval.* *.svg
-rw-rw-r-- 1 connolly connolly 21276242 Aug 23 11:12 extract-2024-08-23T16_12_20.185Z.csv
-rw-rw-r-- 1 connolly connolly  1311000 Aug 23 15:58 requested-interval.slog
-rw-rw-r-- 1 connolly connolly     3990 Aug 23 15:58 requested-interval.puml
-rw-rw-r-- 1 connolly connolly    49601 Aug 23 15:58 slog.svg

The slog-to-diagram.mjs code is kinda scruffy. Any messages such as syscall tag unknown: vatstoreGet that it spits out should probably be reported to the user. A few cases of no source for { ref: 'Rkp13858960' } are probably OK, but a zillion of them suggests that something is going wrong.

Option: diagram key

The participants in the state diagram are vats.

image

Arrows represent messages between vats.

A solid arrow labelled:

0.1 kp13858945 <- ko1009519.fromBridge(866)

That means: at 0.1 seconds into the block, a message with method fromBridge and 866 characters of arguments was sent to kernel object ko1009519, allocating a promise kp13858945 for the result.

An arrow with kp13858945.fulfilled() means the promise was fulfilled. An arrow with kp13858945.rejected() means it was rejected.

An arrow whose tail is the left edge of the diagram means the script couldn't figure out which vat it came from. (Some messages come from the kernel.)

Yellow boxes indicate large computron counts.

image

Option: vat key

@warner has some tools that make vat maps:

   v5 :   timer
   v7 :   board
   v9 :   zoe
  v10 :   bridge
  v15 :   zcf-b1-2371d-econCommitteeCharter
  v37 :   zcf-b1-94e20-walletFactory
  v41 :   zcf-b1-9f877-vaultFactory.governor

Option: slog file input

The user might have a slogfile rather than a datadog extract.

Option: start with offer id

The precipitating event in this case was proposing a DebtLimit change. Like all smart contract interactions, the relevant transaction has an OfferSpec including an id. The user could provide the id, and the service would find where that id shows up in datadog logs and extract from there for the following 10 or 20 seconds.

Option: start with any search string

Maybe the search term doesn't have to be an offer id. It could be a distinctive error message, or whatever.

Option: start with time interval

Perhaps the user knows the relevant time interval.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
devex developer experience logging
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants