race condition with inserting keys?

[brenzi]

PLAY [validator] ***************************************************************

TASK [validator-service : install systemd] *************************************
ok: [161.35.74.216]
ok: [104.248.35.51]
ok: [68.183.216.242]

TASK [validator-service : create substrate service file] ***********************
ok: [68.183.216.242]
ok: [104.248.35.51]
changed: [161.35.74.216]

TASK [validator-service : configure and stop substrate service in systemd] *****
changed: [161.35.74.216]
changed: [104.248.35.51]
changed: [68.183.216.242]

TASK [validator-service : start substrate] *************************************
changed: [104.248.35.51]
changed: [68.183.216.242]
changed: [161.35.74.216]

PLAY [validator] ***************************************************************

TASK [validator-key-insert : ensure curl] **************************************
ok: [161.35.74.216]
ok: [68.183.216.242]
ok: [104.248.35.51]

TASK [validator-key-insert : grab keys] ****************************************
failed: [68.183.216.242] (item=aura) => {"ansible_loop_var": "item", "changed": true, "cmd": "if [ aura = gran ]; then\n  crypto=\"ed25519\"\nelse\n  crypto=\"sr25519\"\nfi\ninspect_result=$(cat /home/subuser/mnemonic | xargs --null /usr/local/bin/subkey --${crypto} inspect)\npublic_key=$(echo -n \"${inspect_result}\" | grep \"Public key\" | cut -d':' -f2 | tr -d '[:space:]')\nmnemonic=$(cat /home/subuser/mnemonic)\n\nprintf \"${public_key}\"\nprintf \"${mnemonic}\"\n\ncurl http://localhost:9933 -H \"Content-Type:application/json\" -d  \"{ \\\n    \\\"jsonrpc\\\":\\\"2.0\\\", \\\n    \\\"id\\\":1, \\\n    \\\"method\\\":\\\"author_insertKey\\\", \\\n    \\\"params\\\": [ \\\n      \\\"aura\\\", \\\n      \\\"${mnemonic}\\\", \\\n      \\\"${public_key}\\\" \\\n    ] \\\n  }\"\n", "delta": "0:00:00.037104", "end": "2020-05-02 11:23:30.333123", "item": "aura", "msg": "non-zero return code", "rc": 7, "start": "2020-05-02 11:23:30.296019", "stderr": "  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current\n                                 Dload  Upload   Total   Spent    Left  Speed\n\r  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0curl: (7) Failed to connect to localhost port 9933: Connection refused", "stderr_lines": ["  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current", "                                 Dload  Upload   Total   Spent    Left  Speed", "", "  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0curl: (7) Failed to connect to localhost port 9933: Connection refused"], "stdout": "0x2c935883949b7cb5503c73e1ee7b765177d4c19d9af9a0977d35c081a5a5ee62ethics response glare rural theme photo small decade poem witness orange window", "stdout_lines": ["0x2c935883949b7cb5503c73e1ee7b765177d4c19d9af9a0977d35c081a5a5ee62ethics response glare rural theme photo small decade poem witness orange window"]}
changed: [161.35.74.216] => (item=aura)
failed: [104.248.35.51] (item=aura) => {"ansible_loop_var": "item", "changed": true, "cmd": "if [ aura = gran ]; then\n  crypto=\"ed25519\"\nelse\n  crypto=\"sr25519\"\nfi\ninspect_result=$(cat /home/subuser/mnemonic | xargs --null /usr/local/bin/subkey --${crypto} inspect)\npublic_key=$(echo -n \"${inspect_result}\" | grep \"Public key\" | cut -d':' -f2 | tr -d '[:space:]')\nmnemonic=$(cat /home/subuser/mnemonic)\n\nprintf \"${public_key}\"\nprintf \"${mnemonic}\"\n\ncurl http://localhost:9933 -H \"Content-Type:application/json\" -d  \"{ \\\n    \\\"jsonrpc\\\":\\\"2.0\\\", \\\n    \\\"id\\\":1, \\\n    \\\"method\\\":\\\"author_insertKey\\\", \\\n    \\\"params\\\": [ \\\n      \\\"aura\\\", \\\n      \\\"${mnemonic}\\\", \\\n      \\\"${public_key}\\\" \\\n    ] \\\n  }\"\n", "delta": "0:00:00.067730", "end": "2020-05-02 11:23:30.420371", "item": "aura", "msg": "non-zero return code", "rc": 7, "start": "2020-05-02 11:23:30.352641", "stderr": "  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current\n                                 Dload  Upload   Total   Spent    Left  Speed\n\r  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0curl: (7) Failed to connect to localhost port 9933: Connection refused", "stderr_lines": ["  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current", "                                 Dload  Upload   Total   Spent    Left  Speed", "", "  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0curl: (7) Failed to connect to localhost port 9933: Connection refused"], "stdout": "0xc0c5f21a2bb8537566a9bfa79287d4873141ed0b8df4b0f45ddafb034bc81974panda best leisure coach sausage file talent marble blouse extra pet frequent", "stdout_lines": ["0xc0c5f21a2bb8537566a9bfa79287d4873141ed0b8df4b0f45ddafb034bc81974panda best leisure coach sausage file talent marble blouse extra pet frequent"]}
failed: [68.183.216.242] (item=gran) => {"ansible_loop_var": "item", "changed": true, "cmd": "if [ gran = gran ]; then\n  crypto=\"ed25519\"\nelse\n  crypto=\"sr25519\"\nfi\ninspect_result=$(cat /home/subuser/mnemonic | xargs --null /usr/local/bin/subkey --${crypto} inspect)\npublic_key=$(echo -n \"${inspect_result}\" | grep \"Public key\" | cut -d':' -f2 | tr -d '[:space:]')\nmnemonic=$(cat /home/subuser/mnemonic)\n\nprintf \"${public_key}\"\nprintf \"${mnemonic}\"\n\ncurl http://localhost:9933 -H \"Content-Type:application/json\" -d  \"{ \\\n    \\\"jsonrpc\\\":\\\"2.0\\\", \\\n    \\\"id\\\":1, \\\n    \\\"method\\\":\\\"author_insertKey\\\", \\\n    \\\"params\\\": [ \\\n      \\\"gran\\\", \\\n      \\\"${mnemonic}\\\", \\\n      \\\"${public_key}\\\" \\\n    ] \\\n  }\"\n", "delta": "0:00:00.037338", "end": "2020-05-02 11:23:30.866179", "item": "gran", "msg": "non-zero return code", "rc": 7, "start": "2020-05-02 11:23:30.828841", "stderr": "  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current\n                                 Dload  Upload   Total   Spent    Left  Speed\n\r  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0curl: (7) Failed to connect to localhost port 9933: Connection refused", "stderr_lines": ["  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current", "                                 Dload  Upload   Total   Spent    Left  Speed", "", "  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0curl: (7) Failed to connect to localhost port 9933: Connection refused"], "stdout": "0x3fee8474ff417eb5b71ce62f631aa0f53617876ed127a5969900fa4fc127a613ethics response glare rural theme photo small decade poem witness orange window", "stdout_lines": ["0x3fee8474ff417eb5b71ce62f631aa0f53617876ed127a5969900fa4fc127a613ethics response glare rural theme photo small decade poem witness orange window"]}
failed: [104.248.35.51] (item=gran) => {"ansible_loop_var": "item", "changed": true, "cmd": "if [ gran = gran ]; then\n  crypto=\"ed25519\"\nelse\n  crypto=\"sr25519\"\nfi\ninspect_result=$(cat /home/subuser/mnemonic | xargs --null /usr/local/bin/subkey --${crypto} inspect)\npublic_key=$(echo -n \"${inspect_result}\" | grep \"Public key\" | cut -d':' -f2 | tr -d '[:space:]')\nmnemonic=$(cat /home/subuser/mnemonic)\n\nprintf \"${public_key}\"\nprintf \"${mnemonic}\"\n\ncurl http://localhost:9933 -H \"Content-Type:application/json\" -d  \"{ \\\n    \\\"jsonrpc\\\":\\\"2.0\\\", \\\n    \\\"id\\\":1, \\\n    \\\"method\\\":\\\"author_insertKey\\\", \\\n    \\\"params\\\": [ \\\n      \\\"gran\\\", \\\n      \\\"${mnemonic}\\\", \\\n      \\\"${public_key}\\\" \\\n    ] \\\n  }\"\n", "delta": "0:00:00.035869", "end": "2020-05-02 11:23:30.914841", "item": "gran", "msg": "non-zero return code", "rc": 7, "start": "2020-05-02 11:23:30.878972", "stderr": "  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current\n                                 Dload  Upload   Total   Spent    Left  Speed\n\r  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0curl: (7) Failed to connect to localhost port 9933: Connection refused", "stderr_lines": ["  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current", "                                 Dload  Upload   Total   Spent    Left  Speed", "", "  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0curl: (7) Failed to connect to localhost port 9933: Connection refused"], "stdout": "0x91d764ea36fa0dec55808fa9b9c90943400dac207ef833a276dc944c763f0311panda best leisure coach sausage file talent marble blouse extra pet frequent", "stdout_lines": ["0x91d764ea36fa0dec55808fa9b9c90943400dac207ef833a276dc944c763f0311panda best leisure coach sausage file talent marble blouse extra pet frequent"]}
changed: [161.35.74.216] => (item=gran)
failed: [68.183.216.242] (item=babe) => {"ansible_loop_var": "item", "changed": true, "cmd": "if [ babe = gran ]; then\n  crypto=\"ed25519\"\nelse\n  crypto=\"sr25519\"\nfi\ninspect_result=$(cat /home/subuser/mnemonic | xargs --null /usr/local/bin/subkey --${crypto} inspect)\npublic_key=$(echo -n \"${inspect_result}\" | grep \"Public key\" | cut -d':' -f2 | tr -d '[:space:]')\nmnemonic=$(cat /home/subuser/mnemonic)\n\nprintf \"${public_key}\"\nprintf \"${mnemonic}\"\n\ncurl http://localhost:9933 -H \"Content-Type:application/json\" -d  \"{ \\\n    \\\"jsonrpc\\\":\\\"2.0\\\", \\\n    \\\"id\\\":1, \\\n    \\\"method\\\":\\\"author_insertKey\\\", \\\n    \\\"params\\\": [ \\\n      \\\"babe\\\", \\\n      \\\"${mnemonic}\\\", \\\n      \\\"${public_key}\\\" \\\n    ] \\\n  }\"\n", "delta": "0:00:00.037135", "end": "2020-05-02 11:23:31.383585", "item": "babe", "msg": "non-zero return code", "rc": 7, "start": "2020-05-02 11:23:31.346450", "stderr": "  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current\n                                 Dload  Upload   Total   Spent    Left  Speed\n\r  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0curl: (7) Failed to connect to localhost port 9933: Connection refused", "stderr_lines": ["  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current", "                                 Dload  Upload   Total   Spent    Left  Speed", "", "  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0curl: (7) Failed to connect to localhost port 9933: Connection refused"], "stdout": "0x2c935883949b7cb5503c73e1ee7b765177d4c19d9af9a0977d35c081a5a5ee62ethics response glare rural theme photo small decade poem witness orange window", "stdout_lines": ["0x2c935883949b7cb5503c73e1ee7b765177d4c19d9af9a0977d35c081a5a5ee62ethics response glare rural theme photo small decade poem witness orange window"]}
failed: [104.248.35.51] (item=babe) => {"ansible_loop_var": "item", "changed": true, "cmd": "if [ babe = gran ]; then\n  crypto=\"ed25519\"\nelse\n  crypto=\"sr25519\"\nfi\ninspect_result=$(cat /home/subuser/mnemonic | xargs --null /usr/local/bin/subkey --${crypto} inspect)\npublic_key=$(echo -n \"${inspect_result}\" | grep \"Public key\" | cut -d':' -f2 | tr -d '[:space:]')\nmnemonic=$(cat /home/subuser/mnemonic)\n\nprintf \"${public_key}\"\nprintf \"${mnemonic}\"\n\ncurl http://localhost:9933 -H \"Content-Type:application/json\" -d  \"{ \\\n    \\\"jsonrpc\\\":\\\"2.0\\\", \\\n    \\\"id\\\":1, \\\n    \\\"method\\\":\\\"author_insertKey\\\", \\\n    \\\"params\\\": [ \\\n      \\\"babe\\\", \\\n      \\\"${mnemonic}\\\", \\\n      \\\"${public_key}\\\" \\\n    ] \\\n  }\"\n", "delta": "0:00:00.037174", "end": "2020-05-02 11:23:31.428979", "item": "babe", "msg": "non-zero return code", "rc": 7, "start": "2020-05-02 11:23:31.391805", "stderr": "  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current\n                                 Dload  Upload   Total   Spent    Left  Speed\n\r  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0curl: (7) Failed to connect to localhost port 9933: Connection refused", "stderr_lines": ["  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current", "                                 Dload  Upload   Total   Spent    Left  Speed", "", "  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0curl: (7) Failed to connect to localhost port 9933: Connection refused"], "stdout": "0xc0c5f21a2bb8537566a9bfa79287d4873141ed0b8df4b0f45ddafb034bc81974panda best leisure coach sausage file talent marble blouse extra pet frequent", "stdout_lines": ["0xc0c5f21a2bb8537566a9bfa79287d4873141ed0b8df4b0f45ddafb034bc81974panda best leisure coach sausage file talent marble blouse extra pet frequent"]}
changed: [161.35.74.216] => (item=babe)
changed: [68.183.216.242] => (item=imol)
changed: [104.248.35.51] => (item=imol)
changed: [161.35.74.216] => (item=imol)
changed: [104.248.35.51] => (item=para)
changed: [68.183.216.242] => (item=para)
changed: [161.35.74.216] => (item=para)
changed: [104.248.35.51] => (item=audi)
changed: [68.183.216.242] => (item=audi)
changed: [161.35.74.216] => (item=audi)

PLAY [validator] ***************************************************************

TASK [validator-service-restart : stop substrate] ******************************
changed: [161.35.74.216]

TASK [validator-service-restart : clean substrate db] **************************
changed: [161.35.74.216]

TASK [validator-service-restart : start substrate] *****************************
changed: [161.35.74.216]

PLAY RECAP *********************************************************************
104.248.35.51              : ok=52   changed=13   unreachable=0    failed=1    skipped=11   rescued=0    ignored=0   
161.35.74.216              : ok=35   changed=23   unreachable=0    failed=0    skipped=1    rescued=0    ignored=0   
68.183.216.242             : ok=28   changed=8    unreachable=0    failed=1    skipped=4    rescued=0    ignored=0   
localhost                  : ok=2    changed=1    unreachable=0    failed=0    skipped=0    rescued=0    ignored=0   

2020-05-02T11:23:35.011Z [Gantree] (cmd) error: Execution failed with code 2: ansible-playbook -i /gantree/inventory/substratee-test/gantree -i /gantree/inventory/substratee-test/active /usr/local/lib/node_modules/gantree-cli/node_modules/gantree-lib/ansible/operation.yml
(node:12) UnhandledPromiseRejectionWarning: Error: 2
    at childCloseCallback (/usr/local/lib/node_modules/gantree-cli/node_modules/gantree-lib/src/lib/cmd.js:117:18)
    at ChildProcess.<anonymous> (/usr/local/lib/node_modules/gantree-cli/node_modules/gantree-lib/src/lib/cmd.js:55:5)
    at ChildProcess.emit (events.js:323:22)
    at maybeClose (internal/child_process.js:1021:16)
    at Process.ChildProcess._handle.onexit (internal/child_process.js:286:5)
(node:12) 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: 1)
(node:12) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.

on second try it worked

[brenzi]

this happened 4 out of 5 times...

[rozifus]

Thanks @brenzi, apologies from our end, and really appreciate your continued feedback on this issue :)

Given the numbers you've reported here it looks more like this might have been a side-effect of something we've recently changed. I'm going to prioritise finding a solution

[brenzi]

hmm, I just realized that my telemetry option doesn't specify a verbosity level. might cause trouble at startup....

[brenzi]

yeah, guess that was it. Would be good to forward node log to the user for quicker debug....

[brenzi]

nope, was just good luck. the same still happens

[rozifus]

I've just pushed a new version of gantree-cli@0.8.5.

This now checks for the RPC port to be ready before considering the substrate service to have been started. I'm not able to reproduce the issue currently so I wasn't able to confirm that this change had an effect, but if it is indeed a race condition on the RPC port becoming available I suspect this will fix it

[DrTexx]

Marking this resolved due to inactivity.

@brenzi please let us know if this is still occuring and we'll reopen this issue.