毎回テーマがコロコロと変わる本連載ですが、
OpenLDAPとログの設定
OpenLDAPのログはsyslogを経由して出力されます。ログの設定はいつものslapd.
loglevel 32
loglevelで指定可能な値は表1のように定義されています。
値 | ログ収集データ |
---|---|
1 | trace function calls |
2 | debug packet handling |
4 | heavy trace debugging |
8 | connection management |
16 | print out packets sent and received |
32 | search filter processing |
64 | configuration file processing |
128 | access control list processing |
256 | stats log connections/ |
512 | stats log entries sent |
1024 | print communication with shell backends |
2048 | entry parsing |
以上のいずれかを設定することにより、
local4.* /var/log/ldap.log
/etc/init.d/syslog restart
syslog-ngなどのその他のsyslogデーモンを使用している場合にも、
ログの出力例
syslogデーモンの設定を適切に行った場合、
Feb 16 21:11:01 localhost slapd[4002]: conn=2 op=1 ENTRY dn="cn=suzuki,ou=People,dc=example,dc=com"
Feb 16 21:11:11 localhost slapd[4044]: conn=0 fd=10 ACCEPT from IP=127.0.0.1:32785 (IP=0.0.0.0:389)
Feb 16 21:11:11 localhost slapd[4044]: conn=0 op=0 BIND dn="cn=Manager,dc=example,dc=com" method=128
Feb 16 21:11:11 localhost slapd[4044]: conn=0 op=0 BIND dn="cn=Manager,dc=example,dc=com" mech=SIMPLE ssf=0
Feb 16 21:11:11 localhost slapd[4044]: conn=0 op=0 RESULT tag=97 err=0 text=
Feb 16 21:11:11 localhost slapd[4044]: conn=0 op=1 ADD dn="cn=suzuki,ou=People,dc=example,dc=com"
Feb 16 21:11:11 localhost slapd[4044]: conn=0 op=2 UNBIND
Feb 16 21:11:11 localhost slapd[4044]: conn=0 op=1 RESULT tag=105 err=0 text=
Feb 16 21:11:11 localhost slapd[4044]: conn=0 fd=10 closed
Feb 16 21:11:11 localhost slapd[4044]: conn=1 fd=10 ACCEPT from IP=127.0.0.1:32786 (IP=0.0.0.0:389)
Feb 16 21:11:11 localhost slapd[4044]: conn=1 op=0 BIND dn="cn=Manager,dc=example,dc=com" method=128
Feb 16 21:11:11 localhost slapd[4044]: conn=1 op=0 BIND dn="cn=Manager,dc=example,dc=com" mech=SIMPLE ssf=0
Feb 16 21:11:11 localhost slapd[4044]: conn=1 op=0 RESULT tag=97 err=0 text=
Feb 16 21:11:11 localhost slapd[4044]: conn=1 op=1 SRCH base="dc=example,dc=com" scope=2 deref=0 filter="(cn=suzuki)"
Feb 16 21:11:11 localhost slapd[4044]: conn=1 op=1 SEARCH RESULT tag=101 err=0 nentries=1 text=
Feb 16 21:11:11 localhost slapd[4044]: conn=1 op=2 UNBIND
Feb 16 21:11:11 localhost slapd[4044]: conn=1 fd=10 closed
Feb 16 21:11:18 localhost slapd[4083]: => access_allowed: write access to "ou=People,dc=example,dc=com" "children" requested
Feb 16 21:11:18 localhost slapd[4083]: <= root access granted
Feb 16 21:11:18 localhost slapd[4083]: => access_allowed: write access to "cn=suzuki,ou=People,dc=example,dc=com" "entry" requested
Feb 16 21:11:18 localhost slapd[4083]: <= root access granted
Feb 16 21:11:18 localhost slapd[4083]: => access_allowed: search access to "cn=suzuki,ou=People,dc=example,dc=com" "cn" requested
Feb 16 21:11:18 localhost slapd[4083]: <= root access granted
Feb 16 21:11:18 localhost slapd[4083]: => access_allowed: read access to "cn=suzuki,ou=People,dc=example,dc=com" "entry" requested
Feb 16 21:11:18 localhost slapd[4083]: <= root access granted
Feb 16 21:11:18 localhost slapd[4083]: => access_allowed: read access to "cn=suzuki,ou=People,dc=example,dc=com" "objectClass" requested
Feb 16 21:11:18 localhost slapd[4083]: <= root access granted
Feb 16 21:11:18 localhost slapd[4083]: => access_allowed: read access to "cn=suzuki,ou=People,dc=example,dc=com" "sn" requested
Feb 16 21:11:18 localhost slapd[4083]: <= root access granted
Feb 16 21:11:18 localhost slapd[4083]: => access_allowed: read access to "cn=suzuki,ou=People,dc=example,dc=com" "cn" requested
Feb 16 21:11:18 localhost slapd[4083]: <= root access granted
Feb 16 21:11:18 localhost slapd[4083]: => access_allowed: read access to "cn=suzuki,ou=People,dc=example,dc=com" "mail" requested
Feb 16 21:11:18 localhost slapd[4083]: <= root access granted
Feb 16 21:11:34 localhost slapd[4160]: line 21 (index cn,serviceType,objectClass,uid,uidNumber,gidNumber,memberUid eq)
Feb 16 21:11:34 localhost slapd[4160]: index cn 0x0004
Feb 16 21:11:34 localhost slapd[4160]: index serviceType 0x0004
Feb 16 21:11:34 localhost slapd[4160]: index objectClass 0x0004
Feb 16 21:11:34 localhost slapd[4160]: index uid 0x0004
Feb 16 21:11:34 localhost slapd[4160]: index uidNumber 0x0004
Feb 16 21:11:34 localhost slapd[4160]: index gidNumber 0x0004
Feb 16 21:11:34 localhost slapd[4160]: index memberUid 0x0004
Feb 16 21:11:34 localhost slapd[4160]: line 26 (access to attrs=userPassword by anonymous auth by self write by * none)
Feb 16 21:11:34 localhost slapd[4160]: line 28 (access to * by * read)
Feb 16 21:11:52 localhost slapd[4237]: begin get_filter
Feb 16 21:11:52 localhost slapd[4237]: EQUALITY
Feb 16 21:11:52 localhost slapd[4237]: end get_filter 0
Feb 16 21:11:52 localhost slapd[4237]: => bdb_filter_candidates
Feb 16 21:11:52 localhost slapd[4237]: AND
Feb 16 21:11:52 localhost slapd[4237]: => bdb_list_candidates 0xa0
Feb 16 21:11:52 localhost slapd[4237]: => bdb_filter_candidates
Feb 16 21:11:52 localhost slapd[4237]: OR
Feb 16 21:11:52 localhost slapd[4237]: => bdb_list_candidates 0xa1
Feb 16 21:11:52 localhost slapd[4237]: => bdb_filter_candidates
Feb 16 21:11:52 localhost slapd[4237]: EQUALITY
Feb 16 21:11:52 localhost slapd[4237]: <= bdb_filter_candidates: id=0 first=0 last=0
Feb 16 21:11:52 localhost slapd[4237]: => bdb_filter_candidates
Feb 16 21:11:52 localhost slapd[4237]: EQUALITY
Feb 16 21:11:52 localhost slapd[4237]: <= bdb_filter_candidates: id=1 first=3 last=3
Feb 16 21:11:52 localhost slapd[4237]: <= bdb_list_candidates: id=1 first=3 last=3
Feb 16 21:11:52 localhost slapd[4237]: <= bdb_filter_candidates: id=1 first=3 last=3
Feb 16 21:11:52 localhost slapd[4237]: <= bdb_list_candidates: id=1 first=3 last=3
Feb 16 21:11:52 localhost slapd[4237]: <= bdb_filter_candidates: id=1 first=3 last=3
Feb 16 21:11:52 localhost slapd[4237]: => test_filter
Feb 16 21:11:52 localhost slapd[4237]: EQUALITY
Feb 16 21:11:52 localhost slapd[4237]: <= test_filter 6
これらのサンプルからわかるように、
ログを読む
HTTPの世界で、
Feb 16 21:11:11 localhost slapd[4044]: conn=0 fd=10 ACCEPT from IP=127.0.0.1:32785 (IP=0.0.0.0:389)
Feb 16 21:11:11 localhost slapd[4044]: conn=0 op=0 BIND dn="cn=Manager,dc=example,dc=com" method=128
Feb 16 21:11:11 localhost slapd[4044]: conn=0 op=0 BIND dn="cn=Manager,dc=example,dc=com" mech=SIMPLE ssf=0
Feb 16 21:11:11 localhost slapd[4044]: conn=0 op=0 RESULT tag=97 err=0 text=
Feb 16 21:11:11 localhost slapd[4044]: conn=0 op=1 ADD dn="cn=suzuki,ou=People,dc=example,dc=com"
Feb 16 21:11:11 localhost slapd[4044]: conn=0 op=2 UNBIND
Feb 16 21:11:11 localhost slapd[4044]: conn=0 op=1 RESULT tag=105 err=0 text=
Feb 16 21:11:11 localhost slapd[4044]: conn=0 fd=10 closed
まずこれらのログで一致しているのは、
次に着目すべきはop
以上の点を整理してみると、
- 127.
0.0. 1:32785というクライアントからからLDAP接続が行われた - その際、
cn=Manager,dc=example,dc=comというDNでシンプル認証が行われ、 無事認証が通った (err=0) - cn=suzuki,ou=People,dc=example,dc=comというDNの追加が試行され成功した
(err=0) - アンバインドされた後、
切断された。
トラブルシューティング
LDAPとさまざまなソフトウェアを連携させる中で、
本連載では過去にOpenSSHの公開鍵をLDAPで管理する方法を紹介しました。これを例として、
まずはもっとも基本的な方法として、
ではログの分析に入りたいと思います。
Feb 17 09:55:19 localhost slapd[16607]: conn=3 fd=11 ACCEPT from IP=10.0.100.11:32790 (IP=0.0.0.0:389)
Feb 17 09:55:19 localhost slapd[16607]: conn=3 op=0 BIND dn="" method=128
Feb 17 09:55:19 localhost slapd[16607]: conn=3 op=0 RESULT tag=97 err=0 text=
Feb 17 09:55:19 localhost slapd[16607]: conn=3 op=1 SRCH base="ou=people,dc=example,dc=com" scope=2 deref=0 filter="(&(objectClass=posixAccount)(objectClass=ldapPublicKey)(uid=root))"
Feb 17 09:55:19 localhost slapd[16607]: conn=3 op=1 SRCH attr=sshPublicKey
Feb 17 09:55:19 localhost slapd[16607]: conn=3 op=1 SEARCH RESULT tag=101 err=0 nentries=0 text=
Feb 17 09:55:19 localhost slapd[16607]: conn=3 op=2 SRCH base="ou=people,dc=example,dc=com" scope=2 deref=0 filter="(&(objectClass=posixAccount)(objectClass=ldapPublicKey)(uid=root))"
Feb 17 09:55:19 localhost slapd[16607]: conn=3 op=2 SRCH attr=sshPublicKey
Feb 17 09:55:19 localhost slapd[16607]: conn=3 op=2 SEARCH RESULT tag=101 err=0 nentries=0 text=
Feb 17 09:55:19 localhost slapd[16607]: conn=3 op=3 SRCH base="ou=people,dc=example,dc=com" scope=2 deref=0 filter="(&(objectClass=posixAccount)(objectClass=ldapPublicKey)(uid=root))"
Feb 17 09:55:19 localhost slapd[16607]: conn=3 op=3 SRCH attr=sshPublicKey
Feb 17 09:55:19 localhost slapd[16607]: conn=3 op=3 SEARCH RESULT tag=101 err=0 nentries=0 text=
Feb 17 09:55:19 localhost slapd[16607]: conn=3 op=4 SRCH base="ou=people,dc=example,dc=com" scope=2 deref=0 filter="(&(objectClass=posixAccount)(objectClass=ldapPublicKey)(uid=root))"
Feb 17 09:55:19 localhost slapd[16607]: conn=3 op=4 SRCH attr=sshPublicKey
Feb 17 09:55:19 localhost slapd[16607]: conn=3 op=4 SEARCH RESULT tag=101 err=0 nentries=0 text=
Feb 17 09:55:22 localhost slapd[16607]: conn=3 fd=11 closed
この操作を見てみると、ou=people,dc=example,dc=com
以下で
filter="(&(objectClass=posixAccount)
という検索が何度か行われているにもかかわらず、
(objectClass=ldapPublicKey)(uid=root))"err=0 nentries=0
となっています。
つまり、
試しにldapsearchコマンドを利用して同等のコマンドを実行しても、
% ldapsearch -x -b "ou=people,dc=example,dc=com" "(&(objectClass=posixAccount)(objectClass=ldapPublicKey)(uid=root))" sshPublicKey
以上のことから、
ou=people,dc=example,dc=com
の下に
"(&(objectClass=posixAccount)(objectClass=ldapPublicKey)
(uid=root))"
であるデータが登録されているか確認- さらに、
そのLDIF中にsshPublicKey属性が含まれ、 値が登録されているかを確認
エラーコード
いくつかのログからLDAP操作を見てきたわけですが、
たとえば、
Feb 17 10:03:42 localhost slapd[16607]: conn=5 fd=11 ACCEPT from IP=127.0.0.1:32806 (IP=0.0.0.0:389)
Feb 17 10:03:42 localhost slapd[16607]: conn=5 op=0 BIND dn="cn=Manager,dc=example,dc=com" method=128
Feb 17 10:03:42 localhost slapd[16607]: conn=5 op=0 BIND dn="cn=Manager,dc=example,dc=com" mech=SIMPLE ssf=0
Feb 17 10:03:42 localhost slapd[16607]: conn=5 op=0 RESULT tag=97 err=0 text=
Feb 17 10:03:42 localhost slapd[16607]: conn=5 op=1 ADD dn="ou=hoge,ou=fuga,ou=pubKey,dc=example,dc=com"
Feb 17 10:03:42 localhost slapd[16607]: conn=5 op=1 RESULT tag=105 err=32 text=
Feb 17 10:03:42 localhost slapd[16607]: conn=5 op=2 UNBIND
Feb 17 10:03:42 localhost slapd[16607]: conn=5 fd=11 closed
同様に、
Feb 17 10:03:50 localhost slapd[16607]: conn=8 fd=11 ACCEPT from IP=127.0.0.1:32809 (IP=0.0.0.0:389)
Feb 17 10:03:50 localhost slapd[16607]: conn=8 op=0 BIND dn="cn=Manager,dc=example,dc=com" method=128
Feb 17 10:03:50 localhost slapd[16607]: conn=8 op=0 BIND dn="cn=Manager,dc=example,dc=com" mech=SIMPLE ssf=0
Feb 17 10:03:50 localhost slapd[16607]: conn=8 op=0 RESULT tag=97 err=0 text=
Feb 17 10:03:51 localhost slapd[16607]: conn=8 op=1 ADD dn="cn=hogeuser,ou=Group,dc=example,dc=com"
Feb 17 10:03:51 localhost slapd[16607]: conn=8 op=1 RESULT tag=105 err=68 text=
Feb 17 10:03:51 localhost slapd[16607]: conn=8 op=2 UNBIND
Feb 17 10:03:51 localhost slapd[16607]: conn=8 fd=11 closed
パスワードが間違っておりうまくバインドできなかった場合はリスト12のようなログです。
Feb 17 10:07:52 localhost slapd[16607]: conn=9 fd=11 ACCEPT from IP=127.0.0.1:32810 (IP=0.0.0.0:389)
Feb 17 10:07:52 localhost slapd[16607]: conn=9 op=0 BIND dn="cn=Manager,dc=example,dc=com" method=128
Feb 17 10:07:52 localhost slapd[16607]: conn=9 op=0 RESULT tag=97 err=49 text=
Feb 17 10:07:52 localhost slapd[16607]: conn=9 fd=11 closed
これらの操作では、
LDAP_
LDAP_
であることがわかります。LDAPサーバを管理していると、
/*
* LDAP Result Codes
*/
#define LDAP_SUCCESS 0x00
#define LDAP_RANGE(n,x,y) (((x) <= (n)) && ((n) <= (y)))
#define LDAP_OPERATIONS_ERROR 0x01
#define LDAP_PROTOCOL_ERROR 0x02
#define LDAP_TIMELIMIT_EXCEEDED 0x03
#define LDAP_SIZELIMIT_EXCEEDED 0x04
#define LDAP_COMPARE_FALSE 0x05
#define LDAP_COMPARE_TRUE 0x06
#define LDAP_AUTH_METHOD_NOT_SUPPORTED 0x07
#define LDAP_STRONG_AUTH_NOT_SUPPORTED LDAP_AUTH_METHOD_NOT_SUPPORTED
#define LDAP_STRONG_AUTH_REQUIRED 0x08
#define LDAP_PARTIAL_RESULTS 0x09 /* LDAPv2+ (not LDAPv3) */
#define LDAP_REFERRAL 0x0a /* LDAPv3 */
#define LDAP_ADMINLIMIT_EXCEEDED 0x0b /* LDAPv3 */
#define LDAP_UNAVAILABLE_CRITICAL_EXTENSION 0x0c /* LDAPv3 */
#define LDAP_CONFIDENTIALITY_REQUIRED 0x0d /* LDAPv3 */
#define LDAP_SASL_BIND_IN_PROGRESS 0x0e /* LDAPv3 */
#define LDAP_ATTR_ERROR(n) LDAP_RANGE((n),0x10,0x15) /* 16-21 */
#define LDAP_NO_SUCH_ATTRIBUTE 0x10
#define LDAP_UNDEFINED_TYPE 0x11
#define LDAP_INAPPROPRIATE_MATCHING 0x12
#define LDAP_CONSTRAINT_VIOLATION 0x13
#define LDAP_TYPE_OR_VALUE_EXISTS 0x14
#define LDAP_INVALID_SYNTAX 0x15
#define LDAP_NAME_ERROR(n) LDAP_RANGE((n),0x20,0x24) /* 32-34,36 */
#define LDAP_NO_SUCH_OBJECT 0x20
#define LDAP_ALIAS_PROBLEM 0x21
#define LDAP_INVALID_DN_SYNTAX 0x22
#define LDAP_IS_LEAF 0x23 /* not LDAPv3 */
#define LDAP_ALIAS_DEREF_PROBLEM 0x24
#define LDAP_SECURITY_ERROR(n) LDAP_RANGE((n),0x2F,0x32) /* 47-50 */
#define LDAP_PROXY_AUTHZ_FAILURE 0x2F /* LDAPv3 proxy authorization */
#define LDAP_INAPPROPRIATE_AUTH 0x30
#define LDAP_INVALID_CREDENTIALS 0x31
#define LDAP_INSUFFICIENT_ACCESS 0x32
#define LDAP_SERVICE_ERROR(n) LDAP_RANGE((n),0x33,0x36) /* 51-54 */
#define LDAP_BUSY 0x33
#define LDAP_UNAVAILABLE 0x34
#define LDAP_UNWILLING_TO_PERFORM 0x35
#define LDAP_LOOP_DETECT 0x36
#define LDAP_UPDATE_ERROR(n) LDAP_RANGE((n),0x40,0x47) /* 64-69,71 */
#define LDAP_NAMING_VIOLATION 0x40
#define LDAP_OBJECT_CLASS_VIOLATION 0x41
#define LDAP_NOT_ALLOWED_ON_NONLEAF 0x42
#define LDAP_NOT_ALLOWED_ON_RDN 0x43
#define LDAP_ALREADY_EXISTS 0x44
#define LDAP_NO_OBJECT_CLASS_MODS 0x45
#define LDAP_RESULTS_TOO_LARGE 0x46 /* CLDAP */
#define LDAP_AFFECTS_MULTIPLE_DSAS 0x47 /* LDAPv3 */
#define LDAP_OTHER 0x50
まとめ
以上、tail -f
するような習慣を身につけたいものです。