X-Forwarded-For の正しい取り扱い方とCloudFrontを通したときのクライアントIPの取得方法

X-Forwarded-For ってなに?

プロキシやロードバランサーを通してサーバーにアクセスすると、サーバーから見たクライアントIPはプロキシのものになってしまいます。それを解決するために、プロキシで X-Forwarded-For HTTP Header にクライアントの Remote IP を記録して、サーバーではその値を見ることでクライアントIPを取得できるようになります。

f:id:mrk21:20200806213221p:plain

X-Forwarded-For からクライアントIPを取得する

X-Forwarded-For HTTP Header は以下のようなフォーマットになっています。

X-Forwarded-For: <client>, <proxy1>, ...

そのためクライアントIPを得るためには X-Forwarded-For の先頭のIPを参照すればよさそうです。

しかし、この方法には問題があります。というのもプロキシでは X-Forwarded-For が存在していたのなら末尾に接続元のIPを追加するので、悪意のあるクライアントが X-Forwarded-For に任意のIPを指定することによってアクセス元IPを偽装することが可能になります(IPスプーフィング)。たとえば、サーバー側で X-Forwarded-For の値を元にIP制限をかけていた場合に突破される可能性があります。

f:id:mrk21:20200806213245p:plain

X-Forwarded-For からクライアントIPをセキュアに取得する

ではどうするのでしょうか。たとえば Rails では信頼できるプロキシのIPを事前に登録しておき、X-Forwarded-For のIPリストからその信頼できるプロキシのIPを除去し、末尾のIPをクライアントIPとして採用するというものがあります。

たとえば、サーバー到達時点の X-Forwarded-For の値が以下のようなものであったとします。

X-Forwarded-For: <偽装されたIP> <クライアントの真のIP>, <プロキシ1のIP>, <プロキシ2のIP>

そして、信頼できるプロキシのIPリストには以下が登録されているとします。

信頼できるプロキシのIPリスト := [プロキシ1のIP, プロキシ2のIP]

このような条件下では次の動作をします。まず、X-Forwarded-For から信頼できるプロキシのIPリストに登録しているIPを除去します。

X-Forwarded-For: <偽装されたIP> <クライアントの真のIP>

そして、その末尾のIPを取得します。これはクライアントの真のIPとなるので、偽装されたIPを取得することなく、悪意のあるクライアントからの攻撃を防げます。

f:id:mrk21:20200806215512p:plain

Railsでの詳細

ActionDispatch::Request#remote_ip では以下のようにして、信頼できるIPアドレスX-Forwarded-For から取得します。

module ActionDispatch
  class RemoteIp
    ...
    def call(env)
      req = ActionDispatch::Request.new env
      req.remote_ip = GetIp.new(req, check_ip, proxies)
      @app.call(req.env)
    end
    ...
    class GetIp
      ...
      def calculate_ip
        # Set by the Rack web server, this is a single value.
        remote_addr = ips_from(@req.remote_addr).last

        # Could be a CSV list and/or repeated headers that were concatenated.
        client_ips    = ips_from(@req.client_ip).reverse
        forwarded_ips = ips_from(@req.x_forwarded_for).reverse

        # +Client-Ip+ and +X-Forwarded-For+ should not, generally, both be set.
        # If they are both set, it means that either:
        #
        # 1) This request passed through two proxies with incompatible IP header
        #    conventions.
        # 2) The client passed one of +Client-Ip+ or +X-Forwarded-For+
        #    (whichever the proxy servers weren't using) themselves.
        #
        # Either way, there is no way for us to determine which header is the
        # right one after the fact. Since we have no idea, if we are concerned
        # about IP spoofing we need to give up and explode. (If you're not
        # concerned about IP spoofing you can turn the +ip_spoofing_check+
        # option off.)
        should_check_ip = @check_ip && client_ips.last && forwarded_ips.last
        if should_check_ip && !forwarded_ips.include?(client_ips.last)
          # We don't know which came from the proxy, and which from the user
          raise IpSpoofAttackError, "IP spoofing attack?! " \
            "HTTP_CLIENT_IP=#{@req.client_ip.inspect} " \
            "HTTP_X_FORWARDED_FOR=#{@req.x_forwarded_for.inspect}"
        end

        # We assume these things about the IP headers:
        #
        #   - X-Forwarded-For will be a list of IPs, one per proxy, or blank
        #   - Client-Ip is propagated from the outermost proxy, or is blank
        #   - REMOTE_ADDR will be the IP that made the request to Rack
        ips = [forwarded_ips, client_ips, remote_addr].flatten.compact

        # If every single IP option is in the trusted list, just return REMOTE_ADDR
        filter_proxies(ips).first || remote_addr
      end
      ...
      def filter_proxies(ips) # :doc:
        ips.reject do |ip|
          @proxies.any? { |proxy| proxy === ip }
        end
      end
    end
    ...
  end
end

rails/remote_ip.rb at c81af6ae723ccfcd601032167d7b7f57c5449c33 · rails/rails

そのため、config.action_dispatch.trusted_proxies に前段にあるプロキシ/ロードバランサーのIPを設定します。

config/initializers/trusted_proxies.rb:

Rails.application.configure do
  # Proxy 1: 56.103.84.14
  # Proxy 2: 56.103.84.15
  config.action_dispatch.trusted_proxies = %w{
    56.103.84.14
    56.103.84.15
  }.map { |proxy| IPAddr.new(proxy) }
end

このようにすることで、X-Forwarded-For が以下のようになっていた場合にクライアントのIPが取得できます。

X-Forwarded-For: 103.10.21.3, 56.103.84.14            # Proxy 1、Proxy 2を経由した場合。103.22.34.5 がクライアントIP
X-Forwarded-For: 17.20.1.3, 103.10.21.3, 56.103.84.14 # Proxy 1、Proxy 2を経由した場合。17.20.1.3 は偽装されたIP
class ApplicationController < ActionController::Base
  before_action :check_ip

  def check_ip
    if request.remote_ip == '17.20.1.3'
      ...
    end
  end
end

CloudFrontを使用した場合に X-Forwarded-For からクライアントIPをセキュアに取得する

上記で述べた方法でクライアントIPをセキュアに取得できますが、 CloudFront - ALB - Server という構成の場合は少々やっかいです。というのも CloudFront は世界中に数十ものエッジサーバーがあり、かつIPが変わり得るので、上記で述べたように CloudFront のIPを事前に信頼できるプロキシに登録するのは困難であるからです。

しかし、AWSAWSの各種サービスの取り得るIPリストを取得できるAPI( https://ip-ranges.amazonaws.com/ip-ranges.json )が存在し、これをもとに信頼できるIPリストに登録できます。Rails で一番簡単なのは config/initializer などで、Rails起動時に https://ip-ranges.amazonaws.com/ip-ranges.json APIにアクセスし、信頼できるIPリストに登録するというものです。

config/initializers/trusted_proxies.rb:

Rails.application.configure do
  ip_ranges_res = Faraday.get('https://ip-ranges.amazonaws.com/ip-ranges.json')
  ip_ranges = JSON.parse(ip_ranges_res.body)
  cloudfront_ips = ip_ranges['prefixes'].select { |v| v['service'] == 'CLOUDFRONT' }.map { |v| IPAddr.new(v['ip_prefix']) } +
                   ip_ranges['ipv6_prefixes'].select { |v| v['service'] == 'CLOUDFRONT' }.map { |v| IPAddr.new(v['ipv6_prefix']) }

  config.action_dispatch.trusted_proxies = cloudfront_ips
end

f:id:mrk21:20200806223957p:plain

まとめ

X-Forwarded-For を使うことで、クライアント・サーバー間にプロキシやロードバランサが存在してもクライアントのIPを取得することができます。 しかし、適切に扱わないと脆弱性が発生するので注意する必要があります。

参考

PROXY protocol を使ってNLB配下のサーバーでクライアントの Remote IP を得る

背景

  1. goproxy を使って HTTP Proxy server を作った
  2. その Proxy server は AWS Fargate で動作していてNLBでロードバランシングされている
  3. NLBはターゲットタイプがインスタンス以外だとRemote IPがNLBのものになってしまう
  4. Proxy server でクライアントのRemote IPがわからず困る

どうするか

goproxy をEC2で動かして、NLBのターゲットタイプをインスタンスにする、というのが手っ取り早いのですが、どうやら PROXY protocol というものがあり、 それを使うとこの問題を解決できるようです。

PROXY protocol ってなに

要はHTTPにおける X-Forwarded-For ヘッダーに相当するもので、TCP/IPベースの任意のプロトコルでクライアントのRemote IPなどの情報を付与するものです。 PROXY Protocolにはバージョン1とバージョン2があり、前者はテキスト、後者はバイナリです。両者ともTCP(UDP)パケットのペイロードに挿入されます。

PROXY protocol v1

以下の形式のプレーンテキストです。

PROXY_STRING + single space + INET_PROTOCOL + single space + CLIENT_IP + single space + PROXY_IP + single space + CLIENT_PORT + single space + PROXY_PORT + "\r\n"

https://developers.cloudflare.com/spectrum/getting-started/proxy-protocol/

たとえば以下のようになります。

PROXY TCP4 192.0.2.0 192.0.2.255 42300 443\r\n
  • INET_PROTOCOL: TCP over IPv4
  • CLIENT_IP: 192.0.2.0
  • PROXY_IP: 192.0.2.255
  • CLIENT_PORT: 42300
  • PROXY_PORT: 443

PROXY protocol v2

バイナリで、プロトコルTCP over IPv4 の場合は以下のようなレイアウトになっています。

 0                   1                   2                   3
 0 1 2 3 4 5 6 7 8 9 0 1 2 3 4 5 6 7 8 9 0 1 2 3 4 5 6 7 8 9 0 1
+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+
|                                                               |
+                                                               +
|                  Proxy Protocol v2 Signature                  |
+                                                               +
|                                                               |
+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+
|Version|Command|   AF  | Proto.|         Address Length        |
+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+
|                      IPv4 Source Address                      |
+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+
|                    IPv4 Destination Address                   |
+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+
|          Source Port          |        Destination Port       |
+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+

https://developers.cloudflare.com/spectrum/getting-started/proxy-protocol/

たとえば以下のようになります。

00000000  0D 0A 0D 0A 00 0D 0A 51  55 49 54 0A 21 11 00 0C  |.......QUIT.!...|
00000010  C0 A8 64 C8 C0 A8 64 C9  D8 6F 1F 90              |..d...d..o..|
  • Proxy Protocol v2 Signature: 0x0D, 0x0A, 0x0D, 0x0A, 0x00, 0x0D, 0x0A, 0x51, 0x55, 0x49, 0x54, 0x0A
  • Version: 2(0x2)
  • Command: PROXY(0x1)
  • AF: IPv4(0x1)
  • Proto.: TCP over IPv4(0x1)
  • Address Length: 12 byte(0x00, 0x0C)
  • IPv4 Source Address: 192.168.100.200(0xC0, 0xA8, 0x64, 0xC8)
  • IPv4 Destination Address: 192.168.100.201(0xC0, 0xA8, 0x64, 0xC9)
  • Source Port: 55407(0xD8, 0x6F)
  • Destination Port: 8080(0x1F, 0x90)

Go言語で PROXY protocol をパースする

Go言語の場合、pires/go-proxyproto というライブラリを使うのが楽です。

server.go:

package main

import (
    "log"
    "net"

    "github.com/pires/go-proxyproto"
)

func main() {
    addr := "127.0.0.1:8080"
    listener, err := net.Listen("tcp", addr)
    if err != nil {
        log.Fatalf("couldn't listen to %q: %q\n", addr, err.Error())
    }

    ppListener := &proxyproto.Listener{Listener: listener}
    defer ppListener.Close()

    conn, _ := ppListener.Accept()
    defer conn.Close()

    if conn.LocalAddr() == nil {
        log.Fatal("couldn't retrieve local address")
    }
    log.Printf("local address: %q", conn.LocalAddr().String())

    if conn.RemoteAddr() == nil {
        log.Fatal("couldn't retrieve remote address")
    }
    log.Printf("remote address: %q", conn.RemoteAddr().String())
}

ppListener := &proxyproto.Listener{Listener: listener} で生の net.Listener をラップすることで PROXY protocol を解析できます。 ppListenernet.Listener 互換のインターフェイスを持っているため、後続のコードでは proxyproto を使っているかどうかを気にせず使用できます(conn.RemoteAddr() などが IPヘッダのものではなく、PROXY Protocol によって指定されたものになる)。

このサーバーに PROXY protocol のヘッダを付与して通信してみます。

client.go:

package main

import "net"

func main() {
    ppv2 := []byte{0x0D, 0x0A, 0x0D, 0x0A, 0x00, 0x0D, 0x0A, 0x51, 0x55, 0x49, 0x54, 0x0A} // \r\n \r\n \0 \r\n QUIT \n
    ppv2 = append(ppv2, []byte{0x21}...)                                                   // Version 2, PROXY command
    ppv2 = append(ppv2, []byte{0x11}...)                                                   // AF_INET, SOCK_STREAM
    ppv2 = append(ppv2, []byte{0x00, 0x0C}...)                                             // Src/Dst addr/port length
    ppv2 = append(ppv2, []byte{0xC0, 0xA8, 0x64, 0xC8}...)                                 // Src addr: 192.168.100.200
    ppv2 = append(ppv2, []byte{0xC0, 0xA8, 0x64, 0xC9}...)                                 // Dst addr: 192.168.100.201
    ppv2 = append(ppv2, []byte{0xD8, 0x6F}...)                                             // Src port: 55407
    ppv2 = append(ppv2, []byte{0x1F, 0x90}...)                                             // Dst port: 8080

    addr := "127.0.0.1:8080"
    conn, err := net.Dial("tcp", addr)
    defer conn.Close()
    if err != nil {
        panic(err)
    }

    conn.Write(ppv2)
}

結果:

2020/07/31 15:40:19 local address: "192.168.100.201:8080"
2020/07/31 15:40:19 remote address: "192.168.100.200:55407"

PROXY protocol で指定したアドレスになっていることが確認できました。

NLBで PROXY protocol を有効にする

NLBではターゲットグループで以下の設定を有効にすることにより、NLB配下のサーバーに PROXY protocol を付与することができます。

f:id:mrk21:20200801195225p:plain f:id:mrk21:20200801195300p:plain

注意点としては、ヘルスチェックするときも PROXY protocol のヘッダを付与するので、ヘルスチェックで指定したエンドポイントでも PROXY protocol を考慮する必要があります。

まとめ

PROXY protocol を利用することによって、TCP/IP上の任意のプロトコルでクライアントのIPを取得することができます。 しかし、PROXY protocol を有効にしたサーバーをインターネット上に公開すると外部からアクセス元が改竄できてしまうので注意が必要です。 また、Go言語で PROXY protocol を使うサンプルは https://github.com/mrk21/sandbox/tree/master/go-go-proxyproto にあります。

参考

terraform コマンドをプロジェクトごとにポータブルにする

terraform コマンドのバージョンをプロジェクトごとに明記しておいても、それぞれのプロジェクトごとに都度指定のバージョンのバイナリを落としてくるのはちょっと面倒くさいので、 それを docker をつかって解決できないか考えてみました。以下のものを使います。

  • Docker
  • hashicorp/terraform dockerイメージ
  • direnv

まず、Docker Hub には hashicorp が terraform の 公式 docker image を公開しているのでこれを使って以下のようなシェルスクリプトを書きます。

bin/terraform:

#!/bin/bash
ROOT_DIR=$(cd $(dirname $0); pwd -P | xargs dirname)

exec docker run \
  -it \
  --rm \
  --workdir=$(pwd -P) \
  -v "${ROOT_DIR}:${ROOT_DIR}" \
  -e "TF_VAR_AWS_ACCESS_KEY_ID=${AWS_ACCESS_KEY_ID}" \
  -e "TF_VAR_AWS_SECRET_ACCESS_KEY=${AWS_SECRET_ACCESS_KEY}" \
  hashicorp/terraform:0.12.25 $*

キモの部分は -v "${ROOT_DIR}:${ROOT_DIR}"--workdir=$(pwd -P) の部分で、 ROOT_DIR/Users/username/foo-project というパスだった場合に、コンテナに /Users/username/foo-project というパスが生成され、ホストの /Users/username/foo-project がマウントされます。そしてさらにコンテナでコマンドを実行するときのワーキングディレクトリを --workdir=$(pwd -P) で指定するとホストとコンテナでパス構成とカレントディレクトリが一致するので、ホスト上の実行ファイルのような感覚で使用することができます。

また、--rm オプションをつけているので実行するたびにゴミが増えていくということもありません。

terraform から環境変数に触りたい場合は -e オプションで任意の環境変数を渡しておきます。

さらに direnv を使うとプロジェクトごとに有効な環境変数PATHを設定できて便利です。

.envrc:

if [ -f .envrc.local ]; then
  source .envrc.local
fi

PATH_add bin

.envrc.local:

export AWS_ACCESS_KEY_ID=xxxxx
export AWS_SECRET_ACCESS_KEY=xxxxx

ここまですると、以下のようにホスト所にインストールされた terraform コマンドと同様に使うことが出来ます。

terraform plan

これらをまとめると以下のようなディレクトリ構成になります。

ディレクトリ構成:

/Users/username/foo-project # project-root
├── .envrc               # direnv の設定ファイル
├── .envrc.local         # バージョン管理しない
├── .envrc.local.sample  # .envrc.localの雛形
├── bin
│   └── terraform       # ポータブルなterraformコマンド
└── terraform            # terraformのファイル郡
    ├── enviromnents
    │   └── production
    │       └── main.tf
    └── modules
        └── main
            ├── ec2.tf
            ...

検索・集計がしやすいロギング環境の構築

調査しやすいロギング環境について社内勉強会で発表したやつをまとめたやつです。


問題が起きたときなどにログを調査することはよくあることだが、ここでは調査しやすログとはどのようなもので、どうやって構築していくかについて述べる。

何も考えずにロギングしたときの問題点

  • ログファイルが巨大すぎて大変
  • ログファイルが複数に大量に分かれて大変
  • 複数のリクエストのログが混ざって識別が困難
  • ログを検索するときに正規表現などで検索しなければならず大変

調査や集計などがしやすいロギング環境への改善

上記の問題を解決するためには以下を行う。

  • ログをローテーションする
  • ログを集約する
  • リクエストを判別できるリクエストIDなどを付与する
  • ログをJSONなどに構造化する

ログをローテーションする

  • ActiveSupport::Loggerlogrotate を使う

ログを集約する

  • CloudWatch Logs / CloudWatch Logs agent などを使って集約する

リクエストを判別できるリクエストIDなどを付与する

  • リクエストIDとはリクエストごとに発行される一意なIDのこと
  • これをロギング時に付与することにより、リクエストレベルで検索可能
    • サーバーは複数あったり、マルチプロセス/マルチスレッドでリクエストを複数同時に処理するため、各リクエストのログが混ざってよくわからなくなりがち

よいこと

  • 検索性が上がる
  • 集計しやすくなる

わるいこと

  • ログサイズが膨れがち
  • 付与する情報が多いと人間が見にくくなる

Railsでの実現はどうするか?

  • ActiveSupport::TaggedLogging によって可能
  • デフォルトだとproduction環境で付与するようになっているはず
ActiveSupport::TaggedLogging とは
  • 任意のLoggerオブジェクト に tagged(*tags) というメソッドを追加するもの
  • このメソッドによりメッセージにタグを付与することが可能
logger = ActiveSupport::TaggedLogging.new(Logger.new(STDOUT))
logger.info 'baz' #=> baz
logger.tagged('hoge') { logger.info 'baz' } #=> [hoge] baz
logger.tagged('hoge','foo') { logger.info 'baz' } #=> [hoge] [foo] baz
logger.info 'baz' #=> baz
リクエストIDを付与する

config.log_tags を設定することにより出力可能。ここで設定された内容が Rails::Rack::Logger にて ActiveSupport::TaggedLogging#tagged(*tags) メソッドに渡されリクエスト毎にタグが付与できる。

config/application.rb:

module HogeApp
  class Application < Rails::Application
    ...
    config.log_tags = [ :request_id ]
  end
end
[8075c9d7-ea51-4069-bba0-e5251a5f4763] Processing by Rails::WelcomeController#index as HTML
[8075c9d7-ea51-4069-bba0-e5251a5f4763]   Rendering /usr/local/bundle/gems/railties-6.0.3/lib/rails/templates/rails/welcome/index.html.erb
[8075c9d7-ea51-4069-bba0-e5251a5f4763]   Rendered /usr/local/bundle/gems/railties-6.0.3/lib/rails/templates/rails/welcome/index.html.erb (Duration: 6.8ms | Allocations: 294)
[8075c9d7-ea51-4069-bba0-e5251a5f4763] Completed 200 OK in 12ms (Views: 9.6ms | ActiveRecord: 0.0ms | Allocations: 1539)

[66587c5c-5b40-41cf-a6ab-dc991bfb9f61] Started GET "/" for 172.29.0.1 at 2020-05-11 08:31:51 +0000
[66587c5c-5b40-41cf-a6ab-dc991bfb9f61] Cannot render console from 172.29.0.1! Allowed networks: 127.0.0.0/127.255.255.255, ::1
[66587c5c-5b40-41cf-a6ab-dc991bfb9f61] Processing by Rails::WelcomeController#index as HTML
[66587c5c-5b40-41cf-a6ab-dc991bfb9f61]   Rendering /usr/local/bundle/gems/railties-6.0.3/lib/rails/templates/rails/welcome/index.html.erb
[66587c5c-5b40-41cf-a6ab-dc991bfb9f61]   Rendered /usr/local/bundle/gems/railties-6.0.3/lib/rails/templates/rails/welcome/index.html.erb (Duration: 6.3ms | Allocations: 179)
[66587c5c-5b40-41cf-a6ab-dc991bfb9f61] Completed 200 OK in 10ms (Views: 8.6ms | ActiveRecord: 0.0ms | Allocations: 784)

ここで config.log_tags では、以下コードに示すとおり、シンボル、Procオブジェクト、文字列などが利用できる。

module Rails
  module Rack
    class Logger < ActiveSupport::LogSubscriber
      ...

      def call(env)
        request = ActionDispatch::Request.new(env)

        if logger.respond_to?(:tagged)
          logger.tagged(compute_tags(request)) { call_app(request, env) }
        else
          call_app(request, env)
        end
      end

      ...

      def compute_tags(request) # :doc:
        @taggers.collect do |tag|
          case tag
          when Proc
            tag.call(request)
          when Symbol
            request.send(tag)
          else
            tag
          end
        end
      end

      ...
    end
  end
end

https://github.com/rails/rails/blob/v6.0.3/railties/lib/rails/rack/logger.rb

  • シンボルを渡すと、 ActionDispatch::Request オブジェクトのメソッドを呼び、その戻り値がタグとして利用される
  • Proc オブジェクトを渡すと ActionDispatch::Request オブジェクトが渡され、呼び出し時の戻り値がタグとして利用される
  • それ以外の文字列などはそのままタグとして利用される

これを踏まえると、以下のように設定することもできる。

module HogeApp
  class Application < Rails::Application
    ...
    config.log_tags = [ 'Server', :method, ->(req){ URI.parse(req.fullpath).path }, :request_id ]
  end
end

結果は以下のようになる。

[Server] [GET] [/] [8075c9d7-ea51-4069-bba0-e5251a5f4763] Processing by Rails::WelcomeController#index as HTML
[Server] [GET] [/] [8075c9d7-ea51-4069-bba0-e5251a5f4763]   Rendering /usr/local/bundle/gems/railties-6.0.3/lib/rails/templates/rails/welcome/index.html.erb
[Server] [GET] [/] [8075c9d7-ea51-4069-bba0-e5251a5f4763]   Rendered /usr/local/bundle/gems/railties-6.0.3/lib/rails/templates/rails/welcome/index.html.erb (Duration: 6.8ms | Allocations: 294)
[Server] [GET] [/] [8075c9d7-ea51-4069-bba0-e5251a5f4763] Completed 200 OK in 12ms (Views: 9.6ms | ActiveRecord: 0.0ms | Allocations: 1539)

[Server] [GET] [/] [66587c5c-5b40-41cf-a6ab-dc991bfb9f61] Started GET "/" for 172.29.0.1 at 2020-05-11 08:31:51 +0000
[Server] [GET] [/] [66587c5c-5b40-41cf-a6ab-dc991bfb9f61] Cannot render console from 172.29.0.1! Allowed networks: 127.0.0.0/127.255.255.255, ::1
[Server] [GET] [/] [66587c5c-5b40-41cf-a6ab-dc991bfb9f61] Processing by Rails::WelcomeController#index as HTML
[Server] [GET] [/] [66587c5c-5b40-41cf-a6ab-dc991bfb9f61]   Rendering /usr/local/bundle/gems/railties-6.0.3/lib/rails/templates/rails/welcome/index.html.erb
[Server] [GET] [/] [66587c5c-5b40-41cf-a6ab-dc991bfb9f61]   Rendered /usr/local/bundle/gems/railties-6.0.3/lib/rails/templates/rails/welcome/index.html.erb (Duration: 6.3ms | Allocations: 179)
[Server] [GET] [/] [66587c5c-5b40-41cf-a6ab-dc991bfb9f61] Completed 200 OK in 10ms (Views: 8.6ms | ActiveRecord: 0.0ms | Allocations: 784)

ログをJSONなどに構造化する

  • いわゆる構造化ロギングで、JSONなどの構造化されたフォーマットでロギングすること

よいこと

  • 検索性が上がる
  • 集計しやすくなる
  • プログラムで処理しやすい

わるいこと

  • ログサイズが膨れがち
  • 人間にとっては見にくい

Railsでの実現はどうするか?

JSONに出力するFormatterを使えばいいが、タグを付与する ActiveSupport::TaggedLogging で少々問題になる。 たとえば、 ActiveSupport::TaggedLogging で使用する Formatter では、タグとメッセージを連結してからオリジナルのFormatterを呼び出している。

  module TaggedLogging
    module Formatter # :nodoc:
      # This method is invoked when a log event occurs.
      def call(severity, timestamp, progname, msg)
        super(severity, timestamp, progname, "#{tags_text}#{msg}")
      end
      ...

https://github.com/rails/rails/blob/v6.0.3/activesupport/lib/active_support/tagged_logging.rb#L22-L24

このままだと、タグ情報を構造化してログ出力できない。そのため、以下のように ActiveSupport::TaggedLogging を拡張するラッパークラスを作成する。

module Logging
  module JsonStructuredTaggedLogging
    module Formatter
      def call(severity, timestamp, progname, message)
        result = {
          severity: severity.to_s,
          timestamp: timestamp.iso8601,
          progname: progname.to_s,
          tags: current_tags.map(&:to_s),
          message: message.to_s,
        }
        result = result.to_json + "\n"
        result
      end
    end

    def self.new(logger)
      logger = ActiveSupport::TaggedLogging.new(logger) unless logger.respond_to?(:tagged)
      logger.formatter.extend Formatter
      logger.extend self
      logger
    end
  end
end

ここまでできたら、 Rails.logger などで使用していく。

config/application.rb:

class Application < Rails::Application
  ...
  config.logger = Logging::JsonStructuredTaggedLogging.new(ActiveSupport::Logger.new(STDOUT))
end

ロギングをよりよくする

Lograge を使ってリクエスト毎の情報をまとめてロギングする

  • リクエスト単位で実行時間やエラーなどのログを出力できるので便利
  • lograge のログにリクエストIDを出力するようにするとRails標準のログと照会できて便利

config/initializers/lograge.rb:

Rails.application.configure do
  config.lograge.enabled = true
  config.lograge.keep_original_rails_log = true
  config.lograge.logger = ActiveSupport::Logger.new(STDOUT)
  config.lograge.formatter = Lograge::Formatters::Json.new

  config.lograge.custom_options = lambda do |event|
    data = {
      request_id: event.payload[:request_id],
    }
    data
  end
end

app/controllers/application_controller.rb:

class ApplicationController < ActionController::Base
  protected

  def append_info_to_payload(payload)
    super
    payload[:request_id] = request.request_id
  end
end

rescue_from などでエラーを補足したときは必ずログにエラー内容を出力する

  • なにが起きたのかがわからなくなるため
  • エラーだけでなく前後でなにが起きたのかも見たいので、Sentry などのエラートラッキングサービスをつかっていても出力する
  • lograge を使っている場合は、例外オブジェクトを append_info_to_payload で追加する

app/controllers/application_controller.rb:

class ApplicationController < ActionController::Base
  rescue_from StandardError, with: :error_500
  rescue_from ActiveRecord::RecordNotFound, with: :error_404

  protected

  def error_404(e)
    Rails.logger.warn e.inspect
    @exception = e
    render plain: 'error 404'
  end

  def error_500(e)
    Rails.logger.error [e.inspect, *e.backtrace].join("\n")
    Raven.capture_exception(e) # Sentry に通知
    @exception = e
    render plain: 'error 500'
  end

  # action => rescue_from => append_info_to_payload の順で呼ばれる
  def append_info_to_payload(payload)
    super
    payload[:request_id] = request.request_id
    if @exception.present?
      payload[:exception_object] ||= @exception
      payload[:exception] ||= [@exception.class.name, @exception.message]
    end
  end
end

config/initializers/lograge.rb:

Rails.application.configure do
  ...
  config.lograge.custom_options = lambda do |event|
    data = {
      request_id: event.payload[:request_id],
    }
    if event.payload[:exception].present?
      data[:exception] = event.payload[:exception]
      data[:exception_backtrace] = event.payload[:exception_object]&.backtrace
    end
    data
  end
end

バックグラウンドjobやrakeタスクなども job id や task id などを出力して検索しやすくする

  • [Rake][hoge_task][xxx-bbb-ddd] みたいな感じでタグを付与する
  • これによってログの調査がしやすくなる
  • IDはUUID v4を使うと楽
    • SecureRandom.uuid

ActiveJob

  • ActiveJobはJobIDをログに付与する

[ActiveJob] もしくは [ActiveJob] [<job-name>] [<job-id>] というプレフィックスがつく

[ActiveJob] Enqueued ExampleJob (Job ID: 6b7b2799-3479-4647-a5cf-b9b371b7e7bb) to Sidekiq(default)
[ActiveJob] [ExampleJob] [6b7b2799-3479-4647-a5cf-b9b371b7e7bb] Performing ExampleJob (Job ID: 6b7b2799-3479-4647-a5cf-b9b371b7e7bb) from Sidekiq(default) enqueued at 2020-05-11T09:01:14Z
[ActiveJob] [ExampleJob] [6b7b2799-3479-4647-a5cf-b9b371b7e7bb] ### test
[ActiveJob] [ExampleJob] [6b7b2799-3479-4647-a5cf-b9b371b7e7bb] Performed ExampleJob (Job ID: 6b7b2799-3479-4647-a5cf-b9b371b7e7bb) from Sidekiq(default) in 0.92ms

Rake タスクなど

ActiveSupport::TaggedLogging#tagged(*tags) を利用して以下のようにする。

namespace :example do
  logging = ->(type, &block) {
    Rails.logger.tagged('Rake', "example:#{type}", SecureRandom.uuid, &block)
  }
  task :exec => [:environment] do
    logging[:exec] do
      Rails.logger.info 'test'
    end
  end
end
$ rails example:exec
$ cat log/development.log
[Rake] [example:exec] [e64f4190-1c70-4ff0-9a4d-c913c5e77ec4] test

構造化されたログの型付け

Rails が出力するログのほかにも様々なログがあるので、ログの型を決めておくとあとで検索がしやすい。 そのため型付けをどうするかについて述べる。

まず、すべての構造化ログは最低でも以下のプロパティを持つものとする。

type LogBase = {
  type: 'rails' | 'lograge';
  level: 'DEBUG' | 'INFO' | 'WARN' | 'ERROR' | 'FATAL' | 'ANY';
  time: string; // ISO 8601
};

そして Rails 標準のログを以下のように定義する。

type RailsLog = LogBase & {
  sub_type: 'server' | 'job' | 'other';
  request_id: string | null; // for server
  job_name: string | null; // for active job
  job_id: string | null; // for active job
  message: string;
  tags: Array<string>;
};

次に Lograge のログはユーザで拡張できるので拡張部分と基本部分をあわせて以下のように定義する。

type LogrageBaseLog = {
  method: string;
  path: string;
  format: string;
  controller: string;
  action: string;
  status: number;
  duration: number;
  view: number;
  db: number;
}
type LogrageAppendedLog = LogBase & {
  request_id: string;
  exception: [string, string] | null;
  exception_backtrace: string[] | null;
};
type LogrageLog = LogrageLog & LogrageAppendedLog;

つまり出力されるログの型は以下のようになる。共通の type により、ログの型が一意に決まる。

type Log = RailsLog | LogrageLog;

これらを踏まえて、Ruby でログイベントを扱うクラスを作る。

module Logging
  module Entity
    class LogBase
      TYPES = %i(rails lograge).freeze
      LEVELS = Logger::SEV_LABEL.freeze

      def self.fetch_type(value)
        Hash[*TYPES.map {|v| [v, v] }.flatten].fetch(value.to_s.intern)
      end

      def self.fetch_level(value)
        Hash[*LEVELS.map {|v| [v, v] }.flatten].fetch(value.to_s.upcase)
      end

      attr_reader :type
      attr_reader :time
      attr_reader :level

      def initialize(type:, level:, time:)
        @type = self.class.fetch_type(type)
        @time = time.iso8601(6)
        @level = self.class.fetch_level(level)
      end
    end

    class RailsLog < LogBase
      SUB_TYPES = %i(server job other)

      def self.fetch_sub_type(value)
        Hash[*SUB_TYPES.map {|v| [v, v] }.flatten].fetch(value.to_s.intern)
      end

      attr_accessor :sub_type
      attr_accessor :tags
      attr_accessor :request_id
      attr_accessor :job_name
      attr_accessor :job_id
      attr_accessor :message

      def initialize(time:, level:, message:, tags:)
        super(type: :rails, time: time, level: level)
        @sub_type = nil
        @tags = tags
        @request_id = nil
        @job_name = nil
        @job_id = nil
        @message = message

        case @tags[0]
        when 'Server'
          @sub_type = self.class.fetch_sub_type(:server)
          @request_id = @tags[1]
        when 'ActiveJob'
          @sub_type = self.class.fetch_sub_type(:job)
          if @tags.size >= 3
            @job_name = @tags[1]
            @job_id = @tags[2]
          end
        else
          @sub_type = self.class.fetch_sub_type(:other)
        end
      end
    end

    class LogrageAppendedLog < LogBase
      attr_reader :request_id
      attr_reader :exception
      attr_reader :exception_backtrace

      def initialize(
        time:,
        level:, 
        request_id:,
        exception: nil,
        exception_backtrace: nil
      )
        super(type: :lograge, time: time, level: level)
        @request_id = request_id
        @exception = exception
        @exception_backtrace = exception_backtrace
      end
    end
  end
end

JSONで構造化するロギングクラスで使い、指定の形式で出力する。

module Logging
  module JsonStructuredTaggedLogging
    module Formatter
      def call(severity, timestamp, _progname, message)
        result = Logging::Entity::RailsLog.new(
          time: timestamp,
          level: severity,
          message: message,
          tags: current_tags
        )
        result = result.to_json + "\n"
        result
      end
    end
    ...
end
Rails.application.configure do
  ...

  config.lograge.custom_options = lambda do |event|
    data = {
      time: event.payload[:time],
      level: event.payload[:level] || 'INFO',
      request_id: event.payload[:request_id],
    }
    if event.payload[:exception].present?
      data[:level] = event.payload[:level] || 'FATAL'
      data[:exception] = event.payload[:exception]
      data[:exception_backtrace] = event.payload[:exception_object]&.backtrace
    end
    Logging::Entity::LogrageAppendedLog.new(**data).as_json
  end
end

ログの検索・集計

CloudWatch Logs で集約・検索

  • AWSを使っているならCloudWatch Logs を使う
  • JSONによる構造化ロギングをサポートしている
  • JSON メトリクスフィルターによる高度な検索

JSON メトリクスフィルターによる高度な検索

JSON メトリクスフィルターとは以下のような構文で、JSONログイベントの特定のキーの値に対する条件を記述することができる。

{ SELECTOR EQUALITY_OPERATOR STRING }

例えば、以下のようなログイベントがあったとして、

{ "type": "type1", "message": "message 1" }
plain text
{ "type": "type1", "message": "message 2" }
{ "type": "type2", "message": "message 3" }

次のような構文で検索すると、

{ $.type = "type1" }

JSON ログイベントかつ typetype1 のもののみ抽出できる。

{ "type": "type1", "message": "message 1" }
{ "type": "type1", "message": "message 2" }

CloudWatch Logs Insights による高度な検索

CloudWatch Logs で JSONメトリクスフィルターを使って高度な検索ができるが、 CloudWatch Logs Insights というサービスで、SQLライクな構文をつかってより高度な検索が可能になる。

fields @timestamp, path, request_id, exception.1
| sort @timestamp desc
| filter type = "lograge" AND level = "WARN"
| limit 20

f:id:mrk21:20200706190127p:plain

S3へのエクスポートとAthenaによる高度な検索・集計

  • Cloudwatch Logs は Insights 含め、検索速度が遅く、ストレージ料金も割高である
    • あくまでも一時的なログ集約場として扱うほうがよい
    • 1,2週間でexpireするのがよい
  • Lambdaを書き、日次でS3に書き出し
  • Athenaを使う
    • Athena とは S3 にあるログファイルをSQLによって検索・集計することができる
    • ログファイルが膨大になってくるとスキャン時の課金が多くなるので、パーティションに分ける
      • Lambdaで日次でやる

S3へのエクスポート

Amazon Kinesis Data Firehose というサービスを使えばフルマネージドにS3にエクスポートできるが料金が高いのでLambdaとCloudWatch Eventsを用いて行う。

Lambda を Node.js で実装する場合 ADS SDKaws.CloudWatchLogs#createExportTask() を用いて指定のS3バケットにログをエクスポートする。

// @see [Lambda + S3 で、CloudWatch Logsのログをログローテーションする - Qiita](https://qiita.com/tamura_CD/items/3a1deba9e55e8b83bd91)
// @see [Class: AWS.CloudWatchLogs — AWS SDK for JavaScript](https://docs.aws.amazon.com/AWSJavaScriptSDK/latest/AWS/CloudWatchLogs.html#createExportTask-property)
'use strict';

const aws = require('aws-sdk');
aws.config.update({ region: 'ap-northeast-1' });

exports.handler = (event, context, callback) => {
  const cloudWatchLogs = new aws.CloudWatchLogs();
  const range = getRange();
  const params = {
    destination: process.env.BucketName,
    from: range.from,
    to: range.to,
    logGroupName: process.env.LogGroupName,
    destinationPrefix: `${process.env.DestinationPrefix}/dt=${range.date}`, // hive形式で出力
    taskName: `${process.env.TaskName}/${range.date}`,
  };
  console.log(`params: ${JSON.stringify(params)}`);

  cloudWatchLogs.createExportTask(params, (error, data) => {
    if (error) {
      console.log(error, error.stack);
      callback(null, error.stack);
    }
    else {
      console.log(data);
      callback(null, data);
    }
  });
};

function getRange() {
  const result = {};
  const time = new Date();
  time.setTime(time.getTime() + 9 * 60 * 60 * 1000); // JST

  time.setDate(time.getDate() - 2);
  time.setHours(0);
  time.setMinutes(0);
  time.setSeconds(0);
  time.setMilliseconds(0);
  result.from = time.getTime(); // 前日の日本時間 00:00:00 のタイムスタンプ(含ミリ秒)

  time.setDate(time.getDate() + 1);
  result.to = time.getTime(); // 本日の日本時間 00:00:00 のタイムスタンプ(含ミリ秒)

  const yyyy = time.getFullYear();
  const mm = ('0' + (time.getMonth() + 1)).slice(-2);
  const dd = ('0' + time.getDate()).slice(-2);
  result.date = `${yyyy}-${mm}-${dd}`; // yyyy-mm-dd のフォーマット

  return result;
}

しかし、この方法でエクスポートすると timestamp が JSONログの前に付与されてしまうので、valid な JSON でなくなってしまう。

2020-05-18T00:00:01.383Z {"type":"rails", ...}
2020-05-18T00:00:01.384Z {"type":"rails", ...}

Athena のテーブルを作成し、検索できるようにする

まずはデータベースを作成する。

CREATE DATABASE ecs_test;

テーブルを作成するが、上述したとおり valid な JSON ではなくなってしまっている。そのため、まずは plain text なカラムが一つあるテーブルを作成する。 Athena はスキャンしたデータ量に応じて課金されるため、日付でパーティションを切る。

CREATE EXTERNAL TABLE IF NOT EXISTS ecs_test.raw_app_logs (`text` string)
PARTITIONED BY (`dt` date)
LOCATION 's3://test-logs/ecs-test/'
TBLPROPERTIES ('has_encrypted_data'='false');
MSCK REPAIR TABLE ecs_test.raw_app_logs;

そして、次にその plain text から JSON を抜き出して各プロパティにアクセス可能にするため、以下の view を作成する。JSONのままでもAthenaにはJSON関数があるので特定のプロパティの値を参照できる。

CREATE OR REPLACE VIEW ecs_test.json_app_logs AS
SELECT
  dt,
  CAST(from_iso8601_timestamp(timestamp) AS TIMESTAMP) AS timestamp,
  CAST(json_extract(json, '$.type') AS VARCHAR) AS type,
  CAST(json_extract(json, '$.level') AS VARCHAR) AS level,
  CAST(from_iso8601_timestamp(CAST(json_extract(json, '$.time') AS VARCHAR)) AS TIMESTAMP) AS time,
  json
FROM (
  SELECT
    dt,
    regexp_extract(text, '^([^ ]+) ({.+})$', 1) AS timestamp,
    regexp_extract(text, '^([^ ]+) ({.+})$', 2) AS json
  FROM raw_app_logs
)
WHERE
  json IS NOT NULL AND
  timestamp IS NOT NULL

このようにすることで、高度な検索・集計などができるようになる。

SELECT
  dt
, type
, level
, time
, CAST(json_extract(json, '$.request_id') AS VARCHAR) AS request_id
, CAST(json_extract(json, '$.message') AS VARCHAR) AS message
FROM json_app_logs
WHERE type = 'rails'
  AND dt = date '2020-05-20'

f:id:mrk21:20200706190121p:plain

最後に

ここまで述べてきたとおり、ログに原因特定のためのメタ情報を付与して、JSON等で構造化することによって、検索・集計がしやすくなる。 また、CloudWatch Logs などに集約し、Athena などでより高度な検索もできるようになる。

最後に、以下に本エントリーのための検証プロジェクトを示す。

ClamAVによるアップロードファイルのウィルスチェック

とあるRailsアプリケーションでアップロードされたファイルをウィルスチェックしたいというのがあって、実装したのでメモ。

方針

ClamAVというオープンソースのアンチウィルスエンジンがあるのでこれを使う。各種言語にクライアントライブラリ(Rubyclamav-clientというgem)があったりして便利。

このアプリケーションはDockerで動かしているので、ClamAVのコンテナを立ててデーモンを動かし、ファイルアップロード時にアップロードされたファイルをClamAVのデーモンに渡してウィルス判定されたらバリデーションエラーになるようにする。

また、ファイルアップロードには shrine という gem を使っている。

実装

環境

docker-compose.yml:

---
version: '3.5'
services:
  clamav:
    image: mkodockx/docker-clamav
    ports:
      - 3310
    volumes:
      - clamav:/var/lib/clamav
      - ./docker/clamav/clamd.conf:/etc/clamd/clamd.conf:ro
      - ./docker/clamav/freshclam.conf:/etc/clamd/freshclam.conf:ro

  app:
    build:
      context: .
      dockerfile: docker/app/Dockerfile
      target: base
    command: >
      bash -c "
        rm -f tmp/pids/server.pid &&
        bundle exec rails s -p 3000 -b '0.0.0.0'"
    depends_on:
      - clamav
    volumes:
      - .:/app
    ports:
      - ${DOCKER_HOST_APP_PORT:-3000}:3000
    environment:
      CLAMD_TCP_HOST: clamav
      CLAMD_TCP_PORT: 3310

volumes:
  clamav:
    driver: local

clamd.conf:

# Daemon
Foreground true
LocalSocket /var/run/clamav/clamd.ctl
FixStaleSocket true
LocalSocketGroup clamav
LocalSocketMode 666
TCPSocket 3310

# Basic
User clamav
ScanMail true
ScanArchive true
ArchiveBlockEncrypted false
MaxDirectoryRecursion 15
FollowDirectorySymlinks false
FollowFileSymlinks false
ReadTimeout 180
MaxThreads 12
MaxConnectionQueueLength 15

# Log
LogFile /dev/stdout
LogSyslog false
LogRotate false
LogFacility LOG_LOCAL6
LogClean false
LogVerbose false
LogTime true
LogFileUnlock false
LogFileMaxSize 0

# Detail
PreludeEnable no
PreludeAnalyzerName ClamAV
DatabaseDirectory /var/lib/clamav
OfficialDatabaseOnly false
SelfCheck 3600
Debug false
ScanPE true
MaxEmbeddedPE 10M
ScanOLE2 true
ScanPDF true
ScanHTML true
MaxHTMLNormalize 10M
MaxHTMLNoTags 2M
MaxScriptNormalize 5M
MaxZipTypeRcg 1M
ScanSWF true
DetectBrokenExecutables false
ExitOnOOM false
LeaveTemporaryFiles false
AlgorithmicDetection true
ScanELF true
IdleTimeout 30
CrossFilesystems true
PhishingSignatures true
PhishingScanURLs true
PhishingAlwaysBlockSSLMismatch false
PhishingAlwaysBlockCloak false
PartitionIntersection false
DetectPUA false
ScanPartialMessages false
HeuristicScanPrecedence false
StructuredDataDetection false
CommandReadTimeout 5
SendBufTimeout 200
MaxQueue 100
ExtendedDetectionInfo true
OLE2BlockMacros false
ScanOnAccess false
AllowAllMatchScan true
ForceToDisk false
DisableCertCheck false
DisableCache false
MaxScanSize 100M
MaxFileSize 25M
MaxRecursion 16
MaxFiles 10000
MaxPartitions 50
MaxIconsPE 100
PCREMatchLimit 10000
PCRERecMatchLimit 5000
PCREMaxFileSize 25M
ScanXMLDOCS true
ScanHWP3 true
MaxRecHWP3 16
StreamMaxLength 25M
Bytecode true
BytecodeSecurity TrustSigned
BytecodeTimeout 60000

freshclam.conf:

# Daemon
Foreground true

# Basic
DatabaseOwner clamav
Debug false
MaxAttempts 5
DatabaseDirectory /var/lib/clamav
DNSDatabaseInfo current.cvd.clamav.net
ConnectTimeout 30
ReceiveTimeout 30
TestDatabases yes
ScriptedUpdates yes
CompressLocalDatabase no
SafeBrowsing false
Bytecode true
NotifyClamd /etc/clamav/clamd.conf

# Log
UpdateLogFile /dev/stdout
LogVerbose false
LogSyslog false
LogFacility LOG_LOCAL6
LogFileMaxSize 0
LogRotate false
LogTime true

# Check
Checks 24
DatabaseMirror db.local.clamav.net
DatabaseMirror database.clamav.net

Rails

Gemfile:

...

# Upload file
gem 'shrine'

# Antivirus
gem 'clamav-client', require: 'clamav/client'

config/initializers/clamav.rb:

class << Rails.application
  def clamav
    Thread.current['clamav'] ||= ClamAV::Client.new(
      ClamAV::Connection.new(
        socket: TCPSocket.new(Settings.clamav.tcp_host, Settings.clamav.tcp_port),
        wrapper: ClamAV::Wrappers::NewLineWrapper.new
      )
    )
  end
end

app/uploaders/basic_uploader.rb:

class BasicUploader < Shrine
  plugin :validation_helpers

  Attacher.validate do
    result = Rails.application.clamav.execute(ClamAV::Commands::InstreamCommand.new(get))
    errors << :has_virus if result.virus_name.present?
  end
end

app/models/hoge_model.rb:

class HogeModel < ApplicationRecord
  include BasicUploader::Attachment.new(:file)
end

テスト

EICARがウィルスチェック用の無害なテストウィルスを配布しているのでこれを使う。

$ docker-compose exec app rails c
irb(main):001:0> model = HogeModel.new(file: Rails.root.join('fixtures/antivirus/eicar.com').open)
irb(main):002:0> model.valid?
irb(main):003:0> model.errors.details
{:file=>[{:error=>:has_virus}]}
irb(main):004:0> model = HogeModel.new(file: Rails.root.join('REDME.md').open)
irb(main):005:0> model.valid?
irb(main):006:0> model.errors.details
{}

git revert したブランチを再度マージする方法

先日あやまって、topic branch を master にマージしてしまったので、 マージコミットを revert しました。のちほど再度 merge しようとしたのですがうまくマージされませんでした。この場合は、git revert したときにできた revert commit に対して git revert するようです。

$ git marge hoge # あやまって hoge branch をマージ
...

$ git log # merge commit が作成される

commit <merge-commit-hash>
Merge: aaaa bbbb
Author: Foo Baz <foo@baz.com>
Date:   Tue Sep 4 17:19:00 2018 +0900

    Merge branch 'hoge'

...
$ git revert -m 1 <merge-commit-hash> # この merge commit を revert
...

$ git log # revert commit が作成され revert された

commit <revert-commit-hash>
Author: Foo Baz <foo@baz.com>
Date:   Tue Sep 4 17:29:00 2018 +0900

    Revert "Merge branch 'hoge'"

    This reverts commit <merge-commit-hash>, reversing
    changes made to cccc.

....

$ git revert <revert-commit-hash> # 再度マージするため revert commit を revert
...

$ git log # revert commit の revert commit が生成され無事マージされた

commit eeee
Author: Foo Baz <foo@baz.com>
Date:   Tue Sep 4 17:39:00 2018 +0900

    Revert "Revert "Merge branch 'hoge'""

    This reverts commit <revert-commit-hash>.

...

参考

UniRx を試してみた

Unity でイベント処理などが複雑になってきたので、どうにかできないかと思い UniRx を試しました。

github.com

UniRx とは イベントを時系列に並んだシーケンスと捉え、それらを filter したり map したりすることでイベント処理を行うものです。

たとえば、Spaceキーが入力されたときに、プレイヤーをジャンプさせるといったことをする場合は、通常は以下のように Update() でキーが入力されたか判定し、その結果のフラグをプロパティに保持しておき、FixedUpdate() でフラグが立っていれば RidgedBody を操作するといったことをします。

using System;
using UnityEngine;

public class JumpBehaviourScript : MonoBehaviour
{
    private Boolean isEnteredSpaceKey;
    private Rigidbody rigidBody;

    private void Start()
    {
        isEnteredSpaceKey = false;
        rigidBody = GetComponent<Rigidbody>();
    }

    private void Update()
    {
        isEnteredSpaceKey = Input.GetKey(KeyCode.Space);
    }

    private void FixedUpdate()
    {
        if (isEnteredSpaceKey) {
            rigidBody.AddForce(Vector3.up, ForceMode.VelocityChange);
        }
    }
}

この方法では、キーが押されたかの判定とその時の動作が別の場所にあるため、キー入力が多くなってくると見通しが悪くなってきます。

ここで、UniRx を用いると以下のように記述できます。

using UniRx;
using UniRx.Triggers;
using UnityEngine;

public class JumpBehaviourScript : MonoBehaviour
{
    private void Start()
    {
        var rididBody = GetComponent<Rigidbody>();

        this.UpdateAsObservable()
            .Where(_ => Input.GetKey(KeyCode.Space))
            .BatchFrame(0, FrameCountType.FixedUpdate)
            .Subscribe(_ => rididBody.AddForce(Vector3.up, ForceMode.VelocityChange));
    }
}

これは、 UpdateAsObservable()Update() のタイミングでイベントが発生するというストリームを生成します。そして .Where(_ => Input.GetKey(KeyCode.Space)) でキーが押されたときだけ filter します。 そのあとに、 BatchFrame(0, FrameCountType.FixedUpdate) でバッファにイベントをためておき、FixedUpdate() のタイミングでポップします。最後に Subscribe(_ => rididBody.AddForce(Vector3.up, ForceMode.VelocityChange)) でジャンプする動作を行います。

このように、UniRx を用いることで、キー入力判定からジャンプの動作までを一つのストリームで簡潔に記述できます。

そのほかにも、MVPパターンのReactive実装のパターンである MV(R)P パターンの実装など Unity において様々なところで活躍しそうです。

UniRx については以下が詳しいです。

www.slideshare.net qiita.com

また、以下に調査時のサンプルコードがあります。

github.com