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

meter overrun (was: just a transcript we'd like to make easier to debug) #4219

Closed
erights opened this issue Dec 28, 2021 · 3 comments
Closed
Assignees
Labels
bug Something isn't working duplicate SwingSet package: SwingSet

Comments

@erights
Copy link
Member

erights commented Dec 28, 2021

(141):solo(markm-use-want-patterns)$ yarn test test/test-home.js 
yarn run v1.22.15
$ ava test/test-home.js

# connecting
.
.
2021-12-27T23:55:42.494Z ag-solo: solo [
  'init',
  '/var/folders/g1/crzbwthn3n72s_8smhth9g_c0000gn/T//startsolo.62945',
  '--egresses=fake',
  '--webport=7999',
  '--defaultManagerType=local'
]
2021-12-27T23:55:42.550Z ag-solo: init: ag-solo initialized in /var/folders/g1/crzbwthn3n72s_8smhth9g_c0000gn/T//startsolo.62945
2021-12-27T23:55:42.550Z ag-solo: init: HTTP/WebSocket will listen on 127.0.0.1:7999
.
2021-12-27T23:55:43.539Z ag-solo: solo [ 'set-fake-chain', '--delay=0', 'mySimGCI' ]
.
2021-12-27T23:55:44.493Z ag-solo: solo [ 'start' ]
.
.
.
.
.
.
.
.
.
.
.
.
.
.
.
.
.
.
.
.
Removing intrinsics.%ArrayPrototype%.findLast
Removing intrinsics.%ArrayPrototype%.findLastIndex
Removing intrinsics.%ArrayBufferPrototype%.maxByteLength
Removing intrinsics.%ArrayBufferPrototype%.resizable
Removing intrinsics.%ArrayBufferPrototype%.resize
Removing intrinsics.%ArrayBufferPrototype%.transfer
Removing intrinsics.%TypedArrayPrototype%.findLast
Removing intrinsics.%TypedArrayPrototype%.findLastIndex
.
.
.
.
2021-12-27T23:56:08.951Z SwingSet: vat: v5: loading bootstrap.js
Removing intrinsics.%ArrayPrototype%.findLast
Removing intrinsics.%ArrayPrototype%.findLastIndex
Removing intrinsics.%ArrayBufferPrototype%.maxByteLength
Removing intrinsics.%ArrayBufferPrototype%.resizable
Removing intrinsics.%ArrayBufferPrototype%.resize
Removing intrinsics.%ArrayBufferPrototype%.transfer
Removing intrinsics.%TypedArrayPrototype%.findLast
Removing intrinsics.%TypedArrayPrototype%.findLastIndex
.
Removing intrinsics.%ArrayPrototype%.findLast
Removing intrinsics.%ArrayPrototype%.findLastIndex
Removing intrinsics.%ArrayBufferPrototype%.maxByteLength
Removing intrinsics.%ArrayBufferPrototype%.resizable
Removing intrinsics.%ArrayBufferPrototype%.resize
Removing intrinsics.%ArrayBufferPrototype%.transfer
Removing intrinsics.%TypedArrayPrototype%.findLast
Removing intrinsics.%TypedArrayPrototype%.findLastIndex
.
Removing intrinsics.%ArrayPrototype%.findLast
Removing intrinsics.%ArrayPrototype%.findLastIndex
Removing intrinsics.%ArrayBufferPrototype%.maxByteLength
Removing intrinsics.%ArrayBufferPrototype%.resizable
Removing intrinsics.%ArrayBufferPrototype%.resize
Removing intrinsics.%ArrayBufferPrototype%.transfer
Removing intrinsics.%TypedArrayPrototype%.findLast
Removing intrinsics.%TypedArrayPrototype%.findLastIndex
Removing intrinsics.%ArrayPrototype%.findLast
Removing intrinsics.%ArrayPrototype%.findLastIndex
Removing intrinsics.%ArrayBufferPrototype%.maxByteLength
Removing intrinsics.%ArrayBufferPrototype%.resizable
Removing intrinsics.%ArrayBufferPrototype%.resize
Removing intrinsics.%ArrayBufferPrototype%.transfer
Removing intrinsics.%TypedArrayPrototype%.findLast
Removing intrinsics.%TypedArrayPrototype%.findLastIndex
.
Removing intrinsics.%ArrayPrototype%.findLast
Removing intrinsics.%ArrayPrototype%.findLastIndex
Removing intrinsics.%ArrayBufferPrototype%.maxByteLength
Removing intrinsics.%ArrayBufferPrototype%.resizable
Removing intrinsics.%ArrayBufferPrototype%.resize
Removing intrinsics.%ArrayBufferPrototype%.transfer
Removing intrinsics.%TypedArrayPrototype%.findLast
Removing intrinsics.%TypedArrayPrototype%.findLastIndex
.
Removing intrinsics.%ArrayPrototype%.findLast
Removing intrinsics.%ArrayPrototype%.findLastIndex
Removing intrinsics.%ArrayBufferPrototype%.maxByteLength
Removing intrinsics.%ArrayBufferPrototype%.resizable
Removing intrinsics.%ArrayBufferPrototype%.resize
Removing intrinsics.%ArrayBufferPrototype%.transfer
Removing intrinsics.%TypedArrayPrototype%.findLast
Removing intrinsics.%TypedArrayPrototype%.findLastIndex
Removing intrinsics.%ArrayPrototype%.findLast
Removing intrinsics.%ArrayPrototype%.findLastIndex
Removing intrinsics.%ArrayBufferPrototype%.maxByteLength
Removing intrinsics.%ArrayBufferPrototype%.resizable
Removing intrinsics.%ArrayBufferPrototype%.resize
Removing intrinsics.%ArrayBufferPrototype%.transfer
Removing intrinsics.%TypedArrayPrototype%.findLast
Removing intrinsics.%TypedArrayPrototype%.findLastIndex
.
2021-12-27T23:56:14.164Z SwingSet: vat: v5: client bootstrap starting
.
2021-12-27T23:56:15.186Z SwingSet: vat: v5: listening on echo port: [object Alleged: Port]
2021-12-27T23:56:15.301Z start: adding HTTP/WS listener on 127.0.0.1:7999
2021-12-27T23:56:15.305Z web: Serving static files from /private/var/folders/g1/crzbwthn3n72s_8smhth9g_c0000gn/T/startsolo.62945/html
2021-12-27T23:56:15.306Z start: adding follower/sender for fake chain mySimGCI
2021-12-27T23:56:15.308Z launch-chain: Launching SwingSet kernel
2021-12-27T23:56:15.314Z launch-chain: buildSwingset
2021-12-27T23:56:15.328Z web: Listening on 127.0.0.1:7999
.
2021-12-27T23:56:15.447Z web: 127.0.0.1:60056[1]: new WebSocket /private/captp?accessToken=8nxqnCoDMMxOHcbmG6yainDt786vw-23LjCOPMv3yrXQs9MxG_Oj54U1PdmhMZ23
o
2021-12-27T23:56:15.467Z SwingSet: vat: v2: vat-http.inbound (from browser) 0 {
  "meta": {
    "channelID": 1,
    "date": 1640649375447,
    "dispatcher": "onOpen",
    "origin": "http://localhost:7999",
    "query": {
      "isQuery": true
    },
    "url": "/private/captp"
  },
  "type": "ws/meta"
}
2021-12-27T23:56:15.481Z SwingSet: vat: v2: Starting CapTP#NaN {
  date: 1640649375447,
  dispatcher: 'onOpen',
  origin: 'http://localhost:7999',
  query: { isQuery: true },
  url: '/private/captp',
  channelHandle: '[Alleged: channelHandle]'
}
2021-12-27T23:56:15.595Z SwingSet: vat: v2: vat-http.inbound (from browser) 1 {
  "epoch": 0,
  "meta": {
    "channelID": 1,
    "date": 1640649375468,
    "origin": "http://localhost:7999",
    "query": {
      "isQuery": true
    },
    "url": "/private/captp"
  },
  "questionID": "test fixture#1",
  "type": "CTP_BOOTSTRAP"
}
2021-12-27T23:56:15.621Z SwingSet: vat: v2: processing inbound { epoch: 0, questionID: 'test fixture#1', type: 'CTP_BOOTSTRAP' }
2021-12-27T23:56:15.822Z SwingSet: vat: v2: vat-http.inbound (from browser) 2 {
  "answerID": "http://localhost:7999#1",
  "epoch": 0,
  "meta": {
    "channelID": 1,
    "date": 1640649375701,
    "origin": "http://localhost:7999",
    "query": {
      "isQuery": true
    },
    "url": "/private/captp"
  },
  "result": {
    "body": "{\"@qclass\":\"undefined\"}",
    "slots": [
      
    ]
  },
  "type": "CTP_RETURN"
}
2021-12-27T23:56:15.859Z SwingSet: vat: v2: processing inbound {
  answerID: 'http://localhost:7999#1',
  epoch: 0,
  result: { body: '{"@qclass":"undefined"}', slots: [] },
  type: 'CTP_RETURN'
}
2021-12-27T23:56:15.946Z SwingSet: vat: v2: vat-http.inbound (from browser) 3 {
  "epoch": 0,
  "meta": {
    "channelID": 1,
    "date": 1640649375769,
    "origin": "http://localhost:7999",
    "query": {
      "isQuery": true
    },
    "url": "/private/captp"
  },
  "method": {
    "body": "[\"getUpdateSince\",[{\"@qclass\":\"undefined\"}]]",
    "slots": [
      
    ]
  },
  "questionID": "test fixture#2",
  "target": "o-2",
  "type": "CTP_CALL"
}
2021-12-27T23:56:15.966Z SwingSet: vat: v2: processing inbound {
  epoch: 0,
  method: { body: '[["getUpdateSince",[{"@qclass":"undefined"}]]]', slots: [] },
  questionID: 'test fixture#2',
  target: 'o-2',
  type: 'CTP_CALL'
}
o
2021-12-27T23:56:16.043Z SwingSet: vat: v2: vat-http.inbound (from browser) 4 {
  "epoch": 0,
  "meta": {
    "channelID": 1,
    "date": 1640649376013,
    "origin": "http://localhost:7999",
    "query": {
      "isQuery": true
    },
    "url": "/private/captp"
  },
  "method": {
    "body": "[\"getUpdateSince\",[3]]",
    "slots": [
      
    ]
  },
  "questionID": "test fixture#3",
  "target": "o-2",
  "type": "CTP_CALL"
}
2021-12-27T23:56:16.053Z SwingSet: vat: v2: processing inbound {
  epoch: 0,
  method: { body: '[["getUpdateSince",[3]]]', slots: [] },
  questionID: 'test fixture#3',
  target: 'o-2',
  type: 'CTP_CALL'
}
Removing intrinsics.%ArrayPrototype%.findLast
Removing intrinsics.%ArrayPrototype%.findLastIndex
Removing intrinsics.%ArrayBufferPrototype%.maxByteLength
Removing intrinsics.%ArrayBufferPrototype%.resizable
Removing intrinsics.%ArrayBufferPrototype%.resize
Removing intrinsics.%ArrayBufferPrototype%.transfer
Removing intrinsics.%TypedArrayPrototype%.findLast
Removing intrinsics.%TypedArrayPrototype%.findLastIndex
Removing intrinsics.%ArrayPrototype%.findLast
Removing intrinsics.%ArrayPrototype%.findLastIndex
Removing intrinsics.%ArrayBufferPrototype%.maxByteLength
Removing intrinsics.%ArrayBufferPrototype%.resizable
Removing intrinsics.%ArrayBufferPrototype%.resize
Removing intrinsics.%ArrayBufferPrototype%.transfer
Removing intrinsics.%TypedArrayPrototype%.findLast
Removing intrinsics.%TypedArrayPrototype%.findLastIndex
Removing intrinsics.%ArrayPrototype%.findLast
Removing intrinsics.%ArrayPrototype%.findLastIndex
Removing intrinsics.%ArrayBufferPrototype%.maxByteLength
Removing intrinsics.%ArrayBufferPrototype%.resizable
Removing intrinsics.%ArrayBufferPrototype%.resize
Removing intrinsics.%ArrayBufferPrototype%.transfer
Removing intrinsics.%TypedArrayPrototype%.findLast
Removing intrinsics.%TypedArrayPrototype%.findLastIndex
2021-12-27T23:56:48.533Z SwingSet: vat: v12: loading bootstrap.js
Removing intrinsics.%ArrayPrototype%.findLast
Removing intrinsics.%ArrayPrototype%.findLastIndex
Removing intrinsics.%ArrayBufferPrototype%.maxByteLength
Removing intrinsics.%ArrayBufferPrototype%.resizable
Removing intrinsics.%ArrayBufferPrototype%.resize
Removing intrinsics.%ArrayBufferPrototype%.transfer
Removing intrinsics.%TypedArrayPrototype%.findLast
Removing intrinsics.%TypedArrayPrototype%.findLastIndex
Removing intrinsics.%ArrayPrototype%.findLast
Removing intrinsics.%ArrayPrototype%.findLastIndex
Removing intrinsics.%ArrayBufferPrototype%.maxByteLength
Removing intrinsics.%ArrayBufferPrototype%.resizable
Removing intrinsics.%ArrayBufferPrototype%.resize
Removing intrinsics.%ArrayBufferPrototype%.transfer
Removing intrinsics.%TypedArrayPrototype%.findLast
Removing intrinsics.%TypedArrayPrototype%.findLastIndex
Removing intrinsics.%ArrayPrototype%.findLast
Removing intrinsics.%ArrayPrototype%.findLastIndex
Removing intrinsics.%ArrayBufferPrototype%.maxByteLength
Removing intrinsics.%ArrayBufferPrototype%.resizable
Removing intrinsics.%ArrayBufferPrototype%.resize
Removing intrinsics.%ArrayBufferPrototype%.transfer
Removing intrinsics.%TypedArrayPrototype%.findLast
Removing intrinsics.%TypedArrayPrototype%.findLastIndex
Removing intrinsics.%ArrayPrototype%.findLast
Removing intrinsics.%ArrayPrototype%.findLastIndex
Removing intrinsics.%ArrayBufferPrototype%.maxByteLength
Removing intrinsics.%ArrayBufferPrototype%.resizable
Removing intrinsics.%ArrayBufferPrototype%.resize
Removing intrinsics.%ArrayBufferPrototype%.transfer
Removing intrinsics.%TypedArrayPrototype%.findLast
Removing intrinsics.%TypedArrayPrototype%.findLastIndex
Removing intrinsics.%ArrayPrototype%.findLast
Removing intrinsics.%ArrayPrototype%.findLastIndex
Removing intrinsics.%ArrayBufferPrototype%.maxByteLength
Removing intrinsics.%ArrayBufferPrototype%.resizable
Removing intrinsics.%ArrayBufferPrototype%.resize
Removing intrinsics.%ArrayBufferPrototype%.transfer
Removing intrinsics.%TypedArrayPrototype%.findLast
Removing intrinsics.%TypedArrayPrototype%.findLastIndex
Removing intrinsics.%ArrayPrototype%.findLast
Removing intrinsics.%ArrayPrototype%.findLastIndex
Removing intrinsics.%ArrayBufferPrototype%.maxByteLength
Removing intrinsics.%ArrayBufferPrototype%.resizable
Removing intrinsics.%ArrayBufferPrototype%.resize
Removing intrinsics.%ArrayBufferPrototype%.transfer
Removing intrinsics.%TypedArrayPrototype%.findLast
Removing intrinsics.%TypedArrayPrototype%.findLastIndex
Removing intrinsics.%ArrayPrototype%.findLast
Removing intrinsics.%ArrayPrototype%.findLastIndex
Removing intrinsics.%ArrayBufferPrototype%.maxByteLength
Removing intrinsics.%ArrayBufferPrototype%.resizable
Removing intrinsics.%ArrayBufferPrototype%.resize
Removing intrinsics.%ArrayBufferPrototype%.transfer
Removing intrinsics.%TypedArrayPrototype%.findLast
Removing intrinsics.%TypedArrayPrototype%.findLastIndex
Removing intrinsics.%ArrayPrototype%.findLast
Removing intrinsics.%ArrayPrototype%.findLastIndex
Removing intrinsics.%ArrayBufferPrototype%.maxByteLength
Removing intrinsics.%ArrayBufferPrototype%.resizable
Removing intrinsics.%ArrayBufferPrototype%.resize
Removing intrinsics.%ArrayBufferPrototype%.transfer
Removing intrinsics.%TypedArrayPrototype%.findLast
Removing intrinsics.%TypedArrayPrototype%.findLastIndex
Removing intrinsics.%ArrayPrototype%.findLast
Removing intrinsics.%ArrayPrototype%.findLastIndex
Removing intrinsics.%ArrayBufferPrototype%.maxByteLength
Removing intrinsics.%ArrayBufferPrototype%.resizable
Removing intrinsics.%ArrayBufferPrototype%.resize
Removing intrinsics.%ArrayBufferPrototype%.transfer
Removing intrinsics.%TypedArrayPrototype%.findLast
Removing intrinsics.%TypedArrayPrototype%.findLastIndex
Removing intrinsics.%ArrayPrototype%.findLast
Removing intrinsics.%ArrayPrototype%.findLastIndex
Removing intrinsics.%ArrayBufferPrototype%.maxByteLength
Removing intrinsics.%ArrayBufferPrototype%.resizable
Removing intrinsics.%ArrayBufferPrototype%.resize
Removing intrinsics.%ArrayBufferPrototype%.transfer
Removing intrinsics.%TypedArrayPrototype%.findLast
Removing intrinsics.%TypedArrayPrototype%.findLastIndex
Removing intrinsics.%ArrayPrototype%.findLast
Removing intrinsics.%ArrayPrototype%.findLastIndex
Removing intrinsics.%ArrayBufferPrototype%.maxByteLength
Removing intrinsics.%ArrayBufferPrototype%.resizable
Removing intrinsics.%ArrayBufferPrototype%.resize
Removing intrinsics.%ArrayBufferPrototype%.transfer
Removing intrinsics.%TypedArrayPrototype%.findLast
Removing intrinsics.%TypedArrayPrototype%.findLastIndex
Removing intrinsics.%ArrayPrototype%.findLast
Removing intrinsics.%ArrayPrototype%.findLastIndex
Removing intrinsics.%ArrayBufferPrototype%.maxByteLength
Removing intrinsics.%ArrayBufferPrototype%.resizable
Removing intrinsics.%ArrayBufferPrototype%.resize
Removing intrinsics.%ArrayBufferPrototype%.transfer
Removing intrinsics.%TypedArrayPrototype%.findLast
Removing intrinsics.%TypedArrayPrototype%.findLastIndex
2021-12-27T23:56:57.434Z start: swingset running
2021-12-27T23:56:57.434Z outbound: deliver { mySimGCI: { inboundAck: 0, outbox: [ [Array] ] } }
2021-12-27T23:56:57.435Z outbound: new outbound message 1 for mySimGCI: 1:0:deliver:ro+1:getChainBundle:rp-40;[]
2021-12-27T23:56:57.435Z outbound: invoking deliverator; 1 new messages for mySimGCI
2021-12-27T23:56:58.035Z SwingSet: vat: v12: sim-chain bootstrap starting
2021-12-27T23:56:58.436Z fake-chain: delivering to mySimGCI (trips=1)
Open CapTP connection to ws://127.0.0.1:7999/private/captp...
2021-12-27T23:56:58.471Z web: 127.0.0.1:60074[2]: new WebSocket /private/captp?accessToken=8nxqnCoDMMxOHcbmG6yainDt786vw-23LjCOPMv3yrXQs9MxG_Oj54U1PdmhMZ23
agoric: deploy: Connected to CapTP!
agoric: deploy: sendJSON {"type":"CTP_BOOTSTRAP","epoch":1640649418473,"questionID":"bundle#1"}
o
agoric: deploy: need: agoric, local
2021-12-27T23:56:58.477Z SwingSet: vat: v2: vat-http.inbound (from browser) 5 {
  "meta": {
    "channelID": 2,
    "date": 1640649418471,
    "dispatcher": "onOpen",
    "origin": "http://127.0.0.1",
    "query": {
      "isQuery": true
    },
    "url": "/private/captp"
  },
  "type": "ws/meta"
}
2021-12-27T23:56:58.478Z SwingSet: vat: v2: Starting CapTP#NaN {
  date: 1640649418471,
  dispatcher: 'onOpen',
  origin: 'http://127.0.0.1',
  query: { isQuery: true },
  url: '/private/captp',
  channelHandle: '[Alleged: channelHandle]'
}
2021-12-27T23:56:58.515Z outbound: deliver { mySimGCI: { inboundAck: 0, outbox: [ [Array] ] } }
2021-12-27T23:56:58.518Z SwingSet: vat: v2: vat-http.inbound (from browser) 6 {
  "epoch": 1640649418473,
  "meta": {
    "channelID": 2,
    "date": 1640649418476,
    "origin": "http://127.0.0.1",
    "query": {
      "isQuery": true
    },
    "url": "/private/captp"
  },
  "questionID": "bundle#1",
  "type": "CTP_BOOTSTRAP"
}
2021-12-27T23:56:58.520Z SwingSet: vat: v2: processing inbound { epoch: 1640649418473, questionID: 'bundle#1', type: 'CTP_BOOTSTRAP' }
agoric: deploy: receiving {"epoch":null,"questionID":"http://127.0.0.1#1","type":"CTP_BOOTSTRAP"}
agoric: deploy: sendJSON {"type":"CTP_RETURN","epoch":1640649418473,"answerID":"http://127.0.0.1#1","result":{"body":"{\"@qclass\":\"undefined\"}","slots":[]}}
agoric: deploy: receiving {"answerID":"bundle#1","epoch":null,"result":{"body":"{\"LOADING\":[\"agoric\",\"wallet\"],\"agoric\":{},\"http\":{\"@qclass\":\"slot\",\"iface\":\"Alleged: httpRegCallback\",\"index\":0},\"loadingNot
agoric: deploy: sendJSON {"type":"CTP_CALL","epoch":1640649418473,"questionID":"bundle#2","target":"o-2","method":{"body":"[\"getUpdateSince\",[{\"@qclass\":\"undefined\"}]]","slots":[]}}
2021-12-27T23:56:58.550Z outbound: deliver { mySimGCI: { inboundAck: 0, outbox: [ [Array] ] } }
agoric: deploy: receiving {}
2021-12-27T23:56:58.554Z SwingSet: vat: v2: vat-http.inbound (from browser) 7 {
  "answerID": "http://127.0.0.1#1",
  "epoch": 1640649418473,
  "meta": {
    "channelID": 2,
    "date": 1640649418527,
    "origin": "http://127.0.0.1",
    "query": {
      "isQuery": true
    },
    "url": "/private/captp"
  },
  "result": {
    "body": "{\"@qclass\":\"undefined\"}",
    "slots": [
      
    ]
  },
  "type": "CTP_RETURN"
}
2021-12-27T23:56:58.555Z SwingSet: vat: v2: processing inbound {
  answerID: 'http://127.0.0.1#1',
  epoch: 1640649418473,
  result: { body: '{"@qclass":"undefined"}', slots: [] },
  type: 'CTP_RETURN'
}
2021-12-27T23:56:58.569Z outbound: deliver { mySimGCI: { inboundAck: 0, outbox: [ [Array] ] } }
agoric: deploy: receiving {}
2021-12-27T23:56:58.572Z SwingSet: vat: v2: vat-http.inbound (from browser) 8 {
  "epoch": 1640649418473,
  "meta": {
    "channelID": 2,
    "date": 1640649418542,
    "origin": "http://127.0.0.1",
    "query": {
      "isQuery": true
    },
    "url": "/private/captp"
  },
  "method": {
    "body": "[\"getUpdateSince\",[{\"@qclass\":\"undefined\"}]]",
    "slots": [
      
    ]
  },
  "questionID": "bundle#2",
  "target": "o-2",
  "type": "CTP_CALL"
}
2021-12-27T23:56:58.573Z SwingSet: vat: v2: processing inbound {
  epoch: 1640649418473,
  method: { body: '[["getUpdateSince",[{"@qclass":"undefined"}]]]', slots: [] },
  questionID: 'bundle#2',
  target: 'o-2',
  type: 'CTP_CALL'
}
agoric: deploy: receiving {"answerID":"bundle#2","epoch":null,"result":{"body":"{\"updateCount\":3,\"value\":[\"agoric\",\"wallet\"]}","slots":[]},"type":"CTP_RETURN"}
o
agoric: deploy: need: agoric
agoric: deploy: sendJSON {"type":"CTP_CALL","epoch":1640649418473,"questionID":"bundle#3","target":"o-2","method":{"body":"[\"getUpdateSince\",[3]]","slots":[]}}
2021-12-27T23:56:58.588Z outbound: deliver { mySimGCI: { inboundAck: 0, outbox: [ [Array] ] } }
agoric: deploy: receiving {}
2021-12-27T23:56:58.593Z SwingSet: vat: v2: vat-http.inbound (from browser) 9 {
  "epoch": 1640649418473,
  "meta": {
    "channelID": 2,
    "date": 1640649418580,
    "origin": "http://127.0.0.1",
    "query": {
      "isQuery": true
    },
    "url": "/private/captp"
  },
  "method": {
    "body": "[\"getUpdateSince\",[3]]",
    "slots": [
      
    ]
  },
  "questionID": "bundle#3",
  "target": "o-2",
  "type": "CTP_CALL"
}
2021-12-27T23:56:58.594Z SwingSet: vat: v2: processing inbound {
  epoch: 1640649418473,
  method: { body: '[["getUpdateSince",[3]]]', slots: [] },
  questionID: 'bundle#3',
  target: 'o-2',
  type: 'CTP_CALL'
}
2021-12-27T23:56:58.606Z outbound: deliver { mySimGCI: { inboundAck: 0, outbox: [ [Array] ] } }
agoric: deploy: receiving {}
o
o
Removing intrinsics.%ArrayPrototype%.findLast
Removing intrinsics.%ArrayPrototype%.findLastIndex
Removing intrinsics.%ArrayBufferPrototype%.maxByteLength
Removing intrinsics.%ArrayBufferPrototype%.resizable
Removing intrinsics.%ArrayBufferPrototype%.resize
Removing intrinsics.%ArrayBufferPrototype%.transfer
Removing intrinsics.%TypedArrayPrototype%.findLast
Removing intrinsics.%TypedArrayPrototype%.findLastIndex
o
Removing intrinsics.%ArrayPrototype%.findLast
Removing intrinsics.%ArrayPrototype%.findLastIndex
Removing intrinsics.%ArrayBufferPrototype%.maxByteLength
Removing intrinsics.%ArrayBufferPrototype%.resizable
Removing intrinsics.%ArrayBufferPrototype%.resize
Removing intrinsics.%ArrayBufferPrototype%.transfer
Removing intrinsics.%TypedArrayPrototype%.findLast
Removing intrinsics.%TypedArrayPrototype%.findLastIndex
o
o
o
2021-12-27T23:57:05.139Z SwingSet: vat: v11: Meter down to 10880351. Refilling to 35880351
o
Removing intrinsics.%ArrayPrototype%.findLast
Removing intrinsics.%ArrayPrototype%.findLastIndex
Removing intrinsics.%ArrayBufferPrototype%.maxByteLength
Removing intrinsics.%ArrayBufferPrototype%.resizable
Removing intrinsics.%ArrayBufferPrototype%.resize
Removing intrinsics.%ArrayBufferPrototype%.transfer
Removing intrinsics.%TypedArrayPrototype%.findLast
Removing intrinsics.%TypedArrayPrototype%.findLastIndex
o
o
2021-12-27T23:57:07.820Z SwingSet: vat: v11: Meter down to 18140412. Refilling to 43140412
Removing intrinsics.%ArrayPrototype%.findLast
Removing intrinsics.%ArrayPrototype%.findLastIndex
Removing intrinsics.%ArrayBufferPrototype%.maxByteLength
Removing intrinsics.%ArrayBufferPrototype%.resizable
Removing intrinsics.%ArrayBufferPrototype%.resize
Removing intrinsics.%ArrayBufferPrototype%.transfer
Removing intrinsics.%TypedArrayPrototype%.findLast
Removing intrinsics.%TypedArrayPrototype%.findLastIndex
o
o
o
2021-12-27T23:57:10.900Z SwingSet: kernel: meter m4 underflow, terminating vat v20
2021-12-27T23:57:10.924Z SwingSet: vat: v11: Meter down to 1895451. Refilling to 26895451
#633:225: exception: throw!
Logging sent error stack (RemoteError#1)
RemoteError#1: vat terminated
Error: vat terminated
 at construct ()
 at Error (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:8833)
 at makeError (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:3103)
 at fullRevive (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:5451)
 at unserialize (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:5534)
 at notifyOnePromise (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:9021)
 at notify (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:9034)
 at dispatchToUserspace (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:9266)
 at runWithoutMetering (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:9648)
 at ()

RemoteError#1 ERROR_NOTE: Rejection from: (Error#2) : 53 . 0
RemoteError#1 ERROR_NOTE: Rejection from: (Error#3) : 39 . 0
RemoteError#1 ERROR_NOTE: Sent as error:liveSlots:v11#70001
Error#2: Event: 51.2
Error: Event: 51.2
 at construct ()
 at Error (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:8833)
 at trackTurns (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:10534)
 at handle (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:11241)
 at (#191:39)
 at startInstance (#633:225)
 at ()
 at ()

Error#3: Event: 38.1
Error: Event: 38.1
 at construct ()
 at Error (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:8833)
 at trackTurns (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:10534)
 at handle (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:11241)
 at deliver (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:8944)
 at dispatchToUserspace (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:9261)
 at runWithoutMetering (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:9648)
 at ()

Logging sent error stack (RemoteError#1)
RemoteError#1: meter underflow, vat terminated
Error: meter underflow, vat terminated
 at construct ()
 at Error (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:8833)
 at makeError (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:3103)
 at fullRevive (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:5451)
 at fullRevive (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:5499)
 at unserialize (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:5534)
 at deliver (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:8926)
 at dispatchToUserspace (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:9261)
 at runWithoutMetering (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:9648)
 at ()

RemoteError#1 ERROR_NOTE: Rejection from: (Error#2) : 31 . 0
RemoteError#1 ERROR_NOTE: Sent as error:liveSlots:v13#70001
Error#2: Event: 30.1
Error: Event: 30.1
 at construct ()
 at Error (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:8833)
 at trackTurns (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:10534)
 at handle (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:11241)
 at deliver (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:8944)
 at dispatchToUserspace (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:9261)
 at runWithoutMetering (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:9648)
 at ()

#655:108: exception: throw!
Logging sent error stack (RemoteError(error:liveSlots:v11#70001)#1)
RemoteError(error:liveSlots:v11#70001)#1: vat terminated
Error: vat terminated
 at construct ()
 at Error (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:8833)
 at makeError (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:3103)
 at fullRevive (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:5451)
 at unserialize (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:5534)
 at notifyOnePromise (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:9021)
 at notify (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:9034)
 at dispatchToUserspace (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:9266)
 at runWithoutMetering (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:9648)
 at ()

RemoteError(error:liveSlots:v11#70001)#1 ERROR_NOTE: Rejection from: (Error#2) : 4 . 0
RemoteError(error:liveSlots:v11#70001)#1 ERROR_NOTE: Rejection from: (Error#3) : 2 . 2
RemoteError(error:liveSlots:v11#70001)#1 ERROR_NOTE: Rejection from: (Error#4) : 1 . 1
RemoteError(error:liveSlots:v11#70001)#1 ERROR_NOTE: Sent as error:liveSlots:v19#70001
Error#2: Event: 2.2
Error: Event: 2.2
 at construct ()
 at Error (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:8833)
 at trackTurns (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:10534)
 at handle (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:11241)
 at (#796:39)
 at start (#655:108)
 at start ()
 at apply ()
 at apply ()
 at dispatchToHandler (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:10911)
 at (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:10550)
 at win (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:11250)
 at ()

Error#2 ERROR_NOTE: Caused by: (Error#3)
Error#3: Event: 1.1
Error: Event: 1.1
 at construct ()
 at Error (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:8833)
 at trackTurns (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:10534)
 at handle (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:11241)
 at (#375:39)
 at startContract (#235:359)
 at apply ()
 at apply ()
 at dispatchToHandler (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:10911)
 at (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:10550)
 at win (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:11250)
 at ()

Error#3 ERROR_NOTE: Caused by: (Error#4)
Error#4: Event: 0.1
Error: Event: 0.1
 at construct ()
 at Error (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:8833)
 at trackTurns (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:10534)
 at handle (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:11241)
 at deliver (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:8944)
 at dispatchToUserspace (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:9261)
 at runWithoutMetering (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:9648)
 at ()

#633:225: exception: throw!
Logging sent error stack (RemoteError(error:liveSlots:v19#70001)#5)
RemoteError(error:liveSlots:v19#70001)#5: vat terminated
Error: vat terminated
 at construct ()
 at Error (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:8833)
 at makeError (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:3103)
 at fullRevive (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:5451)
 at unserialize (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:5534)
 at notifyOnePromise (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:9021)
 at notify (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:9034)
 at dispatchToUserspace (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:9266)
 at runWithoutMetering (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:9648)
 at ()

RemoteError(error:liveSlots:v19#70001)#5 ERROR_NOTE: Rejection from: (Error#6) : 37 . 0
RemoteError(error:liveSlots:v19#70001)#5 ERROR_NOTE: Rejection from: (Error#7) : 31 . 0
RemoteError(error:liveSlots:v19#70001)#5 ERROR_NOTE: Sent as error:liveSlots:v11#70002
Error#6: Event: 35.2
Error: Event: 35.2
 at construct ()
 at Error (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:8833)
 at trackTurns (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:10534)
 at handle (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:11241)
 at (#191:39)
 at startInstance (#633:225)
 at ()
 at ()

Error#7: Event: 30.1
Error: Event: 30.1
 at construct ()
 at Error (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:8833)
 at trackTurns (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:10534)
 at handle (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:11241)
 at deliver (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:8944)
 at dispatchToUserspace (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:9261)
 at runWithoutMetering (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:9648)
 at ()

#583:93: exception: throw!
#583:211: exception: throw!
#185:182: exception: throw!
#185:260: exception: throw!
#185:1104: exception: throw!
Logging sent error stack (RemoteError(error:liveSlots:v11#70002)#1)
RemoteError(error:liveSlots:v11#70002)#1: vat terminated
Error: vat terminated
 at construct ()
 at Error (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:8833)
 at makeError (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:3103)
 at fullRevive (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:5451)
 at unserialize (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:5534)
 at notifyOnePromise (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:9021)
 at notify (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:9034)
 at dispatchToUserspace (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:9266)
 at runWithoutMetering (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:9648)
 at ()

RemoteError(error:liveSlots:v11#70002)#1 ERROR_NOTE: Rejection from: (Error#2) : 49 . 0
RemoteError(error:liveSlots:v11#70002)#1 ERROR_NOTE: Rejection from: (Error#3) : 1 . 1
RemoteError(error:liveSlots:v11#70002)#1 ERROR_NOTE: Sent as error:liveSlots:v12#70001
Error#2: Event: 47.2
Error: Event: 47.2
 at construct ()
 at Error (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:8833)
 at trackTurns (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:10534)
 at handle (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:11241)
 at (#202:39)
 at setupAmm (#583:93)
 at ()
 at ()

Error#3: Event: 0.1
Error: Event: 0.1
 at construct ()
 at Error (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:8833)
 at trackTurns (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:10534)
 at handle (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:11241)
 at deliver (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:8944)
 at dispatchToUserspace (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:9261)
 at runWithoutMetering (/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/supervisor-subprocess-xsnap.js:9648)
 at ()

2021-12-27T23:57:11.080Z SwingSet: kernel: ##### KERNEL PANIC: kp40.policy panic: rejected {"body":"{\"@qclass\":\"error\",\"errorId\":\"error:liveSlots:v12#70001\",\"message\":\"vat terminated\",\"name\":\"Error\"}","slots":[]} #####
2021-12-27T23:57:11.082Z fake-chain: Cannot boot sim chain: (Error#1)
Error#1: kernel panic kp40.policy panic: rejected {"body":"{\"@qclass\":\"error\",\"errorId\":\"error:liveSlots:v12#70001\",\"message\":\"vat terminated\",\"name\":\"Error\"}","slots":[]}

  at panic (eval at <anonymous> (eval at makeEvaluateFactory (file:///Users/markmiller/src/ongithub/agoric/agoric-sdk/node_modules/ses/dist/ses.umd.js:3305:10)), <anonymous>:269:26)
  at doResolve (eval at <anonymous> (eval at makeEvaluateFactory (file:///Users/markmiller/src/ongithub/agoric/agoric-sdk/node_modules/ses/dist/ses.umd.js:3305:10)), <anonymous>:319:9)
  at resolve (eval at <anonymous> (eval at makeEvaluateFactory (file:///Users/markmiller/src/ongithub/agoric/agoric-sdk/node_modules/ses/dist/ses.umd.js:3305:10)), <anonymous>:254:5)
  at Object.doKernelSyscall (eval at <anonymous> (eval at makeEvaluateFactory (file:///Users/markmiller/src/ongithub/agoric/agoric-sdk/node_modules/ses/dist/ses.umd.js:3305:10)), <anonymous>:295:16)
  at vatSyscallHandler (eval at <anonymous> (eval at makeEvaluateFactory (file:///Users/markmiller/src/ongithub/agoric/agoric-sdk/node_modules/ses/dist/ses.umd.js:3305:10)), <anonymous>:911:39)
  at Object.syscallFromWorker (eval at <anonymous> (eval at makeEvaluateFactory (file:///Users/markmiller/src/ongithub/agoric/agoric-sdk/node_modules/ses/dist/ses.umd.js:3305:10)), <anonymous>:251:18)
  at handleUpstream (eval at <anonymous> (eval at makeEvaluateFactory (file:///Users/markmiller/src/ongithub/agoric/agoric-sdk/node_modules/ses/dist/ses.umd.js:3305:10)), <anonymous>:88:23)
  at handleCommand (eval at <anonymous> (eval at makeEvaluateFactory (file:///Users/markmiller/src/ongithub/agoric/agoric-sdk/node_modules/ses/dist/ses.umd.js:3305:10)), <anonymous>:110:22)
  at runToIdle (packages/xsnap/src/xsnap.js:197:42)
  at runMicrotasks (<anonymous>)


/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:3235: exception: throw!
/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:10561: exception: throw!
/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:10561: exception: throw!
/Users/markmiller/src/ongithub/agoric/agoric-sdk/packages/SwingSet/src/kernel/vatManager/lockdown-subprocess-xsnap.js:10575: exception: throw!
  setup

  Rejected promise returned by test. Reason:

  1



  teardown

  Rejected promise returned by test. Reason:

  Error {
    code: 'EPERM',
    errno: -1,
    syscall: 'kill',
    message: 'kill EPERM',
  }

  › kill (packages/solo/test/captp-fixture.js:125:13)
  › packages/solo/test/test-home.js:184:9

  ─

  2 hooks failed
error Command failed with exit code 1.
info Visit https://yarnpkg.com/en/docs/cli/run for documentation about this command.
(1):solo(markm-use-want-patterns)$ 
@erights erights added the bug Something isn't working label Dec 28, 2021
@warner
Copy link
Member

warner commented Dec 28, 2021

The underlying bug turned out to be that we were right at the edge of exhausting the contract vat's initial meter. @erights 's changes increased the meter consumption slightly, but just enough to cross the limit and exhaust the vat's meter before zoe had a chance to refill it.

The initial batch of deliveries to a new ZCF vat contains a large executeContract() delivery followed by about 4 or 5 notify deliveries, the last of which causes more work than the others.

packages/vats/src/bootstrap.js is setting Zoe's metering_config.initial value to 50M. With this setting, Zoe will create a meters with 50M computrons, then pass it to createDynamicVat.

When the new ZCF vat starts, the first delivery is an executeContract, which takes a lot of cycles. Without @erights 's changes, the particular contract being loaded into v20 took 47740267 computrons. The arguments to executeContract include three promises which are already resolved, so there are dispatch.notify deliveries that arrive immediately. The first two notifies don't cause much work (about 15k computrons), but the third requires more: 1778963. After each delivery we also get a small dispatch.bringOutYourDead which needs about 15k each. The total usage is 49594812 computrons, which is above the 25M notification threshold but below the 50M initial meter capacity. After the first executeContract delivery, the kernel queues a message to the vatAdmin vat, to trigger the meter-threshold Notifier. When delivered, this causes vatAdmin to resolve the Notifier's promise, which queues a notify to Zoe. When Zoe receives this, Zoe sends a message to vatAdmin to refill the meter. When this message is received by vatAdmin, it uses its device access to update the meter's value.

The sequence of operations is:

  • ZCF runs executeContract, consumes 47_740_267 computrons
    • kernel deducts meter, remaining is 2_259_733, this is less than 25M so kernel queues vatAdmin message
  • ZCF runs first bringOutYourDead
  • ZCF runs notify, second bringOutYourDead, another notify, another bringOutYourDead, last notify, last bringOutYourDead
    • meter is now down to 405_188
  • vatAdmin gets message, queues notify to zoe
  • zoe sees notifier fire, queues meter.addRemaining(25M) to vatAdmin
  • vatAdmin gets message, increments meter
    • meter increased to 25_405_188

However, @erights 's additions increase the computron usage by just enough to cross over the 50M threshold. The initial executeContract takes 48_015_116 computrons (an extra 274_899, about 0.6% more), and the third notify takes 1_999_972 (an extra 221_009, an extra 12.4%). The total is 50_090_670, which exhausts the 50M of the meter before Zoe has a chance to react. This time, the sequence is:

  • ZCF runs executeContract
    • kernel deducts meter, remaining is below 25M so kernel queues vatAdmin message
  • ZCF runs first bringOutYourDead
  • ZCF runs notify, second bringOutYourDead, another notify, another bringOutYourDead, last notify
    • meter underflows
    • kernel terminates vat
  • vatAdmin gets message, queues notify to zoe
  • zoe sees notifier fire, queues meter.addRemaining(25M) to vatAdmin
  • vatAdmin gets message, increments meter
    • too late, vat is dead, meter is no longer in use

So the immediate fix is to change packages/vats/src/bootstrap.js and increase the meteringConfig.initial from 50_000_00n to more like 100_000_000n.

The medium fix is that we need some sort of CI to tell us how close we are to exhausting the initial meter. We should have learned months ago that the ZCF executeContract on this particular contract was within 1% of underflow. (It's possible that this particular contract is fairly complex, I don't know what contract it is, but it shouldn't matter). We need a report for all our standard contracts to tell us

  • 1: how long they take to load
  • 2: how many computrons are needed for the first few deliveries
  • 3: and probably how large their bundle files are, in bytes

The longer-term fix is some deep thinking about the purpose of metering, especially during contract startup, and how we figure out what a "reasonable" amount it. We don't want the initial meter capacity to be large enough to allow denial-of-service during contract startup, however it's not at all surprising that startup takes more CPU time than later messages, especially the initial large eval/importBundle.

@kriskowal
Copy link
Member

Labeled as SwingSet, @warner please take a look. We’re uncertain what’s next for this issue.

@warner warner changed the title Just a transcript we'd like to make easier to debug. meter overrun (was: just a transcript we'd like to make easier to debug) May 4, 2022
@warner
Copy link
Member

warner commented May 5, 2022

Currently we do not enforce a meter on any vats: static vats are not metered, and Zoe no longer provides a Meter object on the dynamic vat it creates for each contract. That's a quick-and-dirty way to avoid the meter overrun observed in this ticket.

Specifically, Zoe does not assign a MeterID to any of the dynamic vats it creates for contracts, so the vat-loader creates managerOptions with metered: false, which means startXSnap() is called with metered: false, so it provides meteringLimit: 0 to doXSnap(), which overrides the default DEFAULT_CRANK_METERING_LIMIT (currently 100M computrons) with 0, which is falsy so xsnap is invoked without a -l ${meteringLimit} argument, so xsnap.c does not set gxMeteringLimit, so it retains its default value of 0 and interval is not changed from its default value of 0, which means fxBeginMetering() sets the->meterInterval = 0, which means mxCheckMeter() never calls fxCheckMetering(), which effectively disables the per-delivery meter: we count computrons and report back a total at the end of delivery, but we won't interrupt the delivery if the count exceeds a threshold.

That means swingset currently only provides one level to control vat metering. If E(vatAdmin).createVat() is given a meter: Meter option, it will enable the per-delivery limit (100M computrons) and also decrement the Meter object with each delivery (so you must refill the meter periodically).

I'm hearing folks say that this isn't good: we should still be able to catch runaway vats, even if we're not yet trying to charge for usage (or limit cumulative usage). Currently, if you want a per-delivery limit but don't want to be pestered with refills, you can use meter = await E(vatAdmin).makeUnlimitedMeter(), in which case xsnap will do all the usual metering work, but our Meter will skip the decrement at the end of each delivery. We could make this easier by providing two createVat options: a meter: Meter for the cumulative one, and a deliveryLimit: to set the per-delivery limit, like in #3527.

But that returns us to the question raised above: what should that per-delivery limit be? And what should happen if it is exceeded? I'm not convinced that applying a per-delivery limit would help us for MN-1, where we don't have a lot of new contracts. In this timeframe, all contracts are a critical part of the economy, so I think we'd rather have the entire kernel halt than terminate a single vat (since vat termination deletes all of its state, which is a lot harder to recover from). One interesting option would be to halt swingset, but leave the cosmos side running so it could manage a governance vote to decide on a fix (#4516), but we'd need to implement that (and be confident that it wouldn't enable more problems or attacks) before it made sense to turn on vat-threatening delivery limits.

I've opened #5295 to track the task of automated measurements of contract CPU usage and bundle size, which would inform our limit decisions.

I've opened #5296 to track the question of what we should do if an MN-1 contract vat exceeds the per-delivery limit.

I'm going to close this one now: we've identified the problem and have two more-specific tickets to manage the new questions.

@warner warner closed this as completed May 5, 2022
@dckc dckc added the duplicate label May 27, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working duplicate SwingSet package: SwingSet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants