mercariengineering
XLinkedInRSS
XLinkedInRSS

AppEngineの旧Log APIを脱却したい話

Author:
vvakame
 , 
AppEngineの旧Log APIを脱却したい話

この記事はMERPAY TECH OPENNESS MONTHの3日目の記事です。
メルペイ ソリューションチームで毎日コード書いたりして遊んでいるvvakameです。

TL;DR

  • AppEngine 2nd genでロックインAPIから解放され大脱出できるようになった
  • AppEngine Log APIはオーパーツ(完全には真似できない)
  • プラットフォーム出力のrequest logを使う
  • アプリではapplication logだけ出力する
  • 高度なフィルターの使い方を覚える

05/23 もらった情報をもとに追記をしました。

AppEngineはいいものだよ & 2nd genの台頭

メルペイではプロダクト提供のためにAppEngineはほぼ使われていません。だいたいのものがGKE上で動いていて、だいたいのDBはSpannerです。しかし、お客様に提供するものではない、internalなサービスはFirebase HostingやAppEngineでサクっと実装する場合があります。

筆者はAppEngineのファンで、2010年くらいからAppEngine/SE JavaをSlim3と組み合わせて使い始めました。2014年から2015年くらいに、JavaよりもSpinUpの早いGo環境に移りはじめました。
そんなわけで、完全に魂がAppEngineにロックインされているのですが、時代はAppEngine 2nd gen(第二世代)に突入していこうとしてます。2nd genではproprietary AppEngine APIは利用できません12。
よって、様々なAppEngineにロックインされたAPI群をもっと広い範囲で使えるGoogle Cloud クライアントライブラリに置き換えていく必要があります。

これ自体は大歓迎で、AppEngineは昔から”ロックインされるじゃん”とか”普通の環境にはない縛りが多い”と言われることが多く、そうだね、と答えつつ、それでもAppEngineはいいものなんだよぉ！と主張していたわけです。
go111 runtimeによって、その縛りから解放され普通のWebアプリケーションのようなコードを書いても、AppEngine上で動くようになりました。
すると、当然の流れとしてAppEngineに固有な専用APIはやめて、汎用的に生きていこうね、となるわけです。
2nd genへの完全移行までの猶予期間は年単位以上の時間があるでしょうから、慌てることはありません。とはいえ、今のうちから段階的にproprietary AppEngine APIを捨て去る準備をしていくべきです。

2nd gen API論考

筆者は新しいもの好きなので、Betaだろうがなんだろうが突っ込んでしまってとりあえずリリースしてしまう性格なのですがそれでもproprietary AppEngine APIを剥がすのは容易なことではありません。
なぜなら、proprietary AppEngine APIのほうが出来ることが多く高機能だったり、代替先を見つけるのが容易ではなかったりするからです。
App Engine Images APIの移行先がロクにないよぉ… とか Memcache移行候補のMemorystoreにアクセスするためのServerless VPC Accessがus-central1にしかまだないよぉ… とか、そういうやつですね。

できるところからやっていきましょう、ということで検討を進めていきます。

  • appengine package
    • こいつがgo.modに出てこなくなるのが目標
    • 消すのが難しいのは WithAPICallFunc を活用している場合か
  • aetest package
    • 他のものの移行が進めば自然と消えるはず
    • AppEngine Contextが不要になればまぁいらないはず
  • blobstore package
    • おおむねGCSに移行可能なはず
  • capability package
    • おおむねどのアプリでも使ってない
  • channel package
    • goのchannelではなくWebSocketっぽい機能のアイツ
    • かなり前から将来性無しとされていたのでみんなFirebaseとか使ってるはず
  • cloudsql package
    • RDB使ってない
    • 公式にはdatabase/sql使えということらしい
  • datastore package
  • delay package
    • デバッガビリティの観点でtaskqueueしか使ってなかったので問題なし
  • file package
    • 環境変数とかで値渡せばよさそう
  • image package
    • 移行先無し
    • 画像のリサイズとかをわりとコレに依存していたりして悩ましい
  • log package
    • 本記事で詳しく検討します
    • 案外高機能！
  • mail package
    • 結構昔からコレを使うのやめて移行先探せとアナウンスされているやつ
    • 技術書典の場合sendgridに移行した
    • 社内の場合Slackで通知でいいでしょ
  • memcache package
  • module package
    • Admin APIで代替できるはず
    • 全然使ってない
  • remote_api package
    • 懐かしい…
    • 普通にGoogle Cloudクライアントライブラリをローカルから叩けばOK
  • search package
    • Full Text Searchは望まれていたがかなり昔に機能追加が止まっている
    • 自分で何かしらの代替を構築する必要がある…というのはかなり前から既知だった
    • 公式ではElasticSearchが紹介されていた
  • socket package
    • AppEngineの制約上必要だったが今はもう普通にnet使えばOK
  • taskqueue package
    • cloudtasksに移行
    • DatastoreのTransactionにTQを参加させるのができなくなる
  • urlfetch package
  • user package
    • 何気にこれも移行が難しい
    • 公式の提案ではFirebase Authenticationなどがあるようです
    • IAPでもある程度置き換えられる可能性が…という噂を聞いた(よく調べてない
    • 機能だけ移行するならまぁ自前実装でもなんとか
    • /_ah/login 関連機能&UIは開発・運用上、代替するのが難しい…
    • ローカルでの開発時に任意のアカウントでログインしたフリができた
  • xmpp package
    • 使ったことない…！
    • 公式でもまったく言及されていない
  • cron

AppEngine log package 置き換えの検討

公式にはlogが移行先と案内されています。しかしながら、AppEngineのlog packageの便利さとは天と地ほどの差があり、到底代替にはなりえません。公式としてはcloud.google.com/go/loggingを案内したほうがよいのではないかと思います。
ログをQueryする機能についてはまったく使っていないのでここでは扱いません。

本記事では標準出力にログを出すといい感じになるところを目指します。依存するライブラリやプラットフォームがないほうが気楽ですからね。

まずは便利に使っている機能と、自前でなんとかする場合の作戦を書き出してみます。

  1. request logが正しく出力される
    • アプリ内からレスポンスサイズや処理時間を計測するのは難しい
    • プラットフォーム側から自動的に出力されると嬉しい
  2. request logとapplication logが紐付き、1リクエスト処理中に出力した全てのログがグループ化される
    • 実装方法は複数ありそう
    • リクエスト処理中のログをバッファする方式
  3. ログを逐次バラバラに出力しプラットフォーム側でグルーピングする方式
  4. application logでseverityが高いログを出力すると、request logのseverityに伝播される
    • request logのseverityがアプリ側から操作できる必要がある
    • プラットフォームの出力に任せると現状操作できない
    • どうしても実現したかったらrequest logもアプリ側から出力する必要がある
  5. long running taskでも実行途中のログが参照できる
    • バッファ方式だと処理中のログはemitされていないので参照できない
  6. ログをサンプリングした時にグループの一部分が欠損したりしない
    • バラバラ方式だとサンプリング方法次第で欠損が発生する可能性がある？

AppEngineという環境に慣れすぎて、これら機能が提供されるのは当たり前だと思っていました。しかし現実はそんなことはなく、人々はもっとプアなログ環境で生きていたのです。あなおそろしや！

long running taskの例 タスクが走っている途中でもその時までに出力されたログを見ることができる。便利。

f:id:vvakame:20190521161610p:plain
long runnning taskの処理中にログが確認できる例

AppEngineのlog packageとまったく同等の機能を提供するのは大変難しそうなことが既に察せられます。つまり、何かを諦める必要がありそうです。

この分野について、すでにGAEのログに憧れてという記事が書かれています。この偉大な先駆者の仕事を後追いし、後はAppEngineの使い勝手にどう近づき、落とし所を見つけるかを考えていきます。

実際にやってみた

グループ化の条件( GAEのログに憧れて より引用 大本はこちら)

  1. parent, child ともに同一 GCP プロジェクトのログであること
  2. parent, child で log ID (logName) が別々であること
  3. parent, child で Monitored Resource が同一であること (つまりログが吐かれた場所が同じであること)
  4. parent に httpRequest.requestUrl が設定されてること (つまり parent は HTTP のアクセスログであること)
  5. child のログの時刻が、parent のリクエスト処理内の時刻であること (つまり child.timestamp >= parent.timestamp — parent.httpRequest.latency && child.timestamp <= parent.timestamp)
  6. trace が同一であること

本記事では、parentのことをrequest log、childのことをapplication logと書いています。

logNameのルールは次の通り

  • 標準出力
    • projects/[PROJECT_ID]/logs/stdout
  • 標準エラー出力
    • projects/[PROJECT_ID]/logs/stderr
  • プラットフォーム側が出力するrequest log
    • projects/[PROJECT_ID]/logs/appengine.googleapis.com%2Frequest_log

request log, application logでlogNameを分けるには、お手軽にやるには標準出力と標準エラー出力を使い分ければよいということになります。
logNameを上書きする方法がないのが残念です。
projects/[PROJECT_ID]/logs/stdout/{任意の名前} みたいなlogNameにさせてくれる自由度があると嬉しいですね。

標準出力を使う場合、Monitored Resourceは何も気にせずとも統一されます。

{
labels: {
module_id:  "[MODULE_ID]"
project_id: "[PROJECT_ID]"
version_id: "[VERSION_ID]"
zone:       "[ZONE_ID]"
}
type:  "gae_app"
}

request logを自分で出力する時のduration(latency)の出力はgoogle.protobuf.Durationにあわせ、 {“seconds”: int64, “nanos”: int32} 的なデータを出力する必要があります。
timestampと符号化方法をごっちゃにしてしまうと長時間悩むことになるので注意しましょう。

trace(logging.googleapis.com/trace)に使える値と、ついでにspanId(logging.googleapis.com/spanId)に使える値はOpenCensusを利用します。traceの値はプラットフォーム側が生成し X-Cloud-Trace-Context ヘッダとして渡してくれているので、 OpenCensus本体とcontrib.go.opencensus.io/exporter/stackdriver/propagationを使ってTraceとその時のSpanIDを取り出し利用します。

これで諸条件が揃い、うまいこと動きます。

cloud.google.com/go/logging を使ってログ出力する場合は、monitoredResourceとtrace、spanIdを自分でケアしてあげる必要があります。

試した結果

試して、結果をGCPのCloud ConsoleのLoggingの画面で挙動を見ました。

  • 自前でrequest logを出してみた
    • アプリのいくつかのmetricsがアプリ内からは正しく計測できない
      • 処理中に処理時間測るのは無理があるよ…
      • レスポンスサイズ測ろうにもヘッダのサイズが正確にはわからん…
    • プラットフォーム側のrequest logも存在するが問題ない
      • その場合、両方にapplication logがぶら下がるし自分以外のrequest logもぶら下がる
      • 相互に相手がapplication logみたいな振る舞いになる
    • プラットフォームのrequest logはrequest受けた時点に出力した判定
    • アプリで出したrequest logは僕のベタ実装だとrequest終わる時に出力した判定
  • AppEngineのプラットフォームが出力するrequest logを使ってみた
    • severityが変更できない
  • ログの各行毎にSourceLocationが出力できた
    • AppEngine Log APIだと”どこで出したログだよ！”ってなることが割とあった
  • Structured Loggingできた
    • AppEngine Log APIだとベタの文字列だけ
  • 標準出力に出力するのはLogEntryじゃなくてこっちを使う
    • 標準出力をlogging agentが回収してくれてStackdriver Loggingに送られることを意識する
      • ドキュメントにはAppEngineの近くにStackdriver logging agentがいるとは書いてないけど挙動を見る限りだいたい同じ動作のものが潜んでそう
  • Cloud Runでも同じやり方でうまくいく
    • logging agentが動いている環境なら全て同様なのでは？
    • request logもCloud Runはプラットフォーム側がAppEngineと同じく出力してくれる
  • long running taskについては諦める
  • ログ逐次バラバラ出力方式 & ログに除外率を設定した場合の振る舞い
    • 除外する/しないはtrace毎に決定されているっぽい
    • 除外率50%にした場合、request logが50%でサンプリングされる
    • それにぶら下がるapplication logは全部出力される
    • つまり、除外設定した時にログの部分的欠損を心配する必要はない
  • エラー出力はちょっと雑魚になる
    • 昔はログ中のスタックトレースがStackdriver Debuggerへのリンクを作ってくれた気がするが…？
    • 書いてあるとおりmessageにスタックトレース突っ込んでおけばStackdriver Error Report側では拾ってくれる
    • panic時のログは自分でrecoverしてapplication logとして出力しないとリクエストと紐付かなくなるはず
  • jsonPayloadに自由な値を詰めすぎるとBigQueryにsinkした時に困る
    • BQのschemaが1つに定まらないようなjsonPayloadを流すとBQが困る
    • Google先生がメールでsinkできないから直して！って言ってくる
      • [ACTION REQUIRED] Stackdriver Logging export config error in (PROJECT_ID). みたいなタイトル
    • 自由に開発してここを無事に過ごすのすごく難しくない…？
      • ハンガリアン記法か！？(んなわけない
    • jsonPayload.message と jsonPayload.jsonData だけ使うようにしてBQ側で JSON_EXTRACT とかを使う運用がざっくり楽な可能性
  • jsonPayload.message しか出力しないと textPayload 扱いになるのでBQ上でクエリ投げたいなら常に jsonPayload 扱いになるよう工夫したほうがよいかも

request logとapplication logを出してみた結果。
レスポンスサイズや処理時間がうまく計測できていない。そりゃそうだ。

f:id:vvakame:20190521161617p:plain
request logを自分で出してみた例

困っていること

  • stdout/stderrで出したログはlogNameが変更できない
    • 05/23 記事末尾に追記あり
  • Stackdriver LoggingのWeb UIでの検索が今までと同様には使えない
    • path:/ といった絞りこみが意図どおりにできない
      • protoPayload.resource:"/" と同等の意味だった
      • httpRequest.requestUrl:"/" を代わりに使う必要がある
      • 高度なフィルタの書き方に慣れる必要がある…！
    • request log のseverityによる絞り込みが難しい
      • application logのseverityで引っ掛けてそこからtraceを調べ高度なフィルタで全体を調べる みたいなことをする必要がある
    • BigQueryに投げ込んでBigQueryで見る方法覚えたほうが楽…？
    • 監視系を旧構造に依存して組んでる場合移行に時間がかかるという話があった

結論

  • AppEngine Log API時代とまったく同じ運用をするのは諦める
  • request logはプラットフォーム側が出力するのに任せる
    • severityを操作するのは現時点では諦める
    • 高度なフィルタの使い方を泣きながら覚える
  • long running task対応は諦める
    • jsonPayloadで頑張って自力でワークアラウンドを模索する方向性かなぁ
  • これを踏まえてlogging agent+application logなロギングライブラリ作ればよさそう
  • 検討に付き合ってくれたGCPUG Slackの皆さんどうもありがとう！

更に検討できそうなこと

  • insertIdを活用して、同一のログを複数回バラバラ方式+バッファ方式毎に出力することで両方式のうまいとこ取りが出来る可能性が微粒子レベルで存在している…？
    • そもそもStackdriverのLogEntry互換の方法だとバッファ方式は実装できないのでは…？

おまけ:AppEngine以外でやってみた

Cloud Runで同じコードを動かしてみたら普通に同じようにできた。

f:id:vvakame:20190521161613p:plain
Cloud Runで試して得られたログ

終わりに

MERPAY TECH OPENNESS MONTH の4日目の記事はcowsysさんによる「datadogと切り分け太郎（仮）」です！つい趣味に走ってStackdriverの話をしてしまいましたがメルペイではDatadogを使っているため、正統派メルペイ感が期待できます！

05/23 追記

GCPの化身から情報が来たので…。どこで知るのそういう情報…！公式のドキュメントにはこのネタは書いてありません。

まぁとりあえずやってみましょう。
出力するログのフォーマットは本記事で既に紹介した通りです。

/var/log/test1.log というファイルに対してログを出力するとlogName projects/[PROJECT_ID]/logs/%2Fvar%2Flog%2Ftest1.log として出力されます。
これをBQにsinkすると _var_log_test1_log_20190523 というテーブルになりました。
jsonPayload が異なる場合、出力先のファイルを分けることでBQ上のスキーマの不一致を避けるという選択肢も生まれました。

/tmp と違って、 /var/log はtmpfsではないそうで、F1のメモリリミット128MBを超えて、少なくとも900MB程度は書き込むことができました。
よって、stdoutを使う時と同様に、メモリのことを不必要に気にする必要もなさそうです。

  • 問題なく書けた
    • /var/log/test1.log
    • /var/log/appengine/test2.log
    • /var/log/app_engine/app/app-test3.log
    • /var/log/app_engine/app/custom_logs/test4.log
    • /var/log/test8.txt
      • 拡張子 .log じゃなくてもOKだった
  • (当然)ダメだった
    • /var/test5.log
      • 怒られが発生した read-only file system
    • /test6.log
      • 怒られが発生した read-only file system
    • /tmp/test7.log
      • ログとして認識されなかった

普通によさそうですね！

本文から参照されなかったReference
  • X
  • Facebook
  • linkedin
  • このエントリーをはてなブックマークに追加

Related article