Merge pull request #11 from TiltingPoint/feat/logging/PLATFORM-3549

[PLATFORM-3549] Add structured logging

src/api.ts

@@ -10,6 +10,7 @@ import { helloAuth, HelloConfig, LoginSyncParams, LoginSyncResponse, LogoutSyncP
 
 import { PUBLIC_JWKS, PRIVATE_KEY, PUBLIC_KEY } from './jwks'
 import * as state from './state'
+import * as logger from './logger'
 
 import {
     API_ROOT,
@@ -63,6 +64,12 @@ const { version } = require('../package.json')
 const clientId = process.env.CLIENT_ID || process.env.HELLO_CLIENT_ID
 const cookieSecret = process.env.COOKIE_SECRET || process.env.HELLO_COOKIE_SECRET
 
+// create structure log instead of raw error log
+process.on('uncaughtException', (error: Error) => {
+    logger.error(error.message || 'Uncaught Exception', logger.formatError(error));
+    process.exit(1);
+});
+
 if (!clientId) {
     throw new Error('CLIENT_ID or HELLO_CLIENT_ID is required')
 }
@@ -109,7 +116,7 @@ if (USE_DPOP) {
 }
 
 
-console.log('/.well-known/oauth-authorization-server', JSON.stringify(META_DATA, null, 2))
+logger.info('/.well-known/oauth-authorization-server', { metaData: JSON.stringify(META_DATA, null, 2) })
 
 class TokenError extends Error {
     statusCode: number;
@@ -500,7 +507,7 @@ const tokenEndpoint = async (req: FastifyRequest, reply: FastifyReply) => {
         reply.code(400).send({error:'unsupported_grant_type'})
     } catch (e) {
         const error = e as TokenError
-        console.error('token endpoint fault',error)
+        logger.error('token endpoint fault', logger.formatError(error))
         setSessionCookie(reply, '')
         return reply.code(error.statusCode || 500).send({error: 'token parsing'})
     }
@@ -548,7 +555,7 @@ if (loginSyncUrl) {
     if (!(loginSyncUrl.startsWith('http://') || loginSyncUrl.startsWith('https://'))) {
         throw new Error('LOGIN_SYNC_URL must be a valid URL and start with https:// or http://')
     }
-    console.log('loginSyncUrl', loginSyncUrl)
+    logger.info(`loginSyncUrl set ${loginSyncUrl}`)
 }
 
 const logoutUser = async (nonce: string) => {
@@ -572,7 +579,7 @@ const logoutSync = async (params: LogoutSyncParams): Promise<LogoutSyncResponse>
             console.log('logoutSync postheaders', params.cbRes.getHeaders())
 
     } catch (e) {
-        console.error('logoutSync error', e)
+        logger.error('logoutSync error', logger.formatError(e))
     }
 
 
@@ -589,15 +596,15 @@ const loginSync = async ( params: LoginSyncParams ): Promise<LoginSyncResponse>
 
     const currentState = await state.read(nonce)
     if (!currentState) {
-        console.error({error:'invalid_request', error_description:'nonce is invalid'})
+        logger.error("loginSync nonce is invalid")
         return {}
     }
     if (currentState.loggedIn) {
-        console.error({error:'invalid_request', error_description:'nonce is already logged in'})
+        logger.error("loginSync nonce is already logged in")
         return {}
     }
     if ((currentState.exp ?? 0) < now) {
-        console.error({error:'invalid_request', error_description:'state has expired'})
+        logger.error("loginSync state has expired")
         return {}
     }
 
@@ -638,7 +645,7 @@ const loginSync = async ( params: LoginSyncParams ): Promise<LoginSyncResponse>
             })
         })
         if (!response.ok) {
-                console.log(`loginSyncUrl ${loginSyncUrl} returned ${response.status} - access denied for sub ${sub}`)
+                logger.info('loginSync failed, access denied', { status: response.status, sub, url: loginSyncUrl })
                 await logoutUser(nonce)
                 return { accessDenied: true }
         }
@@ -648,7 +655,7 @@ const loginSync = async ( params: LoginSyncParams ): Promise<LoginSyncResponse>
                 const json = await response.json()
                 const { accessDenied, payload, target_uri: new_target_uri }  = json                
                 if (accessDenied) {
-                    console.log('loginSync - access denied for sub', sub)
+                    logger.info("loginSync access denied for sub", { sub })
                     await logoutUser(nonce)
                     return { accessDenied: true}
                 }
@@ -668,7 +675,7 @@ const loginSync = async ( params: LoginSyncParams ): Promise<LoginSyncResponse>
                     syncResponse.target_uri = new_target_uri
                 }
             } catch (e) {
-                console.error('loginSync - JSON parsing error', e)
+                logger.error('loginSync response error', logger.formatError(e));
             }
         }
 

src/jwks.ts

@@ -2,6 +2,7 @@ import fs from 'fs';
 import path from 'path';
 import jwkToPem, { JWK } from 'jwk-to-pem';
 import { promisify } from 'util';
+import * as logger from './logger';
 
 const readFile = promisify(fs.readFile);
 
@@ -68,11 +69,7 @@ const loadKeys = (): void => {
 try {
     loadKeys();
 } catch (error) {
-    if (error instanceof Error) {
-        console.error('Error:', error.message);
-    } else {
-        console.error('Error:', 'An error occurred');
-    }
+    logger.error("failed to load JWKS keys", logger.formatError(error));
 }
 
 export { PRIVATE_KEY, PUBLIC_KEY, PUBLIC_JWKS };

src/logger.ts

@@ -0,0 +1,47 @@
+const LOG_LEVEL = process.env.LOG_LEVEL || "info";
+
+interface LogAttributes {
+  [key: string]: string | number | boolean | unknown | undefined | Error;
+}
+
+export function log(msg: string, level: "debug" | "info" | "warn" | "error", attributes?: LogAttributes) {
+  if (LOG_LEVEL === "info" && level === "debug") {
+    return;
+  }
+
+  if (LOG_LEVEL === "warn" && ["debug", "info"].includes(level)) {
+    return;
+  }
+
+  if (LOG_LEVEL === "error" && level !== "error") {
+    return;
+  }
+
+  const message = { msg, level, ...attributes };
+  //eslint-disable-next-line no-console
+  console.log(JSON.stringify(message));
+}
+
+export function debug(msg: string, attributes?: LogAttributes) {
+  log(msg, "debug", attributes);
+}
+
+export function info(msg: string, attributes?: LogAttributes) {
+  log(msg, "info", attributes);
+}
+
+export function warn(msg: string, attributes?: LogAttributes) {
+  log(msg, "warn", attributes);
+}
+
+export function error(msg: string, attributes?: LogAttributes) {
+  log(msg, "error", attributes);
+}
+
+export function formatError(error: Error | unknown): { error: string } {
+  if (!(error instanceof Error)) {
+    return { error: JSON.stringify({message: 'unable to format error'}) };
+  }
+  const { message, stack, name } = error;
+  return { error: JSON.stringify({ message, stack: stack?.replaceAll('\n', ';'), name }) };
+}

src/server.ts

@@ -2,6 +2,7 @@
 
 import { api, PORT } from './api'
 import Fastify, { FastifyInstance } from 'fastify'
+import * as logger from './logger';
 
 const app: FastifyInstance = Fastify()
 
@@ -12,5 +13,5 @@ app.listen({ host: '0.0.0.0', port: PORT }, function (err, address) {
       console.error(err);
       process.exit(1);
     }
-    console.log(`server listening on ${address}`);
+    logger.info(`server listening on ${address}`);
 })