第9回　LDAPとログ

毎回テーマがコロコロと変わる本連載ですが、今回はOpenLDAPを運用する上で必須となるログの知識についてお話しします。トラブルシューティング時にログと格闘するのは管理者の必要最低限の行動です……よね。

OpenLDAPとログの設定

OpenLDAPのログはsyslogを経由して出力されます。ログの設定はいつものslapd.conf中のloglevelというパラメータで設定します。

リスト1　/etc/openldap/slapd.conf（一部）

loglevel 32

loglevelで指定可能な値は表1のように定義されています。

表1　loglevelの値とログの収集データの関係

値	ログ収集データ
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/operations/results
512	stats log entries sent
1024	print communication with shell backends
2048	entry parsing

以上のいずれかを設定することにより、slapdからsyslogデーモンにログが送出されるのですが、当然のことながらsyslogデーモン側でも適切に設定を行っておく必要があります。slapdからのログはlocal4というファシリティで出力されるため、/etc/syslog.confにリスト2のような設定を追記し、syslogdを再起動しておいてください。

リスト2　/etc/syslog.confに追加する設定

local4.*   /var/log/ldap.log

図1　syslogdの再起動

/etc/init.d/syslog restart

syslog-ngなどのその他のsyslogデーモンを使用している場合にも、local4というファシリティのログを適切に出力できるよう設定を行ってデーモンを再起動しておく必要があります。

ログの出力例

syslogデーモンの設定を適切に行った場合、loglevelの値を変更しつつldapaddやldapsearchコマンドを実行すると、リスト3～7のようなログが出力されます。

リスト3　loglevel 512の場合

Feb 16 21:11:01 localhost slapd[4002]: conn=2 op=1 ENTRY dn="cn=suzuki,ou=People,dc=example,dc=com"

リスト4　loglevel 256の場合

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

リスト5　loglevel 128の場合

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

リスト6　loglevel 64の場合

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)

リスト7　loglevel 32の場合

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

これらのサンプルからわかるように、loglevelは適切に設定しておく必要があります。さもなければ、トラブルが起きても全くログが吐かれていなかった、ということにもなりかねません。基本的にはloglevel 256などを設定しておくのが良いでしょう。

ログを読む

HTTPの世界で、正常にページ表示できれば200、ファイルが存在しなければ404といったステータスコードが返るのと同様、LDAPでも各種コードや操作識別のための手段が用意されています。たとえば、エントリ追加時のログを見てみましょう（リスト8⁠）⁠。すべての操作はログからわかるようになっています。

リスト8　ldapadd時のログ

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

まずこれらのログで一致しているのは、conn=0となっている部分です。つまり、これらのオペレーションは複数のTCP接続ではなく、1度のTCP接続（ldap_open）で行われたことを意味しています。たとえば、もしldapaddコマンドを発行した後にldapsearchコマンドを実行した場合、それらは別々のプロセス、つまり接続として取り扱われますので、ログ中にはconn=0とconn=1が記録されることとなります。

次に着目すべきはop（オペレーション）です。このログが意味するところは、文字通り接続時の操作ですので、1回のLDAP接続で3回のオペレーションが行われた、ということになります。op=0はバインドに関する部分であり、op=1はエントリの追加、op=2はアンバインドです。

以上の点を整理してみると、リスト8のログから、実際にはサーバ上で次のような操作が行われたことがわかります。

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で管理する方法を紹介しました。これを例として、「⁠OpenSSHの設定を正しく行ったつもりだが、うまく公開鍵認証ができない」という問題のトラブルシューティングを行ってみます。

まずはもっとも基本的な方法として、たとえばLDAPサーバに全くログが出力されないとします。この場合、バインドDNや検索フィルタの設定以前に、正しいサーバが指定されていなかったり、そもそもパッチがうまく当たっていないことが考えられます。LDAPサーバの389/tcpに接続が1度でも行われれば、必ずACCEPTというログが出力されるためです。

ではログの分析に入りたいと思います。

リスト9　問題のログ

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))"という検索が何度か行われているにもかかわらず、サーチ後のRESULTが err=0 nentries=0となっています。

つまり、検索自体は成功したけれどもエントリが1つも返ってこなかったことを意味しています。エントリが1件も見つからない、つまりLDAPサーバ上に公開鍵が見つからないのですから、公開鍵認証ができないことは明白です。

試しにldapsearchコマンドを利用して同等のコマンドを実行しても、当然のことながらエントリは返ってきません。

図2　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操作を見てきたわけですが、エラーコードが0でない場合、つまりldapsearchコマンドやldapaddコマンドが失敗した場合のトラブルシューティングはどのように行えば良いのでしょうか？

たとえば、親エントリがない場合にldapaddした際のログは、リスト10のようになります。

リスト10

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

同様に、すでにDNが存在する場合にそれを上書きしようとするとリスト11のようなログになります。

リスト11

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のようなログです。

リスト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

これらの操作では、エラーコードがそれぞれ32、68、49と出力されているため、追加操作に失敗したことを意味しています。また、エラーコードについては/usr/include/ldap.h（リスト13）に定義されています。これらのコードは16進数で定義されています。10進数で表される32、68、31というコードは16進ではそれぞれ0x20、0x44、0x31であるため、原因は
LDAP_NO_SUCH_OBJECT、LDAP_ALREADY_EXISTS、
LDAP_INVALID_CREDENTIALS
であることがわかります。LDAPサーバを管理していると、エラーコード49や68はよく目にしますので、そのうち皆さんも自然と数字の意味を覚えられるようになると思います（笑⁠）⁠。

リスト13　ldap.hで定義されているエラーコードの一部

/* 
 * 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

まとめ

以上、非常に簡単でしたがOpenLDAPのログの読み方について簡単に紹介してきました。LDAPに限った話ではありませんが、困ったときにはすぐにログファイルをtail -fするような習慣を身につけたいものです。