logging improvements

- remove data repetition from 'info' objects
- use structured loggging more consistently
- consistent use of 'type' property on info objects

.gitignore

@@ -130,6 +130,8 @@ dist
 .yarn/install-state.gz
 .pnp.*
 
+volume/cache
+
 # playwright
 /test-results/
 /playwright-report/*

index.js

@@ -3,6 +3,7 @@
 import express from 'express'
 import dotenv from 'dotenv'
 import logger from './src/utils/logger.js'
+import { types } from './src/utils/logging.js'
 import config from './config/index.js'
 
 import { setupMiddlewares } from './src/serverSetup/middlewares.js'
@@ -26,5 +27,8 @@ setupSentry(app)
 setupErrorHandlers(app)
 
 app.listen(config.port, () => {
-  logger.info(`App listening on all interfaces (0.0.0.0) on port ${config.port}`)
+  logger.info({
+    message: `listening on all interfaces (0.0.0.0) on port ${config.port}`,
+    type: types.AppLifecycle
+  })
 })

src/assets/js/statusPage.js

@@ -2,6 +2,7 @@
 
 import { finishedProcessingStatuses } from '../../utils/utils.js'
 import logger from '../../utils/logger.js'
+import { types } from '../../utils/logging.js'
 
 export default class StatusPage {
   constructor (pollingInterval, maxPollAttempts) {
@@ -37,17 +38,22 @@ export default class StatusPage {
       fetch(statusEndpoint)
         .then(res => res.json())
         .then(data => {
-          logger.info('StatusPage: polled request and got a status of: ' + data.status)
+          logger.info('StatusPage: polled request and got a status of: ' + data.status, { type: types.App })
           // ToDo: handle other status' here
           if (finishedProcessingStatuses.includes(data.status)) {
             this.updatePageToComplete()
             clearInterval(interval)
           }
+        }).catch((reason) => {
+          logger.warn(`polling ${statusEndpoint} failed, attempts=${this.pollAttempts}, reason=${reason}`,
+            { type: types.External }
+          )
+          clearInterval(interval)
         })
 
       this.pollAttempts++
-      if (this.pollAttempts > this.maxPollAttempts) {
-        logger.info('StatusPage: polling timed out')
+      if (this.pollAttempts >= this.maxPollAttempts) {
+        logger.info('StatusPage: polling timed out', { type: types.App })
         this.updatePageForPollingTimeout()
         clearInterval(interval)
       }

src/controllers/uploadController.js

@@ -1,10 +1,7 @@
 'use strict'
 import PageController from './pageController.js'
-import config from '../../config/index.js'
 
 class UploadController extends PageController {
-  apiRoute = config.asyncRequestApi.url + config.asyncRequestApi.requestsEndpoint
-
   async post (req, res, next) {
     super.post(req, res, next)
   }

src/controllers/uploadFileController.js

@@ -8,6 +8,7 @@ import multer from 'multer'
 import { promises as fs, createReadStream } from 'fs'
 import config from '../../config/index.js'
 import logger from '../utils/logger.js'
+import { types } from '../utils/logging.js'
 import { postFileRequest } from '../utils/asyncRequestApi.js'
 import { allowedFileTypes } from '../utils/utils.js'
 
@@ -99,7 +100,7 @@ class UploadFileController extends UploadController {
       await s3.upload(params).promise()
       return uuid
     } catch (error) {
-      logger.warn('Error uploading file to S3: ' + error.message)
+      logger.warn({ message: 'Error uploading file to S3', type: types.External })
       throw error
     }
   }

src/serverSetup/errorHandlers.js

@@ -1,12 +1,13 @@
 import logger from '../utils/logger.js'
+import { types } from '../utils/logging.js'
 
 export function setupErrorHandlers (app) {
   app.use((err, req, res, next) => {
     logger.error({
-      type: 'Request error',
+      type: types.Response,
       method: req.method,
       endpoint: req.originalUrl,
-      message: `${req.method} request made to ${req.originalUrl} but an error occurred`,
+      message: 'error occurred',
       error: JSON.stringify(err),
       errorMessage: err.message,
       errorStack: err.stack
@@ -28,10 +29,10 @@ export function setupErrorHandlers (app) {
 
   app.use((req, res, next) => {
     logger.info({
-      type: 'File not found',
+      type: types.Response,
       method: req.method,
       endpoint: req.originalUrl,
-      message: `${req.method} request made to ${req.originalUrl} but the file/endpoint was not found`
+      message: 'not found'
     })
     res.status(404).render('errorPages/404')
   })

src/serverSetup/middlewares.js

@@ -2,18 +2,22 @@ import express from 'express'
 import bodyParser from 'body-parser'
 import cookieParser from 'cookie-parser'
 import logger from '../utils/logger.js'
+import { types } from '../utils/logging.js'
 import hash from '../utils/hasher.js'
 import config from '../../config/index.js'
 
 export function setupMiddlewares (app) {
   app.use((req, res, next) => {
-    logger.info({
-      type: 'Request',
+    const obj = {
+      type: types.Request,
       method: req.method,
       endpoint: req.originalUrl,
-      message: `${req.method} request made to ${req.originalUrl}`,
-      sessionId: hash(req.sessionID)
-    })
+      message: '◦' // we need to put something here or watson will use an obj as the message
+    }
+    if (req.sessionID) {
+      obj.sessionId = hash(req.sessionID)
+    }
+    logger.info(obj)
     next()
   })
 

src/serverSetup/session.js

@@ -4,17 +4,18 @@ import RedisStore from 'connect-redis'
 import cookieParser from 'cookie-parser'
 import config from '../../config/index.js'
 import logger from '../utils/logger.js'
+import { types } from '../utils/logging.js'
 
 export function setupSession (app) {
   app.use(cookieParser())
   let sessionStore
   if (config.redis) {
     const urlPrefix = `redis${config.redis.secure ? 's' : ''}`
-    const redisClient = createClient({
-      url: `${urlPrefix}://${config.redis.host}:${config.redis.port}`
-    })
-    const errorHandler = (err) => {
-      logger.error(`session/setupSession: redis connection error: ${err.code}`)
+    const url = `${urlPrefix}://${config.redis.host}:${config.redis.port}`
+    const redisClient = createClient({ url })
+    const errorHandler = (error) => {
+      logger.info(`session/setupSession: failed to connect to ${url}`, { type: types.AppLifecycle })
+      logger.warn('session/setupSession: redis connection error', { type: types.External, error })
     }
     redisClient.connect().catch(errorHandler)
 

src/utils/asyncRequestApi.js

@@ -29,30 +29,25 @@ export const postUrlRequest = async (formData) => {
   })
 }
 
+/**
+ * POSTs a requeset to the 'publish' API.
+ *
+ * @param {*} formData
+ * @returns {Promise<string>} uuid - unique id of the uploaded file
+ * @throws
+ */
 const postRequest = async (formData) => {
   try {
     const response = await axios.post(requestsEndpoint, { params: formData })
     return response.data.id // assuming the response contains the id
   } catch (error) {
-    let errorMessage = 'An unknown error occurred.'
-
-    if (error.response) {
-      // The request was made and the server responded with a status code
-      // that falls out of the range of 2xx
-      errorMessage = `HTTP error! status: ${error.response.status}. Data: ${error.response.data}.`
-    } else if (error.cause) {
-      // If error has a cause property, it means the error was during axios request
-      errorMessage = `Error during request: (${error.cause.code}) ${error.cause.message}`
-    } else if (error.request) {
-      // The request was made but no response was received
-      errorMessage = 'No response received.'
-    } else if (error.message) {
-      // Something happened in setting up the request that triggered an Error
-      errorMessage = `Error in setting up the request: ${error.message}`
-    } else if (error.config) {
-      // If error has a config property, it means the error was during axios configuration
-      errorMessage = `Error in Axios configuration: ${error.config}`
-    }
+    // see: https://axios-http.com/docs/handling_errors
+    const errorMessage = `post request failed: response.status = '${error.response?.status}', ` +
+      `data: '${error.response.data}', ` +
+      `cause: '${error.cause}'` +
+      (error.request ? 'No response received, ' : '') +
+      `message: '${error.message}', ` +
+      (error.config ? `Error in Axios configuration ${error.config}` : '')
 
     throw new Error(errorMessage)
   }

src/utils/getVerboseColumns.js

@@ -2,12 +2,17 @@
     This file is a utility function that processes a row and returns verbose rows using the column field log and row data.
 */
 import logger from './logger.js'
+import { types } from './logging.js'
 
 const getVerboseColumns = (row, columnFieldLog) => {
   if (!columnFieldLog || !row.issue_logs) {
-    // Log an error if the["column-field-log"] or issue_logs are missing, and return what we can
-    logger.error('Invalid row data, missing["column-field-log"] or issue_logs')
-    return Object.entries(row.converted_row).map(([key, value]) => [key, { value, column: key, field: key, error: 'missing["column-field-log"] or issue_logs' }])
+    // if the["column-field-log"] or issue_logs are missing, return what we can
+    const message = `missing row data: ${columnFieldLog ? '' : 'column-field-log'} ${row.issue_logs ? '' : 'row.issue_logs'}`
+    logger.warn({ message, type: types.DataValidation })
+    const validator = ([key, value]) => {
+      return [key, { value, column: key, field: key, error: message }]
+    }
+    return Object.entries(row.converted_row).map(validator)
   }
   // Process the row and return verbose columns
 
@@ -35,11 +40,11 @@ const reduceVerboseValues = (verboseValuesAsArray) => {
       // If both the existing and new values are not null and they are different, log a message
       if (value.value && acc[key].value && value.value !== acc[key].value) {
         // ToDo: we need to handle this case
-        logger.error(`Duplicate keys with different values: ${key}`)
+        logger.warn(`Duplicate keys with different values: ${key}`, { type: types.DataValidation })
         // If the new value is not null, replace the existing value and log a message
       } else if (value.value) {
         acc[key] = value
-        logger.log(`Duplicate key found, keeping the one with value: ${key}`)
+        logger.debug(`Duplicate key found, keeping the one with value: ${key}`)
       }
       // If the key does not exist in the accumulator, add it
     } else {

src/utils/logging.js

@@ -1,13 +1,28 @@
 import logger from '../utils/logger.js'
 import hash from '../utils/hasher.js'
 
+/**
+ * Types of logging events.
+ *
+ * Use as a value for 'type' entry of {@link https://github.com/winstonjs/winston?tab=readme-ov-file#streams-objectmode-and-info-objects|`info` objects}
+ */
+const types = {
+  PageView: 'PageView',
+  Request: 'Request',
+  Response: 'Response',
+  AppLifecycle: 'AppLifecycle',
+  App: 'App',
+  DataValidation: 'DataValidation',
+  External: 'External'
+}
+
 const logPageView = (route, sessionID) => {
   logger.info({
-    type: 'PageView',
-    pageRoute: route,
-    message: `page view occurred for page: ${route}`,
+    type: types.PageView,
+    endpoint: route,
+    message: 'page view',
     sessionId: hash(sessionID)
   })
 }
 
-export { logPageView }
+export { logPageView, types }