Bug 1038492 - NodeJS app hot_deploy still taking server down
Summary: NodeJS app hot_deploy still taking server down
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: OpenShift Online
Classification: Red Hat
Component: Image
Version: 2.x
Hardware: Unspecified
OS: Unspecified
medium
low
Target Milestone: ---
: ---
Assignee: Ben Parees
QA Contact: libra bugs
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2013-12-05 08:13 UTC by Alex Knol
Modified: 2015-05-15 00:35 UTC (History)
8 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2014-04-09 15:17:40 UTC
Target Upstream Version:
bparees: needinfo+


Attachments (Terms of Use)

Description Alex Knol 2013-12-05 08:13:33 UTC
Description of problem:
We are using a node 0.10 cartridge to run our web app with hot_deploy enabled. The application is, however, being taken down when openshift start building the cartridge. 

Version-Release number of selected component (if applicable):


How reproducible:


Steps to Reproduce:
1. create a NodeJS app
2. add hot_deploy marker
3. push app
4. change something
5. push again
6. watch app become unavailable 503

Actual results:
Counting objects: 13, done.
Delta compression using up to 8 threads.
Compressing objects: 100% (7/7), done.
Writing objects: 100% (7/7), 727 bytes, done.
Total 7 (delta 4), reused 0 (delta 0)
remote: Not stopping cartridge nodejs because hot deploy is enabled        
remote: hot_deploy marker found. Switching to using supervisor. Subsequent pushes won't require restart until the marker is removed.        
remote: Saving away previously installed Node modules        
remote: Building git ref 'master', commit ed05c5f        
remote: Building NodeJS cartridge  <-- at this point the app goes down. service not available.
....
It comes up right after build is done
....
remote: ...done        < ----- here it's back
remote: Not starting cartridge nodejs because hot deploy is enabled        
remote: hot_deploy marker found. Switching to using supervisor. Subsequent pushes won't require restart until the marker is removed.        
remote: Result: success        
remote: Activation status: success        
remote: Deployment completed with status: success  

Expected results:
Not to take the app down

Additional info:

Comment 1 Andy Goldstein 2013-12-05 14:49:14 UTC
From what I understand, all supervisor does is spawn a child process ("node server.js" in our case) and it will restart the child process when files it's watching are modified. This means there will be a small window of downtime, even when using supervisor.

Reassigning to Mrunal for review/comments.

Comment 3 Alex Knol 2013-12-05 23:42:26 UTC
It looks like to npm build process is what's taking node (supervisor) down

Watching the log a deploy, looks like the repo dir, or at least the node_modules dir is emptied:

###############################################################################

DEBUG: crashing child
DEBUG: Starting child process with 'node server.js'
DEBUG: crashing child
DEBUG: Starting child process with 'node server.js'
DEBUG: crashing child
DEBUG: Starting child process with 'node server.js'

module.js:340
    throw err;
          ^
Error: Cannot find module '/var/lib/openshift/529f8c225973ca844d000080/app-root/runtime/repo/server.js'
    at Function.Module._resolveFilename (module.js:338:15)
    at Function.Module._load (module.js:280:25)
    at Function.Module.runMain (module.js:497:10)
    at startup (node.js:119:16)
    at node.js:901:3
DEBUG: crashing child
DEBUG: Starting child process with 'node server.js'

module.js:340
    throw err;
          ^
Error: Cannot find module 'coffee-script'
    at Function.Module._resolveFilename (module.js:338:15)
    at Function.Module._load (module.js:280:25)
    at Module.require (module.js:364:17)
    at require (module.js:380:17)
    at Object.<anonymous> (/var/lib/openshift/529f8c225973ca844d000080/app-root/runtime/repo/server.js:5:3)
    at Object.<anonymous> (/var/lib/openshift/529f8c225973ca844d000080/app-root/runtime/repo/server.js:22:4)
    at Module._compile (module.js:456:26)
    at Object.Module._extensions..js (module.js:474:10)
    at Module.load (module.js:356:32)
    at Function.Module._load (module.js:312:12)
DEBUG: Starting child process with 'node server.js'
DEBUG: crashing child

node.js:728
        throw errnoException(process._errno, 'kill');
              ^
Error: kill ESRCH
    at errnoException (node.js:540:13)
    at process.kill (node.js:728:15)
    at null._onTimeout (/opt/rh/nodejs010/root/usr/lib/node_modules/supervisor/lib/supervisor.js:238:15)
    at Timer.listOnTimeout [as ontimeout] (timers.js:110:15)

module.js:340
    throw err;
          ^
Error: Cannot find module 'coffee-script'
    at Function.Module._resolveFilename (module.js:338:15)
    at Function.Module._load (module.js:280:25)
    at Module.require (module.js:364:17)
    at require (module.js:380:17)
    at Object.<anonymous> (/var/lib/openshift/529f8c225973ca844d000080/app-root/runtime/repo/server.js:5:3)
    at Object.<anonymous> (/var/lib/openshift/529f8c225973ca844d000080/app-root/runtime/repo/server.js:22:4)
    at Module._compile (module.js:456:26)
    at Object.Module._extensions..js (module.js:474:10)
    at Module.load (module.js:356:32)
    at Function.Module._load (module.js:312:12)

#############################################################################

Later on I see this:
Error: ENOENT, stat '/var/lib/openshift/529f8c225973ca844d000080/app-root/runtime/repo/public/app.html'

This is a build process I run on the server (minification and joining) with brunch.io. This means that this dir must emptied.

I thought I could remedy this with this in my deploy hook (post_deploy)
But I guess that didn't help.

echo start building...
cd $OPENSHIFT_REPO_DIR
if ! gem spec sass > /dev/null 2>&1; then
  echo "Gem sass is not installed, installing it..."
  gem install sass --no-rdoc --no-ri
  echo Done installing sass
fi
export PATH=$PATH:$GEM_HOME/bin
node_modules/.bin/brunch build --production
export pub_folder=production
echo switching to $pub_folder
rsync -rtvu --delete-delay production/ public/
export pub_folder=public
echo switching back to $pub_folder
rm -rf production

echo ...done

Comment 4 Ben Parees 2014-01-14 23:03:55 UTC
Alex is your issue that the app never comes back up?  Or that there is a period of unavailability (should be very brief)

As Andy noted, there will always be a small window of downtime as the node process must be restarted by the supervisor when the files change.

Comment 5 Alex Knol 2014-01-15 19:01:49 UTC
the app comes back up, but it takes a few minutes, not what I call brief.

I appreciate that Supervisor needs some time to restart node after file changes, but as you can see in the posted logs, supervisor can't find files.

Am I the only one? Am i doing something wrong?

Comment 6 Ben Parees 2014-01-15 19:24:49 UTC
the app-root/repo/node_modules directory will always start out empty during each deployment, and then be populated by the build(npm) process.  Unless you have checked files into node_modules in your app repo directly and pushed them.

There are some issues with hot deploy for nodeJS that are currently being worked on:

https://bugzilla.redhat.com/show_bug.cgi?id=1043819
https://bugzilla.redhat.com/show_bug.cgi?id=1048756  (does not mention hot deploy but is caused by the same underlying problem).

However neither of those issues look like the issue you are seeing, it definitely does not normally take several minutes for the app to become available again, even without hot_deploy.  

There was another issue with the nodeJS cartridge in december when we switched from only using supervisor for hot_deploy mode, to using supervisor at all times.  Can you confirm you are still seeing this error behavior today?

Comment 7 Ben Parees 2014-02-04 20:03:42 UTC
Are you still having this issue?

Comment 8 Alex Knol 2014-02-05 19:18:35 UTC
Let me check today, but a few days ago it was still there.

Comment 9 Bob Masters 2014-02-06 09:28:47 UTC
Using the Node 0.10 cart', I added the hot_deploy marker, but it restarts with this:

Thu Feb 06 2014 04:09:54 GMT-0500 (EST): Stopping application 'nodeworld' ...
Thu Feb 06 2014 04:09:55 GMT-0500 (EST): Stopped Node application 'nodeworld'
Thu Feb 06 2014 04:09:55 GMT-0500 (EST): Starting application 'nodeworld' ...
/usr/bin/tail: nodejs/logs/node.log: file truncated

DEBUG: Running node-supervisor with
DEBUG:   program 'server.js'
DEBUG:   --watch '.'
DEBUG:   --ignore 'undefined'
DEBUG:   --extensions 'node|js|coffee'
DEBUG:   --exec 'node'

DEBUG: Starting child process with 'node server.js'
DEBUG: Watching directory '/var/lib/openshift/52f320195004461ec000002f/app-root/
runtime/repo' for changes.
Express & WebSocket server listening on port 8080 for IP 127.6.102.1.
World configuration loaded from database.

==> rockmongo/logs/error_log-20140206-000000-EST <==
PHP Warning:  Module 'mongo' already loaded in Unknown on line 0
[Thu Feb 06 04:10:17 2014] [notice] Digest: generating secret for digest authent
ication ...
[Thu Feb 06 04:10:17 2014] [notice] Digest: done
[Thu Feb 06 04:10:17 2014] [notice] Apache/2.2.22 (Unix) PHP/5.3.3 configured --
 resuming normal operations

==> nodejs/logs/node.log <==
GET / 200 1184ms - 5.83kb
GET / 200 61ms - 5.83kb
DEBUG: crashing child
DEBUG: Starting child process with 'node server.js'
DEBUG: crashing child
DEBUG: Starting child process with 'node server.js'
DEBUG: crashing child
DEBUG: Starting child process with 'node server.js'

module.js:340
    throw err;
          ^
Error: Cannot find module 'socket.io'
    at Function.Module._resolveFilename (module.js:338:15)
    at Function.Module._load (module.js:280:25)
    at Module.require (module.js:364:17)
    at require (module.js:380:17)
    at Object.<anonymous> (/var/lib/openshift/52f320195004461ec000002f/app-root/
runtime/repo/server.js:38:8)
    at Module._compile (module.js:456:26)
    at Object.Module._extensions..js (module.js:474:10)
    at Module.load (module.js:356:32)
    at Function.Module._load (module.js:312:12)
    at Function.Module.runMain (module.js:497:10)
DEBUG: Program node server.js exited with code 8

DEBUG: Starting child process with 'node server.js'

module.js:340
    throw err;
          ^
Error: Cannot find module 'socket.io'
    at Function.Module._resolveFilename (module.js:338:15)
    at Function.Module._load (module.js:280:25)
    at Module.require (module.js:364:17)
    at require (module.js:380:17)
    at Object.<anonymous> (/var/lib/openshift/52f320195004461ec000002f/app-root/
runtime/repo/server.js:38:8)
    at Module._compile (module.js:456:26)
    at Object.Module._extensions..js (module.js:474:10)
    at Module.load (module.js:356:32)
    at Function.Module._load (module.js:312:12)
    at Function.Module.runMain (module.js:497:10)
DEBUG: Program node server.js exited with code 8

DEBUG: Starting child process with 'node server.js'

module.js:340
    throw err;
          ^
Error: Cannot find module 'socket.io'
    at Function.Module._resolveFilename (module.js:338:15)
    at Function.Module._load (module.js:280:25)
    at Module.require (module.js:364:17)
    at require (module.js:380:17)
    at Object.<anonymous> (/var/lib/openshift/52f320195004461ec000002f/app-root/
runtime/repo/server.js:38:8)
    at Module._compile (module.js:456:26)
    at Object.Module._extensions..js (module.js:474:10)
    at Module.load (module.js:356:32)
    at Function.Module._load (module.js:312:12)
    at Function.Module.runMain (module.js:497:10)
DEBUG: Program node server.js exited with code 8

DEBUG: Starting child process with 'node server.js'

And then it starts normally and works.

I need supervisor to --watch only my 'server.js' file. The other files are supposed to be changed and reloaded during runtime, without restarting the server. I do this, when testing on my machine.

Comment 10 Ben Parees 2014-02-11 23:33:37 UTC
regarding comment 9, can you open a separate bug/RFE for allowing supervisor to only watch server.js?

Comment 11 Bob Masters 2014-02-15 19:25:27 UTC
(In reply to Ben Parees from comment #10)
> regarding comment 9, can you open a separate bug/RFE for allowing supervisor
> to only watch server.js?

It would be my pleasure.

Comment 12 Michal Fojtik 2014-03-11 11:57:57 UTC
You can now use the 'OPENSHIFT_NODEJS_WATCH' environment variable to change what the supervisor should watch for changes. Note that the supervisor is currently limited to watch only whole directories, not just files.

There is a Trello card to change the current default behavior (iow watching the whole repo dir) and restrict watching to just single file that is touched after each deploy (in hot_deploy mode).

https://trello.com/c/Z0dieVkU/156-1-add-support-for-pseudo-hot-deploy-into-nodejs-npm-devexp

This should be part of the next release.


Note You need to log in before you can comment on or make changes to this bug.