Merge pull request #1324 from bugsnag/aws-lambda-timeout-warning

Automatically notify when a lambda may timeout

packages/plugin-aws-lambda/src/index.js

@@ -1,5 +1,11 @@
 const bugsnagInFlight = require('@bugsnag/in-flight')
 const BugsnagPluginBrowserSession = require('@bugsnag/plugin-browser-session')
+const LambdaTimeoutApproaching = require('./lambda-timeout-approaching')
+
+// JS timers use a signed 32 bit integer for the millisecond parameter. SAM's
+// "local invoke" has a bug that means it exceeds this amount, resulting in
+// warnings. See https://github.com/aws/aws-sam-cli/issues/2519
+const MAX_TIMER_VALUE = Math.pow(2, 31) - 1
 
 const BugsnagPluginAwsLambda = {
   name: 'awsLambda',
@@ -32,14 +38,14 @@ const BugsnagPluginAwsLambda = {
     }
 
     return {
-      createHandler ({ flushTimeoutMs = 2000 } = {}) {
-        return wrapHandler.bind(null, client, flushTimeoutMs)
+      createHandler ({ flushTimeoutMs = 2000, lambdaTimeoutNotifyMs = 1000 } = {}) {
+        return wrapHandler.bind(null, client, flushTimeoutMs, lambdaTimeoutNotifyMs)
       }
     }
   }
 }
 
-function wrapHandler (client, flushTimeoutMs, handler) {
+function wrapHandler (client, flushTimeoutMs, lambdaTimeoutNotifyMs, handler) {
   let _handler = handler
 
   if (handler.length > 2) {
@@ -49,6 +55,38 @@ function wrapHandler (client, flushTimeoutMs, handler) {
   }
 
   return async function (event, context) {
+    let lambdaTimeout
+
+    // Guard against the "getRemainingTimeInMillis" being missing. This should
+    // never happen but could when unit testing
+    if (typeof context.getRemainingTimeInMillis === 'function' &&
+      lambdaTimeoutNotifyMs > 0
+    ) {
+      const timeoutMs = context.getRemainingTimeInMillis() - lambdaTimeoutNotifyMs
+
+      if (timeoutMs <= MAX_TIMER_VALUE) {
+        lambdaTimeout = setTimeout(function () {
+          const handledState = {
+            severity: 'warning',
+            unhandled: true,
+            severityReason: { type: 'log' }
+          }
+
+          const event = client.Event.create(
+            new LambdaTimeoutApproaching(context.getRemainingTimeInMillis()),
+            true,
+            handledState,
+            'aws lambda plugin',
+            0
+          )
+
+          event.context = context.functionName || 'Lambda timeout approaching'
+
+          client._notify(event)
+        }, timeoutMs)
+      }
+    }
+
     client.addMetadata('AWS Lambda context', context)
 
     if (client._config.autoTrackSessions) {
@@ -72,6 +110,10 @@ function wrapHandler (client, flushTimeoutMs, handler) {
 
       throw err
     } finally {
+      if (lambdaTimeout) {
+        clearTimeout(lambdaTimeout)
+      }
+
       try {
         await bugsnagInFlight.flush(flushTimeoutMs)
       } catch (err) {

packages/plugin-aws-lambda/src/lambda-timeout-approaching.js

@@ -0,0 +1,10 @@
+module.exports = class LambdaTimeoutApproaching extends Error {
+  constructor (remainingMs) {
+    const message = `Lambda will timeout in ${remainingMs}ms`
+
+    super(message)
+
+    this.name = 'LambdaTimeoutApproaching'
+    this.stack = []
+  }
+}

packages/plugin-aws-lambda/test/index.test.ts

@@ -24,6 +24,16 @@ const createClient = (events: EventDeliveryPayload[], sessions: SessionDeliveryP
   return client
 }
 
+const DEFAULT_REMAINING_MS = 250
+let getRemainingTimeInMillis: jest.MockedFunction<() => number>
+
+beforeEach(() => {
+  getRemainingTimeInMillis = jest.fn()
+    .mockReturnValueOnce(DEFAULT_REMAINING_MS)
+    .mockReturnValueOnce(DEFAULT_REMAINING_MS / 2)
+    .mockImplementationOnce(() => { throw new Error('unexpected call to "getRemainingTimeInMillis"') })
+})
+
 describe('plugin: aws lambda', () => {
   it('has a name', () => {
     expect(BugsnagPluginAwsLambda.name).toBe('awsLambda')
@@ -514,4 +524,215 @@ describe('plugin: aws lambda', () => {
     expect(events).toHaveLength(0)
     expect(sessions).toHaveLength(0)
   })
+
+  it('notifies when it is close to timing out (async)', async () => {
+    const events: EventDeliveryPayload[] = []
+    const sessions: SessionDeliveryPayload[] = []
+
+    const client = createClient(events, sessions)
+
+    const handler = async (event: any, context: any) => new Promise(resolve => {
+      setTimeout(() => resolve('xyz'), DEFAULT_REMAINING_MS + 100)
+    })
+
+    const event = { very: 'eventy' }
+    const context = { extremely: 'contextual', getRemainingTimeInMillis }
+
+    const plugin = client.getPlugin('awsLambda')
+
+    if (!plugin) {
+      throw new Error('Plugin was not loaded!')
+    }
+
+    const bugsnagHandler = plugin.createHandler()
+    const wrappedHandler = bugsnagHandler(handler)
+
+    expect(events).toHaveLength(0)
+    expect(sessions).toHaveLength(0)
+
+    expect(await wrappedHandler(event, context)).toBe('xyz')
+
+    expect(events).toHaveLength(1)
+    expect(events[0].events).toHaveLength(1)
+    expect(events[0].events[0].errors).toHaveLength(1)
+    expect(events[0].events[0].context).toBe('Lambda timeout approaching')
+
+    const expectedError = {
+      errorClass: 'LambdaTimeoutApproaching',
+      errorMessage: `Lambda will timeout in ${DEFAULT_REMAINING_MS / 2}ms`,
+      stacktrace: [],
+      type: 'nodejs'
+    }
+
+    expect(events[0].events[0].errors[0]).toEqual(expectedError)
+
+    expect(sessions).toHaveLength(1)
+  })
+
+  it('notifies when it is close to timing out (callback)', async () => {
+    const events: EventDeliveryPayload[] = []
+    const sessions: SessionDeliveryPayload[] = []
+
+    const client = createClient(events, sessions)
+
+    const handler = (event: any, context: any, callback: any) => new Promise(resolve => {
+      setTimeout(() => callback(null, 'xyz'), DEFAULT_REMAINING_MS + 100)
+    })
+
+    const event = { very: 'eventy' }
+    const context = { extremely: 'contextual', getRemainingTimeInMillis }
+
+    const plugin = client.getPlugin('awsLambda')
+
+    if (!plugin) {
+      throw new Error('Plugin was not loaded!')
+    }
+
+    const bugsnagHandler = plugin.createHandler()
+    const wrappedHandler = bugsnagHandler(handler)
+
+    expect(events).toHaveLength(0)
+    expect(sessions).toHaveLength(0)
+
+    expect(await wrappedHandler(event, context)).toBe('xyz')
+
+    expect(events).toHaveLength(1)
+    expect(events[0].events).toHaveLength(1)
+    expect(events[0].events[0].errors).toHaveLength(1)
+    expect(events[0].events[0].context).toBe('Lambda timeout approaching')
+
+    const expectedError = {
+      errorClass: 'LambdaTimeoutApproaching',
+      errorMessage: `Lambda will timeout in ${DEFAULT_REMAINING_MS / 2}ms`,
+      stacktrace: [],
+      type: 'nodejs'
+    }
+
+    expect(events[0].events[0].errors[0]).toEqual(expectedError)
+
+    expect(sessions).toHaveLength(1)
+  })
+
+  it('uses the function name as the event context when present', async () => {
+    const events: EventDeliveryPayload[] = []
+    const sessions: SessionDeliveryPayload[] = []
+
+    const client = createClient(events, sessions)
+
+    const handler = async (event: any, context: any) => new Promise(resolve => {
+      setTimeout(() => resolve('xyz'), DEFAULT_REMAINING_MS + 100)
+    })
+
+    const event = { very: 'eventy' }
+    const context = { functionName: 'MyCoolAndGoodLambdaFunction', getRemainingTimeInMillis }
+
+    const plugin = client.getPlugin('awsLambda')
+
+    if (!plugin) {
+      throw new Error('Plugin was not loaded!')
+    }
+
+    const bugsnagHandler = plugin.createHandler()
+    const wrappedHandler = bugsnagHandler(handler)
+
+    expect(events).toHaveLength(0)
+    expect(sessions).toHaveLength(0)
+
+    expect(await wrappedHandler(event, context)).toBe('xyz')
+
+    expect(events).toHaveLength(1)
+    expect(events[0].events[0].errors[0].errorClass).toBe('LambdaTimeoutApproaching')
+    expect(events[0].events[0].errors[0].errorMessage).toBe(`Lambda will timeout in ${DEFAULT_REMAINING_MS / 2}ms`)
+    expect(events[0].events[0].errors[0].stacktrace).toHaveLength(0)
+    expect(events[0].events[0].context).toBe('MyCoolAndGoodLambdaFunction')
+
+    expect(sessions).toHaveLength(1)
+  })
+
+  it('allows the "lambdaTimeoutNotifyMs" to be changed', async () => {
+    // With 6 seconds remaining and a resolve timeout of 500ms, the timeout
+    // warning will never be triggered unless the custom "lambdaTimeoutNotifyMs"
+    // takes effect
+    const superLongWaitMs = 6000
+    const resolveTimeoutMs = 500
+    const lambdaTimeoutNotifyMs = superLongWaitMs - (resolveTimeoutMs / 2)
+
+    getRemainingTimeInMillis = jest.fn()
+      .mockReturnValueOnce(superLongWaitMs)
+      .mockReturnValueOnce(superLongWaitMs - lambdaTimeoutNotifyMs)
+      .mockImplementationOnce(() => { throw new Error('unexpected call to "getRemainingTimeInMillis"') })
+
+    const events: EventDeliveryPayload[] = []
+    const sessions: SessionDeliveryPayload[] = []
+
+    const client = createClient(events, sessions)
+
+    const handler = async (event: any, context: any) => new Promise(resolve => {
+      setTimeout(() => resolve('xyz'), resolveTimeoutMs)
+    })
+
+    const event = { very: 'eventy' }
+    const context = { extremely: 'contextual', getRemainingTimeInMillis }
+
+    const plugin = client.getPlugin('awsLambda')
+
+    if (!plugin) {
+      throw new Error('Plugin was not loaded!')
+    }
+
+    const bugsnagHandler = plugin.createHandler({ lambdaTimeoutNotifyMs })
+    const wrappedHandler = bugsnagHandler(handler)
+
+    expect(events).toHaveLength(0)
+    expect(sessions).toHaveLength(0)
+
+    expect(await wrappedHandler(event, context)).toBe('xyz')
+
+    expect(events).toHaveLength(1)
+    expect(events[0].events).toHaveLength(1)
+    expect(events[0].events[0].errors).toHaveLength(1)
+    expect(events[0].events[0].context).toBe('Lambda timeout approaching')
+
+    const expectedError = {
+      errorClass: 'LambdaTimeoutApproaching',
+      errorMessage: `Lambda will timeout in ${resolveTimeoutMs / 2}ms`,
+      stacktrace: [],
+      type: 'nodejs'
+    }
+
+    expect(events[0].events[0].errors[0]).toEqual(expectedError)
+
+    expect(sessions).toHaveLength(1)
+  })
+
+  it('does not notify if "lambdaTimeoutNotifyMs" is 0', async () => {
+    const events: EventDeliveryPayload[] = []
+    const sessions: SessionDeliveryPayload[] = []
+
+    const client = createClient(events, sessions)
+
+    const handler = async (event: any, context: any) => new Promise(resolve => {
+      setTimeout(() => resolve('xyz'), 100)
+    })
+
+    const event = { very: 'eventy' }
+    const context = { extremely: 'contextual', getRemainingTimeInMillis }
+
+    const plugin = client.getPlugin('awsLambda')
+
+    if (!plugin) {
+      throw new Error('Plugin was not loaded!')
+    }
+
+    const bugsnagHandler = plugin.createHandler({ lambdaTimeoutNotifyMs: 0 })
+    const wrappedHandler = bugsnagHandler(handler)
+
+    expect(events).toHaveLength(0)
+    expect(sessions).toHaveLength(0)
+
+    expect(await wrappedHandler(event, context)).toBe('xyz')
+
+    expect(events).toHaveLength(0)
+    expect(sessions).toHaveLength(1)
+  })
 })

packages/plugin-aws-lambda/types/bugsnag-plugin-aws-lambda.d.ts

@@ -10,6 +10,7 @@ export type BugsnagPluginAwsLambdaHandler = (handler: AsyncHandler|CallbackHandl
 
 export interface BugsnagPluginAwsLambdaConfiguration {
   flushTimeoutMs?: number
+  lambdaTimeoutNotifyMs?: number
 }
 
 export interface BugsnagPluginAwsLambdaResult {