前提知識
BIND DNとBaseDNについての知識が必要になりますので、もし分からなければ以下を参照して下さい。
OpenLDAPログの例と見方
例として、pam_ldapを利用したLDAP認証時のログを以下に示します。
Feb 18 07:35:14 ldapsv1 slapd[11950]: conn=321983 fd=46 ACCEPT from IP=10.10.10.10:49100 (IP=0.0.0.0:636)
Feb 18 07:35:14 ldapsv1 slapd[11950]: conn=321983 fd=46 TLS established tls_ssf=256 ssf=256
Feb 18 07:35:14 ldapsv1 slapd[11950]: conn=321983 op=0 BIND dn=”uid=Bob,ou=dom1,dc=example,dc=com” method=128
Feb 18 07:35:14 ldapsv1 slapd[11950]: conn=321983 op=0 BIND dn=”uid=Bob,ou=dom1,dc=example,dc=com” mech=SIMPLE ssf=0
Feb 18 07:35:14 ldapsv1 slapd[11950]: conn=321983 op=0 RESULT tag=97 err=0 text=
Feb 18 07:35:14 ldapsv1 slapd[11950]: conn=321983 op=1 SRCH base=”uid=Bob,ou=dom1,dc=example,dc=com” scope=0 deref=0 filter=”(objectClass=*)”
Feb 18 07:35:14 ldapsv1 slapd[11950]: conn=321983 op=1 SRCH attr=dn
Feb 18 07:35:14 ldapsv1 slapd[11950]: conn=321983 op=1 SEARCH RESULT tag=101 err=0 nentries=1 text=
Feb 18 07:35:14 ldapsv1 slapd[11950]: conn=321983 op=2 ABANDON msg=2
Feb 18 07:35:14 ldapsv1 slapd[11950]: conn=321983 op=3 UNBIND
Feb 18 07:35:14 ldapsv1 slapd[11950]: conn=321983 fd=46 closed
LDAPログは1つのトランザクションで複数行のログを吐きますが、クライアントから接続しにくるとまず “ACCEPT from IP=” を含むログを生成します。
なのでトランザクションの開始を知りたい（アクセス元IPを知りたい）ときは “ACCEPT from IP=” で grep します。
[LDAPサーバ側の動作ログ] LDAPコネクション開始
“ldapsv1″ はホスト名、”slapd” はプロセス名、[11950] はプロセスID、”conn=”はConnection番号を示しています。
fd は file descripter の番号ですが、たいして意味はありません。fd 番号は0が標準入力、1が標準出力、2がエラー出力で、3番以降が汎用のものとして用意されており、slapd は用意されたfdの中から適当に空いているものを使い、DiskへのIO(入出力)を行います。
“ACCEPT from IP=” の後はLDAPクライアントのIPとTCPポート番号を示しています。 (IP=0.0.0.0:636) はローカルのListenアドレス:ポート番号です。(0.0.0.0は全インタフェースでListenしていることを示しています。
LDAPにはConnectionという概念があり、Connection番号が同じログは、一連のトランザクションであることを示しています。なので注目したいトランザクションがあれば、conn=3219831 等でgrep すればログが見やすくなります。
[LDAPサーバ側の動作ログ] TLSセッション開始
LDAPS ( LDAP over TLS )を使う場合は以下のログが出力されます。
[LDAPクライアント側の動作ログ] BIND要求(LDAP認証)
次に実際のLDAPのオペレーションが始まります。コネクション毎に、オペレーション番号を示すop=が0から始まります。これは同一コネクション内で1ずつ増えていきます。
LDAPコネクションはまずBIND処理(LDAPサーバへのログイン)から始まります。LDAP認証を行う場合は幾つか方法がありますが、このケースでは認証したいユーザ（Bob）をBIND DNとしてBINDを行います。
上記ログでは BIND DN(ログインユーザ)が”uid=Bob,ou=dom1,dc=example,dc=com” であること、methodが128(ユーザパスワード認証)であることが示されています。
さらにこのBIND処理がSIMPLE(平文パスワード) ssf=0(セキュリティ強度0)であることが示されています。op=0なのでその前のログと同じオペレーションです。ただしこのケースでは LDAPS となっており、TLS で通信全体が保護されていますので、実際にはセキュリティ強度は高いです。
[LDAPサーバ側の動作ログ] BIND(LDAP認証)成功
op=0なので上2つのログと同一オペレーションですが、内容としてRESULTなのでサーバ側のログになります。err=0は正常終了を意味しています。もしerr=49となっている場合は「IDパスワード情報が間違っている」ことを示しています。tag=97はBIND要求に対する返答であることを示しています。
なので”tag=97 err=49″ となっている場合は「BIND DNのIDパスワードが間違っている」という意味になります。
[LDAPクライアント側の動作ログ] 検索
SRCH はLDAPサーバの中からユーザエントリを検索する処理を意味しています。
base=～はBase DNを意味していますが、BIND DNと同じ(ユーザ自身)になっています。これはつまりLDAP認証後に自分自身が確かに存在すること(匿名バインドではないこと)を確認しています。また、filter=”(objectClass=*)” は any (何もフィルタしない)という意味です。
op=1 なので前と同じオペレーションです。attr=dn は LDAPサーバに「該当ユーザのdn属性を返すことを要求」しています。
[LDAPサーバ側の動作ログ] 検索結果応答
SEARCH RESULT は検索結果であることを示しています。tag=101 は検索結果の際に付けられるタグです。
err=0は前述の通り、正常終了です。
nentries=1 は応答されたエントリ数が1つあることを示しています。なのでこれにより匿名バインドではなく実際に存在するユーザで認証されたことが確定しました。
[LDAPクライアント側の動作ログ] 操作中止
ABANDON は操作中止の意味です。この場合は検索操作を中止するということです。不要なようにも思えますが、pam_ldapを使った場合はこのような動作になるようです。
[LDAPクライアント側の動作ログ] UNBIND(ログオフ)
UNBIND はログオフ処理です。この処理も無くても動作に支障は無いですが、サーバ側では「ログインしっぱなし」という認識になり、メモリに残るので、このUNBINDできれいにしてあげるのが親切です。
[LDAPサーバ側の動作ログ] LDAPコネクション終了
conn=321983 のコネクションが終了したことを示しています。
