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

前提知識

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

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

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

milestone-of-se.nesuke.com

2020.03.10

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 のコネクションが終了したことを示しています。

IT/インフラエンジニアの地位とスキル向上のために

【年収UPの体験談】あなたの IT/インフラエンジニアとしての価値

IT 技術の進化はとどまることを知りません。矢継ぎ早に新たな技術が出てきたり、数...

milestone-of-se.nesuke.com

【パケットキャプチャ】はNWエンジニアの価値を大きく高める

nesuke の考える NW エンジニアの2つの道 ネットワークエンジニアには ...

milestone-of-se.nesuke.com