Nomad に載った API サーバーのログ監視を考える

これの続き
blog.luispc.com

ログ監視、ここではアプリケーションのエラーログについて

Slack に通知をする

これを使う。
github.com

fluentd.conf

<source>
  @type forward
  port 24224
  bind 0.0.0.0
</source>

<filter *.**>
  @type parser
  <parse>
    @type json
    json_parser oj
    time_format %Y-%m-%dT%H:%M:%S
  </parse>
  key_name log
  replace_invalid_sequence true
  emit_invalid_record_to_error true
  reserve_data true
</filter>

<filter *.**>
  @type grep
  <exclude>
    key caller
    pattern /^$/
  </exclude>
</filter>

<match **.*>
  @type copy
  <store>
    @type elasticsearch
    host elasticsearch.luis.local
    port 9200
    logstash_format true
    logstash_prefix fluentd
    logstash_dateformat %Y%m%d
    include_tag_key true
    type_name fluentd
    tag_key @log_name
    flush_interval 1s
    log_es_400_reason true
    <buffer>
      @type memory
      flush_thread_count 4
    </buffer>
  </store>
  <store>
    @type slack
    webhook_url 
    channel easyuploader
    username "easyuploader api"
    color danger
    icon_url 
    flush_interval 1s
    title_keys func
    title "Error in %s"
    message_keys msg,func,error,client,ua
    message "*%s in %s*\n*err:* %s\n*ip:* %s\n*ua:* %s"
    <buffer>
      @type memory
      flush_thread_count 4
    </buffer>
  </store>
</match>

ネストされた JSON を展開する

{
  "_index": "fluentd-20200106",
  "_type": "_doc",
  "_id": "XsbPem8B4S2PoHfN9N2k",
  "_version": 1,
  "_score": null,
  "_source": {
    "container_id": "6b35a88f599432b461bfd7f1cf54a167f60840deb5dfb409a066739cb891de18",
    "container_name": "/prd-31491e51-65c3-2893-afc0-4bc4f8219a5b",
    "source": "stderr",
    "log": "{\"level\":\"error\",\"ts\":1578312131.531616,\"caller\":\"lib/logger.go:22\",\"msg\":\"GetUploadInfo\",\"func\":\"Delete\",\"error\":\"record not found\",\"client\":\"\",\"ua\":\"Mozilla/5.0 (iPad; CPU OS 10_3_3 like Mac OS X) AppleWebKit/603.3.8 (KHTML, like Gecko) Version/10.0 Mobile/14G60 Safari/602.1\",\"stacktrace\":\"github.com/rluisr/easyuploader_api/lib.logger\\n\\t/go/src/easyuploader_api/lib/logger.go:22\\ngithub.com/rluisr/easyuploader_api/lib.ErrorWithResponseInternalServer\\n\\t/go/src/easyuploader_api/lib/logger.go:30\\ngithub.com/rluisr/easyuploader_api/resource.Delete\\n\\t/go/src/easyuploader_api/resource/delete.go:22\\nmain.main.func9\\n\\t/go/src/easyuploader_api/main.go:73\\ngithub.com/gin-gonic/gin.(*Context).Next\\n\\t/go/pkg/mod/github.com/gin-gonic/gin@v1.4.0/context.go:124\\ngithub.com/gin-gonic/gin.RecoveryWithWriter.func1\\n\\t/go/pkg/mod/github.com/gin-gonic/gin@v1.4.0/recovery.go:83\\ngithub.com/gin-gonic/gin.(*Context).Next\\n\\t/go/pkg/mod/github.com/gin-gonic/gin@v1.4.0/context.go:124\\ngo.elastic.co/apm/module/apmgin.(*middleware).handle\\n\\t/go/pkg/mod/go.elastic.co/apm/module/apmgin@v1.5.0/middleware.go:132\\ngithub.com/gin-gonic/gin.(*Context).Next\\n\\t/go/pkg/mod/github.com/gin-gonic/gin@v1.4.0/context.go:124\\ngithub.com/gin-gonic/gin.(*Engine).handleHTTPRequest\\n\\t/go/pkg/mod/github.com/gin-gonic/gin@v1.4.0/gin.go:389\\ngithub.com/gin-gonic/gin.(*Engine).ServeHTTP\\n\\t/go/pkg/mod/github.com/gin-gonic/gin@v1.4.0/gin.go:351\\nnet/http.serverHandler.ServeHTTP\\n\\t/usr/local/go/src/net/http/server.go:2802\\nnet/http.(*conn).serve\\n\\t/usr/local/go/src/net/http/server.go:1890\"}",
    "level": "error",
    "ts": 1578312131.531616,
    "caller": "lib/logger.go:22",
    "msg": "GetUploadInfo",
    "func": "Delete",
    "error": "record not found",
    "client": ",
    "ua": "Mozilla/5.0 (iPad; CPU OS 10_3_3 like Mac OS X) AppleWebKit/603.3.8 (KHTML, like Gecko) Version/10.0 Mobile/14G60 Safari/602.1",
    "stacktrace": "github.com/rluisr/easyuploader_api/lib.logger\n\t/go/src/easyuploader_api/lib/logger.go:22\ngithub.com/rluisr/easyuploader_api/lib.ErrorWithResponseInternalServer\n\t/go/src/easyuploader_api/lib/logger.go:30\ngithub.com/rluisr/easyuploader_api/resource.Delete\n\t/go/src/easyuploader_api/resource/delete.go:22\nmain.main.func9\n\t/go/src/easyuploader_api/main.go:73\ngithub.com/gin-gonic/gin.(*Context).Next\n\t/go/pkg/mod/github.com/gin-gonic/gin@v1.4.0/context.go:124\ngithub.com/gin-gonic/gin.RecoveryWithWriter.func1\n\t/go/pkg/mod/github.com/gin-gonic/gin@v1.4.0/recovery.go:83\ngithub.com/gin-gonic/gin.(*Context).Next\n\t/go/pkg/mod/github.com/gin-gonic/gin@v1.4.0/context.go:124\ngo.elastic.co/apm/module/apmgin.(*middleware).handle\n\t/go/pkg/mod/go.elastic.co/apm/module/apmgin@v1.5.0/middleware.go:132\ngithub.com/gin-gonic/gin.(*Context).Next\n\t/go/pkg/mod/github.com/gin-gonic/gin@v1.4.0/context.go:124\ngithub.com/gin-gonic/gin.(*Engine).handleHTTPRequest\n\t/go/pkg/mod/github.com/gin-gonic/gin@v1.4.0/gin.go:389\ngithub.com/gin-gonic/gin.(*Engine).ServeHTTP\n\t/go/pkg/mod/github.com/gin-gonic/gin@v1.4.0/gin.go:351\nnet/http.serverHandler.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2802\nnet/http.(*conn).serve\n\t/usr/local/go/src/net/http/server.go:1890",
    "@timestamp": "2020-01-06T12:23:11.429817368+00:00",
    "@log_name": "eu-prd-api"
  },
  "fields": {
    "@timestamp": [
      "2020-01-06T12:23:11.429Z"
    ]
  },
  "sort": [
    1578313391429
  ]
}

log の中身に全部入ってるが、それを ↓ によってパースしている。
その結果、msg とか func が展開された。

<filter *.**>
  @type parser
  <parse>
    @type json
    json_parser oj
    time_format %Y-%m-%dT%H:%M:%S
  </parse>
  key_name log
  replace_invalid_sequence true
  emit_invalid_record_to_error true
  reserve_data true
</filter>

が、パラメータとかはよく分かってない。

アプリのログ以外は無視したい

<filter *.**>
  @type grep
  <exclude>
    key caller
    pattern /^$/
  </exclude>
</filter>

caller がないときは無視する。

Elasticsearch に送りながら Slack に送る

<match **.*>
  @type copy
  <store>
    @type elasticsearch
    host elasticsearch.luis.local
    port 9200
    logstash_format true
    logstash_prefix fluentd
    logstash_dateformat %Y%m%d
    include_tag_key true
    type_name fluentd
    tag_key @log_name
    flush_interval 1s
    log_es_400_reason true
    <buffer>
      @type memory
      flush_thread_count 4
    </buffer>
  </store>
  <store>
    @type slack
    webhook_url 
    channel easyuploader
    username "easyuploader api"
    color danger
    icon_url
    flush_interval 1s
    title_keys func
    title "Error in %s"
    message_keys msg,func,error,client,ua
    message "*%s in %s*\n*err:* %s\n*ip:* %s\n*ua:* %s"
    <buffer>
      @type memory
      flush_thread_count 4
    </buffer>
  </store>
</match>

確認

Slack 上では必要最低限な情報に留めて、Stack trace は Kibana 上で確認できるように ts を載せる。
出来れば footer, author で Kibana の該当レコードへのリンクとか貼りたい。

Tips

これを実現するために改修したこと

ロガー

func logger(funcName, msg, clientIP, ua string, err error) {
    slogger.Errorw(msg,
	"func", funcName,
	"error", err,
	"client", clientIP,
	"ua", ua)
}

func ErrorWithResponseInternalServer(c *gin.Context, funcName, msg, resMsg string, err error) {
    logger(funcName, msg, c.ClientIP(), c.Request.UserAgent(), err)
    c.JSON(http.StatusInternalServerError, resMsg)
}

func ErrorWithResponseBadRequest(c *gin.Context, funcName, msg, resMsg string, err error) {
    logger(funcName, msg, c.ClientIP(), c.Request.UserAgent(), err)
    c.JSON(http.StatusBadRequest, resMsg)
}

Gin を Graceful shutdown に対応させる

func main() {
    router := gin.New()

    srv := &http.Server{
	Addr:    addr,
	Handler: router,
}

    go func() {
	if err := srv.ListenAndServe(); err != nil {
	    log.Printf("listen: %s\n", err)
	}
    }()

    quit := make(chan os.Signal, 1)
    signal.Notify(quit, os.Interrupt)
    <-quit
    log.Println("Shutdown Server ...")

    ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second)
    defer cancel()
    if err := srv.Shutdown(ctx); err != nil {
	log.Fatal("Server Shutdown:", err)
    }
    log.Println("Server exiting")
}

Gin が Proxy 配下にいるときにクライアント IP を正しく出力する

router.ForwardedByClientIP = true

ちなみに中身はリクエストヘッダーを見てる

// ClientIP implements a best effort algorithm to return the real client IP, it parses
// X-Real-IP and X-Forwarded-For in order to work properly with reverse-proxies such us: nginx or haproxy.
// Use X-Forwarded-For before X-Real-Ip as nginx uses X-Real-Ip with the proxy's IP.
func (c *Context) ClientIP() string {
    if c.engine.ForwardedByClientIP {
	clientIP := c.requestHeader("X-Forwarded-For")
	clientIP = strings.TrimSpace(strings.Split(clientIP, ",")[0])
	if clientIP == "" {
	    clientIP = strings.TrimSpace(c.requestHeader("X-Real-Ip"))
	}
	if clientIP != "" {
	    return clientIP
	}
    }

    if c.engine.AppEngine {
	if addr := c.requestHeader("X-Appengine-Remote-Addr"); addr != "" {
	    return addr
	}
    }

    if ip, _, err := net.SplitHostPort(strings.TrimSpace(c.Request.RemoteAddr)); err == nil {
	return ip
    }

    return ""
}

Traefik で X-Forwarded-* を流さずにそのまま流す

今回の場合は Traefik が Nginx の下にいる。

[entryPoints.http.forwardedHeaders]
      insecure = true

insecure 以外にも、trustedIPs でも指定できるけど両方指定すると動かないので注意。
注意深い人は trustedIPs の方が良いと思う。

docs.traefik.io

GoLand から直接 はてなブログにコピペするとインデントがズレる