add v0.10 support and a smattering of logging

Author: tjfontaine

config.sample.js

@@ -5,6 +5,11 @@ var key = fs.readFileSync(path.join(__dirname, 'key.pem'));
 var cert = fs.readFileSync(path.join(__dirname, 'cert.pem'));
 
 module.exports = {
+  loggingConfig: {
+    // any otpions you would pass to createLogger
+    // https://github.com/trentm/node-bunyan
+    level: 'trace',
+  },
   listeners: [
     {
       host: '0.0.0.0',

index.js

@@ -5,6 +5,9 @@
 var child_process = require('child_process');
 var net = require('net');
 var tls = require('tls');
+var util = require('util');
+
+var bunyan = require('bunyan');
 
 var CertCloak = require('./lib/certcloak');
 var ConnectStream = require('./lib/connectstream');
@@ -16,6 +19,22 @@ var TorFilter = require('./lib/torfilter');
 
 var config = require('./config');
 
+var logConfig = util._extend({
+  name: 'webirc',
+}, config.loggingConfig);
+
+var LOG = bunyan.createLogger(logConfig);
+
+LOG.addSerializers({
+  client: function clientSerializer(client) {
+    return util.format('%d:[%s:%d] (isTor: %s)',
+      client.clientId,
+      client.remoteAddress,
+      client.remotePort,
+      client.isTor);
+  },
+});
+
 var definedListeners = {};
 
 config.listeners.forEach(function eachListener(listener) {
@@ -29,6 +48,7 @@ config.listeners.forEach(function eachListener(listener) {
   var serverOptions = {};
 
   var eventName = 'connection';
+
   switch (listener.type) {
     case 'plain':
       proto = net;
@@ -75,31 +95,33 @@ function enableListener(key) {
   var listener = definedListeners[key];
 
   if (!listener) {
-    console.error('trying to enable undefined listener', key);
+    LOG.error('trying to enable undefined listener', key);
     return;
   }
 
   if (listener.server) {
-    console.error('trying to renable enabled listener', key);
+    LOG.error('trying to renable enabled listener', key);
     return;
   }
 
+  LOG.info('starting listener', key);
+
   var server = listener.proto.createServer(listener.serverOptions);
 
-  server.listen(listener.listenOptions);
+  server.listen(listener.listenOptions.port, listener.listenOptions.host);
 
   server.on('listening', function serverListening() {
-    ConnectStream(server, { eventName: listener.eventName })
-      .pipe(Throttle(config))
-      .pipe(DNSFilter(config))
-      .pipe(CertCloak(config))
-      .pipe(TorFilter(config))
-      .pipe(IRCProxy(config))
+    ConnectStream(server, { eventName: listener.eventName, logger: LOG })
+      .pipe(Throttle(config, LOG))
+      .pipe(DNSFilter(config, LOG))
+      .pipe(CertCloak(config, LOG))
+      .pipe(TorFilter(config, LOG))
+      .pipe(IRCProxy(config, LOG))
       .resume(); // Don't stop accepting new clients
   });
 
   server.on('error', function serverError(err) {
-    console.error('listener failed', err);
+    LOG.error('listener failed', err);
     // TODO restart listener?
   });
 
@@ -110,12 +132,12 @@ function disableListener(key) {
   var listener = definedListeners[key];
 
   if (!listener) {
-    console.error('trying to disable undefined listener', key);
+    LOG.error(key, 'trying to disable undefined listener');
     return;
   }
 
   if (!listener.server) {
-    console.error('listener already disabled', key);
+    LOG.error(key, 'listener already disabled');
     return;
   }
 
@@ -135,8 +157,7 @@ process.on('SIGHUP', function configReload() {
     },
     function readConifg(error, stdout, stderr) {
       if (error) {
-        console.error('Failed to read configuration file');
-        console.error(stderr);
+        LOG.error(stderr, 'Failed to read configuration file');
       } else {
         try {
           var newConfig = JSON.parse(stdout);
@@ -145,25 +166,24 @@ process.on('SIGHUP', function configReload() {
             var definedListener = definedListeners[key];
 
             if (!definedListener) {
-              console.error('cannot add new listeners with reload, ignoring', key);
+              LOG.error('cannot add new listeners with reload, ignoring', key);
               return;
             }
 
             if (listener.enabled && !definedListener.server) {
-              console.error('enabling', key, 'listener');
+              LOG.error('enabling', key, 'listener');
               enableListener(key);
             }
 
             if (!listener.enabled && definedListener.server) {
-              console.error('disabling', key, 'listener');
+              LOG.error('disabling', key, 'listener');
               disableListener(key);
             }
           });
           config.blockTor = !!newConfig.blockTor;
           config.blockTorMessage = newConfig.blockTorMessage;
         } catch (e) {
-          console.error('Failed to parse configuration file');
-          console.error(e);
+          LOG.error(e, 'Failed to parse configuration file');
         }
       }
     });

lib/certcloak.js

@@ -4,21 +4,25 @@ var child_process = require('child_process');
 var stream = require('stream');
 var util = require('util');
 
-function CertCloak(config) {
+function CertCloak(config, logger) {
   if (!(this instanceof CertCloak))
-    return new CertCloak(config);
+    return new CertCloak(config, logger);
 
   stream.Transform.call(this, {
     objectMode: true,
     highWaterMark: 0,
   });
 
+  this.log = logger.child({ pipeline: 'certcloak' });
+
   this.cloak_config = config.cloaks;
 }
 util.inherits(CertCloak, stream.Transform);
 
 
 CertCloak.prototype._transform = function certCloakTransform(client, e, cb) {
+  this.log.trace({ client: client }, 'got client');
+
   // We have a TLS Socket
   if (!client.getPeerCertificate) {
     this.push(client);

lib/connectstream.js

@@ -13,6 +13,8 @@ function ConnectStream(socket, options) {
     objectMode: true,
   });
 
+  this.log = options.logger.child({ pipeline: 'connectstream'});
+
   this.cs_socket = socket;
 
   var self = this;
@@ -22,12 +24,14 @@ function ConnectStream(socket, options) {
 
   socket.on(evt, function socketOnConnect(client) {
     client.clientId = CLIENT_ID++;
+    self.log.trace({ client: client }, 'connected');
     self.push(client);
   });
 
   socket.on('close', function socketClosing() {
     // We are no longer expecting new connections, so clear the pipeline
     // pushing null means EOF which closes the writeables along the way
+    self.log.trace({ client: client }, 'disconnected');
     self.push(null);
   });
 }

lib/dnsfilter.js

@@ -8,15 +8,17 @@ var vasync = require('vasync');
 
 var DNSBLQuery = require('./dnsbl');
 
-function DNSFilter(config) {
+function DNSFilter(config, logger) {
   if (!(this instanceof DNSFilter))
-    return new DNSFilter(config);
+    return new DNSFilter(config, logger);
 
   stream.Transform.call(this, {
     objectMode: true,
     highWaterMark: 0,
   });
 
+  this.log = logger.child({ pipeline: 'dnsfilter' });
+
   this.dnsfltr_config = config.dnsbl;
 }
 util.inherits(DNSFilter, stream.Transform);
@@ -25,6 +27,8 @@ util.inherits(DNSFilter, stream.Transform);
 DNSFilter.prototype._transform = function dnsfltrTransform(client, enc, cb) {
   var self = this;
 
+  this.log.trace({ client: client }, 'got client');
+
   var work = vasync.parallel({
     funcs: [
       function reverseDns(next) {
@@ -51,10 +55,11 @@ DNSFilter.prototype._transform = function dnsfltrTransform(client, enc, cb) {
       client.score = score.total;
 
       if (score.total > self.dnsfltr_config.maxScore) {
-        console.error('client', client.remoteAddress,
-                      'exceeded dnsbl score', score.total, 'max of',
-                      self.dnsfltr_config.maxScore, 'reasons:',
-                      score.reasons.join('|'));
+        self.log.error({
+          client: client,
+          score: score,
+          config: self.dnsfltr_config
+        }, 'client exceeded dnsbl score');
         client.end('Administratively refused');
         return client.destroy();
       }

lib/ircproxy.js

@@ -9,61 +9,76 @@ var lstream = require('lstream');
 
 var WebIRC = require('./webirc');
 
-function IRCProxy(config) {
+function IRCProxy(config, logger) {
   if (!(this instanceof IRCProxy))
-    return new IRCProxy(config);
+    return new IRCProxy(config, logger);
 
   stream.Transform.call(this, {
     objectMode: true,
     highWaterMark: 0,
   });
 
   this.ircp_config = config;
+  this.ircp_connect_event = 'connect';
 
   switch (config.destination.type) {
     case 'plain':
       this.ircp_proto = net;
       break;
     case 'tls':
       this.ircp_proto = tls;
+      this.ircp_connect_event = 'secureConnect';
       break;
     default:
       throw new Error('Must define an outbound protocol');
       break;
   }
 
+  this.log = logger.child({ pipeline: 'ircproxy' });
+
   this.ircp_options = util._extend({}, config.destination);
 }
 util.inherits(IRCProxy, stream.Transform);
 
 IRCProxy.prototype._transform = function ircProxyTransform(client, enc, cb) {
+  this.log.trace({ client: client }, 'got client');
+  client.log = this.log.child({ client: client });
+
+  client.log.trace({
+    opts: this.ircp_options,
+    proto: this.ircp_proto,
+  }, 'connecting to irc');
+
   var outbound = this.ircp_proto.connect(this.ircp_options);
 
   var self = this;
 
-  outbound.on('connect', function outboundConnected() {
+  outbound.on(this.ircp_connect_event, function outboundConnected() {
+    client.log.info('connected to irc');
     client
       .pipe(WebIRC(client, self.ircp_config))
       .pipe(outbound)
       .pipe(client);
   });
 
   client.on('close', function clientClosed() {
+    client.log.info('client closed');
     outbound.destroy();
   });
 
   outbound.on('close', function outboundClosed() {
+    client.log.info('outbound closed');
     client.destroy();
   });
 
   outbound.on('error', function outboundError(err) {
     // TODO relay error
-    console.error('outbound connection error', client.remoteAddress, err.message);
+    client.log.error({ err: err }, 'outbound connection error');
   });
 
   client.on('error', function clientError(err) {
     // TODO relay error
-    console.error('client connection error', client.remoteAddress, err.message);
+    client.log.error({ err: err }, 'client connection error');
   });
 
   cb();

lib/throttle.js

@@ -5,15 +5,16 @@ var util = require('util');
 
 var CONNECTIONS = {};
 
-function Throttle(config) {
+function Throttle(config, logger) {
   if (!(this instanceof Throttle))
-    return new Throttle(config);
+    return new Throttle(config, logger);
 
   stream.Transform.call(this, {
     objectMode: true,
     highWaterMakr: 0,
   });
 
+  this.log = logger.child({ pipeline: 'throttle' });
   this.thrt_timeout = config.reconnectTime;
 
   var self = this;
@@ -34,17 +35,25 @@ util.inherits(Throttle, stream.Transform);
 
 
 Throttle.prototype._transform = function thrtlTransform(client, enc, cb) {
+  this.log.trace({ client: client }, 'got client');
+
   var time = CONNECTIONS[client.remoteAddress];
   var cur = Date.now();
   var timeout = this.thrt_timeout;
 
   if (time && (cur - time) < timeout) {
-    console.error('Throttling client', client.remoteAddress);
+    this.log.error('throttling client', {
+      remoteAddress: client.remoteAddress,
+      ts: cur,
+      prev: time,
+      timeout: timeout,
+    });
     client.end('ERROR :Trying to reconnect too fast.\r\n');
     client.destroy();
     return cb();
   }
 
+  this.log.trace('client time registered', { remoteAddress: client.remoteAddress, ts: cur });
   CONNECTIONS[client.remoteAddress] = cur;
   this.push(client);
   return cb();