search

Sparticuz / chrome-aws-lambda

This package has been deprecated in favor of @sparticuz/chromium
https://www.github.com/sparticuz/chromium
MIT License
139 stars 21 forks source link

[BUG] browser.close() does not resolve on Docker container `node:14` #9

Closed jandppw closed 2 years ago

jandppw commented 2 years ago

Environment

Expected Behavior

await browser.close() should resolve

Current Behavior

await browser.close() does not resolve

Steps to Reproduce

Thank you very much, @sparticuz, for picking up from @alixaxel.

I have been using the last version of the original chrome-aws-lambda for about 2 years now (10.1.0). Automated tests with mocha run, and among other things, start up a browser, and finally, after all tests have run, close that browser. These tests run locally (macOS, Windows) and on Bitbucket Pipelines, in a Node Docker container.

I am now trying to switch to your fork so we can evolve with Chromium and Puppeteer.

All tests still run fine on macOS, and in Bitbucket Pipelines, in the node:14 Docker container, and all tests pass, both with chrome-aws-lambda@10.1.0 and /@sparticuz/chrome-aws-lambda@14.3.0 (not tested on Windows lately).

Yet, with chrome-aws-lambda@10.1.0 the browser used for the tests closes finally. With /@sparticuz/chrome-aws-lambda@14.3.0, it does not.

The relevant Bitbucket Pipelines step definition is:

[…]
definitions:
  caches:
    npm14: ~/.npm
  steps:
[…]
    - step: &test
        name: Node 14
        max-time: 15
        image: node:14
        caches:
          - npm14
        script:
          # install Chromium dependencies (https://bitbucket.org/bitbucketpipelines/example-chromium-headless-puppeteer/src/master/bitbucket-pipelines.yml)
          - apt-get update && apt-get install -yq libgconf-2-4
          - >
            apt-get update && apt-get install -y wget --no-install-recommends && \
               wget -q -O - https://dl-ssl.google.com/linux/linux_signing_key.pub | apt-key add -  && \
               sh -c 'echo "deb [arch=amd64] http://dl.google.com/linux/chrome/deb/ stable main" >> /etc/apt/sources.list.d/google.list' && \
               apt-get update && \
               apt-get install -y google-chrome-unstable fonts-ipafont-gothic fonts-wqy-zenhei fonts-thai-tlwg fonts-kacst ttf-freefont --no-install-recommends
          - npm ci
          - npm test

The test script is:

[…]
  "scripts": {
[…]
    "test": "standard && nyc mocha \"test/unit/{*,**/*}.test.js\"",
[…]
  },
[…]

In the mocha configuration, a global afterAll is set up:

[…]
  "mocha": {
[…]
    "require": [
[…]
      "./test/_killChromium"
    ],
[…]
  },
[…]

which is:

const { ensureBrowserClosed } = require('../lib/pdf/browser')

exports.mochaHooks = {
  async afterAll () {
    console.log('all tests done; closing remaining chromium processes')
    await ensureBrowserClosed()
    console.log('all remaining chromium processes closed')
  }
}

The code that (should) close the browser (and did so with chrome-aws-lambda@10.1.0) is ensureBrowserClosed:

const { puppeteer, args, defaultViewport, executablePath, font } = require('@sparticuz/chrome-aws-lambda')
const log = require('../ppwcode/simpleLog')
const assert = require('assert')
const { join } = require('path')

const fontVariants = ['Bold', 'BoldItalic', 'Italic', 'Regular']
const fontBasePath = join(__dirname, 'fonts')
const fontFilePaths = fontVariants.map(fv => join(fontBasePath, `Roboto/Roboto-${fv}.ttf`))

/**
 * @type {Promise<Browser>}
 */
let getBrowserPromise

/**
 * Robust definition of a running puppeteer browser, shared for the entire run of the lambda instance.
 *
 * (Not declared async, because we do no want to wrap the returned Promise in a secondary Promise).
 *
 * Whether we run with or without a sandbox is determined by the environment we run in. See
 * [Puppeteer As Lambda Layer; Launching a Chromium instance](../../PuppeteerAsLambdaLayer.md).
 *
 * @param {UUID} flowId
 * @return {Promise<Browser>}
 */
function getBrowser (flowId) {
  assert(flowId)

  async function launchAndReport () {
    const environment = process.env.CI
      ? 'bitbucket'
      : process.env.LAMBDA_TASK_ROOT && process.env.AWS_EXECUTION_ENV
        ? 'lambda'
        : 'development'
    const noSandbox = ['bitbucket', 'lambda'].includes(environment)
    log.info(module, 'getBrowser#launchAndReport', flowId, 'ENVIRONMENT_DETERMINED', { environment, noSandbox })
    log.info(module, 'getBrowser#launchAndReport', flowId, 'ADDING_FONTS', { fontFilePaths })
    const appliedFonts = await Promise.all(fontFilePaths.map(/* istanbul ignore next */ f => font(f)))
    log.info(module, 'getBrowser#launchAndReport', flowId, 'FONTS_ADDED', { appliedFonts })
    const launchOptions = {
      executablePath: await executablePath,
      args: noSandbox ? args : args.filter(a => a !== '--no-sandbox'),
      defaultViewport,
      headless: true
    }
    log.info(module, 'getBrowser#launchAndReport', flowId, 'LAUNCHING_BROWSER', { launchOptions })
    const browser = await puppeteer.launch(launchOptions)
    const [version, userAgent] = await Promise.all([browser.version(), browser.userAgent()])
    log.info(module, 'getBrowser#launchAndReport', flowId, 'NOMINAL_END', { version, userAgent })
    return browser
  }

  log.info(module, 'getBrowser', flowId, 'CALLED')
  if (!getBrowserPromise) {
    getBrowserPromise = launchAndReport()
  }
  log.info(module, 'getBrowser', flowId, 'NOMINAL_END')
  return getBrowserPromise
}

/**
 * If a Browser was started, make sure it is closed.
 *
 * @param {UUID} flowId
 * @return {Promise<void>}
 */
async function ensureBrowserClosed (flowId) {
  log.info(module, 'ensureBrowserClosed', flowId, 'CALLED')
  if (getBrowserPromise) {
    log.info(module, 'ensureBrowserClosed', flowId, 'FOUND_BROWSER_PROMISE')
    const promise = getBrowserPromise
    getBrowserPromise = undefined
    log.info(module, 'ensureBrowserClosed', flowId, 'DISCARDED_BROWSER_PROMISE')
    const browser = await promise
    log.info(module, 'ensureBrowserClosed', flowId, 'BROWSER_PROMISE_RESOLVED')
    await browser.close()
    log.info(module, 'ensureBrowserClosed', flowId, 'BROWSER_CLOSED')
  }
  log.info(module, 'ensureBrowserClosed', flowId, 'NOMINAL_END')
}

/**
 * Robust definition of a running puppeteer browser, shared for the entire run of the lambda instance.
 */
module.exports = { getBrowser, ensureBrowserClosed }

The relevant output we when the tests are run on macOS is:

{"lambda":{"instanceId":"2bb7897b-e17e-40e8-bf33-6a494067c0c7"},"flowId":"91b5ee9c-632d-4af4-8154-ddd2490bf677","now":1655121437191,"level":"INFO","module":"/Users/jand/Scratchpad/ecachim/pictoperfect-documents-server/lib/pdf/browser.js","function":"getBrowser","phase":"CALLED"}
{"lambda":{"instanceId":"2bb7897b-e17e-40e8-bf33-6a494067c0c7"},"flowId":"91b5ee9c-632d-4af4-8154-ddd2490bf677","now":1655121437191,"level":"INFO","module":"/Users/jand/Scratchpad/ecachim/pictoperfect-documents-server/lib/pdf/browser.js","function":"getBrowser#launchAndReport","phase":"ENVIRONMENT_DETERMINED","details":{"environment":"development","noSandbox":false}}
{"lambda":{"instanceId":"2bb7897b-e17e-40e8-bf33-6a494067c0c7"},"flowId":"91b5ee9c-632d-4af4-8154-ddd2490bf677","now":1655121437191,"level":"INFO","module":"/Users/jand/Scratchpad/ecachim/pictoperfect-documents-server/lib/pdf/browser.js","function":"getBrowser#launchAndReport","phase":"ADDING_FONTS","details":{"fontFilePaths":["/Users/jand/Scratchpad/ecachim/pictoperfect-documents-server/lib/pdf/fonts/Roboto/Roboto-Bold.ttf","/Users/jand/Scratchpad/ecachim/pictoperfect-documents-server/lib/pdf/fonts/Roboto/Roboto-BoldItalic.ttf","/Users/jand/Scratchpad/ecachim/pictoperfect-documents-server/lib/pdf/fonts/Roboto/Roboto-Italic.ttf","/Users/jand/Scratchpad/ecachim/pictoperfect-documents-server/lib/pdf/fonts/Roboto/Roboto-Regular.ttf"]}}
{"lambda":{"instanceId":"2bb7897b-e17e-40e8-bf33-6a494067c0c7"},"flowId":"91b5ee9c-632d-4af4-8154-ddd2490bf677","now":1655121437191,"level":"INFO","module":"/Users/jand/Scratchpad/ecachim/pictoperfect-documents-server/lib/pdf/browser.js","function":"getBrowser","phase":"NOMINAL_END"}
{"lambda":{"instanceId":"2bb7897b-e17e-40e8-bf33-6a494067c0c7"},"flowId":"91b5ee9c-632d-4af4-8154-ddd2490bf677","now":1655121437191,"level":"INFO","module":"/Users/jand/Scratchpad/ecachim/pictoperfect-documents-server/lib/pdf/browser.js","function":"getBrowser","phase":"CALLED"}
{"lambda":{"instanceId":"2bb7897b-e17e-40e8-bf33-6a494067c0c7"},"flowId":"91b5ee9c-632d-4af4-8154-ddd2490bf677","now":1655121437192,"level":"INFO","module":"/Users/jand/Scratchpad/ecachim/pictoperfect-documents-server/lib/pdf/browser.js","function":"getBrowser","phase":"NOMINAL_END"}
[… repeats for a number of tests …]
{"lambda":{"instanceId":"2bb7897b-e17e-40e8-bf33-6a494067c0c7"},"flowId":"91b5ee9c-632d-4af4-8154-ddd2490bf677","now":1655121437193,"level":"INFO","module":"/Users/jand/Scratchpad/ecachim/pictoperfect-documents-server/lib/pdf/browser.js","function":"getBrowser#launchAndReport","phase":"FONTS_ADDED","details":{"appliedFonts":[null,null,null,null]}}
{"lambda":{"instanceId":"2bb7897b-e17e-40e8-bf33-6a494067c0c7"},"flowId":"91b5ee9c-632d-4af4-8154-ddd2490bf677","now":1655121437193,"level":"INFO","module":"/Users/jand/Scratchpad/ecachim/pictoperfect-documents-server/lib/pdf/browser.js","function":"getBrowser#launchAndReport","phase":"LAUNCHING_BROWSER","details":{"launchOptions":{"executablePath":null,"args":["--allow-running-insecure-content","--autoplay-policy=user-gesture-required","--disable-component-update","--disable-domain-reliability","--disable-features=AudioServiceOutOfProcess,IsolateOrigins,site-per-process","--disable-print-preview","--disable-setuid-sandbox","--disable-site-isolation-trials","--disable-speech-api","--disable-web-security","--disk-cache-size=33554432","--enable-features=SharedArrayBuffer","--hide-scrollbars","--ignore-gpu-blocklist","--in-process-gpu","--mute-audio","--no-default-browser-check","--no-pings","--no-zygote","--use-gl=angle","--use-angle=swiftshader","--window-size=1920,1080","--start-maximized"],"defaultViewport":{"deviceScaleFactor":1,"hasTouch":false,"height":1080,"isLandscape":true,"isMobile":false,"width":1920},"headless":true}}}
{"lambda":{"instanceId":"2bb7897b-e17e-40e8-bf33-6a494067c0c7"},"flowId":"91b5ee9c-632d-4af4-8154-ddd2490bf677","now":1655121439582,"level":"INFO","module":"/Users/jand/Scratchpad/ecachim/pictoperfect-documents-server/lib/pdf/browser.js","function":"getBrowser#launchAndReport","phase":"NOMINAL_END","details":{"version":"HeadlessChrome/103.0.5058.0","userAgent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) HeadlessChrome/103.0.5058.0 Safari/537.36"}}
{"lambda":{"instanceId":"2bb7897b-e17e-40e8-bf33-6a494067c0c7"},"flowId":"91b5ee9c-632d-4af4-8154-ddd2490bf677","now":1655121439583,"level":"INFO","module":"/Users/jand/Scratchpad/ecachim/pictoperfect-documents-server/lib/pdf/browser.js","function":"getBrowser","phase":"CALLED"}
{"lambda":{"instanceId":"2bb7897b-e17e-40e8-bf33-6a494067c0c7"},"flowId":"91b5ee9c-632d-4af4-8154-ddd2490bf677","now":1655121439583,"level":"INFO","module":"/Users/jand/Scratchpad/ecachim/pictoperfect-documents-server/lib/pdf/browser.js","function":"getBrowser","phase":"NOMINAL_END"}
[… repeats some more …]

[… tests …]

all tests done; closing remaining chromium processes
{"lambda":{"instanceId":"2bb7897b-e17e-40e8-bf33-6a494067c0c7"},"flowId":"91b5ee9c-632d-4af4-8154-ddd2490bf677","now":1655121439813,"level":"INFO","module":"/Users/jand/Scratchpad/ecachim/pictoperfect-documents-server/lib/pdf/browser.js","function":"ensureBrowserClosed","phase":"CALLED"}
{"lambda":{"instanceId":"2bb7897b-e17e-40e8-bf33-6a494067c0c7"},"flowId":"91b5ee9c-632d-4af4-8154-ddd2490bf677","now":1655121439813,"level":"INFO","module":"/Users/jand/Scratchpad/ecachim/pictoperfect-documents-server/lib/pdf/browser.js","function":"ensureBrowserClosed","phase":"FOUND_BROWSER_PROMISE"}
{"lambda":{"instanceId":"2bb7897b-e17e-40e8-bf33-6a494067c0c7"},"flowId":"91b5ee9c-632d-4af4-8154-ddd2490bf677","now":1655121439813,"level":"INFO","module":"/Users/jand/Scratchpad/ecachim/pictoperfect-documents-server/lib/pdf/browser.js","function":"ensureBrowserClosed","phase":"DISCARDED_BROWSER_PROMISE"}
{"lambda":{"instanceId":"2bb7897b-e17e-40e8-bf33-6a494067c0c7"},"flowId":"91b5ee9c-632d-4af4-8154-ddd2490bf677","now":1655121439813,"level":"INFO","module":"/Users/jand/Scratchpad/ecachim/pictoperfect-documents-server/lib/pdf/browser.js","function":"ensureBrowserClosed","phase":"BROWSER_PROMISE_RESOLVED"}
{"lambda":{"instanceId":"2bb7897b-e17e-40e8-bf33-6a494067c0c7"},"flowId":"91b5ee9c-632d-4af4-8154-ddd2490bf677","now":1655121439966,"level":"INFO","module":"/Users/jand/Scratchpad/ecachim/pictoperfect-documents-server/lib/pdf/browser.js","function":"ensureBrowserClosed","phase":"BROWSER_CLOSED"}
{"lambda":{"instanceId":"2bb7897b-e17e-40e8-bf33-6a494067c0c7"},"flowId":"91b5ee9c-632d-4af4-8154-ddd2490bf677","now":1655121439966,"level":"INFO","module":"/Users/jand/Scratchpad/ecachim/pictoperfect-documents-server/lib/pdf/browser.js","function":"ensureBrowserClosed","phase":"NOMINAL_END"}
all remaining chromium processes closed

On Bitbucket Pipelines, the comparable output is:

2) "after all" hook: afterAll in "{root}"
     >>> logs: all tests done; closing remaining chromium processes
     >>> logs: {"lambda":{"instanceId":"d7e5d7cf-1744-46a4-a2b4-c96ae68b11d4"},"now":1655116230499,"level":"INFO","module":"/opt/atlassian/pipelines/agent/build/lib/pdf/browser.js","function":"ensureBrowserClosed","phase":"CALLED"}
     >>> logs: {"lambda":{"instanceId":"d7e5d7cf-1744-46a4-a2b4-c96ae68b11d4"},"now":1655116230499,"level":"INFO","module":"/opt/atlassian/pipelines/agent/build/lib/pdf/browser.js","function":"ensureBrowserClosed","phase":"FOUND_BROWSER_PROMISE"}
     >>> logs: {"lambda":{"instanceId":"d7e5d7cf-1744-46a4-a2b4-c96ae68b11d4"},"now":1655116230499,"level":"INFO","module":"/opt/atlassian/pipelines/agent/build/lib/pdf/browser.js","function":"ensureBrowserClosed","phase":"DISCARDED_BROWSER_PROMISE"}
     >>> logs: {"lambda":{"instanceId":"d7e5d7cf-1744-46a4-a2b4-c96ae68b11d4"},"now":1655116230499,"level":"INFO","module":"/opt/atlassian/pipelines/agent/build/lib/pdf/browser.js","function":"ensureBrowserClosed","phase":"BROWSER_PROMISE_RESOLVED"}
     >>> logs: Error:   Timeout of 2000ms exceeded. For async tests and hooks, ensure "done()" is called; if returning a Promise, ensure it resolves.
     >>> logs:     at listOnTimeout (internal/timers.js:557:17)
     >>> logs:     at processTimers (internal/timers.js:500:7)
     >>> logs: code:    ERR_MOCHA_TIMEOUT
     >>> logs: timeout: 2000

This must mean that await browser.close() hangs for quite a long time.

Any ideas on why this might occur in the updated version?

jandppw commented 2 years ago

Just made the afterAll hook wait for 20s:

all tests done; closing remaining chromium processes
{"lambda":{"instanceId":"77717a25-5031-4be8-98b0-3004e1310f1e"},"now":1655125427619,"level":"INFO","module":"/opt/atlassian/pipelines/agent/build/lib/pdf/browser.js","function":"ensureBrowserClosed","phase":"CALLED"}
{"lambda":{"instanceId":"77717a25-5031-4be8-98b0-3004e1310f1e"},"now":1655125427619,"level":"INFO","module":"/opt/atlassian/pipelines/agent/build/lib/pdf/browser.js","function":"ensureBrowserClosed","phase":"FOUND_BROWSER_PROMISE"}
{"lambda":{"instanceId":"77717a25-5031-4be8-98b0-3004e1310f1e"},"now":1655125427619,"level":"INFO","module":"/opt/atlassian/pipelines/agent/build/lib/pdf/browser.js","function":"ensureBrowserClosed","phase":"DISCARDED_BROWSER_PROMISE"}
{"lambda":{"instanceId":"77717a25-5031-4be8-98b0-3004e1310f1e"},"now":1655125427620,"level":"INFO","module":"/opt/atlassian/pipelines/agent/build/lib/pdf/browser.js","function":"ensureBrowserClosed","phase":"BROWSER_PROMISE_RESOLVED"}
  1) "after all" hook: afterAll in "{root}"
  4 passing (23s)
  1 failing
  1) "after all" hook: afterAll in "{root}":
     Error: Timeout of 20000ms exceeded. For async tests and hooks, ensure "done()" is called; if returning a Promise, ensure it resolves.
      at listOnTimeout (internal/timers.js:557:17)
      at processTimers (internal/timers.js:500:7)

Even after 20s, the close() command does not resolve, at the end of the test run.

jandppw commented 2 years ago

I now have a limited test suite, that only does some limited tests with the browser. One of the tests is testing whether ensureBrowserClosed works, and it does in that test, repeatedly:

/* eslint-env mocha */

const testName = require('../../_testName')
const { getBrowser, ensureBrowserClosed } = require('../../../lib/pdf/browser')

const flowId = '91b5ee9c-632d-4af4-8154-ddd2490bf677'
const zeroTo9 = Array(10)
  .fill()
  .map((ignore, idx) => idx)

describe(testName(module), function () {
  this.timeout(20000) // starting the browser takes a few seconds

  after(async function () {
    return ensureBrowserClosed() // <<< THIS WORKS
  })

  it('always returns the same browser promise and browser', async function () {
    const browserPromises = zeroTo9.map(i => getBrowser(flowId))
    browserPromises.forEach(bp => {
      bp.should.equal(browserPromises[0])
    })
    const browsers = await Promise.all(browserPromises)
    browsers.forEach(b => {
      b.isConnected().should.be.true()
      b.should.equal(browsers[0])
    })

    // after await
    const browserPromises2 = zeroTo9.map(i => getBrowser(flowId))
    browserPromises2.forEach(bp => {
      bp.should.equal(browserPromises[0])
    })
    const browsers2 = await Promise.all(browserPromises2)
    browsers2.forEach(b => {
      b.isConnected().should.be.true()
      b.should.equal(browsers[0])
    })
  })

  it('discards an existing browser', async function () {
    const browser1Promise = getBrowser(flowId)
    const browser1 = await browser1Promise
    browser1.isConnected().should.be.true()
    const closedPromise = ensureBrowserClosed() // <<< THIS WORKS
    const browser2Promise = getBrowser(flowId)
    browser2Promise.should.not.equal(browser1Promise)
    await closedPromise
    browser1.isConnected().should.be.false()
    const browser2 = await browser2Promise
    browser2.isConnected().should.be.true()
    browser2.should.not.equal(browser1)
  })

  it('does not fail when we try to close a browser if there is none', async function () {
    await ensureBrowserClosed(flowId)
    await ensureBrowserClosed(flowId) // this doesn't fail
  })
})
{"lambda":{"instanceId":"77717a25-5031-4be8-98b0-3004e1310f1e"},"flowId":"91b5ee9c-632d-4af4-8154-ddd2490bf677","now":1655125424998,"level":"INFO","module":"/opt/atlassian/pipelines/agent/build/lib/pdf/browser.js","function":"getBrowser","phase":"CALLED"}
{"lambda":{"instanceId":"77717a25-5031-4be8-98b0-3004e1310f1e"},"flowId":"91b5ee9c-632d-4af4-8154-ddd2490bf677","now":1655125424998,"level":"INFO","module":"/opt/atlassian/pipelines/agent/build/lib/pdf/browser.js","function":"getBrowser","phase":"NOMINAL_END"}
{"lambda":{"instanceId":"77717a25-5031-4be8-98b0-3004e1310f1e"},"now":1655125424998,"level":"INFO","module":"/opt/atlassian/pipelines/agent/build/lib/pdf/browser.js","function":"ensureBrowserClosed","phase":"CALLED"}
{"lambda":{"instanceId":"77717a25-5031-4be8-98b0-3004e1310f1e"},"now":1655125424999,"level":"INFO","module":"/opt/atlassian/pipelines/agent/build/lib/pdf/browser.js","function":"ensureBrowserClosed","phase":"FOUND_BROWSER_PROMISE"}
{"lambda":{"instanceId":"77717a25-5031-4be8-98b0-3004e1310f1e"},"now":1655125424999,"level":"INFO","module":"/opt/atlassian/pipelines/agent/build/lib/pdf/browser.js","function":"ensureBrowserClosed","phase":"DISCARDED_BROWSER_PROMISE"}
{"lambda":{"instanceId":"77717a25-5031-4be8-98b0-3004e1310f1e"},"flowId":"91b5ee9c-632d-4af4-8154-ddd2490bf677","now":1655125424999,"level":"INFO","module":"/opt/atlassian/pipelines/agent/build/lib/pdf/browser.js","function":"getBrowser","phase":"CALLED"}
{"lambda":{"instanceId":"77717a25-5031-4be8-98b0-3004e1310f1e"},"flowId":"91b5ee9c-632d-4af4-8154-ddd2490bf677","now":1655125424999,"level":"INFO","module":"/opt/atlassian/pipelines/agent/build/lib/pdf/browser.js","function":"getBrowser#launchAndReport","phase":"ENVIRONMENT_DETERMINED","details":{"environment":"bitbucket","noSandbox":true}}
{"lambda":{"instanceId":"77717a25-5031-4be8-98b0-3004e1310f1e"},"flowId":"91b5ee9c-632d-4af4-8154-ddd2490bf677","now":1655125425000,"level":"INFO","module":"/opt/atlassian/pipelines/agent/build/lib/pdf/browser.js","function":"getBrowser#launchAndReport","phase":"ADDING_FONTS","details":{"fontFilePaths":["/opt/atlassian/pipelines/agent/build/lib/pdf/fonts/Roboto/Roboto-Bold.ttf","/opt/atlassian/pipelines/agent/build/lib/pdf/fonts/Roboto/Roboto-BoldItalic.ttf","/opt/atlassian/pipelines/agent/build/lib/pdf/fonts/Roboto/Roboto-Italic.ttf","/opt/atlassian/pipelines/agent/build/lib/pdf/fonts/Roboto/Roboto-Regular.ttf"]}}
{"lambda":{"instanceId":"77717a25-5031-4be8-98b0-3004e1310f1e"},"flowId":"91b5ee9c-632d-4af4-8154-ddd2490bf677","now":1655125425000,"level":"INFO","module":"/opt/atlassian/pipelines/agent/build/lib/pdf/browser.js","function":"getBrowser","phase":"NOMINAL_END"}
{"lambda":{"instanceId":"77717a25-5031-4be8-98b0-3004e1310f1e"},"now":1655125425000,"level":"INFO","module":"/opt/atlassian/pipelines/agent/build/lib/pdf/browser.js","function":"ensureBrowserClosed","phase":"BROWSER_PROMISE_RESOLVED"}
{"lambda":{"instanceId":"77717a25-5031-4be8-98b0-3004e1310f1e"},"flowId":"91b5ee9c-632d-4af4-8154-ddd2490bf677","now":1655125425001,"level":"INFO","module":"/opt/atlassian/pipelines/agent/build/lib/pdf/browser.js","function":"getBrowser#launchAndReport","phase":"FONTS_ADDED","details":{"appliedFonts":[null,null,null,null]}}
{"lambda":{"instanceId":"77717a25-5031-4be8-98b0-3004e1310f1e"},"flowId":"91b5ee9c-632d-4af4-8154-ddd2490bf677","now":1655125425002,"level":"INFO","module":"/opt/atlassian/pipelines/agent/build/lib/pdf/browser.js","function":"getBrowser#launchAndReport","phase":"LAUNCHING_BROWSER","details":{"launchOptions":{"executablePath":null,"args":["--allow-running-insecure-content","--autoplay-policy=user-gesture-required","--disable-component-update","--disable-domain-reliability","--disable-features=AudioServiceOutOfProcess,IsolateOrigins,site-per-process","--disable-print-preview","--disable-setuid-sandbox","--disable-site-isolation-trials","--disable-speech-api","--disable-web-security","--disk-cache-size=33554432","--enable-features=SharedArrayBuffer","--hide-scrollbars","--ignore-gpu-blocklist","--in-process-gpu","--mute-audio","--no-default-browser-check","--no-pings","--no-sandbox","--no-zygote","--use-gl=angle","--use-angle=swiftshader","--window-size=1920,1080","--start-maximized"],"defaultViewport":{"deviceScaleFactor":1,"hasTouch":false,"height":1080,"isLandscape":true,"isMobile":false,"width":1920},"headless":true}}}
{"lambda":{"instanceId":"77717a25-5031-4be8-98b0-3004e1310f1e"},"now":1655125425149,"level":"INFO","module":"/opt/atlassian/pipelines/agent/build/lib/pdf/browser.js","function":"ensureBrowserClosed","phase":"BROWSER_CLOSED"}
{"lambda":{"instanceId":"77717a25-5031-4be8-98b0-3004e1310f1e"},"now":1655125425149,"level":"INFO","module":"/opt/atlassian/pipelines/agent/build/lib/pdf/browser.js","function":"ensureBrowserClosed","phase":"NOMINAL_END"}
{"lambda":{"instanceId":"77717a25-5031-4be8-98b0-3004e1310f1e"},"flowId":"91b5ee9c-632d-4af4-8154-ddd2490bf677","now":1655125425175,"level":"INFO","module":"/opt/atlassian/pipelines/agent/build/lib/pdf/browser.js","function":"getBrowser#launchAndReport","phase":"NOMINAL_END","details":{"version":"HeadlessChrome/103.0.5058.0","userAgent":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) HeadlessChrome/103.0.5058.0 Safari/537.36"}}
    ✔ discards an existing browser (178ms)

Yet, at the end of the run:

all tests done; closing remaining chromium processes
{"lambda":{"instanceId":"77717a25-5031-4be8-98b0-3004e1310f1e"},"now":1655125427619,"level":"INFO","module":"/opt/atlassian/pipelines/agent/build/lib/pdf/browser.js","function":"ensureBrowserClosed","phase":"CALLED"}
{"lambda":{"instanceId":"77717a25-5031-4be8-98b0-3004e1310f1e"},"now":1655125427619,"level":"INFO","module":"/opt/atlassian/pipelines/agent/build/lib/pdf/browser.js","function":"ensureBrowserClosed","phase":"FOUND_BROWSER_PROMISE"}
{"lambda":{"instanceId":"77717a25-5031-4be8-98b0-3004e1310f1e"},"now":1655125427619,"level":"INFO","module":"/opt/atlassian/pipelines/agent/build/lib/pdf/browser.js","function":"ensureBrowserClosed","phase":"DISCARDED_BROWSER_PROMISE"}
{"lambda":{"instanceId":"77717a25-5031-4be8-98b0-3004e1310f1e"},"now":1655125427620,"level":"INFO","module":"/opt/atlassian/pipelines/agent/build/lib/pdf/browser.js","function":"ensureBrowserClosed","phase":"BROWSER_PROMISE_RESOLVED"}
  1) "after all" hook: afterAll in "{root}"
  4 passing (23s)
  1 failing
  1) "after all" hook: afterAll in "{root}":
     Error: Timeout of 20000ms exceeded. For async tests and hooks, ensure "done()" is called; if returning a Promise, ensure it resolves.
      at listOnTimeout (internal/timers.js:557:17)
      at processTimers (internal/timers.js:500:7)

Note that in this test, I never open a window, or generate a PDF, …, but I do in other tests in this run, that come later.

jandppw commented 2 years ago

Now, I have ran a test suite with only 1 test, where I do use the browser. In this case, await browser.close() does not resolve.

So it seems that in this version of this package, something happens that prevents closing the browser once we did "something" with the browser.

The test code is:

/* eslint-env mocha */

const testName = require('../../_testName')
const createAndStorePDF = require('../../../lib/pdf/createAndStorePDF')
const { v4: uuidv4 } = require('uuid')
const { example: html } = require('../../../lib/ppwcode/HTML')
const checkObject = require('../05.aws/_checkObject')
const deleteObject = require('../05.aws/_deleteObject')
const { cacheControlNoStore } = require('../../../lib/lambda/apigateway/ResponseHeaders')

describe(testName(module), function () {
  /**
   * @typedef {object} Fixture
   * @property {UUID} flowId
   * @property {string} path
   * @property {string} filename
   */

  beforeEach(
    /** @this {Fixture & Context} */ async function () {
      this.timeout(5000)
      this.flowId = uuidv4()
      this.path = `automated-test/getSignedDownloadURL/${this.flowId}`
      this.filename = `automated-test-getSignedDownloadURL-${this.flowId}.pdf`
    }
  )

  afterEach(
    /** @this {Fixture} */ async function () {
      await deleteObject(this.path)
    }
  )

  it('works', /** @this {Fixture & Context} */ async function () {
    this.timeout(10000)
    const sot = new Date().toISOString()
    await createAndStorePDF(sot, this.flowId, this.path, html, cacheControlNoStore, this.filename)
    await checkObject(this.flowId, this.path, cacheControlNoStore, this.filename)
  })
})

which calls

const log = require('../ppwcode/simpleLog')
const { getBrowser } = require('./browser')
const storeInS3 = require('../aws/storeInS3')
const pdfOptions = require('./pdfOptions')

/**
 * @callback createAndStorePDF
 * @param {PointInTime} sot
 * @param {UUID} flowId
 * @param {string} s3Path
 * @param {HTML} html
 * @param {CacheControl} cacheControl
 * @param {string} filename
 * @return {Promise<undefined>}
 */

/**
 * Create a PDF for the given `html`, and store it in S3 in the `s3Path`, with meta-information for download,
 * such as `cache-control` and `content-disposition = "at
 *
 * @type {createAndStorePDF}
 */
async function createAndStorePDF (sot, flowId, s3Path, html, cacheControl, filename) {
  log.info(module, 'createAndStorePDF', flowId, 'CALLED', { sot, s3Path, cacheControl, filename })
  const browser = await getBrowser(flowId)
  const page = await browser.newPage()
  log.info(module, 'createAndStorePDF', flowId, 'CHROMIUM_PAGE_CREATED')
  /* NOTE: We need to wait for external content to load before we generate a PDF. Notably, we use web fonts.
           The `load` event is fired when the whole page has loaded, including all dependent resources such as
           stylesheets and images. This is in contrast to `DOMContentLoaded`, which is fired as soon as the page DOM has
           been loaded, without waiting for resources to finish loading. */
  await page.setContent(html, { waitUntil: 'load' })
  log.info(module, 'createAndStorePDF', flowId, 'CHROMIUM_CONTENT_LOADED')
  const pdf = await page.pdf(pdfOptions)
  log.info(module, 'createAndStorePDF', flowId, 'CHROMIUM_PDF_GENERATED')
  await Promise.all([
    (async () => {
      await page.close()
      log.info(module, 'createAndStorePDF', flowId, 'CHROMIUM_PAGE_CLOSED')
    })(),
    storeInS3(flowId, s3Path, cacheControl, filename, pdf)
  ])
  log.info(module, 'createAndStorePDF', flowId, 'NOMINAL_END')
}

module.exports = createAndStorePDF
jandppw commented 2 years ago

Next, I limited the test to not creating a PDF, and after that, to not loading the page, and after that, to not even closing the page.

When I only create the page

  const page = await browser.newPage()

browser.close() does not resolve.

jandppw commented 2 years ago

Finally, even removed creating a page. And it still fails.

So I am at a loss here. In direct tests, closing resolves. Indirectly, it doesn't.

jandppw commented 2 years ago

Stripped the test further, bypassing Sparticuz/chrome-aws-lambda completely, talking directly to puppeteer.

Still fails in the indirect test.

In other words, nevermind. This isn't an issue with Sparticuz/chrome-aws-lambda. Sorry for wasting your time.

Sparticuz commented 2 years ago

Still fails in the indirect test.

I've also never gotten browser.close() to work...but I'm not sure I care because the lambda instance terminates anyway.

jandppw commented 2 years ago

@Sparticuz Thx for the reply. Now I know I'm not crazy, at least.

Yes, in production that is true. But I need to be able to kill the Chromium process in the CI tests, or otherwise the mocha run never stops, processes hang, the run does not progress to the next steps, …

Wait a sec. Is that even true? I want to stop Chrome certainly locally, because otherwise I get myriads of chromes running when developing, but that works. But in a container on CI? Maybe it will just kill it for me at the end?

In any case, it's probably a Puppeteer thing, so I'll take my whining there.

aaronce commented 2 years ago

I have this issue as well in lambdas - the lambda instance ends up running until it reaches timeout (~30s), kind of annoying but a pdf is returned well before the limit is reached.