inter-vat Errors appear in validator node logs even when the caller catches them

[katelynsills]

Describe the bug

When running the latest dapp-fungible-faucet, I get the following error:

katesills@kates-mbp dapp-fungible-faucet % agoric start --reset
'@agoric/install-ses' sniffed and found a 'LOCKDOWN_OPTIONS' environment variable

agoric: start: removing _agstate/agoric-servers/dev
agoric: start: rm -rf _agstate/agoric-servers/dev
agoric: start: initializing dev
agoric: start: /Users/katesills/code/agoric-sdk/packages/solo/src/entrypoint.js init dev --egresses=fake --webport=8000
'@agoric/install-ses' sniffed and found a 'LOCKDOWN_OPTIONS' environment variable

agoric: start: setting sim chain with 0 second delay
agoric: start: /Users/katesills/code/agoric-sdk/packages/solo/src/entrypoint.js set-fake-chain --delay=0 sim-chain
'@agoric/install-ses' sniffed and found a 'LOCKDOWN_OPTIONS' environment variable

agoric: start: /Users/katesills/code/agoric-sdk/packages/solo/src/entrypoint.js start
'@agoric/install-ses' sniffed and found a 'LOCKDOWN_OPTIONS' environment variable

2021-08-17T01:22:41.210Z launch-chain: Launching SwingSet kernel
2021-08-17T01:22:41.232Z web: Listening on 127.0.0.1:8000
Logging sent error stack (Error#1)
Error#1: Bank doesn't implement fee collectors
Error: Bank doesn't implement fee collectors
 at apply ()
 at Error ()
 at getFeeCollectorDepositFacet ()
 at ()
 at win ()
 at ()

Error#1 ERROR_NOTE: Thrown from: (Error#2) : 2 . 0
Error#1 ERROR_NOTE: Sent as error:liveSlots:v1#70001
Error#2: Event: 1.1
Error: Event: 1.1
 at construct ()
 at Error ()
 at trackTurns ()
 at handle ()
 at deliver ()
 at dispatchToUserspace ()
 at runWithoutMetering ()
 at ()

2021-08-17T01:23:17.011Z start: swingset running
'@agoric/install-ses' sniffed and found a 'LOCKDOWN_OPTIONS' environment variable

Open CapTP connection to ws://127.0.0.1:8000/private/captp...ooooooooo

To Reproduce

Steps to reproduce the behavior:

1. Go to https://github.com/Agoric/dapp-fungible-faucet
2. Check out main
3. agoric install
4. agoric start --reset
5. In other tab: agoric deploy ./contract/deploy.js ./api/deploy.js

Expected behavior

We shouldn't see any errors when starting the sim chain with our initial dapps.

Platform Environment

• MacOS 11.5.1 (20G80), node v14.17.5 (npm v6.14.14)
• is there anything special/unusual about your platform? Nope
• what version of the Agoric-SDK are you using? (run git describe --tags --always) agoricstage-9-31-g455c293f0

[michaelfig]

I'm reluctant to proceed without throwing an error, which the code already properly catches.

However, the console output is the result of a harder-to-reconcile issue: liveSlots logs all sent errors to console.info, which the chain doesn't output in normal operation. The team's opinion seems to be that sim chains should be verbose to assist in debugging.

I'd suggest the best way around this is to have console output go to a file (or several different ones) instead of stdout, and certainly the SwingSet console mechanism can accomplish it. But that needs some coordination.

@warner do you have some ideas wrt this?

[katelynsills]

Hmm, are we sure that an error must be thrown? Or could we handle the sim-chain case differently?

[michaelfig]

Hmm, are we sure that an error must be thrown? Or could we handle the sim-chain case differently?

It's a layering violation if we don't throw.

[dckc]

Hack-this-fall participants asked why they're getting this error. (#3990)

@michaelfig tells me this is due to a limitation in SES or marshal: he'd like to throw in one vat and catch in another without noise on the console.

He recalls discussion with @warner about per-vat logs... we'd see this in debug mode but not otherwise.

@warner how do you think this should work?

[Tartuffo]

Validators don't want to see these errors, devs only want to see the ones relevant to them. Maybe these transaction specific errors should go into a separate file. Need to discuss to figure out what "better" is - Mark, Brian, Michael, Nick, Dean.

[warner]

I know @michaelfig changed/improved a bunch of the way errors during sim-chain vats get reported, maybe a month or two ago.

@dckc I think you're running similiar tests like this nowadays.. could you tell us if the current "contract raises an error, does it get printed usefully" behavior is good enough?

[dckc]

It's good enough for MN-1, I suppose.

It's not good enough for smooth onboarding of devs in large volumes; so let's keep the devex label. But I suppose that's a later goal.

The current state-of-the art also depends on knowing that I need to edit this line in chain-main.js if I really want to know what's going on. So let's keep cosmic-swingset too.

    const consensusMode = true;

[dckc]

more interest on this tech-debt today: it's hard to see that this test is working as designed:

cd packages/vats
yarn test test/upgrading/test-upgrade-vats.js

Logging sent error stack (Error#1)
Error#1: D() must be given a device node
  at D (.../swingset-liveslots/src/liveslots.js:1025:7)
  at Alleged: root.provideManagerForBridge (.../vats/src/bridge.js:167:1)

# and then a:

Error#4: No inbound handler for storage
  at Object.fromBridge (.../vats/src/bridge.js:61:1)
  at Alleged: BridgeScopedManager.method (.../store/src/patterns/exo-tools.js:161:8)
  at Alleged: BridgeScopedManager.In "fromBridge" method of (BridgeScopedManager) [as fromBridge] (.../store/src/patterns/exo-tools.js:40:14)

The error is a feature, according to the test:

  await t.throwsAsync(
    () => EV.vat('bridge').provideManagerForBridge(1),
    {
      message: /must be given a device node/,
    },
    'rejects non-device node',
  );

[dckc]

This is once again making ci logs hard to decipher. Several of us are scratching our heads around...

Error#1: D() must be given a device node
  at D (.../swingset-liveslots/src/liveslots.js:1043:7)
  at Alleged: root.provideManagerForBridge (.../vats/src/bridge.js:167:1)

https://github.com/Agoric/agoric-sdk/actions/runs/4692275589/jobs/8317883090?pr=7411

[mhofman]

I suppose in a perfect world, we'd be able to better stitch the errors cross vat. At that point there would be no need to report errors crossing vat boundaries to the console, and only unhandled rejections of errors bubbling all the way back to the initial caller would would be reported (with full cross-vat stacks)

[mhofman]

Idea: plumb the JS/swingset logs / stdout to cosmos over RPC, and print them from there using the cosmos logger? There are knobs related to which modules to output in logs. Arguably we have similar knobs in JS, but maybe they're less discoverable ?