Gracefully handle use of an unbound `Logger.{info,debug,...}`

CHANGES.md

@@ -8,7 +8,15 @@ Known issues:
 
 ## bunyan 1.2.4 (not yet released)
 
-(nothing yet)
+- [issue #100] Gracefully handle the case of an unbound
+  `Logger.{info,debug,...}` being used for logging, e.g.:
+
+        myEmittingThing.on('data', log.info)
+
+  Before this change, bunyan would throw. Now it emits a warning to stderr
+  *once*, and then silently ignores those log attempts, e.g.:
+
+        bunyan usage error: /Users/trentm/tm/node-bunyan/foo.js:12: attempt to log with an unbound log method: `this` is: { _events: { data: [Function] } }
 
 
 ## bunyan 1.2.3

lib/bunyan.js

@@ -54,8 +54,12 @@ var isBrowser = function () {
 
 //---- Internal support stuff
 
+/**
+ * A shallow copy of an object. Bunyan logging attempts to never cause
+ * exceptions, so this function attempts to handle non-objects gracefully.
+ */
 function objCopy(obj) {
-    if (obj == null) {
+    if (obj == null) {  // null or undefined
         return obj;
     } else if (Array.isArray(obj)) {
         return obj.slice();
@@ -143,22 +147,22 @@ function getCaller3Info() {
  * If file/line are given, this makes an attempt to warn on stderr only once.
  *
  * @param msg {String} Message with which to warn.
- * @param file {String} Optional. File path relevant for the warning.
- * @param line {String} Optional. Line number in `file` path relevant for
- *    the warning.
+ * @param dedupKey {String} Optional. A short string key for this warning to
+ *      have its warning only printed once.
  */
-function _warn(msg, file, line) {
+function _warn(msg, dedupKey) {
     assert.ok(msg);
-    var key;
-    if (file && line) {
-        key = file + ':' + line;
-        if (_warned[key]) {
+    if (dedupKey) {
+        if (_warned[dedupKey]) {
             return;
         }
-        _warned[key] = true;
+        _warned[dedupKey] = true;
     }
     process.stderr.write(msg + '\n');
 }
+function _haveWarned(dedupKey) {
+    return _warned[dedupKey];
+}
 var _warned = {};
 
 
@@ -758,10 +762,9 @@ Logger.prototype._applySerializers = function (fields, excludeFields) {
         try {
             fields[name] = self.serializers[name](fields[name]);
         } catch (err) {
-            _warn(format('bunyan: ERROR: This should never happen. '
-                + 'This is a bug in <https://github.com/trentm/node-bunyan> '
-                + 'or in this application. Exception from "%s" Logger '
-                + 'serializer: %s',
+            _warn(format('bunyan: ERROR: Exception thrown from the "%s" '
+                + 'Bunyan serializer. This should never happen. This is a bug'
+                + 'in that serializer function.\n%s',
                 name, err.stack || err));
             fields[name] = format('(Error in Bunyan log "%s" serializer '
                 + 'broke field. See stderr for details.)', name);
@@ -884,7 +887,23 @@ function mkLogEmitter(minLevel) {
         var msgArgs = arguments;
         var str = null;
         var rec = null;
-        if (arguments.length === 0) {   // `log.<level>()`
+        if (! this._emit) {
+            /*
+             * Show this invalid Bunyan usage warning *once*.
+             *
+             * See <https://github.com/trentm/node-bunyan/issues/100> for
+             * an example of how this can happen.
+             */
+            var dedupKey = 'unbound';
+            if (!_haveWarned[dedupKey]) {
+                var caller = getCaller3Info();
+                _warn(format('bunyan usage error: %s:%s: attempt to log '
+                    + 'with an unbound log method: `this` is: %s',
+                    caller.file, caller.line, util.inspect(this)),
+                    dedupKey);
+            }
+            return;
+        } else if (arguments.length === 0) {   // `log.<level>()`
             return (this._level <= minLevel);
         } else if (this._level > minLevel) {
             /* pass through */