seanmonstar

Feb 11 2014

intel v0.5

intel is turning into an even more awesome logging framework than before, as if that was possible! Today, I released version 0.5.0, and am now here to hawk it’s newness. You can check out the full changelog yourself, but I want to highlight a couple bits.

JSON function strings

intel.config is really powerful when coupled with some JSON config files, but Formatters and Filters were never 100% in config, because you could pass a custom function to either to customize to your little kidney’s content. It’s not possible to include typical functions in JSON. Much sad face. So, the formatFn and filterFn options allow you to write a function in a string, and intel will try to parse it into a function. Such JSON.

Logger.trace

A new lowest level was introduced, lower than even VERBOSE, and that’s TRACE. Likewise, Logger.trace behaves like console.trace, providing a stack trace with your message. If you don’t enable loggers with TRACE level logging, then no stacks will be traced, and everything will choo-choo along snappy-like.

Full dbug integration

This is the goods. intel is an awesome application logging library, since it lets you powerfully and easily be a logging switchboard: everything you want to know goes everywhere you want. However, stand-alone libraries have no business deciding where logs go. Libraries should simply provide logging when asked to, and shut up otherwise. That’s why libraries should use something like dbug. Since v0.4, intel has been able to integrate somewhat with dbug, but with 0.5, it can hook directly into it, meaning less bugs, and better performance. Examples!

// hood/lib/csp.js
var dbug = require('dbug')('hood:csp');

exports.csp = function csp(options) {
    dbug('csp options:', options);
    if (!options.policy) {
        dbug.warn('no policy provided. are you sure?');
    }
    // ...
};

// myapp/server.js
var intel = require('intel');
intel.console({ debug: 'hood' });
// will see: 'myapp.node_modules.hood.csp:DEBUG csp options: {}'

Dare I say, using intel and dbug together gives the best logging solution for libraries and apps.

Jan 2 2014

syslogger

When recently writing an intel-syslog library, I noticed that somehow, npm was lacking a sane syslog library. The popular one, node-syslog, is a giant singleton, meaning it’s impossible to have more than one instance available. That felt wrong. Plus, it’s a native module, and for something so simple, I’d rather not have to compile anything.

That’s where syslogger comes in. It’s pure JavaScript, and has a simple API to allow you to create as many instances as you’d like.

var SysLogger = require('syslogger');
var logger = new SysLogger({
  name: 'myApp',
  facility: 'user',
  address: '127.0.01',
  port: 514
});

logger.log(severity, message);
// or
logger.notice(message); //etc

Enjoy.

+

intel 0.4

I released v0.4 of intel last month, but never got around to writing up what’s new.

debug/dbug

I started out all this logging business claiming we should console.log() all the things. intel can easily handle any libaries using console.log. However, I started to see how frustrating it could be for libraries to be spilling logs all over stdout without being asked. dbug is a utility for libraries to provide logging, but to be quiet by default.

intel v0.4 includes the ability to play nice with dbug (and debug). You can call intel.console({ debug: someStr }) to turn on dbug in libraries matching your string. Due to how debug works, by checking an environment variable right when it is required, you’ll need to run intel.console() before requiring any library that uses debug.

performance

As with every release, things get faster. According to meaningless benchmarks, we’re now ~2x faster than winston. Whatever that means.

syslog

Not part of the actual release, but released at the same time, is an intel-syslog library. This provides a simple syslog handler that you can easily use in your app.

require('intel').config({

  handlers: {
    'syslog': {
      'class': 'intel-syslog',
      'address': '127.0.0.1',
      'facility': 'user' //etc...
    }
  },

  loggers: {
    'myapp': {
      'handlers': ['syslog']
    }
  }

});

I’ve created a wiki page to contain handlers such as intel-syslog that work with intel. If you create or find a library for intel, please add it to the list so we all can be happier logging things.

Oct 25 2013

dbug v0.1

I’ve been on a logging spree recently, and after having spent some time on an application logging module, I’ve been thinking about what libraries can do about logging. At first I said that libraries should just dump everything into console.log, but I can definitely see downsides to that.

debug

debug is a popular utility that handles this problem of libraries wanting logging without annoying consumers quite well. You can use debug, name a logger, and log messages all you want. Unless a consumer adds en ENV variable to listen to those debug messages, it will be all quiet.

dbug

dbug works largely the same, with a few tweaks that I feel are really helpful, but I don’t think I’d have been able to convince TJ to include them in debug.

First of all, it’s a perfectly safe drop-in replacement for debug. It has the same API.

However, it adds a few familiar methods that you’d find on the console object, so you can classify the severity of particular dbug messages. Some may simply be info messages, while others are meant to signify when an error or warn has occurred. Still though, only if the consumer has opted-in to see your messages by setting process.env.DEBUG.

The log level will be included in the log message, so everyone can see the severity.

Additionally, the DEBUG matching is slightly more lenient. You can still use * and comma separated names, but additionally, specifying a name now implies any of it’s children.

DEBUG=foo will match foo:bar. Basically, every name is also the same as name:*.

v0.1.0

0.1 is available now.

A few things I’ve been toying with adding to additional versions:

  • DEBUG=foo.warn to only get warn or greater message from the foo logger.
  • Allowing . to be a separate in log names also: dbug('foo.bar').

And, currently next up is getting intel to play nice with debug/dbug.

Oct 4 2013

intel 0.2

I’ve already pushed intel 0.2 out the door, after a week of tweaking and massaging it into Persona repos. Here’s the changelog, explanation after:

  • [new] Filters
  • [new] Handler timeout option
  • [new] pid included in LogRecord
  • [new] use JSON with intel.config()
  • [changed] Promises are now LazyPromises
  • [changed] printf is now a small, internal, much faster implementation
  • [removed] node v0.6 support

Filters

There was already a fair amount of filtering possible in v0.1, by combining log levels and named loggers. However, it became apparent that you’d want to also be able to filter messages on arbitrary details, and there wasn’t a super easy way to do that. Now you can. Here’s an example filter:

 handler.addFilter(new intel.Filter(/user/g));

This filter means that the handler will only receive messages that include the string “user” in the message text.

config with JSON

Configuration was powerful, but it required a a JavaScript file to provide Handler classes. Since we use JSON files to define our configuration for our servers, it was immediately noticed that intel needed this as well. So, now, the class property of Handlers and Filters accepts a String, which will be used to require the class. Intel’s handlers are available like this: intel/handlers/console.

Performance

I set up some benchmarks to see just much power intel sucks up, and then cried a little. Clearly, comparing speed to the basic console.log was an exercise meant for trolls, but I also compared against winston. Removing some Array.forEachs, using a light-weight printf, and using LazyPromises made intel faster than winston (woot!).

Specifically, Promises were the biggest slow down. They’re awesome control structures, but boy are they slow. Since most people won’t ever want them anyways, it would suck if everyone had to pay their compute cost. So, log methods now return a proxy with a getter for then. When then is accessed the first time, the Promises are constructed, and handed to the caller. You only pay the cost on the few times you really want their convenience.

intel 0.2

As always, file bugs or feature requests at the issuer tracker. I’m still aiming to be able to call intel at v1.0 soon, so any feedback will help shape this into an excellent go-to logging library.

Sep 30 2013

intel

A couple months ago, I was blagging on about logging libraries in nodejs. After pointing out how annoying it is to use logging libraries with 3rd party modules, I declared that all modules should simply use console.log(), and let applications hijack the console. Then, I looked around the npms, and couldn’t find an excellent example of a logging library that embraced that idea.

So, clearly, that meant I needed to write my own. It’s called intel. Why another logging library? Well duh, cause this one is better.

Loggers get names

Before nodejs, I came from Pythonia. Over yonder, they have an excellent logging module as part of the standard library. It’s glorious. It uses hierarchal named loggers. Winston, the library we currently use in Persona, while being perfectly awesome, doesn’t have support for this. It does allow you to define Containers and Categories, but it’s not as powerful as I’d like.

Specifically, intel adds 2 noteworthy features to Loggers: hierarchy and humane setup.

  1. Loggers use an hierarchy based on their names. Logger foo.bar is a child of foo. So is foo.bar.baz. When a logger receives a log message, after handling itself, it passes the message up to its parents.

    For instance, you could decide that all log messages from foo should go to the terminal. However, your foo/bar.js module has some critical code you want to keep tabs on. You could add a handler to the foo.bar logger that sends all messages of WARN and greater to email. After that handler, foo.bar will hand the message to its parent foo, and also send it to the terminal

  2. Of the other libraries I could fine that supported multiple named loggers, they all required that you instantiate the loggers with all options ahead of time. This adds more friction having a named logger per module in your app. Instead, intel makes it super easy for you get a new named logger.

     var logger = intel.getLogger('foo.bar.baz.quux');
    

    You don’t have to have added any handlers to your newly minted logger. It will just pass the messages right up to it’s parents. The messages will still keep the name of the originating logger, though.

Powerful configuration

Named loggers allow for really powerful yet easy-to-use logging. Combined with a little bit of configuration, and it’s all magical. You can setup a couple root loggers, with various levels pumping messages to various handlers (Console, File, Email, Database, etc). You can see an example in the docs.

Infiltrating the console

The motivating reason I started intel was to do exactly this. I want my apps to have the power to configure logging just the way I want, and I want all my dependencies to play along with my logging rules. So, after you setup your loggers and handlers, you can inject intel into the global console object, and watch as any dependencies that use console.log follow your rules, and automatically get assigned the correct names.

 intel.console();
 intel.getLogger('patrol.node_modules.express').setLevel(intel.WARN);
 // in express.js
 console.log('new request'); // automatically gets assigned to patrol.node_modules.express logger.

intel

I’m starting by a 0.1 release of intel. Any bugs or feature requests can filed in the issue tracker. I don’t want intel to be one of those libraries that is forever sub-1.0. After some use in the wild, with bugs being fixed and possibly APIs being made better, I’d like to get to a 1.0 soon.

So, try swapping out your current logger for intel. Name some loggers. You’ll come around.

Jul 25 2013

console.log() all the things!

Let’s talk about logging. We like logging things. Logging to console, to files, to syslog, maybe even sending some over email. Formatting our logging is pretty fun. Oh, the colors! Of course, we must colorize our logs. Or not, if your colorist. But there’s a problem with logging. There is? Yup. We can’t agree how everything should log its logs.

Let’s look at this from two levels: libraries and apps.

If you follow The Node Way, then you make and use focused packages or libraries from npm to accomplish specific tasks. Sometimes, those tasks need to tell the developer what happened, or otherwise record for eternity their minor quibbles. So we end up with libraries that want to log things.

The modules are no good without plugging them together to make an app. Many apps are web apps, but they could be anything, like flying nodecopters or some such. So you have a bunch of app specific code tying together libraries, and you want to log all over the place. You want to know response codes, response times, when errors occur, when people attack your app, and when unicorns invade.

So what’s the problem?

At the end of the day, you want to ship an app. We all ship apps. And while you were devving away on your machine, logging to console was perfectly fine. But once you start shipping, you can’t just watch the console blast by on hundreds of production machines like The Matrix. This is typically when you decide that you need a configurable logging library, so you can rotate log files, send some to syslog, email exception logs, and fill them full of colors.

To use a real example, we’ll play with winston. To use winston, we create a logger, specify some transports, and then pass the logger all over the application.

const winston = require('winston');
var logger = new (winston.Logger)({ transports: [
    new (winston.transports.File)({ 
        filename: '/var/log/app.log', 
        colorize: true 
    }),
    new (winston.transports.Console)({ colorize: true })
] });
module.exports = logger;

Then, elsewhere, you would require that module we just defined, and log stuff.

const logger = require('./lib/logger');
logger.info('blast off');

This works for a while in your own app, but you’ll notice that you can’t make any of your dependencies use your logger. It’s also pretty terrible when you decide you want to uplift one of your lib modules into a standalone package. You realize you still want the logging messages, but now you can’t depend on the app giving you a logger. There goes another unicorn.

We’re never going to agree on a library that all apps and libs should use, and we shouldn’t! Competition, blah blah, etc. I’ll walk through probably the most obvious solution, show why it’s not good enough, and then propose the real solution.

Log, log, pass?

Libraries could accept a logger option. This works fine when the library provides a constructor. It’s terrible when the library simply provides a handful of static utility functions. Those that do have constructors could allow a logger option, but default to console, and still benefit from the real solution below.

I propose, instead, that all libraries just use console.log and logging libraries overload console.log. Well, clearly, overload all of console. Craziness? Maybe, but then we already get paid to write JavaScript.

console.log()

In node.js, the console object comes with debug, log, info, warn, and error methods already. So a library can depend on this universal global, and log things at the correct levels. The application, at the main module, can create a fancy pants logger, and overload console with it. Now, all library code is pumping its logs through your fancy pants, and is none the wiser. How fancy.

Here’s how we’d do that with our winston logger:

const winston = require('winston');

var logger = new (winston.Logger)({
  // transports and whatever loggy stuffs
});

logger.extend(console);

var log = console.log;
console.log = function hijacked_log(level) {
  if (arguments.length > 1 && level in this) {
    log.apply(this, arguments);
  } else {
    var args = Array.prototype.slice.call(arguments);
    args.unshift('debug');
    log.apply(this, args);
  }
}

So say we all?