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

agoric start output is super noisy #571

Closed
DavidBruant opened this issue Feb 19, 2020 · 6 comments · Fixed by #730
Closed

agoric start output is super noisy #571

DavidBruant opened this issue Feb 19, 2020 · 6 comments · Fixed by #730
Assignees
Labels
agoric-cli package: agoric-cli

Comments

@DavidBruant
Copy link
Contributor

DavidBruant commented Feb 19, 2020

Console output for working "agoric start"
$ agoric start
initializing dev
/home/david/projects/agoric-sdk/packages/cosmic-swingset/bin/ag-solo init dev --egresses=fake
morgan deprecated default format: use combined format ../../node_modules/esm/esm.js:1:278827
solo [ 'init', 'dev', '--egresses=fake' ]
ag-solo initialized in dev
HTTP/WebSocket will listen on 127.0.0.1:8000
setting fake chain with 5 second delay
/home/david/projects/agoric-sdk/packages/cosmic-swingset/bin/ag-solo set-fake-chain --role=two_chain --delay=5 myFakeGCI
morgan deprecated default format: use combined format ../../../node_modules/esm/esm.js:1:278827
solo [ 'set-fake-chain', '--role=two_chain', '--delay=5', 'myFakeGCI' ]
linking html directories
/home/david/projects/agoric-sdk/packages/cosmic-swingset/bin/ag-solo start --role=two_client
morgan deprecated default format: use combined format ../../../node_modules/esm/esm.js:1:278827
solo [ 'start', '--role=two_client' ]
adding HTTP/WS listener on 127.0.0.1:8000
Serving static files from /home/david/projects/agoric-sdk/demo/.agservers/dev/html
adding follower/sender for fake chain two_chain myFakeGCI
Listening on 127.0.0.1:8000
launch: checking for saved mailbox state false
initializing empty swingset state
buildSwingset
kernel.addDevice(mailbox)
kernel.addDevice(timer)
= adding vat 'exchange' from /home/david/projects/agoric-sdk/demo/.agservers/dev/vats/vat-exchange.js
= adding vat 'host' from /home/david/projects/agoric-sdk/demo/.agservers/dev/vats/vat-host.js
= adding vat 'http' from /home/david/projects/agoric-sdk/demo/.agservers/dev/vats/vat-http.js
= adding vat 'mints' from /home/david/projects/agoric-sdk/demo/.agservers/dev/vats/vat-mints.js
= adding vat 'provisioning' from /home/david/projects/agoric-sdk/demo/.agservers/dev/vats/vat-provisioning.js
= adding vat 'registrar' from /home/david/projects/agoric-sdk/demo/.agservers/dev/vats/vat-registrar.js
= adding vat 'sharing' from /home/david/projects/agoric-sdk/demo/.agservers/dev/vats/vat-sharing.js
= adding vat 'uploads' from /home/david/projects/agoric-sdk/demo/.agservers/dev/vats/vat-uploads.js
= adding vat 'wallet' from /home/david/projects/agoric-sdk/demo/.agservers/dev/vats/vat-wallet.js
= adding vat 'zoe' from /home/david/projects/agoric-sdk/demo/.agservers/dev/vats/vat-zoe.js
= adding vat 'vattp' from /home/david/projects/agoric-sdk/packages/SwingSet/src/vats/vat-tp.js
= adding vat 'comms' from /home/david/projects/agoric-sdk/packages/SwingSet/src/vats/comms/index.js
= adding vat 'timer' from /home/david/projects/agoric-sdk/packages/SwingSet/src/vats/vat-timerWrapper.js
= adding vat '_bootstrap' from /home/david/projects/agoric-sdk/demo/.agservers/dev/vats/bootstrap.js
loading bootstrap.js
wasInitialized = false
Assigned VatID v1 for genesis vat exchange
Assigned VatID v2 for genesis vat host
Assigned VatID v3 for genesis vat http
Assigned VatID v4 for genesis vat mints
Assigned VatID v5 for genesis vat provisioning
Assigned VatID v6 for genesis vat registrar
Assigned VatID v7 for genesis vat sharing
Assigned VatID v8 for genesis vat uploads
Assigned VatID v9 for genesis vat wallet
Assigned VatID v10 for genesis vat zoe
Assigned VatID v11 for genesis vat vattp
Assigned VatID v12 for genesis vat comms
Assigned VatID v13 for genesis vat timer
Assigned VatID v14 for genesis vat _bootstrap
Assigned VatID v15 for genesis vat vatAdmin
Assigned DeviceID d7 for genesis device mailbox
Assigned DeviceID d8 for genesis device timer
Assigned DeviceID d9 for genesis device vatAdmin
=> queueing bootstrap()
adding vref _bootstrap [v14]
adding vref comms [v12]
adding vref exchange [v1]
adding vref host [v2]
adding vref http [v3]
adding vref mints [v4]
adding vref provisioning [v5]
adding vref registrar [v6]
adding vref sharing [v7]
adding vref timer [v13]
adding vref uploads [v8]
adding vref vatAdmin [v15]
adding vref vattp [v11]
adding vref wallet [v9]
adding vref zoe [v10]
adding dref mailbox [d7]
adding dref timer [d8]
adding dref vatAdmin [d9]
two_chain bootstrap starting
all vats initialized for two_chain
= loading config from basedir /home/david/projects/agoric-sdk/demo/.agservers/dev/vats
ignoring  bootstrap.js
ignoring  gci.js
ignoring  lib-exchange.js
ignoring  lib-wallet.js
ignoring  observable.js
ignoring  pubsub.js
ignoring  repl.js
ignoring  scratch.js
kernel.addDevice(mailbox)
kernel.addDevice(command)
kernel.addDevice(timer)
= adding vat 'exchange' from /home/david/projects/agoric-sdk/demo/.agservers/dev/vats/vat-exchange.js
= adding vat 'host' from /home/david/projects/agoric-sdk/demo/.agservers/dev/vats/vat-host.js
= adding vat 'http' from /home/david/projects/agoric-sdk/demo/.agservers/dev/vats/vat-http.js
= adding vat 'mints' from /home/david/projects/agoric-sdk/demo/.agservers/dev/vats/vat-mints.js
= adding vat 'provisioning' from /home/david/projects/agoric-sdk/demo/.agservers/dev/vats/vat-provisioning.js
= adding vat 'registrar' from /home/david/projects/agoric-sdk/demo/.agservers/dev/vats/vat-registrar.js
= adding vat 'sharing' from /home/david/projects/agoric-sdk/demo/.agservers/dev/vats/vat-sharing.js
= adding vat 'uploads' from /home/david/projects/agoric-sdk/demo/.agservers/dev/vats/vat-uploads.js
= adding vat 'wallet' from /home/david/projects/agoric-sdk/demo/.agservers/dev/vats/vat-wallet.js
= adding vat 'zoe' from /home/david/projects/agoric-sdk/demo/.agservers/dev/vats/vat-zoe.js
= adding vat 'vattp' from /home/david/projects/agoric-sdk/packages/SwingSet/src/vats/vat-tp.js
= adding vat 'comms' from /home/david/projects/agoric-sdk/packages/SwingSet/src/vats/comms/index.js
= adding vat 'timer' from /home/david/projects/agoric-sdk/packages/SwingSet/src/vats/vat-timerWrapper.js
= adding vat '_bootstrap' from /home/david/projects/agoric-sdk/demo/.agservers/dev/vats/bootstrap.js
loading bootstrap.js
wasInitialized = false
Assigned VatID v1 for genesis vat exchange
Assigned VatID v2 for genesis vat host
Assigned VatID v3 for genesis vat http
Assigned VatID v4 for genesis vat mints
Assigned VatID v5 for genesis vat provisioning
Assigned VatID v6 for genesis vat registrar
Assigned VatID v7 for genesis vat sharing
Assigned VatID v8 for genesis vat uploads
Assigned VatID v9 for genesis vat wallet
Assigned VatID v10 for genesis vat zoe
Assigned VatID v11 for genesis vat vattp
Assigned VatID v12 for genesis vat comms
Assigned VatID v13 for genesis vat timer
Assigned VatID v14 for genesis vat _bootstrap
Assigned VatID v15 for genesis vat vatAdmin
Assigned DeviceID d7 for genesis device mailbox
Assigned DeviceID d8 for genesis device command
Assigned DeviceID d9 for genesis device timer
Assigned DeviceID d10 for genesis device vatAdmin
=> queueing bootstrap()
adding vref _bootstrap [v14]
adding vref comms [v12]
adding vref exchange [v1]
adding vref host [v2]
adding vref http [v3]
adding vref mints [v4]
adding vref provisioning [v5]
adding vref registrar [v6]
adding vref sharing [v7]
adding vref timer [v13]
adding vref uploads [v8]
adding vref vatAdmin [v15]
adding vref vattp [v11]
adding vref wallet [v9]
adding vref zoe [v10]
adding dref command [d8]
adding dref mailbox [d7]
adding dref timer [d9]
adding dref vatAdmin [d10]
two_client bootstrap starting
deliver { myFakeGCI: { outbox: [ [Array] ], inboundAck: 0 } }
new outbound message 1 for myFakeGCI: deliver:ro+1:getDemoBundle:rp-40;["client"]
 1 new messages
 invoking deliverator
swingset running
polled; blockTime:1582108259, h:0 ADDED: false
wrote SwingSet checkpoint (kernel=17179, mailbox=2), [run=0ms, mb=0ms, save=15ms]
mboxDeliver:   ADDED messages
inbound promise rp-40 mapped to p+20
comms.notifyFulfillToData(p+20)
outbox changed
wrote SwingSet checkpoint (kernel=26776, mailbox=694), [run=60ms, mb=0ms, save=18ms]
deliver {
  myFakeGCI: { outbox: [ [Array], [Array], [Array], [Array] ], inboundAck: 1 }
}
new outbound message 2 for myFakeGCI: deliver:ro+22:getLabel:rp-41;[]
new outbound message 3 for myFakeGCI: deliver:ro+22:getExtentOps:rp-42;[]
new outbound message 4 for myFakeGCI: deliver:ro+23:getLabel:rp-43;[]
new outbound message 5 for myFakeGCI: deliver:ro+23:getExtentOps:rp-44;[]
 4 new messages
 invoking deliverator
polled; blockTime:1582108264, h:1 ADDED: false
wrote SwingSet checkpoint (kernel=26776, mailbox=694), [run=0ms, mb=0ms, save=17ms]
mboxDeliver:   ADDED messages
inbound promise rp-41 mapped to p+21
inbound promise rp-42 mapped to p+22
inbound promise rp-43 mapped to p+23
inbound promise rp-44 mapped to p+24
comms.notifyFulfillToData(p+21)
comms.notifyFulfillToData(p+22)
comms.notifyFulfillToData(p+23)
comms.notifyFulfillToData(p+24)
outbox changed
wrote SwingSet checkpoint (kernel=36760, mailbox=389), [run=69ms, mb=1ms, save=13ms]
deliver { myFakeGCI: { outbox: [ [Array], [Array] ], inboundAck: 5 } }
new outbound message 6 for myFakeGCI: deliver:ro+22:makeEmptyPurse:rp-45;["purse"]
new outbound message 7 for myFakeGCI: deliver:ro+23:makeEmptyPurse:rp-46;["purse"]
 2 new messages
 invoking deliverator
polled; blockTime:1582108269, h:2 ADDED: false
wrote SwingSet checkpoint (kernel=36760, mailbox=389), [run=0ms, mb=1ms, save=21ms]
mboxDeliver:   ADDED messages
inbound promise rp-45 mapped to p+25
inbound promise rp-46 mapped to p+26
comms.notifyFulfillToPresence(p+25) = o-62
comms.notifyFulfillToPresence(p+26) = o-63
outbox changed
wrote SwingSet checkpoint (kernel=41787, mailbox=116), [run=34ms, mb=0ms, save=21ms]
subscribing to walletPurseState
subscribing to walletInboxState
all vats initialized for two_client
deliver {
  myFakeGCI: {
    outbox: [ [Array], [Array], [Array], [Array], [Array], [Array] ],
    inboundAck: 7
  }
}
new outbound message 8 for myFakeGCI: deliver:ro+29:getBalance:rp-47;[]
new outbound message 9 for myFakeGCI: deliver:ro+29:getAssay:rp-48;[]
new outbound message 10 for myFakeGCI: deliver:ro+30:getBalance:rp-49;[]
new outbound message 11 for myFakeGCI: deliver:ro+30:getAssay:rp-50;[]
new outbound message 12 for myFakeGCI: deliver:ro+29:depositAll:rp-51:ro+20;[{"@qclass":"slot","index":0}]
new outbound message 13 for myFakeGCI: deliver:ro+30:depositAll:rp-52:ro+21;[{"@qclass":"slot","index":0}]
 6 new messages
 invoking deliverator
polled; blockTime:1582108274, h:3 ADDED: false
wrote SwingSet checkpoint (kernel=41787, mailbox=116), [run=0ms, mb=1ms, save=15ms]
mboxDeliver:   ADDED messages
inbound promise rp-47 mapped to p+27
inbound promise rp-48 mapped to p+28
inbound promise rp-49 mapped to p+29
inbound promise rp-50 mapped to p+30
inbound promise rp-51 mapped to p+31
inbound promise rp-52 mapped to p+32
comms.notifyFulfillToData(p+27)
comms.notifyFulfillToPresence(p+28) = o-55
comms.notifyFulfillToData(p+29)
comms.notifyFulfillToPresence(p+30) = o-56
comms.notifyFulfillToData(p+31)
comms.notifyFulfillToData(p+32)
outbox changed
wrote SwingSet checkpoint (kernel=57984, mailbox=649), [run=97ms, mb=1ms, save=12ms]
deliver {
  myFakeGCI: { outbox: [ [Array], [Array], [Array], [Array] ], inboundAck: 13 }
}
new outbound message 14 for myFakeGCI: deliver:ro+29:getBalance:rp-53;[]
new outbound message 15 for myFakeGCI: deliver:ro+29:getAssay:rp-54;[]
new outbound message 16 for myFakeGCI: deliver:ro+30:getBalance:rp-55;[]
new outbound message 17 for myFakeGCI: deliver:ro+30:getAssay:rp-56;[]
 4 new messages
 invoking deliverator
polled; blockTime:1582108279, h:4 ADDED: false
wrote SwingSet checkpoint (kernel=57984, mailbox=649), [run=0ms, mb=0ms, save=18ms]
mboxDeliver:   ADDED messages
inbound promise rp-53 mapped to p+33
inbound promise rp-54 mapped to p+34
inbound promise rp-55 mapped to p+35
inbound promise rp-56 mapped to p+36
comms.notifyFulfillToData(p+33)
comms.notifyFulfillToPresence(p+34) = o-55
comms.notifyFulfillToData(p+35)
comms.notifyFulfillToPresence(p+36) = o-56
outbox changed
wrote SwingSet checkpoint (kernel=68596, mailbox=388), [run=72ms, mb=0ms, save=14ms]
deliver { myFakeGCI: { outbox: [], inboundAck: 17 } }
 0 new messages
 invoking deliverator
polled; blockTime:1582108284, h:5 ADDED: false
wrote SwingSet checkpoint (kernel=68596, mailbox=388), [run=0ms, mb=0ms, save=24ms]
mboxDeliver:   ADDED messages
outbox changed
wrote SwingSet checkpoint (kernel=69449, mailbox=50), [run=6ms, mb=1ms, save=11ms]
polled; blockTime:1582108289, h:6 ADDED: false
wrote SwingSet checkpoint (kernel=69449, mailbox=50), [run=0ms, mb=0ms, save=27ms]
polled; blockTime:1582108295, h:7 ADDED: false
wrote SwingSet checkpoint (kernel=69449, mailbox=50), [run=0ms, mb=0ms, save=19ms]
polled; blockTime:1582108300, h:8 ADDED: false
wrote SwingSet checkpoint (kernel=69449, mailbox=50), [run=0ms, mb=0ms, save=21ms]
polled; blockTime:1582108305, h:9 ADDED: false
wrote SwingSet checkpoint (kernel=69449, mailbox=50), [run=0ms, mb=0ms, save=21ms]
polled; blockTime:1582108310, h:10 ADDED: false
wrote SwingSet checkpoint (kernel=69449, mailbox=50), [run=0ms, mb=0ms, save=13ms]

(the last lines repeat indefinitely)

Instant reaction:
nopetopus


I understand all of this is probably useful for debugging purposes, but could it be hidden behind an opt-in (like a --debug flag)?

I would have expected something like (intention, not real content):

$ agoric start
✓ Local Agoric Node started
✓ Local Wallet server started, ready to receive requests at http://localhost:5555/
✓ Local Dapp server started, ready to receive requests at http://localhost:8888/

Everything is ok and ready!
Keep this terminal open somewhere
In order to deploy a contract, you need to open a new terminal
@michaelfig
Copy link
Member

PR #730 introduces agoric start --debug, and silences much more of the logs (only printing when there are inbound requests). I think this is good enough to close this issue when it lands.

@DavidBruant please reopen if this issue is closed but not satisfactory.

@DavidBruant
Copy link
Contributor Author

It's much better indeed, thanks!

I'm reopening

The current output is:

agoric: start: rm -rf _agstate/agoric-servers/dev
agoric: start: /home/david/projects/agoric-sdk/packages/cosmic-swingset/bin/ag-solo init dev --egresses=fake
agoric: start: /home/david/projects/agoric-sdk/packages/cosmic-swingset/bin/ag-solo set-fake-chain --role=two_chain --delay=0 myFakeGCI
agoric: start: /home/david/projects/agoric-sdk/packages/cosmic-swingset/bin/ag-solo start --role=two_client
web: Listening on 127.0.0.1:8000
launch-chain: Launching SwingSet kernel
start: swingset running
outbound: invoking deliverator; 1 new messages for myFakeGCI
outbound: invoking deliverator; 4 new messages for myFakeGCI
outbound: invoking deliverator; 2 new messages for myFakeGCI
outbound: invoking deliverator; 5 new messages for myFakeGCI
outbound: invoking deliverator; 3 new messages for myFakeGCI
outbound: invoking deliverator; 2 new messages for myFakeGCI
outbound: invoking deliverator; 0 new messages for myFakeGCI

Out of all of this, my guess is that the only lines that may be of interest to someone working with agoric-cli but not on it are:

agoric: start: rm -rf _agstate/agoric-servers/dev # because it reflects --reset
web: Listening on 127.0.0.1:8000 # because it's some form of indication that some http server is ready to receive requests

Depending on priority, maybe i'll do the rest

@DavidBruant DavidBruant reopened this Mar 19, 2020
@michaelfig
Copy link
Member

I'd recommend to keep the deliverator messages, but rewrite them so that they say something like:

outbound: Send XXX messages to simulated-chain

Those are important to indicate round trips (i.e. activity that might be useful to optimise).

Also the logs should still show the HTTP/WebSocket connections, which is another indication of activity.

Maybe just a single-line indicator of inbound web: XXX messages, outbound chain: XXX messages (like an updating spinner that just increments the counts if there are no errors rather than writing new lines)?

@katelynsills
Copy link
Contributor

@DavidBruant can you check again on the status of this issue?

@DavidBruant
Copy link
Contributor Author

Those are important to indicate round trips (i.e. activity that might be useful to optimise).

I wonder whether this is crucial or nice-to-have information
I'd need more experience running contracts on an actual blockchain to get an idea

But for non-blockchain and fake-blockchain cases, i feel like this should be hidden by default and shown with an opt-in (like --performance-analysis)

@DavidBruant
Copy link
Contributor Author

I think this is good enough for now
i created #909 as a follow-up

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
agoric-cli package: agoric-cli
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants