=== RUN Test3PHBasic 2025-10-28T10:56:53.484292 alice INF Vat is running vat=alice 2025-10-28T10:56:53.484515 carol INF Vat is running vat=carol 2025-10-28T10:56:53.484507 bob INF Vat is running vat=bob vat_3ph_test.go:213: ================ Initial connections done. Alice will ask for Bob's Bootstrap. 2025-10-28T10:56:53.586102 alice DBG Prepared Bootstrap message qid=11001 remote=bob vat=alice 2025-10-28T10:56:53.586214 bob TRC Starting to process inbound msg remote=alice vat=bob which=bootstrap 2025-10-28T10:56:53.586279 bob DBG Exported Bootstrap eid=32001 qid=11001 remote=alice vat=bob 2025-10-28T10:56:53.586330 alice DBG Comitted outgoing message qid=11001 remote=bob vat=alice 2025-10-28T10:56:53.586359 alice TRC Starting to process inbound msg remote=bob vat=alice which=return 2025-10-28T10:56:53.586390 alice DBG Imported cap contained in Return iid=32001 ityp=senderHosted qid=11001 remote=bob vat=alice vat_3ph_test.go:213: ================ Alice got Bob's bootstrap cap. Alice will ask for a sub-cap from boot. 2025-10-28T10:56:53.687170 alice DBG Prepared call for exported cap iid=32001 qid=11002 remote=bob vat=alice 2025-10-28T10:56:53.687271 bob TRC Starting to process inbound msg remote=alice vat=bob which=call 2025-10-28T10:56:53.687300 bob TRC Locally handling call eid=32001 etype=locallyHosted impCap=32001 qid=11002 remote=alice vat=bob 2025-10-28T10:56:53.687351 bob TRC Exporting capability eid=32002 remote=alice typ=senderPromise vat=bob 2025-10-28T10:56:53.687369 bob DBG Processed call into payload result eid=32001 qid=11002 remote=alice vat=bob 2025-10-28T10:56:53.687393 alice DBG Comitted outgoing message qid=11002 remote=bob vat=alice 2025-10-28T10:56:53.687412 alice TRC Starting to process inbound msg remote=bob vat=alice which=return 2025-10-28T10:56:53.687441 alice DBG Imported cap contained in Return iid=32002 ityp=remotePromise qid=11002 remote=bob vat=alice vat_3ph_test.go:213: ================ Alice asked Bob for a new cap. Bob will fetch Carol's Boostrap cap. 2025-10-28T10:56:53.787679 bob DBG Prepared Bootstrap message qid=12001 remote=carol vat=bob 2025-10-28T10:56:53.787760 carol TRC Starting to process inbound msg remote=bob vat=carol which=bootstrap 2025-10-28T10:56:53.787857 carol DBG Exported Bootstrap eid=33001 qid=12001 remote=bob vat=carol 2025-10-28T10:56:53.787904 bob DBG Comitted outgoing message qid=12001 remote=carol vat=bob 2025-10-28T10:56:53.787952 bob TRC Starting to process inbound msg remote=carol vat=bob which=return 2025-10-28T10:56:53.788053 bob DBG Imported cap contained in Return iid=33001 ityp=senderHosted qid=12001 remote=carol vat=bob vat_3ph_test.go:213: ================ Bob got Carol's bootstrap cap. Bob will fulfill Alice's promise with it. 2025-10-28T10:56:53.888632 bob DBG Resolving promised answer to third party eid=32002 remote=alice src=alice target=carol targetIid=33001 vat=bob 2025-10-28T10:56:53.888762 carol TRC Starting to process inbound msg remote=bob vat=carol which=provide 2025-10-28T10:56:53.888803 carol DBG Asked to provide cap to third party iid=33001 remote=bob typ=importedCap uniqueKey=00000000223d3b4d1debf0c80000000000000000000000000000000000000000 vat=carol 2025-10-28T10:56:53.888836 carol TRC Registered expected accept in vat remote=bob uniqueKey=00000000223d3b4d1debf0c80000000000000000000000000000000000000000 vat=carol 2025-10-28T10:56:53.888852 bob DBG Sent provide for imported cap iid=33001 qid=12002 remote=carol vat=bob 2025-10-28T10:56:53.890125 bob TRC Slept to delay Resolve after Provide in 3PH resolution dur=1.00195 remote=alice vat=bob 2025-10-28T10:56:53.890172 bob TRC Resolving previously exported promise eid=32002 remote=alice thirdParty=carol thirdPartyIid=33001 vat=bob 2025-10-28T10:56:53.890242 alice TRC Starting to process inbound msg remote=bob vat=alice which=resolve 2025-10-28T10:56:53.891121 alice TRC Shortening path after 3PH introduction dst=carol src=bob vat=alice 2025-10-28T10:56:53.891470 alice DBG Sending accept for 3PH introduction qid=11001 remote=carol srcConn=bob vat=alice 2025-10-28T10:56:53.891682 carol TRC Starting to process inbound msg remote=alice vat=carol which=accept 2025-10-28T10:56:53.891752 carol DBG Providing shared cap to conn eid=33002 provisionId=00000000223d3b4d1debf0c80000000000000000000000000000000000000000 qid=11001 remote=alice src=bob vat=carol 2025-10-28T10:56:53.891830 alice INF Path-shortened imported cap pipeline step to third party acceptId=11001 dst=carol iid=32002 src=bob vat=alice 2025-10-28T10:56:53.891933 alice TRC resolveThirdPartyCapForStep completed remote=bob vat=alice 2025-10-28T10:56:53.891922 bob TRC Starting to process inbound msg remote=carol vat=bob which=return 2025-10-28T10:56:53.891979 bob DBG Received Return message for prior Provide qid=12002 remote=carol vat=bob 2025-10-28T10:56:53.891988 bob TRC Starting to process inbound msg remote=alice vat=bob which=disembargo 2025-10-28T10:56:53.892681 alice TRC Starting to process inbound msg remote=carol vat=alice which=return 2025-10-28T10:56:53.892755 alice DBG Imported cap contained in Return iid=33002 ityp=senderHosted qid=11001 remote=carol vat=alice 2025-10-28T10:56:53.892754 carol TRC Starting to process inbound msg remote=bob vat=carol which=disembargo vat_3ph_test.go:213: ================ 3PH completed! Alice will make a path-shortened call to Carol. 2025-10-28T10:56:54.094069 alice DBG Prepared call for exported cap iid=33002 qid=11002 remote=carol vat=alice 2025-10-28T10:56:54.094192 carol TRC Starting to process inbound msg remote=alice vat=carol which=call 2025-10-28T10:56:54.094226 carol TRC Locally handling call eid=33002 etype=locallyHosted impCap=33002 qid=11002 remote=alice vat=carol 2025-10-28T10:56:54.094264 carol DBG Processed call into payload result eid=33002 qid=11002 remote=alice vat=carol 2025-10-28T10:56:54.094292 alice DBG Comitted outgoing message qid=11002 remote=carol vat=alice 2025-10-28T10:56:54.094334 alice TRC Starting to process inbound msg remote=carol vat=alice which=return vat_3ph_test.go:213: ================ Path-shortened call completed! 2025-10-28T10:56:54.194901 alice TRC Vat begining stop procedure vat=alice 2025-10-28T10:56:54.194980 alice TRC Cancelling step due to conn done qid=11002 remote=bob vat=alice 2025-10-28T10:56:54.194978 carol TRC Conn goroutines finished successfully vat=carol 2025-10-28T10:56:54.195012 alice TRC Cancelling step due to conn done qid=11001 remote=bob vat=alice 2025-10-28T10:56:54.195036 alice TRC Cancelling step due to conn done qid=11001 remote=carol vat=alice 2025-10-28T10:56:54.195044 bob TRC Conn goroutines finished successfully vat=bob 2025-10-28T10:56:54.195052 alice TRC All conns commanded to stop vat=alice 2025-10-28T10:56:54.194901 carol TRC Vat begining stop procedure vat=carol 2025-10-28T10:56:54.195083 carol TRC All conns commanded to stop vat=carol 2025-10-28T10:56:54.195090 alice TRC Conn goroutines finished successfully vat=alice 2025-10-28T10:56:54.195075 bob TRC Conn goroutines finished successfully vat=bob 2025-10-28T10:56:54.195043 carol DBG Conn goroutines finished due to error error="inLoop receive errored: io: read/write on closed pipe" vat=carol 2025-10-28T10:56:54.195130 bob TRC Vat begining stop procedure vat=bob 2025-10-28T10:56:54.195178 carol INF Vat finished running successfully vat=carol 2025-10-28T10:56:54.195183 bob TRC Cancelling step due to conn done qid=12001 remote=carol vat=bob 2025-10-28T10:56:54.195268 bob TRC All conns commanded to stop vat=bob 2025-10-28T10:56:54.195293 bob INF Vat finished running successfully vat=bob 2025-10-28T10:56:54.195119 alice TRC Conn goroutines finished successfully vat=alice 2025-10-28T10:56:54.195321 alice INF Vat finished running successfully vat=alice --- PASS: Test3PHBasic (0.71s) PASS ok matheusd.com/mdcapnp/capnprpc 0.717s