ものいわぬOpenLDAPサーバのログ管理・その2：OpenLDAPによるディレクトリサーバ運用（4）（2/3 ページ）

» 2010年04月15日 00時00分公開

[菊池研自，伊藤忠テクノソリューションズ株式会社]

syslogが記録するログの読み方

　それでは、「/var/log/ldap.log」をtailコマンドなどで観察しながら、次のようなオプションでldapsearchコマンドを実行してみましょう（注2）。

# cd /usr/local/openldap-2.4.21

  # ./bin/ldapsearch -x -D cn=Manager,dc=my-domain,dc=com -W -b dc=my-domain,dc=com 1.1

  Enter LDAP Password: secret

注2：ここでは前回の設定どおり、「/var/log/ldap.log」にログを出力していることとします。

　「/var/log/ldap.log」には、以下のようなログが記録されるはずです。

# tail -f /var/log/ldap.log

  Mar 11 02:41:18 CentOS53a slapd[18941]: conn=1000 fd=16 ACCEPT from IP=127.0.0.1:40194 (IP=0.0.0.0:389)

  Mar 11 02:41:18 CentOS53a slapd[18941]: conn=1000 op=0 BIND dn="cn=Manager,dc=my-domain,dc=com" method=128

  Mar 11 02:41:18 CentOS53a slapd[18941]: conn=1000 op=0 BIND dn="cn=Manager,dc=my-domain,dc=com" mech=SIMPLE ssf=0

  Mar 11 02:41:18 CentOS53a slapd[18941]: conn=1000 op=0 RESULT tag=97 err=0 text=

  Mar 11 02:41:18 CentOS53a slapd[18941]: conn=1000 op=1 SRCH base="dc=my-domain,dc=com" scope=2 deref=0 filter="(objectClass=*)"

  Mar 11 02:41:18 CentOS53a slapd[18941]: conn=1000 op=1 SRCH attr=1.1

  Mar 11 02:41:18 CentOS53a slapd[18941]: conn=1000 op=2 UNBIND

  Mar 11 02:41:18 CentOS53a slapd[18941]: conn=1000 op=1 SEARCH RESULT tag=101 err=0 nentries=4 text=

  Mar 11 02:41:18 CentOS53a slapd[18941]: conn=1000 fd=16 closed

　まずは、上記ログの前半、つまり左側部分から見ていきましょう。各行に出力された「conn=1000」の直前の「:」までに着目してください。日付と時間の「Mar 11 02:41:18」をひとまとめにすると、先頭から3つの出力は左から

ログが出力された日時
ホスト名
プロセス名[プロセスID]

となっています。ここまでの内容は、OpenLDAPサーバ以外のログファイルでも見慣れた内容ですが、これ以降にLDAPサーバらしい情報が含まれてきます。

　4つ目の「conn」は、connection番号を表します。OpenLDAPサーバは、この番号をインクリメントしながら、クライアントから受け付けたコネクションごとに一意となる番号を付けていきます。5つ目の「op」はoperation番号を表しており、同一コネクション内で行われるBIND（認証）、SRCH（検索）などの操作ごとに、OpenLDAPサーバが番号を付けているものです。

　先ほど出力したログのconnection番号には「1000」だけが存在し、このconnection番号「1000」に対してoperation番号は「0」「1」「2」と3つ存在しています。このことから、この時点では、1つのLDAPクライアントからの接続で3つの操作、BIND（認証）、SRCH（検索）、UNBINDが行われていることが分かります。

　ここまでのログから判断できた処理とパケットのやりとりをシーケンス図にまとめると、接続の開始から終了まで、全体では以下のような処理が行われていることが分かります。

図1　ldapsearchコマンドの処理のシーケンス図

　ここまでの説明で、OpenLDAPサーバからデフォルトで出力されるログを用いてLDAPクライアントから要求された処理と、OpenLDAPサーバ側で行われる処理の流れが把握できるようになりました。

　しかし、このログファイルからはもう少し詳細な情報を読み取ることができます。ログの後半、つまり各行の右側部分にも着目していきましょう。

　後半部分には、「それぞれのオペレーションがどのように行われたか」と「その結果」が示されています。後半部分のログを読む場合は、以下のように同一コネクション内のオペレーション番号ごとに処理を分け、必要であればオペレーション番号順に並べ替えながら確認していくとよいでしょう。

ACCEPT、close処理

　まずは、クライアントからの接続を受けたことを示すACCEPT処理と、その接続の終了を示すclose処理について見ていきましょう。

... conn=1000 fd=16 ACCEPT from IP=127.0.0.1:40194 (IP=0.0.0.0:389)

  …[略]…

  ... conn=1000 fd=16 closed

　上記のログでコネクション番号の次に表示されている「fd」は、接続に利用されているファイルディスクリプタ番号を示します。この接続がクローズされるまで同一のファイルディスクリプタが利用されていることが分かります。

　また、「ACCEPT from」の次の「IP=XX.XX.XX.XX:YYYY」は、アクセス元のLDAPクライアントのIPアドレスとポート番号です。そして括弧で囲まれた「(IP== XX.XX.XX.XX:YYYY)」は、OpenLDAPサーバがバインドしているIPアドレスとポート番号です。

　上記のログでは「(IP=0.0.0.0:389)」と表示されており、特定のIPアドレスのみに絞ってリスニングしているのではなく、標準的なLDAPで利用するポート番号でクライアントからのリクエストをリスニングしていることが分かります。

　もしこの時点でログに出力がなく、対象クライアントからのリクエストを受け取っていないようであれば、OpenLDAPサーバの問題として扱うより、tcpdumpなど別のツールを用いてパケットをキャプチャするなど、TCP/IPコネクションの問題に焦点を当てた確認を行うとよいかもしれません。

　例えば、通信経路上に問題はないか、LDAPクライアントは正しいOpenLDAPサーバのIPアドレスとポート番号にリクエストを送付しているか、またはOpenLDAPサーバはLDAPクライアントがリクエストを送付しているIPアドレスとポート番号でリスニングしているかなどが最初の確認ポイントになるでしょう。

BIND処理

　次は、LDAPでの認証処理を意味するBIND処理についてです。LDAPでは、検索、変更、追加、削除といった各処理を「誰に」許可するかという判断を下すために、事前にこの認証処理が行われる必要があります。

　以下のログの1行目、2行目の「dn」は、誰が認証を要求しているかを示します。以下のログからは、「cn=Manager,dc=my-domain,dc=com」が認証処理を要求していることが分かります。

... conn=1000 op=0 BIND dn="cn=Manager,dc=my-domain,dc=com" method=128

  ... conn=1000 op=0 BIND dn="cn=Manager,dc=my-domain,dc=com" mech=SIMPLE ssf=0

  ... conn=1000 op=0 RESULT tag=97 err=0 text=

　LDAPには、匿名認証という特定DNを指定しない認証が用意されていますが、この匿名認証が要求された場合、「dn」の出力は「dn=””」となります。

　また1行目の「method」は認証方式を示し、簡易認証の場合は「method=128」、SASL認証が利用された場合は「method=163」となります。2行目の「mech」はSASL認証で利用したメカニズムを示しています。例えば、「DIGEST-MD5」「CRAM-MD5」などです。簡易認証の場合、この値は「SIMPLE」となります。

　最後の「ssf」は、Security Strength Factorsの略で暗号の強度を示しています。SASL認証でDIGEST-MD5を利用した場合には「ssf=128」、簡易認証では「ssf=0」などと表示されます。

前のページへ 1|2|3 次のページへ

SpecialPR