chef + test-kitchen の複雑系コンビを追い詰めていくまでに使った手管を残しておきます。

chef-client が実行したコマンドを確認する手順

`kitchen create` でインスタンスを作成する

インスタンスが作成されます（kitchen-vagrant なら、Vagrant インスタンス）:

$ bundle exec kitchen create

chef-client 関連のコードを書き換える

chef-client が最終的に実行しているコマンドを捕らえるために、次のように実行したコマンドを外部ファイルへ書き出すように書き換えます:

$ bundle exec kitchen login

$ whoami
vagrant

$ sudoedit /opt/chef/embedded/lib/ruby/gems/2.3.0/gems/mixlib-shellout-2.2.7/lib/mixlib/shellout.rb

--- /dev/fd/11  2016-09-16 22:21:40.000000000 +0900
+++ /dev/fd/12  2016-09-16 22:21:40.000000000 +0900
@@ -252,10 +252,6 @@
     # * CommandTimeout  when the command does not complete
     #   within +timeout+ seconds (default: 600s)
     def run_command
+      open("/tmp/ran_commands.log", "a") { |f|
+        log_message = (log_tag.nil? ? "" : "#@log_tag ") << "sh(#@command)"
+        f.write(log_message)
+      }
       if logger
         log_message = (log_tag.nil? ? "" : "#@log_tag ") << "sh(#@command)"
         logger.send(log_level, log_message)

`kitchen converge` で recipe を適用する

$ bundle exec kitchen converge

結果を確認する

$ bundle exec kitchen login

$ whoami
vagrant

$ cat /tmp/ran_commands.log
sh(locale -a)
sh(df -P)
sh(df -iP)
sh(mount)
sh(lsblk -P -n -o NAME,FSTYPE)
sh(lsblk -P -n -o NAME,UUID)
...

ヨッシャ、デバッグが捗るぞい

解説

test-kitchen (+ kitchen-vagrant)の仕組み

test-kitchen では、cookbook をいろいろな環境で試すことができます。
例えば、azure 上で試したりといった感じです:

$ bundle exec kitchen driver discover
    Gem Name                          Latest Stable Release
    jackal-kitchen-slack              0.1.2
    kitchen-all                       0.2.0
    kitchen-ansible                   0.45.4
    kitchen-ansiblepush               0.4.0
    kitchen-appbundle-updater         0.1.2
    kitchen-azure                     0.1.0
    kitchen-azurerm                   0.7.0
    ...

また、とくに指定がなければ、kitchen-vagrant による Vagrant 上でのテストになっているはずです。
これを使えばマシン1台で手軽に試せるので、kitchen-vagrant を使うことにしましょう。

さて、kitchen-vagrant は cookbook のディレクトリに .kitchen/kitchen-vagrant というディレクトリをこっそり用意して、そこに Vagrantfile を準備します:

$ cat .kitchen/kitchen-vagrant/kitchen-chef-jenkins-master-default-centos-72/Vagrantfile
Vagrant.configure("2") do |c|
  c.berkshelf.enabled = false if Vagrant.has_plugin?("vagrant-berkshelf")
  c.vm.box = "bento/centos-7.2"
  c.vm.hostname = "default-centos-72"
  c.vm.synced_folder ".", "/vagrant", disabled: true
  c.vm.provider :virtualbox do |p|
  end
end

なので、このディレクトリまで行けば、vagrant ssh で SSH ログインできます。

kitchen-vagrant 使用時の kitchen のサブコマンドの意味

kitchen create: .kitchen.yml で指定された Vagrant イメージを準備する（vagrant up 相当）
kitchen converge: .kitchen.yml で指定された run_list に従って、インスタンスに recipe を適用する（knife zero converge 相当）
kitchen verify: .kitchen.yml で指定された verifier に従って、インスタンス上でテストを実行する
kitchen destroy: Vagrant インスタンスを破棄する（vagrant destroy 相当）
kitchen login: Vagrant インスタンスへ SSH ログインする（vagrant ssh 相当）

また、kitchen test では次のように順番にコマンドを実行します（より丁寧な解説 or 公式）:

kitchen create
kitchen converge
kitchen verify
kitchen destroy

そのため、レシピを適用した状態のインスタンスに SSH ログインしたければ、kitchen create && kitchen converge した後、kitchen login すればよいのです！！！！

他にも

recipe 内なら `log`

recipe 内のコードであれば、log とか Chef::Log とかが使えます：

$ cat recipes/default.rb
...

require 'json'

log 'ndenv' do
  message JSON.generate(node['ndenv'])
  level :error
end

...

$ bundle exec kitchen converge

       ...

       Recipe: test_useradd::default
         * log[ndenv] action write[2016-09-16T11:45:05+00:00] ERROR: {"user":"ndenv","group":"ndenv","manage_home":true,"user_home":"/home/ndenv"}

       ...

実行されている様子を観察する

ログインして ps コマンドとかで監視すると、どのユーザーがどんな感じで実行しているか見えてきて便利です¹:

$ bundle exec kitchen login

$ whoami
vagrant

$ watch -n 0.5 'ps auxf --sort -pid'
Every 0.5s: ps auxf --sort -pid

USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root         1  0.0  1.6  57572  7504 ?        Ss   13:11   0:00 /usr/lib/systemd/systemd --switched-root --system --deserialize 21
root     12819  0.0  0.2 125400  1088 ?        Ss   14:01   0:00 /usr/sbin/anacron -s
root      1061  0.0  0.4  91064  2084 ?        Ss   13:11   0:00 /usr/libexec/postfix/master -w
postfix   1098  0.0  0.8  91236  3904 ?        S    13:11   0:00  \_ qmgr -l -t unix -u
postfix   1097  0.0  0.8  91168  3880 ?        S    13:11   0:00  \_ pickup -l -t unix -u
root       866  0.0  0.7  82488  3576 ?        Ss   13:11   0:00 /usr/sbin/sshd -D
root     13406  0.1  1.0 131056  4760 ?        Ss   14:17   0:00  \_ sshd: vagrant [priv]
vagrant  13409  0.0  0.4 131056  2040 ?        S    14:17   0:00  |   \_ sshd: vagrant@pts/1
vagrant  13410  0.0  0.4 115352  2036 pts/1    Ss+  14:17   0:00  |       \_ -bash
root     12856  0.0  1.0 131056  4764 ?        Ss   14:11   0:00  \_ sshd: vagrant [priv]
...

top とかでもできるかもですが、引数表示とか諸々 ps の方が慣れてる感あるのでこっちでやりました。 ↩