Skip to content
This repository

New logging #44

Merged
merged 13 commits into from about 1 year ago

1 participant

Chris Tavares
This page is out of date. Refresh to see the latest.
2  examples/chat/app.js
@@ -79,7 +79,7 @@ io.configure(function () {
79 79
     topic: topic,
80 80
     subscription: subscription,
81 81
     connectionString: sbconn,
82  
-    listeners: SbStore.logging.console
  82
+    logger: io.get('logger')
83 83
   }));
84 84
 
85 85
   io.set('transports', ['xhr-polling']);
111  lib/logging.js
... ...
@@ -1,111 +0,0 @@
1  
-/**
2  
-* Copyright (c) Microsoft.  All rights reserved.
3  
-*
4  
-* Licensed under the Apache License, Version 2.0 (the "License");
5  
-* you may not use this file except in compliance with the License.
6  
-* You may obtain a copy of the License at
7  
-*   http://www.apache.org/licenses/LICENSE-2.0
8  
-*
9  
-* Unless required by applicable law or agreed to in writing, software
10  
-* distributed under the License is distributed on an "AS IS" BASIS,
11  
-* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
12  
-* See the License for the specific language governing permissions and
13  
-* limitations under the License.
14  
-*/
15  
-
16  
-'use strict';
17  
-
18  
-var util = require('util');
19  
-
20  
-/**
21  
- * Convenience function to create listener objects
22  
- * which wire up to the events on the store
23  
- * and service bus interface.
24  
- *
25  
- * @param {object} handlers
26  
- *    object containing handlers for the various
27  
- *    events from the store & service bus. Looks
28  
- *    for methods with the following names:
29  
- *
30  
- *    onsubscribe(name, consumer) - a new subscriber to a store message
31  
- *    onreceived(nodeId, name, args) - message has been received, args as array
32  
- *    onunsubscribe(name, consumer) - unsubscribe from store
33  
- *    onpoll(err, message) - poll cycle on service bus completed
34  
- *    onsberror(err) - error when interacting with service bus
35  
- *
36  
- */
37  
-
38  
-function makeListener(handlers) {
39  
-  var storeEvents = ['subscribe', 'unsubscribe', 'received'];
40  
-  var sbEvents = ['poll', 'sberror'];
41  
-
42  
-  function wireHandlers(emitter, eventNames) {
43  
-    eventNames.forEach(function (eventName) {
44  
-      var handlerFunc = handlers['on' + eventName];
45  
-      if (handlerFunc) {
46  
-        emitter.on(eventName, handlerFunc.bind(handlers));
47  
-      }    
48  
-    });
49  
-  }
50  
-
51  
-  var listener = {
52  
-    store: function (store) {
53  
-      wireHandlers(store, storeEvents);
54  
-      if (handlers.init) {
55  
-        handlers.init(store);
56  
-      }
57  
-    },
58  
-
59  
-    sb: function (sb) {
60  
-      wireHandlers(sb, sbEvents);
61  
-    }
62  
-  };
63  
-
64  
-  return listener;
65  
-}
66  
-
67  
-/**
68  
- * Logger object which outputs everything to the console
69  
- *
70  
- */
71  
- var consoleLog = makeListener({
72  
-  init: function (store) {
73  
-    this.nodeId = store.nodeId;
74  
-  },
75  
-
76  
-  onsubscribe: function (name, consumer) {
77  
-    log('SbStore has new subscriber for %s events', name);
78  
-  },
79  
-
80  
-  onreceived: function (nodeId, name, args) {
81  
-    log('SbStore nodeId %s received message of type %s from node %s',
82  
-      this.nodeId, name, nodeId);
83  
-  },
84  
-
85  
-  onunsubscribe: function (name, consumer) {
86  
-    log('SbStore unsubscribing from %s', name);
87  
-  },
88  
-
89  
-  onpoll: function (err, message) {
90  
-    if (err === 'No messages to receive') {
91  
-      log('Service bus poll completed, no message');
92  
-    } else {
93  
-      log('Service bus poll completed, err = %s, message = %s', err, util.inspect(message));
94  
-    }
95  
-  },
96  
-
97  
-  onsberror: function (err) {
98  
-    log('Service bus error: %s', err.message);
99  
-  }
100  
- });
101  
-
102  
-// helper for formatting
103  
-
104  
-function log() {
105  
-  console.log(util.format.apply(null, arguments));
106  
-}
107  
-
108  
-module.exports = {
109  
-  makeListener: makeListener,
110  
-  console: consoleLog
111  
-};
41  lib/sbstore.js
@@ -20,14 +20,12 @@ var io = require('socket.io')
20 20
   , uuid = require('node-uuid')
21 21
   , azure = require('azure')
22 22
   , Client = require('./sbclient')
23  
-  , logging = require('./logging')
24 23
   , MessageBatcher = require('./messagebatcher')
25 24
   , MessageSequencer = require('./messagesequencer')
26 25
   , ServiceBusConnector = require('./servicebusconnector');
27 26
 
28 27
 exports = module.exports = ServiceBusStore;
29 28
 ServiceBusStore.Client = Client;
30  
-ServiceBusStore.logging = logging;
31 29
 
32 30
 /**
33 31
  * construct the store that uses Service Bus to communicate
@@ -43,8 +41,14 @@ ServiceBusStore.logging = logging;
43 41
 function ServiceBusStore(options) {
44 42
   io.Store.apply(this, arguments);
45 43
 
  44
+  this.log = options && options.logger;
  45
+
46 46
   this.nodeId = (options && options.nodeId) || uuid.v4();
47 47
   this.sb = this.createServiceBusConnector(options);
  48
+ 
  49
+  this.log && this.log.info('Service Bus Store created', 'host:' + this.serviceBusService.host,
  50
+    'topic:' + options.topic, 'sub:' + options.subscription);
  51
+
48 52
   this.subscribers = {};
49 53
 
50 54
   this.hookupListeners(options && options.listeners);
@@ -95,10 +99,13 @@ ServiceBusStore.prototype.unsubscribe = function (name, consumer) {
95 99
   this.emit('unsubscribe', name, consumer);
96 100
 }
97 101
 
98  
-ServiceBusStore.prototype.destroy = function () {
99  
-  Store.prototype.destroy.call(this);
100  
-  this.sb.stop();
101  
-  this.subscribers = {};
  102
+ServiceBusStore.prototype.destroy = function (stoppedCallback) {
  103
+  var self = this;
  104
+  this.sb.stop(function () {
  105
+    io.Store.prototype.destroy.call(self);
  106
+    self.subscribers = {};
  107
+    stoppedCallback && stoppedCallback();
  108
+  });
102 109
 }
103 110
 
104 111
 ServiceBusStore.prototype.receiveMessage = function (sourceNodeId, name, args) {
@@ -120,24 +127,17 @@ ServiceBusStore.prototype.createServiceBusConnector = function createServiceBusC
120 127
     throw new Error('Must specify one of connectionString or serviceBusService in options');
121 128
   }
122 129
 
123  
-  var serviceBusService;
124  
-
125 130
   if (options.connectionString) {
126  
-    serviceBusService = azure.createServiceBusService(options.connectionString);
127  
-  } else {
128  
-    serviceBusService = options.serviceBusService;
  131
+    options.serviceBusService = azure.createServiceBusService(options.connectionString);
129 132
   }
130 133
 
131  
-  var createOptions = {
132  
-    nodeId: this.nodeId,
133  
-    topic: options.topic,
134  
-    subscription: options.subscription,
135  
-    serviceBusService: serviceBusService
136  
-  };
  134
+  this.serviceBusService = options.serviceBusService;
  135
+  options.logger = this.log;
  136
+  options.nodeId = this.nodeId;
137 137
 
138  
-  return new MessageBatcher(createOptions, 
139  
-    new MessageSequencer(createOptions, 
140  
-      new ServiceBusConnector(createOptions)));
  138
+  return new MessageBatcher(options, 
  139
+    new MessageSequencer(options, 
  140
+      new ServiceBusConnector(options)));
141 141
 }
142 142
 
143 143
 ServiceBusStore.prototype.hookupListeners = function (listeners) {
@@ -152,4 +152,3 @@ ServiceBusStore.prototype.hookupListeners = function (listeners) {
152 152
     l.sb(that.sb);
153 153
   });
154 154
 }
155  
-
20  lib/servicebusconnector.js
@@ -36,6 +36,7 @@ function ServiceBusConnector(options) {
36 36
   this.subscription = options.subscription;
37 37
   this.numReceives = options.numReceives || DEFAULT_SIMULTANEOUS_RECEIVES;
38 38
   this.receivesRunning = 0;
  39
+  this.log = options.logger;
39 40
 }
40 41
 
41 42
 util.inherits(ServiceBusConnector, EventEmitter);
@@ -47,7 +48,9 @@ ServiceBusConnector.prototype.start = function () {
47 48
   function pollSb() {
48 49
     self.serviceBusReceiver.receiveSubscriptionMessage(self.topic, self.subscription, function (err, receivedMessage) {
49 50
 
50  
-      self.emit('poll', err, receivedMessage);
  51
+      if (err === 'No messages to receive') {
  52
+        self.log && self.log.debug('Service Bus poll: no message');
  53
+      }
51 54
 
52 55
       if (!err) {
53 56
         var msg = self.unpackMessage(receivedMessage);
@@ -62,6 +65,7 @@ ServiceBusConnector.prototype.start = function () {
62 65
         pollSb();
63 66
       } else {
64 67
         --self.receivesRunning;
  68
+        self.log && self.log.info('Service Bus poll stopped', 'num:' + self.receivesRunning);
65 69
         if(self.receivesRunning === 0) {
66 70
           self.stopCallback && self.stopCallback(null);
67 71
         }
@@ -71,6 +75,7 @@ ServiceBusConnector.prototype.start = function () {
71 75
 
72 76
   for(var i = 0; i < this.numReceives; ++i) {
73 77
     pollSb();
  78
+    this.log && this.log.info('Service Bus poll started', 'num:' + i);
74 79
   }
75 80
   this.receivesRunning = this.numReceives;
76 81
 }
@@ -84,9 +89,9 @@ ServiceBusConnector.prototype.send = function (name, args) {
84 89
   var self = this;
85 90
   var message = this.packMessage(name, args);
86 91
   this.serviceBusSender.sendTopicMessage(this.topic, message, function (err) {
87  
-
88 92
     if (err) {
89  
-      self.emit('sberror', new Error('Failed to write to service bus on topic %s, err = %s', self.topic, util.inspect(err)));
  93
+      self.log && self.log.error('Service Bus send to topic failed',
  94
+        'topic:' + self.topic, 'error:' + err.toString());
90 95
     }
91 96
   });
92 97
 }
@@ -111,9 +116,18 @@ ServiceBusConnector.prototype.unpackMessage = function(message) {
111 116
 
112 117
   try {
113 118
     result.args = JSON.parse(message.body);
  119
+    this.log && this.log.info('Service Bus received message', 'from:' + result.nodeId, 'message:' + result.name);
  120
+    this.log && this.log.debug('Service Bus received message', 'messageId:' + message.brokerProperties.MessageId);
114 121
     return result;
115 122
   } catch (ex) {
116 123
     // Issue unpacking the message, assume it's bad and toss it
  124
+    this.log && this.log.warn('Service Bus bad message received',
  125
+      'CorrelationId:' + message.brokerProperties.CorrelationId,
  126
+      'Label:' + message.brokerProperties.Label,
  127
+      'SequenceNumber:' + message.brokerProperties.SequenceNumber,
  128
+      'size:' + message.brokerProperties.Size,
  129
+      'enqueuedTime:' + message.brokerProperties.EnqueuedTimeUtc,
  130
+      'messageId:' + message.brokerProperties.MessageId);
117 131
     return result;
118 132
   }
119 133
 }
168  test/logging-tests.js
... ...
@@ -0,0 +1,168 @@
  1
+/**
  2
+* Copyright (c) Microsoft.  All rights reserved.
  3
+*
  4
+* Licensed under the Apache License, Version 2.0 (the "License");
  5
+* you may not use this file except in compliance with the License.
  6
+* You may obtain a copy of the License at
  7
+*   http://www.apache.org/licenses/LICENSE-2.0
  8
+*
  9
+* Unless required by applicable law or agreed to in writing, software
  10
+* distributed under the License is distributed on an "AS IS" BASIS,
  11
+* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
  12
+* See the License for the specific language governing permissions and
  13
+* limitations under the License.
  14
+*/
  15
+
  16
+'use strict';
  17
+
  18
+var should = require('should');
  19
+var sinon = require('sinon');
  20
+
  21
+var SbStore = require('../lib/sbstore');
  22
+
  23
+describe('logging', function () {
  24
+  var store;
  25
+  var logger;
  26
+  var serviceBusService;
  27
+  var recvFuncs;
  28
+  var clock;
  29
+
  30
+  beforeEach(function () {
  31
+    clock = sinon.useFakeTimers();
  32
+    recvFuncs = [];
  33
+
  34
+    serviceBusService = {
  35
+      receiveSubscriptionMessage: function (topic, sub, callback) {
  36
+        recvFuncs.push(callback);
  37
+      },
  38
+      sendTopicMessage: sinon.spy(),
  39
+      withFilter: function (filter) { return this; },
  40
+      host: 'testnamespace.servicebus.example'
  41
+    };
  42
+
  43
+    logger = {
  44
+      error: sinon.spy(),
  45
+      warn: sinon.spy(),
  46
+      info: sinon.spy(),
  47
+      debug: sinon.spy()
  48
+    };
  49
+
  50
+    store = new SbStore({
  51
+      nodeId: 'logtestnode',
  52
+      topic: 'testtopic',
  53
+      subscription: 'testsubscription',
  54
+      serviceBusService: serviceBusService,
  55
+      numReceives: 2,
  56
+      logger: logger,
  57
+      flushIntervalMS: 100
  58
+    });
  59
+  });
  60
+
  61
+  afterEach(function () {
  62
+    clock.restore();
  63
+  });
  64
+
  65
+  it('should log subscription info on creation', function () {
  66
+    logger.info.calledWith('Service Bus Store created', 
  67
+      'host:' + serviceBusService.host,
  68
+      'topic:testtopic', 
  69
+      'sub:testsubscription').should.be.true;
  70
+  });
  71
+
  72
+  it('should log when poll request starts up', function () {
  73
+    logger.info.calledWith('Service Bus poll started', 'num:0').should.be.true;
  74
+    logger.info.calledWith('Service Bus poll started', 'num:1').should.be.true;
  75
+  });
  76
+
  77
+  it('should log when polling stops', function (done) {
  78
+    store.destroy(function () {
  79
+      logger.info.calledWith('Service Bus poll stopped', 'num:1').should.be.true;
  80
+      logger.info.calledWith('Service Bus poll stopped', 'num:0').should.be.true;
  81
+      done();
  82
+    });
  83
+
  84
+    // trigger the receive poll callbacks so they exit
  85
+    recvNothing();
  86
+    recvNothing();
  87
+  });
  88
+
  89
+  it('should log when poll completes without a message', function () {
  90
+    recvNothing();
  91
+    logger.debug.calledWith('Service Bus poll: no message').should.be.true;
  92
+  });
  93
+
  94
+  it('should log when a bad message is received', function () {
  95
+    var message = {
  96
+      brokerProperties: {
  97
+        CorrelationId: 'sourceNode',
  98
+        Label: 'aMessage',
  99
+        SequenceNumber: 1
  100
+      },
  101
+      body: 'This will not deserialize'
  102
+    };
  103
+
  104
+    recv(message);
  105
+    logger.warn.calledWith('Service Bus bad message received', 
  106
+      'CorrelationId:sourceNode', 'Label:aMessage', 'SequenceNumber:1')
  107
+      .should.be.true;
  108
+  });
  109
+
  110
+  it('should log when good message is received', function () {
  111
+    var message = {
  112
+      brokerProperties: {
  113
+        CorrelationId: 'sourceNode',
  114
+        Label: 'aMessage',
  115
+        SequenceNumber: 2
  116
+      },
  117
+      body: JSON.stringify([1, 2, 3])
  118
+    };
  119
+
  120
+    recv(message);
  121
+
  122
+    logger.info.calledWith('Service Bus received message',
  123
+      'from:sourceNode', 'message:aMessage').should.be.true;
  124
+  });
  125
+
  126
+  it('should log details when good message is received', function () {
  127
+    var message = {
  128
+      brokerProperties: {
  129
+        CorrelationId: 'sourceNode',
  130
+        Label: 'aMessage',
  131
+        SequenceNumber: 2,
  132
+        EnqueuedTimeUtc: new Date().toString(),
  133
+        MessageId: 1234
  134
+      },
  135
+      body: JSON.stringify([1, 2, 3])
  136
+    };
  137
+    message.brokerProperties.Size = message.body.length;
  138
+
  139
+    recv(message);
  140
+
  141
+    logger.debug.calledWith('Service Bus received message',
  142
+      'messageId:' + message.brokerProperties.MessageId).should.be.true;
  143
+  });
  144
+
  145
+  it('should log failure to send', function () {
  146
+    store.publish('aMessage', 1, 2, 3);
  147
+    // message batcher flush 
  148
+    clock.tick(300);
  149
+
  150
+    var sendCallback = serviceBusService.sendTopicMessage.getCall(0).args[2];
  151
+    sendCallback('Service Bus send failed');
  152
+
  153
+    logger.error.calledWith('Service Bus send to topic failed',
  154
+      'topic:testtopic', 'error:Service Bus send failed').should.be.true;
  155
+  });
  156
+
  157
+  // Helpers for sending messages
  158
+  function recvNothing() {
  159
+    var recvFunc = recvFuncs.shift();
  160
+    recvFunc('No messages to receive');
  161
+  }
  162
+
  163
+  function recv(message) {
  164
+    var recvFunc = recvFuncs.shift();
  165
+    recvFunc(null, message);
  166
+  }
  167
+
  168
+});
10  test/servicebusconnector-tests.js
@@ -114,16 +114,6 @@ describe('Service Bus connection layer', function () {
114 114
 
115 115
       sentMessage.body.should.equal('"hello"');
116 116
     });
117  
-
118  
-    it('should emit sberror event if service bus send fails', function () {
119  
-      var stub = sinon.stub().callsArgWith(2, new Error('Fake failure'));
120  
-      sb.sendTopicMessage = stub;
121  
-      var error = null;
122  
-      connector.on('sberror', function (err) { console.log('there was an error'); error = err; })
123  
-      connector.send('msg', 'hello', {seq: 6, next: 7});
124  
-
125  
-      error.should.exist;
126  
-    });
127 117
   });
128 118
 
129 119
   describe('when receiving with one receive at a time', function () {
5  test/store-tests.js
@@ -112,7 +112,10 @@ describe('Service Bus Store objects', function() {
112 112
     };
113 113
 
114 114
     before(function () {
115  
-      store = new SbStore({listeners: [SbStore.logging.makeListener(listeners)]});
  115
+      store = new SbStore();
  116
+      store.on('subscribe', listeners.onsubscribe);
  117
+      store.on('received', listeners.onreceived);
  118
+      store.on('unsubscribe', listeners.onunsubscribe);
116 119
 
117 120
       store.subscribe('message1', subscriber1);
118 121
       store.subscribe('message2', subscriber2);
Commit_comment_tip

Tip: You can add notes to lines in a file. Hover to the left of a line to make a note

Something went wrong with that request. Please try again.