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の再起動が増えたので、ログを眺めているとヘルスチェックのアクセス多いなということに気づいた。
さらによく見ると全く同時刻にヘルスチェックへのアクセスが来ていた。
ヘルスチェックは、KubernetesのIngressで必要な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とだーっと流れるように立ち上げるので気にしなくて良さそう。
使えるメモリが256MBであれば、安全に5か、攻めて10ぐらいだろうか。
あとはPDF化するデータサイズも気にする必要があるかもしれない。
まだ実環境でのテストはしてないけど、1コンテナあたりのページ数は控えめにして、複数起動した方が同じリソースでも安定する可能性もある。
まとめ
ページ数、使用メモリを増やした分だけ同時アクセスに耐えられるようになったけど、エラーが出て再起動する可能性は0じゃないので、もっと根本的に解決したいところ。
同時アクセスが原因だったのをPromise.allを使った多重同時アクセスするテストコードで再現できたので、そういう手では難しいテストは特に大事。もっと早く書いておけばよかった。
当たり前だけどまずエラーの再現大事。
![闘うプログラマー[新装版]](https://images-fe.ssl-images-amazon.com/images/I/51kV6tOSplL._SL160_.jpg "闘うプログラマー[新装版]")
