LoginSignup
27
17

More than 5 years have passed since last update.

Google Cloud Platform(2)Advent Calendar 2016Day 15
@soundTricker(keisuke ohashi)

Stackdriver Logging(Log Viewer)で見た目の良いログを出力するためのあれこれ

Posted at

この記事は @chidakiyo さんの GAE Flexible Environmentでアプリケーションのログを出力するためにやったこと。
 が記事にしてくれたので、もう少しマニアックなところを載せようと思って書いたものです。

GAE FEでのログ出力に関しては上記記事を見ると良いと思います。

GAEのログに憧れて

GAE FEや、Stackdriver Logging APIを利用して、Log Viewerでログを見れる状態にするとあることに気が付きます。

GAEのログ
Kobito.vO8zuM.png

GAE以外のログ
Kobito.116tC4.png

そうです。 GAEのログには以下のような特徴があります。

  1. 1リクエスト中のログをまとめられる
  2. POSTやステータスコードなどHTTP Requestに関連した情報が表示される
  3. msecまでしっかり出ている

超素敵ですね。 FEのログでも同じようなログが出したいですね！
今回はFEできれいなログを出せるようにゴニョゴニョしたいと思います。

まとめ

先にまとめを書いておくときれいなログを出すためには

  1. jsonPayloadを利用する
  2. "@type": "type.googleapis.com/google.appengine.logging.v1.RequestLog" をつける
  3. http系のプロパティを設定する
  4. lineプロパティに配列でメッセージを入れる

できれいなログが出せます。

FEできれいなログを出すための道のり

このセクションはきれいなログを出すためにアレコレした道のりです。
技術的にはあんまり情報無いので読まなくても良いです。

LogFormatを探す

きれいな出すにはどうすれば良いのかと思いStackdriver Logging APIのドキュメントを見てみました。

が....

ある程度ログのフォーマット(≒Strickdriver Logging APIのjsonフォーマット)については記載がありますが、どのようなログフォーマットでどのような見た目になるかの記載はありません。

そこでLog ViewerのGAEのログをもう一度見てます。

Kobito.l2lrtT.png

上記のようにログフォーマットが表示されていますのでこれを修正してStackdriver Logging APIに投げて同じようなログがでるか試してみましょう。

表示されていたログ(一部修正)

ログ.json
{
 "protoPayload": {
  "@type": "type.googleapis.com/google.appengine.logging.v1.RequestLog",
  "appId": "s~appid",
  "versionId": "1-34-6",
  "requestId": "111111",
  "ip": "104.155.110.139",
  "startTime": "2016-12-11T03:34:33.931996Z",
  "endTime": "2016-12-11T03:34:33.993449Z",
  "latency": "0.061453s",
  "megaCycles": "11",
  "method": "GET",
  "resource": "/hoge/fuga",
  "httpVersion": "HTTP/1.1",
  "status": 302,
  "responseSize": "325",
  "userAgent": "GoogleStackdriverMonitoring-UptimeChecks(https://cloud.google.com/monitoring",
  "urlMapEntry": "page.main.app",
  "host": "default.appid.appspot.com",
  "cost": 0.0000001,
  "instanceIndex": -1,
  "instanceId": "4444",
  "line": [
   {
    "time": "2016-12-11T03:34:33.991600Z",
    "severity": "INFO",
    "logMessage": "REDIECT URI : /en?"      
   }
  ],
  "appEngineRelease": "1.9.48",
  "traceId": "3333",
 },
 "insertId": "2016-12-10|19:34:36.536369-08|192.168.11.1|2013856561",
 "httpRequest": {
  "status": 302
 },
 "resource": {
  "type": "gae_app"    ,
  "labels": {
   "version_id": "1-34-6"     ,
   "module_id": "default"     ,
   "zone": "us2"     
  },
 },
 "timestamp": "2016-12-11T03:34:33.931996Z",
 "severity": "INFO"   ,
 "labels": {
  "appengine.googleapis.com/request_id": "111111"    ,
  "appengine.googleapis.com/clone_id": "222222"    ,
 },
 "logName": "projects/appid/logs/appengine.googleapis.com%2Frequest_log"   ,
 "operation": {
  "id": "111111"    ,
  "producer": "appengine.googleapis.com/request_id"    
 }
}

GAEのログを修正してAPIを叩いてみる

ではまず上記のJSONを展開しAPIが受け取れる形にしてAPI Explorerを利用してStackdriver logging API v2 logging.entries.writeに投げてみます。

投げるJSON ※実際に投げる場合はapp_idを変換してください。

投げる.json
{
  "entries": 
  [
    {
 "protoPayload": {
  "@type": "type.googleapis.com/google.appengine.logging.v1.RequestLog",
  "appId": "s~appid",
  "versionId": "1-34-6",
  "requestId": "111111",
  "ip": "104.155.110.139",
  "startTime": "2016-12-11T03:34:33.931996Z",
  "endTime": "2016-12-11T03:34:33.993449Z",
  "latency": "0.061453s",
  "megaCycles": "11",
  "method": "GET",
  "resource": "/hoge/fuga",
  "httpVersion": "HTTP/1.1",
  "status": 302,
  "responseSize": "325",
  "userAgent": "GoogleStackdriverMonitoring-UptimeChecks(https://cloud.google.com/monitoring",
  "urlMapEntry": "page.main.app",
  "host": "default.appid.appspot.com",
  "cost": 0.0000001,
  "instanceIndex": -1,
  "instanceId": "4444",
  "line": [
   {
    "time": "2016-12-11T03:34:33.991600Z",
    "severity": "INFO",
    "logMessage": "REDIECT URI : /en?"      
   }
  ],
  "appEngineRelease": "1.9.48",
  "traceId": "3333",
 },
 "insertId": "2016-12-10|19:34:36.536369-08|192.168.11.1|2013856561",
 "httpRequest": {
  "status": 302
 },
 "resource": {
  "type": "gae_app"    ,
  "labels": {
   "version_id": "1-34-6"     ,
   "module_id": "default"     ,
   "zone": "us2"     
  },
 },
 "timestamp": "2016-12-11T03:34:33.931996Z",
 "severity": "INFO"   ,
 "labels": {
  "appengine.googleapis.com/request_id": "111111"    ,
  "appengine.googleapis.com/clone_id": "222222"    ,
 },
 "logName": "projects/appid/logs/appengine.googleapis.com%2Frequest_log"   ,
 "operation": {
  "id": "111111"    ,
  "producer": "appengine.googleapis.com/request_id"    
 }
}
  ]
}

では結果を見てみましょう。

Kobito.5RXTyK.png

見事にできてますね！

FEでこのログを流してみる

では実際にこのログをFEで流しています。json形式のログを流す場合は
ファイル名を.jsonにする必要があり、ファイル出力先は/var/log/app_engineの直下か/var/log/app_engine/custom_logs下にします。

今回はわざわざアプリケーションからやるのは大変なので直接sshで入ってファイルを作成して流してみたいと思います。

まずFEにSSHします。

FEへはCloud ConsoleからSSHできます。

Kobito.6WGMq5.png

次にアプリケーションのコンテナに入ります。

feのコンテナに入る
$ sudo docker exec -it gaeapp bash

適当にログを置きます。

feのコンテナ
$ vi /var/log/app_engine/custom_logs/test.log.json

以下を置きます。 ※app_idとかは適当に修正してください。 実際は1行です。

出力する予定のjson
{
  "@type": "type.googleapis.com/google.appengine.logging.v1.RequestLog",
  "appId": "s~app_id",
  "versionId": "1-34-6",
  "requestId": "111111",
  "ip": "104.155.110.139",
  "startTime": "2016-12-11T03:34:33.931996Z",
  "endTime": "2016-12-21T03:34:33.993449Z",
  "latency": "0.061453s",
  "megaCycles": "11",
  "method": "GET",
  "resource": "/hoge/fuga",
  "httpVersion": "HTTP/1.1",
  "status": 302,
  "responseSize": "325",
  "userAgent": "GoogleStackdriverMonitoring-UptimeChecks(https://cloud.google.com/monitoring",
  "urlMapEntry": "page.main.app",
  "host": "default.app_id.appspot.com",
  "cost": 0.0000001,
  "instanceIndex": -1,
  "instanceId": "4444",
  "line": [
   {
    "time": "2016-12-21T03:34:33.991600Z",
    "severity": "INFO",
    "logMessage": "REDIECT URI : /en?"      
   }
  ],
  "appEngineRelease": "1.9.48",
  "traceId": "3333"
 }

少し待ったらログコンソールを見てみましょう！

Kobito.rLrfW4.png

以下のように新しいログが追加されています。

Kobito.b5qgGd.png

素晴らしい！

ということできれいなログを出すためには

きれいなログを出すためには以下の様なログで1行で出力します。

{
  "@type": "type.googleapis.com/google.appengine.logging.v1.RequestLog",
  "appId": "s~app_id",
  "versionId": "1-34-6",
  "requestId": "111111",
  "ip": "104.155.110.139",
  "startTime": "2016-12-11T03:34:33.931996Z",
  "endTime": "2016-12-21T03:34:33.993449Z",
  "latency": "0.061453s",
  "megaCycles": "11",
  "method": "GET",
  "resource": "/hoge/fuga",
  "httpVersion": "HTTP/1.1",
  "status": 302,
  "responseSize": "325",
  "userAgent": "GoogleStackdriverMonitoring-UptimeChecks(https://cloud.google.com/monitoring",
  "urlMapEntry": "page.main.app",
  "host": "default.app_id.appspot.com",
  "cost": 0.0000001,
  "instanceIndex": -1,
  "instanceId": "4444",
  "line": [
   {
    "time": "2016-12-21T03:34:33.991600Z",
    "severity": "INFO",
    "logMessage": "REDIECT URI : /en?"      
   }
  ],
  "appEngineRelease": "1.9.48",
  "traceId": "3333"
 }

なお一部のプロパティなどは無くて良いはずです。@typeが無いと見た目が崩れました。
また、messageというプロパティが1階層目に含まているとtextログ扱いになってしまいします。(fluentd-google-cloud-pluginの仕様)

またlineに複数のログを詰めれば複数のログをまとめて出すことが可能ですが、
GAEの様に1リクエスト毎にログを出すためには、1リクエスト中のログをバッファリングしておき、リクエストの処理終了時にログを出力する必要があり、ちょい手間が必要です。

では良いFEライフを！

27
17
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
27
17