Improve error handling

nodeca · May 8, 2017 · 02f092e · 02f092e
1 parent 56ecfb9
commit 02f092e
Show file tree

Hide file tree

Showing 2 changed files with 41 additions and 23 deletions.
diff --git a/lib/session.js b/lib/session.js
@@ -5,7 +5,8 @@
 
 const crypto         = require('crypto');
 const Denque         = require('denque');
-const debug          = require('debug')('nntp-server');
+const debug_err      = require('debug')('nntp-server:error');
+const debug_net      = require('debug')('nntp-server:network');
 const destroy        = require('destroy');
 const serializeError = require('serialize-error');
 const split2         = require('split2');
@@ -26,9 +27,10 @@ function escape_regexp(str) {
 function is_stream(s) { return s && typeof s.on === 'function'; }
 
 
-function Command(fn) {
+function Command(fn, input) {
   this.state = CMD_WAIT;
   this.fn = fn;
+  this.input = input;
   this.resolved_value = null;
   this.rejected_value = null;
 }
@@ -70,7 +72,7 @@ function Session(server, stream) {
   this.debug_mark = crypto.pseudoRandomBytes(3).toString('hex');
 
   // Random string used to track connection in logs
-  debug('    [%s] %s', this.debug_mark, 'new connection');
+  debug_net('    [%s] %s', this.debug_mark, 'new connection');
 
   // Create RE to search command name. Longest first (for subcommands)
   let commands = Object.keys(this.server.commands).sort().reverse();
@@ -85,29 +87,29 @@ function Session(server, stream) {
 
   pump(this.out_stream, stream);
 
-  if (debug.enabled) {
+  if (debug_net.enabled) {
     let debug_logger = split2();
 
     pump(this.out_stream, debug_logger);
 
     debug_logger.on('data', line => {
-      debug('<-- [%s] %s', this.debug_mark, line);
+      debug_net('<-- [%s] %s', this.debug_mark, line);
     });
   }
 
   this.lines.on('data', line => {
-    debug('--> [%s] %s', this.debug_mark, line);
+    debug_net('--> [%s] %s', this.debug_mark, line);
     this.parse(line);
   });
 
   this.lines.on('error', err => {
-    debug('ERROR: %O', serializeError(err));
+    debug_err('ERROR: %O', serializeError(err));
     this.server._onError(err);
     this.out_stream.destroy();
   });
 
   this.lines.on('end', () => {
-    debug('    [%s] %s', this.debug_mark, 'connection closed');
+    debug_net('    [%s] %s', this.debug_mark, 'connection closed');
     this.out_stream.destroy();
   });
 }
@@ -143,8 +145,8 @@ Session.prototype.write = function (data) {
 };
 
 
-function enqueue(stream, fn) {
-  stream.pipeline.push(new Command(fn));
+function enqueue(stream, command) {
+  stream.pipeline.push(command);
   stream.tick();
 }
 
@@ -155,28 +157,28 @@ Session.prototype.parse = function (data) {
 
   // Command not recognized
   if (!this.__search_cmd_re.test(input)) {
-    enqueue(this, () => Promise.resolve(status._500_CMD_UNKNOWN));
+    enqueue(this, new Command(() => Promise.resolve(status._500_CMD_UNKNOWN), input));
     return;
   }
 
   let cmd = input.match(this.__search_cmd_re)[1].toUpperCase();
 
   // Command looks known, but whole validation failed -> bad params
   if (!this.server.commands[cmd].validate.test(input)) {
-    enqueue(this, () => Promise.resolve(status._501_SYNTAX_ERROR));
+    enqueue(this, new Command(() => Promise.resolve(status._501_SYNTAX_ERROR), input));
     return;
   }
 
   // Command require auth, but it was not done yet
   // Force secure connection if needed
   if (this.server._needAuth(this, cmd)) {
-    enqueue(this, () => Promise.resolve(
+    enqueue(this, new Command(() => Promise.resolve(
       this.secure ? status._480_AUTH_REQUIRED : status._483_NOT_SECURE
-    ));
+    ), input));
     return;
   }
 
-  enqueue(this, () => Promise.resolve(this.server.commands[cmd].run(this, input)));
+  enqueue(this, new Command(() => Promise.resolve(this.server.commands[cmd].run(this, input)), input));
 };
 
 
@@ -191,9 +193,19 @@ Session.prototype.tick = function () {
     this.tick();
 
   } else if (cmd.state === CMD_REJECTED) {
+    let error = cmd.rejected_value || {};
+
+    let wrapped_error = new Error(`Command "${cmd.input}" failed: ${error.message}`);
+
+    for (let prop of Object.getOwnPropertyNames(error)) {
+      if (prop === 'message') continue;
+
+      wrapped_error[prop] = error[prop];
+    }
+
     this.write(status._403_FUCKUP);
-    debug('ERROR: %O', serializeError(cmd.rejected_value));
-    this.server._onError(cmd.rejected_value);
+    debug_err('ERROR: %O', serializeError(wrapped_error));
+    this.server._onError(wrapped_error);
     this.pipeline.shift();
     this.tick();
 

diff --git a/test/pipeline.js b/test/pipeline.js
@@ -138,19 +138,25 @@ describe('pipeline', function () {
 
 
   it('should report error when command fails', function () {
-    let called;
+    let error;
 
-    nntp._onError = function () {
-      called = true;
+    nntp._onError = function (err) {
+      if (error) throw new Error('onError called twice');
+      error = err;
     };
 
     nntp._selectGroup = async function () {
-      throw new Error('a bug is here');
+      let err = new Error('a bug is here');
+      err.code = 'ETEST';
+      throw err;
     };
 
     return client
-      .send('GROUP a')
+      .send('GROUP foobar')
       .expect(/^403 /)
-      .then(() => assert(called));
+      .then(() => {
+        assert.equal(error.code, 'ETEST');
+        assert(error.message.match(/GROUP foobar.*a bug is here/));
+      });
   });
 });