bringOutYourDead difference between non- and consensusMode vats

[michaelfig]

I saw a block that had console messages happen and bringOutYourDead fail to happen in the diverging node's Zoe vat.

That feels like it shouldn't happen. If that's the case, maybe we should have a separate issue for it?

Originally posted by @mhofman in #4510 (comment)

[michaelfig]

--- consensus-mode.slog   2022-02-08 18:34:45.000000000 -0600
+++ non-consensus-mode.slog   2022-02-08 18:35:12.000000000 -0600
@@ -4906,24 +4906,27 @@
 {"type":"crank-start","message":{"type":"send","target":"ko40","msg":{"method":"fromBridge","args":{"body":"[\"bank\",{\"nonce\":13,\"type\":\"VBANK_BALANCE_UPDATE\",\"updated\":[{\"address\":\"agoric17xpfvakm2amg962yls6f84z3kell8c5lzyplmt\",\"amount\":\"200000\",\"denom\":\"urun\"},{\"address\":\"agoric1xj4jqmdqajsqh8frquqhq9j6hhaeh8kf969e9g\",\"amount\":\"75000000\",\"denom\":\"ubld\"},{\"address\":\"agoric1xj4jqmdqajsqh8frquqhq9j6hhaeh8kf969e9g\",\"amount\":\"73689625478\",\"denom\":\"urun\"}]}]","slots":[]},"result":"kp1075"}}}
 {"type":"clist","crankNum":4680,"mode":"import","vatID":"v1","kobj":"kp1075","vobj":"p-123"}
 {"type":"deliver","crankNum":4680,"vatID":"v1","deliveryNum":164,"replay":false,"kd":["message","ko40",{"method":"fromBridge","args":{"body":"[\"bank\",{\"nonce\":13,\"type\":\"VBANK_BALANCE_UPDATE\",\"updated\":[{\"address\":\"agoric17xpfvakm2amg962yls6f84z3kell8c5lzyplmt\",\"amount\":\"200000\",\"denom\":\"urun\"},{\"address\":\"agoric1xj4jqmdqajsqh8frquqhq9j6hhaeh8kf969e9g\",\"amount\":\"75000000\",\"denom\":\"ubld\"},{\"address\":\"agoric1xj4jqmdqajsqh8frquqhq9j6hhaeh8kf969e9g\",\"amount\":\"73689625478\",\"denom\":\"urun\"}]}]","slots":[]},"result":"kp1075"}],"vd":["message","o+1",{"method":"fromBridge","args":{"body":"[\"bank\",{\"nonce\":13,\"type\":\"VBANK_BALANCE_UPDATE\",\"updated\":[{\"address\":\"agoric17xpfvakm2amg962yls6f84z3kell8c5lzyplmt\",\"amount\":\"200000\",\"denom\":\"urun\"},{\"address\":\"agoric1xj4jqmdqajsqh8frquqhq9j6hhaeh8kf969e9g\",\"amount\":\"75000000\",\"denom\":\"ubld\"},{\"address\":\"agoric1xj4jqmdqajsqh8frquqhq9j6hhaeh8kf969e9g\",\"amount\":\"73689625478\",\"denom\":\"urun\"}]}]","slots":[]},"result":"p-123"}]}
+{"type":"console","state":"delivery","crankNum":4680,"vatID":"v1","deliveryNum":164,"level":"error","args":["Unregistered update","{ address: 'agoric17xpfvakm2amg962yls6f84z3kell8c5lzyplmt', amount: '200000', denom: 'urun' }"]}
+{"type":"console","state":"delivery","crankNum":4680,"vatID":"v1","deliveryNum":164,"level":"error","args":["Successful update","{ address: 'agoric1xj4jqmdqajsqh8frquqhq9j6hhaeh8kf969e9g', amount: '75000000', denom: 'ubld' }"]}
+{"type":"console","state":"delivery","crankNum":4680,"vatID":"v1","deliveryNum":164,"level":"error","args":["Successful update","{ address: 'agoric1xj4jqmdqajsqh8frquqhq9j6hhaeh8kf969e9g', amount: '73689625478', denom: 'urun' }"]}
 {"type":"clist","crankNum":4680,"mode":"drop","vatID":"v1","kobj":"kp1075","vobj":"p-123"}
 {"type":"syscall","crankNum":4680,"vatID":"v1","deliveryNum":164,"syscallNum":0,"replay":false,"ksc":["resolve","v1",[["kp1075",false,{"body":"{\"@qclass\":\"undefined\"}","slots":[]}]]],"vsc":["resolve",[["p-123",false,{"body":"{\"@qclass\":\"undefined\"}","slots":[]}]]]}
 {"type":"syscall-result","crankNum":4680,"vatID":"v1","deliveryNum":164,"syscallNum":0,"replay":false,"ksr":["ok",null],"vsr":["ok",null]}
 {"type":"clist","crankNum":4680,"mode":"drop","vatID":"v1","kobj":"kp1009","vobj":"p-120"}
@@ -5382,33 +5385,24 @@
 {"type":"clist","crankNum":4767,"mode":"drop","vatID":"v5","kobj":"kp1096","vobj":"p-216"}
 {"type":"syscall","crankNum":4767,"vatID":"v5","deliveryNum":326,"syscallNum":0,"replay":false,"ksc":["resolve","v5",[["kp1096",false,{"body":"{\"updateCount\":11,\"value\":{\"brand\":{\"@qclass\":\"slot\",\"iface\":\"Alleged: USDC brand\",\"index\":0},\"value\":{\"@qclass\":\"bigint\",\"digits\":\"70238533781556830349548\"}}}","slots":["ko165"]}]]],"vsc":["resolve",[["p-216",false,{"body":"{\"updateCount\":11,\"value\":{\"brand\":{\"@qclass\":\"slot\",\"iface\":\"Alleged: USDC brand\",\"index\":0},\"value\":{\"@qclass\":\"bigint\",\"digits\":\"70238533781556830349548\"}}}","slots":["o+12"]}]]]}
 {"type":"syscall-result","crankNum":4767,"vatID":"v5","deliveryNum":326,"syscallNum":0,"replay":false,"ksr":["ok",null],"vsr":["ok",null]}
-{"type":"deliver-result","crankNum":4767,"vatID":"v5","deliveryNum":326,"replay":false,"dr":["ok",null,{"meterType":"xs-meter-12","currentHeapCount":68619,"compute":62197,"allocate":46268448}]}
+{"type":"deliver-result","crankNum":4767,"vatID":"v5","deliveryNum":326,"replay":false,"dr":["ok",null,{"meterType":"xs-meter-12","currentHeapCount":68603,"compute":62197,"allocate":46268448}]}
 {"type":"crank-finish","crankNum":4767,"crankhash":"8b57c547eb8f693f1663cda9d9192774a8c7d086e1796817bbc05797bb0b2ab6","activityhash":"8af713b2f775445d3a3a0e4360da4d654dd6f02b47523ecc7a168b1d5f37b9a9"}
 {"type":"crank-start","message":{"type":"bringOutYourDead","vatID":"v5"}}
 {"type":"deliver","crankNum":4768,"vatID":"v5","deliveryNum":327,"replay":false,"kd":["bringOutYourDead"],"vd":["bringOutYourDead"]}
-{"type":"deliver-result","crankNum":4768,"vatID":"v5","deliveryNum":327,"replay":false,"dr":["ok",null,{"meterType":"xs-meter-12","currentHeapCount":58871,"compute":5445,"allocate":46268448}]}
+{"type":"deliver-result","crankNum":4768,"vatID":"v5","deliveryNum":327,"replay":false,"dr":["ok",null,{"meterType":"xs-meter-12","currentHeapCount":58855,"compute":5445,"allocate":46268448}]}
 {"type":"crank-finish","crankNum":4768,"crankhash":"dbe67fe90208115bbac2bb6d0de7c4a600d3249c4a40a55f7ad514576604c09b","activityhash":"400254d76605fb21c9f777747d380ae389fd6571323b2e233753911f1bf5d88e"}
 {"type":"crank-start","message":{"type":"notify","vatID":"v15","kpid":"kp1065"}}
 {"type":"clist","crankNum":4769,"mode":"drop","vatID":"v15","kobj":"kp1065","vobj":"p+226"}
 {"type":"deliver","crankNum":4769,"vatID":"v15","deliveryNum":1032,"replay":false,"kd":["notify",[["kp1065",{"state":"fulfilled","refCount":1,"data":{"body":"{\"@qclass\":\"undefined\"}","slots":[]}}]]],"vd":["notify",[["p+226",false,{"body":"{\"@qclass\":\"undefined\"}","slots":[]}]]]}
-{"type":"deliver-result","crankNum":4769,"vatID":"v15","deliveryNum":1032,"replay":false,"dr":["ok",null,{"meterType":"xs-meter-12","currentHeapCount":43109,"compute":15487,"allocate":42074144}]}
+{"type":"deliver-result","crankNum":4769,"vatID":"v15","deliveryNum":1032,"replay":false,"dr":["ok",null,{"meterType":"xs-meter-12","currentHeapCount":43093,"compute":15487,"allocate":42074144}]}
 {"type":"crank-finish","crankNum":4769,"crankhash":"8213488804470283226081112feb83cd0f1397bd59117baafb2f3dfcdc7b65bd","activityhash":"b8957b69dd6edff396923c767662261dd568bc0219c2e6b262ec3f3dbe9972c7"}
 {"type":"crank-start","message":{"type":"bringOutYourDead","vatID":"v15"}}
 {"type":"deliver","crankNum":4770,"vatID":"v15","deliveryNum":1033,"replay":false,"kd":["bringOutYourDead"],"vd":["bringOutYourDead"]}
-{"type":"deliver-result","crankNum":4770,"vatID":"v15","deliveryNum":1033,"replay":false,"dr":["ok",null,{"meterType":"xs-meter-12","currentHeapCount":39513,"compute":5445,"allocate":42074144}]}
+{"type":"deliver-result","crankNum":4770,"vatID":"v15","deliveryNum":1033,"replay":false,"dr":["ok",null,{"meterType":"xs-meter-12","currentHeapCount":39497,"compute":5445,"allocate":42074144}]}
 {"type":"crank-finish","crankNum":4770,"crankhash":"0a3e8a2eeb8f479869ab920783a0cb3710610cdaf459067de922713051c05a63","activityhash":"38b4174279dce9aa5f75b87a41212f2c26bb04cebb45b1bc477eb900c5c76ea9"}
 {"type":"crank-start","message":{"type":"send","target":"ko496","msg":{"method":"getPayout","args":{"body":"[\"Collateral\"]","slots":[]},"result":"kp1097"}}}
 {"type":"clist","crankNum":4771,"mode":"import","vatID":"v11","kobj":"kp1097","vobj":"p-365"}
 {"type":"deliver","crankNum":4771,"vatID":"v11","deliveryNum":944,"replay":false,"kd":["message","ko496",{"method":"getPayout","args":{"body":"[\"Collateral\"]","slots":[]},"result":"kp1097"}],"vd":["message","o+182",{"method":"getPayout","args":{"body":"[\"Collateral\"]","slots":[]},"result":"p-365"}]}
-{"type":"deliver-result","crankNum":4771,"vatID":"v11","deliveryNum":944,"replay":false,"dr":["ok",null,{"meterType":"xs-meter-12","currentHeapCount":123191,"compute":30894,"allocate":46268448}]}
+{"type":"deliver-result","crankNum":4771,"vatID":"v11","deliveryNum":944,"replay":false,"dr":["ok",null,{"meterType":"xs-meter-12","currentHeapCount":123058,"compute":30894,"allocate":46268448}]}
 {"type":"crank-finish","crankNum":4771,"crankhash":"4eba03becf114db6496004d6d5f24ec88792bc6fd423134b952ab43011279512","activityhash":"732eb30df845de51bc7459646e1aa28973df02dfef64b1a65747120ed10dbd04"}
-{"type":"crank-start","message":{"type":"bringOutYourDead","vatID":"v11"}}
-{"type":"deliver","crankNum":4772,"vatID":"v11","deliveryNum":945,"replay":false,"kd":["bringOutYourDead"],"vd":["bringOutYourDead"]}
-{"type":"deliver-result","crankNum":4772,"vatID":"v11","deliveryNum":945,"replay":false,"dr":["ok",null,{"meterType":"xs-meter-12","currentHeapCount":115872,"compute":5445,"allocate":46268448}]}
-{"type":"crank-finish","crankNum":4772,"crankhash":"4e362726e48512850443a97bf3e3f9173430ceaf88d0c8390936f6893ba644a3","activityhash":"ed3cc7ee80e89eb2b13234595e63e6487bd1968f6c21a22fe34c7f652f97b2d8"}
-{"type":"crank-start","message":{"type":"notify","vatID":"v15","kpid":"kp1066"}}
-{"type":"clist","crankNum":4773,"mode":"drop","vatID":"v15","kobj":"kp1066","vobj":"p+227"}
-{"type":"deliver","crankNum":4773,"vatID":"v15","deliveryNum":1034,"replay":false,"kd":["notify",[["kp1066",{"state":"fulfilled","refCount":1,"data":{"body":"{\"@qclass\":\"undefined\"}","slots":[]}}]]],"vd":["notify",[["p+227",false,{"body":"{\"@qclass\":\"undefined\"}","slots":[]}]]]}
-{"type":"deliver-result","crankNum":4773,"vatID":"v15","deliveryNum":1034,"replay":false,"dr":["ok",null,{"meterType":"xs-meter-12","currentHeapCount":42705,"compute":15487,"allocate":42074144}]}
-{"type":"crank-finish","crankNum":4773,"crankhash":"a92db25254ee439b8177091db814d152fbc0093e93c8930970f1f87804e4bf91","activityhash":"61f807aaf6d81aa627854f6b4e04f846c21fb9544ef01ca88a84755784bd09f5"}
 {"type":"cosmic-swingset-end-block-finish","blockHeight":118,"blockTime":1644350883}

[michaelfig]

@warner, would you please have a look at the above differences? @mhofman is thinking that the last block of differences (the observable BOYD difference, triggering the 'notify' difference) should not have differed. This could be a different bug in SwingSet or the XS worker.

[michaelfig]

The additional console messages (added above) may have contributed to the increase in heap count, but I don't know if they affected the BOYD (bringOutYourDead).

[michaelfig]

I've created a gist with the different slog files (just from the single block that diverged) and the diff: https://gist.github.com/michaelfig/2f36fcdb62ed2cc66227a96f63b5b2a2

[mhofman]

Oh maybe I misunderstood. I thought BOYD happened on both, but resulted in different outcome. Here it looks like BOYD only happened on one of the node. Wondering why since I believe we trigger this deterministically without consideration of heap allocations or computron total.

[warner]

Yeah BOYD should happen on a deterministic schedule, I'll try to look into this.

If doing logging in one case and not in the other could change the timing of organic GC (more work done inside the logging function, more object allocation/release), but since we BOYD after every single delivery (which effectively resets the "clock"), I'd be surprised if that changed the GC results.

If console.log were to hold on to some object internally, then that would change the GC results (userspace isn't holding onto it but the logger is, then liveslots' FR won't fire and we wouldn't see a syscall.dropImport). That seems unlikely, but the logger can do anything it wants, so who knows.