From 4774e61d50f76c518d0628cfdf8beede5017455d Mon Sep 17 00:00:00 2001 From: Michael Jackson Date: Fri, 2 Aug 2019 17:34:00 -0700 Subject: [PATCH] Add request logging --- app-staging.yaml | 1 + modules/actions/serveBrowsePage.js | 9 ++- modules/actions/serveDirectoryBrowser.js | 2 +- modules/actions/serveDirectoryMetadata.js | 2 +- modules/actions/serveFileBrowser.js | 2 +- modules/actions/serveFileMetadata.js | 2 +- modules/createServer.js | 14 +++-- modules/middleware/cors.js | 5 -- modules/middleware/findEntry.js | 2 +- modules/middleware/logger.js | 15 ----- modules/middleware/requestLog.js | 71 +++++++++++++++++++++++ modules/middleware/validateVersion.js | 13 +++-- modules/utils/logging.js | 5 -- modules/utils/npm.js | 21 ++++--- 14 files changed, 112 insertions(+), 52 deletions(-) delete mode 100644 modules/middleware/cors.js delete mode 100644 modules/middleware/logger.js create mode 100644 modules/middleware/requestLog.js delete mode 100644 modules/utils/logging.js diff --git a/app-staging.yaml b/app-staging.yaml index 4374bb0..5620b99 100644 --- a/app-staging.yaml +++ b/app-staging.yaml @@ -5,3 +5,4 @@ basic_scaling: max_instances: 1 env_variables: NODE_ENV: 'staging' + DEBUG: 1 diff --git a/modules/actions/serveBrowsePage.js b/modules/actions/serveBrowsePage.js index 68313ff..01085b9 100644 --- a/modules/actions/serveBrowsePage.js +++ b/modules/actions/serveBrowsePage.js @@ -26,13 +26,16 @@ function byVersion(a, b) { return semver.lt(a, b) ? -1 : semver.gt(a, b) ? 1 : 0; } -async function getAvailableVersions(packageName) { - const versionsAndTags = await getVersionsAndTags(packageName); +async function getAvailableVersions(packageName, log) { + const versionsAndTags = await getVersionsAndTags(packageName, log); return versionsAndTags ? versionsAndTags.versions.sort(byVersion) : []; } async function serveBrowsePage(req, res) { - const availableVersions = await getAvailableVersions(req.packageName); + const availableVersions = await getAvailableVersions( + req.packageName, + req.log + ); const data = { packageName: req.packageName, packageVersion: req.packageVersion, diff --git a/modules/actions/serveDirectoryBrowser.js b/modules/actions/serveDirectoryBrowser.js index 8ab3f09..561fb2e 100644 --- a/modules/actions/serveDirectoryBrowser.js +++ b/modules/actions/serveDirectoryBrowser.js @@ -65,7 +65,7 @@ async function findMatchingEntries(stream, filename) { } async function serveDirectoryBrowser(req, res) { - const stream = await getPackage(req.packageName, req.packageVersion); + const stream = await getPackage(req.packageName, req.packageVersion, req.log); const filename = req.filename.slice(0, -1) || '/'; const entries = await findMatchingEntries(stream, filename); diff --git a/modules/actions/serveDirectoryMetadata.js b/modules/actions/serveDirectoryMetadata.js index c38d848..4054882 100644 --- a/modules/actions/serveDirectoryMetadata.js +++ b/modules/actions/serveDirectoryMetadata.js @@ -90,7 +90,7 @@ function getMetadata(entry, entries) { } async function serveDirectoryMetadata(req, res) { - const stream = await getPackage(req.packageName, req.packageVersion); + const stream = await getPackage(req.packageName, req.packageVersion, req.log); const filename = req.filename.slice(0, -1) || '/'; const entries = await findMatchingEntries(stream, filename); diff --git a/modules/actions/serveFileBrowser.js b/modules/actions/serveFileBrowser.js index cb41534..640f26b 100644 --- a/modules/actions/serveFileBrowser.js +++ b/modules/actions/serveFileBrowser.js @@ -53,7 +53,7 @@ async function findEntry(stream, filename) { } async function serveFileBrowser(req, res) { - const stream = await getPackage(req.packageName, req.packageVersion); + const stream = await getPackage(req.packageName, req.packageVersion, req.log); const entry = await findEntry(stream, req.filename); if (!entry) { diff --git a/modules/actions/serveFileMetadata.js b/modules/actions/serveFileMetadata.js index 030be30..a7b3b45 100644 --- a/modules/actions/serveFileMetadata.js +++ b/modules/actions/serveFileMetadata.js @@ -53,7 +53,7 @@ async function findEntry(stream, filename) { } async function serveFileMetadata(req, res) { - const stream = await getPackage(req.packageName, req.packageVersion); + const stream = await getPackage(req.packageName, req.packageVersion, req.log); const entry = await findEntry(stream, req.filename); if (!entry) { diff --git a/modules/createServer.js b/modules/createServer.js index f65f38d..30d67d2 100644 --- a/modules/createServer.js +++ b/modules/createServer.js @@ -1,4 +1,6 @@ +import cors from 'cors'; import express from 'express'; +import morgan from 'morgan'; import serveDirectoryBrowser from './actions/serveDirectoryBrowser.js'; import serveDirectoryMetadata from './actions/serveDirectoryMetadata.js'; @@ -9,10 +11,9 @@ import serveMainPage from './actions/serveMainPage.js'; import serveModule from './actions/serveModule.js'; import serveStats from './actions/serveStats.js'; -import cors from './middleware/cors.js'; import findEntry from './middleware/findEntry.js'; -import logger from './middleware/logger.js'; import redirectLegacyURLs from './middleware/redirectLegacyURLs.js'; +import requestLog from './middleware/requestLog.js'; import staticFiles from './middleware/staticFiles.js'; import validateFilename from './middleware/validateFilename.js'; import validatePackageURL from './middleware/validatePackageURL.js'; @@ -32,8 +33,11 @@ export default function createServer() { app.enable('trust proxy'); app.enable('strict routing'); - app.use(logger); - app.use(cors); + if (process.env.NODE_ENV === 'development') { + app.use(morgan('dev')); + } + + app.use(cors()); app.use(staticFiles); // Special startup request from App Engine @@ -42,6 +46,8 @@ export default function createServer() { res.status(200).end(); }); + app.use(requestLog); + app.get('/', serveMainPage); app.get('/api/stats', serveStats); diff --git a/modules/middleware/cors.js b/modules/middleware/cors.js deleted file mode 100644 index aad115a..0000000 --- a/modules/middleware/cors.js +++ /dev/null @@ -1,5 +0,0 @@ -import corsMiddleware from 'cors'; - -const cors = corsMiddleware(); - -export default cors; diff --git a/modules/middleware/findEntry.js b/modules/middleware/findEntry.js index 0f0388d..86ca535 100644 --- a/modules/middleware/findEntry.js +++ b/modules/middleware/findEntry.js @@ -157,7 +157,7 @@ function searchEntries(stream, filename) { * Redirect to the "index" file if a directory was requested. */ async function findEntry(req, res, next) { - const stream = await getPackage(req.packageName, req.packageVersion); + const stream = await getPackage(req.packageName, req.packageVersion, req.log); const { foundEntry: entry, matchingEntries: entries } = await searchEntries( stream, req.filename diff --git a/modules/middleware/logger.js b/modules/middleware/logger.js deleted file mode 100644 index 74d020e..0000000 --- a/modules/middleware/logger.js +++ /dev/null @@ -1,15 +0,0 @@ -import morgan from 'morgan'; - -const logger = morgan( - process.env.NODE_ENV === 'development' - ? 'dev' - : ':date[clf] - :method :url :status :res[content-length] - :response-time ms', - { - skip: - process.env.NODE_ENV === 'production' - ? (req, res) => res.statusCode < 400 // Log only errors in production - : () => process.env.NODE_ENV === 'test' // Skip logging in test env - } -); - -export default logger; diff --git a/modules/middleware/requestLog.js b/modules/middleware/requestLog.js new file mode 100644 index 0000000..6102bf3 --- /dev/null +++ b/modules/middleware/requestLog.js @@ -0,0 +1,71 @@ +import util from 'util'; + +// https://cloud.google.com/appengine/docs/standard/nodejs/runtime#environment_variables +const projectId = process.env.GAE_APPLICATION; + +const enableDebugging = process.env.DEBUG != null; + +function noop() {} + +function createLog(req) { + const traceContext = req.headers['x-cloud-trace-context']; + + if (projectId && traceContext) { + const [traceId, spanId] = traceContext.split('/'); + const trace = `projects/${projectId}/traces/${traceId}`; + + return { + debug: enableDebugging + ? (format, ...args) => { + console.log( + JSON.stringify({ + severity: 'DEBUG', + 'logging.googleapis.com/trace': trace, + 'logging.googleapis.com/spanId': spanId, + message: util.format(format, ...args) + }) + ); + } + : noop, + info: (format, ...args) => { + console.log( + JSON.stringify({ + severity: 'INFO', + 'logging.googleapis.com/trace': trace, + 'logging.googleapis.com/spanId': spanId, + message: util.format(format, ...args) + }) + ); + }, + error: (format, ...args) => { + console.error( + JSON.stringify({ + severity: 'ERROR', + 'logging.googleapis.com/trace': trace, + 'logging.googleapis.com/spanId': spanId, + message: util.format(format, ...args) + }) + ); + } + }; + } + + return { + debug: enableDebugging + ? (format, ...args) => { + console.log(util.format(format, ...args)); + } + : noop, + info: (format, ...args) => { + console.log(util.format(format, ...args)); + }, + error: (format, ...args) => { + console.error(util.format(format, ...args)); + } + }; +} + +export default function requestLog(req, res, next) { + req.log = createLog(req); + next(); +} diff --git a/modules/middleware/validateVersion.js b/modules/middleware/validateVersion.js index bce343f..1a29d91 100644 --- a/modules/middleware/validateVersion.js +++ b/modules/middleware/validateVersion.js @@ -17,8 +17,8 @@ function semverRedirect(req, res, newVersion) { ); } -async function resolveVersion(packageName, range) { - const versionsAndTags = await getVersionsAndTags(packageName); +async function resolveVersion(packageName, range, log) { + const versionsAndTags = await getVersionsAndTags(packageName, log); if (versionsAndTags) { const { versions, tags } = versionsAndTags; @@ -41,7 +41,11 @@ async function resolveVersion(packageName, range) { * the resolved version number if necessary. */ async function validateVersion(req, res, next) { - const version = await resolveVersion(req.packageName, req.packageVersion); + const version = await resolveVersion( + req.packageName, + req.packageVersion, + req.log + ); if (!version) { return res @@ -56,7 +60,8 @@ async function validateVersion(req, res, next) { req.packageConfig = await getPackageConfig( req.packageName, - req.packageVersion + req.packageVersion, + req.log ); if (!req.packageConfig) { diff --git a/modules/utils/logging.js b/modules/utils/logging.js deleted file mode 100644 index f3fcbd5..0000000 --- a/modules/utils/logging.js +++ /dev/null @@ -1,5 +0,0 @@ -function noop() {} - -export const debug = process.env.DEBUG ? console.log.bind(console) : noop; -export const info = console.log.bind(console); -export const error = console.error.bind(console); diff --git a/modules/utils/npm.js b/modules/utils/npm.js index 8b33b4d..f625ba5 100644 --- a/modules/utils/npm.js +++ b/modules/utils/npm.js @@ -4,7 +4,6 @@ import gunzip from 'gunzip-maybe'; import LRUCache from 'lru-cache'; import bufferStream from './bufferStream.js'; -import * as log from './logging.js'; const npmRegistryURL = process.env.NPM_REGISTRY_URL || 'https://registry.npmjs.org'; @@ -41,7 +40,7 @@ function encodePackageName(packageName) { : encodeURIComponent(packageName); } -async function fetchPackageInfo(packageName) { +async function fetchPackageInfo(packageName, log) { const name = encodePackageName(packageName); const infoURL = `${npmRegistryURL}/${name}`; @@ -72,8 +71,8 @@ async function fetchPackageInfo(packageName) { return null; } -async function fetchVersionsAndTags(packageName) { - const info = await fetchPackageInfo(packageName); +async function fetchVersionsAndTags(packageName, log) { + const info = await fetchPackageInfo(packageName, log); return info && info.versions ? { versions: Object.keys(info.versions), tags: info['dist-tags'] } : null; @@ -83,7 +82,7 @@ async function fetchVersionsAndTags(packageName) { * Returns an object of available { versions, tags }. * Uses a cache to avoid over-fetching from the registry. */ -export async function getVersionsAndTags(packageName) { +export async function getVersionsAndTags(packageName, log) { const cacheKey = `versions-${packageName}`; const cacheValue = cache.get(cacheKey); @@ -91,7 +90,7 @@ export async function getVersionsAndTags(packageName) { return cacheValue === notFound ? null : JSON.parse(cacheValue); } - const value = await fetchVersionsAndTags(packageName); + const value = await fetchVersionsAndTags(packageName, log); if (value == null) { cache.set(cacheKey, notFound, 5 * oneMinute); @@ -126,8 +125,8 @@ function cleanPackageConfig(config) { }, {}); } -async function fetchPackageConfig(packageName, version) { - const info = await fetchPackageInfo(packageName); +async function fetchPackageConfig(packageName, version, log) { + const info = await fetchPackageInfo(packageName, log); return info && info.versions && version in info.versions ? cleanPackageConfig(info.versions[version]) : null; @@ -137,7 +136,7 @@ async function fetchPackageConfig(packageName, version) { * Returns metadata about a package, mostly the same as package.json. * Uses a cache to avoid over-fetching from the registry. */ -export async function getPackageConfig(packageName, version) { +export async function getPackageConfig(packageName, version, log) { const cacheKey = `config-${packageName}-${version}`; const cacheValue = cache.get(cacheKey); @@ -145,7 +144,7 @@ export async function getPackageConfig(packageName, version) { return cacheValue === notFound ? null : JSON.parse(cacheValue); } - const value = await fetchPackageConfig(packageName, version); + const value = await fetchPackageConfig(packageName, version, log); if (value == null) { cache.set(cacheKey, notFound, 5 * oneMinute); @@ -159,7 +158,7 @@ export async function getPackageConfig(packageName, version) { /** * Returns a stream of the tarball'd contents of the given package. */ -export async function getPackage(packageName, version) { +export async function getPackage(packageName, version, log) { const tarballName = isScopedPackageName(packageName) ? packageName.split('/')[1] : packageName;