Lazy debug logging for Node.js
Tags: node, debug, braindump, wat
Published: 2020-10-21 13:29:01

This may come as a surprise, but I can be *very* lazy. If I can get good results without much effort, then 🥳! So the idea of adding debug logging to a whole codebase sounds absolutely exhausting to me, and I want to find a better (_lazier_) way...

## The problem:

I have a [tool that I've been working on](https://github.com/phenomnomnominal/betterer) for a while, and debugging it can be kind of a pain - especially when it's running inside [VS Code](https://marketplace.visualstudio.com/items?itemName=Betterer.betterer-vscode). It'd be nice to have an easy way to get information about what is going on when the tool runs, without having to manually write a bunch of debug logging code and release a new version. That means that the usual approaches are not going to work:

* no straight up `console.log()` statements
* no `debug(function foo () {})` wrappers
* no fancy `@debug` decorators

I want something I can set and forget, and probably turn on and off via an environment variable. Is this even possible?

## Attempt 1 - override `Function.prototype.constructor`:

I know that in the past I've done something where I wrapped every function call in some logging, so I want to try to get that working again. I'm pretty sure I did it by overwriting `Function.prototype.constructor`, which is a pretty insane hack 😅

JavaScript is a very flexible language, so I can just do stuff like this:

```javascript
Function.prototype.constructor = (() => {
    const original = Function.prototype.constructor;
    return function (...args) {
        // do stuff...
        return original.call(this, ...args);
    };
})();
```

I can store a reference to the original `constructor` function, and replace it with a new function that does some debug logging, and then calls the original function. Seems pretty smart! Job done!

Unfortunately, this doesn't actually work... 😐

```
function foo () { return 'foo'; } <- Function.prototype.constructor doesn't get called here
foo();
```

So perhaps I can overwrite `Function.prototype.call` instead?

```javascript
Function.prototype.call = (() => {
    const original = Function.prototype.call;
    return function (...args) {
        // do stuff...
        return original.apply(this, args);
    };
})();

function foo () { return 'foo'; }
foo(); // <- Function.prototype.call doesn't get called here either 
```

I know I've done this in the past, so I must just be missing something. Off to Stack Overflow I go!

I found a few relevant questions/answers, like [this one](https://stackoverflow.com/questions/5033836/adding-console-log-to-every-function-automatically), which does exactly what I just tried? I also found an answer for this exact problem that I wrote 7 years ago - thanks past-Craig! 🦄

{% stackoverflow 15893197 %}

It even handles a few edge cases, like handling the correct version of `this` that is passed in, and swapping back to the original for the actual call to `console.log`... But I tried it again and still [no cigar](https://open.spotify.com/track/3KLkRy9l3us98SIp6mmxkk). Maybe it used to work but doesn't now?

I used [`n`](https://github.com/tj/n) to go back to an older version of Node.js (0.12), and it still doesn't seem to work. Maybe my old answer was just wrong?

Now that I think about it, this approach is probably a bit *too* much anyway - I would get debug logs for every single function call, including internal Node.js functions! Probably a bit too verbose.

## Attempt 2 - Wrap `require` in a [`Proxy`](https://developer.mozilla.org/en-US/docs/Web/JavaScript/Reference/Global_Objects/Proxy)?

JavaScript has evolved quite a bit since I answered that question in 2013 - and one of the things that has been added is meta-programming capabilities. There's a special JavaScript object called a [Proxy](https://developer.mozilla.org/en-US/docs/Web/JavaScript/Reference/Global_Objects/Proxy) which is designed for this kind of function wrapping. But I still don't want to have to wrap all functions in a call to `new Proxy`...

One of the cool things about Node.js is that a lot of it is written in JavaScript, which means I can mess with the core functionality, for example `require`. I can do the same [monkey-patching](https://en.wikipedia.org/wiki/Monkey_patch) kind of thing from before.

```javascript
global.require = (() => {
    const original = global.require;
    return function (...args) {
        const result = original.apply(this, args);
        // do stuff...
        return result;
    };
})();
```

So now I can examine the result of every call to `require` and mess with it! 

I want to look at each of the object on the result (the `module.exports` object of the module) and find which ones are functions:

```javascript
function getFunctions (exports) {
    const functions = {};
    Object.keys(exports)
      .filter((functionName) => typeof exports[functionName] === 'function')
      .forEach((functionName) => {
        functions[functionName] = map[functionName];
      });
    return functions;
}
```

So I can change the `// do stuff` to something like:

```javascript
global.require = (() => {
    const original = global.require;
    return function (...args) {
        const exports = original.apply(this, args);
        const functions = getFunctions(exports);
        // wrap functions:
        return exports;
    };
})();
```

And the `wrap functions` code will look something like this:

```javascript
Object.keys(functions).forEach((functionName) => {
    Object.defineProperty(exports, functionName, {
        value: new Proxy(exports[functionName], {
            // ... Proxy options:
        })
    });
});
```

This is looking pretty promising I think! But right now it is still going to wrap every single exported function from every module, and that's quite a lot of functions. It'd be great to exclude all dependencies, and only instrument the code from my library. So how does require work?

```javascript
require('fs'); // Built in module
require('express'); // Third-party code in the node_modules folder
require('./some/thing'); // Local code for my library
```

I only want to intercept the last case. I can just intercept any call to require where the argument starts with a `.`, that should get `./` and `../` calls.

```javascript
global.require = (() => {
    const original = global.require;
    return function (id) {
        const exports = original.apply(this, [id]);
        if (shouldWrap(id) {
          const functions = getFunctions(exports);
          // wrap functions:
        }
        return exports;
    };
})();

function shouldWrap (id) {
    return id.startsWith('.');
}
```

Ah, so slight problem. Third-party code in `node_modules` will refer to other local files in the same module, which also start with `.`, so I'm still getting too many functions. I need some better way of filtering the require ids!

I need to dig into `require` a bit more. It turns out that the global `require` function actually delegates to the Node.js `Module` class, which has a `require` function on its prototype. That function internally calls a `_resolveFilename` function which turns the require `id` into a file path. We can call that directly, and check if the path contains `node_modules`. We can also use the list of `builtinModules` to filter out things like `path` and `fs`:

```javascript
immport { buildinModules, Module } from 'module';

Module.prototype.require = (() => {
    const original = Module.prototype.require;
    return function (id) {
      const requirePath = Module._resolveFilename(id, this);
      const module = original.apply(this, [id]);
      if (module && shouldWrap(requirePath)) {
        // wrap module:
      }
      return module;
    };
})();

function shouldWrap (requirePath) {
    const isNodeModule = builtinModules.includes(requirePath) || requirePath.includes('node_modules');
    return !isNodeModule;
}
```

One more little issue is that the `require` function isn't just a function - it's also an object that has some other stuff on it like `require.resolve` and `require.cache`. Right now I am just clobbering everything, so I have to do that a bit better:

```javascript
immport { buildinModules, Module } from 'module';

const original = Module.prototype.require;
const debugRequire = function (id) {
  // ...
};
Module.prototype.require = Object.assign(debugRequire, original);
```

Okay, that's sorted, so how will the actual wrapping work? So far I have this:

```javascript
Object.keys(functions).forEach((functionName) => {
    Object.defineProperty(exports, functionName, {
        value: new Proxy(exports[functionName], {
            // ... Proxy options:
        })
    });
});
```

The way a `Proxy` works is that you have a set of traps that describe different operations in JavaScript. I care about functions, so there are two traps that I care about, [`apply`](https://developer.mozilla.org/en-US/docs/Web/JavaScript/Reference/Global_Objects/Proxy/Proxy/apply) and [`construct`](https://developer.mozilla.org/en-US/docs/Web/JavaScript/Reference/Global_Objects/Proxy/Proxy/construct).

### Proxy `apply` trap:

The `apply` trap gives you control to what happens when a function is called - exactly what I want! The basic form of an `apply` trap handler is like this:

```javascript
function apply (target, thisArg, argumentsList) {
    return target.apply(thisArg, argumentsList);
}
```

I can add a bit more stuff to make it more useful:

```javascript
import { performance } from 'perf_hooks';

function apply (target, thisArg, args) {
    const startTime = performance.now();
    console.log(args);
    const result = target.apply(thisArg, args);
    const endTime = performance.now();
    console.log(result);
    console.log(endTime - startTime);
    return result;
}
```

One other thing is that `result` could be a promise, so I need to handle that case as well. Usually I'd prefer to not use the `.then()` syntax, but using `async` would make this function always return a `Promise`, which I don't want!

```javascript
import { types } from 'util';

function apply (target, thisArg, args) {
    // ...
    const result = target.apply(thisArg, args);
    if (types.isPromise(result)) {
        return result.then((result) => {
            const endTime = performance.now();
            console.log(result);
            console.log(endTime - startTime);
            return result;
        });
      }
    // ...
}
```

Nice, that's pretty rough but it mostly works!

### Proxy `construct` trap:

The `construct` trap gives you control to what happens when a function is called with `new`! The basic form of a `construct` trap handler is like this:

```javascript
function construct (target, args) {
    return new target(...args);
  }
```

I'm going to do basically the same thing as the `apply` trap, but I don't need to worry about `Promises`, since `constructors` are synchronous.

```javascript
import { performance } from 'perf_hooks';

function construct (target, args) {
    const startTime = performance.now();
    console.log(args);
    const instance = new target(...args);
    const endTime = performance.now();
    console.log(endTime - startTime);
    console.log(instance);
    return instance;
}
```

It'd be great if I could also wrap any *methods* of the instance too! I can access them via `target.prototype` and use the `getFunctions` function again:

```javascript
function construct (target, args) {
    // ...
    const proto = target.prototype;
    const prototypeFunctions = getFunctions(proto);
    Object.keys(prototypeFunctions).forEach((functionName) => {
      Object.defineProperty(proto, functionName, {
        value: new Proxy(proto[functionName], {
          apply: applyTrapHandler
        })
      });
    });
    // ...
    return instance;
}
```

Okay so now I have Proxies that wrap Proxies 🤯, but it should still work!

### Adding function names:

One thing that would be good to add is for the traps to log the `name` of the functions. I have access to the name everywhere I need it, but I need the trap to know about it:

```javascript
function createFunctionCallWrap (name) {
  return function apply (target, thisArg, args) {
      // ...
      console.log(name);
      const result = target.apply(thisArg, args);
      // ...
      return result;
  };
}

function createConstructorCallWrap (name) {
  return function apply (target, thisArg, args) {
      // ...
      console.log(name);
      const instance = new target(...args);
      // ...
      return instance;
  };
}
```

Nice! Now I get logs for all function calls, all constructor calls, and all instance method calls!

### Handling function arguments:

It would also be good to have logging for any function which are passed as arguments (like callback functions). Both traps give me access to the function arguments, so I just need to add another wrapper:

```javascript
function wrapArgs(args) {
    return args.map((arg) => {
        if (typeof arg !== 'function') {
            return arg;
        }
        return new Proxy(arg, {
            apply: ...
        });
    });
  }
```

Okay but now I have a little problem. In all the other cases I have access to the name of the function or constructor that is being wrapped, whether it is from the `module.exports` object, or the `target.prototype` object. I don't have the names of the arguments to the function, so I can't know the name of any argument that happens to be a function!

I do have access to the function though, which means I can call `toString()` and get the full text of the function.

```javascript
function foo (callback) { callback(); };

foo.toString() // "function foo (callback) { callback(); };"
```

I could do some RegExp magic and read the argument name? 

```javascript
const [argsString] = foo.toString().match(/function .* \((.*?)\)/);
const argNames = argsString.split(', ');
```

This is going to fall apart very quickly - I'd have to handle async functions, generators, arrow functions, optional arguments, etc. etc.

But I could use a proper parser and it could handle all that for me!

```javascript
import { parseScript } from 'esprima';

function getFunctionArgumentNames(func) {
    const AST = parseScript(`const f = ${func.toString()}`)
    // find argument names in AST
  }
```

I can use [`esprima`](https://esprima.org/) to get an [Abstract Syntax Tree](https://en.wikipedia.org/wiki/Abstract_syntax_tree) for the function. If `func` is an anonymous function (like `function () {}`) the parser will throw, so I need the `const f = ` bit to handle that case.

Once I've got the AST, I can query it for the bits I care about:


```javascript
import { parseScript } from 'esprima';
import { query } from 'esquery';

function getFunctionArgumentNames(func) {
    const [func] = query(parseScript(`const f = ${func.toString()}`), '[type=/Function/]');
    return func.params.map((param) => {
      const [identifier] = query(param, 'Identifier');
      return identifier.name;
    });
  }
```

I find the first (and only) function in the AST (which is the representation of the target function), and get its list of `params`. This could be normal parameters like `a, b, c`, or complex parameters like `d = 6, e =  getE()`. In either case I want to grab the first `Identifier`, and return its name. That would be `'a'`, `'b'`, `'c'`, `'d'`, and `'e'` in my above examples.

Now I can finish off `wrapArgs`

```javascript
function wrapArgs(argNames, args) {
    return args.map((arg, index) => {
        if (typeof arg !== 'function') {
            return arg;
        }
        return new Proxy(arg, {
            apply: createFunctionCallWrap(argNames[index])
        });
    });
  }
```

And change `createFunctionCallWrap` and `createConstructorCallWrap`:

```javascript

function createFunctionCallWrap (name) {
  return function apply (target, thisArg, args) {
      // ...
      const result = target.apply(thisArg, wrapArgs(args));
      // ...
      return result;
  };
}

function createConstructorCallWrap (name) {
  return function construct (target, args) {
      // ...
      const instance = new target(...wrapArgs(args));
      // ...
      return instance;
  };
}
```

### Nicer logs:

Okay, so now I have wrapped all functions, constructors, prototype methods, and any of their arguments that happen to be functions. And each time any of those are called I have access to their name, arguments, return value, and start and end times. It would be awesome to render these as a list with each entry and exit on their own line so I can scan it and see how the program ran.

It would also be cool to show somehow how deep in the call stack the program is. I can track that by incrementing a count before executing the real function, and decrementing it once it has run. I'm going to wrap all this logic up into `logStart` and `logEnd` functions:

```javascript
let depth = 0;

function logStart (name, args) {
    depth += 1;
    let debugString = printDepth(name);
    debugString += ` args: ${JSON.stringify(args)}`;
    process.stdout.write(`${debugString}\n`);
}

function logEnd (name, startTime, endTime, result) {
    let debugString = printDepth(name);
    debugString += ` time: ${endTime - startTime}ms`;
    debugString += ` return: ${JSON.stringify(result)}`;
    process.stdout.write(`${debugString}\n`);
    depth -= 1;
}

function printDepth (name) {
    return `${'▸'.repeat(depth)} ${name}`;
}
```

One issue with this is that if the `args` or `result` have any circular references in them, then `JSON.stringify` will throw. Node.js has already solved that for me though, so I can replace `JSON.stringify` with `util.inspect`.

I'm going to wrap that in a little helper so I can have all the options in one place:

```javascript
import { inspect } from 'util';

function printObject(object) {
    return inspect(object, { getters: true, depth: Infinity }).replace(/\n/g, '');
}
```

This will print all the details about an object that I need, and then strip any new lines so that each log only uses one line.

So with some dummy code this is the output I get:

```
▸ init args: []
▸▸ Fixture args: [ 1, [ 'hello' ], [Function] ]
▸▸ Fixture return: Fixture { _a: 1, _b: [ 'hello' ], _c: [Function] }
▸ init return: Fixture { _a: 1, _b: [ 'hello' ], _c: [Function] }
▸ Fixture.func args: []
▸▸ Fixture._func args: [ 1 ]
▸▸▸ _c args: [ 1 ]
▸▸▸ _c return: 1
▸▸ Fixture._func return: [ 'hello' ]
▸ Fixture.func return: undefined
```

### Adding this into my library:

So this is all going great and I want to try to add it to library. Since I want to turn it on and off with a environment variable, I have wrapped it all in a function like this:

```javascript
function debug () {
    if (process.env.DEBUG) {
        // Overwrite require so it wraps everything.
    }
};
```

I've added the `debug()` call inside library and now when I run it nothing happens... The code looks something like this:

```javascript
import { blah } from './blah';
import { whatever } from './whatever';

export function library () {
    debug();
    // run library
}
```

And when I put a `debugger;` inside the overwritten `require` call, it is never hit... 😐

So there are two things going on here. 

1) All the `import ...` statements are converted into `const { blah } = require('./blah');` calls.
2) The whole dependency graph is traversed long before my call to `debug()` happens.

All the calls to `require` happen before I've even turned on my debug mode...

To check that I'm right, I move the `debug()` call to the first line of my index file, so now it looks more like:

```javascript
debug();

import { blah } from './blah';
import { whatever } from './whatever';

export function betterer () {
    // run Betterer
}
```

And cool, now it works! 😅

This is probably fine, but it means that the tool is much less configurable, and I can't change settings in between different Betterer runs. Maybe that's good enough?

### Wrapping `require.cache`:

I think I can do better than that! As a Node.js application executes, and the dependency graph is traversed, a special cache on the `require` function is populated. I can access this cache using `require.cache`, and it contains the complete exports of any given dependency.

When I call `debug()` I can iterate over that cache and wrap all the functions that have already been required:

```javascript
Object.keys(require.cache).forEach((requirePath) => {
    const module = require.cache[requirePath];
    if (module && shouldWrap(requirePath)) {
      wrap(module.exports);
    }
});
```

Boom, just like that. Now I can have my `debug()` call wherever I want and all past and future requires will be wrapped correctly!

### Wrapping up 😎

So that's pretty neat and is working quite well! I'm quite happy with how it ended up, cause it looked pretty unlikely here and there! I've taken my prototype from here, rewritten it in TypeScript, added a bunch of options, and released it on npm at [`@phenomnomnominal/debug`](https://www.npmjs.com/package/@phenomnomnominal/debug). Maybe that will be of some use to someone else?!

Hit me up with questions/comments/suggestions 🎉