Issue with npm test in Zero-downtime multi-server deployment with NodeJS app

[Brain2life]

Issue

Error during execution of the Run Node.js API app tests Ansible task when provisioning VM in https://github.com/geerlingguy/ansible-for-devops/tree/master/deployments-rolling

Full log:

TASK [Run Node.js API app tests.] **********************************************
fatal: [192.168.56.2]: FAILED! => {"changed": true, "cmd": ["npm", "test"], "delta": "0:00:01.326310", "end": "2023-03-13 05:07:23.132796", "msg": "non-zero return code", "rc": 1, "start": "2023-03-13 05:07:21.806486", "stderr": "(node:4710) [DEP0111] DeprecationWarning: Access to process.binding('http_parser') is deprecated.\n(Use `node --trace-deprecation ...` to show where the warning was created)", "stderr_lines": ["(node:4710) [DEP0111] DeprecationWarning: Access to process.binding('http_parser') is deprecated.", "(Use `node --trace-deprecation ...` to show where the warning was created)"], "stdout": "\n> test\n> mocha test --exit\n\n\n\nrestify listening at http://[::]:8080\n  Hello\n    /hello/:name endpoint\n      ✓ returns a welcome message based on the name\n\n  Ping\n    /ping/:server endpoint\n      ✓ tells us when a server is reachable (129ms)\n\n  Ping\n    /ping/:server endpoint\n      ✓ tells us when a server is unreachable\n\n  1) tells us when a server is unreachable\n\n  3 passing (187ms)\n  1 failing\n\n  1) Ping\n       /ping/:server endpoint\n         tells us when a server is unreachable:\n     Uncaught Error [ERR_HTTP_HEADERS_SENT]: Cannot set headers after they are sent to the client\n      at new NodeError (node:internal/errors:387:5)\n      at ServerResponse.setHeader (node:_http_outgoing:644:11)\n      at ServerResponse.__send (node_modules/restify/lib/response.js:503:18)\n      at ServerResponse.send (node_modules/restify/lib/response.js:316:21)\n      at /opt/demo-nodejs-api/app.js:20:11\n      at Socket.<anonymous> (node_modules/jjg-ping/lib/ping-system.js:105:21)\n      at Socket.emit (node:events:513:28)\n      at Socket.emit (node:domain:489:12)\n      at addChunk (node:internal/streams/readable:315:12)\n      at readableAddChunk (node:internal/streams/readable:289:9)\n      at Socket.Readable.push (node:internal/streams/readable:228:10)\n      at Pipe.onStreamRead (node:internal/stream_base_commons:190:23)", "stdout_lines": ["", "> test", "> mocha test --exit", "", "", "", "restify listening at http://[::]:8080", "  Hello", "    /hello/:name endpoint", "      ✓ returns a welcome message based on the name", "", "  Ping", "    /ping/:server endpoint", "      ✓ tells us when a server is reachable (129ms)", "", "  Ping", "    /ping/:server endpoint", "      ✓ tells us when a server is unreachable", "", "  1) tells us when a server is unreachable", "", "  3 passing (187ms)", "  1 failing", "", "  1) Ping", "       /ping/:server endpoint", "         tells us when a server is unreachable:", "     Uncaught Error [ERR_HTTP_HEADERS_SENT]: Cannot set headers after they are sent to the client", "      at new NodeError (node:internal/errors:387:5)", "      at ServerResponse.setHeader (node:_http_outgoing:644:11)", "      at ServerResponse.__send (node_modules/restify/lib/response.js:503:18)", "      at ServerResponse.send (node_modules/restify/lib/response.js:316:21)", "      at /opt/demo-nodejs-api/app.js:20:11", "      at Socket.<anonymous> (node_modules/jjg-ping/lib/ping-system.js:105:21)", "      at Socket.emit (node:events:513:28)", "      at Socket.emit (node:domain:489:12)", "      at addChunk (node:internal/streams/readable:315:12)", "      at readableAddChunk (node:internal/streams/readable:289:9)", "      at Socket.Readable.push (node:internal/streams/readable:228:10)", "      at Pipe.onStreamRead (node:internal/stream_base_commons:190:23)"]}
fatal: [192.168.56.4]: FAILED! => {"changed": true, "cmd": ["npm", "test"], "delta": "0:00:01.293274", "end": "2023-03-13 05:07:23.731336", "msg": "non-zero return code", "rc": 1, "start": "2023-03-13 05:07:22.438062", "stderr": "(node:4692) [DEP0111] DeprecationWarning: Access to process.binding('http_parser') is deprecated.\n(Use `node --trace-deprecation ...` to show where the warning was created)", "stderr_lines": ["(node:4692) [DEP0111] DeprecationWarning: Access to process.binding('http_parser') is deprecated.", "(Use `node --trace-deprecation ...` to show where the warning was created)"], "stdout": "\n> test\n> mocha test --exit\n\n\n\nrestify listening at http://[::]:8080\n  Hello\n    /hello/:name endpoint\n      ✓ returns a welcome message based on the name\n\n  Ping\n    /ping/:server endpoint\n      ✓ tells us when a server is reachable (82ms)\n\n  Ping\n    /ping/:server endpoint\n      ✓ tells us when a server is unreachable\n      1) tells us when a server is unreachable\n\n  3 passing (143ms)\n  1 failing\n\n  1) Ping\n       /ping/:server endpoint\n         tells us when a server is unreachable:\n     Uncaught Error [ERR_HTTP_HEADERS_SENT]: Cannot set headers after they are sent to the client\n      at new NodeError (node:internal/errors:387:5)\n      at ServerResponse.setHeader (node:_http_outgoing:644:11)\n      at ServerResponse.__send (node_modules/restify/lib/response.js:503:18)\n      at ServerResponse.send (node_modules/restify/lib/response.js:316:21)\n      at /opt/demo-nodejs-api/app.js:20:11\n      at Socket.<anonymous> (node_modules/jjg-ping/lib/ping-system.js:105:21)\n      at Socket.emit (node:events:513:28)\n      at Socket.emit (node:domain:489:12)\n      at addChunk (node:internal/streams/readable:315:12)\n      at readableAddChunk (node:internal/streams/readable:289:9)\n      at Socket.Readable.push (node:internal/streams/readable:228:10)\n      at Pipe.onStreamRead (node:internal/stream_base_commons:190:23)", "stdout_lines": ["", "> test", "> mocha test --exit", "", "", "", "restify listening at http://[::]:8080", "  Hello", "    /hello/:name endpoint", "      ✓ returns a welcome message based on the name", "", "  Ping", "    /ping/:server endpoint", "      ✓ tells us when a server is reachable (82ms)", "", "  Ping", "    /ping/:server endpoint", "      ✓ tells us when a server is unreachable", "      1) tells us when a server is unreachable", "", "  3 passing (143ms)", "  1 failing", "", "  1) Ping", "       /ping/:server endpoint", "         tells us when a server is unreachable:", "     Uncaught Error [ERR_HTTP_HEADERS_SENT]: Cannot set headers after they are sent to the client", "      at new NodeError (node:internal/errors:387:5)", "      at ServerResponse.setHeader (node:_http_outgoing:644:11)", "      at ServerResponse.__send (node_modules/restify/lib/response.js:503:18)", "      at ServerResponse.send (node_modules/restify/lib/response.js:316:21)", "      at /opt/demo-nodejs-api/app.js:20:11", "      at Socket.<anonymous> (node_modules/jjg-ping/lib/ping-system.js:105:21)", "      at Socket.emit (node:events:513:28)", "      at Socket.emit (node:domain:489:12)", "      at addChunk (node:internal/streams/readable:315:12)", "      at readableAddChunk (node:internal/streams/readable:289:9)", "      at Socket.Readable.push (node:internal/streams/readable:228:10)", "      at Pipe.onStreamRead (node:internal/stream_base_commons:190:23)"]}
fatal: [192.168.56.5]: FAILED! => {"changed": true, "cmd": ["npm", "test"], "delta": "0:00:01.281178", "end": "2023-03-13 05:07:23.776612", "msg": "non-zero return code", "rc": 1, "start": "2023-03-13 05:07:22.495434", "stderr": "(node:4683) [DEP0111] DeprecationWarning: Access to process.binding('http_parser') is deprecated.\n(Use `node --trace-deprecation ...` to show where the warning was created)", "stderr_lines": ["(node:4683) [DEP0111] DeprecationWarning: Access to process.binding('http_parser') is deprecated.", "(Use `node --trace-deprecation ...` to show where the warning was created)"], "stdout": "\n> test\n> mocha test --exit\n\n\n\nrestify listening at http://[::]:8080\n  Hello\n    /hello/:name endpoint\n      ✓ returns a welcome message based on the name\n\n  Ping\n    /ping/:server endpoint\n      ✓ tells us when a server is reachable (83ms)\n\n  Ping\n    /ping/:server endpoint\n      ✓ tells us when a server is unreachable\n\n  1) tells us when a server is unreachable\n\n  3 passing (143ms)\n  1 failing\n\n  1) Ping\n       /ping/:server endpoint\n         tells us when a server is unreachable:\n     Uncaught Error [ERR_HTTP_HEADERS_SENT]: Cannot set headers after they are sent to the client\n      at new NodeError (node:internal/errors:387:5)\n      at ServerResponse.setHeader (node:_http_outgoing:644:11)\n      at ServerResponse.__send (node_modules/restify/lib/response.js:503:18)\n      at ServerResponse.send (node_modules/restify/lib/response.js:316:21)\n      at /opt/demo-nodejs-api/app.js:20:11\n      at Socket.<anonymous> (node_modules/jjg-ping/lib/ping-system.js:105:21)\n      at Socket.emit (node:events:513:28)\n      at Socket.emit (node:domain:489:12)\n      at addChunk (node:internal/streams/readable:315:12)\n      at readableAddChunk (node:internal/streams/readable:289:9)\n      at Socket.Readable.push (node:internal/streams/readable:228:10)\n      at Pipe.onStreamRead (node:internal/stream_base_commons:190:23)", "stdout_lines": ["", "> test", "> mocha test --exit", "", "", "", "restify listening at http://[::]:8080", "  Hello", "    /hello/:name endpoint", "      ✓ returns a welcome message based on the name", "", "  Ping", "    /ping/:server endpoint", "      ✓ tells us when a server is reachable (83ms)", "", "  Ping", "    /ping/:server endpoint", "      ✓ tells us when a server is unreachable", "", "  1) tells us when a server is unreachable", "", "  3 passing (143ms)", "  1 failing", "", "  1) Ping", "       /ping/:server endpoint", "         tells us when a server is unreachable:", "     Uncaught Error [ERR_HTTP_HEADERS_SENT]: Cannot set headers after they are sent to the client", "      at new NodeError (node:internal/errors:387:5)", "      at ServerResponse.setHeader (node:_http_outgoing:644:11)", "      at ServerResponse.__send (node_modules/restify/lib/response.js:503:18)", "      at ServerResponse.send (node_modules/restify/lib/response.js:316:21)", "      at /opt/demo-nodejs-api/app.js:20:11", "      at Socket.<anonymous> (node_modules/jjg-ping/lib/ping-system.js:105:21)", "      at Socket.emit (node:events:513:28)", "      at Socket.emit (node:domain:489:12)", "      at addChunk (node:internal/streams/readable:315:12)", "      at readableAddChunk (node:internal/streams/readable:289:9)", "      at Socket.Readable.push (node:internal/streams/readable:228:10)", "      at Pipe.onStreamRead (node:internal/stream_base_commons:190:23)"]}
fatal: [192.168.56.3]: FAILED! => {"changed": true, "cmd": ["npm", "test"], "delta": "0:00:01.303229", "end": "2023-03-13 05:07:23.569470", "msg": "non-zero return code", "rc": 1, "start": "2023-03-13 05:07:22.266241", "stderr": "(node:4693) [DEP0111] DeprecationWarning: Access to process.binding('http_parser') is deprecated.\n(Use `node --trace-deprecation ...` to show where the warning was created)", "stderr_lines": ["(node:4693) [DEP0111] DeprecationWarning: Access to process.binding('http_parser') is deprecated.", "(Use `node --trace-deprecation ...` to show where the warning was created)"], "stdout": "\n> test\n> mocha test --exit\n\n\n\nrestify listening at http://[::]:8080\n  Hello\n    /hello/:name endpoint\n      ✓ returns a welcome message based on the name\n\n  Ping\n    /ping/:server endpoint\n      ✓ tells us when a server is reachable (84ms)\n\n  Ping\n    /ping/:server endpoint\n      ✓ tells us when a server is unreachable\n\n  1) tells us when a server is unreachable\n\n  3 passing (149ms)\n  1 failing\n\n  1) Ping\n       /ping/:server endpoint\n         tells us when a server is unreachable:\n     Uncaught Error [ERR_HTTP_HEADERS_SENT]: Cannot set headers after they are sent to the client\n      at new NodeError (node:internal/errors:387:5)\n      at ServerResponse.setHeader (node:_http_outgoing:644:11)\n      at ServerResponse.__send (node_modules/restify/lib/response.js:503:18)\n      at ServerResponse.send (node_modules/restify/lib/response.js:316:21)\n      at /opt/demo-nodejs-api/app.js:20:11\n      at Socket.<anonymous> (node_modules/jjg-ping/lib/ping-system.js:105:21)\n      at Socket.emit (node:events:513:28)\n      at Socket.emit (node:domain:489:12)\n      at addChunk (node:internal/streams/readable:315:12)\n      at readableAddChunk (node:internal/streams/readable:289:9)\n      at Socket.Readable.push (node:internal/streams/readable:228:10)\n      at Pipe.onStreamRead (node:internal/stream_base_commons:190:23)", "stdout_lines": ["", "> test", "> mocha test --exit", "", "", "", "restify listening at http://[::]:8080", "  Hello", "    /hello/:name endpoint", "      ✓ returns a welcome message based on the name", "", "  Ping", "    /ping/:server endpoint", "      ✓ tells us when a server is reachable (84ms)", "", "  Ping", "    /ping/:server endpoint", "      ✓ tells us when a server is unreachable", "", "  1) tells us when a server is unreachable", "", "  3 passing (149ms)", "  1 failing", "", "  1) Ping", "       /ping/:server endpoint", "         tells us when a server is unreachable:", "     Uncaught Error [ERR_HTTP_HEADERS_SENT]: Cannot set headers after they are sent to the client", "      at new NodeError (node:internal/errors:387:5)", "      at ServerResponse.setHeader (node:_http_outgoing:644:11)", "      at ServerResponse.__send (node_modules/restify/lib/response.js:503:18)", "      at ServerResponse.send (node_modules/restify/lib/response.js:316:21)", "      at /opt/demo-nodejs-api/app.js:20:11", "      at Socket.<anonymous> (node_modules/jjg-ping/lib/ping-system.js:105:21)", "      at Socket.emit (node:events:513:28)", "      at Socket.emit (node:domain:489:12)", "      at addChunk (node:internal/streams/readable:315:12)", "      at readableAddChunk (node:internal/streams/readable:289:9)", "      at Socket.Readable.push (node:internal/streams/readable:228:10)", "      at Pipe.onStreamRead (node:internal/stream_base_commons:190:23)"]}

Tested on

Vagrant 2.3.4
Ansible 2.14.2
Python 3.9.2

[slavid]

I'm having the exact same issue. In the first run with vagrant up only 1 server had an error and the 3 other had 'changed' state, I ran vagrant destroy and ran vagrant up again and got 2 servers with errors and 2 which are fine.

If I re-run with ansible-playbook -i inventory playbooks/deploy.yml I get the following error:

TASK [Ensure Node.js API app is present.] ************************************************************************************************************************************************************************
fatal: [192.168.56.4]: FAILED! => {"ansible_facts": {"discovered_interpreter_python": "/usr/bin/python3"}, "before": "2a73724af5095247eef42ac84480b7bb0663b203", "changed": false, "msg": "Local modifications exist in the destination: /opt/demo-nodejs-api (force=no)."}
fatal: [192.168.56.3]: FAILED! => {"ansible_facts": {"discovered_interpreter_python": "/usr/bin/python3"}, "before": "2a73724af5095247eef42ac84480b7bb0663b203", "changed": false, "msg": "Local modifications exist in the destination: /opt/demo-nodejs-api (force=no)."}
fatal: [192.168.56.5]: FAILED! => {"ansible_facts": {"discovered_interpreter_python": "/usr/bin/python3"}, "before": "2a73724af5095247eef42ac84480b7bb0663b203", "changed": false, "msg": "Local modifications exist in the destination: /opt/demo-nodejs-api (force=no)."}
fatal: [192.168.56.2]: FAILED! => {"ansible_facts": {"discovered_interpreter_python": "/usr/bin/python3"}, "before": "2a73724af5095247eef42ac84480b7bb0663b203", "changed": false, "msg": "Local modifications exist in the destination: /opt/demo-nodejs-api (force=no)."}

I hope anyone can help us.

[skorupcia]

I have added 'force: yes' to git section of 'name: Ensure Node.js API app is present.' and it solved the issue.
Simply had to run command 3 times 😅

it should look like this:

  - name: Ensure Node.js API app is present.
    git:
      repo: "{{ app_repository }}"
      version: "{{ app_version }}"
      dest: "{{ app_directory }}"
      accept_hostkey: true
      force: yes
    register: app_updated
    notify: restart forever apps