ShinobiLayer: SoftLayerで仮想サーバーのプロビジョニング時の動作をハックする

<a href="http://softlayer-bluemix-summit.jp" target="_blank"><img src="http://softlayer-bluemix-summit.jp/wp-content/uploads/2015/07/full_banner_468x60.jpg" alt="SoftLayer Bluemix summit2015" /></a>
私も本Summitにて講演予定です。当日直接お声がけいただいて質問いただくのも大歓迎です！たくさんの方のご参加をお待ちしております！！
また、8月7日 〜 8月31日の間に[blogコンテスト](http://softlayer.connpass.com/event/18370/)もやっていますので、ぜひ皆様もblogを書いて豪華商品を狙ってみてください！

#はじめに
SoftLayerのImage Template作成時およびImage Templateからのプロビジョニング時にはどういう操作がされているのが気になっていましたが・・・当然こんな質問をSoftLayerのサポートに聞いても答えてくれる気がしません。
そこで、今回は[snoopy](https://github.com/a2o/snoopy)という**コマンド実行結果を全部ログに記録してくれるツール**を使ってハックしてみようと試みました。もし試してみたい方は新規の壊れて良いサーバーでお試しすることをオススメします。

#snoopyの導入と動作検証
新規に仮想サーバー（CentOS6)を注文して、[snoopy](https://github.com/a2o/snoopy)を導入します。epelに登録されているsnoopyはv1.7と古く、設定変更時に再コンパイルが必要になるらしいので、今回は最新版を利用することにします。インストール手順はgithubで紹介されているとおり、以下の手順で簡単に導入可能です。
なお、socatというpackageが事前に導入されている必要があるので、CentOS6ではepelを構成しておいた方が良いです。（epelが構成されていれば、インストール時に自動的にダウンロードしてくれます）

```
[OSの最新化/タイムゾーンの変更/epelの設定]
# yum install -y update
# cp -p /usr/share/zoneinfo/Asia/Tokyo /etc/localtime
# yum install -y epel-release
# reboot

[snoopyの導入]
# rm -f snoopy-install.sh &&
wget -q -O snoopy-install.sh https://github.com/a2o/snoopy/raw/install/doc/install/bin/snoopy-install.sh &&
chmod 755 snoopy-install.sh &&
./snoopy-install.sh stable

(途中略）

Complete!
SNOOPY INSTALL: Starting installation, log file name: /root/snoopy-install.log
SNOOPY INSTALL: Installation mode: package-latest-stable
SNOOPY INSTALL: Getting latest Snoopy version: snoopy-2.4.3.tar.gz
SNOOPY INSTALL: Downloading http://source.a2o.si/download/snoopy/snoopy-2.4.3.tar.gz... done.
SNOOPY INSTALL: Unpacking snoopy-2.4.3.tar.gz... done.
SNOOPY INSTALL: Configuring... done.
SNOOPY INSTALL: Building... done.
SNOOPY INSTALL: Installing... done.
SNOOPY INSTALL: Enabling... done.

SNOOPY LOGGER is now installed and enabled.

TIP #1: If Snoopy is to be enabled for all processes, you need
        to restart your system, or at least all services on it.

TIP #2: If you ever need to disable Snoopy, you should use provided
        'snoopy-disable' script. Use 'snoopy-enable' to reenable it.

TIP #3: Snoopy output can usually be found somewhere in /var/log/*
        Check your syslog configuration for details.

TIP #4: Configuration file location: /etc/snoopy.ini
        See included comments for additional configuration options.

Snoopy wishes you a happy logging experience:)

```

導入後はOSを再起動します。

# snoopyの設定変更と動作確認

デフォルト構成ののままだとCentOSでは/var/log/secureに、Ubuntuでは/var/log/auth.logなどに出力されてしまい、ログが読みにくくなってしまいます。そこで出力先を/var/log/snoopy.logに変更します。ちなみにこの設定変更は即時に反映されるようですが、既存の別セッションは影響を受けなさそうなので、再度ログインしなおすか、いっそのこと再起動した方が良さそうです。設定変更は、/etc/snoopy.iniを構成することで可能になります。

```text:/etc/snoopy.ini

（途中略）
message_format = "%{datetime} [uid:%{uid} sid:%{sid} tty:%{tty} cwd:%{cwd} filename:%{filename}]: %{cmdline}"

（途中略）

output = file:/var/log/snoopy.log

（途中略）
```

`tail -f /var/log/snoopy.log`を実行しながら別コンソールでコマンドを叩くと、以下のように実行コマンドが確認できます。ちなみにエラーコマンドはログに出力されません。**これは便利！監査目的にも使えそうですね！**

```
# tail -f /var/log/snoopy.log|grep -v none
2015-08-13T15:24:46+0900 [uid:0 sid:1381 tty:/dev/pts/0 cwd:/root filename:/usr/bin/tail]: tail -f /var/log/snoopy.log
2015-08-13T15:24:53+0900 [uid:0 sid:1450 tty:/dev/pts/1 cwd:/root filename:/bin/ls]: ls --color=auto
2015-08-13T15:24:57+0900 [uid:0 sid:1450 tty:/dev/pts/1 cwd:/root filename:/bin/ls]: ls --color=auto -l
2015-08-13T15:24:58+0900 [uid:0 sid:1450 tty:/dev/pts/1 cwd:/root filename:/bin/df]: df
2015-08-13T15:25:05+0900 [uid:0 sid:1450 tty:/dev/pts/1 cwd:/root filename:/sbin/chkconfig]: chkconfig --list
2015-08-13T15:25:09+0900 [uid:0 sid:1450 tty:/dev/pts/1 cwd:/root filename:/bin/vi]: vi /etc/inittab
```

# イメージテンプレートを使ったプロビジョニング時のログを確認してみる
この状態でイメージテンプレートを取得し、取得したイメージからプロビジョニングをしてみます。イメージテンプレートを取得する前には`rm -f /var/log/snoopy.log`でログをクリーニングしておいた方が良いでしょう。
プロビジョニングが完了してからsnoopy.logを確認してみると1000行ぐらいログが出てくるので、ある程度当たりを付けて読んでいく必要があります。さすがに全行書くのは辛いものがありますし、詳細をWebで公開するのはどうかと思うので、以下は簡単にポイントと流れの紹介に留めたいと思います。

###1. シェルが実行されている？
```text:snoopy.log
# grep "\.sh" snoopy.log
2015-08-13T20:54:17+0900 [uid:0 sid:617 tty:/dev/console cwd:/ filename:/bin/plymouth]: /bin/plymouth --update=install.sh
2015-08-13T20:54:17+0900 [uid:0 sid:617 tty:/dev/console cwd:/ filename:/sbin/initctl]: initctl emit --quiet starting JOB=install.sh
2015-08-13T20:54:17+0900 [uid:0 sid:617 tty:/dev/console cwd:/ filename:/etc/rc3.d/S20install.sh]: /etc/rc3.d/S20install.sh start
2015-08-13T20:54:27+0900 [uid:0 sid:617 tty:/dev/console cwd:/ filename:/bin/rm]: rm -f /root/base_functions.sh
2015-08-13T20:54:57+0900 [uid:0 sid:617 tty:/dev/console cwd:/ filename:/bin/rm]: rm /etc/rc2.d/S20install.sh
2015-08-13T20:54:57+0900 [uid:0 sid:617 tty:/dev/console cwd:/ filename:/bin/rm]: rm /etc/rc3.d/S20install.sh
2015-08-13T20:54:57+0900 [uid:0 sid:617 tty:/dev/console cwd:/ filename:/bin/rm]: rm /etc/rc4.d/S20install.sh
2015-08-13T20:54:57+0900 [uid:0 sid:617 tty:/dev/console cwd:/ filename:/bin/rm]: rm /etc/rc5.d/S20install.sh
2015-08-13T20:54:57+0900 [uid:0 sid:617 tty:/dev/console cwd:/ filename:/bin/rm]: rm /root/install.sh
2015-08-13T20:54:57+0900 [uid:0 sid:617 tty:/dev/console cwd:/ filename:/sbin/initctl]: initctl emit --quiet started JOB=install.sh
```

この結果によると、/etc/rc3.d/S20install.shというものを実行して、その後このシェルが削除されていることが分かります。/root/install.shっていうものもありますね。
プロビジョニング時には、こうしたスクリプトファイルや構成ファイルなどをOS起動前に所定の場所に配置して、プロビジョニング後の初回OS起動時に呼び出せるように呼び出せるようにしているのではないかと想像します。

###2. install.shとS20install.shの関係は？
さすがにこれは上記のログだけからは分かりませんでした。ログからあたりを付けて、プロビジョニング時にS20install.shとかinstall.shを退避させるスクリプトを仕込んでみました。/etc/rc3.d/S19mycustomなどを配置するというのが一番綺麗なやり方だとは思ったのですが、install.sh実行時のログ（これもinstall.sh実行後に削除されてしまう）が欲しかったので、ログが消える直前でコピーしたかったです。今回は一連のファイルを削除する前にsshdを再起動していることに注目し、sshd再起動時に以下のスクリプトが流れるように設定してみました。

```text:/etc/init.d/sshd
restart() {
        stop
        mkdir -p /work/`date +%Y%m%d%H%M` && cp -pr /root/ /work/`date +%Y%m%d%H%M`/
        mkdir -p /work/`date +%Y%m%d%H%M` && cp -pr /etc/rc3.d/ /work/`date +%Y%m%d%H%M`/
        mkdir -p /work/`date +%Y%m%d%H%M` && cp -pr /etc/init.d/ /work/`date +%Y%m%d%H%M`/
        start
}
```

これで、再度イメージ取得＋イメージからのプロビジョニングを実行してみます。このコピーした結果のディレクトリを確認してみると、以下のように/etc/rc3.d/S20install.shの実体は/root/install.shであることが分かりました。

```text:S20install.sh
# ls -l /work/201508132054/rc3.d/S20install.sh
lrwxrwxrwx 1 root root 16 Aug 13 20:53 /work/201508132054/rc3.d/S20install.sh -> /root/install.sh
```

###3. /root/install.shはどんな内容なのか？
これもスクリプトの中身をそのまま晒すとなんなので、処理を羅列してみると大まかには以下のような流れになっているようです。

1. /root/provisioningConfiguration.cfg（OSのパスワード情報やネットワーク情報などが記録されている）を環境変数として読み込む。
2. /root/base_functions.sh（関数が定義されている）を読み込む。
3. rootパスワードを設定する
4. tune2fsを使ってfsckのカウンターをリセット
5. wgetを10.3.xx.xxのサーバーに試行
6. /etc/ssh/ssh_host_*を削除後に再生性（sshdを再起動）
7. 再度10.3.xx.xxのサーバーにアクセスしてログを記録
8. トランザクションのステータスを"INSTALL_COMPLETE"に更新
9. 一連のスクリプトや構成ファイルを削除

この結果から判断すると、FirewallでガチガチにOutBoundまでブロックするのは危険ですね。過去にVyattaでOutbound通信を過剰にブロックしていた際にプロビジョニングが止まってしまったことがあったのはこれのせいだったのかなぁと思ったりしました。
また、SoftLayerではpublic NWに接続しないprivate onlyのサーバーも注文できますが、そのような環境でもpingのテストとしてns1.softlayer.comを使うのは個人的にはいかがなものかと思いました（private onlyのサーバーではpingに失敗します。しかし、ping成功の可否によって何かするわけではなさそう。それならばそんなことしなきゃいいのに・・・）。
IPアドレスの変更とかも/root/install.shで実行しているかなと当初は思っていたのですが、どうもやっていないようです。ログを見たところ、/etc/rc3.d/S10networkの箇所で、割り当て予定のIPが直接ログに出力されていたので、/root/install.shなどの配置のタイミングでifcfg-eth0やifcfg-eth1も置き換ているのかもしれないですね。