pinojs/pino

Memory leak after logging ~26 million lines

webhype opened this issue · 8 comments

webhype commented

In the following code, "choose your poison", i.e. set variable poison to 1, 2, or 3, which are different combinations of using tee.js and/or pretty output... they all lead to the same result... around 26 million lines, console output gets very slow and jerky and invariably crashes with an OOM error.

What is subPoison? subPoison = "a" means loop directly, subPoison = "b" means do an await in the loop. Rationale: I was hopiong maybe this could be worked around by giving the NodeJS event loop a little time to breathe and process any backlogs of whatever events. However, none of it has any effect. Not even waiting 10 ms via setTimeoutPromise() had any positive effect.

Environment: NodeJS 18 LTS, Mac OS Ventura, 32 GB RAM, M2 processor, but this happens on Linux (Ubuntu 22.04) as well.

Typescript code:

import childProcess from "child_process";
import fs from "fs-extra";
import os from "os";
import path from "path";
import stream from "stream";
import pino from "pino";
import pinoms from "pino-multi-stream";
import util from "util";

const setTimeoutPromise = util.promisify(setTimeout);
const setImmediatePromise = () => { return new Promise<void>((resolve) => { setImmediate(() => resolve()); }); };

const logThrough = new stream.PassThrough();

const TEE_PATH = path.join(process.cwd(), "node_modules", "pino-tee", "tee.js");
const LOG_DIR = "./logs";

class MyLogger {
	logger: pino.Logger;
	constructor(
		{viaTee, viaPretty, pathName}:
		{viaTee: boolean, viaPretty: boolean, pathName: string}
	) {
		const level: pino.LevelWithSilent = "trace";

		const streams = [];

		if (viaPretty) {
			streams.push({
				level,
				stream: pinoms.prettyStream({	// ONLY CONSOLE OUTPUT SENT THROUGH THIS
					prettifier: (opts: {[key: string]: any}) => { return (inputData: {
						[key: string]: string | number;
					}) => String(inputData.msg) + ":::"; }, // if left out, uses standard prettifier
					dest: viaTee
						? logThrough
						: fs.createWriteStream(pathName),
				}),
			});
		} else {
			streams.push({
				level,
				stream: logThrough,
			})
		}
		this.logger = pinoms({streams}) as any;
		this.logger.level = "trace";

		if (viaTee) {
			const child = childProcess.spawn(process.execPath, [	// node command
				TEE_PATH,
				"trace", pathName,
			], {
				cwd: process.cwd(),
				env: process.env
			});
			logThrough.pipe(child.stdin);	// now pipe ugly output to tee's stdin
			child.stdout.resume();	// See https://github.com/nodejs/node/issues/42630
		}
	}
}

(async () => {
	// This works as expected
	if  (!fs.existsSync(LOG_DIR))
		fs.mkdirSync(LOG_DIR);

	const poison: number = 3;
	const subPoison: string = "b";

	switch (poison) {

		case 1: {
			const pathName = path.join(LOG_DIR, "test-1-writestream-pretty.log");
			console.log(`Test 1: viaTee: true, viaPretty: true, logging to ${pathName}`);
			const myLogger1 = new MyLogger({
				viaTee: false,
				viaPretty: true,
				pathName,
			});
			for (let i = 1; true; i++) {
				const line = `Test 1, line ${i}: viaTee: false, viaPretty: true`;
				console.log(line);
				switch (subPoison) {
					case "a":
						myLogger1.logger.trace({msg: line + os.EOL});
						break;
					case "b":
						await (async () => { myLogger1.logger.trace({msg: line + os.EOL}); })();
						break;
				}
			}
			break;
		}
		case 2: {
			const pathName = path.join(LOG_DIR, "test-2-tee-pretty.log");
			console.log(`Test 2: viaTee: true, viaPretty: true, logging to ${pathName}`);
			const myLogger2 = new MyLogger({
				viaTee: true,
				viaPretty: true,
				pathName
			});
			for (let i = 1; true; i++) {
				const line = `Test 2, line ${i}: viaTee: true, viaPretty: true`;
				console.log(line);
				switch (subPoison) {
					case "a":
						myLogger2.logger.trace({msg: line + os.EOL});
						break;
					case "b":
						await (async () => { myLogger2.logger.trace({msg: line + os.EOL}); })();
						break;
				}
			}
			break;
		}
		case 3: {
			const pathName = path.join(LOG_DIR, "test-3-tee-notpretty.log");
			console.log(`Test 3: viaTee: true, viaPretty: false, logging to ${pathName}`);
			const myLogger3 = new MyLogger({
				viaTee: true,
				viaPretty: false,
				pathName,
			});
			for (let i = 1; true; i++) {
				const line = `Test 3, line ${i}: viaTee: true, viaPretty: false`;
				console.log(line);
				switch (subPoison) {
					case "a":
						myLogger3.logger.trace({msg: line + os.EOL});
						break;
					case "b":
						await (async () => { myLogger3.logger.trace({msg: line + os.EOL}); })();
						break;
				}
			}
			break;
		}
	}
	// Code execution should never get here
	// Wait for buffers to flush
	await setTimeoutPromise(3000);
	process.exit(0);
})();

package.json:

{
	"name": "pino-test",
	"version": "1.0.0",
	"main": "index.js",
	"license": "MIT",
	"scripts": {
		"start": "node pino-test.js"
	},
	"dependencies": {
		"child_process": "^1.0.2",
		"fs-extra": "^11.1.1",
		"pino": "^8.7.0",
		"pino-colada": "^2.2.2",
		"pino-multi-stream": "^6.0.0",
		"pino-pretty": "^9.1.1",
		"pino-tee": "^0.3.0",
		"stream": "^0.0.2"
	},
	"devDependencies": {
		"@types/fs-extra": "^9.0.13",
		"@types/node": "^17.0.35",
		"@types/pino": "^7.0.5",
		"@types/pino-multi-stream": "^5.1.3",
		"@types/pino-pretty": "^5.0.0",
	}
}

poison = 1, subPoison = "b":

Test 1, line 26177591: viaTee: true, viaPretty: true
Test 1, line 26177592: viaTee: true, viaPretty: true
Test 1, line 26177593: viaTee: true, viaPretty: true
Test 1, line 26177594: viaTee: true, viaPretty: true

<--- Last few GCs --->

[96626:0x7fa750040000]   375011 ms: Scavenge (reduce) 3886.8 (4142.8) -> 3886.0 (4142.8) MB, 4.5 / 0.0 ms  (average mu = 0.035, current mu = 0.002) allocation failure;
[96626:0x7fa750040000]   375018 ms: Scavenge (reduce) 3886.9 (4142.8) -> 3886.1 (4142.8) MB, 4.3 / 0.0 ms  (average mu = 0.035, current mu = 0.002) allocation failure;
[96626:0x7fa750040000]   375026 ms: Scavenge (reduce) 3887.0 (4142.8) -> 3886.2 (4143.1) MB, 4.0 / 0.0 ms  (average mu = 0.035, current mu = 0.002) allocation failure;


<--- JS stacktrace --->

FATAL ERROR: Ineffective mark-compacts near heap limit Allocation failed - JavaScript heap out of memory
 1: 0x1025ded55 node::Abort() (.cold.1) [/usr/local/bin/node]
 2: 0x1010a7259 node::Abort() [/usr/local/bin/node]
 3: 0x1010a743e node::OOMErrorHandler(char const*, bool) [/usr/local/bin/node]
 4: 0x101222193 v8::internal::V8::FatalProcessOutOfMemory(v8::internal::Isolate*, char const*, bool) [/usr/local/bin/node]
 5: 0x1013eabd5 v8::internal::Heap::FatalProcessOutOfMemory(char const*) [/usr/local/bin/node]
 6: 0x1013ef0a0 v8::internal::Heap::CollectSharedGarbage(v8::internal::GarbageCollectionReason) [/usr/local/bin/node]
 7: 0x1013eb8ef v8::internal::Heap::PerformGarbageCollection(v8::internal::GarbageCollector, v8::internal::GarbageCollectionReason, char const*, v8::GCCallbackFlags) [/usr/local/bin/node]
 8: 0x1013e89c8 v8::internal::Heap::CollectGarbage(v8::internal::AllocationSpace, v8::internal::GarbageCollectionReason, v8::GCCallbackFlags) [/usr/local/bin/node]
 9: 0x1013db8ea v8::internal::HeapAllocator::AllocateRawWithLightRetrySlowPath(int, v8::internal::AllocationType, v8::internal::AllocationOrigin, v8::internal::AllocationAlignment) [/usr/local/bin/node]
10: 0x1013dc265 v8::internal::HeapAllocator::AllocateRawWithRetryOrFailSlowPath(int, v8::internal::AllocationType, v8::internal::AllocationOrigin, v8::internal::AllocationAlignment) [/usr/local/bin/node]
11: 0x1013bdeaa v8::internal::Factory::AllocateRaw(int, v8::internal::AllocationType, v8::internal::AllocationAlignment) [/usr/local/bin/node]
12: 0x1013b58d4 v8::internal::FactoryBase<v8::internal::Factory>::NewFixedArrayWithFiller(v8::internal::Handle<v8::internal::Map>, int, v8::internal::Handle<v8::internal::Oddball>, v8::internal::AllocationType) [/usr/local/bin/node]
13: 0x1016c2dbd v8::internal::Handle<v8::internal::NameDictionary> v8::internal::BaseNameDictionary<v8::internal::NameDictionary, v8::internal::NameDictionaryShape>::New<v8::internal::Isolate>(v8::internal::Isolate*, int, v8::internal::AllocationType, v8::internal::MinimumCapacity) [/usr/local/bin/node]
14: 0x10166ae60 v8::internal::JSObject::MigrateToMap(v8::internal::Isolate*, v8::internal::Handle<v8::internal::JSObject>, v8::internal::Handle<v8::internal::Map>, int) [/usr/local/bin/node]
15: 0x10167034d v8::internal::JSObject::OptimizeAsPrototype(v8::internal::Handle<v8::internal::JSObject>, bool) [/usr/local/bin/node]
16: 0x1016a78c4 v8::internal::Map::SetPrototype(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Map>, v8::internal::Handle<v8::internal::HeapObject>, bool) [/usr/local/bin/node]
17: 0x10164a39d v8::internal::JSFunction::SetInitialMap(v8::internal::Isolate*, v8::internal::Handle<v8::internal::JSFunction>, v8::internal::Handle<v8::internal::Map>, v8::internal::Handle<v8::internal::HeapObject>, v8::internal::Handle<v8::internal::JSFunction>) [/usr/local/bin/node]
18: 0x10164a746 v8::internal::JSFunction::EnsureHasInitialMap(v8::internal::Handle<v8::internal::JSFunction>) [/usr/local/bin/node]
19: 0x1013cba19 v8::internal::Factory::NewJSGeneratorObject(v8::internal::Handle<v8::internal::JSFunction>) [/usr/local/bin/node]
20: 0x1017f2cfe v8::internal::Runtime_CreateJSGeneratorObject(int, unsigned long*, v8::internal::Isolate*) [/usr/local/bin/node]
21: 0x101beedf9 Builtins_CEntry_Return1_DontSaveFPRegs_ArgvOnStack_NoBuiltinExit [/usr/local/bin/node]
error Command failed with signal "SIGABRT".

poison = 2, subPoison = "b":

Test 2, line 26133194: viaTee: true, viaPretty: true
Test 2, line 26133195: viaTee: true, viaPretty: true
Test 2, line 26133196: viaTee: true, viaPretty: true
Test 2, line 26133197: viaTee: true, viaPretty: true

<--- Last few GCs --->

[95072:0x7f87f8040000]   392027 ms: Scavenge (reduce) 3885.1 (4142.7) -> 3884.2 (4142.7) MB, 8.3 / 0.0 ms  (average mu = 0.028, current mu = 0.001) allocation failure;
[95072:0x7f87f8040000]   392036 ms: Scavenge (reduce) 3885.1 (4142.7) -> 3884.3 (4143.0) MB, 2.7 / 0.0 ms  (average mu = 0.028, current mu = 0.001) allocation failure;
[95072:0x7f87f8040000]   392042 ms: Scavenge (reduce) 3885.7 (4143.0) -> 3884.8 (4143.2) MB, 2.7 / 0.0 ms  (average mu = 0.028, current mu = 0.001) allocation failure;


<--- JS stacktrace --->

FATAL ERROR: Ineffective mark-compacts near heap limit Allocation failed - JavaScript heap out of memory
 1: 0x101f12d55 node::Abort() (.cold.1) [/usr/local/bin/node]
 2: 0x1009db259 node::Abort() [/usr/local/bin/node]
 3: 0x1009db43e node::OOMErrorHandler(char const*, bool) [/usr/local/bin/node]
 4: 0x100b56193 v8::internal::V8::FatalProcessOutOfMemory(v8::internal::Isolate*, char const*, bool) [/usr/local/bin/node]
 5: 0x100d1ebd5 v8::internal::Heap::FatalProcessOutOfMemory(char const*) [/usr/local/bin/node]
 6: 0x100d230a0 v8::internal::Heap::CollectSharedGarbage(v8::internal::GarbageCollectionReason) [/usr/local/bin/node]
 7: 0x100d1f8ef v8::internal::Heap::PerformGarbageCollection(v8::internal::GarbageCollector, v8::internal::GarbageCollectionReason, char const*, v8::GCCallbackFlags) [/usr/local/bin/node]
 8: 0x100d1c9c8 v8::internal::Heap::CollectGarbage(v8::internal::AllocationSpace, v8::internal::GarbageCollectionReason, v8::GCCallbackFlags) [/usr/local/bin/node]
 9: 0x100d0f8ea v8::internal::HeapAllocator::AllocateRawWithLightRetrySlowPath(int, v8::internal::AllocationType, v8::internal::AllocationOrigin, v8::internal::AllocationAlignment) [/usr/local/bin/node]
10: 0x100d10265 v8::internal::HeapAllocator::AllocateRawWithRetryOrFailSlowPath(int, v8::internal::AllocationType, v8::internal::AllocationOrigin, v8::internal::AllocationAlignment) [/usr/local/bin/node]
11: 0x100cf26de v8::internal::Factory::NewFillerObject(int, v8::internal::AllocationAlignment, v8::internal::AllocationType, v8::internal::AllocationOrigin) [/usr/local/bin/node]
12: 0x1011287ec v8::internal::Runtime_AllocateInYoungGeneration(int, unsigned long*, v8::internal::Isolate*) [/usr/local/bin/node]
13: 0x101522df9 Builtins_CEntry_Return1_DontSaveFPRegs_ArgvOnStack_NoBuiltinExit [/usr/local/bin/node]
14: 0x111875c7d
error Command failed with signal "SIGABRT".

poison = 3, subPoison = "b":

Test 3, line 26059157: viaTee: true, viaPretty: false
Test 3, line 26059158: viaTee: true, viaPretty: false
Test 3, line 26059159: viaTee: true, viaPretty: false
Test 3, line 26059160: viaTee: true, viaPretty: false
Test 3, line 26059161: viaTee: true, viaPretty: false
Test 3, line 26059162: viaTee: true, viaPretty: false
Test 3, line 26059163: viaTee: true, viaPretty: false

<--- Last few GCs --->

[97359:0x7f7828040000]   351226 ms: Scavenge (reduce) 3901.3 (4142.9) -> 3900.4 (4142.9) MB, 1.8 / 0.0 ms  (average mu = 0.039, current mu = 0.002) allocation failure;
[97359:0x7f7828040000]   351230 ms: Scavenge (reduce) 3901.3 (4142.9) -> 3900.5 (4142.9) MB, 2.2 / 0.0 ms  (average mu = 0.039, current mu = 0.002) allocation failure;
[97359:0x7f7828040000]   351235 ms: Scavenge (reduce) 3901.4 (4142.9) -> 3900.6 (4143.2) MB, 2.3 / 0.0 ms  (average mu = 0.039, current mu = 0.002) allocation failure;


<--- JS stacktrace --->

FATAL ERROR: Ineffective mark-compacts near heap limit Allocation failed - JavaScript heap out of memory
 1: 0x103792d55 node::Abort() (.cold.1) [/usr/local/bin/node]
 2: 0x10225b259 node::Abort() [/usr/local/bin/node]
 3: 0x10225b43e node::OOMErrorHandler(char const*, bool) [/usr/local/bin/node]
 4: 0x1023d6193 v8::internal::V8::FatalProcessOutOfMemory(v8::internal::Isolate*, char const*, bool) [/usr/local/bin/node]
 5: 0x10259ebd5 v8::internal::Heap::FatalProcessOutOfMemory(char const*) [/usr/local/bin/node]
 6: 0x1025a30a0 v8::internal::Heap::CollectSharedGarbage(v8::internal::GarbageCollectionReason) [/usr/local/bin/node]
 7: 0x10259f8ef v8::internal::Heap::PerformGarbageCollection(v8::internal::GarbageCollector, v8::internal::GarbageCollectionReason, char const*, v8::GCCallbackFlags) [/usr/local/bin/node]
 8: 0x10259c9c8 v8::internal::Heap::CollectGarbage(v8::internal::AllocationSpace, v8::internal::GarbageCollectionReason, v8::GCCallbackFlags) [/usr/local/bin/node]
 9: 0x10258f8ea v8::internal::HeapAllocator::AllocateRawWithLightRetrySlowPath(int, v8::internal::AllocationType, v8::internal::AllocationOrigin, v8::internal::AllocationAlignment) [/usr/local/bin/node]
10: 0x102590265 v8::internal::HeapAllocator::AllocateRawWithRetryOrFailSlowPath(int, v8::internal::AllocationType, v8::internal::AllocationOrigin, v8::internal::AllocationAlignment) [/usr/local/bin/node]
11: 0x1025726de v8::internal::Factory::NewFillerObject(int, v8::internal::AllocationAlignment, v8::internal::AllocationType, v8::internal::AllocationOrigin) [/usr/local/bin/node]
12: 0x1029a87ec v8::internal::Runtime_AllocateInYoungGeneration(int, unsigned long*, v8::internal::Isolate*) [/usr/local/bin/node]
13: 0x102da2df9 Builtins_CEntry_Return1_DontSaveFPRegs_ArgvOnStack_NoBuiltinExit [/usr/local/bin/node]
error Command failed with signal "SIGABRT".
webhype commented

Update: Using SonicBoom instead of the built-in write stream, the crash happens at around 30 million lines, not 27 million, but no substantial improvement.

Test 1, line 30730308: viaTee: false, viaPretty: true
Test 1, line 30730309: viaTee: false, viaPretty: true
Test 1, line 30730310: viaTee: false, viaPretty: true
Test 1, line 30730311: viaTee: false, viaPretty: true
Test 1, line 30730312: viaTee: false, viaPretty: true

<--- Last few GCs --->

[2464:0x7fe528040000]   339646 ms: Scavenge 4039.4 (4128.0) -> 4025.4 (4128.0) MB, 6.3 / 0.0 ms  (average mu = 0.303, current mu = 0.285) allocation failure;
[2464:0x7fe528040000]   340419 ms: Mark-sweep 4040.8 (4129.0) -> 4023.5 (4127.8) MB, 736.1 / 0.0 ms  (average mu = 0.210, current mu = 0.108) allocation failure; scavenge might not succeed
[2464:0x7fe528040000]   340472 ms: Scavenge 4040.7 (4128.0) -> 4026.6 (4128.0) MB, 5.3 / 0.0 ms  (average mu = 0.210, current mu = 0.108) allocation failure;


<--- JS stacktrace --->

FATAL ERROR: Ineffective mark-compacts near heap limit Allocation failed - JavaScript heap out of memory
 1: 0x105d3cd55 node::Abort() (.cold.1) [/usr/local/bin/node]
 2: 0x104805259 node::Abort() [/usr/local/bin/node]
 3: 0x10480543e node::OOMErrorHandler(char const*, bool) [/usr/local/bin/node]
 4: 0x104980193 v8::internal::V8::FatalProcessOutOfMemory(v8::internal::Isolate*, char const*, bool) [/usr/local/bin/node]
mcollina commented

Thanks for reporting!

This seems absolutely normal looking through your code, which run without letting node spin the event loop and therefore giving the I/O a chance to flush its data. sonic-boom has a few facilities to deal with cases like this, but they are absolutely exceptional in the normal operation of this library.

Note that pino-multi-stream is deprecated & archived, use pino.multistream instead as it has been integrated in the main module.

webhype commented

Thanks for your comment. Definitely not normal to get OOM, ever, on a loop that does nothing wrong to provoke a memory leak. I knew you'd bring up the event loop 😄 so please consider the following code that uses the famous setImmediate() trick to force a full cycle of the event loop (see https://snyk.io/blog/nodejs-how-even-quick-async-functions-can-block-the-event-loop-starve-io/ ). This is decided in the line const eventLoopMethod: string = "c"; :

import childProcess from "child_process";
import fs from "fs-extra";
import os from "os";
import path from "path";
import stream from "stream";
import pino, { LogFn, Logger, DestinationStream, StreamEntry, LogDescriptor, } from "pino";
import pretty, { PrettyOptions, PinoPretty } from "pino-pretty";
import util from "util";
import SonicBoom from "sonic-boom";

// setImmediatePromise() - Forwards the event loop to after any pending I/O requests were handled
// Use this to let I/O events, such as txpool events, be handled, while doing other heavy lifting/blocking stuff
// For example, call every 100 ms
// See https://snyk.io/blog/nodejs-how-even-quick-async-functions-can-block-the-event-loop-starve-io/?utm_source=pocket_mylist

const setImmediatePromise = () => { return new Promise<void>((resolve) => { setImmediate(() => resolve()); }); };
const setTimeoutPromise = util.promisify(setTimeout);

const logThrough = new stream.PassThrough();

const TEE_PATH = path.join(process.cwd(), "node_modules", "pino-tee", "tee.js");
const LOG_DIR = "./logs";

class MyLogger {
	logger: pino.Logger;
	constructor(
		{viaTee, viaSonic, viaPretty, pathName}:
		{viaTee: boolean, viaSonic: boolean, viaPretty: boolean, pathName: string}
	) {
		const level: pino.LevelWithSilent = "trace";

		const streams = [];

		const makeWriteStream =	() => { return viaSonic
			? new SonicBoom({dest: pathName, minLength: 100000, maxLength: 1000000, sync: true, maxWrite: 100001})
			: fs.createWriteStream(pathName);
		}

		streams.push({
			level,
			stream: viaTee
			? logThrough
			: makeWriteStream(),
		});

		if (viaPretty) {
			const prettifierFunc: pretty.MessageFormatFunc =
				(log: LogDescriptor, messageKey: string, levelLabel: string) => `❤️ ${log[messageKey]} ❤️`;

			const prettyOptions: PrettyOptions = {	// ONLY CONSOLE OUTPUT SENT THROUGH THIS
				colorize: true,
				messageFormat: prettifierFunc,
				destination: 1,	// or process.stdout,
			};
			const prettyStreamToConsole: DestinationStream = pretty(prettyOptions);
			streams.push({
				level,
				stream: prettyStreamToConsole,
			});
		}
		this.logger = pino({}, pino.multistream(streams));
		this.logger.level = "trace";

		if (viaTee) {
			const child = childProcess.spawn(process.execPath, [	// node command
				TEE_PATH,
				"trace", pathName,
			], {
				cwd: process.cwd(),
				env: process.env
			});
			logThrough.pipe(child.stdin);	// now pipe ugly output to tee's stdin
			child.stdout.resume();	// See https://github.com/nodejs/node/issues/42630
		}
	}
}

(async () => {

	const eventLoopMethod: string = "c";

	// This works as expected
	if  (!fs.existsSync(LOG_DIR))
		fs.mkdirSync(LOG_DIR);

	const via = {
		viaTee: false,
		viaSonic: false,
		viaPretty: false,
	};
	let viaStr = "";
	for (const [key, value] of Object.entries(via)) {
		if (value)
			viaStr += "-" + key;
		else
			viaStr += "-no-" + key;

	}

	const pathName = path.join(LOG_DIR, `test${viaStr}.log`);
	const myLogger = new MyLogger({...via, pathName});

	for (let i = 1; true; i++) {
		const line = `LINE ${i}: ${pathName}`;
		console.log("console.log(): " + line);
		switch (eventLoopMethod) {
			case "a":
				myLogger.logger.trace({msg: line + os.EOL});
				break;
			case "b":
				await (async () => { myLogger.logger.trace({msg: line + os.EOL}); })();
				break;
			case "c":
				await setImmediatePromise();
				myLogger.logger.trace({msg: line + os.EOL});
				break;
			case "d":
				await setTimeoutPromise(1);
				myLogger.logger.trace({msg: line + os.EOL});
				break;
		}
	}

	// Code execution should never get here
	// Wait for buffers to flush
	await setTimeoutPromise(3000);
	process.exit(0);
})();

The result is, it reliably crashes, this time after 60 million+ lines, but crash it does always:

console.log(): LINE 60554164: logs/test-no-viaTee-no-viaSonic-no-viaPretty.log
console.log(): LINE 60554165: logs/test-no-viaTee-no-viaSonic-no-viaPretty.log
console.log(): LINE 60554166: logs/test-no-viaTee-no-viaSonic-no-viaPretty.log
console.log(): LINE 60554167: logs/test-no-viaTee-no-viaSonic-no-viaPretty.log
console.log(): LINE 60554168: logs/test-no-viaTee-no-viaSonic-no-viaPretty.log

<--- Last few GCs --->

[68902:0x7f97d8078000]  1440452 ms: Mark-sweep 4045.9 (4133.6) -> 4033.4 (4134.1) MB, 939.2 / 0.0 ms  (average mu = 0.174, current mu = 0.117) task; scavenge might not succeed
[68902:0x7f97d8078000]  1441550 ms: Mark-sweep 4046.6 (4134.1) -> 4034.0 (4134.6) MB, 963.2 / 0.0 ms  (average mu = 0.149, current mu = 0.122) task; scavenge might not succeed


<--- JS stacktrace --->

FATAL ERROR: Ineffective mark-compacts near heap limit Allocation failed - JavaScript heap out of memory
 1: 0x1063bfd55 node::Abort() (.cold.1) [/usr/local/bin/node]
 2: 0x104e88259 node::Abort() [/usr/local/bin/node]
 3: 0x104e8843e node::OOMErrorHandler(char const*, bool) [/usr/local/bin/node]
 4: 0x105003193 v8::internal::V8::FatalProcessOutOfMemory(v8::internal::Isolate*, char const*, bool) [/usr/local/bin/node]
 5: 0x1051cbbd5 v8::internal::Heap::FatalProcessOutOfMemory(char const*) [/usr/local/bin/node]
 6: 0x1051d00a0 v8::internal::Heap::CollectSharedGarbage(v8::internal::GarbageCollectionReason) [/usr/local/bin/node]
 7: 0x1051cc8ef v8::internal::Heap::PerformGarbageCollection(v8::internal::GarbageCollector, v8::internal::GarbageCollectionReason, char const*, v8::GCCallbackFlags) [/usr/local/bin/node]
 8: 0x1051c99c8 v8::internal::Heap::CollectGarbage(v8::internal::AllocationSpace, v8::internal::GarbageCollectionReason, v8::GCCallbackFlags) [/usr/local/bin/node]
 9: 0x1052623c1 v8::internal::ScavengeJob::Task::RunInternal() [/usr/local/bin/node]
10: 0x104ef3661 node::PerIsolatePlatformData::RunForegroundTask(std::__1::unique_ptr<v8::Task, std::__1::default_delete<v8::Task>>) [/usr/local/bin/node]
11: 0x104ef20c7 node::PerIsolatePlatformData::FlushForegroundTasksInternal() [/usr/local/bin/node]
12: 0x105933cab uv__async_io [/usr/local/bin/node]
13: 0x105947a7b uv__io_poll [/usr/local/bin/node]
14: 0x105934231 uv_run [/usr/local/bin/node]
15: 0x104db5733 node::SpinEventLoop(node::Environment*) [/usr/local/bin/node]
16: 0x104ecb3d2 node::NodeMainInstance::Run() [/usr/local/bin/node]
17: 0x104e4f08c node::LoadSnapshotDataAndRun(node::SnapshotData const**, node::InitializationResult const*) [/usr/local/bin/node]
18: 0x104e4f373 node::Start(int, char**) [/usr/local/bin/node]
19: 0x20a31241f

Now, I have no proof that pino is the culprit, it could be a "normal" NodeJS weakness, that somehow the regular write stream leaks memory. I am just submitting it here for you to investigate, as it provides for a really bad end user experience. 30 or 60 million lines are quickly logged, and I am struggling with keeping my program alive beyond that.

If it's a documented NodeJS or write stream bug, perhaps it would be worth pointing out that projects that use pino to generate large log files are expected to crash, so people don't wrongfully blame pino. At the moment all I know is that when I log a lot of lines through pino, tens of millions, then my program crashes, and when I do not log anything, it stays alive, essentially forever.

kibertoad commented

@webhype does it work any better if you try same code with e. g. winston?

webhype commented

I am not familiar with winston. Just showing you what I have and I am sure others go down the same path but don't complain and quietly give up on pino. If it were my project, I would try and identify what's wrong here, even if it ends up being NodeJS's "fault" in the end. I don't want to be "right" about anything. I just have made an investment in pino, and don't want to spend hours of my life, learning the competition. I know OOM errors are a bitch to debug but run this code and explain the phenomenon to me! I am stumped...

mcollina commented

Your destination cannot keep up with the amount of log lines your application is producing. You can reproduce the same issue by continuously writing to any stream in Node.js.

In the same situation, all loggers in all languages either:

  1. crash for an out of memory error
  2. slow down your application
  3. drop log lines

In your example you are not using sonic-boom if I read it correctly. I'm pretty convinced sonic-boom (without any other destination) configured like you did should slow down your application until it's done.

Note that this case is uncommon, and only one other company had this issue: Netflix.

In fact, they also contributed the fix: implement the retryEAGAIN() option is sonic-boom to drop the bytes that the destination could not absorb, as slowing things down is not a good answer for them.

webhype commented

Yes it seems to behave better with SonicBoom with buffering (not in the default config). I didn't know that SonicBoom would slow things down, so I will try retryEAGAIN() per your suggestion, thanks.

In any case, in the REAME.md I would advise users with one sentence of the expected crashes, even if it's not pino's "fault", and perhaps recommend the SonicBook solution you suggest!

If I can't get your suggestion to work, I'll reopen this, thanks again!