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

前提知識

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

LDAP基礎用語 DCとは?OUとは?バインドDN、ベースDNとは?匿名バインドとは?
LDAP基礎用語 DCとは?OUとは?バインドDN、ベースDNとは?匿名バインドとは?
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パスワードが間違っている」という意味になります。

[LDAPクライアント側の動作ログ] 検索

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=*)"

SRCH はLDAPサーバの中からユーザエントリを検索する処理を意味しています。

base=~はBase DNを意味していますが、BIND DNと同じ(ユーザ自身)になっています。これはつまりLDAP認証後に自分自身が確かに存在すること(匿名バインドではないこと)を確認しています。また、filter="(objectClass=*)" は any (何もフィルタしない)という意味です。

Feb 18 07:35:14 ldapsv1 slapd[11950]: conn=321983 op=1 SRCH attr=dn

op=1 なので前と同じオペレーションです。attr=dn は LDAPサーバに「該当ユーザのdn属性を返すことを要求」しています。

スポンサーリンク

[LDAPサーバ側の動作ログ] 検索結果応答

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

SEARCH RESULT は検索結果であることを示しています。tag=101 は検索結果の際に付けられるタグです。

err=0は前述の通り、正常終了です。

nentries=1 は応答されたエントリ数が1つあることを示しています。なのでこれにより匿名バインドではなく実際に存在するユーザで認証されたことが確定しました。

[LDAPクライアント側の動作ログ] 操作中止

Feb 18 07:35:14 ldapsv1 slapd[11950]: conn=321983 op=2 ABANDON msg=2

ABANDON は操作中止の意味です。この場合は検索操作を中止するということです。不要なようにも思えますが、pam_ldapを使った場合はこのような動作になるようです。

[LDAPクライアント側の動作ログ] UNBIND(ログオフ)

Feb 18 07:35:14 ldapsv1 slapd[11950]: conn=321983 op=3 UNBIND

UNBIND はログオフ処理です。この処理も無くても動作に支障は無いですが、サーバ側では「ログインしっぱなし」という認識になり、メモリに残るので、このUNBINDできれいにしてあげるのが親切です。

[LDAPサーバ側の動作ログ] LDAPコネクション終了

Feb 18 07:35:14 ldapsv1 slapd[11950]: conn=321983 fd=46 closed

conn=321983 のコネクションが終了したことを示しています。

シェアする

  • このエントリーをはてなブックマークに追加

フォローする