winston-logzio icon indicating copy to clipboard operation
winston-logzio copied to clipboard

Large log messages cause process crash / OOM

Open johnpeb opened this issue 3 years ago • 1 comments

Overly large log messages cause the node process to crash with out of memory.

This happens frequently:

logzio-logger error: Error: There was a problem with the request.
Response: 413: 413 - "" Error: There was a problem with the request.
Response: 413: 413 - ""
    at /var/app/current/node_modules/logzio-nodejs/lib/logzio-nodejs.js:305:42
    at tryCatcher (/var/app/current/node_modules/bluebird/js/release/util.js:16:23)
    at Promise._settlePromiseFromHandler (/var/app/current/node_modules/bluebird/js/release/promise.js:512:31)
    at Promise._settlePromise (/var/app/current/node_modules/bluebird/js/release/promise.js:569:18)
    at Promise._settlePromise0 (/var/app/current/node_modules/bluebird/js/release/promise.js:614:10)
    at Promise._settlePromises (/var/app/current/node_modules/bluebird/js/release/promise.js:689:18)
    at Async._drainQueue (/var/app/current/node_modules/bluebird/js/release/async.js:133:16)
    at Async._drainQueues (/var/app/current/node_modules/bluebird/js/release/async.js:143:10)
    at Immediate.Async.drainQueues [as _onImmediate] (/var/app/current/node_modules/bluebird/js/release/async.js:17:14)
    at processImmediate (internal/timers.js:439:21)

Then at the end this. Presumably, the failed send is retained for retry which is not appropriate if the message is too large and will not index anyway if it does get through to logz.

<--- Last few GCs --->

[31461:0x35d6440]   306124 ms: Mark-sweep 964.0 (982.1) -> 962.9 (982.1) MB, 53.0 / 0.0 ms  (average mu = 0.302, current mu = 0.380) allocation failure scavenge might not succeed
[31461:0x35d6440]   306197 ms: Mark-sweep 964.0 (982.1) -> 962.8 (982.1) MB, 56.2 / 0.0 ms  (average mu = 0.271, current mu = 0.236) allocation failure scavenge might not succeed


<--- JS stacktrace --->

==== JS stack trace =========================================

    0: ExitFrame [pc: 0x1376259]
Security context: 0x2f31614008a1 <JSObject>
    1: split [0x2f316140d031](this=0x1e0baa1324f1 <String[#9]: _bsontype>,0x035ecffc38e1 <String[#1]: .>)
    2: clone(aka clone) [0xfa144281c09] [/var/app/current/node_modules/mongoose/lib/helpers/clone.js:~29] [pc=0x3681f9aaa5de](this=0x035ecffc04a9 <undefined>,0x035ecffc0631 <true>,0x035ecffc04a9 <undefined>,0x035ecffc04a9 <undefined>)
    3: clone(aka clone) ...

FATAL ERROR: Ineffective mark-compacts near heap limit Allocation failed - JavaScript heap out of memory
 1: 0x9dab70 node::Abort() [node]
 2: 0x9dbd26 node::OnFatalError(char const*, char const*) [node]
 3: 0xb3b18e v8::Utils::ReportOOMFailure(v8::internal::Isolate*, char const*, bool) [node]
 4: 0xb3b509 v8::internal::V8::FatalProcessOutOfMemory(v8::internal::Isolate*, char const*, bool) [node]
 5: 0xce68a5  [node]
 6: 0xce6f36 v8::internal::Heap::RecomputeLimits(v8::internal::GarbageCollector) [node]
 7: 0xcf2dca v8::internal::Heap::PerformGarbageCollection(v8::internal::GarbageCollector, v8::GCCallbackFlags) [node]
 8: 0xcf3cd5 v8::internal::Heap::CollectGarbage(v8::internal::AllocationSpace, v8::internal::GarbageCollectionReason, v8::GCCallbackFlags) [node]
 9: 0xcf66e8 v8::internal::Heap::AllocateRawWithRetryOrFail(int, v8::internal::AllocationType, v8::internal::AllocationAlignment) [node]
10: 0xcbccac v8::internal::Factory::AllocateRawWithAllocationSite(v8::internal::Handle<v8::internal::Map>, v8::internal::AllocationType, v8::internal::Handle<v8::internal::AllocationSite>) [node]
11: 0xcc9a54 v8::internal::Factory::NewJSArrayWithUnverifiedElements(v8::internal::Handle<v8::internal::FixedArrayBase>, v8::internal::ElementsKind, int, v8::internal::AllocationType) [node]
12: 0xcc9b81 v8::internal::Factory::NewJSArrayWithElements(v8::internal::Handle<v8::internal::FixedArrayBase>, v8::internal::ElementsKind, int, v8::internal::AllocationType) [node]
13: 0x101f492 v8::internal::Runtime_StringSplit(int, unsigned long*, v8::internal::Isolate*) [node]
14: 0x1376259  [node]

johnpeb avatar Sep 18 '20 14:09 johnpeb

internally we use https://www.npmjs.com/package/rough-object-size to watch out from huge messages we use it like that:

// 1048576 * 0.5 = 0.5MB
function logSize({ maxLogSizeBytes = 1048576 * 0.5 } = {}) {
  return function logSizeLog(log) {
    log.logSize = roughObjectSize(log);

    if (maxLogSizeBytes < log.logSize) {
      log.logObjectKeys = Object.keys(log);
      log.message = 'Log exceeded the max bytes size';
      log.maxLogSize = maxLogSizeBytes;
    }

    return log;
  };
}


AlonMiz avatar Sep 22 '20 13:09 AlonMiz