`npm start -debug` exits

[samhavens]

I tried both Docker and non-Docker setup, and in both cases, when I get to the npm start --debug step, I get

[Tue Oct 25 2016 21:49:24 GMT+0000 (UTC)] ERROR 
error: Forever detected script exited with code: 0
error: Script restart attempt #1

until forever reaches its max number of attempts. Can't really figure out where it is having trouble.

I'd love to get this up and running, do you have any ideas?

[kengz]

Hey there, can you show the log before this?

[osthafen]

Hi, same for me - but I think I know why: in src/start-io.js the nlpServer is required but exists not in the filesystem via the setup: const { nlpServer } = require(path.join(__dirname, '..', '..', 'CGKB'))

[kengz]

It's installed in the node_modules. There's was a user with similar problem, and the cause was the version of nodejs. It runs on the latest v6 right now

[osthafen]

node --version v6.9.1 but path.join(__dirname, '..', '..', 'CGKB') doesn't point to node_modules ?

[kengz]

@osthafen can u check if your version of scripts/cgkb-demo.js is the same as the current master's? https://github.com/kengz/aiva/blob/cgkb/scripts/cgkb-demo.js

[osthafen]

I'm on the cgkb branch as instructed in https://explosion.ai/blog/chatbot-node-js-spacy

[osthafen]

If I change the line in src/start-io.js const { nlpServer } = require(path.join(__dirname, '..', '..', 'CGKB')) to const { nlpServer } = require('cgkb') the error is gone

[osthafen]

Then it runs until error: ERROR Expected number of IO clients failed to join in time

[osthafen]

and yes - scripts/cgkb-demo.js is the same

[kengz]

Oh I see, yep wrong path up there, thanks for catching. Just pushed an update to the branch.

[kengz]

Client-wise, is it expecting 4, and did cgkb-py join in time? shd look like

[Tue Oct 25 2016 22:19:54 GMT+0000 (UTC)] DEBUG import js lib from client.js
[Tue Oct 25 2016 22:19:54 GMT+0000 (UTC)] INFO Starting socketIO client for js at 6466
[Tue Oct 25 2016 22:19:54 GMT+0000 (UTC)] INFO Starting socketIO client for python3 at 6466
[Tue Oct 25 2016 22:19:54 GMT+0000 (UTC)] INFO Starting socketIO client for python3 at 6466
[Tue Oct 25 2016 22:19:54 GMT+0000 (UTC)] DEBUG Set SLACK PORT: 8345
[Tue Oct 25 2016 22:19:54 GMT+0000 (UTC)] DEBUG No WEBHOOK set for adapter SLACK
[Tue Oct 25 2016 22:19:54 GMT+0000 (UTC)] INFO Deploying bot aivadev with adapter SLACK
[Tue Oct 25 2016 22:19:54 GMT+0000 (UTC)] DEBUG js tGUCeLsU49jG976cAAAA joined, 3 remains
[Tue Oct 25 2016 22:19:54 GMT+0000 (UTC)] DEBUG py GFC-QEHJ5lfJJXfVAAAB joined, 2 remains
[Tue Oct 25 2016 22:19:56 GMT+0000 (UTC)] INFO Logged in as aiva-dev of Global Hackers
[Tue Oct 25 2016 22:19:56 GMT+0000 (UTC)] INFO Slack client now connected
[Tue Oct 25 2016 22:19:57 GMT+0000 (UTC)] DEBUG Started global js socketIO client for SLACK at 6466
[Tue Oct 25 2016 22:19:57 GMT+0000 (UTC)] DEBUG global-client-js mGYBTjUZfZy1tNsFAAAC joined, 1 remains
[Tue Oct 25 2016 22:20:07 GMT+0000 (UTC)] DEBUG cgkb-py fYzDdN6nJx0xG5U5AAAD joined, 0 remains
[Tue Oct 25 2016 22:20:07 GMT+0000 (UTC)] INFO All 4 IO clients have joined

[samhavens]

when I use Docker, my log first shows errors trying to connect to postgres, because, as far as I can tell, Docker doesn't install Postgres, only mysql. Then it says

npm run start --debug

> aiva@4.1.2 start /Users/samhavens/aiva
> bin/start

[ ----- Docker image kengz/aiva pulled, using it ------ ]
[ -------- Use Ctrl-p-q to detach bash session -------- ]\n
[ --- Docker container 'aiva-development' exists; attaching to it --- ]
[ ---------------- To run: supervisord ---------------- ]\n
aiva-development
 * Starting MySQL database server mysqld                                                             No directory, logging in with HOME=/
                                                                                              [ OK ]
root@0ddb8602d497:/var/www/aiva# service mysql start && NPM_RUN="development" supervisord
 * Starting MySQL database server mysqld                                                      [ OK ] 
/usr/lib/python2.7/dist-packages/supervisor/options.py:297: UserWarning: Supervisord is running as root and it is searching for its configuration file in default locations (including its current working directory); you probably want to specify a "-c" argument specifying an absolute path to a configuration file for improved security.
  'Supervisord is running as root and it is searching '
2016-10-25 21:49:18,429 CRIT Set uid to user 0
2016-10-25 21:49:18,429 WARN Included extra file "/etc/supervisor/conf.d/supervisord.conf" during parsing
2016-10-25 21:49:18,444 INFO RPC interface 'supervisor' initialized
2016-10-25 21:49:18,444 CRIT Server 'unix_http_server' running without any HTTP authentication checking
2016-10-25 21:49:18,444 INFO supervisord started with pid 559
2016-10-25 21:49:19,448 INFO spawned: 'run_nginx' with pid 562
2016-10-25 21:49:19,450 INFO spawned: 'run_aiva' with pid 563

> aiva@4.1.2 development /var/www/aiva
> mkdir -p ./logs; NODE_ENV=development ./node_modules/forever/bin/forever --minUptime=1000 --spinSleepTime=1000 --killSignal=SIGTERM --uid aiva-development -m 10 -a index.js | tee ./logs/aiva-development.log

2016-10-25 21:49:21,132 INFO success: run_nginx entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2016-10-25 21:49:21,132 INFO success: run_aiva entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
[Tue Oct 25 2016 21:49:24 GMT+0000 (UTC)] ERROR 
error: Forever detected script exited with code: 0
error: Script restart attempt #1

[osthafen]

[Tue Oct 25 2016 22:20:37 GMT+0000 (utc)] INFO Starting poly-socketio server on port: 6466, expecting 4 IO clients [Tue Oct 25 2016 22:20:37 GMT+0000 (utc)] DEBUG import js lib from client.js [Tue Oct 25 2016 22:20:37 GMT+0000 (utc)] INFO Starting socketIO client for js at 6466 [Tue Oct 25 2016 22:20:37 GMT+0000 (utc)] INFO Starting socketIO client for python3 at 6466 [Tue Oct 25 2016 22:20:37 GMT+0000 (utc)] DEBUG Set SLACK PORT: 8345 [Tue Oct 25 2016 22:20:37 GMT+0000 (utc)] DEBUG No WEBHOOK set for adapter SLACK [Tue Oct 25 2016 22:20:37 GMT+0000 (utc)] INFO Deploying bot xyz with adapter SLACK [Tue Oct 25 2016 22:20:37 GMT+0000 (utc)] INFO Starting socketIO client for python3 at 6466 [Tue Oct 25 2016 22:20:37 GMT+0000 (utc)] DEBUG js xA6Qgozmszvhi7SSAAAA joined, 3 remains [Tue Oct 25 2016 22:20:38 GMT+0000 (utc)] DEBUG py sD1UQGCwv7IQTr1vAAAB joined, 2 remains [Tue Oct 25 2016 22:20:52 GMT+0000 (utc)] ERROR {} [Tue Oct 25 2016 22:20:52 GMT+0000 (utc)] ERROR Expected number of IO clients failed to join in time [Tue Oct 25 2016 22:20:52 GMT+0000 (utc)] INFO Shutting down error: Forever detected script exited with code: 1 [Tue Oct 25 2016 22:20:52 GMT+0000 (utc)] INFO Exit: killed ioClient.js children [Tue Oct 25 2016 22:20:52 GMT+0000 (utc)] INFO Exit: killed ioClient.js children

[kengz]

@samhavens woops sorry I haven't rebuild the latest Docker - so it doesnt have postgres or spacy yet. A fast resolution would be to install the dependency by executing npm run setup inside the container. This runs the bin/setup file to install the dependencies

[samhavens]

@kengz no worries, I am not invested in using Docker, I was just getting a similar error without it, thought it might help the dependency situation. Thanks for taking to the time to write the article and help with debugging.

[samhavens]

When I do that, I run into trouble, I think because the Ubuntu container doesn't have postgres

root@79d2ac1b7289:/var/www/aiva# bin/setup
Nodejs is already installed
Python3 is already installed
bin/setup: line 69: sudo: command not found
postgresql: unrecognized service

[kengz]

@samhavens docker doesn't take sudo inside the container, bummer. Ok can u run these first:

# install postgres
if which postgres >/dev/null; then
  echo "Postgresql is already installed"
else
  if [ $(uname) == "Darwin" ]; then
    brew install postgres
    brew services start postgresql
    sleep 5
    createuser -s postgres
  else
    apt-get -y install postgresql postgresql-contrib
  fi
fi

# start postgres
UP=$(pgrep postgres | wc -l);
if [ "$UP" -eq 0 ];
then
  if [ $(uname) == "Darwin" ]; then
    brew services start postgresql
  else
    service postgresql start
  fi
else
  echo "Postgresql is already started"
fi

[osthafen]

@samhavens yes I had to install some missing dependencies, too. Running in a ubuntu-docker-container on a MAC Maybe my "ERROR Expected number of IO clients failed to join in time" is because of this container. I think I opened all ports for docker though - I'll doublecheck

[kengz]

then install spacy, neo4j, then the node modules:

pip install -U socketIO-client  # for communication with interface
pip install -U spacy
python -m spacy.en.download     # download spaCy's models

neo4j:

# install neo4j
if which neo4j >/dev/null; then
  echo "Neo4j is already installed"
else
  if [ $(uname) == "Darwin" ]; then
    brew install neo4j
  else
    wget -O - https://debian.neo4j.org/neotechnology.gpg.key | sudo apt-key add -
    echo 'deb http://debian.neo4j.org/repo stable/' | sudo tee /etc/apt/sources.list.d/neo4j.list
    apt-get update
    apt-get -y install neo4j
  fi
fi

# start neo4j
UP=$(pgrep neo4j | wc -l);
if [ "$UP" -eq 0 ];
then
  if [ $(uname) == "Darwin" ]; then
    neo4j start
  else
    service neo4j start
  fi
else
  echo "Neo4j is already started"
fi

finally npm install

[samhavens]

@kengz I just deleted the container and image, to force it to use my local config, and with the patch you pushed it is working now, but I am stuck in the same problem as @osthafen now. I am happy to help debug the Docker setup also, but here is the error @osthafen mentioned:

[Tue Oct 25 2016 22:30:03 GMT+0000 (UTC)] INFO Starting aiva process
[Tue Oct 25 2016 22:30:03 GMT+0000 (UTC)] DEBUG globalConfig {
  "BOTNAME": "kengzbot",
  "PORTS": {
    "NEO4J": 7476,
    "SOCKETIO": 6466,
    "SLACK": 8345,
    "TELEGRAM": 8443,
    "FB": 8545
  },
  "NGROK_AUTH": null,
  "ADMINS": [
    "samhavens@gmail.com"
  ],
  "TEST": {
    "HUBOT_SHELL_USER_ID": "ID0000001",
    "HUBOT_SHELL_USER_NAME": "alice"
  }
}
[Tue Oct 25 2016 22:30:03 GMT+0000 (UTC)] INFO Starting poly-socketio server on port: 6466, expecting 4 IO clients
[Tue Oct 25 2016 22:30:03 GMT+0000 (UTC)] DEBUG adapterConfig {
  "ACTIVATE": true,
  "HUBOT_SLACK_TOKEN": "REDACTED"
}
[Tue Oct 25 2016 22:30:03 GMT+0000 (UTC)] DEBUG import js lib from client.js
[Tue Oct 25 2016 22:30:03 GMT+0000 (UTC)] INFO Starting socketIO client for js at 6466
[Tue Oct 25 2016 22:30:03 GMT+0000 (UTC)] INFO Starting socketIO client for python3 at 6466
[Tue Oct 25 2016 22:30:03 GMT+0000 (UTC)] INFO Starting socketIO client for python3 at 6466
[Tue Oct 25 2016 22:30:03 GMT+0000 (UTC)] DEBUG Set SLACK PORT: 8345
[Tue Oct 25 2016 22:30:03 GMT+0000 (UTC)] DEBUG No WEBHOOK set for adapter SLACK
[Tue Oct 25 2016 22:30:03 GMT+0000 (UTC)] INFO Deploying bot testbot with adapter SLACK
[Tue Oct 25 2016 22:30:03 GMT+0000 (UTC)] DEBUG js zAYdrI-nyLSXUKbMAAAA joined, 3 remains
[Tue Oct 25 2016 22:30:03 GMT+0000 (UTC)] ERROR Traceback (most recent call last):
  File "/Users/samhavens/aiva/node_modules/spacy-nlp/src/client.py", line 14, in <module>
    from py import *
  File "/Users/samhavens/aiva/node_modules/spacy-nlp/src/py/nlp.py", line 2, in <module>
    from spacy.en import English  # NLP with spaCy https://spacy.io
ImportError: No module named 'spacy'

[Tue Oct 25 2016 22:30:03 GMT+0000 (UTC)] DEBUG py 9-i7ObbLeNq0uGcrAAAB joined, 2 remains
[Tue Oct 25 2016 22:30:04 GMT+0000 (UTC)] INFO Logged in as kengzbot of CarLabs
[Tue Oct 25 2016 22:30:05 GMT+0000 (UTC)] INFO Slack client now connected
[Tue Oct 25 2016 22:30:05 GMT+0000 (UTC)] DEBUG Started global js socketIO client for SLACK at 6466
DEPRECATION WARNING: The logging-option should be either a function or false. Default: console.log
[Tue Oct 25 2016 22:30:05 GMT+0000 (UTC)] DEBUG global-client-js M2nfxR34oGXYK2KQAAAC joined, 1 remains
[Tue Oct 25 2016 22:30:18 GMT+0000 (UTC)] ERROR {}
[Tue Oct 25 2016 22:30:18 GMT+0000 (UTC)] ERROR Expected number of IO clients failed to join in time
[Tue Oct 25 2016 22:30:18 GMT+0000 (UTC)] INFO Shutting down
[Tue Oct 25 2016 22:30:18 GMT+0000 (UTC)] INFO Exit: killed ioClient.js children
[Tue Oct 25 2016 22:30:18 GMT+0000 (UTC)] INFO Exit: killed ioClient.js children
error: Forever detected script exited with code: 1
error: Script restart attempt #2

Note, I have installed spaCy.

[kengz]

@osthafen yes the Docker image is old, sorry bout that. I'll rebuild a version tonight and update here :)

[samhavens]

Is it trying to connect to all adapters, even inactive ones?

[osthafen]

I didn't use your docker image - I took a plain ubuntu container and followed your steps at your post

[kengz]

@samhavens python version? Likely it is installed into 2. Aiva's internal process runs python3. Explicitly.

python3 -m pip install -U socketIO-client
python3 -m pip install -U spacy
python3 -m spacy.en.download

And nope it does not connect to inactive adapters. The timeout there is because spacy's adapter did not join.

[samhavens]

@kengz that's totally it, thank you!

[kengz]

@osthafen the 2 remaining clients did not join in time, perhaps they need a little longer. Here's a quick hack:

in src/start-io.js line 79, pass a longer waiting time argument, so the ioStart() looks like:

function ioStart() {
  polyIO.server({
      port: process.env.IOPORT,
      clientCount: CLIENT_COUNT,
      timeoutMs: 30000, # this is the increment
      debug: process.env['npm_config_debug']
    })
    .then(ioClient)
  return global.ioPromise
}

[osthafen]

thanks - now Slack is connected - but still: INFO Slack client now connected DEBUG Started global js socketIO client for SLACK at 6466 ERROR Expected number of IO clients failed to join in time

[kengz]

@osthafen hmm, I'm not sure how long does spacy take to load on your machine (the models are bout 1Gb total). Since it's not throwing cannot find module spacy, i'm assuming loading time is the problem.

Can you start a python bash process by just typing python in the terminal, then

import spacy
nlp = spacy.load('en')
doc = nlp('Bob brought Alice the pizza.')

and see how long it takes? Then adjust the timeoutMs to be longer for it.

[kengz]

@samhavens let me know if things are working or still not for you

[osthafen]

I canceled "forever" and now I've got a realy strange Error: npm start --debug path.js:1142 cwd = process.cwd(); ^

Error: ENOENT: no such file or directory, uv_cwd at Error (native) at Object.resolve (path.js:1142:25) at Function.Module._resolveLookupPaths (module.js:390:17) at Function.Module._resolveFilename (module.js:460:31) at Function.Module._load (module.js:417:25) at Module.require (module.js:497:17) at require (internal/module.js:20:19) at /usr/lib/node_modules/npm/bin/npm-cli.js:25:13 at Object. (/usr/lib/node_modules/npm/bin/npm-cli.js:75:3) at Module._compile (module.js:570:32)

[samhavens]

@kengz 👍 With the patch, and installing the deps with python3, it works locally! Thanks!

[samhavens]

[kengz]

@osthafen haha ok to clean up forever do a npm run stop then to make sure nothing gets stuck on the system, do a killall forever or ps ax | grep forever to check for any remianing processes

[kengz]

@samhavens kengzbot 😂 Ok awesome! I assume you can see the graph on localhost:7474 too. U can also clear the whole graph by saying clear kb to the bot.

[osthafen]

YES :-) INFO All 4 IO clients have joined Saved to brain ;-) Thank you very much! Very slow in my container though

[kengz]

@osthafen Awesome! what was the timeout u used? I'll increase the default longer so people dont face the same problem.

[osthafen]

I guess it's pythons fault: cgkb.add(text) in cgkb-demo.js gives sometimes:

[Tue Oct 25 2016 23:17:57 GMT+0000 (utc)] DEBUG IO on pass, msg: { "hash": "global-client-js_03ff58bc98667df002c8d22e9bdd444b", "from": "global-client-js", "input": "why are you so slow?", "to": "nlp.cgkb-py", "intent": "parse" } fn: undefined Unhandled rejection TimeoutError: operation timed out at ontimeout (timers.js:365:14) at tryOnTimeout (timers.js:237:5) at Timer.listOnTimeout (timers.js:207:5) From previous event: at cdefer (/var/www/html/bot/aiva/node_modules/poly-socketio/src/global-client.js:93:6) at Socket.pass (/var/www/html/bot/aiva/node_modules/poly-socketio/src/global-client.js:36:15) at Object.parse (/var/www/html/bot/aiva/node_modules/spacy-nlp/src/nlp.js:16:24) at Object. (/var/www/html/bot/aiva/node_modules/CGKB/src/cgkb.js:43:27) at undefined.next (native) at onFulfilled (/var/www/html/bot/aiva/node_modules/co/index.js:65:19) at /var/www/html/bot/aiva/node_modules/co/index.js:54:5 From previous event: at Object.co (/var/www/html/bot/aiva/node_modules/co/index.js:50:10) at Object.createPromise as add at TextListener.robot.respond as callback at /var/www/html/bot/aiva/node_modules/hubot/src/listener.coffee:65:12 at allDone (/var/www/html/bot/aiva/node_modules/hubot/src/middleware.coffee:44:37) at /var/www/html/bot/aiva/node_modules/hubot/node_modules/async/lib/async.js:274:13 at Object.async.eachSeries (/var/www/html/bot/aiva/node_modules/hubot/node_modules/async/lib/async.js:142:20) at Object.async.reduce (/var/www/html/bot/aiva/node_modules/hubot/node_modules/async/lib/async.js:268:15) at /var/www/html/bot/aiva/node_modules/hubot/src/middleware.coffee:49:13 at _combinedTickCallback (internal/process/next_tick.js:67:7) at process._tickCallback (internal/process/next_tick.js:98:9)

[osthafen]

timeoutMs: 160000,

[kengz]

Yeah that warning, if the node picks up any input and tries to send it to the python client, before python joins, then the promise misses. It's not harmful. Generally I'd wait till everything has joined to start talking.

[kengz]

👍 thanks for discovering the issues guys. Closing this, have fun! :)

[osthafen]

Thanks again for your great work!