pipelined requests through fake-chain linkage can fail

[dtribble]

Describe the bug
When sending pipelined messages from the api deploy script via ag-solo to objects on the chain, the comm internal fail. See below.

To Reproduce

1. in one window, run agoric start --reset -v
2. in another window, run agoric deploy contract/depoy.js api/deploy.js

Expected behavior
Contract and API server should complete installation

Platform Environment
WSL
agoric-sdk: new-zoe-spike-2
dapp-encouragement: new-zoe

Additional context
Specific exampel pipelining code that causes this:

  const assuranceIssuerP = E(publicAPI).getAssuranceIssuer();
  const asurranceBrandP = E(assuranceIssuerP).getBrand();

results in:

SwingSet: kernel: doProcess: vat[v2][p+59].getBrand dispatch failed: Error <Object <[Object: null prototype] {}>>: unknown target type o-64
    at getRemoteFor (v2/packages/SwingSet/src/vats/comms/outbound.js:41:9)
    at getRemoteFor (v2/packages/SwingSet/src/vats/comms/outbound.js:25:16)
    at Object.deliverToRemote (v2/packages/SwingSet/src/vats/comms/outbound.js:54:20)
    at Object.deliver (v2/packages/SwingSet/src/vats/comms/dispatch.js:42:23)
    at eval (kernel/packages/SwingSet/src/kernel/vatManager/deliver.js:48:48)

Adding an await to avoid pipelining also avoids the problem.

[warner]

I've tracked this down to a comms-vat bug that probably got introduced when we added vpid retirement to both kernel and liveslots, but we missed comms, and apparently I didn't have a message-patterns test which triggers it.

The sequence is:

• machine A transmits two messages to machine B, the second being pipelined to the result of the first
  • message one targets ro+15, has a result named rp-20
  • message two targets rp-20, and has a result named rp-21
• B-comms receives the first message:
  • it looks up ro+15 and finds that it points to local object o-7 that it received from the kernel some time before
  • it allocates a VPID (say p+1) for the result,
  • it tells B-kernel to deliver one to o-7 with a result of p+1
• Now, crucially, B-kernel resolves p+1 (to e.g. o-8) before B-comms receives the second message. This might be more likely when A actually sent three messages, zero, one, and two (or at least that's what happened in the original failure)
  • the kernel forgets about p+1 because it believes the vat will also retire the VPID
  • B-comms allocates a new ro+30, transmits a resolve(rp-20) to machine A
• now B-comms receives the second message, addressed to rp-20
  • B-comms looks up rp-20 and, for some reason, still thinks it points at the p+1 that it allocated
    • this is clearly wrong, it should point at o-8
  • B-comms thinks it is pipelining two into the kernel promise for the result of one
  • B-comms tells B-kernel to deliver two to p+1, with some result we don't care about
• B-kernel gets the two delivery from B-comms and sees that it targets p+1
  • B-kernel doesn't know about p+1 (it forgot it back when the vpid was retired), so it allocates a new c-list entry
  • p+1 is allocated by the vat (the +), so the vat is the decider
  • the delivery is pushed onto the run-queue
• B-kernel's run-queue brings the two delivery up to the top
  • the target is p+1, whose decider is the comms vat
  • the comms vat is marked with enablePipelining: true
  • the kernel delivers the two to the comms vat, thinking it's doing a pipelined delivery
• B-comms gets the kernel's two delivery to p+1
  • comms looks up p+1 and finds o-8
    • this is out of sync with the other table. We got rp-20 -> p+1, but p+1 -> o-8.
    • this suggests we're updating the per-remote table but not the local table
  • comms refuses to deliver the kernel's message to o-8 because that's back in the kernel, and the kernel shouldn't be sending gratuitous messages. "you know where it was supposed to go to, and it's not me, why are you bothering me with it?"

[warner]

I'm working on a test to demonstrate this within swingset/comms directly. I don't think it involves capTP, but I'll prove that with the test before removing the CapTP label and upating the title.

[warner]

For (mostly my own) reference, here's my annotated trace of the original expression of the bug:

web: 127.0.0.1:45306[3]: new WebSocket /private/captp
SwingSet: v2: --comms[ag-solo].deliver o+21 getValue r=p-127
SwingSet: v2: -- deliverToRemote
SwingSet: v2: -- remoteID remote1
SwingSet: v2: -- transmit deliver:ro+29:getValue:rp-72;["15326650"]
outbound: invoking deliverator; 1 new messages for sim-chain
SwingSet: v2: --comms[chain].deliver o+10{FROM-OTHER} receive r=p-95
SwingSet: v2: -- deliverFromRemote
SwingSet: v2: -- msg deliver:ro+29:getValue:rp-72;["15326650"]
SwingSet: v2: -- syscall.send(o-62).getValue, r=p+52
SwingSet: v2: --comms[chain].notifyFulfillToPresence p+52 -> o-76
SwingSet: v2: -- transmit resolve:object:rp+72:ro-43;
SwingSet: v2: --comms[ag-solo].deliver o+10{FROM-OTHER} receive r=p-128
SwingSet: v2: -- deliverFromRemote
SwingSet: v2: -- msg resolve:object:rp+72:ro-43;
SwingSet: v2: -- syscall.resolve(p-127) object}, o+35 [object Object]
outbound: invoking deliverator; 0 new messages for sim-chain

  const {
    creatorInvitation: adminInvite,
    creatorFacet
  } = await E(zoe).makeInstance(encouragementInstallation, issuerKeywordRecord);
SwingSet: v2: --comms[ag-solo].deliver o+22{solo.proxies[ZOE]} makeInstance r=p-129
SwingSet: v2: -- deliverToRemote
SwingSet: v2: -- remoteID remote1
SwingSet: v2: -- transmit deliver:ro+30{ZOE}:makeInstance:rp-73:ro+43:ro+35;[{"@qclass":"slot","index":0},{"Tip
outbound: invoking deliverator; 1 new messages for sim-chain
SwingSet: v2: --comms[chain].deliver o+10{FROM-OTHER} receive r=p-96
SwingSet: v2: -- deliverFromRemote
SwingSet: v2: -- msg deliver:ro+30{ZOE}:makeInstance:rp-73:ro+43:ro+35;[{"@qclass":"slot","index":0},{"Tip
SwingSet: v2: -- syscall.send(o-63).makeInstance, r=p+53

SwingSet: v17: TERMS  Presence o-56 <[Object: null prototype] [Presence o-56] {}> [Presence o-56] {}
SwingSet: v2: --comms[chain].notifyFulfillToData p+53
SwingSet: v2: -- transmit resolve:data:rp+73:ro-44:ro-45;{"creatorFacet":{"@qclass":"slot","index":0},"cre
SwingSet: v2: --comms[ag-solo].deliver o+10{FROM-OTHER} receive r=p-130
SwingSet: v2: -- deliverFromRemote
SwingSet: v2: -- msg resolve:data:rp+73:ro-44:ro-45;{"creatorFacet":{"@qclass":"slot","index":0},"cre
SwingSet: v2: -- syscall.resolve(p-129) data}, o+36 [object Object]
outbound: invoking deliverator; 0 new messages for sim-chain

  const instance = await E(creatorFacet).getInstance();
SwingSet: v2: --comms[ag-solo].deliver o+36 getInstance r=p-131
SwingSet: v2: -- deliverToRemote
SwingSet: v2: -- remoteID remote1
SwingSet: v2: -- transmit deliver:ro+44:getInstance:rp-74;[]
outbound: invoking deliverator; 1 new messages for sim-chain

SwingSet: v2: --comms[chain].deliver o+10{FROM-OTHER} receive r=p-97
SwingSet: v2: -- deliverFromRemote
SwingSet: v2: -- msg deliver:ro+44:getInstance:rp-74;[]
SwingSet: v2: -- syscall.send(o-77).getInstance, r=p+54

SwingSet: v2: --comms[chain].notifyFulfillToPresence p+54 -> o-79
SwingSet: v2: -- transmit resolve:object:rp+74:ro-46;

SwingSet: v2: --comms[ag-solo].deliver o+10{FROM-OTHER} receive r=p-132
SwingSet: v2: -- deliverFromRemote
SwingSet: v2: -- msg resolve:object:rp+74:ro-46;
SwingSet: v2: -- syscall.resolve(p-131) object}, o+38 [object Object] // instance

outbound: invoking deliverator; 0 new messages for sim-chain

  const publicAPI = E(zoe).getPublicFacet(instance);
SwingSet: v2: --comms[ag-solo].deliver o+22{solo.proxies[ZOE]} getPublicFacet r=p-133
SwingSet: v2: -- deliverToRemote
SwingSet: v2: -- remoteID remote1
SwingSet: v2: -- transmit deliver:ro+30{ZOE}:getPublicFacet:rp-75:ro+46;[{"@qclass":"slot","index":0}]
outbound: invoking deliverator; 1 new messages for sim-chain
solo->chain queue: getPublicFacet
solo waiting for: getPublicFacet

  const adminSeat = E(zoe).offer(adminInvite); // adding await here hides the bug
SwingSet: v2: --comms[ag-solo].deliver o+22{solo.proxies[ZOE]} offer r=p-134{solo.proxies[adminSeatP]} // adminSeat = E(zoe).offer(adminInvite)
SwingSet: v2: -- deliverToRemote
SwingSet: v2: -- remoteID remote1
SwingSet: v2: -- transmit deliver:ro+30{ZOE}:offer:rp-76:ro+45;[{"@qclass":"slot","index":0}]
solo->chain queue: getPublicFacet, offer
solo waiting for: getPublicFacet, offer


SwingSet: v2: --comms[chain].deliver o+10{FROM-OTHER} receive r=p-98
SwingSet: v2: -- deliverFromRemote
SwingSet: v2: -- msg deliver:ro+30{ZOE}:getPublicFacet:rp-75:ro+46;[{"@qclass":"slot","index":0}]
SwingSet: v2: -- syscall.send(o-63).getPublicFacet, r=p+55
solo->chain queue: offer
kernel comms waiting on kernel for: getPublicFacet

SwingSet: v2: --comms[chain].notifyFulfillToPresence p+55 -> o-80
SwingSet: v2: -- transmit resolve:object:rp+75:ro-47;
outbound: invoking deliverator; 1 new messages for sim-chain
solo->chain queue: offer
kernel comms waiting on kernel for:
chain->solo: resolve(getPublicFacet)

  const outcomeP = E(adminSeat).getOfferResult(); // XXX
SwingSet: v2: --comms[ag-solo].deliver p-134{solo.proxies[adminSeatP]} getOfferResult r=p-135 // outcomeP = E(adminSeat).getOfferResult()
SwingSet: v2: -- deliverToRemote
SwingSet: v2: -- remoteID remote1
SwingSet: v2: -- transmit deliver:rp-76:getOfferResult:rp-77;[]
solo->chain queue: offer, getOfferResult
kernel comms waiting on kernel for:
chain->solo: resolve(getPublicFacet)

SwingSet: v2: --comms[chain].deliver o+10{FROM-OTHER} receive r=p-99
SwingSet: v2: -- deliverFromRemote
SwingSet: v2: -- msg deliver:ro+30{ZOE}:offer:rp-76:ro+45;[{"@qclass":"slot","index":0}]
SwingSet: v2: -- syscall.send(o-63).offer, r=p+56
solo->chain queue: getOfferResult
kernel comms waiting on kernel for: offer
chain->solo: resolve(getPublicFacet)

SwingSet: v2: --comms[chain].notifyFulfillToPresence p+56 -> o-81{chain.adminSeat}
SwingSet: v2: -- transmit resolve:object:rp+76:ro-48;
outbound: invoking deliverator; 1 new messages for sim-chain
solo->chain queue: getOfferResult
kernel comms waiting on kernel for:
chain->solo: resolve(getPublicFacet), resolve(offer)
### chain.comms now knows p+56 -> o-81, BUT BUT kernel clist will retire+delete p+56

  E(scratch).set('adminPayoutP', E(adminSeat).getPayouts());
SwingSet: v2: --comms[ag-solo].deliver p-134{solo.proxies[adminSeatP]} getPayouts r=p-136
SwingSet: v2: -- deliverToRemote
SwingSet: v2: -- remoteID remote1
SwingSet: v2: -- transmit deliver:rp-76:getPayouts:rp-78;[]
solo->chain queue: getOfferResult, getPayouts
kernel comms waiting on kernel for:
chain->solo: resolve(getPublicFacet), resolve(offer)

SwingSet: v2: --comms[chain].deliver o+10{FROM-OTHER} receive r=p-100
SwingSet: v2: -- deliverFromRemote
SwingSet: v2: -- msg deliver:rp-76:getOfferResult:rp-77;[] ## rp-76 should map to o-81, not p+56
SwingSet: v2: -- syscall.send(p+56).getOfferResult, r=p+57
solo->chain queue: getPayouts
kernel comms waiting on kernel for: getOfferResult
chain->solo: resolve(getPublicFacet), resolve(offer)

SwingSet: v2: --comms[chain].deliver p+56 getOfferResult r=p+57
SwingSet: v2: -- deliverToRemote
SwingSet: kernel: doProcess: vat[v2][p+56].getOfferResult dispatch failed: Error <Object <[Object: null prototype] {}>>: unknown target type o-81{chain.adminSeat}
    at getRemoteFor (v2/packages/SwingSet/src/vats/comms/outbound.js:41:9)
    at getRemoteFor (v2/packages/SwingSet/src/vats/comms/outbound.js:25:16)
    at Object.deliverToRemote (v2/packages/SwingSet/src/vats/comms/outbound.js:54:20)
    at Object.deliver (v2/packages/SwingSet/src/vats/comms/dispatch.js:50:23)
    at eval (kernel/packages/SwingSet/src/kernel/vatManager/deliver.js:48:48)
outbound: invoking deliverator; 1 new messages for sim-chain
SwingSet: v2: --comms[chain].deliver o+10{FROM-OTHER} receive r=p-101
SwingSet: v2: -- deliverFromRemote
SwingSet: v2: -- msg deliver:rp-76:getPayouts:rp-78;[]
SwingSet: v2: -- syscall.send(p+56).getPayouts, r=p+58
SwingSet: v2: --comms[chain].deliver p+56 getPayouts r=p+58
SwingSet: v2: -- deliverToRemote
SwingSet: kernel: doProcess: vat[v2][p+56].getPayouts dispatch failed: Error <Object <[Object: null prototype] {}>>: unknown target type o-81{chain.adminSeat}
    at getRemoteFor (v2/packages/SwingSet/src/vats/comms/outbound.js:41:9)
    at getRemoteFor (v2/packages/SwingSet/src/vats/comms/outbound.js:25:16)
    at Object.deliverToRemote (v2/packages/SwingSet/src/vats/comms/outbound.js:54:20)
    at Object.deliver (v2/packages/SwingSet/src/vats/comms/dispatch.js:50:23)
    at eval (kernel/packages/SwingSet/src/kernel/vatManager/deliver.js:48:48)
SwingSet: v2: --comms[ag-solo].deliver o+10{FROM-OTHER} receive r=p-137
SwingSet: v2: -- deliverFromRemote
SwingSet: v2: -- msg resolve:object:rp+75:ro-47;
SwingSet: v2: -- syscall.resolve(p-133) object}, o+39 [object Object]
outbound: invoking deliverator; 0 new messages for sim-chain
SwingSet: v2: --comms[ag-solo].deliver o+10{FROM-OTHER} receive r=p-138
SwingSet: v2: -- deliverFromRemote
SwingSet: v2: -- msg resolve:object:rp+76:ro-48;
SwingSet: v2: -- syscall.resolve(p-134{solo.proxies[adminSeatP]}) object}, o+40 [object Object]
outbound: invoking deliverator; 0 new messages for sim-chain

[warner]

I found a way to test the fix. A key difference between the swingset unit tests (test-message-patterns.js) and the failing situation (using cosmic-swingset in the "fake-chain" mode) is the order of inter-machine message delivery. I have to change the way we do our tests to let them trigger the bug.

In the swingset unit tests, a turn or crank that produces multiple messages will deliver them to the "loopbox" device, which delivers them back into the same swingset machine (but to a second instance of vat-tp, which delivers them to a second instance of the comms vat). When the left vat sends right~.one()~.two(), both one and two turn into syscalls that get pushed onto the kernel run-queue. These arrive at the comms vat and are turned into syscalls aimed at the vat-tp vat.

When they arrive at vat-tp, the old loopbox device immediately pushed them onto the run-queue as separate messages to the right-side vat-tp vat. Then right-vattp pushes both messages to right-comms. Right-comms sees one and pushes a one to right-vat, then right-comms sees two and pushes two to the kernel (targeting the pipelined result of one, which works fine at that point because right-comms hasn't yet seen the resolution of one). Right-vat responds to one with a resolution, that gets pushed onto the end of the run-queue. Then two comes to the top of the run-queue, the kernel sees that the promise to which it was targetted has been resolved to some object, and the kernel delivers one to right-vat. Then a bunch of resolutions travel backwards.

The overall order of delivery is:

• left-vat: start (pushes (A) one and (B) two to comms), q: [lcomms.one, lcomms.two]
• left-comms: one (pushes one to left-vattp), q: [lcomms.two, lvattp.one]
• left-comms: two (pushes two to left-vattp), q: [lvattp.one, lvattp.two]
• left-vattp: one (invokes loopback, which pushes), q: [lvattp.two, rvattp.one]
• left-vattp: two (same), q: [rvattp.one, rvattp.two]
• right-vattp: one (pushes one to comms), q: [rvattp.two, rcomms.one]
• right-vattp: two (pushes two to comms), q: [rcomms.one, rcomms.two]
• right-comms: one (sends one), q: [rcomms.two, rvat.one]
• right-comms: (C) two (pipelines two), q: [rvat.one, oneP.two]
• right-vat: one (resolves to objOne), q: [oneP.two, notifyRComms(oneP)]
• kernel: sees oneP.two, sees that oneP has been resolved to objOne
  • delivers two to right-vat, where objOne lives
  • q: [notifyRComms(oneP), notifyRComms(twoP)]
• right-comms: (D) notify(oneP) (pushes resolve to right-vattp)
  • q: [notifyRComms(twoP), rvattp.resolve(oneP)]
• etc

So the one and two messages are sent from one side to the other, and all deliveries strictly alternate between something involving one, and something involving two.

The bug here only happens when right-comms sees "D" (notifyRComms(oneP)) before it sees "C" (rcomms.two). The two message is aimed at oneP. When "C" arrives first, right-comms sees that oneP is unresolved, and pipelines two into the kernel as it's supposed to, aimed at the promiseID which it allocated when it sent one into the kernel.

If "D" happens first, right-comms dutifully updates its internal promise table to record the fact that oneP is now resolved to some object objOne, and sends a resolution message back to the left (meanwhile, the kernel has forgotten about the oneP identifier, because it's been retired). When "C" arrives, still targetting oneP (because the left side sent the message way back at "B", way too early to know about the resolution), right-comms is supposed to use the internal promise table to route the message to objOne. The bug is that it wasn't doing this lookup on the inbound side, so right-comms really sent two into the kernel aimed at oneP. The kernel says "I don't know that ID, you must be allocating a new one, sure whatever", and eventually pipelines two back into right-comms, which finally produces the error message we saw.

The failing delivery order is "A B D C". This happens because fake-chain uses a queue that lives above the kernel's run-queue, and cross-machine deliveries are made one message at a time. The first cross-machine delivery makes the right side do:

• right-vattp: one (pushes one to comms), q: [rcomms.one]
• right-comms: one (sends one), q: [rvat.one]
• right-vat: one (resolves to objOne), q: [notifyRComms(oneP)]
• right-comms: (D) notify(oneP) (pushes resolve to right-vattp)
  • q: [rvattp.resolve(oneP)]
• right-vattp: resolve(oneP) (queues cross-machine message), q: []

and the second makes it do:

• right-vattp: two (pushes two to comms), q: [rcomms.two]
• right-comms: (C) two (pipelines two to oneP), q: [oneP.two]
• kernel: sees brand new identifier "oneP", decider is right-comms, pipelines
  • q: [rcomms.two]
• right-comms: two (aimed at oneP), throws error

The quick fix that @dtribble found was to add an await on the sender. By adding an await between A and B, it makes the total delivery order is "A D B C", in which case left-comms sends two at objOne, rather than oneP, which bypasses the bug.

To exercise the "A B D C" order in our unit tests, I'm changing (#1425) the loopbox device to have a higher-level queue, just like the fake-chain delivery code does.