Added extended logging to some modules

Changelog:
 - Changed all 'trace' logs to level 'debug'
 - Added logging to the version check functions on log level 'info' and 'debug'
 - Added some time measures on ready checks to see what's taking so long on startup

src/cache.js

@@ -4,7 +4,7 @@ import * as redis from './redis.js'
 const cache = {}
 
 export function set (key, value) {
-  logger.trace(`[Cache] Set ${key}`)
+  logger.debug(`[Cache] Set ${key}`)
   if (cache[key] === value) return
   cache[key] = value
   if (redis.isEnabled()) {
@@ -20,7 +20,7 @@ export async function clear () {
 
 export function get (key, fallback) {
   if (cache[key]) {
-    logger.trace(`[Cache] Resolve "${key}" from memory`)
+    logger.debug(`[Cache] Resolve "${key}" from memory`)
     return cache[key]
   }
 
@@ -28,7 +28,7 @@ export function get (key, fallback) {
     if (redis.isEnabled()) {
       let result = await redis.client.get(key)
       if (result) {
-        logger.trace(`[Cache] Resolve "${key}" from redis`)
+        logger.debug(`[Cache] Resolve "${key}" from redis`)
         result = JSON.parse(result)
         cache[key] = result
         return result
@@ -39,7 +39,7 @@ export function get (key, fallback) {
 
     const fallbackResult = await fallback()
     if (fallbackResult) {
-      logger.trace(`[Cache] Found a fallback for "${key}"`)
+      logger.debug(`[Cache] Found a fallback for "${key}"`)
       cache[key] = fallbackResult
       if (redis.isEnabled()) redis.client.set(key, JSON.stringify(fallbackResult))
     }

src/config.js

@@ -6,7 +6,7 @@ class Config {
   async load () {
     const urlsSource = await fs.readFile('./config/config.yaml', 'utf8')
     this._urls = yaml.load(urlsSource).baseUrls
-    logger.trace('[Config] Config has been loaded')
+    logger.debug('[Config] Config has been loaded')
   }
 
   get urls () {

src/index.js

@@ -5,7 +5,6 @@ import { logger } from './logger.js'
 import { createApp } from './create-app.js'
 import express from 'express'
 import createQueues from './create-queues.js'
-
 config()
 
 const root = express()
@@ -14,7 +13,7 @@ createQueues()
 
 // Binds and listens for connections on the specified host and port
 root.listen(process.env.PORT, () => {
-  logger.info(`[Server] ui-middleware listening on port ${process.env.PORT}`)
+  logger.info(`[Server] ui-middleware listening on port ${process.env.PORT}, PID: ${process.pid}`)
 })
 
 process.on('uncaughtException', err => {

src/logger.js

@@ -4,3 +4,5 @@ config()
 
 export const httpLogger = createHttpLogger()
 export const logger = createLogger()
+export const t0 = +new Date()
+export const timeSinceStartup = () => (new Date() - t0) / 1000

src/redis.js

 import Redis from 'ioredis'
-import { logger } from './logger.js'
+import { logger, timeSinceStartup } from './logger.js'
 import Queue from 'bull'
 
 const commonQueueOptions = { enableReadyCheck: false, maxRetriesPerRequest: null }
@@ -8,7 +8,7 @@ const createClient = (type, options = {}) => {
   if (!isEnabled()) {
     return new Proxy({}, {
       get () {
-        throw new Error('Redis is disabled. Do not use it.')
+        throw new Error('Redis is disabled. Check for redis.isEnabled()')
       }
     })
   }
@@ -20,7 +20,7 @@ const createClient = (type, options = {}) => {
     password: process.env.REDIS_PASSWORD,
     ...options
   })
-  client.on('ready', () => logger.info(`[Redis] Connected ${type} to redis on ${process.env.REDIS_HOST}`))
+  client.on('ready', () => logger.info(`[Redis] Connected ${type} to redis on ${process.env.REDIS_HOST}. Time since startup: ${timeSinceStartup()}s`))
   client.on('error', (err) => logger.error(`[Redis] Connect error: ${err}`))
 
   return client

src/routes/health.js

@@ -4,7 +4,7 @@ import * as redis from '../redis.js'
 import { getLatestVersion } from '../version.js'
 import { once } from '../util.js'
 import { config } from '../config.js'
-
+import { logger, timeSinceStartup } from '../logger.js'
 const router = Router()
 const healthCheck = new health.HealthChecker()
 
@@ -17,7 +17,9 @@ const checkLatestVersion = new health.StartupCheck('check latest version', once(
   // config is required before the first version check
   await config.load()
   await getLatestVersion()
+  logger.info(`[Health] Check latest version on startup. Time since startup: ${timeSinceStartup()}`)
 }))
+
 healthCheck.registerStartupCheck(checkLatestVersion)
 
 router.use('/live', health.LivenessEndpoint(healthCheck))

src/util.js

@@ -71,3 +71,4 @@ export function once (fn, context) {
     return res
   }
 }
+export const t0 = +new Date()

src/version.js

@@ -17,7 +17,7 @@ export const fetchLatestVersion = async () => {
       if (!version) throw new Error()
       return version
     } catch (err) {
-      logger.debug(`[Version] UI container at ${baseUrl} does not have meta.json. Fall back to version hash based on manifest.`)
+      logger.error(`[Version] UI container at ${baseUrl} does not have meta.json. Fall back to version hash based on manifest.`)
     }
     try {
       const response = await fetch(new URL('manifest.json', baseUrl))
@@ -33,20 +33,23 @@ export const fetchLatestVersion = async () => {
 
 export async function getLatestVersion () {
   if (latestVersion) return latestVersion
-
   if (redis.isEnabled()) {
     const version = await redis.client.get(getRedisKey({ name: 'latestVersion' }))
-    if (version) return (latestVersion = version)
+    if (version) {
+      logger.debug(`[Version] Got initial version from redis: '${version}'`)
+      return (latestVersion = version)
+    }
   }
 
-  const newVersion = await fetchLatestVersion()
+  const version = await fetchLatestVersion()
+  logger.info(`[Version] Fetched initial version: '${version}'`)
 
   if (redis.isEnabled()) {
-    redis.pubClient.publish(getRedisKey({ name: 'updateLatestVersion' }), newVersion)
-    await redis.client.set(getRedisKey({ name: 'latestVersion' }), newVersion)
+    redis.pubClient.publish(getRedisKey({ name: 'updateLatestVersion' }), version)
+    await redis.client.set(getRedisKey({ name: 'latestVersion' }), version)
   }
 
-  return (latestVersion = newVersion)
+  return (latestVersion = version)
 }
 
 export function registerLatestVersionListener (client) {
@@ -54,26 +57,33 @@ export function registerLatestVersionListener (client) {
 
   const key = getRedisKey({ name: 'updateLatestVersion' })
   client.subscribe(key, (errs, count) => logger.info(`[Redis] Subscribed to ${key}.`))
-  client.on('message', async (channel, message) => {
+  client.on('message', async (channel, version) => {
     if (channel !== key) return
+    logger.info(`[Version] Received 'updateLatestVersion' event. Clearing cache. New version: '${version}'`)
     await config.load()
     cache.clear()
-    latestVersion = message
+    latestVersion = version
   })
 }
 
 export async function updateVersionProcessor () {
+  logger.info('[Version] Check for new version')
   await config.load()
   const [storedVersion, fetchedVersion] = await Promise.all([
     getLatestVersion(),
     fetchLatestVersion()
   ])
-  if (storedVersion === fetchedVersion) return fetchedVersion
+  if (storedVersion === fetchedVersion) {
+    logger.info(`[Version] No new version has been found. No update needed. Current version: ${storedVersion}`)
+    return fetchedVersion
+  }
+  logger.info(`[Version] Found new source version. Current version: '${storedVersion}', new version: '${fetchedVersion}'`)
   if (redis.isEnabled()) {
     redis.pubClient.publish(getRedisKey({ name: 'updateLatestVersion' }), fetchedVersion)
     await redis.client.set(getRedisKey({ name: 'latestVersion' }), fetchedVersion)
   } else {
     // if redis is disabled, this will only be trigger by a setInterval and not from a redis event
+    logger.info('[Version] Clear local cache due to version update.')
     cache.clear()
   }
   return (latestVersion = fetchedVersion)