OpenLDAP のログの見方、確認、解析方法

前提知識
OpenLDAPログの例と見方
IT/インフラエンジニアの地位とスキル向上のために

前提知識

BIND DN と Base DN についての知識が必要になりますので、もし分からなければ以下を参照して下さい。

【LDAP基礎用語】DCとは？OUとは？バインドDN,ベースDN,サフィックスとは？匿名バインドとは？ldapsearchのオプション

DNとは、DCとは、OUとは LDAP ツリーを構成する要素は全てオブジェクト...

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コネクション開始

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)

"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) を使う場合は以下のログが出力されます。

Feb 18 07:35:14 ldapsv1 slapd[11950]: conn=321983 fd=46 TLS established tls_ssf=256 ssf=256

[LDAPクライアント側の動作ログ] BIND要求(LDAP認証)

次に実際の LDAP のオペレーションが始まります。コネクション毎に、オペレーション番号を示す op= が 0 から始まります。これは同一コネクション内で 1 ずつ増えていきます。

LDAP コネクションはまず BIND 処理 (LDAP サーバへのログイン) から始まります。LDAP 認証を行う場合は幾つか方法がありますが、このケースでは認証したいユーザ (Bob) を BIND DN として BIND を行います。

Feb 18 07:35:14 ldapsv1 slapd[11950]: conn=321983 op=0 BIND dn="uid=Bob,ou=dom1,dc=example,dc=com" method=128

上記ログでは 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=Admin,ou=dom1,dc=example,dc=com" mech=SIMPLE ssf=0

さらにこの BIND 処理が SIMPLE (平文パスワード) ssf=0 (セキュリティ強度 0) であることが示されています。op=0 なのでその前のログと同じオペレーションです。ただしこのケースでは LDAPS となっており、TLS で通信全体が保護されていますので、実際にはセキュリティ強度は高いです。

[LDAPサーバ側の動作ログ] BIND(LDAP認証)成功

Feb 18 07:35:14 ldapsv1 slapd[11950]: conn=321983 op=0 RESULT tag=97 err=0 text=

op=0 なので上 2 つのログと同一オペレーションですが、内容として RESULT なのでサーバ側のログになります。err=0 は正常終了を意味しています。もし err=49 となっている場合は「ID/パスワード情報が間違っている」ことを示しています。tag=97 は BIND 要求に対する返答であることを示しています。

なので "tag=97 err=49" となっている場合は「BIND DN の ID/パスワードが間違っている」という意味になります。