Add timeout and abort middleware and processing halts (#18177)

* Add middleware to timeout requests after a period

* Add halt-on-dropped-connection middleware to stop the middleware processing stack if the connection was already dropped

* Add a few strategic bail-out spots for dropped connections during the render-page middleware

* Handle 404s and HEAD requests earlier in the page rendering flow

* Add a few more strategic bail-out spots for dropped connections during the render-page middleware

* Add middleware to notice aborted requests

* Add a check for aborted requests into the isConnectionDropped logic

* Reformat comment for consistency

* Handle aborted requests correctly in the error handler

* Explicit returns for consistency

middleware/abort.js

@@ -0,0 +1,15 @@
+module.exports = function (req, res, next) {
+  // If the client aborts the connection, send an error
+  req.once('aborted', () => {
+    // NOTE: Node.js will also automatically set `req.aborted = true`
+
+    const abortError = new Error('Client closed request')
+    abortError.statusCode = 499
+    abortError.code = 'ECONNRESET'
+
+    // Pass the error to the Express error handler
+    return next(abortError)
+  })
+
+  return next()
+}

middleware/halt-on-dropped-connection.js

@@ -0,0 +1,18 @@
+function isConnectionDropped (req, res) {
+  // Have the flags been set for:
+  //  - a global request timeout (via the express-timeout-handler middleware)?
+  //  - an aborted request connection (via Node.js core's HTTP IncomingMessage)?
+  return Boolean(res.globalTimeout || req.aborted)
+}
+
+function haltOnDroppedConnection (req, res, next) {
+  // Only proceed if the flag has not been set for the express-timeout-handler middleware
+  if (!isConnectionDropped(req, res)) {
+    return next()
+  }
+}
+
+// Export this logic, too
+haltOnDroppedConnection.isConnectionDropped = isConnectionDropped
+
+module.exports = haltOnDroppedConnection

middleware/handle-errors.js

@@ -6,7 +6,9 @@ const loadSiteData = require('../lib/site-data')
 function shouldLogException (error) {
   const IGNORED_ERRORS = [
     // avoid sending CSRF token errors (from bad-actor POST requests)
-    'EBADCSRFTOKEN'
+    'EBADCSRFTOKEN',
+    // Client connected aborted
+    'ECONNRESET'
   ]
 
   if (IGNORED_ERRORS.includes(error.code)) {
@@ -26,8 +28,8 @@ async function logException (error, req) {
 }
 
 module.exports = async function handleError (error, req, res, next) {
-  // If the headers have already been sent...
+  // If the headers have already been sent or the request was aborted...
-  if (res.headersSent) {
+  if (res.headersSent || req.aborted) {
     // Report to Failbot
     await logException(error, req)
 

middleware/index.js

@@ -1,5 +1,6 @@
 const express = require('express')
 const instrument = require('../lib/instrument-middleware')
+const haltOnDroppedConnection = require('./halt-on-dropped-connection')
 
 const isDevelopment = process.env.NODE_ENV === 'development'
 
@@ -11,6 +12,10 @@ const asyncMiddleware = fn =>
   }
 
 module.exports = function (app) {
+  // *** Request connection management ***
+  app.use(require('./timeout'))
+  app.use(require('./abort'))
+
   // *** Development tools ***
   app.use(require('morgan')('dev', { skip: (req, res) => !isDevelopment }))
   if (isDevelopment) app.use(require('./webpack'))
@@ -60,6 +65,9 @@ module.exports = function (app) {
   app.use(instrument('./find-page')) // Must come before archived-enterprise-versions, breadcrumbs, featured-links, products, render-page
   app.use(instrument('./block-robots'))
 
+  // Check for a dropped connection before proceeding
+  app.use(haltOnDroppedConnection)
+
   // *** Rendering, 2xx responses ***
   // I largely ordered these by use frequency
   app.use(instrument('./archived-enterprise-versions-assets')) // Must come before static/assets
@@ -91,6 +99,9 @@ module.exports = function (app) {
   app.use(instrument('./loaderio-verification'))
   app.get('/_500', asyncMiddleware(instrument('./trigger-error')))
 
+  // Check for a dropped connection before proceeding (again)
+  app.use(haltOnDroppedConnection)
+
   // *** Preparation for render-page ***
   app.use(asyncMiddleware(instrument('./contextualizers/enterprise-release-notes')))
   app.use(instrument('./contextualizers/graphql'))
@@ -106,7 +117,12 @@ module.exports = function (app) {
   // *** Headers for pages only ***
   app.use(require('./set-fastly-cache-headers'))
 
-  // *** Rendering, must go last ***
+  // Check for a dropped connection before proceeding (again)
+  app.use(haltOnDroppedConnection)
+
+  // *** Rendering, must go almost last ***
   app.get('/*', asyncMiddleware(instrument('./render-page')))
+
+  // *** Error handling, must go last ***
   app.use(require('./handle-errors'))
 }

middleware/render-page.js

@@ -6,6 +6,7 @@ const getMiniTocItems = require('../lib/get-mini-toc-items')
 const Page = require('../lib/page')
 const statsd = require('../lib/statsd')
 const RedisAccessor = require('../lib/redis-accessor')
+const { isConnectionDropped } = require('./halt-on-dropped-connection')
 
 const { HEROKU_RELEASE_VERSION } = process.env
 const pageCacheDatabaseNumber = 1
@@ -28,31 +29,6 @@ function addCsrf (req, text) {
 module.exports = async function renderPage (req, res, next) {
   const page = req.context.page
 
-  // Remove any query string (?...) and/or fragment identifier (#...)
-  const { pathname, searchParams } = new URL(req.originalUrl, 'https://docs.github.com')
-
-  for (const queryKey in req.query) {
-    if (!cacheableQueries.includes(queryKey)) {
-      searchParams.delete(queryKey)
-    }
-  }
-  const originalUrl = pathname + ([...searchParams].length > 0 ? `?${searchParams}` : '')
-
-  // Serve from the cache if possible (skip during tests)
-  const isCacheable = !process.env.CI && process.env.NODE_ENV !== 'test' && req.method === 'GET'
-
-  // Is the request for JSON debugging info?
-  const isRequestingJsonForDebugging = 'json' in req.query && process.env.NODE_ENV !== 'production'
-
-  if (isCacheable && !isRequestingJsonForDebugging) {
-    const cachedHtml = await pageCache.get(originalUrl)
-    if (cachedHtml) {
-      console.log(`Serving from cached version of ${originalUrl}`)
-      statsd.increment('page.sent_from_cache')
-      return res.send(addCsrf(req, cachedHtml))
-    }
-  }
-
   // render a 404 page
   if (!page) {
     if (process.env.NODE_ENV !== 'test' && req.context.redirectNotFound) {
@@ -70,15 +46,52 @@ module.exports = async function renderPage (req, res, next) {
     return res.status(200).end()
   }
 
+  // Remove any query string (?...) and/or fragment identifier (#...)
+  const { pathname, searchParams } = new URL(req.originalUrl, 'https://docs.github.com')
+
+  for (const queryKey in req.query) {
+    if (!cacheableQueries.includes(queryKey)) {
+      searchParams.delete(queryKey)
+    }
+  }
+  const originalUrl = pathname + ([...searchParams].length > 0 ? `?${searchParams}` : '')
+
+  // Serve from the cache if possible (skip during tests)
+  const isCacheable = !process.env.CI && process.env.NODE_ENV !== 'test' && req.method === 'GET'
+
+  // Is the request for JSON debugging info?
+  const isRequestingJsonForDebugging = 'json' in req.query && process.env.NODE_ENV !== 'production'
+
+  if (isCacheable && !isRequestingJsonForDebugging) {
+    // Stop processing if the connection was already dropped
+    if (isConnectionDropped(req, res)) return
+
+    const cachedHtml = await pageCache.get(originalUrl)
+    if (cachedHtml) {
+      // Stop processing if the connection was already dropped
+      if (isConnectionDropped(req, res)) return
+
+      console.log(`Serving from cached version of ${originalUrl}`)
+      statsd.increment('page.sent_from_cache')
+      return res.send(addCsrf(req, cachedHtml))
+    }
+  }
+
   // add page context
   const context = Object.assign({}, req.context, { page })
 
   // collect URLs for variants of this page in all languages
   context.page.languageVariants = Page.getLanguageVariants(req.path)
 
+  // Stop processing if the connection was already dropped
+  if (isConnectionDropped(req, res)) return
+
   // render page
   context.renderedPage = await page.render(context)
 
+  // Stop processing if the connection was already dropped
+  if (isConnectionDropped(req, res)) return
+
   // get mini TOC items on articles
   if (page.showMiniToc) {
     context.miniTocItems = getMiniTocItems(context.renderedPage, page.miniTocMaxHeadingLevel)

middleware/timeout.js

@@ -0,0 +1,27 @@
+const timeout = require('express-timeout-handler')
+
+// Heroku router requests timeout after 30 seconds. We should stop them earlier!
+const maxRequestTimeout = parseInt(process.env.REQUEST_TIMEOUT, 10) || 25000
+
+module.exports = timeout.handler({
+  // Default timeout for all endpoints
+  // To override for a given router/endpoint, use `require('express-timeout-handler').set(...)`
+  timeout: maxRequestTimeout,
+
+  // IMPORTANT:
+  // We cannot allow the middleware to disable the `res` object's methods like
+  // it does by default if we want to use `next` in the `onTimeout` handler!
+  disable: [],
+
+  onTimeout: function (req, res, next) {
+    // Create a custom timeout error
+    const timeoutError = new Error('Request timed out')
+    timeoutError.statusCode = 503
+    timeoutError.code = 'ETIMEDOUT'
+
+    // Pass the error to our Express error handler for consolidated processing
+    return next(timeoutError)
+  }
+
+  // Can also set an `onDelayedResponse` property IF AND ONLY IF you allow for disabling methods
+})

package-lock.json

@@ -10914,6 +10914,11 @@
       "resolved": "https://registry.npmjs.org/express-rate-limit/-/express-rate-limit-5.1.3.tgz",
       "integrity": "sha512-TINcxve5510pXj4n9/1AMupkj3iWxl3JuZaWhCdYDlZeoCPqweGZrxbrlqTCFb1CT5wli7s8e2SH/Qz2c9GorA=="
     },
+    "express-timeout-handler": {
+      "version": "2.2.0",
+      "resolved": "https://registry.npmjs.org/express-timeout-handler/-/express-timeout-handler-2.2.0.tgz",
+      "integrity": "sha512-Ae9M32r3T+RmrY1MGwBvyVjnzVo1iD4s0YQHgvJqzPlT0d4qS84pr87LHyiUtnD7qDQLMYw6rl2fhsgH4TH8aQ=="
+    },
     "ext": {
       "version": "1.4.0",
       "resolved": "https://registry.npmjs.org/ext/-/ext-1.4.0.tgz",

package.json

@@ -43,6 +43,7 @@
     "dotenv": "^8.2.0",
     "express": "^4.17.1",
     "express-rate-limit": "^5.1.3",
+    "express-timeout-handler": "^2.2.0",
     "flat": "^5.0.0",
     "github-slugger": "^1.2.1",
     "got": "^9.6.0",