前提知識
BIND DN と Base DN についての知識が必要になりますので、もし分からなければ以下を参照して下さい。
OpenLDAPログの例と見方
例として、pam_ldapを利用したLDAP認証時のログを以下に示します。
[root@ldapsv1 ~]# cat /var/log/ldap.log 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 します。
# cat /var/log/ldap.log | grep "ACCEPT from IP=" | more
[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 すればログが見やすくなります。
# cat /var/log/ldap.log | grep conn=3219831
[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 のコネクションが終了したことを示しています。
コメント