Skip to content

Commit

Permalink
feat: Add server-side logging capability (strimzi#59)
Browse files Browse the repository at this point in the history
* feat: Add server-side logging capability

Contributes to: strimzi#43

Signed-off-by: Andrew Borley <[email protected]>

* fix: Address review comments

Addresses initial review comments from @matthew-chirgwin.

Contributes to: strimzi#43

Signed-off-by: Andrew Borley <[email protected]>

* fix: Move pino types to devDependencies

Contributes to: strimzi#43

Signed-off-by: Andrew Borley <[email protected]>
  • Loading branch information
ajborley authored Nov 4, 2020
1 parent 01ccd9f commit b4563ae
Show file tree
Hide file tree
Showing 17 changed files with 514 additions and 226 deletions.
304 changes: 298 additions & 6 deletions package-lock.json

Large diffs are not rendered by default.

6 changes: 6 additions & 0 deletions package.json
Original file line number Diff line number Diff line change
Expand Up @@ -56,6 +56,10 @@
"mini-css-extract-plugin": "^0.9.0",
"optimize-css-assets-webpack-plugin": "^5.0.3",
"react": "^16.13.1",
"pino": "^6.7.0",
"pino-filter": "^1.0.0",
"pino-http": "^5.3.0",
"pino-pretty": "^4.3.0",
"sass": "^1.26.10",
"subscriptions-transport-ws": "^0.9.18",
"terser-webpack-plugin": "^3.0.7",
Expand All @@ -74,6 +78,8 @@
"@types/express": "^4.17.8",
"@types/jest": "^26.0.14",
"@types/node": "^14.11.2",
"@types/pino": "^6.3.2",
"@types/pino-http": "^5.0.5",
"@types/supertest": "^2.0.10",
"@typescript-eslint/eslint-plugin": "^4.2.0",
"@typescript-eslint/parser": "^4.2.0",
Expand Down
1 change: 1 addition & 0 deletions server/README.md
Original file line number Diff line number Diff line change
Expand Up @@ -9,6 +9,7 @@ This directory contains all server code for the Strimzi UI - ie code which is re
- [`log`](./log/README.md) - module that handles client logging events.
- [`mockapi`](./mockapi/README.md) - handlers for emulating a real instance of `Strimzi-admin` in dev and test scenarios. Also allows the configuration of the server to be changed to enable test scenarios.
- [`test`](./test/README.md) - common test code and helpers for the UI server.
- `logging.ts` - logging handling module. Uses the logging configuration from the server's configuration to create the `pino` and `pino-http` loggers, and extends the Logger object with entry and exit tracing methods.
- `main.ts` - the build entry point for the production UI server. It bootstraps the server, and owns the creation and management of a node `http`/`https` server (and binding express to it).
- `serverConfig.ts` - configuration handling module. If an `configPath` envar is provided, the file specified is used for the server's configuration, else, `server.config.json` in the current working directory will be used. If neither exist, a default config defined in this module will be used.
- `types.ts` - custom types and interfaces used in the server code base.
Expand Down
18 changes: 8 additions & 10 deletions server/api/controller.ts
Original file line number Diff line number Diff line change
Expand Up @@ -9,10 +9,10 @@ export const proxyErrorHandler: (
req: strimziUIRequestType,
res: strimziUiResponseType
) => void = (err, req, res) => {
const { entry } = res.locals.strimziuicontext.loggers;
const { exit, debug } = entry('proxyErrorHandler', req.url, err.message);
debug(`Error occurred during proxy`, err);
exit(500);
res.locals.strimziuicontext.logger.debug(
{ err },
`Error occurred whilst proxying request '${req.url}'. ${err.message}`
);
res.sendStatus(500);
};

Expand All @@ -21,9 +21,9 @@ export const proxyStartHandler: (
req: strimziUIRequestType,
res: strimziUiResponseType
) => void = (_, req, res) => {
const { entry } = res.locals.strimziuicontext.loggers;
const { exit } = entry('proxyStartHandler');
exit(`Starting proxy of request '${req.url}' to the backend api`);
res.locals.strimziuicontext.logger.debug(
`Proxying request '${req.url}' to the backend api`
);
};

export const proxyCompleteHandler: (
Expand All @@ -34,9 +34,7 @@ export const proxyCompleteHandler: (
req: strimziUIRequestType,
res: strimziUiResponseType
) => void = ({ statusCode, statusMessage }, req, res) => {
const { entry } = res.locals.strimziuicontext.loggers;
const { exit } = entry('proxyCompleteHandler');
exit(
res.locals.strimziuicontext.logger.debug(
`Response from backend api for request '${req.url}' : ${statusCode} - ${statusMessage}`
);
};
7 changes: 3 additions & 4 deletions server/api/router.ts
Original file line number Diff line number Diff line change
Expand Up @@ -16,10 +16,9 @@ const moduleName = 'api';

export const ApiModule: UIServerModule = {
moduleName,
addModule: (logGenerator, authFn, serverConfig) => {
const { entry } = logGenerator(moduleName);
addModule: (logger, authFn, serverConfig) => {
const { proxy } = serverConfig;
const { debug, exit } = entry('addModule', proxy);
const { exit } = logger.entry('addModule', proxy);
const { hostname, port, contextRoot, transport } = proxy;
const { cert, minTLS } = transport;

Expand All @@ -31,7 +30,7 @@ export const ApiModule: UIServerModule = {
secure: cert ? true : false,
};

debug(`api proxy configuration`, JSON.stringify(proxyConfig));
logger.debug({ proxyConfig }, `api proxy configuration`);

const routerForModule = express.Router();
const backendProxy = createProxyServer(proxyConfig);
Expand Down
9 changes: 4 additions & 5 deletions server/client/router.ts
Original file line number Diff line number Diff line change
Expand Up @@ -11,10 +11,9 @@ const moduleName = 'client';

export const ClientModule: UIServerModule = {
moduleName,
addModule: (logGenerator, authFn, serverConfig) => {
addModule: (logger, authFn, serverConfig) => {
const { publicDir } = serverConfig.client.configOverrides;
const { entry } = logGenerator(moduleName);
const { debug, exit } = entry('addModule', publicDir);
const { exit } = logger.entry('addModule', publicDir);
const routerForModule = express.Router();

const {
Expand All @@ -24,10 +23,10 @@ export const ClientModule: UIServerModule = {
hasIndexFile,
} = getFiles(publicDir);

debug(
logger.debug(
`Client is hosting ${totalNumberOfFiles} static files, ${protectedFiles.length} of which are protected and require authentication`
);
debug(`Client has index.html to serve? ${hasIndexFile}`);
logger.debug(`Client has index.html to serve? ${hasIndexFile}`);

// add the auth middleware to all non public files
protectedFiles.forEach((file) => routerForModule.get(`${file}`, authFn));
Expand Down
5 changes: 2 additions & 3 deletions server/config/router.ts
Original file line number Diff line number Diff line change
Expand Up @@ -9,9 +9,8 @@ const moduleName = 'config';

export const ConfigModule: UIServerModule = {
moduleName,
addModule: (logGenerator, authFn) => {
const { entry } = logGenerator(moduleName);
const { exit } = entry('addModule');
addModule: (logger, authFn) => {
const { exit } = logger.entry('addModule');
const routerForModule = express.Router();

// implementation to follow
Expand Down
77 changes: 25 additions & 52 deletions server/core/app.ts
Original file line number Diff line number Diff line change
Expand Up @@ -4,26 +4,28 @@
*/
import express from 'express';
import helmet from 'helmet';
import { randomBytes } from 'crypto';
import * as availableModules from './modules';
import { serverConfig, UIServerModule } from 'types';
import { authFunction } from 'placeholderFunctionsToReplace';
import {
generateLoggers,
log,
authFunction,
} from 'placeholderFunctionsToReplace';

const STRIMZI_UI_REQUEST_ID_HEADER = 'x-strimzi-ui-request';
generateLogger,
generateHttpLogger,
STRIMZI_UI_REQUEST_ID_HEADER,
} from 'logging';

export const returnExpress: (
serverName: string,
getConfig: () => serverConfig
) => express.Application = (serverName, getConfig) => {
const logger = generateLogger('core');
const app = express();

// add helmet middleware
app.use(helmet());

// add pino-http middleware
app.use(generateHttpLogger());

// for each module, call the function to add it to the routing table
const routingTable = Object.values(availableModules).reduce(
(
Expand All @@ -33,78 +35,49 @@ export const returnExpress: (
>,
{ moduleName, addModule }: UIServerModule
) => {
log(
serverName,
'startup',
'core',
'moduleMount',
`Mounting module '${moduleName}'`
);
logger.info(`Mounting module '${moduleName}'`);
const config = getConfig();
const { mountPoint, routerForModule } = addModule(
(moduleName) => generateLoggers(serverName, moduleName, 'startup'),
generateLogger(moduleName),
authFunction(config.authentication),
config
);
log(
serverName,
'startup',
'core',
'moduleMount',
`Mounted module '${moduleName}' on '${mountPoint}'`
);
logger.info(`Mounted module '${moduleName}' on '${mountPoint}'`);
return { ...acc, [moduleName]: { mountPoint, routerForModule } };
},
{}
);

// before all handlers, add context and request start/end handlers
app.all('*', (req, res, next) => {
// add id to request for use downstream
if (!req.headers[STRIMZI_UI_REQUEST_ID_HEADER]) {
req.headers[STRIMZI_UI_REQUEST_ID_HEADER] = randomBytes(8).toString(
'hex'
);
}
const requestID = req.headers[STRIMZI_UI_REQUEST_ID_HEADER] as string;
// and make sure the response has the header
res.setHeader(STRIMZI_UI_REQUEST_ID_HEADER, requestID);
// create a 'context' for this request, containing config, a request ID, and loggers. Available to handlers via `res.locals.strimziuicontext`
// log start of request (end of request is automatically logged)
req.log.debug('Request received');
// make sure the response has the requestID header (set via the pino-http middleware)
res.setHeader(STRIMZI_UI_REQUEST_ID_HEADER, req.id as string);

// create a 'context' for this request, containing config and the request ID. Available to handlers via `res.locals.strimziuicontext`
res.locals.strimziuicontext = {
config: getConfig(),
requestID,
requestID: req.id,
};
// set up loggers for start/end of request
const { event } = generateLoggers(serverName, 'core', requestID);
event(`requestStart`, `${req.method} of ${req.url} starting`);
res.once('finish', () => {
event(
`requestEnd`,
`${req.method} of ${req.url} complete RC: ${res.statusCode}`
);
});
next();
});

Object.entries(routingTable).forEach(
([moduleName, { mountPoint, routerForModule }]) =>
app.use(`${mountPoint}`, (req, res, next) => {
// add loggers for this module
// add logger for this module
res.locals.strimziuicontext = {
...res.locals.strimziuicontext,
loggers: generateLoggers(
serverName,
moduleName,
res.locals.strimziuicontext.requestID
),
logger: generateLogger(moduleName, req.id as string),
};

const { entry } = res.locals.strimziuicontext.loggers;
const { debug, exit } = entry(`module enabled check`);
const isEnabled =
res.locals.strimziuicontext.config.modules[moduleName];
debug(`Enabled?`, isEnabled);
exit(isEnabled);
res.locals.strimziuicontext.logger.debug(
`%s module is ${isEnabled ? '' : 'not '}enabled`,
moduleName
);
isEnabled ? routerForModule(req, res, next) : next(); // if enabled, call the router for the module so it can handle the request. Else, call the next module
})
);
Expand Down
5 changes: 2 additions & 3 deletions server/log/router.ts
Original file line number Diff line number Diff line change
Expand Up @@ -9,9 +9,8 @@ const moduleName = 'log';

export const LogModule: UIServerModule = {
moduleName,
addModule: (logGenerator, authFn) => {
const { entry } = logGenerator(moduleName);
const { exit } = entry('addModule');
addModule: (logger, authFn) => {
const { exit } = logger.entry('addModule');
const routerForModule = express.Router();

// implementation to follow
Expand Down
98 changes: 98 additions & 0 deletions server/logging.ts
Original file line number Diff line number Diff line change
@@ -0,0 +1,98 @@
/*
* Copyright Strimzi authors.
* License: Apache License 2.0 (see the file LICENSE or http://apache.org/licenses/LICENSE-2.0.html).
*/

import pinoLogger from 'pino';
import pinoHttpLogger from 'pino-http';
import { randomBytes } from 'crypto';

import { getServerName } from 'serverConfig';
import { entryExitLoggerType } from 'types';

const STRIMZI_UI_REQUEST_ID_HEADER = 'x-strimzi-ui-request';

const serverName = getServerName();

let rootLogger = pinoLogger();

/** Replaces the rootLogger with a new pinoLogger with the supplied options */
const updateRootLoggerOptions: (
loggerOptions: pinoLogger.LoggerOptions,
isUpdate: boolean
) => void = (loggerOptions, isUpdate) => {
rootLogger.info(
{
serverName,
module: 'logging',
loggerOptions,
},
`Strimzi ui logging options${isUpdate ? ' updated' : ''}`
);
try {
// Update the root logger with the new options
rootLogger = pinoLogger(loggerOptions);
} catch (err) {
rootLogger.error(
{
serverName,
module: 'logging',
loggerOptions,
err,
},
`Failed to configure logging options: ${err.message}`
);
}
};

/** Generate an entryExitLogger */
const generateLogger: (
module: string,
requestID?: string
) => entryExitLoggerType = (module, requestID) => {
const logger = rootLogger.child({
serverName,
module,
requestID,
});

const entryExitLogger = logger;
entryExitLogger.entry = (fnName, ...params) => {
logger.trace({ fnName, params }, 'entry');
return {
exit: (returns) => {
logger.trace({ fnName, returns }, 'exit');
return returns; // return params so you can do `return exit(.....)`
},
};
};

return entryExitLogger as entryExitLoggerType;
};

/** Generate a pino-http HttpLogger */
const generateHttpLogger: () => pinoHttpLogger.HttpLogger = () =>
pinoHttpLogger({
logger: rootLogger,
useLevel: 'debug',
genReqId: generateRequestID,
reqCustomProps: () => ({
serverName,
module: 'core',
}),
});

/** Generate or retrieve the request ID used in the pino-http HttpLogger */
const generateRequestID: (Request) => string = (req) => {
if (!req.headers[STRIMZI_UI_REQUEST_ID_HEADER]) {
req.headers[STRIMZI_UI_REQUEST_ID_HEADER] = randomBytes(8).toString('hex');
}
return req.headers[STRIMZI_UI_REQUEST_ID_HEADER] as string;
};

export {
generateLogger,
generateHttpLogger,
updateRootLoggerOptions,
STRIMZI_UI_REQUEST_ID_HEADER,
};
Loading

0 comments on commit b4563ae

Please sign in to comment.