Forum is not available anymore

Nicolas

Any ideas why ./nodebb start does not work, and ./nodebb dev works?
Anything I could do to rebuild something in a less harmful way to try ./nodebb start?
Any suggestions why Express does not work in production mode?

Nicolas

So I'm debugging Express, in production, Route registration does not happen. For example, in debug mode I see logs like:

  express:router:route get /user/:userslug/edit/password +0ms
  express:router:layer new / +0ms
  express:router:route get /user/:userslug/edit/password +0ms
  express:router:layer new / +0ms
  express:router:route get /user/:userslug/edit/password +0ms
  express:router:layer new / +0ms
  express:router:route new /api/user/:userslug/edit/password +0ms
  express:router:layer new /api/user/:userslug/edit/password +0ms
  express:router:route get /api/user/:userslug/edit/password +0ms
  express:router:layer new / +0ms
  express:router:route get /api/user/:userslug/edit/password +0ms
  express:router:layer new / +0ms
  express:router:route get /api/user/:userslug/edit/password +0ms
  express:router:layer new / +0ms
  express:router:route get /api/user/:userslug/edit/password +0ms
  express:router:layer new / +0ms
  express:router:route get /api/user/:userslug/edit/password +0ms
  express:router:layer new / +0ms
  express:router:route new /user/:userslug/settings +0ms
  express:router:layer new /user/:userslug/settings +0ms
  express:router:route get /user/:userslug/settings +0ms
  express:router:layer new / +0ms
  express:router:route get /user/:userslug/settings +1ms
  express:router:layer new / +0ms
  express:router:route get /user/:userslug/settings +0ms
  express:router:layer new / +0ms
  express:router:route get /user/:userslug/settings +0ms
  express:router:layer new / +0ms
  express:router:route get /user/:userslug/settings +0ms
  express:router:layer new / +0ms
  express:router:route get /user/:userslug/settings +0ms
  express:router:layer new / +0ms
  express:router:route get /user/:userslug/settings +0ms
  express:router:layer new / +0ms
  express:router:route new /api/user/:userslug/settings +0ms
  express:router:layer new /api/user/:userslug/settings +0ms
  express:router:route get /api/user/:userslug/settings +0ms
  express:router:layer new / +0ms
  express:router:route get /api/user/:userslug/settings +0ms
  express:router:layer new / +0ms
  express:router:route get /api/user/:userslug/settings +0ms
  express:router:layer new / +0ms
  express:router:route get /api/user/:userslug/settings +0ms
  express:router:layer new / +0ms
  express:router:route get /api/user/:userslug/settings +0ms
  express:router:layer new / +0ms
  express:router:route new /user/:userslug/session/:uuid +0ms
  express:router:layer new /user/:userslug/session/:uuid +0ms
  express:router:route delete /user/:userslug/session/:uuid +0ms

But in production mode I can see only initial Express operations:

express:application set "x-powered-by" to true +0ms
  express:application set "etag" to 'weak' +1ms
  express:application set "etag fn" to [Function: wetag] +1ms
  express:application set "env" to 'development' +0ms
  express:application set "query parser" to 'extended' +0ms
  express:application set "query parser fn" to [Function: parseExtendedQueryString] +0ms
  express:application set "subdomain offset" to 2 +0ms
  express:application set "trust proxy" to false +0ms
  express:application set "trust proxy fn" to [Function: trustNone] +1ms
  express:application booting in development mode +0ms
  express:application set "view" to [Function: View] +0ms
  express:application set "views" to '/web/overseers/node/forum/views' +0ms
  express:application set "jsonp callback name" to 'callback' +0ms
  express:application set "view engine" to 'tpl' +85ms
  express:application set "views" to '/web/overseers/node/forum/public/templates' +1ms
  express:application set "json spaces" to 0 +0ms
  express:router use / query +0ms
  express:router:layer new / +1ms
  express:router use / expressInit +0ms
  express:router:layer new / +0ms
  express:router use / <anonymous> +0ms
  express:router:layer new / +0ms
  express:application set "view cache" to true +1ms
  express:router use / compression +0ms
  express:router:layer new / +0ms
  express:router use  favicon +0ms
  express:router:layer new  +0ms
  express:router use /apple-touch-icon <anonymous> +0ms
  express:router:layer new /apple-touch-icon +0ms
  express:router use / urlencodedParser +26ms
  express:router:layer new / +1ms
  express:router use / jsonParser +0ms
  express:router:layer new / +0ms
  express:router use / cookieParser +0ms
  express:router:layer new / +0ms
  express:router use / <anonymous> +1ms
  express:router:layer new / +0ms
  express:router use / session +0ms
  express:router:layer new / +0ms
  express:router use / <anonymous> +0ms
  express:router:layer new / +0ms
  express:router use / <anonymous> +1ms
  express:router:layer new / +0ms
  express:router use / initialize +0ms
  express:router:layer new / +0ms
  express:router use / authenticate +0ms
  express:router:layer new / +0ms
  express:router use / <anonymous> +0ms
  express:router:layer new / +0ms
  express:router use / <anonymous> +1ms
  express:router:layer new / +0ms
  express:application set "cache" to true +1ms
  express:application set "minification" to true +0ms

That is why even the basic root route does not work since none of them are registered. Any hints where to look next?

Nicolas

@psychobunny @baris what am I risking by running forum as NODE_ENV=development ./nodebb start?

PitaJ

My guess is corrupted files. You can try setting up a new nodebb instance with a copy of your database.

Since it's affected by node_env it could be a nodebb file that was corrupted. Have you tried using git to detect a file diff?

Running with an ancient version of NodeBB is probably more dangerous than running in development mode. Might make MITM a little more likely.

<baris>

Can you post the output of git status as well?

You can always add console.logs into src/routes.js and webserver js to debug.

PitaJ

You might also want to try git diff --name-status HEAD^ as git status uses file size and modification time.

Nicolas

@baris Git Status

$ git status
On branch v1.x.x
Your branch is up-to-date with 'origin/v1.x.x'.
nothing to commit, working directory clean

@PitaJ Git DIff is package.json only. Likely because I have plugins.

<baris>

I am not sure if 1.0.2 has ./nodebb plugins command but if it has run that and paste the output. If it doesn't have that command you can run the following in mongodb cli db.objects.find({_key: "plugins:active"});

Also put a console.log here and check if it is triggered in dev and ./nodebb start.

Nicolas

@baris plugins command output:

$ ./nodebb plugins
5/3 04:06 [30726] - info: [database] Checking database indices.
5/3 04:06 [30726] - info: Active plugins:
	 - nodebb-theme-overseers
	 - nodebb-widget-essentials
	 - nodebb-plugin-soundpack-default
	 - nodebb-plugin-mentions
	 - nodebb-plugin-markdown
	 - nodebb-plugin-emoji-apple
	 - nodebb-plugin-emoji-extended
	 - nodebb-plugin-composer-default
	 - nodebb-plugin-ns-api
	 - nodebb-plugin-ns-likes
	 - nodebb-plugin-ns-login
	 - nodebb-plugin-ns-points
	 - nodebb-plugin-ns-slugify
	 - nodebb-plugin-write-api
	 - nodebb-plugin-ns-embed
	 - nodebb-plugin-dbsearch
	 - nodebb-plugin-ns-custom-fields
	 - nodebb-plugin-ns-awards
	 - nodebb-widget-ns-birthdays
	 - nodebb-widget-ns-stats
	 - nodebb-plugin-emailer-mailgun
	 - nodebb-plugin-google-analytics

Interesting, any of these plugins interact with external services maybe? That is why it's stopped working. If no changes to local plugins like my ("NS") or others, it should still work without any issues.

As for console.log, it's triggered for ./nodebb dev, but it is not triggered for ./nodebb start

<baris>

@nicolas Ok if it's not triggering for ./nodebb start you will have to add some more console.logs in here basically add a console.log for each block in that async.waterfall(). My guess is one of the steps before routes(app, middleware); is breaking in production mode, like a build step or a plugin that uses static:app.preload. Change the code to look like this .

async.waterfall([
	async.apply(cacheStaticFiles),
	async.apply(meta.themes.setupPaths),
	function(next) {
		console.log('1');
		plugins.init(app, middleware, next);
	},
	function(next) {
		console.log('2');
		async.parallel([
			async.apply(meta.templates.compile),
			async.apply(!skipJS ? meta.js.minify : meta.js.getFromFile, 'nodebb.min.js'),
			async.apply(!skipJS ? meta.js.minify : meta.js.getFromFile, 'acp.min.js'),
			async.apply(!skipLess ? meta.css.minify : meta.css.getFromFile),
			async.apply(meta.sounds.init),
			async.apply(meta.blacklist.load)
		], next);
	},
	function(results, next) {
		console.log('3');
		plugins.fireHook('static:app.preload', {
			app: app,
			middleware: middleware
		}, next);
	},
	function(next) {
		console.log('4');
		routes(app, middleware);
		next();
	}
], callback);

Run it in prod mode and let me know the output.

Nicolas

I feel we are very close. @baris Thank you for looking into this!

It chokes here - https://github.com/NodeBB/NodeBB/blob/v1.0.2/src/webserver.js#L92-L101

I do not see console.log in the next waterfall step after template compilation.

PitaJ

@nicolas after disabling all plugins so you still see this issue? That will quickly rule out a plugin issue

<baris>

@nicolas What logs did you get did it not print 3 ?

Nicolas

@baris It did not print 3

<baris>

Ok now modify it again to the below to figure out which of those steps is breaking. Like below:

async.waterfall([
	async.apply(cacheStaticFiles),
	async.apply(meta.themes.setupPaths),
	function(next) {
		console.log('1');
		plugins.init(app, middleware, next);
	},
	function(next) {
		console.log('2');
		async.waterfall([
			function (next) {
				meta.templates.compile(function (err) {
					console.log('2.compile');
					next(err);
				});
			},
			function (next) {
				if (!skipJS) {
					meta.js.minify('nodebb.min.js', function (err) {
						console.log('2.b.minify');
						next(err);
					})
				} else {
					meta.js.getFromFile('nodebb.min.js', function (err) {
						console.log('2.b.getFromFile');
						next(err);
					});
				}
			},
			function (next) {
				if (!skipJS) {
					meta.js.minify('acp.min.js', function (err) {
						console.log('2.b.minifyjs');
						next(err);
					})
				} else {
					meta.js.getFromFile('acp.min.js', function (err) {
						console.log('2.b.getFromFilejs');
						next(err);
					});
				}
			},
			function (next) {
				if (!skipLess) {
					meta.css.minify(function (err) {
						console.log('2.b.minifycss');
						next(err);
					})
				} else {
					meta.css.getFromFile(function (err) {
						console.log('2.b.getFromFileCss');
						next(err);
					});
				}
			},
			function (next) {
				meta.sounds.init(function (err) {
					console.log('2.sounds');
					next(err);
				})
			},
			function (next) {
				meta.sounds.init(function (err) {
					console.log('2.blaclist');
					next(err);
				})
			}
		], next);
	},
	function(results, next) {
		console.log('3');
		plugins.fireHook('static:app.preload', {
			app: app,
			middleware: middleware
		}, next);
	},
	function(next) {
		console.log('4');
		routes(app, middleware);
		next();
	}
], callback);

Sorry it's a bit long due to all the callbacks and error logging.

Nicolas

A bit weird results. You have switched to waterfall, now it goes to the next step, but chokes there.

1
2
2.compile
2.b.minify
2.b.minifyjs
5/3 04:41 [31364] - info: NodeBB Ready
5/3 04:41 [31364] - info: Enabling 'trust proxy'
2.b.minifycss
5/3 04:41 [31364] - info: NodeBB is now listening on: 0.0.0.0:8081
2.sounds
2.blaclist
3

Reverted back to parallel:

1
2

<baris>

If it goes to next step with waterfall, it could be due to the server not having enough ram to run all the build process in parallel.

Keep it as a waterfall and take a look at your active plugins that are using the hook 'static:app.preload' one of them is not calling the callback properly or has an issue.

You can run grep -rnw "static:app.preload" node_modules/ to search for that in the node_modules folder.

Nicolas

I have switched your proposed extra flow with console logs to parallel, and receive these results:

1
2.sounds
5/3 04:54 [31928] - error: [sounds] Could not initialise sounds: EEXIST: file already exists, symlink '/web/overseers/node/forum/public/uploads/sounds/.gitignore' -> '/web/overseers/node/forum/public/sounds/.gitignore'
2.blaclist
2.b.minifycss
2.b.minify
5/3 04:54 [31928] - info: NodeBB Ready
5/3 04:54 [31928] - info: Enabling 'trust proxy'
2.compile
5/3 04:54 [31928] - info: NodeBB is now listening on: 0.0.0.0:8081

<baris>

Does it work in prod if you disable sounds with this?

function (next) {
        next();
	// meta.sounds.init(function (err) {
	//	console.log('2.sounds');
	//	next(err);
	//})
},

<baris>

Looks like sounds module is just logging the error but not preventing the flow.

I suggest switching to async.waterfall and checking the plugins using 'static:app.preload' hook and making sure the server has enough memory.