openldap環境を使用するにあたり、例えばldapユーザでうまくsshログインできなかったり、slapdデーモンがうまく起動できなかったりすると、ログなどを見てデバックしたくなる。
しかし、openldap-serversはデフォルトでログが記録されるようになっていない。/var/log配下にldapログが履かれないのだ。
centosの機能として、logをリアルタイムで目視する方法としてjournalctlコマンドがある。
ldapサーバにログインし、journalctlコマンドを実行してみる。
[user01@ldapserver ~]$ sudo journalctl -u slapd -f パスワード: 12月 24 14:33:53 ldapserver slapd[1103]: conn=1003 op=0 EXT oid=1.3.6.1.4.1.1466.20037 12月 24 14:33:53 ldapserver slapd[1103]: conn=1003 op=0 STARTTLS 12月 24 14:33:53 ldapserver slapd[1103]: conn=1003 op=0 RESULT oid= err=0 text= 12月 24 14:33:53 ldapserver slapd[1103]: conn=1003 fd=22 TLS established tls_ssf=256 ssf=256 12月 24 14:33:53 ldapserver slapd[1103]: conn=1003 op=1 BIND dn="uid=user01,cn=ldapmanager,ou=Group,dc=abc,dc=def,dc=com" method=128 12月 24 14:33:53 ldapserver slapd[1103]: slap_global_control: unrecognized control: 1.3.6.1.4.1.42.2.27.8.5.1 12月 24 14:33:53 ldapserver slapd[1103]: conn=1003 op=1 BIND dn="uid=user01,cn=ldapmanager,ou=Group,dc=abc,dc=def,dc=com" mech=SIMPLE ssf=0 12月 24 14:33:53 ldapserver slapd[1103]: conn=1003 op=1 RESULT tag=97 err=0 text= 12月 24 14:33:53 ldapserver slapd[1103]: conn=1003 op=2 UNBIND 12月 24 14:33:53 ldapserver slapd[1103]: conn=1003 fd=22 closed
一応前提として、rootユーザではなくldapユーザでsshログインしているためsudoをつけている。そのためsudoパスワードが聞かれる。オプションの説明は以下。
「-u」 ： ユニット名を指定するときに使う。ユニット名とはデーモンのことで、ここではslapd。sshdやsssdなども指定できる。
「-f」 ： ログの末尾を表示する際に使用する。tail -f コマンドのようなもの。
ここで表示されるログはこの場だけで、ファイルに残るわけではない。
ファイルに残したい場合は、/etc/syslog.confにログが残る設定をする。
[user01@ldapserver ~]$ sudo cp -p /etc/rsyslog.conf /etc/rsyslog.conf.bk ※一応事前のバックアップ
[user01@ldapserver ~]$ sudo vi /etc/rsyslog.conf
：
local4.* /var/log/ldap.log
：
[user01@ldapserver ~]$ sudo systemctl restart rsyslog
上記の「local4.*～」の行を追加した後、rsyslogサービスを再起動する。再起動直後は、まだ/var/log/ldap.logが存在しない。
この状態で、試しにldapクライアントへsshログインした後に/var/log配下を確認すると。。。
[user01@ldapserver ~]$ ls -lrt /var/log | grep ldap
-rw-------. 1 root root 5105 12月 24 14:51 ldap.log
ldap.logができた！ではcatコマンドで中を見てみる。
[user01@ldapserver ~]$ sudo cat /var/log/ldap.log パスワード: Dec 24 15:03:04 ldapserver slapd[1103]: conn=1011 op=2 SRCH base="dc=abc,dc=def,dc=com" scope=2 deref=0 filter="(&(uid=user01)(objectClass=posixAccount)(uid=*)(&(uidNumber=*)(!(uidNumber=0))))" Dec 24 15:03:04 ldapserver slapd[1103]: conn=1011 op=2 SRCH attr=objectClass uid userPassword uidNumber gidNumber gecos homeDirectory loginShell krbPrincipalName cn modifyTimestamp modifyTimestamp shadowLastChange shadowMin shadowMax shadowWarning shadowInactive shadowExpire shadowFlag krbLastPwdChange krbPasswordExpiration pwdAttribute authorizedService accountExpires userAccountControl nsAccountLock host loginDisabled loginExpirationTime loginAllowedTimeMap sshPublicKey mail Dec 24 15:03:04 ldapserver slapd[1103]: <= bdb_equality_candidates: (uid) not indexed Dec 24 15:03:04 ldapserver slapd[1103]: conn=1011 op=2 SEARCH RESULT tag=101 err=0 nentries=1 text= Dec 24 15:03:04 ldapserver slapd[1103]: conn=1011 op=3 SRCH base="dc=abc,dc=def,dc=com" scope=2 deref=0 filter="(&(uid=user01)(objectClass=posixAccount)(&(uidNumber=*)(!(uidNumber=0))))" Dec 24 15:03:04 ldapserver slapd[1103]: conn=1011 op=3 SRCH attr=objectClass uid userPassword uidNumber gidNumber gecos homeDirectory loginShell krbPrincipalName cn modifyTimestamp modifyTimestamp shadowLastChange shadowMin shadowMax shadowWarning shadowInactive shadowExpire shadowFlag krbLastPwdChange krbPasswordExpiration pwdAttribute authorizedService accountExpires userAccountControl nsAccountLock host loginDisabled loginExpirationTime loginAllowedTimeMap sshPublicKey mail Dec 24 15:03:04 ldapserver slapd[1103]: <= bdb_equality_candidates: (uid) not indexed Dec 24 15:03:04 ldapserver slapd[1103]: conn=1011 op=3 SEARCH RESULT tag=101 err=0 nentries=1 text= Dec 24 15:03:04 ldapserver slapd[1103]: conn=1011 op=4 SRCH base="dc=abc,dc=def,dc=com" scope=2 deref=0 filter="(&(memberUid=user01)(objectClass=posixGroup)(cn=*)(&(gidNumber=*)(!(gidNumber=0))))" Dec 24 15:03:04 ldapserver slapd[1103]: conn=1011 op=4 SRCH attr=objectClass cn userPassword gidNumber modifyTimestamp modifyTimestamp Dec 24 15:03:04 ldapserver slapd[1103]: <= bdb_equality_candidates: (memberUid) not indexed Dec 24 15:03:04 ldapserver slapd[1103]: conn=1011 op=4 SEARCH RESULT tag=101 err=0 nentries=0 text= Dec 24 15:03:04 ldapserver slapd[1103]: conn=1011 op=5 SRCH base="dc=abc,dc=def,dc=com" scope=2 deref=0 filter="(&(gidNumber=1001)(objectClass=posixGroup)(cn=*)(&(gidNumber=*)(!(gidNumber=0))))" Dec 24 15:03:04 ldapserver slapd[1103]: conn=1011 op=5 SRCH attr=objectClass cn userPassword gidNumber memberuid modifyTimestamp modifyTimestamp Dec 24 15:03:04 ldapserver slapd[1103]: <= bdb_equality_candidates: (gidNumber) not indexed Dec 24 15:03:04 ldapserver slapd[1103]: conn=1011 op=5 SEARCH RESULT tag=101 err=0 nentries=1 text=
はっきり言って なんじゃこら状態^^;;
なので、一応openldapがどんな動きをしているか、イメージつく範囲でかみ砕く。
■１行目「SRCH base」
conn=1011 op=2 SRCH base=”dc=abc,dc=def,dc=com” scope=2 deref=0 filter=”(&(uid=user01)(objectClass=posixAccount)(uid=*)(&(uidNumber=*)(!(uidNumber=0))))”
「conn=1011」 ： コネクション番号で、この番号が同じログが一連の処理となる。上記のログではすべてconn=1011なので、このログ全部がつながった動きだと判断できる。
「op=2」 ： オペレーション番号で、BIND（認証）やSEARCH（検索）を行うごとに振られる番号。
「SRCH」 ： SEARCHなので、検索。ユーザがログインしてきたときに、そのユーザがいるかどうかを確認している。
「base=”dc=abc,dc=def,dc=com”」 ： 検索対象のベースDN。3．OpenLDAPサーバ ベースDN／管理者DNの設定で設定したベースDNがもとになっているが、検索の出発点をどこにするかによって、base=の内容も変わってくる。
「scope=2」 ： scopeの値は0～3があり、それぞれ以下の意味を持つ。
0 ⇒ 検索対象のベースDNのみ検索。
1 ⇒ 検索対象のベースDNと、その直下ディレクトリのみ検索。
2 ⇒ 検索対象のベースDNを含むその配下のディレクトリすべてを検索。
3 ⇒ 検索対象のベースDNを含まないその配下のディレクトリすべてを検索。
「deref=0」 ： エイリアス参照（別名参照）をどのように行うかの数値。エイリアス参照については後日。。。ただ、本稿ではエイリアス参照の設定は行っていないため、deref=0になっている。わたし個人の印象としても、デバックする際はあまり気にしなくてよいかと。
「filter=”(&(uid=user01)(objectClass=posixAccount)(uid=*)(&(uidNumber=*)(!(uidNumber=0))))”」 ：
検索フィルタ。uid属性／オブジェクトクラス／uidNumber属性がAND条件で検索されている。この条件で引っかかるユーザを探している。「!(uidNumber=0)」の！は否を表しているので、uidNumberが0じゃない値を探していることになる。
■２行目「SRCH attr」
conn=1011 op=2 SRCH attr=objectClass uid userPassword uidNumber gidNumber ・・・
「attr=」はattribute（属性）のことで、ldapがスキームされている属性が網羅されているように見える。以前の投稿に記載したグループやユーザ設定で使用していない属性も検索対象として含まれている。
■３行目「bdb_equality_candidates」
<= bdb_equality_candidates: (uid) not indexed
インデックス検索を行っていて、「uidがインデックスにない」というエラー。インデックス追加の方法は別途。ただしここもインデックスにないだけで、個人としてはデバックで気にするところではない印象。
■４行目「SEARCH RESULT」
conn=1011 op=2 SEARCH RESULT tag=101 err=0 nentries=1 text=
「SEARCH RESULT」 ： 文字のごとく、検索結果。そのあとの記述で検索結果の詳細を表している。
「tag=101」 ： tagは、何の処理に対する結果なのかを示している。以下、数値の意味を示す。
97 ⇒ BIND（認証）
101 ⇒ SEARCH RESULT（検索）
103 ⇒ MOD（変更）
105 ⇒ ADD（追加）
107 ⇒ DEL（削除）
「err=0」 ： エラーコードを示す、0になっているので、エラーなし。エラーの詳細は別途。
「nentries=1」 ： nentriesにフラグがたつと、検索した結果ヒットありとなる。0の場合、検索ヒットなし。この場合1になっているので、検索したユーザがいるということになる。
「text=」 ： 正直このtext=のあとに数値が割り振られたところを見たことがないので、役割については不明。
以上、ログインしたときのログについては、1～4行目を繰り返した感じの内容になっているので、ほぼ意味は理解できそうだ。