Linuxで、こんな状況に遭遇することが、たまにある。
「アプリが動かない。ログによると、どこかのファイルで Permission denied / Operation not permitted になっているみたい。でもどこで？」
例えば、アプリ作成者の想定外の場所でエラーが起こっていたり、プロトタイピングなどでエラー処理を手抜きしていると、ログに十分な情報がなく、そんな困った状況になりがち。
しかし、最近のLinuxでは、auditdを使って、簡単に問題ファイルを特定できる。
たまに auditd を使うので、記事にまとめてみた。
1. auditdの概要
Auditdは、Linuxカーネルとアプリケーションのやりとりを監査（audit）するOSの機能。
いわゆる「Mandatory Access Control(MAC) / 強制アクセス制御」の一種。
RHEL系ではデフォルト ON になっているので、ツールの追加インストールは不要。
開発目標の一つに監査オーバーヘッドの最小化を掲げており、性能の足を引っ張ることも、ほとんどない優れもの。
1.1. Kernel内の仕掛け
以下の図は、本家サイトにあるプレゼン資料 “Updated version of the 2007 Red Hat Summit slides” より引用した。
Kernel内の監視ポイント（Filter）
左側の App が、Linux Kernelとやりとりするとき、重要なポイントに 関門（Filter） をおいて、App の動きを監視する。
関門（Filter）は以下の５つ。
| 関門（Filter） | 役割 |
|---|---|
| User | Trusted App（後述）から監査イベントを受け取る |
| Entry | 監査準備：リソース確保、Kernel突入時刻の記録など |
| Exit | 監査ログの出力、リソース解放 |
| Task | Appの子プロセス（fork）を追跡 |
| Exclude | 対象外イベントの除去 |
また、PAM と連携して、Appの実行ユーザの変化を追跡する。
最後は、関心ある監査イベントだけ、カーネルから Audit Daemon プロセスに渡す。
1.2. 周辺ツール
再び、プレゼン資料 “Updated version of the 2007 Red Hat Summit slides” より引用。
周辺ツール
図に書かれた各コンポーネント／周辺ツールを説明する。
Auditd & Logs
図の中心にある Auditd は、Kernelから受け取った監査イベントを Logs にログ出力する。
このログの実体は、CentOS6のマシンを見ると
/var/log/audit/audit.logにある（設定ファイル /etc/audit/auditd.conf より）。Ausearch, Aureport, Aulast
Logs に蓄積された監査イベントを、検索／整形表示／サマライズするツール。
蓄積された後にバッチ的に処理するのでなく、監査イベント発生のタイミングで即アクションを起こしたいときは、Audispd を使う。Audispd から警報を鳴らす、アカウントをロックするなど、色々な外部ツールへの連携が想定されている。
Auditctl
赤い箱で書かれた Auditctl は、Kernel側の制御を行う。監査ルールの設定など。
Trusted App
Trusted Appは、Auditが動作するのに、悪意ある動作をしないと信用しているソフトウェア達で、Trusted App自身も監視イベントを発生できる。
Trusted Appが生成した監視イベントは、Kernel内のUser関門で処理され、Auditdを経由して、Logsへ格納されることになる。
Trusted Appには、PAM、Login、sshd、crond、semanage などが該当する。
2. 使い方
2.1. 監査ルールの設定
auditctlコマンドで、監査ルールの追加や削除を行う。
コマンドラインオプションの基本形は
-a (追加) または -d (削除) に続けて filter,action -S syscall -F condition -k label
-S や -F は、必要な数だけ、複数渡すことができる。
一つのルール内で、複数の
-SはOR条件、複数の-FはAND条件となる。
各項目の説明は以下。太字はデフォルト。
| 項目 | 値の範囲 | 説明 |
|---|---|---|
| filter | user,exit,task,exclude | 関門を指定 ※entryは指定不可 |
| action | always, never | 監査イベントを生成(always)するか否か(never) |
| syscall | all, 2, open 等 | システムコール名やシステムコール番号を指定 ※ allはワイルドカード |
| condition | euid=0, arch=b64 など多彩 | 監査イベントを抜き出す条件を指定 |
| label | 任意の文字列 | 監査イベントにラベルを付け、ログを後から検索できる |
filterで、user,task を使うことはあまりない。大抵 exit だけか、監査イベントの抑制のために exclude を利用する程度。
actionで、never を使うことは殆ど無い。通常は alwaysを指定する。
syscall は、ausyscall コマンドが返却するテーブルの値を利用することができる。
ausyscall コマンドはこんな感じ。詳しくは “man ausyscall” を参照。
[root@localhost ~]# ausyscall i386 open
open 5
mq_open 277
openat 295
perf_event_open 336
open_by_handle_at 342
[root@localhost ~]# ausyscall x86_64 open --exact
2
-F condition 指定
-Fオプションは、多様なフィールドを使って条件を作り、監査イベントを絞り込む。
詳細は “man 8 auditctl” の
-F の項を見てもらうとして、ここではよく使いそうなフィールドを挙げてみる。なお、右辺の即値は例。| 条件 | 意味 |
|---|---|
| a0>3 | システムコールの第一引数が 3 を超えるとき ※ 同様に a1,a2,a3 も利用可 |
| arch=b64 | 64bitのシステムコールのとき ※ 32bitはb32 |
| dir=/tmp | /tmp 配下の全ファイルを監視 |
| filetype=socket | 対象ファイルがソケットのとき |
| inode=1187942 | inode番号が1187942のとき |
| perm=rwxa | open() が Read,Write,eXecute,Attribute-change の何れかを要求するとき |
| exit=EACCES | システムコールが errno=EACCES で失敗のとき ※ 成功なら exit=0 |
| success=0 | システムコールが失敗(0)したとき ※ 成功なら success=1 |
右辺には即値しか使えないので、”-F uid=euid” みたいには書けない。
代わりに
代わりに
-C uid=euid と書く。2.2. 監視ルールの一覧
現在設定されているルールは、
-l オプションで表示できる。 auditctl -l
2.3. 監視ログの表示
監視ログは、ausearchコマンドで検索できる。
最も簡単な方法は、ルールに付けたラベル（
-kオプション）をキーワードにして、そのルールに該当したイベントだけ抜き出すこと。 ausearch -i -k label
-i オプションを渡すと、ログ中の数字を、人間にわかりやすい形式に変換（interpret）して表示する。UNIXタイムスタンプや、システムコール番号、エラー番号などを変換してくれる。-k以外にも、さまざま絞込みをかけられるので、詳しくは “man 8 ausearch” を参照。3. 実践編
試しに、/tmp配下のファイルで、実際にアクセスエラーを発生させ、ログからファイルと原因を特定してみる。
3.1. /tmpをウォッチする
まず、監査ルールの設定と確認より。
Kernel内のexitフィルターに、/tmp内の全ファイルを監視する “dir=/tmp” というルールを追加する。システムコールの選択は Kernel に任せる。よって
-Sオプションは省略。
どんなアクセスで失敗するかわからないから、”perm=rwxa” を条件とする。
アクセス失敗した時だけログしたいので “success=0” も条件に加える。
[root@localhost ~]# auditctl -a exit,always -F dir=/tmp -F perm=rwxa -F success=0 -k access_fail
[root@localhost ~]# auditctl -l
LIST_RULES: exit,always dir=/tmp perm=rwxa success=0 key=access_fail
できた。
3.2. アクセスエラーを発生させる
/tmp配下のファイルで、意図的に、アクセスエラーを発生させてみる。
具体的には、ユーザ testuser1とtestuser2を作り、testuser1で作成した
/tmp/my_fileを、testuser2から削除してみる。
ユーザ作成：
[root@localhost ~]# useradd testuser1
[root@localhost ~]# useradd testuser2
testuser1になり、ファイル
/tmp/my_file を作成：[root@localhost ~]# su - testuser1
[testuser1@localhost ~]$ echo hi > /tmp/my_file
[testuser1@localhost ~]$ cat /tmp/my_file
hi
testuser2になり、ファイル
/tmp/my_file を削除：[root@localhost ~]# su - testuser2
[testuser2@localhost ~]$ rm /tmp/my_file
rm: remove write-protected regular file ‘/tmp/my_file’? y
rm: cannot remove ‘/tmp/my_file’: Operation not permitted
果たして、/tmp ディレクトリの sticky bit のお陰で、ファイル削除に失敗した。
めでたし。
めでたし。
3.3. ウォッチの解除
監査ログを見る前に、これ以上ログが増えないよう、念の為にルールを削除しておく。
[root@localhost ~]# auditctl -d exit,always -F dir=/tmp -F perm=rwxa -F success=0 -k access_fail
[root@localhost ~]# auditctl -l
No rules
3.4. 監査ログの検査
監査ログを詳しく見てみる。
[root@localhost ~]# ausearch -i -k access_fail
----
type=CONFIG_CHANGE msg=audit(10/25/2014 22:02:24.220:423) : auid=root ses=1 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 op="add rule" key=access_fail list=exit res=yes
----
type=PATH msg=audit(10/25/2014 22:10:57.528:439) : item=1 name=/tmp/my_file inode=100957948 dev=08:02 mode=file,664 ouid=testuser1 ogid=testuser1 rdev=00:00 obj=unconfined_u:object_r:user_tmp_t:s0 objtype=DELETE
type=PATH msg=audit(10/25/2014 22:10:57.528:439) : item=0 name=/tmp/ inode=100663425 dev=08:02 mode=dir,sticky,777 ouid=root ogid=root rdev=00:00 obj=system_u:object_r:tmp_t:s0 objtype=PARENT
type=CWD msg=audit(10/25/2014 22:10:57.528:439) : cwd=/home/testuser2
type=SYSCALL msg=audit(10/25/2014 22:10:57.528:439) : arch=x86_64 syscall=unlinkat success=no exit=-1(Operation not permitted) a0=0xffffffffffffff9c a1=0x62b0c0 a2=0x0 a3=0x7fff0ab0eb40 items=2 ppid=7754 pid=7776 auid=root uid=testuser2 gid=testuser2 euid=testuser2 suid=testuser2 fsuid=testuser2 egid=testuser2 sgid=testuser2 fsgid=testuser2 tty=pts0 ses=1 comm=rm exe=/usr/bin/rm subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 key=access_fail
ちゃんとログがとれている模様。
かなりドッサリだけれども、
---- で仕切られた一塊が、イベント１つに相当。
１つ目のイベントは「ルールが設定された」と言っているだけ。
２つ目のイベントを詳しくみる。
２つ目のイベントを詳しくみる。
１行目
まず、１行目をわかりやすく分解してみた。
type=PATH
msg=audit(10/25/2014 22:10:57.528:439) :
item=1
name=/tmp/my_file inode=100957948 dev=08:02 mode=file,664
ouid=testuser1 ogid=testuser1 rdev=00:00
obj=unconfined_u:object_r:user_tmp_t:s0
objtype=DELETE
msg=audit(10/25/2014 22:10:57.528:439) は、イベント発生時刻と、イベントのシリアル番号 439。続く３行のシリアル番号も 439 なので、同じイベントの一部だと判断できる。name=/tmp/my_fileから、問題ファイルのパス /tmp/my_file が判る。もしパス情報が利用できない場合、inode番号 100957948 から、”find /tmp -inum 100957948” という風に見つけることもできる。
ouidやogidは、ファイル所有者と所有グループ。testuser1:testuser1 になっている。
objはSELinux関連の情報。
objはSELinux関連の情報。
２行目
親ディレクトリの情報。
type=PATH
msg=audit(10/25/2014 22:10:57.528:439) :
item=0
name=/tmp/ inode=100663425 dev=08:02 mode=dir,sticky,777
ouid=root ogid=root rdev=00:00
obj=system_u:object_r:tmp_t:s0
objtype=PARENT
mode=dir,sticky,777から、/tmp には sticky bit がついているようだ。
sticky bitがついていると、ディレクトリのモードが777でも、その配下のファイルは、ファイルオーナーしか削除できない。
３行目
削除しようとしたプロセスのカレントディレクトリ（CWD）の情報。
type=CWD
msg=audit(10/25/2014 22:10:57.528:439) :
cwd=/home/testuser2
４行目
実際に失敗したシステムコールと、それを呼び出したプロセスの情報。
type=SYSCALL
msg=audit(10/25/2014 22:10:57.528:439) :
arch=x86_64 syscall=unlinkat
success=no exit=-1(Operation not permitted)
a0=0xffffffffffffff9c a1=0x62b0c0 a2=0x0 a3=0x7fff0ab0eb40
items=2
ppid=7754 pid=7776
auid=root uid=testuser2 gid=testuser2 euid=testuser2 suid=testuser2
fsuid=testuser2 egid=testuser2 sgid=testuser2 fsgid=testuser2
tty=pts0 ses=1
comm=rm exe=/usr/bin/rm
subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023
key=access_fail
arch=x86_64 syscall=unlinkatから、システムコールは x86_64版の unlinkat と判明。success=no exit=-1 から、システムコールの戻り値は -1。エラー時は errno を負数にして返す決まりなので、実際は正負逆の 1 = EPERM が返却されている。ausearchの-iオプションのお陰で、カッコ内で Operation not permitted と表示されている。
a0~a3 は、このシステムコールに渡された引数。
カーネルソースから、unlinkatの関数シグニチャはこんなだと分かり：
long sys_unlinkat(int dfd, const char __user * pathname, int flag);
この情報を元に引数の意味を解釈すると・・・
a0=0xffffffffffffff9cは、64bitの2の補数で -100 なので、第一引数には -100 が渡っている。これはカーネルヘッダーの一つ linux/include/linux/fcntl.h で定義されている AT_FDCWD に該当する。a1=0x62b0c0 は、このプロセスのユーザ空間でのポインタアドレス。削除しようとしたファイルのパスが入っていたはず。もうプロセスは寿命を終えているで、今から内容を確認することはできない。a2=0x0 はフラグ。値０。
すなわち、以下の呼出しがあり、戻り値は EPERM だったと判明する。
sys_unlinkat(AT_FDCWD, 0x62 b0c0, 0) = -1 ※EPERM
横道にそれるけれど、sys_unlinkat() は、カーネルのVFSのソースコード
linux/fs/namei.c に定義がある。ppid=7754 pid=7776 は、EPERM をもらったプロセスのPIDとPPID。tty=pts0は、このプロセスが動作していた擬似端末（今回のテストではSSHでログインしたから pts 系）。ログインセッションの履歴をたどれば、どこから誰が操作したかも追跡できる可能性が高い。exe=/usr/bin/rmは、このプロセスを生成した実行ファイルが /usr/bin/rmだと言っている。4. まとめ
Auditdを利用すると、以下の様な情報を、アプリ実行中に、簡単に取得できる。
- エラーの発生時刻はいつか
- エラーが発生したファイルはどれか
- その理由は何だったか
- どのプロセスがエラーを受けたか
- どのログインセッションから生成されたプロセスなのか
また、ファイル置換（inode番号が変化）や、特定ファイルをピンポイントで監視するなどにも対応しており、痒いところに手が届くツールとなっている。
今回はファイル操作についてまとめたけれど、auditは他にも様々な使い方ができる。
使いこなせば、大変お役立ちなツールと思う。
参考ドキュメント
- RHEL7 SECURITY GUIDE - Chapter 5. System Auditing
auditdの設定方法の詳細や、より詳しいログの見方など情報あり
今日はここまで。
