GAミント至上主義

Web Monomaniacal Developer@DMM

Headless Chromeを使ったPDF変換サーバーが落ちないようにした対策まとめ

yagish履歴書でも使っているPDF変換サーバーがまれによく下記のエラーを吐いて落ちてしまう問題が一段落ついたのでまとめる。
2019年1月スタートのアニメはまだ何を見ていいか分からない状態です。

Error: Protocol error (Page.printToPDF): The previous printing job hasn't finished
    at Promise (/hcep/node_modules/puppeteer/lib/Connection.js:186:56)
    at new Promise (<anonymous>)
    at CDPSession.send (/hcep/node_modules/puppeteer/lib/Connection.js:185:12)
    at Page.pdf (/hcep/node_modules/puppeteer/lib/Page.js:911:39)
    at Page.<anonymous> (/hcep/node_modules/puppeteer/lib/helper.js:145:23)
    at app.route.get.post (/hcep/app/express-app.js:110:35)
    at process._tickCallback (internal/process/next_tick.js:68:7)

ソースコードはこれ
GitHub - uyamazak/hcep-pdf-server: Simple PDF rendering server using Headless Chrome & Express & Puppeteer

対策1:このエラーが出たらprocess.exit()して、Kubernetesのdeploymentに再起動してもらう(済)

メリット:エラーをcatchしてprocess.exit()するだけの簡単なお仕事
デメリット:ユーザーが一度はダウンロードを失敗してしまう

とりあえずの応急処置。エラーが出ると止まってしまいそのままだったので、process.exit()でコンテナごと落とした。
Kubernetes (GKE)でレプリカ数を複数にしてあるので、再度ダウンロードしてもらえば、別Podが使われるのでほぼ問題なかった。

対策2: The previous printing job has finishedしているか確認する(未)

Puppeteerのソースを確認して、前回の印刷ジョブ(今回はPDF生成処理のこと)が残っているか否かを確認しようとしたが、よく分からなくてやめた。

github.com

対策3:ヘルスチェックの間隔を長くしたりずらす(済)

メリット:yamlの数字を変えるだけの簡単なお仕事
デメリット:長くすると正常判定されるのがまでちょっと遅くなる

最近よく対策1の再起動が増えたので、ログを眺めているとヘルスチェックのアクセス多いなということに気づいた。
さらによく見ると全く同時刻にヘルスチェックへのアクセスが来ていた。

ヘルスチェックは、KubernetesIngressで必要なdeployment設定内のlivenessProbeの設定。
詳しくは以前の記事。
uyamazak.hatenablog.com

そういえば、新しいサービスも増え、今回のPDFサーバーを参照するdeploymentが増えたのであった。

そのため、間隔(periodSeconds)やinitialDelaySecondsを変えて重なりにくくした。
また30秒とかだったのを60秒とか長くもした。
ここでもしかして、同時にリクエストが来るとエラーになるのでは?と気づき始めた。

対策4:サーバーでリトライさせる(済)

メリット:デコレーターつけるだけの簡単なお仕事
デメリット:PDFサーバーが完全に落ちてるときは、ユーザーが結構待つ(3秒✕3回 + jitterだと10秒近く)

yagishではユーザーがPDFサーバーに直接リクエストするのではなく、間にDjangoを使ったAPIを挟んで、危ないタグの除去や必要なCSSの挿入を行っていた。

そのため、Djangoの方でリトライ処理を追加した。便利で使い慣れているretryというライブラリがあったのも要因。
リクエスト処理は関数になっていたのでデコレータを追加するだけで良い。

uyamazak.hatenablog.com

対策5: Headless ChromeのPageをたくさん用意して使う(検証中)

メリット:同時アクセスに強くなる
デメリット:コードがちょっと複雑に。あとメモリを食う(1ページ7MBぐらい)

Puppeteerでは、puppeteer.launch()で作るブラウザ本体と、browser.newPage()で作るページという概念があり、これまではどちらも一つだけ作って使いまわしていた。
今回のPDF処理はページ単位のため、ページがたくさんあればいいのでは?と考え実装してみた。

before
app/hc-page.js

module.exports.hcPage = async () => {
  const puppeteer = require('puppeteer')
  const launchOptions = generateLaunchOptions()
  debug('launchOptions:', launchOptions)
  // launch browser and page only once
  const browser = await puppeteer.launch(launchOptions)
  const chromeVersion = await browser.version()
  debug('chromeVersion:', chromeVersion)
  const page = await browser.newPage()
  return page
}

after
app/hc-pages.js

module.exports.hcPages = async (PagesNum) => {
  const puppeteer = require('puppeteer')
  const launchOptions = generateLaunchOptions()
  debug('launchOptions:', launchOptions)
  // launch browser and page only once
  const browser = await puppeteer.launch(launchOptions)
  const chromeVersion = await browser.version()
  debug('chromeVersion:', chromeVersion)
  const pages = []
  for(let i=0; i < PagesNum; i++){
    debug('page launched No.' + i)
    pages.push(await browser.newPage())
  }
  return pages
}

変数や関数名もpageではなくpagesにした。

これを使うexpress側では順番に取り出す関数を作った

//省略
  const pagesNum = pages.length
  console.log(`pages.length: ${pages.length}`)
  let currentPageNo = 0
  const getSinglePage = () => {
    currentPageNo++
    if (currentPageNo >= pagesNum) {
      currentPageNo = 0
    }
    debug('currentPageNo:' + currentPageNo)
    return pages[currentPageNo]
  }
//省略

まだテスト中のため、デバッグ用に今何個目を使っているかを出すようにしている。

対策2で書いたページが現在印刷処理中がどうかが分かれば、このgetSinglePage内でスキップすることができそうなので、調査したい。

実際これで解決できるのか、同時に多重リクエストするテストを書いた

test/express-app.js

  it('LAUNCH_HC_PAGES_NUM of concurrent access to POST / html=' + HTML_TEST_STRINGS, async () => {
    function task() {
      return new Promise(async function(resolve) {
        await req.post('/')
          .send('html=' + encodeURI(HTML_TEST_STRINGS))
          .expect('Content-Type', 'application/pdf')
          .expect(200)
        resolve()
      })
    }
    const tasks = []
    for (let i=0; i<LAUNCH_HC_PAGES_NUM; i++) {
      tasks.push(task())
    }
    await Promise.all(tasks)
  })

既存の普通のリクエストをPromise化し、リストにいれて、Promise.allを使って同時実行した。
とりあえず立ち上げたページと同じ数で実行したところ問題なく完了。
ためしにリクエスト数をページ数の2倍にしたところ、同じエラーがテストでも確認できた。

 Error: Protocol error (Page.printToPDF): The previous printing job hasn't finished

メモリ使用量の確認

開発サーバー上で立ち上げるページ数(n)を変えてdocker statsコマンドで確認した。
起動だけで実際のPDF生成は行わない状態での数値。

CONTAINER ID        NAME                      CPU %               MEM USAGE / LIMIT     MEM %               NET I/O             BLOCK I/O           PIDS
# n = 1
1a88b0499334        varuna-hcep-pdf-server    0.90%               135.9MiB / 31.33GiB   0.42%               40.7MB / 8.64MB     0B / 3.91MB         139
# n = 2
1a88b0499334        varuna-hcep-pdf-server    1.04%               143.3MiB / 31.33GiB   0.45%               40.7MB / 8.64MB     0B / 3.91MB         153
# n = 3
1a88b0499334        varuna-hcep-pdf-server    0.87%               150MiB / 31.33GiB     0.47%               40.7MB / 8.64MB     0B / 3.92MB         167
# n = 5
1a88b0499334        varuna-hcep-pdf-server    0.68%               164.3MiB / 31.33GiB   0.51%               40.7MB / 8.64MB     0B / 3.92MB         193
# n = 10
1a88b0499334        varuna-hcep-pdf-server    1.24%               198.6MiB / 31.33GiB   0.62%               40.7MB / 8.64MB     0B / 3.92MB         257
# n = 20
1a88b0499334        varuna-hcep-pdf-server    0.71%               267.3MiB / 31.33GiB   0.83%               40.7MB / 8.64MB     0B / 3.93MB         388
# n = 30
1a88b0499334        varuna-hcep-pdf-server    0.78%               337.2MiB / 31.33GiB   1.05%               40.7MB / 8.64MB     0B / 3.93MB         518

1ページ増やすと約7MB増えることが分かる。起動時間に関しては、最初だけだし、1ページ20-30msとだーっと流れるように立ち上げるので気にしなくて良さそう。
f:id:uyamazak:20190130150826p:plain

使えるメモリが256MBであれば、安全に5か、攻めて10ぐらいだろうか。
あとはPDF化するデータサイズも気にする必要があるかもしれない。

まだ実環境でのテストはしてないけど、1コンテナあたりのページ数は控えめにして、複数起動した方が同じリソースでも安定する可能性もある。

まとめ

ページ数、使用メモリを増やした分だけ同時アクセスに耐えられるようになったけど、エラーが出て再起動する可能性は0じゃないので、もっと根本的に解決したいところ。

同時アクセスが原因だったのをPromise.allを使った多重同時アクセスするテストコードで再現できたので、そういう手では難しいテストは特に大事。もっと早く書いておけばよかった。
当たり前だけどまずエラーの再現大事。

Nodeクックブック

Nodeクックブック

Google Cloud Buildの完了をCloud Functionsで受け取る

GitHubへのPushからCloud Buildで自動ビルド&Container Registoryにアップロードまでができた続き。

uyamazak.hatenablog.com

Cloud Pub/Subに

projects/{project id}/topics/gcr

というトピックが勝手にできていて、gcrはGoogle Cloud Registoryだと思うので、何かのタイミングでここにメッセージが来ると予想。

でもググると、GCRではなくCloud Buildの方もPub/Subトピックが自動で出来てると下記には書いてあるけど自分のプロジェクトにはない。なぜ?

ビルド通知の送信  |  Cloud Build  |  Google Cloud

試しにCloud BuildのAPIをオンオフしてみたらFunctions側で選択できるようになった。

とりあえずデフォルトのコードを使いログ出力だけしてみる。
f:id:uyamazak:20190121184044p:plain

トピックcloud-buildsこんなのが出た。QUEUED、WORKING、SUCCESSの三種。ビルド開始、成功、失敗(未確認)をslackに流すならこっちかも
f:id:uyamazak:20190121185810p:plain

トピックgcrはINSERTでアップしたイメージのURLが来るので、自動デプロイするならこっちが必要になりそう。Functionsでできるのだろうか。
f:id:uyamazak:20190121185940p:plain

Google Cloud Platform エンタープライズ設計ガイド

Google Cloud Platform エンタープライズ設計ガイド

WSL(Windows Subsystem for Linux)でDockerを動かす(使えない)

2019/1/21追記

Docker Desktop for Windowsは動いた(使えそう)
docs.docker.com

追記ここまで

普段の開発はLinux上で行っているけど、WSLに関してはLinux信者として興味があり、以前Bash on Windowsを動かしてみたりはしてた。
でも日本語がダメだったり、普通にLinuxが使える環境であれば実用性はなく放置してたけど、最近Dockerが動くようになったと聞くようになったので試してみた。
Amazonプライムで2019年のアニメがいろいろ始まったけどまだ何見ていいかわからない状態。

WSL(Windows Subsystem for Linux)に関してはここらへん
qiita.com

参考はここらへん。
qiita.com
qiita.com

Microsoft StoreからUbuntu16.04を入れ、上記記事を参考にdockerをインストールしたが動かなかった。
その後、Windowsアップデートをして下記バージョンにしたところ、hello-worldやnginxは動くようになった。

f:id:uyamazak:20190116165552p:plain

じゃあさっそく自分が作ってるアプリを動かしてみようと下記のnode、puppeteerを使ったPDFサーバーをcloneしてビルドしてみたところ失敗。

github.com

Unpacking dh-python (2.20170125) ...
Setting up libpython3.5-minimal:amd64 (3.5.3-1+deb9u1) ...
Setting up python3.5-minimal (3.5.3-1+deb9u1) ...
Traceback (most recent call last):
  File "/usr/lib/python3.5/py_compile.py", line 186, in <module>
    sys.exit(main())
  File "/usr/lib/python3.5/py_compile.py", line 178, in main
    compile(filename, doraise=True)
  File "/usr/lib/python3.5/py_compile.py", line 136, in compile
    os.makedirs(dirname)
  File "/usr/lib/python3.5/os.py", line 241, in makedirs
    mkdir(name, mode)
OSError: [Errno 39] Directory not empty: '/usr/lib/python3.5/__pycache__'
dpkg: error processing package python3.5-minimal (--configure):
 subprocess installed post-installation script returned error exit status 1
dpkg: dependency problems prevent configuration of python3-minimal:
 python3-minimal depends on python3.5-minimal (>= 3.5.3-1~); however:
  Package python3.5-minimal is not configured yet.

dpkg: error processing package python3-minimal (--configure):
 dependency problems - leaving unconfigured
Errors were encountered while processing:
 python3.5-minimal
 python3-minimal
W: Download is performed unsandboxed as root as file '/var/cache/apt/archives/partial/fontconfig_2.11.0-6.7+b1_amd64.deb' couldn't be accessed by user '_apt'. - pkgAcquire::Run (13: Permission denied)
E: Sub-process /usr/bin/dpkg returned an error code (1)
The command '/bin/sh -c 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-stable --no-install-recommends   && rm -rf /var/lib/apt/lists/*   && rm -rf /src/*.deb' returned a non-zero code: 100
uyamazak@windows10pro:~/hcep-pdf-server$ sudo docker build -t hcep-pdf-server:latest .

chromeインストールでこけている。

もしかして開発に使ってるLinux(Ubuntu16.04)でだけ?と思ったけど、GCPのCloud Buildでもビルドは成功しているのでWSL側の問題である確率の方が高そう。
エラー出してる部分をなんとか直せば上手くいくのかもしれないけど、使わないWSLのためにそこまでしたくない。

開発作業以外なら、Windowsでも社内の事情、ハードウェアの自由もあるし全然嫌ではない。

でも開発環境はVM、ハイパーバイザーなどを使わない素に近いLinux、強いて言えば本番環境に近いLinux、強いて言えばDebian, Ubuntuがいいなぁと改めて思った。