request times out... see UnhandledPromiseRejectionWarning: "listener" argument must be a function

[meowsbits]

Describe the bug jade-service-runner times out on my request.

To Reproduce

$ cat /etc/systemd/system/jade_service_runner.service
[Unit]
Description=Jade Service Runner

[Service]
Type=simple
User=ia
Restart=always
RestartSec=3
TimeoutStopSec=10min
ExecStart=/bin/sh -c 'JADE_DEBUG=1 /home/ia/.nvm/versions/node/v13.1.0/bin/jade-service-runner -d /home/ia/jade-services -c ~/dev/meowsbits/stargate-sg1/jade-extended-config.json'

[Install]
WantedBy=default.target

$ systemctl [re]start jade_service_runner.service

$ http --verbose --timeout 5 --json POST localhost:8002 id=0 method=listServices params:=[]

http: error: Request timed out (5.0s).

(The less fancy curl - as below - gives same result.)

$ curl -X POST -d '{"method": "listServices", params:[], "id": "0"}' localhost:8002
curl: (52) Empty reply from server

$ journalctl -u jade_service_runner.service -f
Hint: You are currently not seeing messages from other users and the system.
      Users in groups 'adm', 'systemd-journal' can see all messages.
      Pass -q to turn off this notice.
-- Logs begin at Fri 2019-10-18 17:07:27 EDT. --
Nov 12 14:57:21 ubp52 sh[21592]: (node:21593) 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(). (rejection id: 9)
Nov 12 15:02:34 ubp52 sh[24339]: (node:24344) ExperimentalWarning: The http2 module is an experimental API.
Nov 12 15:02:34 ubp52 sh[24339]: (node:24344) Warning: N-API is an experimental feature and could change at any time.
Nov 12 15:02:34 ubp52 sh[24339]: info: Service Runner port starting on [object Object] {"service":"ServiceRunner","context":"startServiceRunner","path":"/"}
Nov 12 15:02:34 ubp52 sh[24339]: debug: Service Runner internal port starting on 37155 {"service":"ServiceRunner","context":"startServiceRunner","path":"/"}
Nov 12 15:02:34 ubp52 sh[24339]: debug: added service / with 37155 http to routing table {"service":"ServiceRunner","context":"Router","path":"/"}
Nov 12 15:02:34 ubp52 sh[24339]: debug: setting up connections {"service":"ServiceRunner","context":"ProxyServer","path":"/"}
Nov 12 15:02:34 ubp52 sh[24339]: debug: listening on 8002 {"service":"ServiceRunner","context":"httpFrontend","path":"/"}
Nov 12 15:02:34 ubp52 sh[24339]: debug: set up connections {"service":"ServiceRunner","context":"ProxyServer","path":"/"}
Nov 12 15:02:34 ubp52 sh[24339]: info: Service Runner started on [object Object] {"service":"ServiceRunner","context":"startServiceRunner","path":"/"}
Nov 12 15:02:40 ubp52 sh[24339]: debug: Requesting connection be established {"service":"ServiceRunner","context":"httpFrontend","path":"/"}
Nov 12 15:02:40 ubp52 sh[24339]: debug: established http connection {"service":"ServiceRunner","context":"httpFrontend","path":"/"}
Nov 12 15:02:40 ubp52 sh[24339]: debug: forwarding request [object Object] POST {"id":"0","method":"listServices","params":[]} {"service":"ServiceRunner","context":"httpFrontend","path":"/"}
Nov 12 15:02:40 ubp52 sh[24339]: debug: making request to backend on port 37155 with {"id":"0","method":"listServices","params":[]} {"service":"ServiceRunner","context":"HttpBackend","path":"/"}
Nov 12 15:02:40 ubp52 sh[24339]: (node:24344) UnhandledPromiseRejectionWarning: TypeError: "listener" argument must be a function
Nov 12 15:02:40 ubp52 sh[24339]:     at ClientRequest.once (events.js:340:11)
Nov 12 15:02:40 ubp52 sh[24339]:     at new ClientRequest (_http_client.js:164:10)
Nov 12 15:02:40 ubp52 sh[24339]:     at Object.request (http.js:38:10)
Nov 12 15:02:40 ubp52 sh[24339]:     at Promise (/home/ia/.nvm/versions/node/v13.1.0/lib/node_modules/@etclabscore/jade-service-runner/build/src/lib/backends/httpBackend.js:31:44)
Nov 12 15:02:40 ubp52 sh[24339]:     at new Promise (<anonymous>)
Nov 12 15:02:40 ubp52 sh[24339]:     at Object.send (/home/ia/.nvm/versions/node/v13.1.0/lib/node_modules/@etclabscore/jade-service-runner/build/src/lib/backends/httpBackend.js:27:16)
Nov 12 15:02:40 ubp52 sh[24339]:     at ConnectionManager.forwardRequest (/home/ia/.nvm/versions/node/v13.1.0/lib/node_modules/@etclabscore/jade-service-runner/build/src/lib/connectionManager.js:61:53)
Nov 12 15:02:40 ubp52 sh[24339]:     at EventEmitter.connectionBus.on (/home/ia/.nvm/versions/node/v13.1.0/lib/node_modules/@etclabscore/jade-service-runner/build/src/lib/connectionManager.js:108:18)
Nov 12 15:02:40 ubp52 sh[24339]:     at emitOne (events.js:116:13)
Nov 12 15:02:40 ubp52 sh[24339]:     at EventEmitter.emit (events.js:211:7)
Nov 12 15:02:40 ubp52 sh[24339]: (node:24344) 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(). (rejection id: 3)
Nov 12 15:02:40 ubp52 sh[24339]: (node:24344) [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.

Expected behavior Not to silently time out; at least an error message.

Desktop (please complete the following information):

$ jade-service-runner -v                                                                                                                │
1.7.4

$ node -v && npm -v && uname -a
v13.1.0
6.12.1
Linux ubp52 5.2.9-050209-generic #201908160940 SMP Fri Aug 16 09:42:58 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux

[meowsbits]

Just noting that I also get this when running my oh-so-fancy new jade-service-runner-cli (generated with the tool over at https://github.com/gregdhill/go-openrpc)

$ jade-service-runner-cli --http-addr 'http://localhost:8002' listServices

(

$ jade-service-runner-cli --help
This is an auto-generated CLI interface for an Open-RPC compliant API.

Open-RPC Version: 1.1.2

Run 'jade-service-runner-cli completion --help' to learn about auto-auto-completion! It's easy!

Usage:
  jade-service-runner-cli [command]

Available Commands:
  completion            Generates bash completion scripts
  help                  Help about any command
  installService
  listInstalledServices
  listRunningServices
  listServices
  startService

Flags:
      --config string      config file (default is $HOME/.jade-service-runner-cli.yaml)
  -h, --help               help for jade-service-runner-cli
      --http-addr string   Address for JSON-RPC HTTP calls (default "http://localhost:8545")
  -t, --toggle             Help message for toggle

Use "jade-service-runner-cli [command] --help" for more information about a command.

)

[shanejonas]

seems pretty odd, maybe missing content type application/json ?

[meowsbits]

$ curl --max-time 5 -X POST -H 'Content-Type: application/json' -d '{"method": "listServices", "params":[], "id": "0"}' localhost:8002
curl: (28) Operation timed out after 5001 milliseconds with 0 bytes received

$ http  --verbose --timeout 5 --json post http://localhost:8002 id=0 method=list_services params:=[] Content-Type:application/json

http: error: Request timed out (5.0s).

and the gen'd CLI is also definitely setting the header.