Server that facilitates communication between hosted Agents and a Host's Holochain Conductor
Holo hosting container and CLI
See https://hackmd.io/qLBM-1K7S1GNbPuBsoSsag for design thoughts
See PR 129
I see this error happen fairly frequently. Not sure what it is or what it does.
Feb 25 14:36:36 hpos holo-envoy[9825]: 2021-02-25T14:36:36.495Z [ index.js ] DEBUG: App Info Call spec details for installed_app_id ( uhCkkDP7aytnEKH7BqkPXc9FnkHx3xm_cU0pUGWlsHNht4d4TG5mU )
Feb 25 14:36:36 hpos holo-envoy[9825]: 2021-02-25T14:36:36.495Z [ index.js ] SILLY: Calling Conductor method (appInfo) over client 'app' with input {"installed_app_id":"uhCkkDP7aytnEKH7BqkPXc9FnkHx3xm_cU0pUGWlsHNht4d4TG5mU"}:
Feb 25 14:36:36 hpos holo-envoy[9825]: 2021-02-25T14:36:36.496Z [ index.js ] DEBUG: Successful app interface response: {"installed_app_id":"uhCkkDP7aytnEKH7BqkPXc9FnkHx3xm_cU0pUGWlsHNht4d4TG5mU","cell_data":[[[{"type":"Buffer","data":[132,45,36,189,224,81,149,254,17,189,207,158,51,133,18,85,64,4,97,45,164,158,7,37,171,8,150,14,11,18,105,68,220,181,134,180,220,173,84]},{"type":"Buffer","data":[132,32,36,205,172,20,61,200,233,4,70,198,110,52,115,87,156,146,110,63,5,83,158,56,154,255,149,198,216,60,52,251,171,252,223,192,247,208,19]}],"elemental-chat"]]}
Feb 25 14:36:36 hpos holo-envoy[9825]: 2021-02-25T14:36:36.496Z [ index.js ] NORMA: Conductor call returned successful 'object' response: {"installed_app_id":"uhCkkDP7aytnEKH7BqkPXc9FnkHx3xm_cU0pUGWlsHNht4d4TG5mU","cell_data":[[[{"type":"Buffer","data":[132,45,36,189,224,81,149,254,17,189,207,158,51,133,18,85,64,4,97,45,164,158,7,37,171,8,150,14,11,18,105,68,220,181,134,180,220,173,84]},{"type":"Buffer","data":[132,32,36,205,172,20,61,200,233,4,70,198,110,52,115,87,156,146,110,63,5,83,158,56,154,255,149,198,216,60,52,251,171,252,223,192,247,208,19]}],"elemental-chat"]]}
Feb 25 14:36:36 hpos holo-envoy[9825]: (node:9825) UnhandledPromiseRejectionWarning: Error: Unexpected buffer length of 39. Buffer should be 32 bytes.
Feb 25 14:36:36 hpos holo-envoy[9825]: at Object.encode (/nix/store/74vpkcbqv97hz1j66sih9xdkixkf2gvz-holo-envoy/node_modules/@holo-host/cryptolib/src/index.js:115:17)
Feb 25 14:36:36 hpos holo-envoy[9825]: at Object.encode (/nix/store/74vpkcbqv97hz1j66sih9xdkixkf2gvz-holo-envoy/node_modules/@holo-host/cryptolib/src/index.js:82:37)
Feb 25 14:36:36 hpos holo-envoy[9825]: at /nix/store/74vpkcbqv97hz1j66sih9xdkixkf2gvz-holo-envoy/build/index.js:1147:77
Feb 25 14:36:36 hpos holo-envoy[9825]: at Array.forEach (<anonymous>)
Feb 25 14:36:36 hpos holo-envoy[9825]: at Envoy.<anonymous> (/nix/store/74vpkcbqv97hz1j66sih9xdkixkf2gvz-holo-envoy/build/index.js:1146:43)
Feb 25 14:36:36 hpos holo-envoy[9825]: at step (/nix/store/74vpkcbqv97hz1j66sih9xdkixkf2gvz-holo-envoy/build/index.js:57:23)
Feb 25 14:36:36 hpos holo-envoy[9825]: at Object.next (/nix/store/74vpkcbqv97hz1j66sih9xdkixkf2gvz-holo-envoy/build/index.js:38:53)
Feb 25 14:36:36 hpos holo-envoy[9825]: at fulfilled (/nix/store/74vpkcbqv97hz1j66sih9xdkixkf2gvz-holo-envoy/build/index.js:29:58)
Feb 25 14:36:36 hpos holo-envoy[9825]: at runMicrotasks (<anonymous>)
Feb 25 14:36:36 hpos holo-envoy[9825]: at processTicksAndRejections (internal/process/task_queues.js:97:5)
Feb 25 14:36:36 hpos holo-envoy[9825]: (node:9825) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 19)
Feb 25 14:38:08 hpos holo-envoy[9825]: 2021-02-25T14:38:08.874Z [ index.js ] SILLY: Incoming connection from /hosting/?anonymous=true&agent_id=uhCAkuC7UVIDFPGF8VK4e8oralJQcWplC9qeE6fjU5yuiF_8H5WnI&hha_hash=uhCkkDP7aytnEKH7BqkPXc9FnkHx3xm_cU0pUGWlsHNht4d4TG5mU
Feb 25 14:38:09 hpos holo-envoy[9825]: 2021-02-25T14:38:08.875Z [ index.js ] NORMA: Anonymous (uhCAkuC7UVIDFPGF8VK4e8oralJQcWplC9qeE6fjU5yuiF_8H5WnI) connection for HHA ID: uhCkkDP7aytnEKH7BqkPXc9FnkHx3xm_cU0pUGWlsHNht4d4TG5mU
Feb 25 14:38:09 hpos holo-envoy[9825]: 2021-02-25T14:38:08.875Z [ index.js ] DEBUG: Adding Agent uhCAkuC7UVIDFPGF8VK4e8oralJQcWplC9qeE6fjU5yuiF_8H5WnI to anonymous list with HHA ID uhCkkDP7aytnEKH7BqkPXc9FnkHx3xm_cU0pUGWlsHNht4d4TG5mU
Feb 25 14:38:09 hpos holo-envoy[9825]: 2021-02-25T14:38:08.875Z [ index.js ] INFO: Retrieve the hosted app cell_data using the anonymous installed_app_id: 'uhCkkDP7aytnEKH7BqkPXc9FnkHx3xm_cU0pUGWlsHNht4d4TG5mU'
Feb 25 14:38:09 hpos holo-envoy[9825]: 2021-02-25T14:38:08.875Z [ index.js ] NORMA: Received request to call Conductor using client 'app' with call spec of type 'object'
Feb 25 14:38:09 hpos holo-envoy[9825]: 2021-02-25T14:38:08.875Z [ index.js ] DEBUG: App Info Call spec details for installed_app_id ( uhCkkDP7aytnEKH7BqkPXc9FnkHx3xm_cU0pUGWlsHNht4d4TG5mU )
Feb 25 14:38:09 hpos holo-envoy[9825]: 2021-02-25T14:38:08.875Z [ index.js ] SILLY: Calling Conductor method (appInfo) over client 'app' with input {"installed_app_id":"uhCkkDP7aytnEKH7BqkPXc9FnkHx3xm_cU0pUGWlsHNht4d4TG5mU"}:
Feb 25 14:38:09 hpos holo-envoy[9825]: 2021-02-25T14:38:08.876Z [ index.js ] DEBUG: Successful app interface response: {"installed_app_id":"uhCkkDP7aytnEKH7BqkPXc9FnkHx3xm_cU0pUGWlsHNht4d4TG5mU","cell_data":[[[{"type":"Buffer","data":[132,45,36,189,224,81,149,254,17,189,207,158,51,133,18,85,64,4,97,45,164,158,7,37,171,8,150,14,11,18,105,68,220,181,134,180,220,173,84]},{"type":"Buffer","data":[132,32,36,205,172,20,61,200,233,4,70,198,110,52,115,87,156,146,110,63,5,83,158,56,154,255,149,198,216,60,52,251,171,252,223,192,247,208,19]}],"elemental-chat"]]}
Feb 25 14:38:09 hpos holo-envoy[9825]: 2021-02-25T14:38:08.877Z [ index.js ] NORMA: Conductor call returned successful 'object' response: {"installed_app_id":"uhCkkDP7aytnEKH7BqkPXc9FnkHx3xm_cU0pUGWlsHNht4d4TG5mU","cell_data":[[[{"type":"Buffer","data":[132,45,36,189,224,81,149,254,17,189,207,158,51,133,18,85,64,4,97,45,164,158,7,37,171,8,150,14,11,18,105,68,220,181,134,180,220,173,84]},{"type":"Buffer","data":[132,32,36,205,172,20,61,200,233,4,70,198,110,52,115,87,156,146,110,63,5,83,158,56,154,255,149,198,216,60,52,251,171,252,223,192,247,208,19]}],"elemental-chat"]]}
Feb 25 14:38:09 hpos holo-envoy[9825]: (node:9825) UnhandledPromiseRejectionWarning: Error: Unexpected buffer length of 39. Buffer should be 32 bytes.
Feb 25 14:38:09 hpos holo-envoy[9825]: at Object.encode (/nix/store/74vpkcbqv97hz1j66sih9xdkixkf2gvz-holo-envoy/node_modules/@holo-host/cryptolib/src/index.js:115:17)
Feb 25 14:38:09 hpos holo-envoy[9825]: at Object.encode (/nix/store/74vpkcbqv97hz1j66sih9xdkixkf2gvz-holo-envoy/node_modules/@holo-host/cryptolib/src/index.js:82:37)
Feb 25 14:38:09 hpos holo-envoy[9825]: at /nix/store/74vpkcbqv97hz1j66sih9xdkixkf2gvz-holo-envoy/build/index.js:1147:77
Feb 25 14:38:09 hpos holo-envoy[9825]: at Array.forEach (<anonymous>)
Feb 25 14:38:09 hpos holo-envoy[9825]: at Envoy.<anonymous> (/nix/store/74vpkcbqv97hz1j66sih9xdkixkf2gvz-holo-envoy/build/index.js:1146:43)
Feb 25 14:38:09 hpos holo-envoy[9825]: at step (/nix/store/74vpkcbqv97hz1j66sih9xdkixkf2gvz-holo-envoy/build/index.js:57:23)
Feb 25 14:38:09 hpos holo-envoy[9825]: at Object.next (/nix/store/74vpkcbqv97hz1j66sih9xdkixkf2gvz-holo-envoy/build/index.js:38:53)
Feb 25 14:38:09 hpos holo-envoy[9825]: at fulfilled (/nix/store/74vpkcbqv97hz1j66sih9xdkixkf2gvz-holo-envoy/build/index.js:29:58)
Feb 25 14:38:09 hpos holo-envoy[9825]: at runMicrotasks (<anonymous>)
Feb 25 14:38:09 hpos holo-envoy[9825]: at processTicksAndRejections (internal/process/task_queues.js:97:5)
Feb 25 14:38:09 hpos holo-envoy[9825]: (node:9825) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 20)
I tried to sign in and got this error:
Feb 25 16:10:36 hpos holo-envoy[777]: 2021-02-25T16:10:36.603Z [ index.js ] SILLY: Calling Conductor method (activateApp) over client 'admin' with input {"installed_app_id":"uhCkkDP7aytnEKH7BqkPXc9FnkHx3xm_cU0pUGWlsHNht4d4TG5mU:uhCAkLO9HVKq1Y4Y2G8PcuUNpWAq_PHkUMzolKCqaCuYz9iZmm8SY"}:
Feb 25 16:10:36 hpos holo-envoy[777]: CONDUCTOR CALL ERROR:
Feb 25 16:10:36 hpos holo-envoy[777]: {
Feb 25 16:10:36 hpos holo-envoy[777]: type: 'error',
Feb 25 16:10:36 hpos holo-envoy[777]: data: {
Feb 25 16:10:36 hpos holo-envoy[777]: type: 'internal_error',
Feb 25 16:10:36 hpos holo-envoy[777]: data: 'Conductor returned an error while using a ConductorApi: AppNotInstalled("uhCkkDP7aytnEKH7BqkPXc9FnkHx3xm_cU0pUGWlsHNht4d4TG5mU:uhCAkLO9HVKq1Y4Y2G8PcuUNpWAq_PHkUMzolKCqaCuYz9iZmm8SY")'
Feb 25 16:10:36 hpos holo-envoy[777]: }
Feb 25 16:10:36 hpos holo-envoy[777]: }
Feb 25 16:10:36 hpos holo-envoy[777]: 2021-02-25T16:10:36.604Z [ index.js ] ERROR: Failed during Conductor call with error: Error: CONDUCTOR CALL ERROR: {"type":"error","data":{"type":"internal_error","data":"Conductor returned an error while using a ConductorApi: AppNotInstalled(\"uhCkkDP7aytnEKH7BqkPXc9FnkHx3xm_cU0pUGWlsHNht4d4TG5mU:uhCAkLO9HVKq1Y4Y2G8PcuUNpWAq_PHkUMzolKCqaCuYz9iZmm8SY\")"}}
Feb 25 16:10:36 hpos holo-envoy[777]: 2021-02-25T16:10:36.605Z [ index.js ] ERROR: Failed during 'activateApp': HoloError: Error: CONDUCTOR CALL ERROR: {"type":"error","data":{"type":"internal_error","data":"Conductor returned an error while using a ConductorApi: AppNotInstalled(\"uhCkkDP7aytnEKH7BqkPXc9FnkHx3xm_cU0pUGWlsHNht4d4TG5mU:uhCAkLO9HVKq1Y4Y2G8PcuUNpWAq_PHkUMzolKCqaCuYz9iZmm8SY\")"}}
hc-state shows that this hApp is installed and active:
[root@hpos:~]# hc-state -a
Connecting to holochain
Successfully connected to admin interface on port 4444
Active App Ids:
[
'core-happs:alpha10:0001',
'elemental-chat:alpha19:develop',
'servicelogger:alpha4:0001',
'uhCkkDP7aytnEKH7BqkPXc9FnkHx3xm_cU0pUGWlsHNht4d4TG5mU::servicelogger',
'uhCkkDP7aytnEKH7BqkPXc9FnkHx3xm_cU0pUGWlsHNht4d4TG5mU',
'uhCkkDP7aytnEKH7BqkPXc9FnkHx3xm_cU0pUGWlsHNht4d4TG5mU:uhCAkY_gzsJDV_MhBVmGyt-bvqx-nOPOrH38rgPoBiWnVF7y4bvkr',
'uhCkkDP7aytnEKH7BqkPXc9FnkHx3xm_cU0pUGWlsHNht4d4TG5mU:uhCAkLO9HVKq1Y4Y2G8PcuUNpWAq_PHkUMzolKCqaCuYz9iZmm8SY'
]
when we make a holo/service/confirm from chaperone it returns
{code: -32000, message: "TypeError", data: "Cannot read property 'agent_id' of undefined"}
These are the logs from envoy when we see this error:
I have consistently reproduced this issue on 2 machines across several wipes.
I can create as many channels as I want and the first message sent in any channel works. However, the second message ALWAYS fails at this point:
// verify message for channel does not already exist
const messageExists = !!appChannel.messages.find(
m => message.message.uuid === m.message.uuid
);
if (messageExists) return;
It fails because the zome call fails. Holo-envoy reports this error:
Feb 23 13:23:26 hpos holo-envoy[764]: 2021-02-23T13:23:26.871Z [ index.js ] DEBUG: Calling zome function chat->create_message( last_seen : object, channel : object, message : object, [object Object] ) on cell_id ([{"type":"Buffer","data":[132,45,36,134,132,81,150,23,141,201,221,142,171,216,171,67,117,29,49,119,79,79,100,240,184,56,3,226,17,87,255,180,239,7,124,33,112,8,182]},{"type":"Buffer","data":[132,32,36,68,187,222,147,93,88,144,178,234,152,70,225,248,171,70,255,206,232,183,26,137,66,204,176,165,228,162,31,165,197,102,255,84,49,62,126]}]), cap token (null), and provenance (uhCAkRLvek11YkLLqmEbh-KtG_87otxqJQsywpeSiH6XFZv9UMT5-):
Feb 23 13:23:26 hpos holo-envoy[764]: 2021-02-23T13:23:26.872Z [ index.js ] NORMA: Received request to call Conductor using client 'app' with call spec of type 'object'
Feb 23 13:23:26 hpos holo-envoy[764]: 2021-02-23T13:23:26.873Z [ index.js ] DEBUG:
Feb 23 13:23:26 hpos holo-envoy[764]: Zome Call spec details - called with cap token (null), provenance ({"type":"Buffer","data":[132,32,36,68,187,222,147,93,88,144,178,234,152,70,225,248,171,70,255,206,232,183,26,137,66,204,176,165,228,162,31,165,197,102,255,84,49,62,126]}), cell_id([{"type":"Buffer","data":[132,45,36,134,132,81,150,23,141,201,221,142,171,216,171,67,117,29,49,119,79,79,100,240,184,56,3,226,17,87,255,180,239,7,124,33,112,8,182]},{"type":"Buffer","data":[132,32,36,68,187,222,147,93,88,144,178,234,152,70,225,248,171,70,255,206,232,183,26,137,66,204,176,165,228,162,31,165,197,102,255,84,49,62,126]}]), and zome fn call: chat->create_message( {"last_seen":{"Message":{"type":"Buffer","data":[132,33,36,212,212,42,18,128,129,2,124,235,54,16,213,194,162,48,158,53,156,15,240,142,185,215,243,144,114,41,170,194,20,223,249,150,115,9,133]}},"channel":{"category":"General","uuid":"eaab39c7-19fc-4f99-9956-e299ed9e8e55"},"message":{"uuid":"c03f0e45-3b11-42d3-8476-3b15a4a7acf1","content":"ALASTAIR - 2:\n \nSending a message"},"chunk":0} )
Feb 23 13:23:26 hpos holo-envoy[764]: 2021-02-23T13:23:26.873Z [ index.js ] SILLY: Calling Conductor method (callZome) over client 'app' with input {"cell_id":[{"type":"Buffer","data":[132,45,36,134,132,81,150,23,141,201,221,142,171,216,171,67,117,29,49,119,79,79,100,240,184,56,3,226,17,87,255,180,239,7,124,33,112,8,182]},{"type":"Buffer","data":[132,32,36,68,187,222,147,93,88,144,178,234,152,70,225,248,171,70,255,206,232,183,26,137,66,204,176,165,228,162,31,165,197,102,255,84,49,62,126]}],"zome_name":"chat","fn_name":"create_message","payload":{"last_seen":{"Message":{"type":"Buffer","data":[132,33,36,212,212,42,18,128,129,2,124,235,54,16,213,194,162,48,158,53,156,15,240,142,185,215,243,144,114,41,170,194,20,223,249,150,115,9,133]}},"channel":{"category":"General","uuid":"eaab39c7-19fc-4f99-9956-e299ed9e8e55"},"message":{"uuid":"c03f0e45-3b11-42d3-8476-3b15a4a7acf1","content":"ALASTAIR - 2:\n \nSending a message"},"chunk":0},"cap":null,"provenance":{"type":"Buffer","data":[132,32,36,68,187,222,147,93,88,144,178,234,152,70,225,248,171,70,255,206,232,183,26,137,66,204,176,165,228,162,31,165,197,102,255,84,49,62,126]}}:
Feb 23 13:23:26 hpos holo-envoy[764]: CONDUCTOR CALL ERROR:
Feb 23 13:23:26 hpos holo-envoy[764]: {
Feb 23 13:23:26 hpos holo-envoy[764]: type: 'error',
Feb 23 13:23:26 hpos holo-envoy[764]: data: {
Feb 23 13:23:26 hpos holo-envoy[764]: type: 'ribosome_error',
Feb 23 13:23:26 hpos holo-envoy[764]: data: 'Wasm error while working with Ribosome: Zome("failed to deserialize args: FromBytes(\\"invalid type: map, expected a HoloHash of primitive hash_type\\")")'
Feb 23 13:23:26 hpos holo-envoy[764]: }
Feb 23 13:23:26 hpos holo-envoy[764]: }
Feb 23 13:23:26 hpos holo-envoy[764]: 2021-02-23T13:23:26.876Z [ index.js ] ERROR: Failed during Conductor call with error: Error: CONDUCTOR CALL ERROR: {"type":"error","data":{"type":"ribosome_error","data":"Wasm error while working with Ribosome: Zome(\"failed to deserialize args: FromBytes(\\\"invalid type: map, expected a HoloHash of primitive hash_type\\\")\")"}}
This is not true if two people publish the exact same happ. In that case there are two HHA hashes which both have the same DNA hash.
Lines 1209 to 1231 in 898ad4b
Conductor needs to be run as a subprocess in our node.js integration tests to avoid manually running Conductor.
Instructions for running integration tests are in CONTRIBUTING.md.
Current implementation needs us to pass {} when we need to pass null.
This needs to be fixed in web-sdk and holo-envoy.
I am regularly seeing chain rollback errors pop up in my logs. They don't seem to cause any issue with sign up / sign in / etc.
My suspicion is that it is to do with the anonymous agent. This is because:
hc-state -aMar 03 10:10:26 hpos holochain[1131]: There were 1 headers at this position
Mar 03 10:10:26 hpos holochain[1131]: Mar 03 10:10:26.086 ERROR holochain::core::sys_validate: Chain rollback detected at position 3 for agent AgentPubKey(uhCAksay2eopfcVj2U7mnHEe9InpBBOTUIxD8WAzyZ80_80bdM56R) from header Create(Create { author: AgentPubKey(uhCAksay2eopfcVj2U7mnHEe9InpBBOTUIxD8WAzyZ80_80bdM56R), timestamp: Timestamp(1614745001, 194574565), header_seq: 3, prev_header: HeaderHash(uhCkkElxXkcG2b6fU69tysR5CxFj7VGWcQX2uMDbK48cyyXPHurCr), entry_type: CapGrant, entry_hash: EntryHash(uhCEk9fojkNNyIPdxVMbbny-1dwEv84oQtj6eZ4BXKE-8BT3jNPO0) })
Mar 03 10:10:26 hpos holochain[1131]: There were 1 headers at this position
Mar 03 10:10:26 hpos holochain[1131]: Mar 03 10:10:26.086 ERROR holochain::core::sys_validate: Chain rollback detected at position 0 for agent AgentPubKey(uhCAktgCnzGS77yTuL0gZYBH4F1s_y32o6o9hILrkWDjUua50pEVT) from header Dna(Dna { author: AgentPubKey(uhCAktgCnzGS77yTuL0gZYBH4F1s_y32o6o9hILrkWDjUua50pEVT), timestamp: Timestamp(1614744294, 26714277), hash: DnaHash(uhC0kveBRlf4Rvc-eM4USVUAEYS2kngclqwiWDgsSaUTctYa03K1U) })
Mar 03 10:10:26 hpos holochain[1131]: There were 1 headers at this position
Mar 03 10:10:26 hpos holochain[1131]: Mar 03 10:10:26.086 ERROR holochain::core::sys_validate: Chain rollback detected at position 1 for agent AgentPubKey(uhCAktgCnzGS77yTuL0gZYBH4F1s_y32o6o9hILrkWDjUua50pEVT) from header AgentValidationPkg(AgentValidationPkg { author: AgentPubKey(uhCAktgCnzGS77yTuL0gZYBH4F1s_y32o6o9hILrkWDjUua50pEVT), timestamp: Timestamp(1614744294, 241873823), header_seq: 1, prev_header: HeaderHash(uhCkkInVInSAbc1bBn1WMPDXRd2EQFirx3UExyn_JY9bcBhHjUlsn), membrane_proof: None })
Currently while passing Buffers and UInt8Arrays over json-rpc changes the type into an object as mentioned bellow
For Buffers
{ type: "Buffer", data: [120, 32, 45] }or For Uint8Arrays
{"0": 120, "1": 32, "2": 45}This causes an issues when sending a zomeCall that expects a HoloHash/Uint8Array: #73
Holochain Conductor seems to restart the WebSocket server every time an interface is updated. This causes the RPC WebSocket ready state to be momentarily closed. Currently, we are avoiding this issue by awaiting the open state for every request (https://github.com/Holo-Host/holo-envoy/blob/2020-01-22-vm-integration/src/index.ts#L603). We can handle this more explicitly by detecting the close event and only waiting for open if it was closed.
Writing my uncollected thoughts here.
I think we have some kind of circular dependency issue going on.
Envoy starts before holochain. It fails to connect per the logs below, and then for some reason it says it's all normal.
Feb 19 11:17:49 hpos holo-envoy[3784]: Starting Envoy server...
Feb 19 11:17:49 hpos holo-envoy[3784]: 2021-02-19T11:17:49.355Z [ index.js ] SILLY: Initializing Envoy with input: {"NS":"/hosting/"}
Feb 19 11:17:49 hpos holo-envoy[3784]: 2021-02-19T11:17:49.357Z [ index.js ] NORMA: Initializing with port (4656) and namespace (/hosting/)
Feb 19 11:17:49 hpos holo-envoy[3784]: 2021-02-19T11:17:49.363Z [ wss.js ] INFO: RPC WebSocket server 0.0.0.0:4656 >> Starting RPC WebSocket server on port 4656
Feb 19 11:17:49 hpos holo-envoy[3784]: 2021-02-19T11:17:49.363Z [ wss.js ] DEBUG: RPC WebSocket server 0.0.0.0:4656 >> Registering method 'holo/wormhole/event' in namespace: /hosting/
Feb 19 11:17:49 hpos holo-envoy[3784]: 2021-02-19T11:17:49.363Z [ wss.js ] DEBUG: RPC WebSocket server 0.0.0.0:4656 >> Registering method 'holo/wormhole/response' in namespace: /hosting/
Feb 19 11:17:49 hpos holo-envoy[3784]: 2021-02-19T11:17:49.363Z [ wss.js ] DEBUG: RPC WebSocket server 0.0.0.0:4656 >> Registering method 'holo/agent/signup' in namespace: /hosting/
Feb 19 11:17:49 hpos holo-envoy[3784]: 2021-02-19T11:17:49.364Z [ wss.js ] DEBUG: RPC WebSocket server 0.0.0.0:4656 >> Registering method 'holo/app_info' in namespace: /hosting/
Feb 19 11:17:49 hpos holo-envoy[3784]: 2021-02-19T11:17:49.364Z [ wss.js ] DEBUG: RPC WebSocket server 0.0.0.0:4656 >> Registering method 'holo/call' in namespace: /hosting/
Feb 19 11:17:49 hpos holo-envoy[3784]: 2021-02-19T11:17:49.364Z [ wss.js ] DEBUG: RPC WebSocket server 0.0.0.0:4656 >> Registering method 'holo/service/confirm' in namespace: /hosting/
Feb 19 11:17:49 hpos holo-envoy[3784]: 2021-02-19T11:17:49.364Z [ shim.js ] NORMA: init wormhole
Feb 19 11:17:49 hpos holo-envoy[3784]: Server has started on port: 4656
Feb 19 11:17:49 hpos holo-envoy[3784]: Error while trying to set hcc_clients: Error: could not connect to holochain conductor, please check that a conductor service is running and available at ws://localhost:4444
Feb 19 11:17:49 hpos holo-envoy[3784]: 2021-02-19T11:17:49.370Z [ index.js ] NORMA: All Conductor clients are in a 'CONNECTED' state
At the same time Holochain fails to start, because it can't find lair shim socket that envoy is supposed to create
Feb 19 11:17:49 hpos systemd[1]: Started holochain.service.
Feb 19 11:17:49 hpos holochain[3800]: Feb 19 11:17:49.198 ERROR lair_keystore_client: error=IpcClientConnectError("/var/lib/holochain-rsm/lair-shim/socket", Os { code: 2, kind: NotFound, message: "No such file or directory" }) file="/build/holochain-vendor.tar.gz/lair_keystore_client/src/lib.rs" line=42
Feb 19 11:17:49 hpos holochain[3800]: Feb 19 11:17:49.199 ERROR lair_keystore_client: error=Other(Os { code: 2, kind: NotFound, message: "No such file or directory" }) file="/build/holochain-vendor.tar.gz/lair_keystore_client/src/lib.rs" line=49
Feb 19 11:17:49 hpos holochain[3800]: Feb 19 11:17:49.199 ERROR lair_keystore_client: error=Other(Os { code: 2, kind: NotFound, message: "No such file or directory" }) file="/build/holochain-vendor.tar.gz/lair_keystore_client/src/lib.rs" line=62
Feb 19 11:17:49 hpos holochain[3800]: Well, this is embarrassing.
Feb 15 15:36:08 hpos holo-envoy[2622]: 2021-02-15T15:36:08.455Z [ index.js ] SILLY: Incoming connection from /hosting/?anonymous=false&agent_id=uhCAkScPKvx9er32h47HowR5tGHLs2mAcZbWTvLbuP_tNfeGS5QeF&hha_hash=uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt
Feb 15 15:36:08 hpos holo-envoy[2622]: 2021-02-15T15:36:08.455Z [ index.js ] NORMA: Agent (uhCAkScPKvx9er32h47HowR5tGHLs2mAcZbWTvLbuP_tNfeGS5QeF) connection for HHA ID: uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt
Feb 15 15:36:08 hpos holo-envoy[2622]: 2021-02-15T15:36:08.664Z [ index.js ] SILLY: Incoming websocket message: {"jsonrpc":"2.0","method":"rpc.on","params":["signal"],"id":1}
Feb 15 15:36:08 hpos holo-envoy[2622]: 2021-02-15T15:36:08.776Z [ index.js ] SILLY: Incoming websocket message: {"jsonrpc":"2.0","method":"holo/wormhole/event","params":["uhCAkScPKvx9er32h47HowR5tGHLs2mAcZbWTvLbuP_tNfeGS5QeF"],"id":2}
Feb 15 15:36:08 hpos holo-envoy[2622]: 2021-02-15T15:36:08.777Z [ index.js ] NORMA: Initializing wormhole setup for Agent (uhCAkScPKvx9er32h47HowR5tGHLs2mAcZbWTvLbuP_tNfeGS5QeF)
Feb 15 15:36:08 hpos holo-envoy[2622]: 2021-02-15T15:36:08.777Z [ index.js ] DEBUG: Registering RPC WebSocket event (uhCAkScPKvx9er32h47HowR5tGHLs2mAcZbWTvLbuP_tNfeGS5QeF/wormhole/request) in namespace: /hosting/
Feb 15 15:36:08 hpos holo-envoy[2622]: 2021-02-15T15:36:08.986Z [ index.js ] SILLY: Incoming websocket message: {"jsonrpc":"2.0","method":"rpc.on","params":["uhCAkScPKvx9er32h47HowR5tGHLs2mAcZbWTvLbuP_tNfeGS5QeF/wormhole/request"],"id":3}
Feb 15 15:36:09 hpos holo-envoy[2622]: 2021-02-15T15:36:09.203Z [ index.js ] SILLY: Incoming websocket message: {"jsonrpc":"2.0","method":"holo/agent/signup","params":["uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt","uhCAkScPKvx9er32h47HowR5tGHLs2mAcZbWTvLbuP_tNfeGS5QeF"],"id":4}
Feb 15 15:36:09 hpos holo-envoy[2622]: 2021-02-15T15:36:09.205Z [ index.js ] NORMA: Received sign-up request from Agent (uhCAkScPKvx9er32h47HowR5tGHLs2mAcZbWTvLbuP_tNfeGS5QeF) for HHA ID: uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt
Feb 15 15:36:09 hpos holo-envoy[2622]: 2021-02-15T15:36:09.205Z [ index.js ] INFO: Retrieve the hosted app cell_data using the anonymous installed_app_id: 'uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt'
Feb 15 15:36:09 hpos holo-envoy[2622]: 2021-02-15T15:36:09.205Z [ index.js ] NORMA: Received request to call Conductor using client 'app' with call spec of type 'object'
Feb 15 15:36:09 hpos holo-envoy[2622]: 2021-02-15T15:36:09.206Z [ index.js ] DEBUG: App Info Call spec details for installed_app_id ( uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt )
Feb 15 15:36:09 hpos holo-envoy[2622]: 2021-02-15T15:36:09.206Z [ index.js ] SILLY: Calling Conductor method (appInfo) over client 'app' with input {"installed_app_id":"uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt"}:
Feb 15 15:36:09 hpos holo-envoy[2622]: 2021-02-15T15:36:09.208Z [ index.js ] DEBUG: Successful app interface response: {"installed_app_id":"uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt","cell_data":[[[{"type":"Buffer","data":[132,45,36,134,132,81,150,23,141,201,221,142,171,216,171,67,117,29,49,119,79,79,100,240,184,56,3,226,17,87,255,180,239,7,124,33,112,8,182]},{"type":"Buffer","data":[132,32,36,191,255,210,30,157,220,104,62,123,187,247,226,31,148,132,109,156,98,177,107,55,114,197,40,150,106,117,22,220,143,124,163,140,13,73,11]}],"elemental-chat"]]}
Feb 15 15:36:09 hpos holo-envoy[2622]: 2021-02-15T15:36:09.208Z [ index.js ] NORMA: Conductor call returned successful 'object' response: {"installed_app_id":"uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt","cell_data":[[[{"type":"Buffer","data":[132,45,36,134,132,81,150,23,141,201,221,142,171,216,171,67,117,29,49,119,79,79,100,240,184,56,3,226,17,87,255,180,239,7,124,33,112,8,182]},{"type":"Buffer","data":[132,32,36,191,255,210,30,157,220,104,62,123,187,247,226,31,148,132,109,156,98,177,107,55,114,197,40,150,106,117,22,220,143,124,163,140,13,73,11]}],"elemental-chat"]]}
Feb 15 15:36:09 hpos holo-envoy[2622]: 2021-02-15T15:36:09.208Z [ index.js ] SILLY: NUMBER OF DNAs in the hosted happ:
Feb 15 15:36:09 hpos holo-envoy[2622]: 2021-02-15T15:36:09.208Z [ index.js ] SILLY: AppInfo on sign-up:
Feb 15 15:36:09 hpos holo-envoy[2622]: 2021-02-15T15:36:09.208Z [ index.js ] SILLY: Hosted App Cell Data: [[[{"type":"Buffer","data":[132,45,36,134,132,81,150,23,141,201,221,142,171,216,171,67,117,29,49,119,79,79,100,240,184,56,3,226,17,87,255,180,239,7,124,33,112,8,182]},{"type":"Buffer","data":[132,32,36,191,255,210,30,157,220,104,62,123,187,247,226,31,148,132,109,156,98,177,107,55,114,197,40,150,106,117,22,220,143,124,163,140,13,73,11]}],"elemental-chat"]]
Feb 15 15:36:09 hpos holo-envoy[2622]: 2021-02-15T15:36:09.208Z [ index.js ] INFO: Found 1 DNA(s) for the app bundle with HHA ID: uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt
Feb 15 15:36:09 hpos holo-envoy[2622]: 2021-02-15T15:36:09.209Z [ index.js ] INFO: Encoded Agent ID (uhCAkScPKvx9er32h47HowR5tGHLs2mAcZbWTvLbuP_tNfeGS5QeF) into buffer form: {"type":"Buffer","data":[132,32,36,73,195,202,191,31,94,175,125,161,227,177,232,193,30,109,24,114,236,218,96,28,101,181,147,188,182,238,63,251,77,125,225,146,229,7,133]}
Feb 15 15:36:09 hpos holo-envoy[2622]: 2021-02-15T15:36:09.209Z [ index.js ] INFO: Installing App with HHA ID (uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt) as Installed App ID (uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt:uhCAkScPKvx9er32h47HowR5tGHLs2mAcZbWTvLbuP_tNfeGS5QeF)
Feb 15 15:36:09 hpos holo-envoy[2622]: 2021-02-15T15:36:09.209Z [ index.js ] DEBUG: installedDnas : [{"nick":"elemental-chat","hash":{"type":"Buffer","data":[132,45,36,134,132,81,150,23,141,201,221,142,171,216,171,67,117,29,49,119,79,79,100,240,184,56,3,226,17,87,255,180,239,7,124,33,112,8,182]}}]
Feb 15 15:36:09 hpos holo-envoy[2622]: 2021-02-15T15:36:09.209Z [ index.js ] NORMA: Received request to call Conductor using client 'admin' with call spec of type 'string'
Feb 15 15:36:09 hpos holo-envoy[2622]: 2021-02-15T15:36:09.209Z [ index.js ] DEBUG: Admin Call spec payload: ( installed_app_id : string, agent_key : object, dnas : object )
Feb 15 15:36:09 hpos holo-envoy[2622]: 2021-02-15T15:36:09.209Z [ index.js ] SILLY: Calling Conductor method (installApp) over client 'admin' with input {"installed_app_id":"uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt:uhCAkScPKvx9er32h47HowR5tGHLs2mAcZbWTvLbuP_tNfeGS5QeF","agent_key":{"type":"Buffer","data":[132,32,36,73,195,202,191,31,94,175,125,161,227,177,232,193,30,109,24,114,236,218,96,28,101,181,147,188,182,238,63,251,77,125,225,146,229,7,133]},"dnas":[{"nick":"elemental-chat","hash":{"type":"Buffer","data":[132,45,36,134,132,81,150,23,141,201,221,142,171,216,171,67,117,29,49,119,79,79,100,240,184,56,3,226,17,87,255,180,239,7,124,33,112,8,182]}}]}:
Feb 15 15:36:09 hpos holo-envoy[2622]: 2021-02-15T15:36:09.210Z [ index.js ] ERROR: Failed during Conductor call with error: Error: CONDUCTOR CALL ERROR: [object Object]
Feb 15 15:36:09 hpos holo-envoy[2622]: 2021-02-15T15:36:09.211Z [ index.js ] ERROR: Failed during 'installApp': HoloError: Error: CONDUCTOR CALL ERROR: [object Object]
Feb 15 15:36:09 hpos holo-envoy[2622]: 2021-02-15T15:36:09.211Z [ index.js ] ERROR: Failed during DNA processing for Agent (uhCAkScPKvx9er32h47HowR5tGHLs2mAcZbWTvLbuP_tNfeGS5QeF) HHA ID (uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt): HoloError: Error: CONDUCTOR CALL ERROR: [object Object]
Feb 15 15:36:09 hpos holo-envoy[2622]: 2021-02-15T15:36:09.211Z [ index.js ] ERROR: Failed during sign-up process for Agent (uhCAkScPKvx9er32h47HowR5tGHLs2mAcZbWTvLbuP_tNfeGS5QeF) HHA ID (uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt): {"name":"HoloError","message":"Failed to create a new hosted agent"}
Feb 15 15:36:09 hpos holo-envoy[2622]: 2021-02-15T15:36:09.429Z [ index.js ] NORMA: Socket is closing for Agent (uhCAkScPKvx9er32h47HowR5tGHLs2mAcZbWTvLbuP_tNfeGS5QeF) using HHA ID uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt
Feb 25 17:49:18 hpos holo-envoy[779]: 2021-02-25T17:49:18.857Z [ index.js ] SILLY: Set service request from Agent (uhCAkcN1hfGir0VYJ8--tiozpPq0J_qcxE0p2xwxar_jeXlz5MwUE) with signature (1p3qAxZskqamUd/I85iTibmsWB4ECUEsBgnizXiasrfAjQO1d5FaFOKRwTyZhMREpMfjOeIqauoKrQDyeSg/DA==)
Feb 25 17:49:18 hpos holo-envoy[779]: {
Feb 25 17:49:18 hpos holo-envoy[779]: "agent_id": "uhCAkcN1hfGir0VYJ8--tiozpPq0J_qcxE0p2xwxar_jeXlz5MwUE",
Feb 25 17:49:18 hpos holo-envoy[779]: "request": {
Feb 25 17:49:18 hpos holo-envoy[779]: "timestamp": [
Feb 25 17:49:18 hpos holo-envoy[779]: 1614275359,
Feb 25 17:49:18 hpos holo-envoy[779]: 0
Feb 25 17:49:18 hpos holo-envoy[779]: ],
Feb 25 17:49:18 hpos holo-envoy[779]: "host_id": "uhCAkXxc0B3nyfctiKW1jpzUULGyBlPzZV1IZBLe1-13HRUslUv_K",
Feb 25 17:49:18 hpos holo-envoy[779]: "call_spec": {
Feb 25 17:49:18 hpos holo-envoy[779]: "hha_hash": "uhCkkDP7aytnEKH7BqkPXc9FnkHx3xm_cU0pUGWlsHNht4d4TG5mU",
Feb 25 17:49:18 hpos holo-envoy[779]: "dna_alias": "elemental-chat",
Feb 25 17:49:18 hpos holo-envoy[779]: "zome": "chat",
Feb 25 17:49:18 hpos holo-envoy[779]: "function": "list_messages",
Feb 25 17:49:18 hpos holo-envoy[779]: "args_hash": "EoIBeyJhY3RpdmVfY2hhdHRlciI6dHJ1ZSwiY2hhbm5lbCI6eyJjYXRlZ29yeSI6IkdlbmVyYWwiLCJ1dWlkIjoiZDg0MGE2MjktNTk4Ny00ZTA1LTg3ZjAtMGI1YjQ4MzA1YWRjIn0sImNodW5rIjp7ImVuZCI6MCwic3RhcnQiOjB9fQ=="
Feb 25 17:49:18 hpos holo-envoy[779]: }
Feb 25 17:49:18 hpos holo-envoy[779]: },
Feb 25 17:49:18 hpos holo-envoy[779]: "request_signature": "1p3qAxZskqamUd/I85iTibmsWB4ECUEsBgnizXiasrfAjQO1d5FaFOKRwTyZhMREpMfjOeIqauoKrQDyeSg/DA=="
Feb 25 17:49:18 hpos holo-envoy[779]: }
Feb 25 17:49:18 hpos holo-envoy[779]: 2021-02-25T17:49:18.857Z [ index.js ] DEBUG: Calling zome function chat->list_messages( channel : object, chunk : object, active_chatter : boolean ) on cell_id ([{"type":"Buffer","data":[132,45,36,189,224,81,149,254,17,189,207,158,51,133,18,85,64,4,97,45,164,158,7,37,171,8,150,14,11,18,105,68,220,181,134,180,220,173,84]},{"type":"Buffer","data":[132,32,36,112,221,97,124,104,171,209,86,9,243,239,173,138,140,233,62,173,9,254,167,49,19,74,118,199,12,90,175,248,222,94,92,249,51,5,4]}]), cap token (null), and provenance (uhCAkcN1hfGir0VYJ8--tiozpPq0J_qcxE0p2xwxar_jeXlz5MwUE):
Feb 25 17:49:18 hpos holo-envoy[779]: 2021-02-25T17:49:18.858Z [ index.js ] ERROR: Failed during Conductor call: RangeError: Extra 2 of 3 byte(s) found at buffer[1]
Feb 25 17:49:18 hpos holo-envoy[779]: 2021-02-25T17:49:18.858Z [ index.js ] FATAL: Conductor call threw unknown error: RangeError: Extra 2 of 3 byte(s) found at buffer[1]
Feb 25 17:49:18 hpos holo-envoy[779]: RangeError: Extra 2 of 3 byte(s) found at buffer[1]
Feb 25 17:49:18 hpos holo-envoy[779]: at Decoder.createExtraByteError (/nix/store/74vpkcbqv97hz1j66sih9xdkixkf2gvz-holo-envoy/node_modules/@msgpack/msgpack/dist/Decoder.js:78:16)
Feb 25 17:49:18 hpos holo-envoy[779]: at Decoder.decode (/nix/store/74vpkcbqv97hz1j66sih9xdkixkf2gvz-holo-envoy/node_modules/@msgpack/msgpack/dist/Decoder.js:85:24)
Feb 25 17:49:18 hpos holo-envoy[779]: at Object.decode (/nix/store/74vpkcbqv97hz1j66sih9xdkixkf2gvz-holo-envoy/node_modules/@msgpack/msgpack/dist/decode.js:14:20)
Feb 25 17:49:18 hpos holo-envoy[779]: at Envoy.<anonymous> (/nix/store/74vpkcbqv97hz1j66sih9xdkixkf2gvz-holo-envoy/build/index.js:569:72)
Feb 25 17:49:18 hpos holo-envoy[779]: at step (/nix/store/74vpkcbqv97hz1j66sih9xdkixkf2gvz-holo-envoy/build/index.js:57:23)
Feb 25 17:49:18 hpos holo-envoy[779]: at Object.next (/nix/store/74vpkcbqv97hz1j66sih9xdkixkf2gvz-holo-envoy/build/index.js:38:53)
Feb 25 17:49:18 hpos holo-envoy[779]: at fulfilled (/nix/store/74vpkcbqv97hz1j66sih9xdkixkf2gvz-holo-envoy/build/index.js:29:58)
Feb 25 17:49:18 hpos holo-envoy[779]: at runMicrotasks (<anonymous>)
Feb 25 17:49:18 hpos holo-envoy[779]: at processTicksAndRejections (internal/process/task_queues.js:97:5)
Feb 25 17:49:18 hpos holo-envoy[779]: 2021-02-25T17:49:18.860Z [ wss.js ] ERROR: Handler 'holo/call' threw an error: TypeError: Value is required
Feb 25 17:49:34 hpos holo-envoy[779]: 2021-02-25T17:49:34.630Z [ index.js ] ERROR: Failed during signing request #78 with timeout (20000ms)
Seen in browser logs as:
Attached payload signature (yq2WS+oNx80k44yq7p3+mYw2XVUV4om7wrs6dgd+pxaPH0M/6f8HiwaQhc2D+aeE6wWTlUPBMSZd7NDESapoAg==) from Agent (uhCAkCX6GUmgSDXHqnQR1Mnj8S4tzWWisdKQGTJge20nTJHiyQvYv)
2.holo_hosting_chaperone.js:1 Sending request signature yq2WS+oNx80k44yq7p3+mYw2XVUV4om7wrs6dgd+pxaPH0M/6f8HiwaQhc2D+aeE6wWTlUPBMSZd7NDESapoAg== to Envoy
2.holo_hosting_chaperone.js:1 {code: -32000, message: "TypeError", data: "Value is required"}
elementalChat.js:13 1614276848204 "signalMessageSent zome done"
If any code fails before method is assigned the method would remain undefined. This code is quite messy and should be made less complicated. Once issue #14 is complete, we can depend on the client being resilient to past interruptions. Then this code should be restructured to also be more resilient.
PR #28 is a temporary fix that raises the first try/catch error.
https://github.com/Holo-Host/holo-envoy/blob/develop/src/index.ts#L690-L716
let method;
try {
if ( typeof client === "string" )
client = this.hcc_clients[ client ];
let ready_state = client.socket.readyState;
if ( ready_state !== 1 ) {
log.silly("Waiting for 'CONNECTED' state because current ready state is %s (%s)", ready_state, READY_STATES[ready_state] );
await client.opened();
}
// Assume the method is "call" unless `call_spec` is a string.
method = "call";
if ( typeof call_spec === "string" ) {
log.debug("Admin call spec details: %s( %s )", () => [
call_spec, Object.entries(args).map(([k,v]) => `${k} : ${typeof v}`).join(", ") ]);
method = call_spec;
}
else {
log.debug("Call spec details: %s::%s->%s( %s )", () => [
call_spec.instance_id, call_spec.zome, call_spec.function, Object.entries(call_spec.args).map(([k,v]) => `${k} : ${typeof v}`).join(", ") ]);
args = call_spec;
}
} catch ( err ) {
console.log("callConductor preamble threw", err );
throw new HoloError("callConductor preamble threw error: %s", String(err));
}This line hardcodes the database path as lmdb4, but this is incorrect in testing, and we occasionally bump it in production to wipe the database.
Line 7 in 1a128eb
Steps to reproduce:
With chaperone.holohost.dev running 2020-09-17-fix-retrieve-host-agent-key
testfuel.holo.host
Occasionally we receive this error that puts Chaperone in a failure state and requires UI refresh and sign up/in again
Mar 05 10:49:03 hpos holo-envoy[785]: CONDUCTOR CALL ERROR:
Mar 05 10:49:03 hpos holo-envoy[785]: {
Mar 05 10:49:03 hpos holo-envoy[785]: type: 'error',
Mar 05 10:49:03 hpos holo-envoy[785]: data: {
Mar 05 10:49:03 hpos holo-envoy[785]: type: 'zome_call_unauthorized',
Mar 05 10:49:03 hpos holo-envoy[785]: data: 'No capabilities grant has been committed that allows the CapSecret None to call the function list_channels in zome chat'
Mar 05 10:49:03 hpos holo-envoy[785]: }
Mar 05 10:49:03 hpos holo-envoy[785]: }
Mar 05 10:49:03 hpos holo-envoy[785]: 2021-03-05T10:49:03.272Z [ index.js ] ERROR: Failed during Conductor call with error: Error: CONDUCTOR CALL ERROR: {"type":"error","data":{"type":"zome_call_unauthorized","data":"No capabilities grant has been committed that allows the CapSecret None to call the function list_channels in zome chat"}}
Mar 05 10:49:03 hpos holo-envoy[785]: 2021-03-05T10:49:03.272Z [ index.js ] ERROR: Failed during Conductor call: HoloError: Error: CONDUCTOR CALL ERROR: {"type":"error","data":{"type":"zome_call_unauthorized","data":"No capabilities grant has been committed that allows the CapSecret None to call the function list_channels in zome chat"}}
Mar 05 10:49:03 hpos holo-envoy[785]: 2021-03-05T10:49:03.272Z [ index.js ] WARN: Setting error response to raised HoloError: HoloError: Error: CONDUCTOR CALL ERROR: {"type":"error","data":{"type":"zome_call_unauthorized","data":"No capabilities grant has been committed that allows the CapSecret None to call the function list_channels in zome chat"}}
Mar 05 10:49:03 hpos holo-envoy[785]: 2021-03-05T10:49:03.273Z [ index.js ] NORMA: Returning error:
Mar 05 10:49:35 hpos holo-envoy[785]: 2021-03-05T10:49:35.325Z [ index.js ] NORMA: Socket is closing for Agent (uhCAkrHIL5psIUFP0Ob-S9llpOD1-S7ZEhr4DOI3z-RcmtHLCbYFg) using HHA ID uhCkkihH-AGTAffws7BjuJx-aBviIFJw4zarV-KPy0Q8hI2aQDmMB
https://github.com/Holo-Host/holo-envoy/blob/2020-01-22-vm-integration/src/index.ts#L166-L169
const agent = agents.find( agent => agent.public_address === agent_id );
if ( agent === undefined ) {
return (new HoloError("Agent '%s' is unknown to this Host", agent_id )).toJSON();Identify (which is used to establish a wormhole subscription) needs to run before sign-up. However, it the check above requires the agent to already be signed-up to execute identify.
See logs below.
Also note that hosted agent is uhCAkScPKvx9er32h47HowR5tGHLs2mAcZbWTvLbuP_tNfeGS5QeF but at one point signature is requested for uhCAkGdlFEZ2ohJzdNlL74U2Ts3V1sRMxMgD6TyFUeOrw9Mim47BY which is a PREVIOUS hosted agent I tried to sign up with.
And at another point a signature request is made for agent uhCAkIfNjZMFKVjKJD90En1wtBBJipDUdlvqK1dC1mRx1RxowmN_1. I don't know who this is
Feb 13 10:27:54 hpos holo-envoy[757]: 2021-02-13T10:27:54.450Z [ index.js ] SILLY: Incoming connection from /hosting/?anonymous=false&agent_id=uhCAkScPKvx9er32h47HowR5tGHLs2mAcZbWTvLbuP_tNfeGS5QeF&hha_hash=uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt
Feb 13 10:27:54 hpos holo-envoy[757]: 2021-02-13T10:27:54.450Z [ index.js ] NORMA: Agent (uhCAkScPKvx9er32h47HowR5tGHLs2mAcZbWTvLbuP_tNfeGS5QeF) connection for HHA ID: uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt
Feb 13 10:27:54 hpos holo-envoy[757]: 2021-02-13T10:27:54.656Z [ index.js ] SILLY: Incoming websocket message: {"jsonrpc":"2.0","method":"rpc.on","params":["signal"],"id":1}
Feb 13 10:27:54 hpos holo-envoy[757]: 2021-02-13T10:27:54.656Z [ index.js ] SILLY: Incoming websocket message: {"jsonrpc":"2.0","method":"holo/wormhole/event","params":["uhCAkScPKvx9er32h47HowR5tGHLs2mAcZbWTvLbuP_tNfeGS5QeF"],"id":2}
Feb 13 10:27:54 hpos holo-envoy[757]: 2021-02-13T10:27:54.657Z [ index.js ] NORMA: Initializing wormhole setup for Agent (uhCAkScPKvx9er32h47HowR5tGHLs2mAcZbWTvLbuP_tNfeGS5QeF)
Feb 13 10:27:54 hpos holo-envoy[757]: 2021-02-13T10:27:54.657Z [ index.js ] DEBUG: Registering RPC WebSocket event (uhCAkScPKvx9er32h47HowR5tGHLs2mAcZbWTvLbuP_tNfeGS5QeF/wormhole/request) in namespace: /hosting/
Feb 13 10:27:54 hpos holo-envoy[757]: 2021-02-13T10:27:54.864Z [ index.js ] SILLY: Incoming websocket message: {"jsonrpc":"2.0","method":"rpc.on","params":["uhCAkScPKvx9er32h47HowR5tGHLs2mAcZbWTvLbuP_tNfeGS5QeF/wormhole/request"],"id":3}
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.069Z [ index.js ] SILLY: Incoming websocket message: {"jsonrpc":"2.0","method":"holo/agent/signup","params":["uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt","uhCAkScPKvx9er32h47HowR5tGHLs2mAcZbWTvLbuP_tNfeGS5QeF"],"id":4}
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.070Z [ index.js ] NORMA: Received sign-up request from Agent (uhCAkScPKvx9er32h47HowR5tGHLs2mAcZbWTvLbuP_tNfeGS5QeF) for HHA ID: uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.070Z [ index.js ] INFO: Retrieve the hosted app cell_data using the anonymous installed_app_id: 'uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt'
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.070Z [ index.js ] NORMA: Received request to call Conductor using client 'app' with call spec of type 'object'
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.071Z [ index.js ] DEBUG: App Info Call spec details for installed_app_id ( uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt )
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.071Z [ index.js ] SILLY: Calling Conductor method (appInfo) over client 'app' with input {"installed_app_id":"uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt"}:
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.072Z [ index.js ] DEBUG: Successful app interface response: {"installed_app_id":"uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt","cell_data":[[[{"type":"Buffer","data":[132,45,36,134,132,81,150,23,141,201,221,142,171,216,171,67,117,29,49,119,79,79,100,240,184,56,3,226,17,87,255,180,239,7,124,33,112,8,182]},{"type":"Buffer","data":[132,32,36,33,243,99,100,193,74,86,50,137,15,221,4,159,92,45,4,18,98,164,53,29,150,250,138,213,208,181,153,28,117,71,26,48,152,223,245]}],"elemental-chat"]]}
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.073Z [ index.js ] NORMA: Conductor call returned successful 'object' response: {"installed_app_id":"uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt","cell_data":[[[{"type":"Buffer","data":[132,45,36,134,132,81,150,23,141,201,221,142,171,216,171,67,117,29,49,119,79,79,100,240,184,56,3,226,17,87,255,180,239,7,124,33,112,8,182]},{"type":"Buffer","data":[132,32,36,33,243,99,100,193,74,86,50,137,15,221,4,159,92,45,4,18,98,164,53,29,150,250,138,213,208,181,153,28,117,71,26,48,152,223,245]}],"elemental-chat"]]}
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.073Z [ index.js ] SILLY: NUMBER OF DNAs in the hosted happ:
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.073Z [ index.js ] SILLY: AppInfo on sign-up:
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.073Z [ index.js ] SILLY: Hosted App Cell Data: [[[{"type":"Buffer","data":[132,45,36,134,132,81,150,23,141,201,221,142,171,216,171,67,117,29,49,119,79,79,100,240,184,56,3,226,17,87,255,180,239,7,124,33,112,8,182]},{"type":"Buffer","data":[132,32,36,33,243,99,100,193,74,86,50,137,15,221,4,159,92,45,4,18,98,164,53,29,150,250,138,213,208,181,153,28,117,71,26,48,152,223,245]}],"elemental-chat"]]
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.074Z [ index.js ] INFO: Found 1 DNA(s) for the app bundle with HHA ID: uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.074Z [ index.js ] INFO: Encoded Agent ID (uhCAkScPKvx9er32h47HowR5tGHLs2mAcZbWTvLbuP_tNfeGS5QeF) into buffer form: {"type":"Buffer","data":[132,32,36,73,195,202,191,31,94,175,125,161,227,177,232,193,30,109,24,114,236,218,96,28,101,181,147,188,182,238,63,251,77,125,225,146,229,7,133]}
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.074Z [ index.js ] INFO: Installing App with HHA ID (uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt) as Installed App ID (uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt:uhCAkScPKvx9er32h47HowR5tGHLs2mAcZbWTvLbuP_tNfeGS5QeF)
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.074Z [ index.js ] DEBUG: installedDnas : [{"nick":"elemental-chat","hash":{"type":"Buffer","data":[132,45,36,134,132,81,150,23,141,201,221,142,171,216,171,67,117,29,49,119,79,79,100,240,184,56,3,226,17,87,255,180,239,7,124,33,112,8,182]}}]
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.074Z [ index.js ] NORMA: Received request to call Conductor using client 'admin' with call spec of type 'string'
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.074Z [ index.js ] DEBUG: Admin Call spec payload: ( installed_app_id : string, agent_key : object, dnas : object )
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.075Z [ index.js ] SILLY: Calling Conductor method (installApp) over client 'admin' with input {"installed_app_id":"uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt:uhCAkScPKvx9er32h47HowR5tGHLs2mAcZbWTvLbuP_tNfeGS5QeF","agent_key":{"type":"Buffer","data":[132,32,36,73,195,202,191,31,94,175,125,161,227,177,232,193,30,109,24,114,236,218,96,28,101,181,147,188,182,238,63,251,77,125,225,146,229,7,133]},"dnas":[{"nick":"elemental-chat","hash":{"type":"Buffer","data":[132,45,36,134,132,81,150,23,141,201,221,142,171,216,171,67,117,29,49,119,79,79,100,240,184,56,3,226,17,87,255,180,239,7,124,33,112,8,182]}}]}:
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.076Z [ wormhole.j ] NORMA: Intercepted sign by public key
Feb 13 10:27:55 hpos holo-envoy[757]: Wormhole Signing Requested...
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.077Z [ index.js ] NORMA: Opening a request (#28) for Agent (uhCAkScPKvx9er32h47HowR5tGHLs2mAcZbWTvLbuP_tNfeGS5QeF) signature of payload: typeof '{"type":"Buffer","data":[132,164,116,121,112,101,163,68,110,97,166,97,117,116,104,111,114,196,39,132,32,36,73,195,202,191,31,94,175,125,161,227,177,232,193,30,109,24,114,236,218,96,28,101,181,147,188,182,238,63,251,77,125,225,146,229,7,133,169,116,105,109,101,115,116,97,109,112,146,206,96,39,169,171,206,4,131,201,159,164,104,97,115,104,196,39,132,45,36,134,132,81,150,23,141,201,221,142,171,216,171,67,117,29,49,119,79,79,100,240,184,56,3,226,17,87,255,180,239,7,124,33,112,8,182]}'
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.077Z [ index.js ] INFO: Adding signature request #28 to pending signatures
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.077Z [ index.js ] NORMA: Sent signing request #28 to Agent (uhCAkScPKvx9er32h47HowR5tGHLs2mAcZbWTvLbuP_tNfeGS5QeF)
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.284Z [ index.js ] SILLY: Incoming websocket message: {"jsonrpc":"2.0","method":"holo/wormhole/response","params":[28,"LuhQ/4FIG1qCQb50AOEbvJmRcXT2Pb5MiZwT6kVywIaE6luZv0YJpF8ndXWEv2iJqF8MCElj+Nasyg4xwukCDA=="],"id":5}
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.285Z [ index.js ] NORMA: Received signing response #28 with signature: LuhQ/4FIG1qCQb50AOEbvJmRcXT2Pb5MiZwT6kVywIaE6luZv0YJpF8ndXWEv2iJqF8MCElj+Nasyg4xwukCDA==
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.288Z [ wormhole.j ] NORMA: Intercepted sign by public key
Feb 13 10:27:55 hpos holo-envoy[757]: Wormhole Signing Requested...
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.290Z [ index.js ] NORMA: Opening a request (#29) for Agent (uhCAkScPKvx9er32h47HowR5tGHLs2mAcZbWTvLbuP_tNfeGS5QeF) signature of payload: typeof '{"type":"Buffer","data":[134,164,116,121,112,101,178,65,103,101,110,116,86,97,108,105,100,97,116,105,111,110,80,107,103,166,97,117,116,104,111,114,196,39,132,32,36,73,195,202,191,31,94,175,125,161,227,177,232,193,30,109,24,114,236,218,96,28,101,181,147,188,182,238,63,251,77,125,225,146,229,7,133,169,116,105,109,101,115,116,97,109,112,146,206,96,39,169,171,206,17,19,19,248,170,104,101,97,100,101,114,95,115,101,113,1,171,112,114,101,118,95,104,101,97,100,101,114,196,39,132,41,36,80,70,66,30,34,28,213,251,121,82,126,99,65,184,34,110,168,172,155,113,71,105,232,245,72,145,236,207,6,143,210,51,128,233,242,7,174,109,101,109,98,114,97,110,101,95,112,114,111,111,102,192]}'
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.293Z [ index.js ] INFO: Adding signature request #29 to pending signatures
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.294Z [ index.js ] NORMA: Sent signing request #29 to Agent (uhCAkScPKvx9er32h47HowR5tGHLs2mAcZbWTvLbuP_tNfeGS5QeF)
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.592Z [ index.js ] SILLY: Incoming websocket message: {"jsonrpc":"2.0","method":"holo/wormhole/response","params":[29,"nk8ToA12YeeC4/krwhB+LxcTYcldLrxADj1raDcNPsDYQ06pXfJt/IUP77uxNTL3SdrljcUr5AwenbunlnbBBw=="],"id":6}
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.593Z [ index.js ] NORMA: Received signing response #29 with signature: nk8ToA12YeeC4/krwhB+LxcTYcldLrxADj1raDcNPsDYQ06pXfJt/IUP77uxNTL3SdrljcUr5AwenbunlnbBBw==
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.599Z [ wormhole.j ] NORMA: Intercepted sign by public key
Feb 13 10:27:55 hpos holo-envoy[757]: Wormhole Signing Requested...
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.600Z [ index.js ] NORMA: Opening a request (#30) for Agent (uhCAkScPKvx9er32h47HowR5tGHLs2mAcZbWTvLbuP_tNfeGS5QeF) signature of payload: typeof '{"type":"Buffer","data":[135,164,116,121,112,101,166,67,114,101,97,116,101,166,97,117,116,104,111,114,196,39,132,32,36,73,195,202,191,31,94,175,125,161,227,177,232,193,30,109,24,114,236,218,96,28,101,181,147,188,182,238,63,251,77,125,225,146,229,7,133,169,116,105,109,101,115,116,97,109,112,146,206,96,39,169,171,206,35,165,21,241,170,104,101,97,100,101,114,95,115,101,113,2,171,112,114,101,118,95,104,101,97,100,101,114,196,39,132,41,36,48,182,156,228,8,129,50,157,97,247,144,140,176,125,170,210,11,125,48,133,56,62,154,75,177,234,205,132,46,245,144,240,9,55,177,205,170,101,110,116,114,121,95,116,121,112,101,129,171,65,103,101,110,116,80,117,98,75,101,121,192,170,101,110,116,114,121,95,104,97,115,104,196,39,132,33,36,73,195,202,191,31,94,175,125,161,227,177,232,193,30,109,24,114,236,218,96,28,101,181,147,188,182,238,63,251,77,125,225,146,229,7,133]}'
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.600Z [ index.js ] INFO: Adding signature request #30 to pending signatures
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.600Z [ index.js ] NORMA: Sent signing request #30 to Agent (uhCAkScPKvx9er32h47HowR5tGHLs2mAcZbWTvLbuP_tNfeGS5QeF)
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.901Z [ index.js ] SILLY: Incoming websocket message: {"jsonrpc":"2.0","method":"holo/wormhole/response","params":[30,"xIL18tdlgwcqTySq/4miGYX4g3ITv9MR2e67Rt+e9Dy9r8NaBbQcCeZWuQcnTkHZI5CS7Zpyouh7tflr7A3+DA=="],"id":7}
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.902Z [ index.js ] NORMA: Received signing response #30 with signature: xIL18tdlgwcqTySq/4miGYX4g3ITv9MR2e67Rt+e9Dy9r8NaBbQcCeZWuQcnTkHZI5CS7Zpyouh7tflr7A3+DA==
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.904Z [ index.js ] DEBUG: Successful admin interface response: {"installed_app_id":"uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt:uhCAkScPKvx9er32h47HowR5tGHLs2mAcZbWTvLbuP_tNfeGS5QeF","cell_data":[[[{"type":"Buffer","data":[132,45,36,134,132,81,150,23,141,201,221,142,171,216,171,67,117,29,49,119,79,79,100,240,184,56,3,226,17,87,255,180,239,7,124,33,112,8,182]},{"type":"Buffer","data":[132,32,36,73,195,202,191,31,94,175,125,161,227,177,232,193,30,109,24,114,236,218,96,28,101,181,147,188,182,238,63,251,77,125,225,146,229,7,133]}],"elemental-chat"]],"type":"success"}
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.905Z [ index.js ] NORMA: Conductor call returned successful 'object' response: {"installed_app_id":"uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt:uhCAkScPKvx9er32h47HowR5tGHLs2mAcZbWTvLbuP_tNfeGS5QeF","cell_data":[[[{"type":"Buffer","data":[132,45,36,134,132,81,150,23,141,201,221,142,171,216,171,67,117,29,49,119,79,79,100,240,184,56,3,226,17,87,255,180,239,7,124,33,112,8,182]},{"type":"Buffer","data":[132,32,36,73,195,202,191,31,94,175,125,161,227,177,232,193,30,109,24,114,236,218,96,28,101,181,147,188,182,238,63,251,77,125,225,146,229,7,133]}],"elemental-chat"]],"type":"success"}
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.905Z [ index.js ] INFO: Activating Installed App (uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt:uhCAkScPKvx9er32h47HowR5tGHLs2mAcZbWTvLbuP_tNfeGS5QeF)
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.906Z [ index.js ] NORMA: Received request to call Conductor using client 'admin' with call spec of type 'string'
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.906Z [ index.js ] DEBUG: Admin Call spec payload: ( installed_app_id : string )
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.906Z [ index.js ] SILLY: Calling Conductor method (activateApp) over client 'admin' with input {"installed_app_id":"uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt:uhCAkScPKvx9er32h47HowR5tGHLs2mAcZbWTvLbuP_tNfeGS5QeF"}:
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.910Z [ wormhole.j ] NORMA: Intercepted sign by public key
Feb 13 10:27:55 hpos holo-envoy[757]: Wormhole Signing Requested...
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.912Z [ index.js ] NORMA: Opening a request (#31) for Agent (uhCAkIfNjZMFKVjKJD90En1wtBBJipDUdlvqK1dC1mRx1RxowmN_1) signature of payload: typeof '{"type":"Buffer","data":[133,165,115,112,97,99,101,196,36,134,132,81,150,23,141,201,221,142,171,216,171,67,117,29,49,119,79,79,100,240,184,56,3,226,17,87,255,180,239,7,124,33,112,8,182,165,97,103,101,110,116,196,36,33,243,99,100,193,74,86,50,137,15,221,4,159,92,45,4,18,98,164,53,29,150,250,138,213,208,181,153,28,117,71,26,48,152,223,245,164,117,114,108,115,145,217,97,107,105,116,115,117,110,101,45,112,114,111,120,121,58,47,47,101,97,56,121,66,66,102,56,105,68,122,70,51,51,109,51,85,82,70,117,105,74,104,80,73,66,53,98,73,72,84,107,97,86,81,67,116,81,114,83,100,99,115,47,107,105,116,115,117,110,101,45,113,117,105,99,47,104,47,49,54,53,46,50,50,46,51,50,46,49,49,47,112,47,53,55,55,56,47,45,45,172,115,105,103,110,101,100,95,97,116,95,109,115,207,0,0,1,119,154,238,199,132,176,101,120,112,105,114,101,115,95,97,102,116,101,114,95,109,115,206,0,27,119,64]}'
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.912Z [ index.js ] WARN: Trying to get signature from unknown Agent (uhCAkIfNjZMFKVjKJD90En1wtBBJipDUdlvqK1dC1mRx1RxowmN_1)
Feb 13 10:27:55 hpos holo-envoy[757]: Agent uhCAkIfNjZMFKVjKJD90En1wtBBJipDUdlvqK1dC1mRx1RxowmN_1 is not registered. It must be a host call
Feb 13 10:27:55 hpos holo-envoy[757]: 2021-02-13T10:27:55.912Z [ wormhole.j ] NORMA: Forwarding message to Lair
Feb 13 10:27:56 hpos holo-envoy[757]: 2021-02-13T10:27:56.017Z [ wormhole.j ] NORMA: Intercepted sign by public key
Feb 13 10:27:56 hpos holo-envoy[757]: Wormhole Signing Requested...
Feb 13 10:27:56 hpos holo-envoy[757]: 2021-02-13T10:27:56.019Z [ index.js ] NORMA: Opening a request (#32) for Agent (uhCAkScPKvx9er32h47HowR5tGHLs2mAcZbWTvLbuP_tNfeGS5QeF) signature of payload: typeof '{"type":"Buffer","data":[133,165,115,112,97,99,101,196,36,134,132,81,150,23,141,201,221,142,171,216,171,67,117,29,49,119,79,79,100,240,184,56,3,226,17,87,255,180,239,7,124,33,112,8,182,165,97,103,101,110,116,196,36,73,195,202,191,31,94,175,125,161,227,177,232,193,30,109,24,114,236,218,96,28,101,181,147,188,182,238,63,251,77,125,225,146,229,7,133,164,117,114,108,115,145,217,97,107,105,116,115,117,110,101,45,112,114,111,120,121,58,47,47,101,97,56,121,66,66,102,56,105,68,122,70,51,51,109,51,85,82,70,117,105,74,104,80,73,66,53,98,73,72,84,107,97,86,81,67,116,81,114,83,100,99,115,47,107,105,116,115,117,110,101,45,113,117,105,99,47,104,47,49,54,53,46,50,50,46,51,50,46,49,49,47,112,47,53,55,55,56,47,45,45,172,115,105,103,110,101,100,95,97,116,95,109,115,207,0,0,1,119,154,238,199,239,176,101,120,112,105,114,101,115,95,97,102,116,101,114,95,109,115,206,0,27,119,64]}'
Feb 13 10:27:56 hpos holo-envoy[757]: 2021-02-13T10:27:56.019Z [ index.js ] INFO: Adding signature request #32 to pending signatures
Feb 13 10:27:56 hpos holo-envoy[757]: 2021-02-13T10:27:56.020Z [ index.js ] NORMA: Sent signing request #32 to Agent (uhCAkScPKvx9er32h47HowR5tGHLs2mAcZbWTvLbuP_tNfeGS5QeF)
Feb 13 10:27:56 hpos holo-envoy[757]: 2021-02-13T10:27:56.223Z [ index.js ] SILLY: Incoming websocket message: {"jsonrpc":"2.0","method":"holo/wormhole/response","params":[32,"UVhi2pe1BbPbPfonyw80A1oeUjjuUWYzGVaDrataEO3nkkZYX2/EZ3+0yonRngytz+6ZYdpf0IHE0rlqcj20DA=="],"id":8}
Feb 13 10:27:56 hpos holo-envoy[757]: 2021-02-13T10:27:56.224Z [ index.js ] NORMA: Received signing response #32 with signature: UVhi2pe1BbPbPfonyw80A1oeUjjuUWYzGVaDrataEO3nkkZYX2/EZ3+0yonRngytz+6ZYdpf0IHE0rlqcj20DA==
Feb 13 10:27:56 hpos holo-envoy[757]: 2021-02-13T10:27:56.318Z [ wormhole.j ] NORMA: Intercepted sign by public key
Feb 13 10:27:56 hpos holo-envoy[757]: Wormhole Signing Requested...
Feb 13 10:27:56 hpos holo-envoy[757]: 2021-02-13T10:27:56.319Z [ index.js ] NORMA: Opening a request (#33) for Agent (uhCAkGdlFEZ2ohJzdNlL74U2Ts3V1sRMxMgD6TyFUeOrw9Mim47BY) signature of payload: typeof '{"type":"Buffer","data":[133,165,115,112,97,99,101,196,36,134,132,81,150,23,141,201,221,142,171,216,171,67,117,29,49,119,79,79,100,240,184,56,3,226,17,87,255,180,239,7,124,33,112,8,182,165,97,103,101,110,116,196,36,25,217,69,17,157,168,132,156,221,54,82,251,225,77,147,179,117,117,177,19,49,50,0,250,79,33,84,120,234,240,244,200,166,227,176,88,164,117,114,108,115,145,217,97,107,105,116,115,117,110,101,45,112,114,111,120,121,58,47,47,101,97,56,121,66,66,102,56,105,68,122,70,51,51,109,51,85,82,70,117,105,74,104,80,73,66,53,98,73,72,84,107,97,86,81,67,116,81,114,83,100,99,115,47,107,105,116,115,117,110,101,45,113,117,105,99,47,104,47,49,54,53,46,50,50,46,51,50,46,49,49,47,112,47,53,55,55,56,47,45,45,172,115,105,103,110,101,100,95,97,116,95,109,115,207,0,0,1,119,154,238,201,27,176,101,120,112,105,114,101,115,95,97,102,116,101,114,95,109,115,206,0,27,119,64]}'
Feb 13 10:27:56 hpos holo-envoy[757]: 2021-02-13T10:27:56.320Z [ index.js ] INFO: Adding signature request #33 to pending signatures
Feb 13 10:27:56 hpos holo-envoy[757]: 2021-02-13T10:27:56.320Z [ index.js ] NORMA: Sent signing request #33 to Agent (uhCAkGdlFEZ2ohJzdNlL74U2Ts3V1sRMxMgD6TyFUeOrw9Mim47BY)
Feb 13 10:28:10 hpos holo-envoy[757]: 2021-02-13T10:28:10.922Z [ index.js ] ERROR: Failed during Conductor call with error: Error: CONDUCTOR CALL ERROR: {}
Feb 13 10:28:10 hpos holo-envoy[757]: 2021-02-13T10:28:10.922Z [ index.js ] ERROR: Failed during 'activateApp': HoloError: Error: CONDUCTOR CALL ERROR: {}
Feb 13 10:28:10 hpos holo-envoy[757]: 2021-02-13T10:28:10.923Z [ index.js ] ERROR: Failed during DNA processing for Agent (uhCAkScPKvx9er32h47HowR5tGHLs2mAcZbWTvLbuP_tNfeGS5QeF) HHA ID (uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt): HoloError: Error: CONDUCTOR CALL ERROR: {}
Feb 13 10:28:10 hpos holo-envoy[757]: 2021-02-13T10:28:10.923Z [ index.js ] ERROR: Failed during sign-up process for Agent (uhCAkScPKvx9er32h47HowR5tGHLs2mAcZbWTvLbuP_tNfeGS5QeF) HHA ID (uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt): {"name":"HoloError","message":"Failed to create a new hosted agent"}
Feb 13 10:28:11 hpos holo-envoy[757]: 2021-02-13T10:28:11.131Z [ index.js ] NORMA: Socket is closing for Agent (uhCAkScPKvx9er32h47HowR5tGHLs2mAcZbWTvLbuP_tNfeGS5QeF) using HHA ID uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt
See logs below
Feb 13 10:26:55 hpos holo-envoy[757]: 2021-02-13T10:26:55.662Z [ index.js ] NORMA: Received signing response #27 with signature: h8fMEZH6GbUoKhfiPooTVww7Blq2SrbxlVKtDUtMHJbaC6xIL7SPfajcxXLhYyYJNqeae0/pkdfvFkBFFhhIAg==
Feb 13 10:26:55 hpos holo-envoy[757]: 2021-02-13T10:26:55.743Z [ index.js ] DEBUG: Successful admin interface response: {"type":"success"}
Feb 13 10:26:55 hpos holo-envoy[757]: 2021-02-13T10:26:55.743Z [ index.js ] NORMA: Conductor call returned successful 'object' response: {"type":"success"}
Feb 13 10:26:55 hpos holo-envoy[757]: 2021-02-13T10:26:55.744Z [ index.js ] INFO: Starting installed-app (uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt:uhCAkGdlFEZ2ohJzdNlL74U2Ts3V1sRMxMgD6TyFUeOrw9Mim47BY) on port (42233)
Feb 13 10:26:55 hpos holo-envoy[757]: 2021-02-13T10:26:55.744Z [ index.js ] NORMA: Received request to call Conductor using client 'admin' with call spec of type 'string'
Feb 13 10:26:55 hpos holo-envoy[757]: 2021-02-13T10:26:55.744Z [ index.js ] DEBUG: Admin Call spec payload: ( port : number )
Feb 13 10:26:55 hpos holo-envoy[757]: 2021-02-13T10:26:55.745Z [ index.js ] SILLY: Calling Conductor method (attachAppInterface) over client 'admin' with input {"port":42233}:
Feb 13 10:26:55 hpos holo-envoy[757]: 2021-02-13T10:26:55.748Z [ index.js ] ERROR: Failed during Conductor call with error: Error: CONDUCTOR CALL ERROR: {"type":"error","data":{"type":"internal_error","data":"Conductor returned an error while using a ConductorApi: InterfaceError(IoTodo(Os { code: 98, kind: AddrInUse, message: \"Address already in use\" }))"}}
Feb 13 10:26:55 hpos holo-envoy[757]: 2021-02-13T10:26:55.748Z [ index.js ] ERROR: Failed during 'attachAppInterface': HoloError: Error: CONDUCTOR CALL ERROR: {"type":"error","data":{"type":"internal_error","data":"Conductor returned an error while using a ConductorApi: InterfaceError(IoTodo(Os { code: 98, kind: AddrInUse, message: \"Address already in use\" }))"}}
Feb 13 10:26:55 hpos holo-envoy[757]: 2021-02-13T10:26:55.748Z [ index.js ] ERROR: Failed during DNA processing for Agent (uhCAkGdlFEZ2ohJzdNlL74U2Ts3V1sRMxMgD6TyFUeOrw9Mim47BY) HHA ID (uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt): HoloError: Error: CONDUCTOR CALL ERROR: {"type":"error","data":{"type":"internal_error","data":"Conductor returned an error while using a ConductorApi: InterfaceError(IoTodo(Os { code: 98, kind: AddrInUse, message: \"Address already in use\" }))"}}
Feb 13 10:26:55 hpos holo-envoy[757]: 2021-02-13T10:26:55.749Z [ index.js ] ERROR: Failed during sign-up process for Agent (uhCAkGdlFEZ2ohJzdNlL74U2Ts3V1sRMxMgD6TyFUeOrw9Mim47BY) HHA ID (uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt): {"name":"HoloError","message":"Failed to create a new hosted agent"}
Currently, anyone can call the identify endpoint giving any agent ID. A malicious actor could use this information to discover an Agent's Hosts for targeted attacks. Hosts should only respond to identify requests if it is the Agent making the request.
Currently, service-logger will throw an error if the signature does not match which acts as authentication. Envoy should do this check explicitly rather than relying on service-logger.
Envoy works fine until it suddenly starts encountering lots of timeout issues. It may even freeze up (logs frozen). Once Envoy is in this state it requires restart / reboot. This seems to occur at any point - sign in, creating channels, posting messages, calling listChannel or listMessage, or logging out.
Mar 05 11:16:54 hpos holo-envoy[778]: CONDUCTOR CALL ERROR:
Mar 05 11:16:54 hpos holo-envoy[778]: Error: Timed out in 30000ms: zome_call_invocation
Mar 05 11:16:54 hpos holo-envoy[778]: at Timeout.<anonymous> (/nix/store/zyfrzxgpr7xc1n9hbgfx1yp9m5adjxwq-holo-envoy/node_modules/@holochain/conductor-api/lib/websocket/common.js:16:20)
Mar 05 11:16:54 hpos holo-envoy[778]: at listOnTimeout (internal/timers.js:549:17)
Mar 05 11:16:54 hpos holo-envoy[778]: at processTimers (internal/timers.js:492:7)
Mar 05 11:16:54 hpos holo-envoy[778]: 2021-03-05T11:16:54.172Z [ index.js ] ERROR: Failed during Conductor call with error: Error: CONDUCTOR CALL ERROR: {}
Mar 05 11:16:54 hpos holo-envoy[778]: 2021-03-05T11:16:54.172Z [ index.js ] ERROR: Failed during Conductor call: HoloError: Error: CONDUCTOR CALL ERROR: {}
Mar 05 11:16:54 hpos holo-envoy[778]: 2021-03-05T11:16:54.173Z [ index.js ] WARN: Setting error response to raised HoloError: HoloError: Error: CONDUCTOR CALL ERROR: {}
Mar 05 11:16:54 hpos holo-envoy[778]: 2021-03-05T11:16:54.173Z [ index.js ] NORMA: Returning error:
Mar 05 11:16:55 hpos holo-envoy[778]: CONDUCTOR CALL ERROR:
Mar 05 11:16:55 hpos holo-envoy[778]: Error: Timed out in 30000ms: zome_call_invocation
Mar 05 11:16:55 hpos holo-envoy[778]: at Timeout.<anonymous> (/nix/store/zyfrzxgpr7xc1n9hbgfx1yp9m5adjxwq-holo-envoy/node_modules/@holochain/conductor-api/lib/websocket/common.js:16:20)
Mar 05 11:16:55 hpos holo-envoy[778]: at listOnTimeout (internal/timers.js:549:17)
Mar 05 11:16:55 hpos holo-envoy[778]: at processTimers (internal/timers.js:492:7)
Mar 05 11:16:55 hpos holo-envoy[778]: 2021-03-05T11:16:55.291Z [ index.js ] ERROR: Failed during Conductor call with error: Error: CONDUCTOR CALL ERROR: {}
Mar 05 11:16:55 hpos holo-envoy[778]: 2021-03-05T11:16:55.292Z [ index.js ] ERROR: Failed during Conductor call: HoloError: Error: CONDUCTOR CALL ERROR: {}
Mar 05 11:16:55 hpos holo-envoy[778]: 2021-03-05T11:16:55.292Z [ index.js ] WARN: Setting error response to raised HoloError: HoloError: Error: CONDUCTOR CALL ERROR: {}
Mar 05 11:16:55 hpos holo-envoy[778]: 2021-03-05T11:16:55.292Z [ index.js ] NORMA: Returning error:
Mar 05 11:16:55 hpos holo-envoy[778]: 2021-03-05T11:16:55.427Z [ index.js ] SILLY: Incoming websocket message: {"jsonrpc":"2.0","method":"holo/call","params":{"anonymous":false,"agent_id":"uhCAkgXB14NzDbxZ-z8F0gfHmOJQrdhusPtsC0j7KlRk3bLpVOveU","payload":{"timestamp":[1614943015,0],"host_id":"uhCAkXxc0B3nyfctiKW1jpzUULGyBlPzZV1IZBLe1-13HRUslUv_K","call_spec":{"cell_id":[{"type":"Buffer","data":[132,45,36,10,149,226,187,233,242,168,78,37,152,67,31,92,91,23,176,197,130,14,114,252,7,217,186,242,46,62,179,32,31,241,113,75,34,87,170]},{"type":"Buffer",
During testing of hosted elemental chat, I got this issue. Was not able to reproduce it across 2 machines and 44 messages. Does not need to be investigated yet, but due to severity we should keep an eye out for it.
Feb 25 11:04:22 hpos holo-envoy[773]: CONDUCTOR CALL ERROR:
Feb 25 11:04:22 hpos holo-envoy[773]: {
Feb 25 11:04:22 hpos holo-envoy[773]: type: 'error',
Feb 25 11:04:22 hpos holo-envoy[773]: data: {
Feb 25 11:04:22 hpos holo-envoy[773]: type: 'internal_error',
Feb 25 11:04:22 hpos holo-envoy[773]: data: 'Conductor returned an error while using a ConductorApi: CellMissing(CellId(DnaHash(uhC0kveBRlf4Rvc-eM4USVUAEYS2kngclqwiWDgsSaUTctYa03K1U), AgentPubKey(uhCAkABvCWIfD4iT2lDooGFFdeh9jPts8s-wG9sH1v_dWS3jYNRhV)))'
Feb 25 11:04:22 hpos holo-envoy[773]: }
Feb 25 11:04:22 hpos holo-envoy[773]: }
Feb 25 11:04:22 hpos holo-envoy[773]: 2021-02-25T11:04:22.617Z [ index.js ] ERROR: Failed during Conductor call with error: Error: CONDUCTOR CALL ERROR: {"type":"error","data":{"type":"internal_error","data":"Conductor returned an error while using a ConductorApi: CellMissing(CellId(DnaHash(uhC0kveBRlf4Rvc-eM4USVUAEYS2kngclqwiWDgsSaUTctYa03K1U), AgentPubKey(uhCAkABvCWIfD4iT2lDooGFFdeh9jPts8s-wG9sH1v_dWS3jYNRhV)))"}}
Feb 25 11:04:22 hpos holo-envoy[773]: 2021-02-25T11:04:22.617Z [ index.js ] ERROR: Failed during Conductor call: HoloError: Error: CONDUCTOR CALL ERROR: {"type":"error","data":{"type":"internal_error","data":"Conductor returned an error while using a ConductorApi: CellMissing(CellId(DnaHash(uhC0kveBRlf4Rvc-eM4USVUAEYS2kngclqwiWDgsSaUTctYa03K1U), AgentPubKey(uhCAkABvCWIfD4iT2lDooGFFdeh9jPts8s-wG9sH1v_dWS3jYNRhV)))"}}
Feb 25 11:04:22 hpos holo-envoy[773]: 2021-02-25T11:04:22.618Z [ index.js ] WARN: Setting error response to raised HoloError: HoloError: Error: CONDUCTOR CALL ERROR: {"type":"error","data":{"type":"internal_error","data":"Conductor returned an error while using a ConductorApi: CellMissing(CellId(DnaHash(uhC0kveBRlf4Rvc-eM4USVUAEYS2kngclqwiWDgsSaUTctYa03K1U), AgentPubKey(uhCAkABvCWIfD4iT2lDooGFFdeh9jPts8s-wG9sH1v_dWS3jYNRhV)))"}}
Oct 02 14:21:48 hpos holo-envoy[626]: 2020-10-02T14:21:48.140Z [ client.js ] SILLY: Checking ready state for RPC WebSocket client (master): 3
Oct 02 14:21:48 hpos holo-envoy[626]: 2020-10-02T14:21:48.141Z [ client.js ] SILLY: Triggering timeout for 'master' because ready state is not 'CONNECTED' withing 60000ms
Oct 02 14:21:48 hpos holo-envoy[626]: 2020-10-02T14:21:48.141Z [ index.js ] FATAL: Conductor client 'master' failed to connect: undefined
Oct 02 14:21:48 hpos holo-envoy[626]: master undefined
Oct 02 14:21:48 hpos holo-envoy[626]: 2020-10-02T14:21:48.142Z [ index.js ] DEBUG: Conductor client 'master' is 'CONNECTED': readyState = 3
Oct 02 14:21:48 hpos holo-envoy[626]: 2020-10-02T14:21:48.142Z [ client.js ] SILLY: Checking ready state for RPC WebSocket client (service): 3
Oct 02 14:21:48 hpos holo-envoy[626]: 2020-10-02T14:21:48.142Z [ client.js ] SILLY: Triggering timeout for 'service' because ready state is not 'CONNECTED' withing 60000ms
Oct 02 14:21:48 hpos holo-envoy[626]: 2020-10-02T14:21:48.142Z [ index.js ] FATAL: Conductor client 'service' failed to connect: undefined
Oct 02 14:21:48 hpos holo-envoy[626]: service undefined
Oct 02 14:21:48 hpos holo-envoy[626]: 2020-10-02T14:21:48.143Z [ index.js ] DEBUG: Conductor client 'service' is 'CONNECTED': readyState = 3
Oct 02 14:21:48 hpos holo-envoy[626]: 2020-10-02T14:21:48.143Z [ client.js ] SILLY: Checking ready state for RPC WebSocket client (internal): 3
Oct 02 14:21:48 hpos holo-envoy[626]: 2020-10-02T14:21:48.143Z [ client.js ] SILLY: Triggering timeout for 'internal' because ready state is not 'CONNECTED' withing 60000ms
Oct 02 14:21:48 hpos holo-envoy[626]: 2020-10-02T14:21:48.143Z [ index.js ] FATAL: Conductor client 'internal' failed to connect: undefined
Oct 02 14:21:48 hpos holo-envoy[626]: internal undefined
Oct 02 14:21:48 hpos holo-envoy[626]: 2020-10-02T14:21:48.144Z [ index.js ] DEBUG: Conductor client 'internal' is 'CONNECTED': readyState = 3
Oct 02 14:21:48 hpos holo-envoy[626]: 2020-10-02T14:21:48.144Z [ client.js ] SILLY: Checking ready state for RPC WebSocket client (hosted): 3
Oct 02 14:21:48 hpos holo-envoy[626]: 2020-10-02T14:21:48.145Z [ client.js ] SILLY: Triggering timeout for 'hosted' because ready state is not 'CONNECTED' withing 60000ms
Oct 02 14:21:48 hpos holo-envoy[626]: 2020-10-02T14:21:48.146Z [ index.js ] FATAL: Conductor client 'hosted' failed to connect: undefined
Oct 02 14:21:48 hpos holo-envoy[626]: hosted undefined
Oct 02 14:21:48 hpos holo-envoy[626]: 2020-10-02T14:21:48.147Z [ index.js ] DEBUG: Conductor client 'hosted' is 'CONNECTED': readyState = 3
Oct 02 14:21:48 hpos holo-envoy[626]: 2020-10-02T14:21:48.147Z [ index.js ] NORMA: All Conductor clients are in a 'CONNECTED' state
Furthermore, Envoy logs that they are all connected after they all fail
whenever the zome calls fail due to an improper instance identifier (either due to an anonymous case or due to the issue of hosted instance being removed from the conductor upon restart), the calls to log the zome calls with servicelogger are still made
Holo-envoy cannot rebuild / update due to the issue below. Manually fixed by deleting /var/lib/holochain-rsm/ folder. Blocks upgrades
Feb 13 09:50:22 hpos holo-envoy[1954]: Starting Envoy server...
Feb 13 09:50:22 hpos holo-envoy[1954]: 2021-02-13T09:50:22.022Z [ index.js ] SILLY: Initializing Envoy with input: {"NS":"/hosting/"}
Feb 13 09:50:22 hpos holo-envoy[1954]: 2021-02-13T09:50:22.024Z [ index.js ] NORMA: Initializing with port (4656) and namespace (/hosting/)
Feb 13 09:50:22 hpos holo-envoy[1954]: 2021-02-13T09:50:22.029Z [ wss.js ] INFO: RPC WebSocket server 0.0.0.0:4656 >> Starting RPC WebSocket server on port 4656
Feb 13 09:50:22 hpos holo-envoy[1954]: 2021-02-13T09:50:22.030Z [ wss.js ] DEBUG: RPC WebSocket server 0.0.0.0:4656 >> Registering method 'holo/wormhole/event' in namespace: /hosting/
Feb 13 09:50:22 hpos holo-envoy[1954]: 2021-02-13T09:50:22.030Z [ wss.js ] DEBUG: RPC WebSocket server 0.0.0.0:4656 >> Registering method 'holo/wormhole/response' in namespace: /hosting/
Feb 13 09:50:22 hpos holo-envoy[1954]: 2021-02-13T09:50:22.030Z [ wss.js ] DEBUG: RPC WebSocket server 0.0.0.0:4656 >> Registering method 'holo/agent/signup' in namespace: /hosting/
Feb 13 09:50:22 hpos holo-envoy[1954]: 2021-02-13T09:50:22.030Z [ wss.js ] DEBUG: RPC WebSocket server 0.0.0.0:4656 >> Registering method 'holo/app_info' in namespace: /hosting/
Feb 13 09:50:22 hpos holo-envoy[1954]: 2021-02-13T09:50:22.030Z [ wss.js ] DEBUG: RPC WebSocket server 0.0.0.0:4656 >> Registering method 'holo/call' in namespace: /hosting/
Feb 13 09:50:22 hpos holo-envoy[1954]: 2021-02-13T09:50:22.030Z [ wss.js ] DEBUG: RPC WebSocket server 0.0.0.0:4656 >> Registering method 'holo/service/confirm' in namespace: /hosting/
Feb 13 09:50:22 hpos holo-envoy[1954]: 2021-02-13T09:50:22.030Z [ wormhole.j ] NORMA: init wormhole
Feb 13 09:50:22 hpos holo-envoy[1954]: Server has started on port: 4656
Feb 13 09:50:22 hpos holo-envoy[1954]: events.js:292
Feb 13 09:50:22 hpos holo-envoy[1954]: throw er; // Unhandled 'error' event
Feb 13 09:50:22 hpos holo-envoy[1954]: ^
Feb 13 09:50:22 hpos holo-envoy[1954]: Error: listen EADDRINUSE: address already in use /var/lib/holochain-rsm/lair-shim/socket
Feb 13 09:50:22 hpos holo-envoy[1954]: at Server.setupListenHandle [as _listen2] (net.js:1296:21)
Feb 13 09:50:22 hpos holo-envoy[1954]: at listenInCluster (net.js:1361:12)
Feb 13 09:50:22 hpos holo-envoy[1954]: at Server.listen (net.js:1458:5)
Feb 13 09:50:22 hpos holo-envoy[1954]: at Object.init (/nix/store/zw1fggksqxq03k1mnl5pd5sdxbfyrngb-holo-envoy/build/wormhole.js:57:8)
Feb 13 09:50:22 hpos holo-envoy[1954]: at Envoy.<anonymous> (/nix/store/zw1fggksqxq03k1mnl5pd5sdxbfyrngb-holo-envoy/build/index.js:158:60)
Feb 13 09:50:22 hpos holo-envoy[1954]: at step (/nix/store/zw1fggksqxq03k1mnl5pd5sdxbfyrngb-holo-envoy/build/index.js:46:23)
Feb 13 09:50:22 hpos holo-envoy[1954]: at Object.next (/nix/store/zw1fggksqxq03k1mnl5pd5sdxbfyrngb-holo-envoy/build/index.js:27:53)
Feb 13 09:50:22 hpos holo-envoy[1954]: at /nix/store/zw1fggksqxq03k1mnl5pd5sdxbfyrngb-holo-envoy/build/index.js:21:71
Feb 13 09:50:22 hpos holo-envoy[1954]: at new Promise (<anonymous>)
Feb 13 09:50:22 hpos holo-envoy[1954]: at __awaiter (/nix/store/zw1fggksqxq03k1mnl5pd5sdxbfyrngb-holo-envoy/build/index.js:17:12)
Feb 13 09:50:22 hpos holo-envoy[1954]: Emitted 'error' event on Server instance at:
Feb 13 09:50:22 hpos holo-envoy[1954]: at emitErrorNT (net.js:1340:8)
Feb 13 09:50:22 hpos holo-envoy[1954]: at processTicksAndRejections (internal/process/task_queues.js:84:21) {
Feb 13 09:50:22 hpos holo-envoy[1954]: code: 'EADDRINUSE',
Feb 13 09:50:22 hpos holo-envoy[1954]: errno: 'EADDRINUSE',
Feb 13 09:50:22 hpos holo-envoy[1954]: syscall: 'listen',
Feb 13 09:50:22 hpos holo-envoy[1954]: address: '/var/lib/holochain-rsm/lair-shim/socket',
Feb 13 09:50:22 hpos holo-envoy[1954]: port: -1
Feb 13 09:50:22 hpos holo-envoy[1954]: }
Feb 15 16:14:18 hpos holo-envoy[749]: 2021-02-15T16:14:18.780Z [ index.js ] NORMA: Completed sign-up process for Agent (uhCAkCQZSSO0xSbujgcpou0lIIGCDepyOSYYQOtoEhacH3I81OInc) HHA ID (uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt)
Feb 15 16:14:19 hpos holo-envoy[749]: 2021-02-15T16:14:19.698Z [ index.js ] SILLY: Incoming websocket message: {"jsonrpc":"2.0","method":"holo/app_info","params":{},"id":9}
Feb 15 16:14:19 hpos holo-envoy[749]: 2021-02-15T16:14:19.699Z [ index.js ] DEBUG: Calling AppInfo function with installed_app_id(undefined) :
Feb 15 16:14:19 hpos holo-envoy[749]: 2021-02-15T16:14:19.699Z [ index.js ] NORMA: Received request to call Conductor using client 'app' with call spec of type 'object'
Feb 15 16:14:19 hpos holo-envoy[749]: 2021-02-15T16:14:19.699Z [ index.js ] DEBUG:
Feb 15 16:14:19 hpos holo-envoy[749]: Zome Call spec details - called with cap token (undefined), provenance (undefined), cell_id(undefined), and zome fn call: undefined->undefined( undefined )
Feb 15 16:14:19 hpos holo-envoy[749]: 2021-02-15T16:14:19.700Z [ index.js ] SILLY: Calling Conductor method (callZome) over client 'app' with input {}:
Feb 15 16:14:19 hpos holo-envoy[749]: 2021-02-15T16:14:19.701Z [ index.js ] ERROR: Failed during Conductor call with error: Error: CONDUCTOR CALL ERROR: [object Object]
Feb 15 16:14:19 hpos holo-envoy[749]: 2021-02-15T16:14:19.701Z [ index.js ] ERROR: Failed during Conductor AppInfo call: HoloError: Error: CONDUCTOR CALL ERROR: [object Object]
Feb 15 16:14:59 hpos holo-envoy[749]: 2021-02-15T16:14:59.654Z [ index.js ] NORMA: Socket is closing for Agent (uhCAki5gC1cWnRbboeu9R30GzTxpeSckQ7NrbkKR7w5uW5k-WN27x) using HHA ID uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt
Feb 15 16:14:59 hpos holo-envoy[749]: 2021-02-15T16:14:59.654Z [ index.js ] DEBUG: Remove anonymous Agent (uhCAki5gC1cWnRbboeu9R30GzTxpeSckQ7NrbkKR7w5uW5k-WN27x) from anonymous list
Feb 15 16:15:49 hpos holo-envoy[749]: 2021-02-15T16:15:49.701Z [ index.js ] NORMA: Socket is closing for Agent (uhCAkCQZSSO0xSbujgcpou0lIIGCDepyOSYYQOtoEhacH3I81OInc) using HHA ID uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt
Browser Console error:
Unhandled Promise Rejection: HoloError: Identify Error: {"code":-32601,"message":"Method not found"}
Envoy logs:
Feb 15 16:27:43 hpos holo-envoy[749]: 2021-02-15T16:27:43.515Z [ index.js ] SILLY: Incoming connection from /hosting/?anonymous=false&agent_id=uhCAkCQZSSO0xSbujgcpou0lIIGCDepyOSYYQOtoEhacH3I81OInc&hha_hash=uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt
Feb 15 16:27:43 hpos holo-envoy[749]: 2021-02-15T16:27:43.516Z [ index.js ] NORMA: Agent (uhCAkCQZSSO0xSbujgcpou0lIIGCDepyOSYYQOtoEhacH3I81OInc) connection for HHA ID: uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt
Feb 15 16:27:43 hpos holo-envoy[749]: 2021-02-15T16:27:43.722Z [ index.js ] SILLY: Incoming websocket message: {"jsonrpc":"2.0","method":"rpc.on","params":["signal"],"id":1}
Feb 15 16:27:43 hpos holo-envoy[749]: 2021-02-15T16:27:43.825Z [ index.js ] SILLY: Incoming websocket message: {"jsonrpc":"2.0","method":"holo/wormhole/event","params":["uhCAkCQZSSO0xSbujgcpou0lIIGCDepyOSYYQOtoEhacH3I81OInc"],"id":2}
Feb 15 16:27:43 hpos holo-envoy[749]: 2021-02-15T16:27:43.826Z [ index.js ] NORMA: Initializing wormhole setup for Agent (uhCAkCQZSSO0xSbujgcpou0lIIGCDepyOSYYQOtoEhacH3I81OInc)
Feb 15 16:27:43 hpos holo-envoy[749]: 2021-02-15T16:27:43.826Z [ index.js ] DEBUG: Registering RPC WebSocket event (uhCAkCQZSSO0xSbujgcpou0lIIGCDepyOSYYQOtoEhacH3I81OInc/wormhole/request) in namespace: /hosting/
Feb 15 16:27:43 hpos holo-envoy[749]: 2021-02-15T16:27:43.826Z [ index.js ] WARN: RPC WebSocket event 'uhCAkCQZSSO0xSbujgcpou0lIIGCDepyOSYYQOtoEhacH3I81OInc/wormhole/request' is already registered for Agent (uhCAkCQZSSO0xSbujgcpou0lIIGCDepyOSYYQOtoEhacH3I81OInc)
Feb 15 16:27:44 hpos holo-envoy[749]: 2021-02-15T16:27:44.043Z [ index.js ] SILLY: Incoming websocket message: {"jsonrpc":"2.0","method":"rpc.on","params":["uhCAkCQZSSO0xSbujgcpou0lIIGCDepyOSYYQOtoEhacH3I81OInc/wormhole/request"],"id":3}
Feb 15 16:27:44 hpos holo-envoy[749]: 2021-02-15T16:27:44.295Z [ index.js ] SILLY: Incoming websocket message: {"jsonrpc":"2.0","method":"holo/agent/identify","params":["uhCAkCQZSSO0xSbujgcpou0lIIGCDepyOSYYQOtoEhacH3I81OInc"],"id":4}
Feb 15 16:27:44 hpos holo-envoy[749]: 2021-02-15T16:27:44.514Z [ index.js ] NORMA: Socket is closing for Agent (uhCAkCQZSSO0xSbujgcpou0lIIGCDepyOSYYQOtoEhacH3I81OInc) using HHA ID uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt
React
A declarative, efficient, and flexible JavaScript library for building user interfaces.
🖖 Vue.js is a progressive, incrementally-adoptable JavaScript framework for building UI on the web.
Typescript
TypeScript is a superset of JavaScript that compiles to clean JavaScript output.
An Open Source Machine Learning Framework for Everyone
Django
The Web framework for perfectionists with deadlines.
Laravel
A PHP framework for web artisans
Bring data to life with SVG, Canvas and HTML. 📊📈🎉
JavaScript (JS) is a lightweight interpreted programming language with first-class functions.
Some thing interesting about web. New door for the world.
A server is a program made to process requests and deliver data to clients.
Machine learning is a way of modeling and interpreting data that allows a piece of software to respond intelligently.
Some thing interesting about visualization, use data art
Some thing interesting about game, make everyone happy.
Facebook
We are working to build community through open source technology. NB: members must have two-factor auth.
Microsoft
Open source projects and samples from Microsoft.
Google
Google ❤️ Open Source for everyone.
Alibaba
Alibaba Open Source for everyone
D3
Data-Driven Documents codes.
Tencent
China tencent open source team.