Merge pull request #655 from ExchangeUnion/order-logging

feat(orderbook): logging enhancements

lib/orderbook/OrderBook.ts

@@ -268,7 +268,7 @@ class OrderBook extends EventEmitter {
     // if max time exceeded, don't try to match
     if (maxTime && Date.now() > maxTime) {
       assert(discardRemaining, 'discardRemaining must be true on recursive calls where maxTime could exceed');
-      this.logger.info(`placeOrder max time exceeded. order (${JSON.stringify(order)}) won't be matched`);
+      this.logger.debug(`placeOrder max time exceeded. order (${JSON.stringify(order)}) won't be fully matched`);
 
       // returning the remaining order to be rolled back and handled by the initial call
       return Promise.resolve({
@@ -297,6 +297,7 @@ class OrderBook extends EventEmitter {
       const portion: OrderPortion = { id: maker.id, pairId: maker.pairId, quantity: maker.quantity };
       if (orders.isOwnOrder(maker)) {
         // internal match
+        this.logger.info(`internal match executed on taker ${taker.id} and maker ${maker.id} for ${maker.quantity}`);
         portion.localId = maker.localId;
         result.internalMatches.push(maker);
         this.emit('ownOrder.filled', portion);
@@ -312,20 +313,24 @@ class OrderBook extends EventEmitter {
 
         try {
           await this.repository.addOrderIfNotExists(maker);
+          this.logger.debug(`matched with peer ${maker.peerPubKey}, executing swap on taker ${taker.id} and maker ${maker.id} for ${maker.quantity}`);
           const swapResult = await this.swaps.executeSwap(maker, taker);
           this.emit('peerOrder.filled', portion);
           result.swapResults.push(swapResult);
+          this.logger.info(`match executed on taker ${taker.id} and maker ${maker.id} for ${maker.quantity} with peer ${maker.peerPubKey}`);
           onUpdate && onUpdate({ case: PlaceOrderEventCase.SwapResult, payload: swapResult });
         } catch (err) {
           this.emit('peerOrder.invalidation', portion);
           swapFailures.push(taker);
+          this.logger.warn('swap failed during order matching, will repeat matching routine for failed swap quantity');
           // TODO: penalize peer for failed swap? penalty severity should depend on reason for failure
         }
       }
     }
 
     // if we have swap failures, attempt one retry for all available quantity. don't re-add the maker orders
     if (swapFailures.length > 0) {
+      this.logger.debug(`${swapFailures.length} swaps failed for order ${order.id}, repeating matching routine for failed swaps quantity`);
       // aggregate failures quantities with the remaining order
       const remainingOrder: OwnOrder = result.remainingOrder || { ...order, quantity: 0 };
       swapFailures.forEach(order => remainingOrder.quantity += order.quantity);
@@ -381,7 +386,6 @@ class OrderBook extends EventEmitter {
     this.localIdMap.set(order.localId, { id: order.id, pairId: order.pairId });
 
     this.emit('ownOrder.added', order);
-    this.logger.debug(`order added: ${JSON.stringify(order)}`);
 
     this.broadcastOrder(order);
     return true;
@@ -395,7 +399,6 @@ class OrderBook extends EventEmitter {
   private addPeerOrder = (order: orders.IncomingOrder): boolean => {
     const tp = this.tradingPairs.get(order.pairId);
     if (!tp) {
-      this.logger.debug(`incoming peer order invalid pairId: ${order.pairId}`);
       // TODO: penalize peer
       return false;
     }
@@ -408,7 +411,6 @@ class OrderBook extends EventEmitter {
       return false;
     }
 
-    this.logger.debug(`order added: ${JSON.stringify(stampedOrder)}`);
     this.emit('peerOrder.incoming', stampedOrder);
 
     return true;
@@ -430,13 +432,11 @@ class OrderBook extends EventEmitter {
   private addOrderHold = (orderId: string, pairId: string, holdAmount: number) => {
     const tp = this.getTradingPair(pairId);
     tp.addOrderHold(orderId, holdAmount);
-    this.logger.debug(`added hold on ${holdAmount} for order ${orderId}`);
   }
 
   private removeOrderHold = (orderId: string, pairId: string, holdAmount: number) => {
     const tp = this.getTradingPair(pairId);
     tp.removeOrderHold(orderId, holdAmount);
-    this.logger.debug(`removed hold on ${holdAmount} for order ${orderId}`);
   }
 
   /**
@@ -476,7 +476,6 @@ class OrderBook extends EventEmitter {
   }
 
   private removePeerOrders = async (peer: Peer): Promise<void> => {
-    // TODO: remove only from pairs which are supported by the peer
     if (!peer.nodePubKey) {
       return;
     }
@@ -487,6 +486,8 @@ class OrderBook extends EventEmitter {
         this.emit('peerOrder.invalidation', order);
       });
     });
+
+    this.logger.debug(`removed all orders for peer ${peer.nodePubKey}`);
   }
 
   /**

lib/orderbook/TradingPair.ts

@@ -128,6 +128,7 @@ class TradingPair {
     }
 
     map.set(order.id, order);
+    this.logger.debug(`order added: ${JSON.stringify(order)}`);
 
     if (!this.nomatching) {
       const queue = order.isBuy ? this.queues!.buy : this.queues!.sell;
@@ -272,13 +273,15 @@ class TradingPair {
     assert(holdAmount > 0);
     assert(order.hold + holdAmount <= order.quantity, 'the amount of an order on hold cannot exceed the available quantity');
     order.hold += holdAmount;
+    this.logger.debug(`added hold of ${holdAmount} on order ${orderId}`);
   }
 
   public removeOrderHold = (orderId: string, holdAmount: number) => {
     const order = this.getOwnOrder(orderId);
     assert(holdAmount > 0);
     assert(order.hold >= holdAmount, 'cannot remove more than is currently on hold for an order');
     order.hold -= holdAmount;
+    this.logger.debug(`removed hold of ${holdAmount} on order ${orderId}`);
   }
 
   /**

lib/p2p/Peer.ts

@@ -226,6 +226,11 @@ class Peer extends EventEmitter {
 
   public sendPacket = (packet: Packet): void => {
     this.sendRaw(packet.toRaw());
+    if (this.nodePubKey !== undefined) {
+      this.logger.trace(`Sent packet to ${this.nodePubKey}: ${packet.body ? JSON.stringify(packet.body) : ''}`);
+    } else {
+      this.logger.trace(`Sent packet to ${addressUtils.toString(this.address)}: ${packet.body ? JSON.stringify(packet.body) : ''}`);
+    }
     this.packetCount += 1;
 
     if (packet.direction === PacketDirection.Request) {
@@ -461,9 +466,9 @@ class Peer extends EventEmitter {
       this.lastRecv = Date.now();
       const dataStr = data.toString();
       if (this.nodePubKey !== undefined) {
-        this.logger.trace(`Received data (${this.nodePubKey}): ${dataStr}`);
+        this.logger.trace(`Received data from ${this.nodePubKey}: ${dataStr}`);
       } else {
-        this.logger.trace(`Received data (${addressUtils.toString(this.address)}): ${data.toString()}`);
+        this.logger.trace(`Received data from ${addressUtils.toString(this.address)}: ${data.toString()}`);
       }
       this.parser.feed(dataStr);
     });

lib/p2p/Pool.ts

@@ -487,7 +487,7 @@ class Pool extends EventEmitter {
       }
       case PacketType.OrderInvalidation: {
         const orderPortion = (packet as packets.OrderInvalidationPacket).body!;
-        this.logger.verbose(`canceled order from ${peer.nodePubKey}: ${JSON.stringify(orderPortion)}`);
+        this.logger.verbose(`received order invalidation from ${peer.nodePubKey}: ${JSON.stringify(orderPortion)}`);
         this.emit('packet.orderInvalidation', orderPortion, peer.nodePubKey as string);
         break;
       }