技術部ネットワーク課の上曽山です。
先日、LDAPサーバの応答遅延が発生したため原因調査を行った結果をまとめました。

この応答遅延は大量にアクセスを受けた時に発生し、ローカルホストからのリクエストでも遅延するため、最初はリソース不足を疑いましたが、openldapの設定変更やサーバのメモリ増強等を行っても問題は解消しませんでした。
まさかアレが影響するとは思いもよらず...。

タイトルはラノベ風ですけど、作業内容はヘビーでした。

目次
サーバ環境
どんな通信が行われているか確認する
DNSの応答結果が関係するか？
プロセスの動きをトレースしてみる
処理をトレースして分かった事
6秒の遅延が発生する理由
TCP Wrapperの設定を確認する
TCP Wrapperの評価方法を確認する
LDAPとTCP Wrapper
まとめ

サーバ環境

	バージョン
OS	CentOS Linux release 7.8.2003
openldap	openldap-2.4.44-21.el7_6

どんな通信が行われているか確認する

そもそもLDAP検索時にどういう通信が行われているか正確に把握していなかったのでパケットキャプチャを行って確認しました。 f:id:kanimisoya:20210912200734p:plain これはLDAP検索のリクエストを受けるサーバ側のパケットキャプチャ結果です。
#黒塗りが多くていかがわしい感じになっておりますが、やましい点は一切ございません。

6～9行目でDNSの問い合わせが行われています。LDAP検索にDNSは関係ないはずだけど？？？

DNSの応答結果が関係するか？

論より証拠という訳で、DNSの応答結果を受け取れない状況にしてLDAP検索を行ってみました。
具体的には以下のようにiptablesでサーバ側にフィルタリングを行いました。

iptables -A INPUT -p tcp --sport 53 -j DROP
iptables -A INPUT -p udp --sport 53 -j DROP

フィルタリング後、LDAP検索を行ったところ毎回確実に6秒以上の遅延が発生するようになりました。
やはりDNSとLDAPの応答速度には何らかの関係がありそうです。

プロセスの動きをトレースしてみる

じゃあ、どこでDNSの問い合わせが発生しているのかstraceコマンドで処理内容を確認します。
※ログが多すぎるので必要な所だけ抜粋しています。IPアドレスはダミーです。

[pid  2109] 18:45:51 open("/etc/hosts.allow", O_RDONLY) = 30
[pid  2109] 18:45:51 open("/etc/hosts.allow_slapd", O_RDONLY = 31
[pid  2109] 18:45:51 stat("/etc/resolv.conf", {st_mode=S_IFREG|0644, st_size=120, ...}) = 0
[pid  2109] 18:45:51 connect(32, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("192.168.0.1")}, 16) = 0
[pid  2109] 18:45:51 sendto(32, "\325.\1\0\0\1\0\0\0\0\0\0\002100\0030\003168\003192\7in-a"..., 45, MSG_NOSIGNAL, NULL, 0) = 45
[pid  2109] 18:45:51 poll([{fd=32, events=POLLIN}], 1, 1000) = 0 (Timeout)
[pid  2109] 18:45:52 connect(33, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("192.168.0.2")}, 16) = 0
[pid  2109] 18:45:52 sendto(33, "\325.\1\0\0\1\0\0\0\0\0\0\002100\0030\003168\003192\7in-a"..., 45, MSG_NOSIGNAL, NULL, 0) = 45
[pid  2109] 18:45:52 poll([{fd=33, events=POLLIN}], 1, 1000) = 0 (Timeout)
[pid  2109] 18:45:53 connect(35, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("192.168.0.3")}, 16) = 0
[pid  2109] 18:45:53 sendto(35, "\325.\1\0\0\1\0\0\0\0\0\0\002100\0030\003168\003192\7in-a"..., 45, MSG_NOSIGNAL, NULL, 0) = 45
[pid  2109] 18:45:53 poll([{fd=35, events=POLLIN}], 1, 1000) = 0 (Timeout)
[pid  2109] 18:45:54 sendto(32, "\325.\1\0\0\1\0\0\0\0\0\0\002100\0030\003168\003192\7in-a"..., 45, MSG_NOSIGNAL, NULL, 0) = 45
[pid  2109] 18:45:54 poll([{fd=32, events=POLLIN}], 1, 1000) = 0 (Timeout)
[pid  2109] 18:45:55 sendto(33, "\325.\1\0\0\1\0\0\0\0\0\0\002100\0030\003168\003192\7in-a"..., 45, MSG_NOSIGNAL, NULL, 0) = 45
[pid  2109] 18:45:55 poll([{fd=33, events=POLLIN}], 1, 1000) = 0 (Timeout)
[pid  2109] 18:45:56 sendto(35, "\325.\1\0\0\1\0\0\0\0\0\0\002100\0030\003168\003192\7in-a"..., 45, MSG_NOSIGNAL, NULL, 0) = 45
[pid  2109] 18:45:56 poll([{fd=35, events=POLLIN}], 1, 1000) = 0 (Timeout)
[pid  2109] 18:45:57 close(32)          = 0
[pid  2109] 18:45:57 close(33)          = 0
[pid  2109] 18:45:57 close(35)          = 0

言い忘れていましたが、これはセッション開始から実際にLDAP検索が始まるまでに行われている処理です。

この結果から、LDAP検索に時間がかかっているのではなく、検索が始まるまでに時間がかかっている事が分かりました。

処理をトレースして分かった事

TCP Wrapperが関係していそう。(open("/etc/hosts.allow"...の部分)
DNS問い合わせ毎に応答待ちで1秒経過している。(poll..(Timeout)の部分)
DNS問い合わせの回数はOSの設定に依存している。(stat("/etc/resolv.conf"...の部分)

6秒の遅延が発生する理由

LDAPの応答遅延に直接関係ない部分なので先に説明します。
/etc/resolv.confが以下のように設定されていました。

nameserver 192.168.0.1
nameserver 192.168.0.2
nameserver 192.168.0.3
options timeout:1

6秒の遅延が発生するのは、正引き・逆引きの名前解決でレスポンスが無いため、ネームサーバ3台分リトライを行い、それぞれ1秒のタイムアウトが発生していたのが原因でした。

TCP Wrapperの設定を確認する

それでは本題に戻ります。
まず/etc/hosts.allowの内容

ALL: 127.0.0.1
slapd: /etc/hosts.allow_slapd

LDAPのアクセス許可は/etc/hosts.allow_slapdを参照するようになっています。
続いて/etc/hosts.allow_slapdの内容(IPアドレス、ホスト名はダミーです)

192.168.100.1 　　# server1
192.168.100.2 　　# server2
192.168.101.10　　# client1
192.168.102.20　　# client2

アクセス許可するIPアドレスの後ろに、アクセス元が分かるようホスト名をコメントとしてつけてあります。
この書き方に問題があるのか確認するため、3パターンのリストを作ってテストしました。
テストはDNSレスポンスを受け取れず遅延が発生する状態で行っています。

パターン1：IPアドレスのみのリスト

192.168.100.1
192.168.100.2
192.168.101.10
192.168.102.20

この設定で4台のホストからLDAP検索を行った結果。

IPアドレス	ホスト名	遅延の有無	LDAP検索可否
192.168.100.1	server1	なし	可
192.168.100.2	server2	なし	可
192.168.101.10	client1	なし	可
192.168.102.20	client2	なし	可

パターン2：ホスト名のみのリスト

server1
server2
client1
client2

この設定で4台のホストからLDAP検索を行った結果。

IPアドレス	ホスト名	遅延の有無	LDAP検索可否
192.168.100.1	server1	あり	不可
192.168.100.2	server2	あり	不可
192.168.101.10	client1	あり	不可
192.168.102.20	client2	あり	不可

パターン3：IPアドレス/ホスト名混在のリスト

192.168.100.1 　　# server1
192.168.100.2 　　# server2
192.168.101.10　　# client1
192.168.102.20　　# client2

この設定で4台のホストからLDAP検索を行った結果。

IPアドレス	ホスト名	遅延の有無	LDAP検索可否
192.168.100.1	server1	なし	可
192.168.100.2	server2	あり	可
192.168.101.10	client1	あり	可
192.168.102.20	client2	あり	可

IPアドレス/ホスト名混在のリストを使った時、奇妙な事が起こりました。
最初のホストのみ遅延が発生しなかったのです。

TCP Wrapperの評価方法を確認する

TCP Wrapperのアクセス許可は、左→右、上→下と評価していくので、リストを評価順に並べ直すとこうなります。

192.168.100.1
#
server1
　　：
　　略
　　：
192.168.102.20
#
client2

TCP WrapperはソースIPアドレスを使って照合を行うため、1行目の「192.168.100.1」はそのまま評価されます。

2行目は「#」です。これではIPアドレスと照合出来ないので、ソースIPアドレスを使って逆引きのDNS問い合わせを行いアクセス元のホスト名を求めます。
この時、求めたホスト名で改めて正引きで問い合わせ、ホスト名が偽装されていないか確認が行われます。

DNS問い合わせはソースIPアドレスで行うため、設定内に何個ホスト名が書いてあっても1度しか行いません。
また、マッチするIPアドレスが書いてあれば、DNS問い合わせが失敗していてもアクセス許可判定には影響しません。

つまり、IPアドレス/ホスト名混在のリストを使うと以下のように処理が行われる、という事になります。

192.168.100.1からアクセス

　ソースIPアドレスが1つ目のレコードとマッチ
　→アクセスを許可

192.168.100.2からアクセス

　ソースIPアドレスが1つ目のレコードでマッチしない
　→2つ目のレコードが文字列なのでDNS問い合わせを行う
　　→DNSのレスポンスが無いため遅延(タイムアウト待ち)
　　　→ソースIPアドレスが4つ目のレコードとマッチ
　　　　→アクセスを許可

※残り2台のホストも同様の流れで判定が行われる。

結論
~~余計なコメントは書くな~~
TCP Wrapperの判定にホスト名(もしくは何らかの文字列)を使うとDNS問い合わせが発生する。

LDAPとTCP Wrapper

さて、冒頭で「ローカルホストからのリクエストでも遅延する」点に触れました。
そして、ローカルホスト(127.0.0.1)からのアクセスはすべて許可されています。

TCP Wrapperの処理中に遅延が発生するのは分かりましたが、LDAPはマルチスレッドで動いているんだから、別のスレッドで受けたリクエストは普通にレスポンスを返せるのではないか？
アクセス許可判定時にDNS問い合わせを行わないローカルホストからのLDAP検索まで遅延するのはおかしいじゃないか!!

と、ぼやいていたら部長がソースを確認してくれました。 https://github.com/openldap/openldap/blob/OPENLDAP_REL_ENG_2_4_44/servers/slapd/daemon.c#L2040-L2060

  2040  #ifdef HAVE_TCPD
  2041                  {
  2042                          int rc;
  2043                          ldap_pvt_thread_mutex_lock( &sd_tcpd_mutex );
  2044                          rc = hosts_ctl("slapd",
  2045                                  dnsname != NULL ? dnsname : SLAP_STRING_UNKNOWN,
  2046                                  peeraddr,
  2047                                  SLAP_STRING_UNKNOWN );
  2048                          ldap_pvt_thread_mutex_unlock( &sd_tcpd_mutex );
  2049                          if ( !rc ) {
  2050                                  /* DENY ACCESS */
  2051                                  Statslog( LDAP_DEBUG_STATS,
  2052                                          "fd=%ld DENIED from %s (%s)\n",
  2053                                          (long) sfd,
  2054                                          dnsname != NULL ? dnsname : SLAP_STRING_UNKNOWN,
  2055                                          peeraddr, 0, 0 );
  2056                                  slapd_close(sfd);
  2057                                  return 0;
  2058                          }
  2059                  }
  2060  #endif /* HAVE_TCPD */

TCPD(TCP Wrapper)を使用する際はmutexロックがかかり、他のスレッドからはアクセス出来なくなります。
リクエストの受付や検索処理は並列で行えるのに、アクセス許可判定だけは受付順に1つずつ処理されるようでした。

まとめ

TCP Wrapperの設定に文字列が含まれているとDNS問い合わせが発生する。
LDAPはTCP Wrapperのアクセス許可判定を排他的に制御している。
よって、DNSの応答遅延が発生すると以降のLDAP検索がすべて遅延する。

結局、TCP Wrapperの設定方法に問題があり、DNSの応答が遅延するとLDAPの応答も遅延するという状態でした。
現在は設定ファイルにIPアドレスのみを記載し、LDAP検索時にDNS問い合わせが発生しないようにしてあります。
現在のところ、遅延を感じることなくLDAPが稼働してい(るように見え)ます。

理由はシンプルなのに、そこに辿り着くまでに苦労した、そんな茶飯事でした。
別口でDNSの応答遅延を解消するためにロードバランサをアレコレしたりしたんですけど、それはまた別のお話ということで。