読者です 読者をやめる 読者になる 読者になる

ユニファ開発者ブログ

ユニファ株式会社システム開発部メンバーによるブログです。

月に一度のBeer Bash

 こんにちは、赤沼です。今回はユニファ開発部で行なっている取り組みの一つの、Beer Bashについてご紹介させていただきます。

開発部 Beer Bash

 ユニファ システム開発部では、毎月下旬の金曜日の夜に、社内イベントとして Beer Bash を開催しています。これは昨年(2016年)の10月から始めたもので、今のところ5ヶ月間毎月開催しています。

ビール片手にLT大会

 内容としては、ビールでも飲みながら、テーマは自由でLTしましょう、というものです。最初はみんな気軽に参加できるように、とりあえず会社近くのなか卯で唐揚げ100個ぐらいと、カクヤス等でビールを手配して、イベント名も唐揚げBeer Bashとしていましたが、当日急遽参加できなくなるメンバーが多かったりすると予約していた唐揚げがかなり余ってしまったりしたので、現在は各自食べたいものを調達して集まるというスタイルにしています。

 LTの内容は自由で、仕事に全く関係なかったり、技術的な内容でなくてもOKです。今までのLTの内容の例としては下記のようなものがありました。

  • これさえやればマテリアルデザイン
  • tensorflowを使って遊んでみたはなし
  • BLE nanoでLチカしました報告
  • ガチャのためのコインをひたすら稼ぐ話
  • AmazonDashButtonで遊んでみた
  • 園内ドキュメンテーションとるくみーの可能性 などなど

 上記以外も含めてどれもメンバーの個性が出ていてとても面白い内容でした。

参加は自由

 開催時間を業務時間外としていることもあり、参加は任意です。毎月Confluence(社内Wiki)にイベントのページを作って、参加したい人はそこに名前とLTのテーマを書いてもらうようにしています。LTなしで聞くだけでもOK。最初はどれぐらい集まるかわかりませんでしたが、毎回一定数以上のメンバーが参加してくれています。こういったイベントは強制的に参加させられてもあまり意味がないと思っていますし、任意参加でメンバーが集まらなくなったら終了、もしくは違う形のイベントに変更ということにしようと思っています。

開発メンバーも自己発信は重要

 Beer Bashを始めた目的としては、下記のようなものがあります。

  • 業務以外での気軽な交流の場を増やす
  • 他のメンバーがどんなことに興味があるのか、どんなことに詳しいのかを知ることができる
  • プレゼンの練習の場とすることができる
  • ビールと唐揚げ

 開発メンバーは普段の仕事ではあまりプレゼンのようなことをする機会がありませんが、自己発信していくことは重要だと思っています。自己発信の手段は色々とありますが、メンバーにはもし機会があれば外部のカンファレンス等でも積極的に登壇してもらいたいと思っています。そのための練習の場としても大いに活用してもらいたいと思っています。

 参加は任意としていることもあり、どれぐらい発表者がいるかわからなかったのですが、蓋を開けてみると前述のように色々なテーマでの発表があり、一応1枠10分を目安としているものの、それでは収まりきらないぐらいの内容を持ってきてくれています。(時間内に収めるというのもそれはそれで必要ですが。)

 開発部以外のメンバーも興味ある方は参加してもらってOKということにしていて、今までに参加してくれた他部署のメンバーからは、開発部メンバーの違った一面が見れて良かった、とか、自分もプレゼンしてみたいと思った、等のポジティブな感想をもらうことができました。

課題は時間と場所

 今のところ社内イベントとしてはうまくいっていて、定着してきていますが、まだ課題も残っています。まず時間帯が業務時間外の夜の時間なので、なかなか参加でいないメンバーもいます。また、ユニファは本社が名古屋なので、名古屋にも開発メンバーがいるのですが、リモートではなかなか参加しづらいイベントになっています。この時間と場所の問題を解決する方法がないかというのは今後も考えていきたいと思っています。

2020年度から小学校でプログラミング教育必修? 今日からお家で始められるお子様向けプログラミング入門

はじめまして、ユニファ株式会社のスマートフォンエンジニアのまさと申します。 2020年からプログラミング教育が必修となります。 でもいまいち「何から始めていいかわからない。」「私算数苦手だったし。」 「スクールに通わせるにもお金がかかるし。」と悩むこともあるかと思います。 そんな時に、お家で簡単に子供と一緒に始められるプログラミングツールをご紹介します。

今回は本当に初めてのお子様にも親しみやすいブロックをつなぐような入門環境のみご紹介します。

ゲーム好きのお子様におすすめ

Scratch Jr(無料) 5歳〜7歳

f:id:unifa_tech:20170210133545j:plain

ScratchJr - Home

この後紹介する、Scratchがまだ難しい子供にもっと身近にプログラミングをとKickstarterによって開発されたアプリです。 iPadやAndroidタブレットにて使用できます。 さまざまな画像や、背景、音楽が用意されていて、ブロックをつなげていくだけでキャラクターの動く物語が作れます。入門としては最適です。

プログラミン(無料) 6歳〜

f:id:unifa_tech:20170210133715j:plain

プログラミン | 文部科学省

文部科学省がプログラミングをもっと身近に感じてもらうべく開発されたプログラミング学習環境です。 Webアプリであるため、ブラウザさえあれば始められます。 Scratch Jrのようにブロックをつないで、もう少し難しい「もし〜の時はこうする」 というような条件分岐を含むプログラミングができるため、簡単なゲームも作れます。

スクラッチ(無料) 8歳〜

f:id:unifa_tech:20170210133721j:plain Scratch - Imagine, Program, Share

米国マサチューセッツ工科大学のMITメディアラボが開発したプログラミング学習環境です こちらもWebアプリであるため、ブラウザさえあれば始められます。 プログラミンではできなかった変数や乱数をつかった本格的なプログラミングが可能です。 NHKの教育番組「Why!? プログラミング」でも有名ですね。

ロボットやラジコン好きのお子様におすすめ

little bits(1万数千円〜)5歳〜

f:id:unifa_tech:20170210133728j:plain

littleBits(リトルビッツ)

ちょっとプログラミングと呼ぶまではいかないかもしれませんが、ブロックを繋げることで電子工作を楽しむことができます。 少々値段がはりますが、お子様と一緒にできる難易度の低さが魅力です。 簡単に明るさセンサーで暗いときに自動点灯する懐中電灯や、動く車などを作成できます。

chibi bits(4,000円程) 6歳〜

f:id:unifa_tech:20170210133737j:plain

chibi:bit - スイッチサイエンス

http://chibibit.io/ide/

chibi:bitは、BBC(英国放送協会)が主体となって作っている教育向けマイコンボードBBC micro:bitの互換機です。 Webにて開発が可能ので、ブロックを繋げるだけで、5x5のLEDの好きなところをON,OFFしたり、文字を表示したり、音楽を奏でることも可能です(別途100円ショップなどに売っているスピーカーが必要)。 使い方も簡単。chibi bitsをusbケーブルでつなぎ、PCに認識させます。 web上でブロックをつなげて開発したら、ダウンロードボタンを押して、ファイルを保存します。 そのファイルを認識させたchibi:bitに、ドラッグアンドドロップするだけです。

まとめ

とくにプログラムをしたことのない親御さんも、触ってみるとこうやってするのかと、コツをつかめてきます。 週末にお子様と初めてのプログラミングにチャレンジしてみてはいかがでしょうか。

JaSST’17 Tokyoで登壇してきました!

こんにちは、ビールが大好きなQAの鶴岡です。

先日、あの有名なJaSSTで登壇してきました!

JaSSTとは

Japan Symposium on Software Testingの略で、「ジャスト」と読みます。

2003年から開催されている国内最大のソフトウェアテストシンポジウムで日本各地で開催されています。
詳細はこちらからどうぞ。 JaSSTソフトウェアテストシンポジウム-JaSSTについて

2日間に渡って開催されたJaSST、その2日目のセッションで登壇させていただきました。

セッションの話

Web.JaSST ~ Web Service QA Meeting in JaSST ~というセッションに参加させていただきました。

これはWebサービスに関わるQA担当者の勉強会Web Service QA MeetingをJaSSTでやろうというものでした。

~ Web Service QA Meeting のコンセプト ~

ウェブサービスの開発現場では、スピードとクオリティの両立が求められます。 組み込み開発やエンタープライズシステム開発などのドメインに比べて歴史は浅いですが、その分、QA担当者は現場で高い技術と柔軟性を求められます。 「Web Service QA Meeting」 では、発表を通して知見をぶつけ合い、シナジーを起こすことで現場の技術向上のヒントを生み出すことを目的としています。

セッション会場の様子 f:id:unifa_tech:20170216121956j:plain

登壇内容について

スライドがこちら。 speakerdeck.com

弊社QAの仕様改善についての動き方は特徴があるのでそこのお話をさせていただきました。
ユーザビリティを重視した仕様チェックを1周目の開発プロセス上で最低3回行っていますという話です。

詳細はスライドを見ていただくとして、
このプロセスが成り立っている理由のひとつとしては、エンジニアとQAとの信頼関係が強いからだと思っています。

載せきれなかった小話

QAが上流工程から参加する上でのエンジニアのメリット(実際に聞いてきました)

  • エンジニアだけだと作りやすさで考えがち、QA視点があると◎。
  • QAはほとんどの案件、機能を見ているので対応漏れがないかチェックできる。
  • 基本設計時に考えた仕様で、不安な部分の相談が気軽にできる。悩む時間が減る。
  • QAに渡す時に仕様説明をしなくていいから楽。
  • サポートとの間に入って調整してもらえる。

→全体的に安心感がある。というお話でした。嬉しかったです。聞いてよかった。

私はエンジニアが実装に集中できるように動くことも仕事の一つだ思っています。
それもエンジニアと良い信頼関係を築けている理由かもしれません。

登壇してみて思ったこと

大勢の人の前で話すということが初めてでした。
初舞台があのJaSST!ということで緊張しましたが、本当に光栄な話で、やってよかったと思っています。
登壇後、内容について質問をいただいたり色々な方とお話しすることができてとても刺激的な2日間でした。

あと資料作るのはいいですね!
というのも、自分がやってることの整理ができるので今後の課題だったり自分が向かいたい方向を改めて確認することができたなと。
普段無意識でやってることの理由付けというか、 あー結局ユーザーに気持ちよく使ってもらいたいんだなと改めて思いました。
スライドの「QAがやりたいこと」にもありますが、
私がQAするシステムを使うことで、ユーザーが何かを得てくれるとか、ユーザーが幸せになってほしいとかなんだなと。

そんな感じでこれからもQAの枠にはあまり捕らわれず、ユーザビリティ向上のために活動していこうと思いました。

(終わったあとのビールはとても美味しかったです。)

最後まで読んでいただきありがとうございました!

f:id:unifa_tech:20170216121854j:plain

ユニファのQAの取り組みと課題

こんにちは、某VRをいまも入手できないQAの駒井です。 2017年が早くも1ヶ月経過した・・・みたいなことを毎年考えている気がします。

年の経過もそうですが、私自身もユニファに入社したのが昨年の7月ですので まだ半年ほどしか経過していないのですが、それ以上の期間いるんじゃないかと思う程入社以来濃い経験をさせてもらってます。

今回はそんな自分がユニファのQAについてほんの少し紹介させていただこうと思います。

続きを読む

調査しやすくするためログにリクエストIDを入れましょう

はじめまして、ユニファ株式会社のWEBエンジニアのチョウと申します。

こんなことがないでしょうか。突然調査依頼が来て、あるユーザーについて調べてほしいです。大量のログから掘り出してみましたが、ユーザー何人がアクセスするによってログが混じってしまいました。RailsのログにプロセスのIDが入ってますが、1つのプロセスは連続で複数ユーザーに使われて、リクエストとリクエストの境界が見づらく、時間かかるケースよくあります。もっと問題なのは、システムは必ず1つのログファイルに出力するわけではない。リクエストログは複数のファイルに分けられてしまったら、調査自体が邪魔されるといっても過言ではない。

ここで問題をまとめましょう。

  1. ユーザーあるいはユーザーのリクエストを特定したい
  2. 1つのリクエストが複数のログファイルに分けても分かる

ここですぐ分かる方がいるかもしれません、1つのリクエストは複数行のログを出力しているので、この複数行のログをあるIDなどでつなげればいいのです。 もっと具体的には、リクエストごとにユニークをIDを作成し、ログを出力するところ、このIDを一緒に出せば連続の行でもわかります。

request-id-1: foo
request-id-2: bar
request-id-1: foo2

ここでrequest-id-1でgrepすればプロセスID関係なくこのリクエストのログだけフィルターできます。

Rails自体はlog_tagsという設定があります。

config.log_tags = [ :uuid ]

を有効にすれば、ログにX-Request-Idの内容を出力されます。X-Request-Idはリクエスト別で作成されましたので、要望1に合ってます。

Log tagging in Rails | We Are Stac

BEFORE

Started GET "/dashboard" for 127.0.0.1 at 2014-11-24 15:48:30 +0000

AFTER

[a00c54e0-874f-4358-a7b9-accef0c407c6] Started GET "/dashboard" for 127.0.0.1 at 2014-11-24 15:48:30 +0000

これで終わり?残念ながら、この方法はRails.loggerだけに効き、複数のログファイルに通用しないです。 しかし、log_tagsのように、ログ出力するとき、X-Request-Idを入れれば解決できると思います。

そもそもX-Request-Idはどこからですか。答えはRailsのRake Middleware:ActionDispatch::RequestIdです。このmiddlewareはX-Request-Idを決め、Rackのenvに設定してます。 envの中にあると、ログを出力するところ取得しにくいため、まずthread local variableとかに保存してみます。つまり、自分でmiddlewareを作り、X-Request-Idをthread local variableに設定します。

middlewareリスト

use ActionDispatch::Static
use Rack::Lock
use #<ActiveSupport::Cache::Strategy::LocalCache::Middleware:0x007f9112ed8258>
use Rack::Runtime
use Rack::MethodOverride
use ActionDispatch::RequestId
use Rails::Rack::Logger
use ActionDispatch::ShowExceptions
use ActionDispatch::DebugExceptions
use BetterErrors::Middleware
use ActionDispatch::RemoteIp
use RailsDevTweaks::GranularAutoload::Middleware
use ActionDispatch::Callbacks
use ActiveRecord::ConnectionAdapters::ConnectionManagement
use ActiveRecord::QueryCache
use ActionDispatch::Cookies
use ActionDispatch::Flash
use ActionDispatch::ParamsParser
use ActionDispatch::Head
use Rack::ConditionalGet
use Rack::ETag
use ActionDispatch::BestStandardsSupport
use ExceptionNotification::Rack
run Foo::Application.routes

application.rb

config.middleware.insert_after 'ActionDispatch::RequestId', 'MyLogContextCollector'
class MyLogContextCollector
  def initialize(app)
    @app = app
  end

  def call(env)
    # request id from ActionDispatch::RequestId
    request_id = env['action_dispatch.request_id']
    MyLogContext.set_current_request_id(request_id)
    @app.call(env)
  ensure
    MyLogContext.clear_current_request_id
  end
end

ここでenvからX-Request-Idを取り出し、MyLogContextのthread local variableに設定します。

class MyLogContext
  TRANS_VAR_REQUEST_ID = :request_id

  attr_reader :severity # String
  attr_reader :time # DateTime
  attr_reader :program_name # String
  attr_reader :message # Object

  # @param [String] severity
  # @param [DateTime] time
  # @param [String] program_name
  # @param [Object] message
  def initialize(severity, time, program_name, message)
    @severity = severity
    @time = time
    @program_name = program_name
    @message = message
  end

  # @return [Integer]
  def get_process_id
    $$
  end

  # @param [String] format
  # @return [String]
  def get_formatted_time(format = nil)
    return nil if @time.nil?
    return @time.strftime(format) if format

    "#{@time.strftime('%Y-%m-%d %H:%M:%S')}.#{'%06d' % @time.usec.to_s}"
  end

  # @return [String]
  def message2string
    case @message
      when ::String
        @message
      when ::Exception
        "#{ @message.message } (#{ @message.class })\n" <<
            (@message.backtrace || []).join("\n")
      else
        @message.inspect
    end
  end

  class << self
    # @param [String] request_id
    def set_current_request_id(request_id)
      set_trans_var(TRANS_VAR_REQUEST_ID, request_id)
    end

    # @return [String]
    def get_current_request_id
      get_trans_var(TRANS_VAR_REQUEST_ID)
    end

    def clear_current_request_id
      set_trans_var(TRANS_VAR_REQUEST_ID, nil)
    end

    # @param [Symbol] key
    # @param [Object] value
    def set_trans_var(key, value)
      ::Thread.current.thread_variable_set(key, value)
    end

    # @param [Symbol] key
    def get_trans_var(key)
      ::Thread.current.thread_variable_get(key)
    end
  end
end

ログを出力する時、都度thread local variableであるX-Request-Idを入れるのはしたくないため、log formatのところすこし改造してみました。

logger = Logger.new('log/foo.log')
logger.formatter = MyLogFormatter.new(lambda{|context|
  "[%s #%d] %5s -- %s: [%s] %s\n" % [
      context.get_formatted_time,
      context.get_process_id,
      context.severity,
      context.program_name,
      MyLogContext.get_current_request_id,
      context.message2string
  ]
})
class MyLogFormatter
  def initialize(lambda)
    @lambda = lambda
  end

  # @param [String] severity
  # @param [DateTime] time
  # @param [String] prog_name
  # @param [Object] msg
  # @return [String]
  def call(severity, time, prog_name, msg)
    context = ::Yoursmile::LogContext.new(severity, time, prog_name, msg)
    @lambda.call(context)
  end
end

これで全部終わりました。

==> log/1.log <==
[2016-11-25 17:26:11.350612 #66417]  INFO -- : [b15ea4d9a43bc7aa390051e16c2dbe3b] 1
[2016-11-25 17:26:11.367210 #66417]  INFO -- : [b15ea4d9a43bc7aa390051e16c2dbe3b] 2
[2016-11-25 17:26:11.367284 #66417]  INFO -- : [b15ea4d9a43bc7aa390051e16c2dbe3b] 3
[2016-11-25 17:26:11.370316 #66417] DEBUG -- : [b15ea4d9a43bc7aa390051e16c2dbe3b] 4
[2016-11-25 17:26:11.372182 #66417] DEBUG -- : [b15ea4d9a43bc7aa390051e16c2dbe3b] 5
[2016-11-25 17:26:11.374109 #66417] DEBUG -- : [b15ea4d9a43bc7aa390051e16c2dbe3b] 6

==> log/2.log <==
[2016-11-25 17:26:11.383344 #66417] DEBUG -- : [b15ea4d9a43bc7aa390051e16c2dbe3b] 7

==> log/3.log <==
[2016-11-25 17:26:11.391745 #66417] DEBUG -- : [b15ea4d9a43bc7aa390051e16c2dbe3b] 8

==> log/1.log <==
[2016-11-25 17:26:11.415792 #66417] DEBUG -- : [b15ea4d9a43bc7aa390051e16c2dbe3b] 9
[2016-11-25 17:26:11.432047 #66417]  INFO -- : [b15ea4d9a43bc7aa390051e16c2dbe3b] 10
[2016-11-25 17:26:11.441824 #66417] DEBUG -- : [b15ea4d9a43bc7aa390051e16c2dbe3b] 11
[2016-11-25 17:26:11.448600 #66417] DEBUG -- : [b15ea4d9a43bc7aa390051e16c2dbe3b] 12
[2016-11-25 17:26:11.450477 #66417] DEBUG -- : [b15ea4d9a43bc7aa390051e16c2dbe3b] 13
[2016-11-25 17:26:11.451106 #66417]  INFO -- : [b15ea4d9a43bc7aa390051e16c2dbe3b] 14

よさそう。

まとめ

あとで本番にリリースし、調査がすこし楽になった感じがします。エラーはある原因で別のファイルに出力されましたから、本来エラーを起こすリクエストを特定するのは難しかったです。そこでこの機能のおかげて、エラーを出力する行のrequest idが分かればすぐgrepで見つかりました。

実際、X-Request-Idはアプリケーション内のログではなく、1つのリクエストが複数アプリケーションに関わる場合も利用できます。それは最初のアプリケーションあるいはWEBサーバーがRequest-Idを作成し、RPCのパラメータとしてほかのアプリケーションに通信し、処理のログを繋げます。つまり、request tracerみたいなものです。

最後に、以上の内容は役に立ちましたら幸いです。

テストコード(RSpec)の高速化事例

はじめまして、ユニファ株式会社でWebエンジニアとして働いている本間と申します。 普段は、Ruby on Railsを使ったサービスのサーバーサイドの機能追加や改善を担当しています。

弊社の主要サービスである写真サービス るくみーは2013年5月に開発がスタートし、あと少しで5年目を迎えようとしています。 開発がこれだけの期間続けられているというのはとても喜ばしいことだと思うのですが、一方で開発初期にはなかった問題も発生してきています。 そのような問題の1つに「テストコードの実行完了までに時間がかかる」というものがあり、弊社でも発生しておりました。

今回、この問題に対して改善施策を実施し、それなりの効果を得ることができましたのでご紹介したいと思います。

※注意 : RSpecは2系、かつDatabaseCleanerを使用していることが前提となる箇所があります。

結果比較

はじめに改善施策の実施前後の結果の比較です。 以下は、私のローカル環境(MacBook Pro (Retina 13-inch、Early 2015))で全てのテストコードを走らせた時の実行時間の比較です。

実施前(17:02)

f:id:ryu39:20170123113700p:plain

実施後(3:16)

f:id:ryu39:20170124111411p:plain

改善対象の洗い出し

性能改善を始めるにあたって、最初に攻めどころを明確化を行いました。

RSpecはデフォルトで時間がかかるexampleやspecファイルを表示してくれますが、今回の用途に少しマッチしなかったため「合計実行時間」が大きい順にspecファイルを表示してくれるFormatterを自作して対応しました。作成したFormatterは扱いやすいようにGemにしてあります(※注意 RSpec 2系でしか動きません)。

このFomatterを使ってRSpecのテストを実行すると、下記のように合計実行時間の上位10specファイルが表示されます(クラス名とパスは隠しています)。

f:id:ryu39:20170124112446p:plain

改善施策の実施

合計実行時間が長い順にspecファイルを調べ、原因と思われる箇所に対して対策を実施していきました。

不要な機能のテストコードを削除

実行時間がかかる上位のspecの中に、今後使う予定がないrakeタスクのテストコードがいくつかありました。 このコードは不要でしたので本体コードごと削除しました。

権限チェックテストの簡略化

弊社サービスには何種類かのロールがあり、ロールによって操作可能なアクションが異なります。

時間のかかるControllerのテストでは、各アクションに対して全てのロールで成功 or エラーのテストを実施していました。具体的には、以下のようなコードになります。

describe UsersController do
  describe '#index' do
    let!(:users) { create_list(:user, 10) } # テストデータ作成

    subject(:response) { get :index }

    # 全てのロールで成功 or エラーをテスト
    UsersController::PERMITTED_ROLE_IDS.each do |role_id|
      before do
        session[:role_id] = role_id
      end

      it { 
        expect(response.status).to eq(200)
        expect(assigns(:users)).to eq(users)
      }
    end
    (Role::ALL_ROLE_IDS - UsersController::PERMITTED_ROLE_IDS).each do |role_id|
      before do
        session[:role_id] = role_id
      end

      it { expect(response.status).to eq(403) }
    end
  end
end

ロールによる権限チェックのテストは重要なのですが、「テストデータ作成」と「アクション処理」が複数回実施されていて、ここに改善の余地があると考えました。

解決策としては、機能的なテストは1つの代表ロールでのみチェックし、ロールの権限チェックテストではAnonymous controllerを使用することで「テストデータの作成」と「成功時のアクション処理」をスキップするようにしました。

Anonymous controller はRSpecが提供する機能の一つで、テスト対象のControllerを継承したクラスをテストコード内で定義することができます。Anonymous contollerでアクションの中身をオーバーライドして空のレスポンスを返すことで、before_action で実施している権限チェックのコードをテストしつつ、アクション処理の実行時間を短縮できます。

修正後は以下のようなコードになりました。

describe UsersController do
  before do
    session[:role_id] = 9999 # 代表ロールID
  end

  # 機能的なテストは1つの代表ロールでのみ確認
  describe '#index' do
    let!(:users) { create_list(:user, 10) } # データ準備

    subject(:response) { get :index }

    it { 
      expect(response.status).to eq(200)
      expect(assigns(:users)).to eq(users)
    }
  end

  describe '権限チェック' do
    controller do
      # 空レスポンスを返すだけ、成功時のアクション処理時間を短縮
      def index
        head :ok
      end
    end
    before do
      routes.draw do
        resources :users, controller: :anonymous, only: [:index]
      end
    end

    describe '#index' do
      # 権限チェックではテストデータを作成しないことで時間短縮

      subject(:response) { get :index }

      UsersController::PERMITTED_ROLE_IDS.each do |role_id|
        before do
          session[:role_id] = role_id
        end

        it { expect(response.status).to eq(200) }
      end
      (Role::ALL_ROLE_IDS - UsersController::PERMITTED_ROLE_IDS).each do |role_id|
        before do
          session[:role_id] = role_id
        end

        it { expect(response.status).to eq(403) }
      end
    end
  end
end

共通データの事前作成

時間のかかるspecの多くでは、DBへのデータ書き込み(特にどのテストでも使う共通のオブジェクトの作成)で時間がかかっていました。

この問題を解決する方法として、specファイル内で共有可能なデータは before(:all) で事前に作成し、これを各exampleで参照するようにしました。

しかし、この方法はテスト間の独立性を壊してしまう可能性があるため利用には注意を払う必要があります。今回、以下のルールに沿って実施しました。

  • 共有するのは参照専用のオブジェクトのみ。
  • 共有する範囲は1つのspecファイル内まで。
  • 対象は合計実行時間の上位20specファイルまで。
  • 必ず after(:all) で作成したオブジェクトを全て削除する。

テストコードは以下のようになります。

describe SomeController do
  before(:all) do
    @user = create(:user)
  end
  after(:all) do
    DatabaseCleaner.clean_with(:truncation)
  end

  # 以降、@userでユーザーオブジェクトを参照
end

rspecの並列実行

上記施策を実施して実行時間を10分前後に減らすことはできたのですが、大きな改善を見込める箇所が見当たらなくなってしまいました。 そこで、最終手段としていたテストの並列実行を導入しました。

RSpecを並列実行するGemとしてparallel_teststest-queueが有名なようです。 今回は「parallel_tests」を使用しました。導入にあたって実施した内容は以下になります。

  1. Gemfileに parallel_tests を追加し、 bundle install
  2. database.ymlを開き、テスト用のデータベース名の末尾に <%= ENV['TEST_ENV_NUMBER'] %> をつけるように修正。
  3. bundle exec rake parallel:setup を実行し、テスト用のデータベースを準備する。
  4. parallel_rspec spec でテストを実行する。

並列化の効果は非常に大きく、これだけでテストの実行時間が3分の1程度になりました。

parallel_testsを使う場合、以下の設定をしておくとオススメです。

  • 各specの実行時間を記録したログを出力しておく。公式リポジトリに説明があります。この設定を行うと前回の実行時間に基づいてspecファイルが分配されるため、プロセスごとの実行時間のばらつきが小さくなり、早く全てのテストが終わる。
  • parallel_rspecを実行する際に --nice を指定すると、テスト実行中に他の作業をするとき動作がもっさりしにくくなる。

実施しなかった対策

下記の施策は検討には上がっていたのですが、実施はしませんでした。 本体への影響が大きかったり、実施に時間がかかるというのが主な理由です。

  • インメモリDBを使う
  • RubyやRailsのバージョンアップ
  • テストの精査・サンプリング

Werckerでも並列実行

弊社ではCIサービスのWerckerを利用しており、リポジトリへのpushを検知して自動でテストを流すようにしています。 こちらも並列化により実行時間を大幅に短縮できたので、合わせてご紹介いたします。

設定は非常に簡単で wercker.yml の記載を以下のように変更するだけでした。

build:
    steps:
        - bundle-install

        # rails-database-ymlが生成するdababase.ymlにはDB名に環境変数「TEST_ENV_NUMBER」が組み込まれている。
        - rails-database-yml

        # db:schema:load の代わりに parallel:setup を、 rspecコマンドの代わりにparallel_rspecコマンドを使うだけ。
        - script:
            name: Set up db
            code: bundle exec rake parallel:setup
        - script:
            name: rspec
            code: parallel_rspec spec

まとめ

今回、弊社で実施したRSpecのテストコードの高速化事例をご紹介させていただきました。

この活動はまだまだ終わりではなく、継続して改善していく必要があります(テストコードはどんどん増えていくため...)。 今後、大きな改善をすることができたら、またこのブログで紹介したいと考えています。

それでは最後まで読んでいただきありがとうございました。

td-agent(Fluentd) を利用したログ収集

はじめまして! 仕事内容がわかりにくいインフラエンジニアのすずきです。

先日このブログにて弊社田渕が書いていましたが、 昨年Ruby biz Grand prix 2016で審査員特別賞をいただくことができとてもありがたく思います。

Ruby biz Grand prix 2016 - ユニファ開発者ブログ

この賞を頂いたからというわけではないですが、
いろんな方に弊社サービスを安心して快適に利用していただけるように日々頑張っていかねばと改めて思った次第です。

そういえば、Ruby biz Grand prix といえば前回大賞となったトレジャーデータ株式会社様、 弊社でも一部で恩恵をうけているので軽く紹介できればと思います。

ただサービスではなく、公開していただいているFluentdのパッケージ版td-agentを利用させていただいているといった感じです。

Fluentd とは

Fluentd はログの収集、集約やデータの収集、集約、プラグインを利用した集計などなど ログやデータの収集にまつわるものならなんでも出来ちゃいそうなツールです。
プラグインによる拡張ができるので必要な機能が必要であれば自分で作ることも可能です。

今回Fluentdの事を書いていますが、検索すれば設定例などは沢山出てくるとおもうので一つの例として見ていただけたらなと思います。

ログの収集の方法

Fluentdの利用はまだログの収集がメインになっています。
弊社エンジニアもログの集約サーバでログを見てもらっているかなと思いますが、
裏でFluentdが動いてる事を知ってる方は少なそうなのでこの場を借りて共有しておこおうかなと思います。 ※詳細は別途勉強会で

構成としては単純で以下の2種類になります。

  • サービス用のサーバ群
    • ログ収集の設定がされたFluentd
  • ログ集約サーバ
    • ログ集約用の設定 がされたFluentd

ログ収集の設定

ログ収集ならトレジャーデータ株式会社の田籠さんの作られたfluent-agent-liteや、株式会社カヤックのfujiwaraさんの作られたfluent-agent-hydraなどもあるのですが、 これらは軽量なのですがツール停止時点からログ収集を再開することができなさそうだったので収集もFluentdを利用しています。

サンプルとしてWebサーバのログ収集設定を用意してみました。(fluentdハイライト何が良いんだろ、とりあえずshが見やすそうでした)
なお利用しているFluentdのバージョンはちょっと古くて申し訳ないのですが0.12系です。
設定の説明はコメントとして追記しています。
また、これから出てくるpathの値などは適当な値を羅列しているだけなので、 試される方はご自分の環境にあわせて変更してください。

<source>
  @type tail
  ## apacheのアクセスログはltsvにしているのでltsvフォーマットで収集するようにしています。
  format ltsv
  path /var/log/httpd/access_log
  tag httpd.access_log
  pos_file /var/log/td-agent/httpd-access.log.pos

  ## Fluentdのデータのやりとりにはtimeフィールドがつくいているのですが、time_formatをつけることでFluentdが処理した時間ではなく、
  ## ログのtimeフィールドの時刻を利用してFluentdを処理できます。
  time_format %d/%b/%Y:%H:%M:%S %z
  read_from_head true
  rotate_wait 60

  ## TAILラベルをつける
  @label @TAIL
</source>

<source>
  @type tail
  ## errorログなどフォーマットが決まっていないものがあるのでnoneフォーマットで収集するようにしています。
  format none

  ## pathにワイルドカードを利用して全てのログを対象に収集します。
  ## 弊社ではログローテーションしたものはOLDフォルダに移動させているので、
  ## OLDフォルダと先頭で収集設定を入れたアクセスログを exclude_path に追加して2重で収集されないようにしています。
  path /var/log/httpd/*
  exclude_path ["/var/log/httpd/OLD", "/var/log/httpd/access_log"]

  ## 収集対象がワイルドカードするとpathの/を.に変えたものがタグとして付与されます。
  ## 今回の場合だと/var/log/httpd/error.logの場合 httpd.var.log.httpd.error.log というタグが付与されることになります。
  tag httpd.*
  pos_file /var/log/td-agent/httpd-other.log.pos
  read_from_head true
  rotate_wait 60

  ## TAILラベルをつける
  @label @TAIL
</source>

<source>
  @type tail
  ## こちらはRailsのログですがapacheのログ収集と同じく不要なものを除いて全て収集します。
  format none
  path /www/rails/web/shared/log/*
  exclude_path ["/www/rails/web/shared/log/OLD",  "/www/rails/web/shared/log/newrelic_agent.log"]
  tag web.*
  pos_file /var/log/td-agent/web.log.pos
  read_from_head true
  rotate_wait 60
   ## TAILラベルをつける。
  @label @TAIL
</source>


## TAILラベルのついたデータは全てログ集約サーバに転送するようにします。
## 古いFluentdでは httpd.**,web.**など書いてタグによる処理を書かないといけませんでしたが、
## 0.12から追加されたlabelでそのようなことをしなくてよくなりました。
<label @TAIL>
  <match **>
    @type forward
    flush_interval 1s
    <server>
      name log-server
      host 10.0.0.251
    </server>
  </match>
</label>

ログ収集ではこのような設定を利用しています。
path*を利用できるとはかいてあったのですが、 利用している記事などはあまりみかけなかったのでこんな感じかな?といった感じで設定を作っています。
path*を利用している理由ですが、サーバアプリのログが固定ではないからです。
固定というと語弊がありますが、必要に応じでてサーバアプリ側でログが追加されたり消されたりするためです。
その度にFluentdの設定変更対応をする為の連携を取るのもお互いに無駄かと思い手離れしやすいようにこの設定にしました。

ログ集約用の設定

先程収集されて、転送されてきたデータを受け取るログ集約サーバ側の設定サンプルも用意しました。

## サーバサーバに転送されてきたログをすべてにlogsラベルをつけています。
## 別のサービスからデータを受け取る場合はポートを変更して別のラベルをつけるなどの対応が必要です。
<source>
  @type forward
  @label @logs
</source>

<label @logs>
  ## apacheのアクセスログのみなので受け取ったログをファイルにおとすよくある設定にしています。
  <match  httpd.access_log>
    @type file

    time_slice_format %Y%m%d%H
    compress gz
    format ltsv
    include_time_key true
    buffer_chunk_limit 1g
    path /data/log/httpd/access_log
    symlink_path /data/log/httpd/httpd.access_log
  </match>

  ## apacheのアクセスログ以外すべて受け取っているのでfluent-forest-pluginを利用しています。
  ## このプラグインを利用することでタグに応じた設定がかけるので楽です。
  ## そうでない場合上記のapacheのアクセスログを同じような設定をログの数だけ用意する必要があって非常に面倒ですし、
  ## ログが増えるたびに設定を追加するなどの作業が発生します。
  <match {httpd,web}.**>
    @type forest
     subtype file
    <template>
       time_slice_format %Y%m%d%H
       compress gz
       format single_value
       add_newline true
       message_key message
       buffer_chunk_limit 1g
    </template>

    <case httpd.**>
       path  /data/log/httpd/__TAG_PARTS[0]__/__TAG_PARTS[-1]__
       symlink_path /data/log/httpd/__TAG_PARTS[0]__.__TAG_PARTS[-1]__     
    </case>

    <case web.**>
        path  /data/log/rails/__TAG_PARTS[0]__/__TAG_PARTS[0]__/__TAG_PARTS[-2]__.log
        symlink_path /data/log/rails/__TAG_PARTS[0]__/__TAG_PARTS[0]__.__TAG_PARTS[-2]__.log
    </case>
  </match>

__TAG_PARTS[0]__,__TAG_PARTS[1]__とありますが、 これらはタグを.で区切った配列とみなしてその情報を利用しています。

path  /data/log/rails/__TAG_PARTS[0]__/__TAG_PARTS[0]__/__TAG_PARTS[-2]__.log

コレはどういうことかというと web.app.error.logのタグが付いたデータは/data/log/rails/web/web/error.logに吐き出されるということです。

今回fluent-plugin-forestを利用したログ収集の設定を書きましたが、 v0.12からこのプラグインが無くてもいい感じに書けそうみたいなのを見た気がするのですがやり方が思いつかなかったので現在も利用しています。

ご存じの方居たらお知らせ頂けたらと思います。

さいごに

今回Fluentdの弊社の利用方法をすこし紹介させていただきました。
だれか1人の方にでも参考にしていただけたら幸いです。

他にもAWSサービスの連携や、文字列から条件分岐してSlackに通知するなどやっていたりもします。
またの機会があれば紹介させていただこうと思います。

弊社はZabbixでログ監視もしていますが可能ならいつかFluentdを利用したログ監視に移動したいなとはおもっています。
Zabbixはログ監視の追加が面倒なので………
そういった話も書けていけたらと思っています。

引続き弊社ブログよろしくお願いします。

すずき