Add request logging

app-staging.yaml

@@ -5,3 +5,4 @@ basic_scaling:
   max_instances: 1
 env_variables:
   NODE_ENV: 'staging'
+  DEBUG: 1

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) {
+async function getAvailableVersions(packageName, log) {
-  const versionsAndTags = await getVersionsAndTags(packageName);
+  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,

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);

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);

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) {

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) {

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);
+    if (process.env.NODE_ENV === 'development') {
-    app.use(cors);
+      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);
 

modules/middleware/cors.js

@@ -1,5 +0,0 @@
-import corsMiddleware from 'cors';
-
-const cors = corsMiddleware();
-
-export default cors;

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

modules/middleware/logger.js

@@ -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;

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();
+}

modules/middleware/validateVersion.js

@@ -17,8 +17,8 @@ function semverRedirect(req, res, newVersion) {
     );
 }
 
-async function resolveVersion(packageName, range) {
+async function resolveVersion(packageName, range, log) {
-  const versionsAndTags = await getVersionsAndTags(packageName);
+  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) {

modules/utils/logging.js

@@ -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);

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) {
+async function fetchVersionsAndTags(packageName, log) {
-  const info = await fetchPackageInfo(packageName);
+  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) {
+async function fetchPackageConfig(packageName, version, log) {
-  const info = await fetchPackageInfo(packageName);
+  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;