アドベントカレンダーは、ぎりぎりにならないと書けないを解決する

この記事は freee Developers Advent Calendar の 23 日目の記事です。


悩みの種の泉へようこそ

ここでは皆様から送られてきた悩みの種を ひも(@him0net) が無駄に技術で解決し、どのくらい解決できているかを担当編集者の takuma に評価してもらいます。

それでは、悩みの種を紹介しましょう。

「こんにちは、会計 freee のアプリケーションをエンジニアをしている ひも です。弊社では freee developer アドベントカレンダーというものがあり、12/1 から 12/25 のクリスマスまで、1日1つブログ記事を公開していくという取り組みをしています。私は毎年11月に、この執筆者の募集で立候補してしまうのですが、いざ12月になるとバタバタして全然記事が書けていないことに状態で苦しんでいます。ここで思ったのですが、技術の力で記事の執筆を支援することはできないでしょうか?よろしくおねがいします。」

この悩みの種、技術で解決するとこうなります。

developers ブログの記事をもとに文章の自動生成を行うと「xxx」という文章ができる。

実際に実装してみた

まずは、文章の生成の方法の技術選定を行う。文書の生成プログラムをざっくり調べたところ、Chainer や TensorFlow を用いた RNN (回帰型ニューラルネットワーク)によるものと、マルコフ連鎖に基づくものが見つかった。

時間が無い(超重要)ので、アルゴリズムを理解しているマルコフ連鎖に基づく文章の自動生成を採用することにした。

また freee のアドベントカレンダーの記事を作成することが目的なので、シードデータには過去のアドベントカレンダー (2018-2020) の記事を利用することにする。記事の収集には先進の技術(コピペ)を用いた。

f:id:him0:20201223011411g:plain
アドベントカレンダーをコピペしてシードデータを集めている様子。

マルコフ連鎖の辞書作成にあたり、分かち書きには、形態素解析エンジン MeCab を用いた。セットアップには ipa辞書インストールも必要であった。

python から MeCab が呼び出せる環境を構築を行い、分かち書きを行った。

$ poetry run python wakati.py
['', 'こんにちは', '、', 'freee', '株式会社', 'で', 'エンジニア', 'を', 'やっ', 'て', 'いる', 'id', ':', 'ymrl', 'です', '。', '\n', 'はやい', 'もの', 'で', '、', '2018', '年', 'も', '残す', 'ところ', '1', 'ヶ月', 'と', 'なり', 'まし', 'た', '。', '\n', '12', '月', 'と', 'いえ', 'ば', '年末', '調整', 'と', 'Advent', 'Calendar', 'です', 'ね', '!', 'という', 'わけ', 'で', '、', 'この', '記事', 'は', 'freee', 'Developers', 'Advent', 'Calendar', 'の', '1', '日', '目', 'です', '。', '\n', '今年', 'も', 'また', '12', '月', '25', '日', 'まで', '毎日', 'リレー', 'で', '記事', 'を', '掲載', 'し', 'て', 'いき', 'ます', '。', '\n', 'さて', '、', '今回', 'は', '開発', '者', 'ブログ', '、', 'つまり', ...

分かち書きが正しくできているのか確認すため、単語の出現回数順で表示してみた。

$ poetry run python collection_order.py
('の', 4699)
('、', 4405)
('\n', 3983)
('。', 3968)
('を', 3824)
('て', 3585)
('に', 3415)
('が', 2946)
('は', 2708)
('で', 2459)
('た', 2301)
('し', 2279)
('ます', 1709)
('と', 1603)
('です', 1125)
('こと', 971)
('も', 970)
('い', 898)
('する', 832)
('な', 797)
('まし', 789)
('いる', 599)
('という', 572)
('freee', 561)
...

freee という単語がこの順位ででてくるのはなかなかにこの freee developers blog らしい文章ができそうで期待が高まってきた。

マルコフ連鎖のロジックの実装を行う。階層は適当に決め打ちで3階でいくことにした。3単語をキーにして、次に出てくる単語が決定する。分かち書きを行った単語をキーとその後に出てくる単語のリストと言う形で辞書として格納していく。

dictionary = [
  ([ 'こんにちは', '、', 'freee' ], [ '株式会社', ... ]),
  ([ '、', 'freee', '株式会社' ], [ 'で', ... ]), ...
]

実際の文章を生成するロジックでは最新の3単語は保持して、マルコフ連鎖の辞書から次のワードのリストを決定し、リストの要素からランダムで1つの単語を抽選する。

prev_three = ['こんにちは', '、', 'freee']

# python で、array find するの地味に大変だった
next_word_list =  next(filter(lambda x: (x[0][0] == prev_three[0] and x[0][1] == prev_three[1] and x[0][2] == prev_three[2]), dictionary), None)
next_word = random.choice(next_word_list)

ロジックが出揃った。

実際に出力してみた。

さて、どんな文章が生成されるのか!!!

f:id:him0:20201223135850g:plain
terminal でプログラムを実行している様子

$ poetry run python markov_chain.py
昔からエンジニアリングもマネージメントも好きなので、エンジニアとしての原点回帰であっても、どういった料理が来たかや何をお皿によそったのかを知るために編 み出した方法として、巷では自作キーボード界隈でいうところの終着点的な意味です。

こうしてこの世界でまた1つ悩みの種が技術で解決された。

developers ブログの記事をもとに文章の自動生成を行うと「エンジニアから料理に目覚め、自作キーボードに落ち着く」という文章ができる。

運命の評価発表

それでは、どのくらい解決できたかを評価していただきます。

him0「どうですか?」

takuma「エンジニアとしてのキャリア像について語るかと思いきや実際には料理について考察しているようで、非常に興味深いです。」

takuma「でも、そんなことより、来年は11月から準備してくださいね。」

him0 🥺

him0「明日は、hg さんの記事です。」

him0, takuma 「それでは、またお会いしましょう。でわでわ〜」


自分はマルコフ連鎖の辞書をタプルで実装してしまったが、[Python]N階マルコフ連鎖で文章生成 の deque を使った実装がきれいだったので、コードはこちらを参考にした方が良いです。また、文章の初めに [BOS] を設定し、 を FOS として扱う実装もこちらを参考にさせていただきました。ありがとうございました。

オンラインになった社内イベントをエンジニアも全力で手伝っている話

この記事は freee Developers Advent Calendar の 22 日目の記事になります.

こんにちは, freee で会計freee の開発をしているエンジニアのけむりだま (@_kemuridama) です. 2018 年に新卒入社して, 普段は会計freee の新機能開発や保守運用, 社内デザインシステム Vibes のメンテナンスをしていたりしています.

asobiba スタジオ

フルリモートで社内イベントがオンラインになった

今年は新型コロナウィルス感染症が猛威を奮った激動の一年でした. freee も 3 月から完全フルリモート勤務を行っていて, 自分がリーダーとして主催している freee Tech Night も残念ながらオフラインではなく 4 月からオンラインで実施しています.

freee は「ムーブメントで世界を変える」という目標を組織として掲げていて, ムーブメント型チームを目指すために社内交流をを促進させるための社内イベントも数多く存在しています. これらのイベントもオンラインで実施できるように社内で試行錯誤してきました. 自分はエンジニアとしてそのほとんどに携わってきたのでその紹介をしていきたいなと思います.

New社式 (入社式)

3 月からフルリモートになって初めてのオンラインイベントは 4/1 の New社式でした. もともと自分はこの New社式の企画の時点から携わっていたのですが, 刻一刻と情勢が変わる中で完全にオンラインでやるのか, 新卒だけはオフラインでやるのかなど本当にギリギリまで調整をしていました.

今年は残念ながら完全オンラインとして配信スタジオとなった本社の 9F の asobiba (多目的スペース) にある畳スペースには MC と配信スタッフの 4 人だけという最小構成で新卒を迎えるべく New社式を開催しました.

New社式の asobiba スタジオ
New社式の asobiba スタジオ

カメラで MC の 2 人を撮りつついろんな出演者たちと Google Meet とつないで MC とコミュニケーションできるようにキャプチャーボードを使って OBS で合成しつつ社内 SNS の Workplace で配信を行いました. このときはまだ社内にも配信するための機材が十分になくて自分もいくつか機材を提供したりして, なんとか無事に配信することができました.

New社式の詳しい中身に関しては 【 New社式 】オンラインで新卒27名の入社式を開催しました! を見てください!!

freee SPIRIT 2021

次に自分が携わってきたのが年に 1 度の全社合宿の freee Spirit (通称フリスピ) です. こちらも本来であれば大きな会場を借りて開催をしているのですが, 今年はオンラインになりました. フリスピは登壇者も多く, かつ社員同士がグループに分かれてディスカッションする必要があるので Web 会議サービスの Remo を使って配信しました.

フリスピでは「DS (CEO) を自宅からオンラインで中継 & クロマキーを使って合成する」という試みと「ワカルさん (社内に存在するゆるキャラ) をバーチャル合成する」という試みを新たに行いました.

freee SPIRIT 2020 の asobiba スタジオ
freee SPIRIT 2020 の asobiba スタジオ

前述の DS の中継に関しては自分が担当していました. 事前に DS の自宅にロケハンに向かい, 中継安定のために有線 LAN が中継場所となる部屋に引けるだろうかとかクロマキーのためのグリーンバックがちゃんと設置できるかなど確認したり, 当日も朝早くから集合して中継や asobiba スタジオにいる MC と合成ができるかなど調整をしました. DS の映像の他に登壇スライドも asobiba に送らないといけなかったり, asobiba にいる MC と DS がコミュニケーションできるようにしないといけなかったり, かなり色々とハックしてやり遂げました.

DS の自宅から中継する様子
DS の自宅から中継する様子

後述のワカルさんのバーチャル合成は UX の id:ymrl がもともとあった絵からモデルを Live2D でサクッと作ってくれて, VT-4 で声を変えつつ Web カメラでモデルと動きを Sync できるようなシステムを作ってくれました.

ワカルさん合成システム
ワカルさん合成システム

フリスピの詳しい内容については「社員500名 全員オンライン!8時間の大規模イベントを気合とハックでやりきった話。」を見てください!!

株主総会

こちらは社内イベントではないですが, 自分が関わったイベントかつ freee らしい新しい取り組みだったと思うので紹介させてください. freee が上場後初めての株主総会はコロナ禍ということもあって, オフラインとオンラインで同時開催するハイブリッド株主総会にすることになりました.

株主総会の配信スタジオ
株主総会の配信スタジオ

株主総会はオフラインでやっている内容をそのまま YouTube Live で配信するという形でした. そのため, 喋る可能性のある人数が多かったのでマイクの台数こそ多かったものの配信システムはカメラとミキサーと ATEM mini という単純な構成で配信することができました. スライドはカメラを通して映すと見えづらくなったので ATEM mini で合成しました.

大忘年会

先週末に開催された freee大忘年会ももちろんオンライン開催です. asobiba の一角をスタジオに変えて毎週全社会議で司会をやっている 2 人を MC に迎えてカメラとミキサーと ATEM mini と OBS でスタジオを構築し, Remo で配信を行いました.

大忘年会の配信スタジオ
大忘年会の配信スタジオ

今回の肝は 12 拠点からの生中継でした. 12 人が各自宅から Google Meet に入ってそれをスタジオでスイッチングしながら配信するという挑戦をしました. 自分はオフラインとオンラインの映像のスイッチングすべてを担当しました. どのタイミングでどれにスイッチすればいいのか映像ソースが多いので混乱したりしましたがなんとか無事に配信することができました.

おわりに

今回は自分の携わってきた freee の社内オンラインイベント運営について紹介しました. 自分を含めた社内のエンジニアの何人かはよくわからないガジェットをたくさん持っていたり, 家に配信システムがあったりする人がいるので, それらの知識を最大限に発揮して試行錯誤しながら毎回 1 からお手製で配信スタジオを構築しています.

生配信はミスやトラブルが起きればそのまま流れてしまって緊張しますが, やり遂げたときの達成感や参加者からの感想を聞いているとやっていて楽しくなってきます. また社内イベントの配信クオリティを高めることは自分との戦いとなる部分も大きいので, 毎回前回の自分を超えられるように…って思ってます.

こんな感じで色々なものを Hack Everything★ して様々な課題を乗り越えていける仲間を freee では募集してます. コードを書いてプロダクトの成長に貢献する以外にも自分ができることを最大限発揮して freee のカルチャーに貢献してくれるような人が来てくれたら嬉しいです.

jobs.freee.co.jp

明日は一緒に社内イベントの配信をやっているひもくんです. お楽しみに!!!

ミドルウェアのソースコードリーディングのすすめ

この記事は freee Developers Advent Calendar 2020 の 21 日目です。

プロダクト基盤本部で本部長をしています浅羽と申します。プロダクト基盤は文字通りプロダクトの基盤を作っており、SRE、アカウントアグリゲーション基盤、セキュリティ、アプリケーションの基盤、品質、Eng企画と多岐にわたるチームになっています。普段は組織運営であったり困ったことに相談乗ったり、暇を見つけてコード書いたりしています。よろしくおねがいします!

freeeではサービスの安定稼働を重視しており、SREではデプロイの高速化やカナリアリリースなどのような「仮にまずいリリースがでてもすぐに引っ込める」仕組みの開発をしています。もちろんサービス障害が発生しないようにQAチーム中心に対策していますが、失敗はある前提の元でいかにリカバリを素早くできるかも大切にしています。これはこれでどこかで記事にしたいですが、今回は別の話です。

障害が発生しないように対策していますが、それでもサービスの進化とともに課題も生まれてきて予期せぬサービス障害を引き起こすケースがまれに発生します。障害の根本原因はさまざまです。そこで、サービス障害が発生したらなぜそれが発生したのだろう?というのを振り返り、組織的な課題や技術的な課題を見つけて改善していきます。

社内では「なぜなぜ分析」と呼び、社内で定義した障害レベルに応じて「なぜ?」とN階層まで深ぼっていきます。経験的には3階層くらい深堀ると徐々に本質的な課題が見えてくるので、発生した現象に対して「なぜ?」を3階層以上問い続けるのをオススメします。これはこれでどこかで記事にしたいですが、今回は別の話です。

サービス障害の原因の一つとしてミドルウェア起因の障害があるかと思います。超意訳で「ちゃんとドキュメントを読んで、ちゃんと使いましょう」みたいな振り返りで解決するケースもありますが、ミドルウェアの挙動をしっかり追いかけて特性を理解することは結構大事だと思っています。また障害に限らず、新しいミドルウェアを導入する際にある程度検証するかと思いますが、検証しているなかでどうしても不可解な挙動に悩まされることは経験ある方もいるかと思います。なので、色々学びがある(それ以上に楽しい!)のでミドルウェアのソースコードを一緒に読んでみましょう、というのを社内でたまにやります。いくつかのミドルウェアのソースコードリーディングの事例を紹介したいと思います。

なお、この記事で取り上げているソースコードのバージョンが古いものもありますが、過去に調べたものを使っているためです。現時点で使っているバージョンではないのでその点はご承知おきください。

ソースコードリーディングの準備

大抵のミドルウェアのコードはそこそこ大きいです。先頭から読み始めるとすぐに挫折するので興味あるところだけに絞るとよいです。例えば「xxの機能が想定しない挙動をした」という場合は、xxの機能のエントリポイントを見つけてそこだけを深ぼっていきます(これはミドルウェアに限った話ではないですね)。過去の経験からこんな感じで読んだり、読む準備をすると良いんじゃないかなというのをご紹介します。

デバッグビルドとデバッガで止める方法を探す

エディタだけでコードを読むのは結構大変です。動かしながらコード追いかけるのをおすすめします。

  • 大抵の場合はデバッグビルドをするためのオプションが用意されているので、configureを動かす前にオプションを探す
  • C/C++の場合、コンパイラの最適化が走らないようにオプションを制御します(CFLAGSで無理やり-O0を渡すとか)
    • 最適化が効いた状態でデバッガを起動するとレジスタに書かれたりして変数のダンプが大変になります
  • 勇気を持って必要ないところ(もしくは細かすぎる挙動のところ)は読まない、というのも大事
  • データ構造等は紙とペンつかって書き出すのも大事

あると便利ツール

コマンド名 用途
lsof 開いているファイルやソケットを調べる
procfs プロセスの状態を色々調べたいときにみる
netstat, ss ネットワークの接続状況などを調べる
tcpdump 何送っているんだろう?と調べたい場合。暗号化されたら見てもわからない
ipcs shared memoryを調べたい場合(めったに使わない)
strace システムコールをトレース

知っておくとあたりを付けやすい

  • 読みたい機能に関連したシステムコールからbreakpointを貼ることで目的の場所に早く行くことができるので、システムコール名と役割はなんとなく知っていると良い
  • サーバー実装のテクニック
    • self pipe trick
    • Cの場合はメモリプール
    • daemon処理
    • マルチスレッド、マルチプロセス(都度forkする、pre-fork)
    • などなどあるが、いくつかコードを読むと「あ、このテクニックどこかでもみたことある」と気づけるはず

ではいくつかやっていきましょう。

nginx

まだALBが存在していない時期になりますが、とある社内のサービスでCLBの前段にnginxを置きたい要件がありました。nginxがinternal CLBにproxy passするという設定を入れていたのですが、CLBのインスタンスが入れ替わってIPアドレスも変わった場合に、接続タイムアウトが頻発する問題が発生しました。挙動的にCNAMEの結果をTTL無視してキャッシュしているんだろうなと想像したのですが、念のため確認することにしました。ちなみに最新のコードでどのような挙動になっているかは確認していません。ぜひ確認してみてください。

debug build

1.11.12ですが最新版でも恐らく同じような方法です。

wget https://github.com/nginx/nginx/archive/release-1.11.12.tar.gz
tar zxvf release-1.11.12.tar.gz
cd nginx-release-1.11.12
sudo apt-get install gdb emacs make libzip-dev
./auto/configure --prefix=$HOME/nginx --with-debug --without-http_rewrite_module
make install

起動

こんな感じなのを設定します。resolverはresolv.confにかいてあるアドレスを書いてください。

events {
  worker_connections  4096;
}

http {
  server {
    listen 8800;
    location / {
      resolver xx.xx.xx.xx valid=30s; # ここは自宅の環境等のresolv.confを調べてください
      resolver_timeout 3s;
      proxy_pass http://www.freee.co.jp; # これは適当
    }
  }
}

以下のコマンドでnginxを立ち上げます。親プロセスと子プロセスが一個立ち上がります。子プロセスが実際のworkerです。

% ~/nginx/sbin/nginx
% ps auwwfx (MacOSのpsだと f オプションないです) で、子プロセスのPIDをメモってください。
% gdb -p 上のpid

breakpoint

proxy passするということは、とうぜんconnect(2)をどこかで呼び出しているはずなので、まずはソースコードをざっくり検索します。

 % grep -r 'connect(' .
./event/ngx_event_openssl_stapling.c:static void ngx_ssl_ocsp_connect(ngx_ssl_ocsp_ctx_t *ctx);
./event/ngx_event_openssl_stapling.c:    ngx_ssl_ocsp_connect(ctx);
...
./http/ngx_http_upstream.c:static void ngx_http_upstream_connect(ngx_http_request_t *r,
./http/ngx_http_upstream.c:static ngx_int_t ngx_http_upstream_test_connect(ngx_connection_t *c);
./http/ngx_http_upstream.c:            ngx_http_upstream_connect(r, u);
./http/ngx_http_upstream.c:    ngx_http_upstream_connect(r, u);
./http/ngx_http_upstream.c:    ngx_http_upstream_connect(r, u);
./http/ngx_http_upstream.c:ngx_http_upstream_connect(ngx_http_request_t *r, ngx_http_upstream_t *u)
./http/ngx_http_upstream.c:    if (ngx_http_upstream_test_connect(c) != NGX_OK) {
./http/ngx_http_upstream.c:    if (!u->request_sent && ngx_http_upstream_test_connect(c) != NGX_OK) {
./http/ngx_http_upstream.c:    if (!u->request_sent && ngx_http_upstream_test_connect(c) != NGX_OK) {
./http/ngx_http_upstream.c:ngx_http_upstream_test_connect(ngx_connection_t *c)
./http/ngx_http_upstream.c:                                    "kevent() reported that connect() failed");
./http/ngx_http_upstream.c:            (void) ngx_connection_error(c, err, "connect() failed");
./http/ngx_http_upstream.c:    ngx_http_upstream_connect(r, u);
...

なんとなくupstreamに対してconnectしている↑のあたりが怪しいと推測できるので、片っ端からbreakpointを貼っていきます。

  • 読みたい処理が決まったら、多分通るんだろうなと思う関数を見つけてbreakpointを貼ってみる
  • 止まらなかった場合は別にbreakpointを貼る
    • 止まったらbacktraceを bt コマンドで取る
  • debuggerだけでなく、他のツールも組み合わせて読む
    • 今回の場合はupstreamへのconnect(2)のタイミングを知りたかった
  • gdbでstep実行しつつ、netstat -ntで、www.freee.co.jpに接続する(ESTABLISHED)タイミングをみつける
  • primitiveなところまでたどり着いたら、今度は逆に抽象度を上げていって、必要なさそうな箇所はすっとばす
  • いい具合で調査を切り上げる(はまってそのまま読み続けてもok)

proxy passの挙動

コードを読んで見るとproxy_passの名前解決は2つ挙動があることがわかりました。

  • proxy_passに直接proxy先を書いてある場合は、nginx起動時にgethostbyname()をやって、TTL無視してそのまま再利用する(いままでの設定)
  • proxy先を一旦変数に入れてやると、resolverの設定を使って自前でDNSに問い合わせる
DNS lookupを自前でする箇所
  • gethostbyname()を使わずに、nginxのソースコード内でDNS queryを組み立ててUDP(or TCP)で指定したDNS serverへ送る
  • DNSへ送るデータのフォーマットはRFC1035を見てみてください
(gdb) bt
#0  ngx_resolve_name (ctx=0xc72570) at src/core/ngx_resolver.c:412
#1  0x00000000004573bc in ngx_http_upstream_init_request (r=r@entry=0xc78730) at src/http/ngx_http_upstream.c:750
#2  0x0000000000457d02 in ngx_http_upstream_init (r=r@entry=0xc78730) at src/http/ngx_http_upstream.c:532
#3  0x000000000044af39 in ngx_http_read_client_request_body (r=r@entry=0xc78730,
    post_handler=0x457c1f <ngx_http_upstream_init>) at src/http/ngx_http_request_body.c:84
#4  0x0000000000478054 in ngx_http_proxy_handler (r=0xc78730) at src/http/modules/ngx_http_proxy_module.c:929
#5  0x000000000043e22c in ngx_http_core_content_phase (r=0xc78730, ph=<optimized out>)
    at src/http/ngx_http_core_module.c:1386
#6  0x0000000000438f33 in ngx_http_core_run_phases (r=r@entry=0xc78730) at src/http/ngx_http_core_module.c:860
#7  0x0000000000439042 in ngx_http_handler (r=r@entry=0xc78730) at src/http/ngx_http_core_module.c:843
#8  0x0000000000441540 in ngx_http_process_request (r=r@entry=0xc78730) at src/http/ngx_http_request.c:1921
#9  0x00000000004441f2 in ngx_http_process_request_headers (rev=rev@entry=0x7fa63bdd20d0)
    at src/http/ngx_http_request.c:1348
#10 0x0000000000444507 in ngx_http_process_request_line (rev=rev@entry=0x7fa63bdd20d0)
    at src/http/ngx_http_request.c:1028
#11 0x0000000000444f1c in ngx_http_wait_request_handler (rev=0x7fa63bdd20d0) at src/http/ngx_http_request.c:503
#12 0x0000000000435b66 in ngx_epoll_process_events (cycle=0xc72f10, timer=<optimized out>, flags=<optimized out>)
    at src/event/modules/ngx_epoll_module.c:902
#13 0x000000000042bc3a in ngx_process_events_and_timers (cycle=cycle@entry=0xc72f10) at src/event/ngx_event.c:242
#14 0x0000000000433630 in ngx_worker_process_cycle (cycle=0xc72f10, data=<optimized out>)
    at src/os/unix/ngx_process_cycle.c:749
#15 0x0000000000431f92 in ngx_spawn_process (cycle=cycle@entry=0xc72f10,
    proc=proc@entry=0x43359d <ngx_worker_process_cycle>, data=data@entry=0x0,
    name=name@entry=0x48b72f "worker process", respawn=respawn@entry=-3) at src/os/unix/ngx_process.c:198
#16 0x0000000000433795 in ngx_start_worker_processes (cycle=cycle@entry=0xc72f10, n=1, type=type@entry=-3)
    at src/os/unix/ngx_process_cycle.c:358
#17 0x0000000000434226 in ngx_master_process_cycle (cycle=cycle@entry=0xc72f10) at src/os/unix/ngx_process_cycle.c:130
#18 0x000000000040c854 in main (argc=<optimized out>, argv=<optimized out>) at src/core/nginx.c:375
upstreamにconnect(2)するところ
(gdb) bt
#0  ngx_event_connect_peer (pc=pc@entry=0xc79720) at src/event/ngx_event_connect.c:172
#1  0x0000000000456265 in ngx_http_upstream_connect (r=r@entry=0xc78730, u=u@entry=0xc79710)
    at src/http/ngx_http_upstream.c:1485
#2  0x000000000045778d in ngx_http_upstream_resolve_handler (ctx=0xc72570) at src/http/ngx_http_upstream.c:1210
#3  0x000000000042683a in ngx_resolver_process_a (ans=<optimized out>, trunc=<optimized out>, nan=<optimized out>,
    qtype=<optimized out>, code=<optimized out>, ident=<optimized out>, n=<optimized out>, buf=0x7fff6eabf670 "",
    r=0xc8b3a0) at src/core/ngx_resolver.c:2440
#4  ngx_resolver_process_response (r=0xc8b3a0, buf=buf@entry=0x7fff6eabf750 "}\223\201\200", n=<optimized out>,
    tcp=tcp@entry=0) at src/core/ngx_resolver.c:1844
#5  0x0000000000427d68 in ngx_resolver_udp_read (rev=0x7fa63bdd2130) at src/core/ngx_resolver.c:1585
#6  0x0000000000435b66 in ngx_epoll_process_events (cycle=0xc72f10, timer=<optimized out>, flags=<optimized out>)
    at src/event/modules/ngx_epoll_module.c:902
#7  0x000000000042bc3a in ngx_process_events_and_timers (cycle=cycle@entry=0xc72f10) at src/event/ngx_event.c:242
#8  0x0000000000433630 in ngx_worker_process_cycle (cycle=0xc72f10, data=<optimized out>)
    at src/os/unix/ngx_process_cycle.c:749
#9  0x0000000000431f92 in ngx_spawn_process (cycle=cycle@entry=0xc72f10,
    proc=proc@entry=0x43359d <ngx_worker_process_cycle>, data=data@entry=0x0,
    name=name@entry=0x48b72f "worker process", respawn=respawn@entry=-3) at src/os/unix/ngx_process.c:198
#10 0x0000000000433795 in ngx_start_worker_processes (cycle=cycle@entry=0xc72f10, n=1, type=type@entry=-3)
    at src/os/unix/ngx_process_cycle.c:358
#11 0x0000000000434226 in ngx_master_process_cycle (cycle=cycle@entry=0xc72f10) at src/os/unix/ngx_process_cycle.c:130
#12 0x000000000040c854 in main (argc=<optimized out>, argv=<optimized out>) at src/core/nginx.c:375

なので、当時の回避策として以下のような設定をしました。

events {
  worker_connections  4096;
}

http {
  server {
    listen 8800;
    location / {
      resolver xx.xx.xx.xx valid=30s;
      resolver_timeout 3s;
      set $server "www.freee.co.jp"; #これは適当に
      proxy_pass http://$server;
    }
  }
}

unicorn

unicornはRubyで書かれたRackアプリケーションサーバーです。freeeで使っています。unicornは以下の特徴を持っています。

  • multi processでpre fork型
  • hot restartができる

このhot restartは実際にどういう挙動で、本番に入れる際にどういうリスクがありそうか調べることにしました。

debug準備

ダミーアプリの準備

unicornを動かすためにrailsアプリを生成します。

bundle exec rails new . -B -d mysql --skip-turbolinks --skip-test

Gemfileに以下の行を追加してbundle installします。

gem 'pry'
gem 'pry-remote'
gem 'pry-byebug'
gem 'unicorn'
config/unicorn.rb

こんな感じのを用意します。

worker_processes Integer(ENV["WEB_CONCURRENCY"] || 3)
timeout 15
preload_app true

remote_pryを仕込む

bundle installしてインストールしたunicornのソースコードを直接編集します。例えばSIGUSR2の挙動を調べたい場合はhttp.rbの以下のあたりのコードを追加します。

@@ -305,6 +305,8 @@
         logger.info "master done reopening logs"
         soft_kill_each_worker(:USR1)
       when :USR2 # exec binary, stay alive in case something went wrong
+        require 'pry-remote'
+        binding.remote_pry
         reexec
       when :WINCH
         if $stdin.tty?

修正したらunicornを立ち上げます。

% bundle exec unicorn_rails -c config/unicorn.rb -E development

リモートデバッグする

ps auwwfxで親プロセスのPIDを探し、 kill -USR2 pid でシグナルを送ります。そうするとunicorn側で以下のようなログが出ます。

[pry-remote] Waiting for client on druby://127.0.0.1:9876

でたら、remote debugの準備で以下のコマンドを叩きます。

 % bundle exec pry-remote

そうするとunicornを起動したコンソールがdebug可能状態になります。

[pry-remote] Client received, starting remote session
[pry-remote] Remote session terminated
[pry-remote] Ensure stop service

From: /home/y-asaba/dev/testapp/vendor/bundle/ruby/2.4.0/gems/pry-remote-0.1.8/lib/pry-remote.rb @ line 321 Object#remote_pry:

    319: def remote_pry(host = PryRemote::DefaultHost, port = PryRemote::DefaultPort, options = {})
    320:   PryRemote::Server.new(self, host, port, options).run
 => 321: end

[1] pry(#<Binding>)>

あとはお好きにどうぞ。

Redis

O(n)の処理を呼んでしまったためにパフォーマンスが劣化した障害がありました。振り返り後に社内で勉強会を開催しました。Cで書かれておりだいたいnginxと同じような感じで読みすすめることができます。細かい手順は以下のスライドに書いてあるのでそちらをご覧ください。

speakerdeck.com

環境作るのが面倒な場合はDockerfileも用意してありますのでご自由にお使いください。

github.com

MySQL

freeeではMySQLを使っています。instant add columnのニュースが来たときは「これは使えれば最高だが本当に大丈夫?」と思い、2018年のadvent calendarで書きました。(裏advent calendarなので公式blogではないです)

y-asaba.hatenablog.com

MySQLはこのなかで一番巨大なので、ソースコードを見る前にRDBMSのなんとなくの構造を先に理解しておくと捗るかと思います。コードを見つつ以下の資料を参考にしてみてください。

おわりに

デバッガを使うことで動かしながらコードを読む方法をいくつか紹介しました。大抵の挙動はドキュメントに書かれていることが多いですが、細かいところはコード見ないとようわからんというケースも一方では僅かではありますがありますので、今回紹介した手法を用いてぜひミドルウェアのソースコードリーディングを楽しんでみてください!不具合を見つけてPull Requestも送ってあげれば喜ばれると思います。

次回は会計freeeのフロントエンドからバックエンドまで開発しまくっているkemuridama氏です。お楽しみに!

Amazon Elastisearch Serviceで作ったSIEMにDeepSecurityのログを統合する

この記事はfreee Developers Advent Calendar 2020 20日目の記事です。

freee PSIRT専属エンジニアのEiji Sugiuraです。

クリスマスまで1週間を切りましたね。
この時期に思い出すのは、まだ子供達が小さかった頃のクリスマスです。

その年の12/24 21時すぎ、子供達が寝静まったあと、準備をはじめました。
ラッピングの材料を広げ、Amazonで調達しておいたプレゼントの中身が入った箱を開けて、さて包もうとしたときのことです。

ん?

息子に贈るはずだったNINTENDO DSのソフトにしては、固いパッケージ、
CDのパッケージのような...
いや、実際のところ自分で頼んだCDだったわけですが...。プレゼントが荷物として届いたことを気づかせないため、無造作に段ボール箱を積み上げた中に箱も開けずに隠していたことが仇となりました。

Amazonのアカウント情報には、1週間以上前に欠品のためにキャンセルのお知らせが来てました。

教訓としては、荷物は届いたら中身を確認しよう、Amazonだったらアカウント情報の配送記録見ようね、です。

ということで、ログは保存したら中身を精査しよう、AmazonだったらElasticsearch serviceでSIEMを作ってみようね、という話をします。

SOCって大変

freeeでは、SOC*1を自分たちで運用し、24hours 7days休むことなく以下を実施しています。

  1. WAF*2やIPS*3、access logといったsecurity sensorのログから、攻撃を検知する
  2. 対応が必要なものがないか分析し、優先度をつける
  3. 優先度順に対応を実施する

freeeでは、社内のcyber securityへの対処を行うCSIRT*4と、service siteのcyber securityへの対処を行うPSIRT*5が組織されており、SOC業務を専任で担当しています。 securityを担保する体制としては、かなり恵まれています。しかし、それでも、毎日すべてのログを精査して、優先度をつけて全て対応なんてことをやっていると、すぐに時間が溶けてしまいます。

ある日のSOC業務

12月に入ったある日、WAFのログを見ていると、以下のようなアクセスを見つけました。

f:id:eiji-sugiura:20201219184509p:plain
あるIPから、WAF ip blacklistによってblockされたアクセス

これが、適当なpathにGET requestを飛ばしている/_vti_bin/owssvr.dllだけならば気にしません。悪意あるclientをweb serverに、たどり着く前に止めてくれてよかった!と思うだけです。
妙なのは、通常のアクセスである/dealsが直前に行われていることです。

もしかして?と思い、web serverのaccess logを見てみたところ、少し時間帯はずれていますが、通常の利用が行われていました。

f:id:eiji-sugiura:20201219185407p:plain
あるIPから、web serverへのアクセス

これは良くありません。お客様のサービス利用をip blacklistが止めてしまっていることに、なりますからね。

念のため、同じ時間帯のDeepSecurityのログを見てみたところ、

f:id:eiji-sugiura:20201219185654p:plain
あるIPから、DeepSecurityによってresetされたアクセス

WAFのip blacklistでblockされるよりも前に、同様のアクセスをDeepSecurityがresetしていることも確認できました。

さて、ここまでで分かったことは、以下のような事象が起きていることです。

  1. あるIPから、/_vti_bin/owssvr.dllへのアクセスをDeepSecurityがreset
  2. 同じIPから、同じ時刻帯に、通常のサービス利用を行われている
  3. 同じIPからのアクセスが、WAFのip blacklistによってblock

これらを割り出すには、バラバラに記録された3つのログを行き来しながら、grepをかけて状況をあぶりだす必要があります。 作業に熟練したとしても、結構な時間がかかってしまいます。

解決する方法の一つは、SIEM*6を導入することです。 ログを一つの入れ物に入れておき、attributeとvalueを揃えておく*7ことで、全てのログに横串を通して検索することが可能になります。
ということで、今回、SIEMとして利用するのは、SIEM on Amazon Elasticsearch Serviceです。

github.com

元々、AWS WAF、CloudTrail、GuardDuty、VPC flow logなど、AWSのmanaged serviceには対応していますが、今回はDeepSecurityのログをここに統合していきます。

以下では、こちらの手順に従って、SIEM on Amazon Elasticsearch serviceを稼働していることを前提とします。

es-loaderでDeepSecurityのログを取り込む

簡単に仕組みを以下に図示しておきます。

es-loaderでDeepSecurity IPSのログをElasticsearchにloadする
Elasticsearchで作ったSIEMにDeepSecurityのログを取り込む

以下の処理を順に行って、DeepSecurityのログをSIEMに取り込んでいきます。

  1. ec2 instance上で動作しているDeepSecurity が、syslogでlocalhostの/var/log/dsa.logにログを出力
  2. td-agent/fluentdで/var/log/dsa.log → s3 bucketに転送
  3. es-loaderでs3を読み取って、Elasticsearchにloadする

以降では、これらを順に設定していきます。

DeepSecurity SaaSでのlocalhostへのsyslog転送設定

まず、DeepSecurity SaaSの管理画面にloginし、Adminitration -> System Settings -> Event Forwardingで、localhostにsyslogを転送する設定を行なっておきます。

DeepSecurityでのsyslog profile = localhost syslogを指定したもの
DeepSecurityでのsyslog転送設定

Local Syslog profileは、以下のように localhost=127.0.0.1の514/udpに送信する設定で作成したものです。 このとき、formatにはCommonEventFormat、Agent should forward logsには Directory to the Syslog Serverを指定し、ログをDeepSecurity SaaSを介さずに直接送信する設定を行っておきます。

127.0.0.1 514/udpに直接ログを送信する設定
"Local Syslog" profileの作成

詳しくは、公式のmanualを参照してください。

cloudone.trendmicro.com

rsyslogで/var/log/dsa.logにDeepSecurityのログを保存

次に、rsyslogを用いて、CEF:やLEEF:を含むログをDeepSecurityのログとして、/var/log/dsa.logに保存します。

/etc/rsyslog.d/ds_agent.conf

$FileCreateMode 0644

:syslogtag, contains, "CEF:" /var/log/dsa.log
& stop

:syslogtag, contains, "LEEF:" /var/log/dsa.log
& stop

この設定によって、/var/log/dsa.logに、以下のようなログが記載されていきます。

Dec  3 15:08:33 ip-10-0-XXX-XXX CEF: 0|Trend Micro|Deep Security Agent|20.0.0.1194|1002751|Disallowed Resources|10|cn1=2387187 cn1Label=Host ID dvc=10.0.32.44 TrendMicroDsTenant=production freee TrendMicroDsTenantId=XXXXXX dmac=06:9C:B6:19:29:18 smac=06:06:2A:80:00:05 TrendMicroDsFrameType=IP src=10.0.XXX.XXX dst=10.0.XXX.XXX in=1584 cs3=DF 0 cs3Label=Fragmentation Bits proto=TCP spt=24920 dpt=8080 cs2=0x00 ACK PSH cs2Label=TCP Flags cnt=1 act=Reset cn3=23 cn3Label=DPI Packet Position cs5=6813 cs5Label=DPI Stream Position cs1=2-Disallowed cs1Label=DPI Note cs6=8 cs6Label=DPI Flags TrendMicroDsPacketData=R0VUIC9...

td-agent/fluendからS3へのlog転送

/var/log/dsa.logをtd-agentでtailして、S3にJSON形式でログを転送します。

/etc/td-agent/conf.d/ds_agent.conf

<source>
  @type    tail
  format   none
  path     /var/log/dsa.log
  pos_file /var/log/td-agent/.dsa.pos
  tag      ds_agent.*
</source>

<filter ds_agent.**>
  @type record_transformer
  @id ds_agent_record_modifier
  enable_ruby true
  <record>
    hostname "#{Socket.gethostname}"
    timestamp ${time.strftime('%FT%T%:z')}
    tag ${tag}
  </record>
</filter>

<match ds_agent.**>
  @type s3
  @id ds_agent_s3
  s3_bucket             ${BUCKET_NAME}
  s3_region             ${REGION}
  path                  ds_agent/
  s3_object_key_format  %{path}%{time_slice}_${hostname}_%{index}.%{file_extension}
  time_slice_format     %Y/%m/%d/%H
  timezone              Asia/Tokyo
  output_time           false
  output_tag            false
  <buffer tag,time>
    @type               file
    path                /var/log/td-agent/buffer/s3_ds_agent
    flush_mode          interval
    flush_interval      1m
    flush_at_shutdown   true
  </buffer>
</match>

ec2 instanceからのs3への書き込みは、instance profileで許可をしてあげると良いです。

aws.amazon.com

ここまでの設定で、S3 bucketのds_agent/YYYY/MM/DD/HH_hostname_NN.gzに以下の形式でログが保存されていきます。

{
    "message":"Oct 28 14:46:28 ip-10-0-XX-XX CEF: 0|Trend Micro|Deep Security Agent|20.0.0.1194|1000552|Generic Cross Site Scripting(XSS) Prevention|10|cn1=2312751 cn1Label=Host ID dvc=10.0.XX.XX TrendMicroDsTenant=tenant name TrendMicroDsTenantId=XXXXXX dmac=0E:37:8C:B4:47:10 smac=0E:28:7B:CF:58:50 TrendMicroDsFrameType=IP src=10.0.XX.XX dst=10.0.YY.YY in=5770 cs3=DF 0 cs3Label=Fragmentation Bits proto=TCP spt=54056 dpt=80 cs2=0x00 ACK PSH cs2Label=TCP Flags cnt=1 act=IDS:Log cn3=1472 cn3Label=DPI Packet Position cs5=60218 cs5Label=DPI Stream Position cs1=XSS Attack cs1Label=DPI Note cs6=8 cs6Label=DPI Flags TrendMicroDsPacketData=IDwh...YXku\\=\\=",
    "hostname":"ip-10-0-XX-XX",
    "timestamp":"2020-10-28T14:46:28+09:00"
}

{
    "message":"Nov 28 10:33:58 ip-10-0-XX-XX CEF: 0|Trend Micro|Deep Security Agent|20.0.0.1194|3002831|Unix - Syslog|6|cn1=2313513 cn1Label=Host ID dvc=10.0.XX.XX TrendMicroDsTenant=tenant name TrendMicroDsTenantId=XXXXXX cs1=Non standard syslog message (size too large) cs1Label=LI Description fname=/var/log/messages shost=ip-10-0-XX-XX msg=Nov 28 10:33:57 ip-10-0-XX-XX error: message:Could not push log to Elasticsearch: {\"took\"\\=>329, \"errors\"\\=>true, ...",
    "hostname":"ip-10-0-XX-XX",
    "timestamp":"2020-11-28T10:33:58+09:00"
}

elasticsearchでのlog-deepsecurity templateの定義

ElasticserachがJSON形式で送られてくるログを解釈する際のmappingを定義しておきます。今回は元々log-*のtemplateで共通のものは定義されているため、deepsecurityで特有のものだけを定義しておけば良いです。

PUT _template/log-deepsecurity
{
  "log-deepsecurity" : {
    "index_patterns" : [
      "log-deepsecurity*"
    ],
    "mappings" : {
      "properties" : {
        "cloud.account" : {
          "type" : "object"
        },
        "event.severity" : {
          "type" : "integer"
        },
        "event.original" : {
          "type" : "text"
        },
        "event.count" : {
          "type" : "integer"
        },
        "timestamp" : {
          "type" : "date"
        }
      }
    }
  }
}

es_loader側の設定

es_loader lambda functionに、DeepSecurityのCEF形式のログを解釈させるため、user.iniに以下を定義します。

[deepsecurity]
index = log-deepsecurity
s3_key = ds_agent
format = json
script_ecs = event.action destination.ip destination.port destination.mac destination.bytes source.ip source.port source.mac source.bytes network.transport event.action server.name file.path event.count rule.category host.id event.original
event.action = act
destination.ip = dst
destination.port = dpt
destination.mac = dmac
destination.bytes = out
source.ip = src
source.port = spt
source.mac = smac
source.bytes = in
network.transport = proto
server.name = hostname
file.path = fname
event.count = cnt
rule.category = cs1
host.id = cn1
event.original = msg

次に、es_loader lambda functionに、deepsecurityのlogを解釈する siem/sf_deepsecurity.py が存在していることを確認してください。 ここまでの設定で、Elasticsearchにログがloadされていくはずです。

なお、ここまでのes_loaderの機能追加は、以下のPRでdevelop branchに既にmergeされています。

github.com

SIEMを用いたSOC業務

Amazon Elasticsearch serviceを用いて構築したSIEMで、先ほど解析した事象を見てみましょう。

ログ解析は1画面で!

ElasticsearchのDiscoveryで同じIP、同じ時間帯のログを表示させてみると、以下の通りです。

f:id:eiji-sugiura:20201219210343p:plain
SIEMによる解析その1
f:id:eiji-sugiura:20201219211146p:plain
SIEMによる解析 その2

これらから、以下のことが言えます。

  1. AWS WAF fulllogから、通常のアクセスが行われている
  2. AWS WAFは、/_vti_bin/owssvr.dllをALLOWし、通している
  3. DeepSecurityで、/_vti_bin/owssvr.dllに対するアクセスを検知しResetしている
  4. 直後の/MSOffice/cltreq.aspについては、何も検知されずALLOWしている
  5. その後、25分ほどアクセスが行われていない = ここでip blacklistへの登録が行われたと推測
  6. ip blacklistによって、あるIPからのアクセスを全てBLOKしている

ipや時間帯のような簡単な絞り込みで、AWS WAF fulllogやDeepSecurityのtimelineが1画面で表示されるため、解析作業が捗るようになりました。

その後の対応

実は、今回DeepSecurityで検知された以下のアクセスは、Microsoft Office 2000/XpのWebディスカッション機能を有効化していると、発生します。

GET /_vti_bin/owssvr.dll?UL=...

残念ながら、Webディスカッション機能が用いるURIについてのMicrosoft社の一次情報は、既に削除されているようです。

お客様に以下を連絡し、

  • お客様がオフィスで利用されているWindows端末から、上記のアクセスが生じていること
  • おそらく、上記のアクセスを他のsiteにも実施したことが原因で、オフィスのipがblacklistに登録されてしまい、結果としてfreeeへのアクセスが行えなくなっていること

PC環境を更新していただくことで、対応を終了しました。

まとめ

Amazon Elasticsearch serviceを用いて構築したSIEMにDeepSecurityのログを統合することで、毎日のSOC業務が、メチャメチャはかどるようになりました。

SIEMは商用製品も多数ありますが、freeeのサービス規模だと、年間数千万円を超えるコストがかかってしまいます。AWSのmanaged serviceを利用して構築した今回のSIEMは、かなりの節約になりました。オススメです。

おわりに

SIEMのdashboardみたいなキレイな画面は目を引くのですが、実際に業務を回す人にとっては、ログに横串を通して解析できることの方が意味があるんですよね。

f:id:eiji-sugiura:20201219221854p:plain
DeepSecurity Summary

あ、息子のクリスマスプレゼントは、夜中に車で駆けずり回ってNINTENDO 3DSを調達しました。

明日は、freeeのインフラ部隊を率いる浅羽さんです!

freeeでは、securityを担保する仕組みを一緒に作り上げていく仲間を求めています。

www.wantedly.com

*1:Security operation Center

*2:Web Application Firewall = HTTP request filterです。正規表現やip blacklist、ratelimitを用いることができます。

*3:Intrusion Prevention System = packet capture + stream再構築 + signature match

*4:Computer Security Incident Response Team

*5:Product Security Incident Response Team

*6:Security Information and Event Management = セキュリティに関係するログを集めて解析をする仕組み

*7:今回はElastic Common Schemaに統一します。

ECS Field Reference | Elastic Common Schema (ECS) Reference [1.7] | Elastic