From 70fbe714e3ca92863a5c62cd8bf29c459c96486f Mon Sep 17 00:00:00 2001
From: Koen Kanters <koenkanters94@gmail.com>
Date: Sat, 8 Jun 2019 19:56:35 +0200
Subject: [PATCH] Add trace logging and add trace logging to zigbeeQueue.
 https://github.com/Koenkk/zigbee2mqtt/issues/1566

---
 lib/extension/deviceAvailability.js |  8 ++++----
 lib/util/logger.js                  | 22 ++++++++++++++++++++++
 lib/util/zigbeeQueue.js             | 13 ++++++++++++-
 3 files changed, 38 insertions(+), 5 deletions(-)

diff --git a/lib/extension/deviceAvailability.js b/lib/extension/deviceAvailability.js
index c6ae512b3..44ab7b838 100644
--- a/lib/extension/deviceAvailability.js
+++ b/lib/extension/deviceAvailability.js
@@ -30,20 +30,20 @@ class DeviceAvailability {
     }
 
     isPingable(device) {
-        logger.debug(`Checking if ${device.ieeeAddr} is pingable`);
+        logger.trace(`Checking if ${device.ieeeAddr} is pingable`);
 
         if (this.blacklist.includes(device.ieeeAddr)) {
-            logger.debug(`${device.ieeeAddr} is not pingable because of blacklist`);
+            logger.trace(`${device.ieeeAddr} is not pingable because of blacklist`);
             return false;
         }
 
         if (pingableDevices.find((d) => d.zigbeeModel.includes(device.modelId))) {
-            logger.debug(`${device.ieeeAddr} is pingable because in pingable devices`);
+            logger.trace(`${device.ieeeAddr} is pingable because in pingable devices`);
             return true;
         }
 
         const result = utils.isRouter(device) && !utils.isBatteryPowered(device);
-        logger.debug(`${device.ieeeAddr} is pingable (${result}) not router or battery powered`);
+        logger.trace(`${device.ieeeAddr} is pingable (${result}) not router or battery powered`);
         return result;
     }
 
diff --git a/lib/util/logger.js b/lib/util/logger.js
index 2966156ce..d0661b502 100644
--- a/lib/util/logger.js
+++ b/lib/util/logger.js
@@ -16,8 +16,27 @@ const directory = settings.get().advanced.log_directory.replace('%TIMESTAMP%', t
 // Make sure that log directoy exsists
 fx.mkdirSync(directory);
 
+// Custom level
+const levels = {
+    levels: {
+        error: 0,
+        warn: 1,
+        info: 2,
+        debug: 3,
+        trace: 4,
+    },
+    colors: {
+        error: 'red',
+        warn: 'yellow',
+        info: 'green',
+        debug: 'blue',
+        trace: 'magenta',
+    },
+};
+
 // Create logger
 const logger = new winston.Logger({
+    levels: levels.levels,
     transports: [
         new winston.transports.File({
             filename: path.join(directory, 'log.txt'),
@@ -37,6 +56,9 @@ const logger = new winston.Logger({
     ],
 });
 
+// Add colors
+winston.addColors(levels.colors);
+
 logger.info(`Logging to directory: '${directory}'`);
 
 logger.transports.console.level = level;
diff --git a/lib/util/zigbeeQueue.js b/lib/util/zigbeeQueue.js
index dc63b5f34..c9870c41d 100644
--- a/lib/util/zigbeeQueue.js
+++ b/lib/util/zigbeeQueue.js
@@ -1,6 +1,7 @@
 const maxSimultaneouslyRunning = 5;
 const delay = 250;
 const error17Retries = 3;
+const logger = require('./logger');
 
 class ZigbeeQueue {
     constructor() {
@@ -8,6 +9,7 @@ class ZigbeeQueue {
         this.active = [];
         this.timer = null;
         this.running = false;
+        this.ID = 0;
     }
 
     start() {
@@ -16,7 +18,13 @@ class ZigbeeQueue {
     }
 
     push(entityID, func) {
-        this.queue.push({entityID, func, attempts: 0});
+        this.ID++;
+        this.queue.push({entityID, func, attempts: 0, ID: this.ID});
+        this.log(`Added new job with ID ${this.ID} for ${entityID}`);
+    }
+
+    log(message) {
+        logger.trace(`zigbeeQueue: ${message}`);
     }
 
     stopTimer() {
@@ -40,6 +48,8 @@ class ZigbeeQueue {
     }
 
     handleJobComplete(job, error) {
+        this.log(`Completed job with ID ${job.ID} for ${job.entityID}${error ? ` with error ${error}` : ''}`);
+
         if (error && error.message === 'rsp error: 17' && job.attempts < error17Retries) {
             // Error 17 means that the buffer of the ZNP was full,
             // retry this for a maximum of 3 times.
@@ -60,6 +70,7 @@ class ZigbeeQueue {
 
         if (next) {
             this.active.push(next);
+            this.log(`Executing job with ID ${next.ID} for ${next.entityID}`);
             next.func((error) => this.handleJobComplete(next, error));
         }
     }