Added more debug logs (#4)

Author: HarshDaryani896

package.json

@@ -34,5 +34,8 @@
     "arrowParens": "always",
     "trailingComma": "es5",
     "singleQuote": true
+  },
+  "dependencies": {
+    "winston": "^3.14.2"
   }
 }

packages/pg/lib/client.js

@@ -12,6 +12,7 @@ var Query = require('./query')
 var defaults = require('./defaults')
 var Connection = require('./connection')
 const dns = require('dns')
+const { logger } = require('./logger')
 const YB_SERVERS_QUERY = 'SELECT * FROM yb_servers()'
 const DEFAULT_FAILED_HOST_TTL_SECONDS = 5
 
@@ -56,6 +57,7 @@ class Lock {
 const lock = new Lock()
 class Client extends EventEmitter {
   constructor(config) {
+    logger.silly("Received connection string " + config)
     super()
     this.connectionParameters = new ConnectionParameters(config)
     this.user = this.connectionParameters.user
@@ -152,6 +154,7 @@ class Client extends EventEmitter {
   }
 
   getLeastLoadedServer(hostsList) {
+    logger.silly("getLeaseLoadedServer() is called")
     if (hostsList.size === 0) {
       return this.host
     }
@@ -213,6 +216,8 @@ class Client extends EventEmitter {
     }
     let randomIdx = Math.floor(Math.random() * leastLoadedHosts.length - 1) + 1
     let leastLoadedHost = leastLoadedHosts[randomIdx]
+    logger.silly("Least loaded servers are " + leastLoadedHosts)
+    logger.debug("Returning " + leastLoadedHost + "as the least loaded host")
     return leastLoadedHost
   }
 
@@ -243,6 +248,7 @@ class Client extends EventEmitter {
         }
       }
     }
+    logger.warn("Given topology-key " + key + " is invalid")
     return false
   }
 
@@ -255,15 +261,18 @@ class Client extends EventEmitter {
     if (Client.connectionMap.has(host)) {
       prevCount = Client.connectionMap.get(host)
     } else if (Client.failedHosts.has(host)) {
+      logger.debug("Removing " + host + " from failed host list")
       let serverInfo = Client.failedHosts.get(host)
       Client.hostServerInfo.set(host, serverInfo)
       Client.failedHosts.delete(host)
       Client.failedHostsTime.delete(host)
     }
     Client.connectionMap.set(host, prevCount + 1)
+    logger.debug("Increasing connection count of " + host + " by 1")
   }
 
   _connect(callback) {
+    logger.silly("connect() is called")
     var self = this
     if (this.connectionParameters.loadBalance && this._connecting) {
       this.connection =
@@ -299,16 +308,19 @@ class Client extends EventEmitter {
       if (Client.connectionMap.size && Client.hostServerInfo.size) {
         this.host = this.getLeastLoadedServer(Client.connectionMap)
         this.port = Client.hostServerInfo.get(this.host).port
+        logger.silly("Least loaded host received " + this.host + " port " + this.port)
       } else if (Client.failedHosts.size) {
         this.host = this.getLeastLoadedServer(Client.failedHosts)
         this.port = Client.failedHosts.get(this.host).port
+        logger.silly("Least loaded host received " + this.host + " port " + this.port)
       }
     }
     if (Client.usePublic) {
       let currentHost = this.host
       let serverInfo = Client.hostServerInfo.get(currentHost)
       this.prevHostIfUsePublic = currentHost
       this.host = serverInfo.public_ip
+      logger.silly("Using public ips, host " + this.host)
     }
     if (this.host && this.host.indexOf('/') === 0) {
       con.connect(this.host + '/.s.PGSQL.' + this.port)
@@ -362,6 +374,7 @@ class Client extends EventEmitter {
   attachErrorListenerOnClientConnection(client) {
     client.on('error', () => {
       if (Client.hostServerInfo.has(client.host)) {
+        logger.debug("Not able to connect to host " + client.host + " adding it to failedHosts")
         Client.failedHosts.set(client.host, Client.hostServerInfo.get(client.host))
         let start = new Date().getTime();
         Client.failedHostsTime.set(client.host, start)
@@ -379,6 +392,7 @@ class Client extends EventEmitter {
     while (upHost !== undefined && !hostIsUp) {
       client.host = upHost.value
       client.connectionParameters.host = client.host
+      logger.debug("Trying to create control connection to " + client.host)
       await client
         .nowConnect()
         .then((res) => {
@@ -401,6 +415,7 @@ class Client extends EventEmitter {
   }
 
   async getConnection() {
+    logger.silly("Creating control connection...")
     let currConnectionString = this.connectionString
     var client = new Client(currConnectionString)
     this.attachErrorListenerOnClientConnection(client)
@@ -441,10 +456,12 @@ class Client extends EventEmitter {
         }
       })
     }
+    logger.debug("Created control connection to host " + client.host)
     return client
   }
 
   async getServersInfo() {
+    logger.silly("Refreshing server info")
     var client = Client.controlClient
     var result
     await client
@@ -466,6 +483,7 @@ class Client extends EventEmitter {
   }
 
   createServersList(data) {
+    logger.silly("Creating servers list")
     Client.hostServerInfo.clear()
     data.forEach((eachServer) => {
       var placementInfo = eachServer.cloud + '.' + eachServer.region + '.' + eachServer.zone
@@ -477,14 +495,17 @@ class Client extends EventEmitter {
       } else {
         Client.placementInfoHostMap.set(placementInfo, [eachServer.host])
       }
+      logger.debug("Updated placementInfoHost Map " + [...Client.placementInfoHostMap])
       Client.hostServerInfo.set(eachServer.host, server)
       if (eachServer.public_ip === this.host) {
         Client.usePublic = true
       }
+      logger.debug("Updated hostServerInfo to " + [...Client.hostServerInfo] + " and usePublic to " + Client.usePublic)
     })
   }
 
   createConnectionMap(data) {
+    logger.silly("Creating connection map")
     const currConnectionMap = new Map(Client.connectionMap)
     Client.connectionMap.clear()
     data.forEach((eachServer) => {
@@ -496,16 +517,19 @@ class Client extends EventEmitter {
         }
       } else {
         let start = new Date().getTime();
-        if(start - Client.failedHostsTime.get(eachServer.host) > (DEFAULT_FAILED_HOST_TTL_SECONDS * 1000)){
+        if (start - Client.failedHostsTime.get(eachServer.host) > (DEFAULT_FAILED_HOST_TTL_SECONDS * 1000)) {
+          logger.debug("Removing " + eachServer.host + " from failed host list")
           Client.connectionMap.set(eachServer.host, 0)
           Client.failedHosts.delete(eachServer.host)
           Client.failedHostsTime.delete(eachServer.host)
         }
       }
     })
+    logger.debug("Updated connection map " + [...Client.connectionMap])
   }
 
   createTopologyKeyMap() {
+    logger.silly("Creating Topology key map")
     var seperatedKeys = this.connectionParameters.topologyKeys.split(',')
     for (let idx = 0; idx < seperatedKeys.length; idx++) {
       let key = seperatedKeys[idx]
@@ -526,9 +550,11 @@ class Client extends EventEmitter {
         throw new Error('Bad Topology Key found - ' + key)
       }
     }
+    logger.debug("Updated topologyKey Map " + [...Client.topologyKeyMap])
   }
 
   createMetaData(data) {
+    logger.silly("Creating metadata ...")
     this.createServersList(data)
     Client.lastTimeMetaDataFetched = new Date().getTime() / 1000
     this.createConnectionMap(data)
@@ -538,12 +564,14 @@ class Client extends EventEmitter {
   }
 
   nowConnect(callback) {
+    logger.silly("nowConnect() is called...")
     if (callback) {
       if (this.connectionParameters.loadBalance) {
         this._connect((error) => {
           if (error) {
             if (this.connectionParameters.loadBalance) {
               if (Client.hostServerInfo.has(this.host)) {
+                logger.debug("Adding " + this.host + " to failed host list")
                 Client.failedHosts.set(this.host, Client.hostServerInfo.get(this.host))
                 let start = new Date().getTime();
                 Client.failedHostsTime.set(this.host, start)
@@ -579,6 +607,7 @@ class Client extends EventEmitter {
         if (error) {
           if (this.connectionParameters.loadBalance) {
             if (Client.hostServerInfo.has(this.host)) {
+              logger.debug("Adding " + this.host + " to failed host list")
               Client.failedHosts.set(this.host, Client.hostServerInfo.get(this.host))
               let start = new Date().getTime();
               Client.failedHostsTime.set(this.host, start)
@@ -605,14 +634,16 @@ class Client extends EventEmitter {
   }
 
   updateConnectionMapAfterRefresh() {
+    logger.silly("Updating connection map after refresh")
     let hostsInfoList = Client.hostServerInfo.keys()
     for (let eachHost of hostsInfoList) {
       if (!Client.connectionMap.has(eachHost)) {
         if(!Client.failedHosts.has(eachHost)){
           Client.connectionMap.set(eachHost, 0)
         } else {
           let start = new Date().getTime();
-          if(start - Client.failedHostsTime.get(eachHost) > (DEFAULT_FAILED_HOST_TTL_SECONDS * 1000)){
+          if (start - Client.failedHostsTime.get(eachHost) > (DEFAULT_FAILED_HOST_TTL_SECONDS * 1000)) {
+            logger.debug("Removing" + eachHost + " from failed host list")
             Client.connectionMap.set(eachHost, 0)
             Client.failedHosts.delete(eachHost)
             Client.failedHostsTime.delete(eachHost)
@@ -626,9 +657,12 @@ class Client extends EventEmitter {
         Client.connectionMap.delete(eachHost)
       }
     }
+    logger.debug("Updated connection Map after refresh " + [...Client.connectionMap]);
+    logger.debug("Updated failed host list after refresh " + [...Client.failedHosts]);
   }
 
   updateMetaData(data) {
+    logger.silly("Updating MetaData")
     this.createServersList(data)
     Client.lastTimeMetaDataFetched = new Date().getTime() / 1000
     this.updateConnectionMapAfterRefresh()
@@ -637,7 +671,13 @@ class Client extends EventEmitter {
   isRefreshRequired() {
     let currentTime = new Date().getTime() / 1000
     let diff = Math.floor(currentTime - Client.lastTimeMetaDataFetched)
-    return diff >= this.connectionParameters.ybServersRefreshInterval
+    if (diff >= this.connectionParameters.ybServersRefreshInterval) {
+      logger.silly("Refresh is required")
+      return true
+    } else {
+      logger.silly("Refresh is not required")
+      return false
+    }
   }
 
   connect(callback) {
@@ -1127,6 +1167,7 @@ class Client extends EventEmitter {
       if (this.connectionParameters.loadBalance) {
         let prevCount = Client.connectionMap.get(this.host)
         if (prevCount > 0) {
+          logger.debug("Decreasing connection count (" + prevCount + ") of " + this.host + " by 1")
           Client.connectionMap.set(this.host, prevCount - 1)
         }
         lock.release()

packages/pg/lib/logger.js

@@ -0,0 +1,55 @@
+'use strict'
+
+const winston = require('winston');
+
+/*
+
+Users can set the log level either by using an enviornment variable:
+
+`LOG_LEVEL = debug`
+
+or by using `setLogLevel` method:`
+
+const { logger, setLogLevel } = require('./logger');
+
+// Change log level dynamically
+setLogLevel('debug');
+
+// Log messages
+logger.debug('This is a debug message');
+logger.info('This is an info message');
+
+*/
+
+// Set the initial log level from the environment variable, default to 'info'
+let logLevel = process.env.LOG_LEVEL || 'info';
+
+// Configure the winston logger
+var logger = winston.createLogger({
+    level: logLevel,
+    levels: winston.config.npm.levels,
+    format: winston.format.combine(
+        winston.format.colorize(),
+        winston.format.timestamp(),
+        winston.format.printf(({ timestamp, level, message }) => {
+            return `${timestamp} [${level}]: ${message}`;
+        })
+    ),
+    transports: [
+        new winston.transports.Console(),
+        new winston.transports.File({ filename: 'app.log' })
+    ]
+});
+
+// Function to set the log level dynamically and update the environment variable
+var setLogLevel = (level) => {
+    logLevel = level;
+    process.env.LOG_LEVEL = level;  // Update the environment variable
+    logger.level = level;  // Update the logger's level
+    logger.info('Log level set to ' + level);
+};
+
+module.exports = {
+    logger,
+    setLogLevel
+};