yagishで使っているPDF変換サーバーが落ちてしまったので、エラーログを確認して対策を考える。
復旧は再起動だけでひとまず完了。
比較的アクセスの少ない朝4時から10時ぐらいまでの営業日だったのが幸い。昼間や連休中だったら大変だった。
Stackdriverで周辺のログを見るといろんな種類のものが出ていたけど、一番わかりやすいのが3つ目の「Page crashed! 」
2018-09-25 03:59:11.000 JST
{ Error: Protocol error (Page.printToPDF): Printing failed undefined
at Promise (/hcep/node_modules/puppeteer/lib/Connection.js:202:56)
at new Promise (<anonymous>)
at CDPSession.send (/hcep/node_modules/puppeteer/lib/Connection.js:201:12)
at Page.pdf (/hcep/node_modules/puppeteer/lib/Page.js:851:39)
at app.post (/hcep/app/pdf-server.js:136:31)
at <anonymous>
at process._tickCallback (internal/process/next_tick.js:182:7)
2018-09-25 04:00:07.000 JST
ServiceUnavailableError: Response timeout
at IncomingMessage.<anonymous> (/hcep/node_modules/connect-timeout/index.js:84:8)
at IncomingMessage.emit (events.js:180:13)
at Timeout.<anonymous> (/hcep/node_modules/connect-timeout/index.js:49:11)
at ontimeout (timers.js:466:11) at tryOnTimeout (timers.js:304:5)
at Timer.listOnTimeout (timers.js:267:5)
2018-09-25 04:00:07.000 JST
(node:1) UnhandledPromiseRejectionWarning: Error: Page crashed!
at Page._onTargetCrashed (/hcep/node_modules/puppeteer/lib/Page.js:156:24)
at CDPSession.Page.client.on.event (/hcep/node_modules/puppeteer/lib/Page.js:132:56)
at CDPSession.emit (events.js:180:13)
at CDPSession._onMessage (/hcep/node_modules/puppeteer/lib/Connection.js:232:12)
at Connection._onMessage (/hcep/node_modules/puppeteer/lib/Connection.js:119:19)
at WebSocket.emit (events.js:180:13)
at Receiver.receiverOnMessage (/hcep/node_modules/ws/lib/websocket.js:718:20)
at Receiver.emit (events.js:180:13)
at Receiver.dataMessage (/hcep/node_modules/ws/lib/receiver.js:414:14)
at Receiver.getData (/hcep/node_modules/ws/lib/receiver.js:346:17)
2018-09-25 04:00:07.000 JST
(node:1) UnhandledPromiseRejectionWarning:
Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). (rejection id: 1)
2018-09-25 04:00:07.000 JST
(node:1) [DEP0018] DeprecationWarning:
Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.
2018-09-25 04:00:11.000 JST
ServiceUnavailableError: Response timeout at IncomingMessage.<anonymous> (/hcep/node_modules/connect-timeout/index.js:84:8)
at IncomingMessage.emit (events.js:180:13)
at Timeout.<anonymous> (/hcep/node_modules/connect-timeout/index.js:49:11)
at ontimeout (timers.js:466:11) at tryOnTimeout (timers.js:304:5)
at Timer.listOnTimeout (timers.js:267:5)
2018-09-25 04:20:07.000 JST
ServiceUnavailableError: Response timeout
at IncomingMessage.<anonymous> (/hcep/node_modules/connect-timeout/index.js:84:8)
at IncomingMessage.emit (events.js:180:13)
at Timeout.<anonymous> (/hcep/node_modules/connect-timeout/index.js:49:11)
at ontimeout (timers.js:466:11)
at tryOnTimeout (timers.js:304:5)
at Timer.listOnTimeout (timers.js:267:5)
2018-09-25 10:04:07.000 JST
{ Error: Protocol error (Runtime.callFunctionOn): Target closed.
at Promise (/hcep/node_modules/puppeteer/lib/Connection.js:202:56)
at new Promise (<anonymous>)
at CDPSession.send (/hcep/node_modules/puppeteer/lib/Connection.js:201:12)
at ExecutionContext.evaluateHandle (/hcep/node_modules/puppeteer/lib/ExecutionContext.js:79:75)
at ExecutionContext.evaluate (/hcep/node_modules/puppeteer/lib/ExecutionContext.js:46:31)
at Frame.evaluate (/hcep/node_modules/puppeteer/lib/FrameManager.js:326:20)
at <anonymous>
at process._tickCallback (internal/process/next_tick.js:182:7)Pageはpuppeteerで下記のような感じで作るPageオブジェクト
# 疑似コード
const puppeteer = require('puppeteer')
const browser = puppeteer.launch(launchOptions)
const page = browser.newPage()そこらへんのエラー文言で検索すると、良い記事が見つかる。
qiita.com
What is "Page crashed!" error? · Issue #1321 · GoogleChrome/puppeteer · GitHub
Page crashed!は/dev/shmというRAMディスク領域の容量不足で起きるらしい。
今回も同じ原因かはわからないけど、現在GKEで動いているものがどうなっているか調べてみる。
kubectl exec -it {podのid} bashでdfを叩いてみる
hcep-pdf-server-7799668b8c-bw6r2:/hcep$ df -h /dev/shm Filesystem Size Used Avail Use% Mounted on shm 64M 0 64M 0% /dev/shm
容量はデフォルトの64MBのまま。大きいページでは足りなくなってしまい落ちるらしい。
Dockerではrun時にオプション--shm-size=256mで変更できるらしいが、GKEではオプションが無い。
その代わり、/dev/shmにディスクをマウントしてしまうという方法が見つかった。
容量は増えてもRAMじゃなくなるから遅くなるだろうか。
stackoverflow.com
なんでshmという名前なのが気になるけど、tmpfsが以前shmfsという名前だったのが関係ありそうだけどshmの意味まではまだ分かってない。意味的にshered memory?
今後のやることとしては、まず容量の大きいページを開いて同じようにcrashするか確認して原因を特定。
原因が上記と同じ容量だったら
- crashしても自動で復旧できるようにnodeのプログラム側を考える
- そもそも大きいページを開かないように前段階で遮断する
- GKEでshmにディスクマウントして容量を増やす（やりたくない）
という感じで考えている。
自動復旧はchromeのプロセスも絡み、nodeだけでは難しそうなのでエラーをcatchしてprocess.exitし、podごと落とし、再起動はkubernetesのdeployに任せる感じでいいかもしれない。
[2018/9/25 17時追記] アクセスログの調査
上記の容量オーバー説の調査のため、サーバーダウン前後のリクエストを確認した。
こちらもStackdriverでHTTPロードバランサーのログを確認する。
これをみるとPDFダウンロードのPOSTリクエストがある前に、ヘルスチェックへのGETアクセスですでにエラーが出始めている。
と、なると大きなPOSTリクエストが原因ではなさそう。
あと忘れてたけど、リクエストボディをPageに渡す前に、body-parserでlimitを10MBで指定していたのだった。
10MBだったらおそらく64MBを超えることはなさそう。
まだ原因は特定できなさそうなので、Puppeteerのバージョンを上げたり、まるごとメイン関数をtryで包んで、catchでprocess.exitでpod終了＆PDFサーバーのpod数を増やしておく応急処置をすることにした。
[2018/9/26 10時 追記] エラーハンドリングで詳細をログ出力＆大きいリクエストのテスト
よく見たら最新のコードだとエラー箇所をちゃんとtryで囲っていたので、今回の「unhandledRejection」は起きなさそう。
現状のログ情報だけだとエラーの再現ができそうにない。
データ量だけでなく、質の問題もありそうなので、次エラーがでたときは、下記のようなエラーcatch時に実行する関数を作り、表示しようとしたHTMLなどの詳細もログに出しておくことにした。
function handlePageError(e, option) {
console.error('Page error occurred! process.exit()')
console.error('error:', e)
console.error('option:', option)
process.exit()
}試しに大きなリクエストのテストとして青空文庫から吾輩は猫であるを全文コピーして何度か貼り付けたデータを送り付け、数MB、PDFで300ページ超でも問題なく動いてしまった。
[2018/9/27 16時追記] バージョンをそろえるためChromeではなく、Puppeteer付属のChromiumを使う
Puppeteerのバージョンと対応しているChrome、もしくはChromium のバージョンが違うと問題になることがあるらしい。ソースは見失った。
https://github.com/GoogleChrome/puppeteer/blob/master/docs/api.md#puppeteer-vs-puppeteer-core
Linux向けChromeではDockerfile内でバージョン指定インストールが面倒そうなので、素直に付属のChromiumを使うことにした。
今のところPDF生成においてはChromeとChromiumの違いは気づいていない。
Releases per Chromium Version: Chromium 71.0.3542.0 - Puppeteer v1.8.0 Chromium 70.0.3508.0 - Puppeteer v1.7.0 Chromium 69.0.3494.0 - Puppeteer v1.6.2 Chromium 68.0.3419.0 - Puppeteer v1.4.0 Chromium 67.0.3392.0 - Puppeteer v1.3.0 Chromium 66.0.3347.0 - Puppeteer v1.1.1
Kubernetes完全ガイド (impress top gear)
- 作者: 青山真也
- 出版社/メーカー: インプレス
- 発売日: 2018/09/21
- メディア: 単行本（ソフトカバー）
- この商品を含むブログを見る
- 作者: 山田明憲
- 出版社/メーカー: 技術評論社
- 発売日: 2018/08/25
- メディア: 単行本（ソフトカバー）
- この商品を含むブログ (1件) を見る
