[D-01193] Sign up fails during installApp stage
Closed this issue · 9 comments
alastairong commented
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
alastairong commented
Sometimes I get timeouts instead. But I have reliably found that these installhApp issues only happen when creating ADDITIONAL hosted instances. I never have an issue creating the 1st hosted instance.
alastairong commented
Only getting timeouts now. Here are the logs
Feb 15 17:39:16 hpos holo-envoy[767]: 2021-02-15T17:39:16.050Z [ 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,186,119,55,24,147,170,95,20,233,156,137,195,163,3,20,35,110,169,237,65,49,144,58,146,55,124,181,65,155,103,53,226,174,92,33,176]}],"elemental-chat"]]}
Feb 15 17:39:16 hpos holo-envoy[767]: 2021-02-15T17:39:16.050Z [ index.js ] SILLY: NUMBER OF DNAs in the hosted happ:
Feb 15 17:39:16 hpos holo-envoy[767]: 2021-02-15T17:39:16.052Z [ index.js ] SILLY: AppInfo on sign-up:
Feb 15 17:39:16 hpos holo-envoy[767]: 2021-02-15T17:39:16.052Z [ 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,186,119,55,24,147,170,95,20,233,156,137,195,163,3,20,35,110,169,237,65,49,144,58,146,55,124,181,65,155,103,53,226,174,92,33,176]}],"elemental-chat"]]
Feb 15 17:39:16 hpos holo-envoy[767]: 2021-02-15T17:39:16.052Z [ index.js ] INFO: Found 1 DNA(s) for the app bundle with HHA ID: uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt
Feb 15 17:39:16 hpos holo-envoy[767]: 2021-02-15T17:39:16.052Z [ index.js ] INFO: Encoded Agent ID (uhCAk_FxrlqprmZSXg9fWOBJ_l-b9Im2VakY4Uq7jkyRrwK2Id-2w) into buffer form: {"type":"Buffer","data":[132,32,36,252,92,107,150,170,107,153,148,151,131,215,214,56,18,127,151,230,253,34,109,149,106,70,56,82,174,227,147,36,107,192,173,136,119,237,176]}
Feb 15 17:39:16 hpos holo-envoy[767]: 2021-02-15T17:39:16.052Z [ index.js ] INFO: Installing App with HHA ID (uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt) as Installed App ID (uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt:uhCAk_FxrlqprmZSXg9fWOBJ_l-b9Im2VakY4Uq7jkyRrwK2Id-2w)
Feb 15 17:39:16 hpos holo-envoy[767]: 2021-02-15T17:39:16.052Z [ 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 17:39:16 hpos holo-envoy[767]: 2021-02-15T17:39:16.053Z [ index.js ] NORMA: Received request to call Conductor using client 'admin' with call spec of type 'string'
Feb 15 17:39:16 hpos holo-envoy[767]: 2021-02-15T17:39:16.053Z [ index.js ] DEBUG: Admin Call spec payload: ( installed_app_id : string, agent_key : object, dnas : object )
Feb 15 17:39:16 hpos holo-envoy[767]: 2021-02-15T17:39:16.053Z [ index.js ] SILLY: Calling Conductor method (installApp) over client 'admin' with input {"installed_app_id":"uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt:uhCAk_FxrlqprmZSXg9fWOBJ_l-b9Im2VakY4Uq7jkyRrwK2Id-2w","agent_key":{"type":"Buffer","data":[132,32,36,252,92,107,150,170,107,153,148,151,131,215,214,56,18,127,151,230,253,34,109,149,106,70,56,82,174,227,147,36,107,192,173,136,119,237,176]},"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 17:39:31 hpos holo-envoy[767]: CONDUCTOR CALL ERROR:
Feb 15 17:39:31 hpos holo-envoy[767]: Error: Timed out in 15000ms: install_app
Feb 15 17:39:31 hpos holo-envoy[767]: at Timeout.<anonymous> (/nix/store/pvn43dlaj0v9bnqm2m9sj1q9qp14hbf4-holo-envoy/node_modules/@holochain/conductor-api/lib/websocket/common.js:16:20)
Feb 15 17:39:31 hpos holo-envoy[767]: at listOnTimeout (internal/timers.js:549:17)
Feb 15 17:39:31 hpos holo-envoy[767]: at processTimers (internal/timers.js:492:7)
Feb 15 17:39:31 hpos holo-envoy[767]: 2021-02-15T17:39:31.065Z [ index.js ] ERROR: Failed during Conductor call with error: Error: CONDUCTOR CALL ERROR: {}
Feb 15 17:39:31 hpos holo-envoy[767]: 2021-02-15T17:39:31.065Z [ index.js ] ERROR: Failed during 'installApp': HoloError: Error: CONDUCTOR CALL ERROR: {}
Feb 15 17:39:31 hpos holo-envoy[767]: 2021-02-15T17:39:31.066Z [ index.js ] ERROR: Failed during DNA processing for Agent (uhCAk_FxrlqprmZSXg9fWOBJ_l-b9Im2VakY4Uq7jkyRrwK2Id-2w) HHA ID (uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt): HoloError: Error: CONDUCTOR CALL ERROR: {}
Feb 15 17:39:31 hpos holo-envoy[767]: 2021-02-15T17:39:31.066Z [ index.js ] ERROR: Failed during sign-up process for Agent (uhCAk_FxrlqprmZSXg9fWOBJ_l-b9Im2VakY4Uq7jkyRrwK2Id-2w) HHA ID (uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt): {"name":"HoloError","message":"Failed to create a new hosted agent"}
Feb 15 17:39:31 hpos holo-envoy[767]: 2021-02-15T17:39:31.278Z [ index.js ] NORMA: Socket is closing for Agent (uhCAk_FxrlqprmZSXg9fWOBJ_l-b9Im2VakY4Uq7jkyRrwK2Id-2w) using HHA ID uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt
zo-el commented
This is a weird one. This commit in holo-nixpkgs is where we can change results. Let me know if you can reproduce it consistently.
alastairong commented
Still getting this. Still consistently with ADDITIONAL hosted instances (never the first instance).
Note that in the 2 requests in the eventList, the one ending "Inc" is the FIRST hosted agent. "0hw" is the SECOND (new) one
Feb 16 11:19:59 hpos holo-envoy[751]: 2021-02-16T11:19:59.976Z [ index.js ] INFO: Installing App with HHA ID (uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt) as Installed App ID (uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt:uhCAkaU1TzWBEEAormKWx9rI95s40KGlIPT69wXSAfb1mCs7knOhw)
Feb 16 11:19:59 hpos holo-envoy[751]: 2021-02-16T11:19:59.976Z [ 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 16 11:19:59 hpos holo-envoy[751]: 2021-02-16T11:19:59.976Z [ index.js ] NORMA: Received request to call Conductor using client 'admin' with call spec of type 'string'
Feb 16 11:19:59 hpos holo-envoy[751]: 2021-02-16T11:19:59.976Z [ index.js ] DEBUG: Admin Call spec payload: ( installed_app_id : string, agent_key : object, dnas : object )
Feb 16 11:19:59 hpos holo-envoy[751]: 2021-02-16T11:19:59.976Z [ index.js ] SILLY: Calling Conductor method (installApp) over client 'admin' with input {"installed_app_id":"uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt:uhCAkaU1TzWBEEAormKWx9rI95s40KGlIPT69wXSAfb1mCs7knOhw","agent_key":{"type":"Buffer","data":[132,32,36,105,77,83,205,96,68,16,10,43,152,165,177,246,178,61,230,206,52,40,105,72,61,62,189,193,116,128,125,189,102,10,206,228,156,232,112]},"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 16 11:19:59 hpos holo-envoy[751]: 2021-02-16T11:19:59.979Z [ shim.js ] NORMA: Intercepted sign by public key
Feb 16 11:19:59 hpos holo-envoy[751]: 2021-02-16T11:19:59.979Z [ index.js ] NORMA: Wormhole Signing Requested...
Feb 16 11:19:59 hpos holo-envoy[751]: 2021-02-16T11:19:59.979Z [ index.js ] NORMA: Opening a request (#101) for Agent (uhCAkaU1TzWBEEAormKWx9rI95s40KGlIPT69wXSAfb1mCs7knOhw) 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,105,77,83,205,96,68,16,10,43,152,165,177,246,178,61,230,206,52,40,105,72,61,62,189,193,116,128,125,189,102,10,206,228,156,232,112,169,116,105,109,101,115,116,97,109,112,146,206,96,43,170,95,206,58,74,20,170,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 16 11:19:59 hpos holo-envoy[751]: 2021-02-16T11:19:59.979Z [ index.js ] SILLY: Agent id: uhCAkaU1TzWBEEAormKWx9rI95s40KGlIPT69wXSAfb1mCs7knOhw
Feb 16 11:19:59 hpos holo-envoy[751]: Event List: [
Feb 16 11:19:59 hpos holo-envoy[751]: 'uhCAkCQZSSO0xSbujgcpou0lIIGCDepyOSYYQOtoEhacH3I81OInc/wormhole/request',
Feb 16 11:19:59 hpos holo-envoy[751]: 'uhCAkaU1TzWBEEAormKWx9rI95s40KGlIPT69wXSAfb1mCs7knOhw/wormhole/request'
Feb 16 11:19:59 hpos holo-envoy[751]: ]
Feb 16 11:19:59 hpos holo-envoy[751]: 2021-02-16T11:19:59.980Z [ index.js ] SILLY: Payload to be signed: {"type":"Dna","author":{"type":"Buffer","data":[132,32,36,105,77,83,205,96,68,16,10,43,152,165,177,246,178,61,230,206,52,40,105,72,61,62,189,193,116,128,125,189,102,10,206,228,156,232,112]},"timestamp":[1613474399,977933482],"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 16 11:19:59 hpos holo-envoy[751]: 2021-02-16T11:19:59.980Z [ index.js ] INFO: Adding signature request #101 to pending signatures
Feb 16 11:19:59 hpos holo-envoy[751]: 2021-02-16T11:19:59.980Z [ index.js ] NORMA: Sent signing request #101 to Agent (uhCAkaU1TzWBEEAormKWx9rI95s40KGlIPT69wXSAfb1mCs7knOhw)
Feb 16 11:20:00 hpos holo-envoy[751]: 2021-02-16T11:20:00.165Z [ index.js ] SILLY: Incoming websocket message: {"jsonrpc":"2.0","method":"holo/wormhole/response","params":[101,"Cy9DI8gkTPIqxd4/aK8+RoKYSRoFsJO9E9WGh8aq2zagjL8fCVUC1NXCYHFFjAZQZxdbZvy8H6blKAL0AzT0BQ=="],"id":5}
Feb 16 11:20:00 hpos holo-envoy[751]: 2021-02-16T11:20:00.165Z [ index.js ] NORMA: Received signing response #101 with signature: Cy9DI8gkTPIqxd4/aK8+RoKYSRoFsJO9E9WGh8aq2zagjL8fCVUC1NXCYHFFjAZQZxdbZvy8H6blKAL0AzT0BQ==
Feb 16 11:20:19 hpos holo-envoy[751]: 2021-02-16T11:20:19.264Z [ index.js ] NORMA: Socket is closing for Agent (uhCAkCQZSSO0xSbujgcpou0lIIGCDepyOSYYQOtoEhacH3I81OInc) using HHA ID uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt
Feb 16 11:20:29 hpos holo-envoy[751]: CONDUCTOR CALL ERROR:
Feb 16 11:20:29 hpos holo-envoy[751]: Error: Timed out in 30000ms: install_app
Feb 16 11:20:29 hpos holo-envoy[751]: at Timeout.<anonymous> (/nix/store/7biypkv3fwxqkkh9y4g327v1c0q22sg3-holo-envoy/node_modules/@holochain/conductor-api/lib/websocket/common.js:16:20)
Feb 16 11:20:29 hpos holo-envoy[751]: at listOnTimeout (internal/timers.js:549:17)
Feb 16 11:20:29 hpos holo-envoy[751]: at processTimers (internal/timers.js:492:7)
Feb 16 11:20:29 hpos holo-envoy[751]: 2021-02-16T11:20:29.978Z [ index.js ] ERROR: Failed during Conductor call with error: Error: CONDUCTOR CALL ERROR: {}
Feb 16 11:20:29 hpos holo-envoy[751]: 2021-02-16T11:20:29.978Z [ index.js ] ERROR: Failed during 'installApp': HoloError: Error: CONDUCTOR CALL ERROR: {}
Feb 16 11:20:29 hpos holo-envoy[751]: 2021-02-16T11:20:29.978Z [ index.js ] ERROR: Failed during DNA processing for Agent (uhCAkaU1TzWBEEAormKWx9rI95s40KGlIPT69wXSAfb1mCs7knOhw) HHA ID (uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt): HoloError: Error: CONDUCTOR CALL ERROR: {}
Feb 16 11:20:29 hpos holo-envoy[751]: 2021-02-16T11:20:29.978Z [ index.js ] ERROR: Failed during sign-up process for Agent (uhCAkaU1TzWBEEAormKWx9rI95s40KGlIPT69wXSAfb1mCs7knOhw) HHA ID (uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt): {"name":"HoloError","message":"Failed to create a new hosted agent"}
Feb 16 11:20:30 hpos holo-envoy[751]: 2021-02-16T11:20:30.259Z [ index.js ] NORMA: Socket is closing for Agent (uhCAkaU1TzWBEEAormKWx9rI95s40KGlIPT69wXSAfb1mCs7knOhw) using HHA ID uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt
Feb 16 11:20:31 hpos holo-envoy[751]: 2021-02-16T11:20:31.173Z [ index.js ] SILLY: Incoming connection from /hosting/?anonymous=true&agent_id=uhCAkE3-CQk2EB91sLll93jIjxul3C2FnD5IGoslW5Ryr3aeDV40p&hha_hash=uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt
Feb 16 11:20:31 hpos holo-envoy[751]: 2021-02-16T11:20:31.173Z [ index.js ] NORMA: Anonymous (uhCAkE3-CQk2EB91sLll93jIjxul3C2FnD5IGoslW5Ryr3aeDV40p) connection for HHA ID: uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt
Feb 16 11:20:31 hpos holo-envoy[751]: 2021-02-16T11:20:31.173Z [ index.js ] DEBUG: Adding Agent (uhCAkE3-CQk2EB91sLll93jIjxul3C2FnD5IGoslW5Ryr3aeDV40p) to anonymous list with HHA ID uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt
Feb 16 11:20:31 hpos holo-envoy[751]: 2021-02-16T11:20:31.366Z [ index.js ] SILLY: Incoming websocket message: {"jsonrpc":"2.0","method":"rpc.on","params":["signal"],"id":1}
alastairong commented
Trying another time. Same problem. But based on logs it looks like it fails earlier?
Feb 16 11:22:35 hpos holo-envoy[751]: 2021-02-16T11:22:35.396Z [ index.js ] NORMA: Received sign-up request from Agent (uhCAk_FxrlqprmZSXg9fWOBJ_l-b9Im2VakY4Uq7jkyRrwK2Id-2w) for HHA ID: uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt
Feb 16 11:22:35 hpos holo-envoy[751]: 2021-02-16T11:22:35.396Z [ index.js ] INFO: Retrieve the hosted app cell_data using the anonymous installed_app_id: 'uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt'
Feb 16 11:22:35 hpos holo-envoy[751]: 2021-02-16T11:22:35.396Z [ index.js ] NORMA: Received request to call Conductor using client 'app' with call spec of type 'object'
Feb 16 11:22:35 hpos holo-envoy[751]: 2021-02-16T11:22:35.397Z [ index.js ] DEBUG: App Info Call spec details for installed_app_id ( uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt )
Feb 16 11:22:35 hpos holo-envoy[751]: 2021-02-16T11:22:35.397Z [ index.js ] SILLY: Calling Conductor method (appInfo) over client 'app' with input {"installed_app_id":"uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt"}:
Feb 16 11:22:35 hpos holo-envoy[751]: 2021-02-16T11:22:35.398Z [ 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,251,174,56,176,10,72,14,246,44,92,253,28,172,41,139,134,105,229,242,159,75,229,129,60,74,85,167,196,184,20,79,25,222,104,103,211]}],"elemental-chat"]]}
Feb 16 11:22:35 hpos holo-envoy[751]: 2021-02-16T11:22:35.399Z [ 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,251,174,56,176,10,72,14,246,44,92,253,28,172,41,139,134,105,229,242,159,75,229,129,60,74,85,167,196,184,20,79,25,222,104,103,211]}],"elemental-chat"]]}
Feb 16 11:22:35 hpos holo-envoy[751]: 2021-02-16T11:22:35.399Z [ index.js ] SILLY: NUMBER OF DNAs in the hosted happ:
Feb 16 11:22:35 hpos holo-envoy[751]: 2021-02-16T11:22:35.399Z [ index.js ] SILLY: AppInfo on sign-up:
Feb 16 11:22:35 hpos holo-envoy[751]: 2021-02-16T11:22:35.399Z [ 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,251,174,56,176,10,72,14,246,44,92,253,28,172,41,139,134,105,229,242,159,75,229,129,60,74,85,167,196,184,20,79,25,222,104,103,211]}],"elemental-chat"]]
Feb 16 11:22:35 hpos holo-envoy[751]: 2021-02-16T11:22:35.399Z [ index.js ] INFO: Found 1 DNA(s) for the app bundle with HHA ID: uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt
Feb 16 11:22:35 hpos holo-envoy[751]: 2021-02-16T11:22:35.400Z [ index.js ] INFO: Encoded Agent ID (uhCAk_FxrlqprmZSXg9fWOBJ_l-b9Im2VakY4Uq7jkyRrwK2Id-2w) into buffer form: {"type":"Buffer","data":[132,32,36,252,92,107,150,170,107,153,148,151,131,215,214,56,18,127,151,230,253,34,109,149,106,70,56,82,174,227,147,36,107,192,173,136,119,237,176]}
Feb 16 11:22:35 hpos holo-envoy[751]: 2021-02-16T11:22:35.400Z [ index.js ] INFO: Installing App with HHA ID (uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt) as Installed App ID (uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt:uhCAk_FxrlqprmZSXg9fWOBJ_l-b9Im2VakY4Uq7jkyRrwK2Id-2w)
Feb 16 11:22:35 hpos holo-envoy[751]: 2021-02-16T11:22:35.400Z [ 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 16 11:22:35 hpos holo-envoy[751]: 2021-02-16T11:22:35.400Z [ index.js ] NORMA: Received request to call Conductor using client 'admin' with call spec of type 'string'
Feb 16 11:22:35 hpos holo-envoy[751]: 2021-02-16T11:22:35.400Z [ index.js ] DEBUG: Admin Call spec payload: ( installed_app_id : string, agent_key : object, dnas : object )
Feb 16 11:22:35 hpos holo-envoy[751]: 2021-02-16T11:22:35.400Z [ index.js ] SILLY: Calling Conductor method (installApp) over client 'admin' with input {"installed_app_id":"uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt:uhCAk_FxrlqprmZSXg9fWOBJ_l-b9Im2VakY4Uq7jkyRrwK2Id-2w","agent_key":{"type":"Buffer","data":[132,32,36,252,92,107,150,170,107,153,148,151,131,215,214,56,18,127,151,230,253,34,109,149,106,70,56,82,174,227,147,36,107,192,173,136,119,237,176]},"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 16 11:23:05 hpos holo-envoy[751]: CONDUCTOR CALL ERROR:
Feb 16 11:23:05 hpos holo-envoy[751]: Error: Timed out in 30000ms: install_app
Feb 16 11:23:05 hpos holo-envoy[751]: at Timeout.<anonymous> (/nix/store/7biypkv3fwxqkkh9y4g327v1c0q22sg3-holo-envoy/node_modules/@holochain/conductor-api/lib/websocket/common.js:16:20)
Feb 16 11:23:05 hpos holo-envoy[751]: at listOnTimeout (internal/timers.js:549:17)
Feb 16 11:23:05 hpos holo-envoy[751]: at processTimers (internal/timers.js:492:7)
Feb 16 11:23:05 hpos holo-envoy[751]: 2021-02-16T11:23:05.401Z [ index.js ] ERROR: Failed during Conductor call with error: Error: CONDUCTOR CALL ERROR: {}
Feb 16 11:23:05 hpos holo-envoy[751]: 2021-02-16T11:23:05.401Z [ index.js ] ERROR: Failed during 'installApp': HoloError: Error: CONDUCTOR CALL ERROR: {}
Feb 16 11:23:05 hpos holo-envoy[751]: 2021-02-16T11:23:05.401Z [ index.js ] ERROR: Failed during DNA processing for Agent (uhCAk_FxrlqprmZSXg9fWOBJ_l-b9Im2VakY4Uq7jkyRrwK2Id-2w) HHA ID (uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt): HoloError: Error: CONDUCTOR CALL ERROR: {}
Feb 16 11:23:05 hpos holo-envoy[751]: 2021-02-16T11:23:05.401Z [ index.js ] ERROR: Failed during sign-up process for Agent (uhCAk_FxrlqprmZSXg9fWOBJ_l-b9Im2VakY4Uq7jkyRrwK2Id-2w) HHA ID (uhCkkcF0X1dpwHFeIPI6-7rzM6ma9IgyiqD-othxgENSkL1So1Slt): {"name":"HoloError","message":"Failed to create a new hosted agent"}
alastairong commented
The second set of logs, where it does not reach the stage where it logs the Event List, seems to be more common
alastairong commented
@zo-el And yes I can reproduce it consistently.
alastairong commented
Resolved now