Solarisでアクセス監視 - 部屋を掃除したら漫画が沢山出てきたので書く日記

今日仕事が一段落して帰ろうとしていたらお客さんから電話が来ました。曰く「リリース予定の本番機の昨日のログ見ていたら怪しいメッセージが出ていたので調べて欲しい」との事。さっそく調べてみることにしました。結果は大したこと無かったのですが突き止める過程が自分なりに発見があって楽しかったので記します。

なお、かなり狭い範囲のテクニカルな話なので、興味の無い方のために畳んでおきます。

まず前提条件ですが
・対象サーバはSunFire T2000、OSはSolaris 10
・商用環境にいるが近々リリース予定でサービスインはしていない
・host名はhoge(仮名)
・お客さんの作業用ユーザはhoge(仮名)
・サービスイン前なので私はrootになれる(サービスイン後はできない)

という事で、お客さんに許可を貰い、hogeサーバにhogeアクセスしてみることに。
まず、お客さんの言う怪しいメッセージというのは、/var/adm/messagesに出ている以下のログとの事。

% cat /var/adm/messages
・
・
・
Apr  7 16:01:27 hoge vnex: [ID 367333 kern.info] virtual-device: glvc1
Apr  7 16:01:27 hoge genunix: [ID 936769 kern.info] glvc1 is /virtual-devices@100/sunvts@a
Apr  7 16:01:27 hoge vnex: [ID 367333 kern.info] virtual-device: glvc2
Apr  7 16:01:27 hoge genunix: [ID 936769 kern.info] glvc2 is /virtual-devices@100/sunmc@b
Apr  7 16:01:27 hoge vnex: [ID 367333 kern.info] virtual-device: glvc3
Apr  7 16:01:27 hoge genunix: [ID 936769 kern.info] glvc3 is /virtual-devices@100/explorer@c
Apr  7 16:01:27 hoge vnex: [ID 367333 kern.info] virtual-device: glvc4
Apr  7 16:01:27 hoge genunix: [ID 936769 kern.info] glvc4 is /virtual-devices@100/led@d
Apr  7 16:01:27 hoge vnex: [ID 367333 kern.info] virtual-device: glvc5
Apr  7 16:01:27 hoge genunix: [ID 936769 kern.info] glvc5 is /virtual-devices@100/flashupdate@e
Apr  7 16:01:27 hoge ebus: [ID 521012 kern.info] su0 at ebus0: offset 0,3f8
Apr  7 16:01:27 hoge genunix: [ID 936769 kern.info] su0 is /pci@7c0/pci@0/pci@1/pci@0/isa@2/serial@0,3f8
Apr  7 16:01:27 hoge mac: [ID 543131 kern.info] NOTICE: e1000g4/0 registered
Apr  7 16:01:27 hoge e1000g: [ID 766679 kern.info] Intel(R) PRO/1000 Network Connection, Driver Ver. 5.0.14
Apr  7 16:01:28 hoge mac: [ID 543131 kern.info] NOTICE: nxge1/0 registered
Apr  7 16:01:28 hoge pseudo: [ID 129642 kern.info] pseudo-device: fssnap0
Apr  7 16:01:28 hoge genunix: [ID 936769 kern.info] fssnap0 is /pseudo/fssnap@0
Apr  7 16:01:28 hoge pseudo: [ID 129642 kern.info] pseudo-device: ramdisk1024
Apr  7 16:01:28 hoge genunix: [ID 936769 kern.info] ramdisk1024 is /pseudo/ramdisk@1024
Apr  7 16:01:28 hoge pseudo: [ID 129642 kern.info] pseudo-device: winlock0
Apr  7 16:01:28 hoge genunix: [ID 936769 kern.info] winlock0 is /pseudo/winlock@0
Apr  7 16:01:28 hoge mac: [ID 543131 kern.info] NOTICE: nxge2/0 registered
Apr  7 16:01:28 hoge genunix: [ID 408114 kern.info] /pci@7c0/pci@0/pci@8/network@0,3 (nxge3) online
Apr  7 16:01:28 hoge pseudo: [ID 129642 kern.info] pseudo-device: lockstat0
Apr  7 16:01:28 hoge genunix: [ID 936769 kern.info] lockstat0 is /pseudo/lockstat@0
Apr  7 16:01:28 hoge pseudo: [ID 129642 kern.info] pseudo-device: llc10
Apr  7 16:01:28 hoge genunix: [ID 936769 kern.info] llc10 is /pseudo/llc1@0
Apr  7 16:01:29 hoge pseudo: [ID 129642 kern.info] pseudo-device: pm0
Apr  7 16:01:29 hoge genunix: [ID 936769 kern.info] pm0 is /pseudo/pm@0
Apr  7 16:01:29 hoge pseudo: [ID 129642 kern.info] pseudo-device: lofi0
Apr  7 16:01:29 hoge genunix: [ID 936769 kern.info] lofi0 is /pseudo/lofi@0
Apr  7 16:01:29 hoge pseudo: [ID 129642 kern.info] pseudo-device: rsm0
Apr  7 16:01:29 hoge genunix: [ID 936769 kern.info] rsm0 is /pseudo/rsm@0
Apr  7 16:01:29 hoge pseudo: [ID 129642 kern.info] pseudo-device: trapstat0
Apr  7 16:01:29 hoge genunix: [ID 936769 kern.info] trapstat0 is /pseudo/trapstat@0
Apr  7 16:01:29 hoge pseudo: [ID 129642 kern.info] pseudo-device: tsalarm0
Apr  7 16:01:29 hoge genunix: [ID 936769 kern.info] tsalarm0 is /pseudo/tsalarm@0
Apr  7 16:01:29 hoge pseudo: [ID 129642 kern.info] pseudo-device: fbt0
Apr  7 16:01:29 hoge genunix: [ID 936769 kern.info] fbt0 is /pseudo/fbt@0
Apr  7 16:01:30 hoge pseudo: [ID 129642 kern.info] pseudo-device: profile0
Apr  7 16:01:30 hoge genunix: [ID 936769 kern.info] profile0 is /pseudo/profile@0
Apr  7 16:01:30 hoge pseudo: [ID 129642 kern.info] pseudo-device: systrace0
Apr  7 16:01:30 hoge genunix: [ID 936769 kern.info] systrace0 is /pseudo/systrace@0
Apr  7 16:01:30 hoge pseudo: [ID 129642 kern.info] pseudo-device: sdt0
Apr  7 16:01:30 hoge genunix: [ID 936769 kern.info] sdt0 is /pseudo/sdt@0
Apr  7 16:01:30 hoge pseudo: [ID 129642 kern.info] pseudo-device: fasttrap0
Apr  7 16:01:30 hoge genunix: [ID 936769 kern.info] fasttrap0 is /pseudo/fasttrap@0
Apr  7 16:01:30 hoge pseudo: [ID 129642 kern.info] pseudo-device: mdesc0
Apr  7 16:01:30 hoge genunix: [ID 936769 kern.info] mdesc0 is /pseudo/mdesc@0
Apr  7 16:01:30 hoge pseudo: [ID 129642 kern.info] pseudo-device: fcsm0
Apr  7 16:01:30 hoge genunix: [ID 936769 kern.info] fcsm0 is /pseudo/fcsm@0
・
・
・

このメッセージが何を示しているのかは不明ですが、エラーとかワーニングじゃないし、放っといても良いんではないかと思いました。しかし何かの予兆だと嫌なので色々ログを当たってみました。解決までは色々模索して大体、2時間くらいかかりましたが、要約します。

まず、/var/adm/sulogを見てみました。該当日時のログには、

SU 04/07 16:00 + pts/1 hoge-root

というメッセージが。このログから分かることは、「怪しい」ログメッセージが出ている4月7日の16:01の直前に、pts/1という回線(大体telnetかsshでリモートアクセスした際に振られる番号)でhogeというユーザでログインしている人が管理者権限になった、という事です。前後の時間帯にアクセスしている人はいなかったので、ほぼ間違いなくこの人が何かしていたと思われます。

次にこの人が誰か、という事を調べます。lastコマンドを実行すれば、アクセス先が調べられるので実行してみました。ところが

% last
bata64    pts/3        192.168.0.1     Tue Apr  8 21:23   ログイン中です。
root      pts/2        192.168.0.1     Tue Apr  8 21:03 - 21:03  (00:00)
root      pts/1        192.168.0.1     Tue Apr  8 21:02 - 21:23  (00:21)

というように、4月7日の情報が残っていません。どうしたものかと思い、ネットで検索をしたところ、こちらのサイトを見つけ、lastコマンドは/var/adm/wtmpを参照して結果を表示していることが分かりました。hogeサーバの/var/adm/を見てみると、

% ls -l /var/adm/wtm*
-rw-r--r--   1 adm      adm        67332  4月  8日  21:23 /var/adm/wtmpx
-rw-r--r--   1 adm      adm        2763960  4月  7日  23:59 /var/adm/wtmpx.0

というように、wtmpx.0という名前で古いデータはローテートされていました。man lastで調べて、読み込むファイルを指定できることが分かったので以下のコマンドを実行。

% last -f /var/adm/wtmpx.0
・
・
・
hoge      pts/1        192.168.0.2 Mon Apr  7 14:00 - 19:00  (5:00)
・
・
・

ここで、「192.168.0.2」というお客さんしか使えないIPアドレスで、pts/1という回線で、該当時間帯にhogeユーザでアクセスしている人がいる事が判明。十中八九、お客さんです。この旨電話で聞いてみると、「サービスイン前に内部ディスクのフルバックアップをフィールドエンジニア*1に依頼したのでやっていたかもしれない。確認します」との事。
推測ですが/var/adm/messagesの「怪しい」メッセージは、バックアップ用に何かのDISK装置(NFSとかで)を接続して認識させたために発生したのではないかと。

とりあえずこれでたぶん解決。3時間拘束されましたが何だか満足。さあ帰ろう。

ではー。

*1:まあようするに現地作業員です