diff --git a/app.js b/app.js index 8d101984..b94359f8 100644 --- a/app.js +++ b/app.js @@ -1,249 +1,249 @@ 'use strict'; const http = require( 'http' ); const BBPromise = require( 'bluebird' ); const express = require( 'express' ); const compression = require( 'compression' ); const bodyParser = require( 'body-parser' ); const fs = BBPromise.promisifyAll( require( 'fs' ) ); const sUtil = require( './lib/util' ); const apiUtil = require( './lib/api-util' ); const packageInfo = require( './package.json' ); const yaml = require( 'js-yaml' ); const addShutdown = require( 'http-shutdown' ); const path = require( 'path' ); -const { setLogger } = require( './src/logger.js' ); +const { getLogger, setLogger } = require( './src/logger.js' ); /** * Creates an express app and initialises it * * @param {Object} options the options to initialise the app with * @return {bluebird} the promise resolving to the app object */ function initApp( options ) { // the main application object const app = express(); - const logger = options.logger; - setLogger( logger ); + setLogger( options.logger ); + const logger = getLogger(); // get the options and make them available in the app - app.logger = options.logger; // the logging device + app.logger = logger; // the logging device app.metrics = options.metrics; // the metrics app.conf = options.config; // this app's config options app.info = packageInfo; // this app's package info // ensure some sane defaults app.conf.port = app.conf.port || 8888; app.conf.interface = app.conf.interface || '0.0.0.0'; // eslint-disable-next-line max-len app.conf.compression_level = app.conf.compression_level === undefined ? 3 : app.conf.compression_level; app.conf.cors = app.conf.cors === undefined ? '*' : app.conf.cors; if ( app.conf.csp === undefined ) { app.conf.csp = "default-src 'self'; object-src 'none'; media-src 'none'; img-src 'none'; style-src 'none'; base-uri 'self'; frame-ancestors 'self'"; } // set outgoing proxy if ( app.conf.proxy ) { process.env.HTTP_PROXY = app.conf.proxy; // if there is a list of domains which should // not be proxied, set it if ( app.conf.no_proxy_list ) { if ( Array.isArray( app.conf.no_proxy_list ) ) { process.env.NO_PROXY = app.conf.no_proxy_list.join( ',' ); } else { process.env.NO_PROXY = app.conf.no_proxy_list; } } } // set up header whitelisting for logging if ( !app.conf.log_header_whitelist ) { app.conf.log_header_whitelist = [ 'cache-control', 'content-type', 'content-length', 'if-match', 'user-agent', 'x-request-id' ]; } app.conf.log_header_whitelist = new RegExp( `^(?:${app.conf.log_header_whitelist.map( ( item ) => { return item.trim(); } ).join( '|' )})$`, 'i' ); // set up the request templates for the APIs apiUtil.setupApiTemplates( app ); // set up the spec if ( !app.conf.spec ) { app.conf.spec = `${__dirname}/spec.yaml`; } if ( app.conf.spec.constructor !== Object ) { try { app.conf.spec = yaml.safeLoad( fs.readFileSync( app.conf.spec ) ); } catch ( e ) { - app.logger.log( 'warn/spec', `Could not load the spec: ${e}` ); + logger.log( 'warn/spec', `Could not load the spec: ${e}` ); app.conf.spec = {}; } } if ( !app.conf.spec.openapi ) { app.conf.spec.openapi = '3.0.0'; } if ( !app.conf.spec.info ) { app.conf.spec.info = { version: app.info.version, title: app.info.name, description: app.info.description }; } app.conf.spec.info.version = app.info.version; if ( !app.conf.spec.paths ) { app.conf.spec.paths = {}; } // set the CORS and CSP headers app.all( '*', ( req, res, next ) => { if ( app.conf.cors !== false ) { res.header( 'access-control-allow-origin', app.conf.cors ); res.header( 'access-control-allow-headers', 'accept, x-requested-with, content-type' ); res.header( 'access-control-expose-headers', 'etag' ); } if ( app.conf.csp !== false ) { res.header( 'x-xss-protection', '1; mode=block' ); res.header( 'x-content-type-options', 'nosniff' ); res.header( 'x-frame-options', 'SAMEORIGIN' ); res.header( 'content-security-policy', app.conf.csp ); } sUtil.initAndLogRequest( req, app ); next(); } ); // set up the user agent header string to use for requests app.conf.user_agent = app.conf.user_agent || app.info.name; // disable the X-Powered-By header app.set( 'x-powered-by', false ); // disable the ETag header - users should provide them! app.set( 'etag', false ); // enable compression app.use( compression( { level: app.conf.compression_level } ) ); // use the JSON body parser app.use( bodyParser.json( { limit: app.conf.max_body_size || '100kb' } ) ); // use the application/x-www-form-urlencoded parser app.use( bodyParser.urlencoded( { extended: true } ) ); return BBPromise.resolve( app ); } /** * Loads all routes declared in routes/ into the app * * @param {Application} app the application object to load routes into * @param {string} dir routes folder * @return {bluebird} a promise resolving to the app object */ function loadRoutes( app, dir ) { // recursively load routes from .js files under routes/ return fs.readdirAsync( dir ).map( ( fname ) => { return BBPromise.try( () => { const resolvedPath = path.resolve( dir, fname ); const isDirectory = fs.statSync( resolvedPath ).isDirectory(); if ( isDirectory ) { loadRoutes( app, resolvedPath ); } else if ( /\.js$/.test( fname ) ) { // import the route file const route = require( `${dir}/${fname}` ); return route( app ); } } ).then( ( route ) => { if ( route === undefined ) { return undefined; } // check that the route exports the object we need if ( route.constructor !== Object || !route.path || !route.router || !( route.api_version || route.skip_domain ) ) { throw new TypeError( `routes/${fname} does not export the correct object!` ); } // normalise the path to be used as the mount point if ( route.path[ 0 ] !== '/' ) { route.path = `/${route.path}`; } if ( route.path[ route.path.length - 1 ] !== '/' ) { route.path = `${route.path}/`; } if ( !route.skip_domain ) { route.path = `/:domain/v${route.api_version}${route.path}`; } // wrap the route handlers with Promise.try() blocks sUtil.wrapRouteHandlers( route, app ); // all good, use that route app.use( route.path, route.router ); } ); } ).then( () => { // catch errors sUtil.setErrorHandler( app ); // route loading is now complete, return the app object return BBPromise.resolve( app ); } ); } /** * Creates and start the service's web server * * @param {Application} app the app object to use in the service * @return {bluebird} a promise creating the web server */ function createServer( app ) { // return a promise which creates an HTTP server, // attaches the app to it, and starts accepting // incoming client requests let server; return new BBPromise( ( resolve ) => { server = http.createServer( app ).listen( app.conf.port, app.conf.interface, resolve ); server = addShutdown( server ); } ).then( () => { - app.logger.log( 'info', + getLogger().log( 'info', `Worker ${process.pid} listening on ${app.conf.interface || '*'}:${app.conf.port}` ); // Don't delay incomplete packets for 40ms (Linux default) on // pipelined HTTP sockets. We write in large chunks or buffers, so // lack of coalescing should not be an issue here. server.on( 'connection', ( socket ) => { socket.setNoDelay( true ); } ); return server; } ); } /** * The service's entry point. It takes over the configuration * options and the logger- and metrics-reporting objects from * service-runner and starts an HTTP server, attaching the application * object to it. * * @param {Object} options the options to initialise the app with * @return {bluebird} HTTP server */ module.exports = ( options ) => { return initApp( options ) .then( ( app ) => loadRoutes( app, `${__dirname}/routes` ) ) .then( ( app ) => { // serve static files from static/ app.use( '/static', express.static( `${__dirname}/static` ) ); return app; } ).then( createServer ); }; diff --git a/src/logger.js b/src/logger.js index 164b17be..ecc73fcc 100644 --- a/src/logger.js +++ b/src/logger.js @@ -1,20 +1,139 @@ 'use strict'; -const bunyan = require( 'bunyan' ); +const ServiceRunner = require( 'service-runner' ); +/** + * This is a wrapper for the logger provided by service runner. + * It provides more user-friendly logging APIs and better error + * signaling for when it is used incorrectly. + * + * This is the logger that other scripts in this project will interact with. + * Usage: + * const { getLogger } = require( '...logger.js' ); + * const logger = getLogger() + * logger.log('warn', 'hello this is a message'); + * logger.warn('hello this is also a message'); + */ +class LoggerWrapper { + constructor( logger ) { + this._logger = logger; + } + + /** + * Logs a message on a given severity level. + * Acceptable levels: trace, debug, info, warn, error, and fatal. + * + * @param {string} level Severity level and components. + * Level options: trace, debug, info, warn, error, and fatal. + * E.g. trace or trace/request. + * @param {string} msg A string message for the log. + */ + log( level, msg ) { + if ( !level || !msg ) { + // The service runner implementation will just silently no-op + // in this situation. We want to alert the caller here. + throw new Error( + `Incorrect usage of the logger. Both arguments need to be + present. E.g. logger.log(level, msg). Alternatively you can + use the logger.level() API.` ); + } + this._logger.log( level, msg ); + } + + /** + * Logs a tracing message. + * + * @param {string} msg Trace message. + */ + trace( msg ) { + this.log( 'trace', msg ); + } + + /** + * Logs a debug message. + * + * @param {string} msg Debug message. + */ + debug( msg ) { + this.log( 'debug', msg ); + } + + /** + * Logs a info message. + * + * @param {string} msg Info message. + */ + info( msg ) { + this.log( 'info', msg ); + } + + /** + * Logs a warning message. + * + * @param {string} msg Warning message. + */ + warn( msg ) { + this.log( 'warn', msg ); + } + + /** + * Logs a error message. + * + * @param {string} msg Error message. + */ + error( msg ) { + this.log( 'error', msg ); + } + + /** + * Logs a fatal message. + * + * @param {string} msg Fatal message. + */ + fatal( msg ) { + this.log( 'fatal', msg ); + } + + /** + * Creates a child logger for a sub-component of your application. + * This directly wraps its core logger obj's implementation. + * + * @param {*} args arguments for the child wrapper. + * @return {LoggerWrapper} A new logger for the sub-component. + */ + child( args ) { + return new LoggerWrapper( this._logger.child( args ) ); + } +} + +// This is the universal logger we will use for this orchestrator +// project. let _logger; +/** + * Gets the universal logger for this app. It should have been + * set during initialization, but if it somehow wasn't, a new + * one will be created. + * + * @return {LoggerWrapper} The universal logger for this orchestrator app. + */ function getLogger() { if ( !_logger ) { - setLogger( bunyan.createLogger( { + setLogger( ServiceRunner.getLogger( { name: 'function-orchestrator' } ) ); } return _logger; } +/** + * Sets the universal logger for this app. It wraps the service runner logger + * in a new object with more logging APIs. + * + * @param {*} logger The Service Runner logger object. + */ function setLogger( logger ) { - _logger = logger; + _logger = new LoggerWrapper( logger ); } module.exports = { getLogger, setLogger }; diff --git a/src/orchestrate.js b/src/orchestrate.js index 23103e02..ff04a3e9 100644 --- a/src/orchestrate.js +++ b/src/orchestrate.js @@ -1,149 +1,153 @@ 'use strict'; const canonicalize = require( '../function-schemata/javascript/src/canonicalize.js' ); const normalize = require( '../function-schemata/javascript/src/normalize.js' ); const { makeMappedResultEnvelope, setMetadataValue } = require( '../function-schemata/javascript/src/utils.js' ); const { validatesAsFunctionCall } = require( '../function-schemata/javascript/src/schema.js' ); const { error, normalError } = require( '../function-schemata/javascript/src/error' ); const ErrorFormatter = require( '../function-schemata/javascript/src/errorFormatter' ); const { validate } = require( './validation.js' ); const { execute } = require( './execute.js' ); const { containsError, isError, makeWrappedResultEnvelope, returnOnFirstError } = require( './utils.js' ); const { Evaluator } = require( './Evaluator.js' ); const { Invariants } = require( './Invariants.js' ); const { ReferenceResolver } = require( './db.js' ); const { ZWrapper } = require( './ZWrapper' ); const { cpuUsage, memoryUsage } = require( 'node:process' ); const { getLogger } = require( './logger.js' ); /** * Decides whether to validate a function. Returns the pair * if validation succeeds; otherwise returns the pair * . * * @param {Object} zobject * @param {boolean} doValidate whether to run validation; succeeds trivially if false * @param {Invariants} invariants for resolving Z9s * @return {Object} a Z22 */ async function maybeValidate( zobject, doValidate, invariants ) { if ( doValidate ) { const errors = ( await validate( zobject, invariants ) ).map( ( errorWrapper ) => errorWrapper.asJSON() ); if ( errors.length > 0 ) { return makeMappedResultEnvelope( null, errors.length === 1 ? errors[ 0 ] : ErrorFormatter.createZErrorList( errors ) ); } } return makeMappedResultEnvelope( zobject, null ); } /** * Returns the pair if the input object is a Z7; * otherwise returns the pair . * * @param {Object} zobject * @return {Object} a Z22 as described above */ async function Z7OrError( zobject ) { if ( ( await validatesAsFunctionCall( zobject ) ).isValid() ) { return makeMappedResultEnvelope( zobject, null ); } return makeMappedResultEnvelope( null, normalError( [ error.wrong_content_type ], [ 'The provided object is not a function call' ] ) ); } /** * Main orchestration workflow. Executes an input Z7 and returns either the * results of function evaluation or the relevant error(s). * * Takes and returns JSON representation; not ZWrapper. * * @param {Object} input the input for a function call * @param {ImplementationSelector} implementationSelector * @return {Object} a Z22 containing the result of function evaluation or a Z5 */ async function orchestrate( input, implementationSelector = null ) { const startTime = new Date(); const startUsage = cpuUsage(); + const logger = getLogger(); let zobject = input.zobject; if ( zobject === undefined ) { zobject = input; } let currentPair; if ( isError( zobject ) ) { currentPair = makeMappedResultEnvelope( null, zobject, /* canonicalize= */true ); } else { currentPair = makeMappedResultEnvelope( zobject, null, /* canonicalize= */true ); } const evaluator = new Evaluator( input.evaluatorUri || null ); const resolver = new ReferenceResolver( input.wikiUri || null ); const invariants = new Invariants( evaluator, resolver ); const doValidate = typeof input.doValidate === 'boolean' ? input.doValidate : true; const callTuples = [ [ normalize, [ /* generically= */true, /* withVoid= */ true ], 'normalize' ], // TODO (T296685): Dereference top-level object if it is a Z9? [ Z7OrError, [], 'Z7OrError' ], [ makeWrappedResultEnvelope, [], 'wrapAsZObject' ], [ maybeValidate, [ doValidate, invariants ], 'maybeValidate' ], [ execute, [ invariants, /* doValidate= */true, /* implementationSelector= */implementationSelector, /* resolveInternals= */true, /* topLevel= */true ], 'execute' ] ]; - currentPair = await returnOnFirstError( currentPair, callTuples ); + try { + currentPair = await returnOnFirstError( currentPair, callTuples ); + } catch ( e ) { + logger.error( `Call tuples failed in returnOnFirstError. Error: ${e}.` ); + } if ( currentPair instanceof ZWrapper ) { currentPair = currentPair.asJSON(); } const cpuUsageStats = cpuUsage( startUsage ); const cpuUsageStr = ( ( cpuUsageStats.user + cpuUsageStats.system ) / 1000 ) + ' ms'; const memoryUsageStr = Math.round( memoryUsage.rss() / 1024 / 1024 * 100 ) / 100 + ' MiB'; const endTime = new Date(); const startTimeStr = startTime.toISOString(); const endTimeStr = endTime.toISOString(); const durationStr = ( endTime.getTime() - startTime.getTime() ) + ' ms'; currentPair = setMetadataValue( currentPair, { Z1K1: 'Z6', Z6K1: 'orchestrationMemoryUsage' }, { Z1K1: 'Z6', Z6K1: memoryUsageStr } ); currentPair = setMetadataValue( currentPair, { Z1K1: 'Z6', Z6K1: 'orchestrationCpuUsage' }, { Z1K1: 'Z6', Z6K1: cpuUsageStr } ); currentPair = setMetadataValue( currentPair, { Z1K1: 'Z6', Z6K1: 'orchestrationStartTime' }, { Z1K1: 'Z6', Z6K1: startTimeStr } ); currentPair = setMetadataValue( currentPair, { Z1K1: 'Z6', Z6K1: 'orchestrationEndTime' }, { Z1K1: 'Z6', Z6K1: endTimeStr } ); currentPair = setMetadataValue( currentPair, { Z1K1: 'Z6', Z6K1: 'orchestrationDuration' }, { Z1K1: 'Z6', Z6K1: durationStr } ); const canonicalized = await canonicalize( currentPair, /* withVoid= */ true ); if ( containsError( canonicalized ) ) { // If canonicalization fails, return normalized form instead. - const logger = getLogger(); - logger.log( 'Could not canonicalize; outputting in normal form.' ); + logger.info( 'Could not canonicalize; outputting in normal form.' ); } else { currentPair = canonicalized.Z22K1; } return currentPair; } module.exports = orchestrate;