How to Send Large Messages: Process Out of Memory Thrown

[pixelshaded]

Getting this in stdout

<--- Last few GCs --->

  101344 ms: Mark-sweep 1376.9 (1457.0) -> 1375.7 (1457.0) MB, 146.9 / 0 ms [allocation failure] [GC in old space requested].
  101523 ms: Mark-sweep 1376.9 (1457.0) -> 1376.9 (1457.0) MB, 169.9 / 0 ms [allocation failure] [GC in old space requested].
  101686 ms: Mark-sweep 1376.9 (1457.0) -> 1376.9 (1457.0) MB, 163.3 / 0 ms [last resort gc].
  101869 ms: Mark-sweep 1376.9 (1457.0) -> 1376.9 (1457.0) MB, 182.2 / 0 ms [last resort gc].


<--- JS stacktrace --->

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

Security context: 000001385A6B4639 <JS Object>
    1: flatten(aka flatten) [C:\...\node_modules\gelf-stream\gelf-stream.js:73] [pc=000000A25884537E] (this=000001385A6041B9 <undefined>,obj=000003B7688B5629 <an Uint8Array with map 000001B5E0804629>,int
o=000003B7688B5611 <an Object with map 000002F4C0BD9E01>,prefix=00000373A1C06F71 <Very long string[5940]>,sep=000001385A635221 <St...

FATAL ERROR: CALL_AND_RETRY_LAST Allocation failed - process out of memory

This scares me only because logging should never throw and it brings down the whole server.

[mhart]

Can you create a repro for this?

[pixelshaded]

How would I go about doing that? My graylog server isn't public. Do you have a graylog server to run against?

[mhart]

You can't reproduce against localhost?

What sort of messages are you sending?

[mhart]

The concern that "logging should never throw" is also a bit of a red herring – if your process is running out of memory, and it just happens to be when gelf-stream is allocating, then that's not an issue with gelf-stream – there's nothing gelf-stream can do to prevent that (especially if you're sending very large messages/objects). It's only an issue with gelf-stream if it's leaking memory in some way.

[Migo2014]

I am getting the same problem, it seems to happen on complex nested objects, because on simple string or object it works

[mhart]

@Migo2014 is it a recursive object of some kind?

[Migo2014]

yes, I wrote too early, sorry. It's mongoose objects that make it crash, since it worked on regular bunyan, I didn't think about it.

[aalexgabi]

After crashes in production and a long investigation I found that the flatten() does not detect circular references and generates a infinite recursion. This is a big problem because as @pixelshaded mentioned the logger should never throw but crashing your process is even more serious.

Basically there are no checks of circular references in flatten():

function flatten(obj, into, prefix, sep) {
  if (into == null) into = {}
  if (prefix == null) prefix = ''
  if (sep == null) sep = '.'
  var key, prop
  for (key in obj) {
    if (!Object.prototype.hasOwnProperty.call(obj, key)) continue
    prop = obj[key]
    if (typeof prop === 'object' && !(prop instanceof Date) && !(prop instanceof RegExp))
      flatten(prop, into, prefix + key + sep, sep)
    else
      into[prefix + key] = prop
  }
  return into
}

I think is important to be able to opt-in for flatten and not be obliged to use it. I prefer using a Graylog extractor instead. This is related: https://github.com/mhart/gelf-stream/issues/11

Here is a workaround:

+function safeCycles() {
+    var seen = [];
+    return function (key, val) {
+        if (!val || typeof val !== 'object') {
+            return val;
+        }
+        if (seen.indexOf(val) !== -1) {
+            return '[Circular]';
+        }
+        seen.push(val);
+        return val;
+    };
+}
-                    var stream = gelfStream.forBunyan(logOptions.server);
+                    var bunyanGelfLevels = {
+                        '10': 7, // bunyan.TRACE - gelfling.DEBUG
+                        '20': 7, // bunyan.DEBUG - gelfling.DEBUG
+                        '30': 6, // bunyan.INFO  - gelfling.INFO
+                        '40': 4, // bunyan.WARN  - gelfling.WARNING
+                        '50': 3, // bunyan.ERROR - gelfling.ERROR
+                        '60': 0, // bunyan.FATAL - gelfling.EMERGENCY
+                    };
+                    var stream = gelfStream.create(logOptions.server, {
+                        map: function (log) {
+                            return {
+                                host: log.hostname,
+                                timestamp: +new Date(log.time) / 1000,
+                                short_message: log.msg,
+                                facility: log.name,
+                                level: bunyanGelfLevels[log.level],
+                                full_message: JSON.stringify(log, safeCycles(), 2)
+                            };
+                        }
+                    });

[aalexgabi]

It seems that bunyan-gelf has the same problem: https://github.com/hughsk/flat/issues/24#issuecomment-273439342

[aalexgabi]

@pixelshaded Can you please change the title to something like "Crashes process when serializing objects with circular references: process out of memory" to be more precise?