LDAPログ journalctl

投稿者: | 2017年12月24日

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がどんな動きをしているか、イメージつく範囲でかみ砕く。


■1行目「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じゃない値を探していることになる。

■2行目「SRCH attr」

conn=1011 op=2 SRCH attr=objectClass uid userPassword uidNumber gidNumber ・・・

「attr=」はattribute(属性)のことで、ldapがスキームされている属性が網羅されているように見える。以前の投稿に記載したグループやユーザ設定で使用していない属性も検索対象として含まれている。

■3行目「bdb_equality_candidates」

<= bdb_equality_candidates: (uid) not indexed

インデックス検索を行っていて、「uidがインデックスにない」というエラー。インデックス追加の方法は別途。ただしここもインデックスにないだけで、個人としてはデバックで気にするところではない印象。

■4行目「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行目を繰り返した感じの内容になっているので、ほぼ意味は理解できそうだ。

コメントを残す

メールアドレスが公開されることはありません。 * が付いている欄は必須項目です

CAPTCHA