feature/logging

Dockerfile

-FROM node:15-alpine
+FROM node:17-alpine
 LABEL maintainer="ui-team@open-xchange.com"
 
 WORKDIR /app

helm/core-manifest-service/values.yaml

@@ -27,7 +27,8 @@ serviceAccount:
   # If not set and create is true, a name is generated using the fullname template
   name: ""
 
-podAnnotations: {}
+podAnnotations:
+  logging.open-xchange.com/format: "appsuite-json"
 
 podSecurityContext: {}
   # fsGroup: 2000

package.json

@@ -15,34 +15,32 @@
   "license": "CC-BY-NC-SA-2.5",
   "dependencies": {
     "@cloudnative/health-connect": "^2.1.0",
-    "dotenv-defaults": "^2.0.1",
+    "@open-xchange/logging": "^0.0.5",
+    "dotenv-defaults": "^3.0.0",
     "eslint-config-standard": "^16.0.2",
     "express": "^4.17.1",
     "express-prom-bundle": "^6.4.1",
-    "helmet": "^4.4.1",
+    "helmet": "^5.0.1",
     "js-yaml": "^4.0.0",
-    "node-fetch": "^2.6.1",
-    "pino": "^6.11.2",
-    "pino-http": "^5.5.0",
-    "prom-client": "^13.1.0",
+    "node-fetch": "^3.1.0",
+    "prom-client": "^14.0.1",
     "swagger-ui-express": "^4.1.6"
   },
   "devDependencies": {
     "babel-cli": "^6.26.0",
     "babel-preset-env": "^1.7.0",
-    "eslint": "^7.20.0",
+    "eslint": "^8.6.0",
     "eslint-plugin-import": "^2.22.1",
-    "eslint-plugin-jest": "^24.4.0",
+    "eslint-plugin-jest": "^25.3.4",
     "eslint-plugin-node": "^11.1.0",
-    "eslint-plugin-promise": "^5.1.0",
+    "eslint-plugin-promise": "^6.0.0",
     "husky": ">=6",
     "jest": "^27.1.0",
-    "jest-extended": "^0.11.5",
-    "jest-junit": "^12.2.0",
+    "jest-extended": "^1.2.0",
+    "jest-junit": "^13.0.0",
     "lint-staged": ">=10",
     "mock-fs": "^5.0.0",
     "nodemon": "^2.0.7",
-    "pino-pretty": "^4.7.1",
     "superagent": "^6.1.0",
     "supertest": "^6.1.6"
   },

src/createApp.js

@@ -6,8 +6,7 @@ import express from 'express'
 import helmet from 'helmet'
 
 // Fastest HTTP logger for Node.js in town
-import { getLogger } from './logger.js'
-import pinoHttp from 'pino-http'
+import { createHttpLogger } from '@open-xchange/logging'
 // Readiness and liveness checks middleware
 import health from '@cloudnative/health-connect'
 
@@ -22,6 +21,7 @@ import fs from 'fs'
 import { getCSSDependenciesFor, getDependencies, getOxManifests, getVersion, loadViteManifests, viteManifestToDeps } from './manifests.js'
 import { fileCache } from './files.js'
 
+const { logger } = createHttpLogger
 const ignorePaths = ['/ready', '/healthy']
 const swaggerDocument = yaml.load(fs.readFileSync('./src/swagger.yaml', 'utf8'))
 const bypass = (request) => ignorePaths.includes(request.path)
@@ -37,9 +37,6 @@ export function createApp () {
 
   const app = express()
 
-  const logger = getLogger()
-  const httpLogger = pinoHttp({ logger, autoLogging: { ignorePaths } })
-
   const healthCheck = new health.HealthChecker()
   const startupCheck = new health.StartupCheck('warmup cache', async function () {
     const stopTimer = startUpTimeGauge.startTimer()
@@ -57,7 +54,7 @@ export function createApp () {
   healthCheck.registerStartupCheck(startupCheck)
 
   // Application-level middleware
-  app.use(httpLogger)
+  app.use(createHttpLogger())
   app.use((req, res, next) => {
     const { sha256Sum } = fileCache.get(req.path)
     res.locals.sha256Sum = sha256Sum

src/files.js

@@ -2,7 +2,9 @@ import fetch from 'node-fetch'
 import crypto from 'crypto'
 import { config } from './config.js'
 import promClient from 'prom-client'
-import { getLogger } from './logger.js'
+import { getLogger } from '@open-xchange/logging'
+
+const logger = getLogger()
 
 async function fetchData (path, baseUrl) {
   const response = await fetch(new URL(path, baseUrl))
@@ -30,6 +32,7 @@ class FileCache {
   }
 
   async warmUp (manifests, deps) {
+    logger.debug('beginning to warm up cache')
     const cache = Object.fromEntries(await (async function () {
       const files = Object.keys(deps)
       const chunkSize = 50
@@ -43,13 +46,13 @@ class FileCache {
               (m?.css?.indexOf(file) >= 0)
             )
             if (!manifest) {
-              getLogger().error('could not find manifest for', file)
+              logger.error(`could not find manifest for "${file}"`)
               return null
             }
             return await fetchData(file, manifest.meta.baseUrl)
           } catch (e) {
             fileErrorCounter.inc()
-            getLogger().error(e)
+            logger.error(e)
           }
         }))).filter(data => Array.isArray(data) && data.length === 2))
       }
@@ -57,6 +60,7 @@ class FileCache {
       return result
     }()))
     this._cache = cache
+    logger.debug('cache warmed up')
   }
 
   async fetchAndStore (path) {

src/index.js

 // Add env vars from files
 // Note: actual env vars supersede .env file and .env file supersedes .env.defaults file
 import { config } from 'dotenv-defaults'
-import { getLogger } from './logger.js'
+import { getLogger } from '@open-xchange/logging'
 import { createApp } from './createApp.js'
 import express from 'express'
 
+const logger = getLogger()
 config()
 
 const root = express()
@@ -12,7 +13,17 @@ const app = createApp()
 
 // Binds and listens for connections on the specified host and port
 root.listen(process.env.PORT, () => {
-  getLogger().info(`manifest-service listening on port ${process.env.PORT}`)
+  logger.info(`manifest-service listening on port ${process.env.PORT}`)
+})
+
+process.on('uncaughtException', err => {
+  logger.error(err, 'uncaughtException')
+  process.exit(1)
+})
+
+process.on('unhandledRejection', err => {
+  logger.error(err, 'unhandledRejection')
+  process.exit(1)
 })
 
 root.use(process.env.APP_ROOT, app)

src/logger.js

-// Very low overhead Node.js logger. Logs in json use pino-pretty for dev.
-import Logger from 'pino'
-
-export const getLogger = (() => {
-  let logger
-  return function getLogger () {
-    if (!logger) {
-      logger = new Logger({
-        level: process.env.LOG_LEVEL
-      })
-    }
-    return logger
-  }
-})()

src/manifests.js

@@ -4,6 +4,9 @@ import { URL } from 'url'
 import { fileCache } from './files.js'
 import { config } from './config.js'
 import { hash } from './util.js'
+import { getLogger } from '@open-xchange/logging'
+
+const logger = getLogger()
 
 export const loadViteManifests = (() => {
   let cachePromise
@@ -22,6 +25,7 @@ export const loadViteManifests = (() => {
       try {
         const manifest = await result.json()
         for (const file in manifest) {
+          logger.debug(`retrieved ${file} from ${url}`)
           manifest[file].meta = manifest[file].meta || {}
           manifest[file].meta.baseUrl = origin
         }
@@ -37,17 +41,24 @@ export const loadViteManifests = (() => {
       enumerable: false,
       writable: true
     })
-    viteManifest.__hash__ = hash(viteManifests)
+
+    try {
+      viteManifest.__hash__ = hash(viteManifests)
+    } catch (err) {
+      logger.error(`Failed to calculate hash: ${err.message}`)
+    }
 
     return viteManifest
   }
 
   return function loadViteManifests ({ useCache = true } = {}) {
     const CACHE_TTL = parseInt(process.env.CACHE_TTL)
+    const timeElapsed = () => +((+new Date() - lastCacheTime) / 1000).toFixed(2)
 
     if (!cachePromise || useCache === false || +new Date() > lastCacheTime + CACHE_TTL) {
       cachePromise = reload()
       cachePromise.then(manifests => {
+        if (useCache) logger.info(`reloaded manifests after ${timeElapsed()} seconds`)
         // update cache promise
         const newHash = manifests.__hash__
         if (newHash !== lastHash) {