FreeBSD daemonize Node.js fails with crash while boot time

[Zabrah]

• Node.js Version: 13.7
• OS: Freebsd 12.1
• Scope (install, code, runtime, meta, other?): runtime, rc.d script

Hi,
I am trying to get a Node.js app to run via an rc.d script in FreeBSD. While the OS runtime the rc.d script works fine and my app starts as expected.
But on system boot Node crashes. I didn't get enough info, so I traced the issue by logging some code-positions into a file via write-stream.

With this info Node.js seems to crash every time it comes to cluster.fork, but I cannot be 100% sure.
Could there be any dependency, that have to be waited for, before Node can safely be started while booting FreeBSD?

Here's the code of my rc.d script, with already some dependencies I thought they would be enough.

#!/bin/sh

# PROVIDE: testserver
# REQUIRE: LOGIN DAEMON NETWORKING SERVERS FILESYSTEMS
# BEFORE: 
# KEYWORD: shutdown

. /etc/rc.subr

name="testserver"

rcvar=${name}_enable

: ${miniserver_enable:="NO"}

pidfile="/var/run/testserver.pid"

command="/usr/sbin/daemon"
command_args="-u www -t 'Testserver Daemon' -P ${pidfile} -o /www/testserver/daemon.log -r /usr/local/bin/node /www/testserver/start.js"

load_rc_config $name
run_rc_command "$1"

I already searched the net for example startup scripts, but every of them are for using with the modules forever or pm2. But I want to try to get it working without them.

The only info coming from the daemon-service into the daemon.log is this (not even console.log infos are redirected into that file):

 1: 0x14fe830 node::Abort(void) [/usr/local/bin/node]
 2: 0x14d6aea node::PlatformInit(void) [/usr/local/bin/node]
 3: 0x14d6024 node::InitializeOncePerProcess(int, char**) [/usr/local/bin/node]
 4: 0x14d6479 node::Start(int, char**) [/usr/local/bin/node]

[addaleax]

Can you check other Node.js versions as well (in particular, latest v13.x and latest v12.x)?

Is there any other output, and/or can you share the Node.js binary you’re using so that one can correlate the stack trace to source code positions?

My best guess is that the issue is that Node.js finds that the stdio fds are missing and that opening /dev/null to replace them with dummy fds fails. I would consider that a bug in Node.js, I think.

[Zabrah]

Unfortunately I am not able to test the newest versions, but I've tested 12.13.1 but with the same results.
In the meantime I found out, the crash only happens by requiring custom modules (but not by using native modules, as fs). If I put every code in one file, it works. And I found out, the issue happens with every kind of sending my app to background at boot-time. This means using "&" in the end of the sh-script and by using the daemon-tool. But when I don't take it to background, it works. But with that it blocks the remaining boot-process until pressing Strg+C.

Here is my code in file "start.js":

"use strict";
console.log(__dirname);
console.log("start.js")

const cluster = require('cluster');
const fs = require("fs");

const errlog = fs.createWriteStream(__dirname + "/error.log", {flags: "a"});

if (cluster.isMaster) {
	//Master-Process
	errlog.write("master\n", "utf8")
	errlog.write("fork\n", "utf8")
	cluster.fork();
	cluster.on("error", (info) => {
		errlog.write(`Error: ${info}\n`, "utf8")
	});
	cluster.on("exit", (code, signal) => {
		//cluster.fork();
		errlog.write(`Exit: ${JSON.stringify(code)} ${signal}\n`, "utf8");
	});
} else {
	//Sub-Process
	errlog.write("worker\n", "utf8")
	console.log("lade server")
	errlog.write("starte server\n", "utf8")
	const server = require("./web.js");
	console.log("starte listening für server")
	errlog.write("starte listening für server\n", "utf8")
	server.listen(3080);
}

And "web.js":

"use strict";

const http = require("http");
const fs = require("fs");
const zlib = require("zlib");

const errlog = fs.createWriteStream(__dirname + "/error.log", {flags: "a"});
errlog.write("web.js\n", "utf8")

//Pfad-Parser
const urlPathParse = (str) => {
	const qstart = str.indexOf("?");
	const hstart = str.indexOf("#");
	const len = str.length;
	const obj = {
		filePath: str.slice(str.indexOf("/"), qstart !== -1 ? qstart : (hstart !== -1 ? hstart : len)),
		hash: hstart !== -1 ? str.slice(hstart+1, len) : ""
	}
	
	const fpPos = obj.filePath.lastIndexOf("/");
	obj.file = obj.filePath.slice(fpPos + 1);
	obj.path = obj.filePath.slice(0, fpPos + 1);
	const fdPos = obj.file.indexOf(".");
	obj.fileExt = fdPos !== -1 ? obj.file.slice(fdPos + 1) : "";
	
	if (qstart !== -1) {
		const queryStr = str.slice(qstart + 1, hstart !== -1 ? hstart : len);
		if (queryStr !== "") {
			const arr = queryStr.split("&");
			const qobj = {};
			for (let i = 0, l = arr.length; i < l; i++) {
				const ePos = arr[i].indexOf("=");
				const al = arr[i].length;
				const sep = ePos !== -1 ? ePos : al;
				const tmp = [arr[i].slice(0,sep),arr[i].slice(sep+1, al)];
				if (tmp[0] === "") continue;
				qobj[tmp[0]] = tmp[1];
			}
			obj.query = qobj;
		} else obj.query = {};
	} else obj.query = {};
	
	return obj;
}

String.prototype.contains = function(str) {
	"use strict";
	return this.indexOf(str) !== -1;
}

const webdir = __dirname + "/web";

console.log("komprimiere dateien")
errlog.write("komprimiere dateien\n", "utf8")
//Erstelle vorkomprimierte Daten in einen Cache
const fileCache = {};
(() => {
	const files = fs.readdirSync(webdir);
	files.forEach(fileR => {
		const file = webdir + "/" + fileR;
		if(!fs.statSync(file).isFile()) return;
		if (file.contains(".gz") || file.contains(".br")) return;
		const fileBuf = fs.readFileSync(file, {encoding: "utf8"});
		
		const mtimeMs = fs.statSync(file).mtimeMs;
		
		fileCache[file] = {buf: fileBuf};
		fileCache[file].size = Buffer.byteLength(fileCache[file].buf);
		fileCache[file].mtimeMs = mtimeMs;
		
		fileCache[file + ".gzip"] = {buf: zlib.gzipSync(fileBuf, {level: zlib.constants.Z_BEST_COMPRESSION})};
		fileCache[file + ".gzip"].size = Buffer.byteLength(fileCache[file + ".gzip"].buf);
		fileCache[file + ".gzip"].mtimeMs = mtimeMs;
		
		fileCache[file + ".br"] = {buf: zlib.brotliCompressSync(fileBuf, {BROTLI_PARAM_MODE: "BROTLI_MODE_TEXT", BROTLI_PARAM_QUALITY: "BROTLI_MAX_QUALITY"})};
		fileCache[file + ".br"].size = Buffer.byteLength(fileCache[file + ".br"].buf);
		fileCache[file + ".br"].mtimeMs = mtimeMs;
	});
})();

console.log("öffne streams für logfiles")
errlog.write("öffne streams für logfiles\n", "utf8")
//Datei für Log
const logfile = fs.createWriteStream(__dirname + "/logfile.log", {flags: "a"});

//mime-Types
const mime = {
	"html": "text/html",
	"js": "text/javascript",
	"css": "text/css",
	"woff2": "font/woff2"
};

//Webserver
const server = http.createServer((req, res) => {
	const time = Date.now();
	const url = urlPathParse(req.url);
	
	//Konvertiere url-Daten zu Index-Seite
	if (url.filePath === "/") {
		url.filePath = "/index.html";
		url.file = "index.html";
		url.fileExt = "html";
	}
	
	const fullPath = webdir + url.filePath;
	
	if (fileCache[fullPath]) {
		
		if (fileCache[fullPath].mtimeMs == req.headers["if-none-match"]) {
			res.writeHead(304);
			res.end();
		} else {
			//Prüfe akzeptierte Kompressionsmethode und streame Datei mit voher versandten passendem Header
			let compr = "";
			if (req.headers['accept-encoding'].contains("br")) {
				compr = "br";
			} else if (req.headers['accept-encoding'].contains("gzip")) {
				compr = "gzip";
			}
			
			const comprPath = compr ? "." + compr : "";
			
			//const statSize = compr ? (await fs.promises.stat(fullPath + comprPath)).size : stat.size;
			//const statSize = compr ? fileCache[fullPath + comprPath].byteLength : stat.size;
			const statSize = compr ? fileCache[fullPath + comprPath].size : fileCache[fullPath].size;
			
			res.writeHead(200, {
				'Content-Type': mime[url.fileExt] + "; charset=utf-8",
				'Cache-Control': 'max-age=' + (url.fileExt === "html" ? '0' : '900'),
				'Content-Length': statSize,
				//'ETag': stat.mtimeMs,
				'ETag': fileCache[fullPath].mtimeMs,
				'Content-Encoding': compr
			});
			
			//fs.createReadStream(fullPath + comprPath).pipe(res);
			res.end(fileCache[fullPath + comprPath].buf);
		}
	};
	
	//Wenn sonst nix passt, Error oder Weiterleitung
	if (!res.headersSent) {
		if (url.fileExt) {
			res.statusCode = 404;
			res.end("Stille Leere");
		} else {
			res.writeHead(301, {
				'location': req.headers.host + "/"
			});
			res.end();
		}
	}
	
	logfile.write(`${time};${req.method};${req.url};${res.statusCode};${req.headers.referer};"${req.headers['user-agent']}"\n`, "utf8");
});

server.on('clientError', (err, socket) => {
	socket.end('HTTP/1.1 400 Bad Request\r\n\r\n');
});

//server.listen(8080);

module.exports = server;

process.on("error", (info) => {
	errlog.write("Error: "+info+"\n", "utf8")
});

This results in the following stout-messages:

/www/miniserver
start.js
 1: 0x15ddb80 node::Abort(void) [/usr/local/bin/node]
 2: 0x15b56ca node::PlatformInit(void) [/usr/local/bin/node]
 3: 0x15b4bf4 node::InitializeOncePerProcess(int, char**) [/usr/local/bin/node]
 4: 0x15b503e node::Start(int, char**) [/usr/local/bin/node]

And "error.log" contains:

master
fork
Exit: {"_events":{},"_eventsCount":1,"exitedAfterDisconnect":false,"state":"dead","id":1,"process":{"_events":{"internalMessage":[null,null]},"_eventsCount":3,"_closesNeeded":2,"_closesGot":1,"connected":false,"signalCode":"SIGABRT","exitCode":null,"killed":false,"spawnfile":"/usr/local/bin/node","_handle":null,"spawnargs":["/usr/local/bin/node","/www/miniserver/start.js"],"pid":30386,"stdin":null,"stdout":null,"stderr":null,"stdio":[null,null,null,null],"channel":null,"_handleQueue":null,"_pendingMessage":null}} null

[Zabrah]

Ok, after further testing I realized its not the require of custom modules, which is problematic. I just used a relative path, which I've corrected, but the real error is still using cluster.fork(), which causes Node to crash at boot time.
The logs in my previous post are still correct, because here Node never came to that point, where the relative path would have given an error.

[lhunath]

Any indication as to why cluster.fork() causes the crash and whether there are ways to mitigate?

[Zabrah]

No, there's no solution yet. Now I've tested it with Node 13.7
To simplify the code and to be sure, it's really not my own code, I've used the example code without any modification from https://nodejs.org/dist/latest-v13.x/docs/api/cluster.html#cluster_cluster
But it's still crashing on boot.
Here's the error log:

Master 88211 is running
 1: 0xe4e5c0 node::Abort(void) [/usr/local/bin/node]
 2: 0xe25a1a node::PlatformInit(void) [/usr/local/bin/node]
 3: 0xe24d94 node::InitializeOncePerProcess(int, char**) [/usr/local/bin/node]
 4: 0xe253a9 node::Start(int, char**) [/usr/local/bin/node]
worker 1380 died

[Kal42]

I have the same issue, but I am not using cluster.
The strange thing, it's that some times it crash some times it works.
And if you add the -r, to restart node automatically after 1s, some times after many fail, it's working...

If you want the node binary, it's here : http://pkg.freebsd.org/FreeBSD:12:amd64/quarterly/All/node-13.10.1_1.txz

[bnoordhuis]

Would it be possible for either of you to check what line in PlatformInit() specifically is failing, e.g., by capturing a core dump? You can find that function in src/node.cc:

https://github.com/nodejs/node/blob/3e2a3007107b7a100794f4e4adbde19263fc7464/src/node.cc#L571-L688

[Kal42]

I mange to have the core dump

Node.zip

Edit; I think I understand the issue. When we use daemon witt -o or -S, stdin is something, and this generate the abort.
I think it's related to that : https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=236117

The workaround I have found :
add "exec < /dev/null" int the rc.d file.

[bnoordhuis]

I can't (meaningfully) read the core dump on my system but can you check locally with gdb or lldb what the bt command prints and check at what source line the PlatformInit() stack frame is (and check the contents of local variables and errno if possible)?

[Zabrah]

Thank you Kal42. The workaround solves the problem.
So it seems its not to be an issue of Node but of FreeBSD. I had opened a thread on their forum. I will link that bug report there and show them the workaround.

[PoojaDurgad]

@Zabrah - is this still outstanding? looks like this issue can be closed now .please let me know if that is not the case.

[Zabrah]

@PoojaDurgad - Yes, it can be closed.

[mohd-akram]

A simple solution to this is to pass the -f option to daemon.