DSAS開発者の部屋:Unbound のリトライ処理を追跡してみました

ことの発端

とある案件で AWS を利用した構成の運用を任されていたのですが、アプリケーションのエラーログには以下のような記録が残っており、何らかの理由で RDS で運用している DB サーバの名前解決に失敗し接続できない問題が発生していました。

...
  File "/opt/klab/home/hoge/contents/python/lib/python/site-packages/pymysql/connections.py", line 688, in __init__
    self.connect ()
  File "/opt/klab/home/hoge/contents/python/lib/python/site-packages/pymysql/connections.py", line 937, in connect
    raise exc
sqlalchemy.exc.OperationalError: (pymysql.err.OperationalError) (2003, "Can't connect to MySQL server on 'db001.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com' ([Errno -2] Name or service not known)")

ここで名前解決のフローに注目してみます。

運用していたシステムでは名前解決にローカルの Unbound を利用していました。ホストが他のホストに接続する際にはすべてローカルの Unbound を経由して名前解決がなされます。

アプリケーションが動作しているサーバでも同様に名前解決を行い、複数の DB サーバに対して接続を行っています。 DB サーバは RDS を利用して運用しているため、 Unbound での名前解決の問合せ先は 10.0.0.2 を指定していました。アプリケーションのログからは何らかの理由で Unbound からクライアントに対して SERVFAIL が返されていて、名前解決を諦めていることが分かります。 RDS のホストのレコードの TTL は 5 秒になっていてレコードのキャッシュが切れるたびに 10.0.0.2 に問い合わせるのですが、どうやらその問合せの際に問題が発生していて、 Unbound が SERVFAIL を返すようです。

ということで以降では本題である Unbound を掘り下げていきます。

詳細の追跡

まずは Unbound のログを追っていきます。

名前解決に失敗する以上、名前解決のフローをログに出力するように設定します。

"Unbound documentation" https://www.unbound.net/documentation/unbound.conf.html

    verbosity: 2

Unbound では unbound.conf の verbosity の項目を 2 に設定し、 debug レベル以上のログが出力されるようにすると、以下のように SERVFAIL を返すまでの名前解決のフローが表示されるようになります。

Dec 14 01:20:56 unbound[8826:0] debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new
Dec 14 01:20:56 unbound[8826:0] info: resolving db001.xxxxxxxxxxxx.xxxxxxxx.rds.amazonaws.com. A IN
Dec 14 01:20:56 unbound[8826:0] info: processQueryTargets: db001.xxxxxxxxxxxx.xxxxxxxx.rds.amazonaws.com. A IN
Dec 14 01:20:56 unbound[8826:0] info: sending query: db001.xxxxxxxxxxxx.xxxxxxxx.rds.amazonaws.com. A IN
Dec 14 01:20:56 unbound[8826:0] debug: sending to target: <.> 10.0.0.2#53
Dec 14 01:20:56 unbound[8826:0] debug: cache memory msg=17590 rrset=18512 infra=1009 val=0
Dec 14 01:20:56 unbound[8826:0] debug: iterator[module 0] operate: extstate:module_wait_reply event:module_event_noreply
Dec 14 01:20:56 unbound[8826:0] info: iterator operate: query db001.xxxxxxxxxxxx.xxxxxxxx.rds.amazonaws.com. A IN
Dec 14 01:20:56 unbound[8826:0] info: processQueryTargets: db001.xxxxxxxxxxxx.xxxxxxxx.rds.amazonaws.com. A IN
Dec 14 01:20:56 unbound[8826:0] info: sending query: db001.xxxxxxxxxxxx.xxxxxxxx.rds.amazonaws.com. A IN
Dec 14 01:20:56 unbound[8826:0] debug: sending to target: <.> 10.0.0.2#53
Dec 14 01:20:56 unbound[8826:0] debug: cache memory msg=17590 rrset=18512 infra=1009 val=0
Dec 14 01:20:57 unbound[8826:0] debug: iterator[module 0] operate: extstate:module_wait_reply event:module_event_noreply
Dec 14 01:20:57 unbound[8826:0] info: iterator operate: query db001.xxxxxxxxxxxx.xxxxxxxx.rds.amazonaws.com. A IN
Dec 14 01:20:57 unbound[8826:0] info: processQueryTargets: db001.xxxxxxxxxxxx.xxxxxxxx.rds.amazonaws.com. A IN
Dec 14 01:20:57 unbound[8826:0] info: sending query: db001.xxxxxxxxxxxx.xxxxxxxx.rds.amazonaws.com. A IN
Dec 14 01:20:57 unbound[8826:0] debug: sending to target: <.> 10.0.0.2#53
Dec 14 01:20:57 unbound[8826:0] debug: cache memory msg=17590 rrset=18512 infra=1009 val=0
Dec 14 01:21:00 unbound[8826:0] debug: iterator[module 0] operate: extstate:module_wait_reply event:module_event_noreply
Dec 14 01:21:00 unbound[8826:0] info: iterator operate: query db001.xxxxxxxxxxxx.xxxxxxxx.rds.amazonaws.com. A IN
Dec 14 01:21:00 unbound[8826:0] info: processQueryTargets: db001.xxxxxxxxxxxx.xxxxxxxx.rds.amazonaws.com. A IN
Dec 14 01:21:00 unbound[8826:0] info: sending query: db001.xxxxxxxxxxxx.xxxxxxxx.rds.amazonaws.com. A IN
Dec 14 01:21:00 unbound[8826:0] debug: sending to target: <.> 10.0.0.2#53
Dec 14 01:21:00 unbound[8826:0] debug: cache memory msg=17590 rrset=18512 infra=1009 val=0
Dec 14 01:21:05 unbound[8826:0] debug: iterator[module 0] operate: extstate:module_wait_reply event:module_event_noreply
Dec 14 01:21:05 unbound[8826:0] info: iterator operate: query db001.xxxxxxxxxxxx.xxxxxxxx.rds.amazonaws.com. A IN
Dec 14 01:21:05 unbound[8826:0] info: processQueryTargets: db001.xxxxxxxxxxxx.xxxxxxxx.rds.amazonaws.com. A IN
Dec 14 01:21:05 unbound[8826:0] info: sending query: db001.xxxxxxxxxxxx.xxxxxxxx.rds.amazonaws.com. A IN
Dec 14 01:21:05 unbound[8826:0] debug: sending to target: <.> 10.0.0.2#53
Dec 14 01:21:05 unbound[8826:0] debug: cache memory msg=17590 rrset=18512 infra=1009 val=0
Dec 14 01:21:14 unbound[8826:0] debug: iterator[module 0] operate: extstate:module_wait_reply event:module_event_noreply
Dec 14 01:21:14 unbound[8826:0] info: iterator operate: query db001.xxxxxxxxxxxx.xxxxxxxx.rds.amazonaws.com. A IN
Dec 14 01:21:14 unbound[8826:0] info: processQueryTargets: db001.xxxxxxxxxxxx.xxxxxxxx.rds.amazonaws.com. A IN
Dec 14 01:21:14 unbound[8826:0] debug: configured forward servers failed -- returning SERVFAIL
Dec 14 01:21:14 unbound[8826:0] debug: return error response SERVFAIL
Dec 14 01:21:14 unbound[8826:0] debug: cache memory msg=17590 rrset=18512 infra=1009 val=0

このとき tcpdump でパケットをダンプしてみると、この Unbound は 10 回、 10.0.0.2 に問い合わせているように見えるのですが、 Unbound Timeout Info によると 5 回タイムアウトすると SERVFAIL を返すそうです。

"Unbound Timeout Info" https://www.unbound.net/documentation/info_timeout.html

Queries that failed to attain probe status, or if the server is blocked due to timeouts, get a reply with the SERVFAIL error. Also, if the available IP addresses for a domain have been probed for 5 times by a query it is also replied with SERVFAIL. New queries must come in to continue the probing.

Unbound は 1 回の問合せで応答が得られなかった場合、再送処理としてもう一度パケットを送信していて、この 2 回の問合せを 1 回のトライとして、 5 回のトライで応答が得られなかった場合に SERVFAIL を返すようです。これ以上ログの出力レベルを上げることで各問合せの詳細をさらに出力することもできるのですが、大変に冗長になってしまいログが膨大なサイズになり流れてしまう可能性があります。そのため、細かい単位での問合せの詳細を追うには tcpdump を使いパケットをダンプしたほうがよさそうです。

というわけで、ここに肝心のエラーが発生したときの tcpdump 結果があるので見ていきます。

0000-00-00 01:23:53.723674 IP (tos 0x0, ttl 64, id 6363, offset 0, flags [none], proto UDP (17), length 119)
    10.0.0.2.53 > 10.0.2.241.58995: [udp sum ok] 28426 q: A? db011.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. 1/0/1 db011.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. [5s] A 10.0.7.56 ar: . OPT UDPsize=4096 OK (91)
0000-00-00 01:23:59.008910 IP (tos 0x0, ttl 64, id 65362, offset 0, flags [none], proto UDP (17), length 103)
    10.0.2.241.61649 > 10.0.0.2.53: [bad udp cksum 0x1757 -> 0xf0ae!] 45680+% [1au] A? db001.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. ar: . OPT UDPsize=1480 OK (75)
0000-00-00 01:23:59.011944 IP (tos 0x0, ttl 64, id 6364, offset 0, flags [none], proto UDP (17), length 119)
    10.0.0.2.53 > 10.0.2.241.61649: [udp sum ok] 45680 q: A? db001.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. 1/0/1 db001.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. [5s] A 10.0.7.231 ar: . OPT UDPsize=4096 OK (91)
0000-00-00 01:23:59.019073 IP (tos 0x0, ttl 64, id 65363, offset 0, flags [none], proto UDP (17), length 103)
    10.0.2.241.41853 > 10.0.0.2.53: [bad udp cksum 0x1757 -> 0xcc92!] 8929+% [1au] A? db011.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. ar: . OPT UDPsize=1480 OK (75)
0000-00-00 01:23:59.069337 IP (tos 0x0, ttl 64, id 65365, offset 0, flags [none], proto UDP (17), length 103)
    10.0.2.241.56077 > 10.0.0.2.53: [bad udp cksum 0x1757 -> 0x900f!] 12244+% [1au] A? db011.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. ar: . OPT UDPsize=1472 OK (75)
0000-00-00 01:23:59.119624 IP (tos 0x0, ttl 64, id 65367, offset 0, flags [none], proto UDP (17), length 103)
    10.0.2.241.9116 > 10.0.0.2.53: [bad udp cksum 0x1757 -> 0xd633!] 39201+% [1au] A? db011.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. ar: . OPT UDPsize=1480 OK (75)
0000-00-00 01:23:59.177145 IP (tos 0x0, ttl 64, id 65369, offset 0, flags [none], proto UDP (17), length 103)
    10.0.2.241.53906 > 10.0.0.2.53: [bad udp cksum 0x1757 -> 0x9062!] 12028+% [1au] A? db021.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. ar: . OPT UDPsize=1480 OK (75)
0000-00-00 01:23:59.180150 IP (tos 0x0, ttl 64, id 6365, offset 0, flags [none], proto UDP (17), length 119)
    10.0.0.2.53 > 10.0.2.241.53906: [udp sum ok] 12028 q: A? db021.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. 1/0/1 db021.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. [5s] A 10.0.7.47 ar: . OPT UDPsize=4096 OK (91)
0000-00-00 01:23:59.219905 IP (tos 0x0, ttl 64, id 65380, offset 0, flags [none], proto UDP (17), length 103)
    10.0.2.241.64595 > 10.0.0.2.53: [bad udp cksum 0x1757 -> 0x4a5a!] 21571+% [1au] A? db011.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. ar: . OPT UDPsize=1472 OK (75)
0000-00-00 01:23:59.270182 IP (tos 0x0, ttl 64, id 65386, offset 0, flags [none], proto UDP (17), length 103)
    10.0.2.241.61783 > 10.0.0.2.53: [bad udp cksum 0x1757 -> 0x0725!] 39540+% [1au] A? db011.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. ar: . OPT UDPsize=1480 OK (75)
0000-00-00 01:23:59.370381 IP (tos 0x0, ttl 64, id 65391, offset 0, flags [none], proto UDP (17), length 103)
    10.0.2.241.7110 > 10.0.0.2.53: [bad udp cksum 0x1757 -> 0x2a07!] 21796+% [1au] A? db011.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. ar: . OPT UDPsize=1472 OK (75)
0000-00-00 01:23:59.470732 IP (tos 0x0, ttl 64, id 65412, offset 0, flags [none], proto UDP (17), length 103)
    10.0.2.241.48543 > 10.0.0.2.53: [bad udp cksum 0x1757 -> 0x2824!] 44333+% [1au] A? db011.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. ar: . OPT UDPsize=1480 OK (75)
0000-00-00 01:23:59.671118 IP (tos 0x0, ttl 64, id 65441, offset 0, flags [none], proto UDP (17), length 103)
    10.0.2.241.16698 > 10.0.0.2.53: [bad udp cksum 0x1757 -> 0x501a!] 2461+% [1au] A? db011.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. ar: . OPT UDPsize=1472 OK (75)
0000-00-00 01:23:59.871559 IP (tos 0x0, ttl 64, id 65490, offset 0, flags [none], proto UDP (17), length 103)
    10.0.2.241.41675 > 10.0.0.2.53: [bad udp cksum 0x1757 -> 0x1644!] 55777+% [1au] A? db011.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. ar: . OPT UDPsize=1480 OK (75)
0000-00-00 01:24:00.271760 IP (tos 0x0, ttl 64, id 53, offset 0, flags [none], proto UDP (17), length 103)
    10.0.2.241.52486 > 10.0.0.2.53: [bad udp cksum 0x1757 -> 0x9c38!] 12722+% [1au] A? db011.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. ar: . OPT UDPsize=1472 OK (75)
0000-00-00 01:24:01.021605 IP (tos 0x0, ttl 64, id 6366, offset 0, flags [none], proto UDP (17), length 119)
    10.0.0.2.53 > 10.0.2.241.56077: [udp sum ok] 12244 q: A? db011.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. 1/0/1 db011.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. [5s] A 10.0.7.56 ar: . OPT UDPsize=4096 OK (91)
0000-00-00 01:24:01.021665 IP (tos 0x0, ttl 64, id 6367, offset 0, flags [none], proto UDP (17), length 119)
    10.0.0.2.53 > 10.0.2.241.9116: [udp sum ok] 39201 q: A? db011.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. 1/0/1 db011.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. [5s] A 10.0.7.56 ar: . OPT UDPsize=4096 OK (91)
0000-00-00 01:24:01.021679 IP (tos 0x0, ttl 64, id 6368, offset 0, flags [none], proto UDP (17), length 119)
    10.0.0.2.53 > 10.0.2.241.61783: [udp sum ok] 39540 q: A? db011.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. 1/0/1 db011.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. [5s] A 10.0.7.56 ar: . OPT UDPsize=4096 OK (91)
0000-00-00 01:24:01.021703 IP (tos 0x0, ttl 64, id 6369, offset 0, flags [none], proto UDP (17), length 119)
    10.0.0.2.53 > 10.0.2.241.64595: [udp sum ok] 21571 q: A? db011.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. 1/0/1 db011.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. [5s] A 10.0.7.56 ar: . OPT UDPsize=4096 OK (91)
0000-00-00 01:24:01.021723 IP (tos 0x0, ttl 64, id 6370, offset 0, flags [none], proto UDP (17), length 119)
    10.0.0.2.53 > 10.0.2.241.7110: [udp sum ok] 21796 q: A? db011.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. 1/0/1 db011.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. [5s] A 10.0.7.56 ar: . OPT UDPsize=4096 OK (91)

4 行目から db011.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. のレコードに対する問合せが始まっています。以降の行ではすぐに応答結果が得られず、問い合わせの再送処理が始まっていることが分かります。

そして 3 回目の問合せ (Unbound 的には 2 回目の問合せの 1 回目の問合せ) の後に他のレコード db021.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. への問い合わせがあります。しかし、直後にこの問合せの結果はすぐに得ることができています。その後も db011.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. の応答は返されることがなく、 Unbound からパケットが 10 回に渡って送信され、 Unbound が Timeout してから応答が返ってきています。どうやら、問合せ先の 10.0.0.2 が特定のレコードの問合せに対して、応答が遅れることが原因としてあるようです。

Unbound の最初の問合せから最後の問合せの間隔を見ていきましょう。

1 回目の問合せ (01:23:59.019073)
2 回目の問合せ (01:23:59.069337) + 50 ms
3 回目の問合せ (01:23:59.119624) + 50 ms
4 回目の問合せ (01:23:59.219905) + 100 ms
5 回目の問合せ (01:23:59.270182) + 50 ms
6 回目の問合せ (01:23:59.370381) + 100 ms
7 回目の問合せ (01:23:59.470732) + 100 ms
8 回目の問合せ (01:23:59.671118) + 200 ms
9 回目の問合せ (01:23:59.871559) + 200 ms
10 回目の問合せ (01:24:00.271760) + 400 ms

一定の間隔を空けて、リトライ処理や再送処理が行われているように見えますが、他のレコードに対する問合せが走行したタイミング (3 回目と 4 回目の問合せ間) で問合せの間隔がリセットされているように見えます。

リトライ処理中に他のレコードに対する問合せがない Unbound の処理について再送間隔を見てみましょう (tcpdump の結果は省略します) 。

1 回目の問合せ (09:48:53.980913)
2 回目の問合せ (09:48:54.031078) + 50ms
3 回目の問合せ (09:48:54.081281) + 50ms
4 回目の問合せ (09:48:54.181447) + 100ms
5 回目の問合せ (09:48:54.281630) + 100ms
6 回目の問合せ (09:48:54.481851) + 200ms
7 回目の問合せ (09:48:54.682216) + 200ms
8 回目の問合せ (09:48:55.082701) + 400ms
9 回目の問合せ (09:48:55.483326) + 400ms
10 回目の問合せ (09:48:56.284297) + 800ms

初めは 50ms だった再送間隔がリトライ処理を重ねるにつれ、倍になっているのが分かります。

どうやら、問合せの走行中に他のレコードに対する問合せを同じ DNS サーバに対して行い、応答を受け取ることができると、再送間隔がリセットされている可能性がありそうです。

本当にそういった状況で今回の現象が発生するのか、再現環境を構築して見ていきます。

再現 & 検証

再現環境を用意するためには、特定のレコードに対する問合せが応答を返さずタイムアウトする環境を用意する必要がありそうです。要件としては特定のクエリの応答を受け取らなければよいだけなので、今回は Netfilter の string モジュールを使い、応答結果のパケットを DROP することで検証を行いました。

以下に検証の手順を残しておきます。

# SRTT を計算する
for i in $(seq 10 200); do dig @127.0.0.1 +tries=1 +retries=1 db001.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com; dig @127.0.0.1 +tries=1 +retries=1 db011.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com; sleep 5s; done

iptables -A INPUT -i eth0 -p udp -s 10.0.0.2/32 -m string --string 'db001' --algo bm --sport 53 -j DROP
tcpdump -tttt -vv -n host 10.0.0.2
time dig +time=20 +tries=1 +retries=1 db001.xxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com& sleep 0.25s; time dig +time=20 +tries=1 +retries=1 db011.xxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com

同様に tcpdump でパケットキャプチャを行ったのですが、結果は以下のようになりました (db001.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. の応答は省略しています) 。

2016-12-14 05:51:10.578120 IP (tos 0x0, ttl 64, id 13830, offset 0, flags [none], proto UDP (17), length 103)
    10.0.65.4.18425 > 10.0.0.2.53: [bad udp cksum 0x556a -> 0xd18f!] 46972+ [1au] A? db001.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. ar: . OPT UDPsize=1480 OK (75)
2016-12-14 05:51:10.703403 IP (tos 0x0, ttl 64, id 13858, offset 0, flags [none], proto UDP (17), length 103)
    10.0.65.4.20472 > 10.0.0.2.53: [bad udp cksum 0x556a -> 0x2b20!] 24045+ [1au] A? db001.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. ar: . OPT UDPsize=1472 OK (75)
2016-12-14 05:51:10.828773 IP (tos 0x0, ttl 64, id 13882, offset 0, flags [none], proto UDP (17), length 103)
    10.0.65.4.57086 > 10.0.0.2.53: [bad udp cksum 0x556a -> 0xfdc3!] 62530+ [1au] A? db001.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. ar: . OPT UDPsize=1480 OK (75)
2016-12-14 05:51:11.078512 IP (tos 0x0, ttl 64, id 13911, offset 0, flags [none], proto UDP (17), length 103)
    10.0.65.4.48558 > 10.0.0.2.53: [bad udp cksum 0x556a -> 0x0215!] 4162+ [1au] A? db011.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. ar: . OPT UDPsize=1480 OK (75)
2016-12-14 05:51:11.078934 IP (tos 0x0, ttl 64, id 13912, offset 0, flags [none], proto UDP (17), length 103)
    10.0.65.4.29401 > 10.0.0.2.53: [bad udp cksum 0x556a -> 0xaeaa!] 46977+ [1au] A? db001.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. ar: . OPT UDPsize=1472 OK (75)
2016-12-14 05:51:11.155562 IP (tos 0x0, ttl 64, id 63125, offset 0, flags [none], proto UDP (17), length 119)
    10.0.0.2.53 > 10.0.65.4.48558: [udp sum ok] 4162 q: A? db011.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. 1/0/1 db011.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. A 10.0.3.242 ar: . OPT UDPsize=4096 OK (91)
2016-12-14 05:51:11.329385 IP (tos 0x0, ttl 64, id 13922, offset 0, flags [none], proto UDP (17), length 103)
    10.0.65.4.39718 > 10.0.0.2.53: [bad udp cksum 0x556a -> 0xea21!] 19389+ [1au] A? db001.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. ar: . OPT UDPsize=1480 OK (75)
2016-12-14 05:51:11.484734 IP (tos 0x0, ttl 64, id 13943, offset 0, flags [none], proto UDP (17), length 103)
    10.0.65.4.58656 > 10.0.0.2.53: [bad udp cksum 0x556a -> 0x18ea!] 56058+ [1au] A? db001.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. ar: . OPT UDPsize=1472 OK (75)
2016-12-14 05:51:11.640151 IP (tos 0x0, ttl 64, id 13963, offset 0, flags [none], proto UDP (17), length 103)
    10.0.65.4.16822 > 10.0.0.2.53: [bad udp cksum 0x556a -> 0x4f48!] 16391+ [1au] A? db001.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. ar: . OPT UDPsize=1480 OK (75)
2016-12-14 05:51:11.950629 IP (tos 0x0, ttl 64, id 14002, offset 0, flags [none], proto UDP (17), length 103)
    10.0.65.4.9942 > 10.0.0.2.53: [bad udp cksum 0x556a -> 0x446a!] 28101+ [1au] A? db001.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. ar: . OPT UDPsize=1472 OK (75)
2016-12-14 05:51:12.261191 IP (tos 0x0, ttl 64, id 14064, offset 0, flags [none], proto UDP (17), length 103)
    10.0.65.4.50418 > 10.0.0.2.53: [bad udp cksum 0x556a -> 0x510a!] 47880+ [1au] A? db001.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. ar: . OPT UDPsize=1480 OK (75)
2016-12-14 05:51:12.882042 IP (tos 0x0, ttl 64, id 14182, offset 0, flags [none], proto UDP (17), length 103)
    10.0.65.4.42999 > 10.0.0.2.53: [bad udp cksum 0x556a -> 0xb35c!] 32177+ [1au] A? db001.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com. ar: . OPT UDPsize=1472 OK (75)

再送の間隔についても計算すると以下のようになりました。

1 回目の問合せ (05:51:10.578120)
2 回目の問合せ (05:51:10.703403) + 125ms
3 回目の問合せ (05:51:10.828773) + 125ms
4 回目の問合せ (05:51:11.078934) + 250ms
5 回目の問合せ (05:51:11.329385) + 250ms
6 回目の問合せ (05:51:11.484734) + 125ms
7 回目の問合せ (05:51:11.640151) + 125ms
8 回目の問合せ (05:51:11.950629) + 250ms
9 回目の問合せ (05:51:12.261191) + 250ms
10 回目の問合せ (05:51:12.882042) + 500ms

今回ブログ記事を執筆するにあたり、最新版の Unbound-1.5.10 で再度検証してみたのですが、無事に仮説を実証することができました。問合せのリトライ処理の走行中に他の問合せが走行して応答が得られると送信間隔がリセットされる確証が得られました。

まとめ & 考察

今回の問題について対応を考える前に、ここまでを簡単にまとめます。

DNS サーバの応答が遅れて、Unbound がタイムアウトして SERVFAIL を返す

Unbound がタイムアウトして SERVFAIL 返すのは DNS サーバへの 5 回の問合せ ( 10 回のパケットの送信) の間に応答が得られない場合

Unbound は間隔を指数的に空けて再度問合せを行うが、同一の DNS サーバに対する他の問合せが成功すると再送間隔がリセットされる

レコードが異なっても問合せ先の DNS サーバが同じ以上、 Unbound が再送処理中の問合せ以外の問合せが成功すれば、リトライ間隔をリセットするのは理にかなった実装です。しかし、このままだと同じ DNS サーバに対する他のレコードの問合せが増加するほど、この現象が発生しやすくなるため、場合によってはサーバが応答を返すのに Unbound が待つ時間は 500 ms 程度になってしまう可能性があります。

問合せから応答の SERVFAIL が返される時間があまりにも短いと、権威サーバから SERVFAIL が返って来て名前解決に失敗しているのか、 Unbound がタイムアウトしているのか判断がつかず、問題の切り分けの際にも困ります。

よって、 Unbound のタイムアウトを安定して延ばすため、再送間隔が他の問合せの影響を受けないような対応を考えたいと思います。

対応策の検討

対応としては今回、 forward-zone を分けることで対応できることを確認しました。

#   Forward-Zone section
forward-zone:
  name: "db001.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com"
  forward-addr: 10.0.0.2

forward-zone:
  name: "db011.xxxxxxxxxxxx.xxxxxxxxx.rds.amazonaws.com"
  forward-addr: 10.0.0.2

内部の RTT や再送間隔を管理している構造体が独立して分かれるため、それぞれのレコードに対する問合せが影響することはありません。しかし、あくまで暫定的な対応となるためおすすめはできません。そのため、ソースコードのパッチ作成も考えたのですが、他のキャッシュサーバがどのようにリトライ処理を行っているのか気になるところなので、そちらを調査してからソースコードのパッチを作成することを検討しています。

以上、長くなりましたが Unbound のリトライ処理時の挙動について調査したお話でした。

最後になりますが、この問題を調査するにあたり、 @pandax381 さんに SRTT の概念や Netfilter の string モジュールについてアドバイスいただきました。ありがとうございます!

明日の KLab Advent Calendar 2016 は jukey17 さんです。

klab_gijutsu2 at 18:00│Comments(0)│TrackBack(0)

トラックバックURL

この記事にコメントする

名前:
メール:
URL:
	情報を記憶:	評価:	顔星

Blog内検索