[Unbound-users] unbound closes receive socket => udp probes

Ilya Bakulin ilya at bakulin.de
Wed Jul 3 13:07:22 UTC 2013


Hi Unbound developers,

Unbound uses a smart algorithm to adjust timeouts for outgoing queries,
reducing timeout in case the server replies quickly. Which is good.

In real world the upstream server may become temporarily overloaded and may not answer as quickly as before.
In this case Unbound will close the receive socket before the actual reply reaches it.
When there is a fair amount of traffic between the Unbound and upstream server, quite a few replies will hit
the closed socket.
Normally the server will just send "ICMP unreachable" message (taking into account that there may be MANY such
messages -- for each failed query). Our product reports them as "UDP probe attempt", which is logical, because
many UDP packets hitting closed ports may indeed signal about UDP probe attack.
There are several possible ways this problem can be solved.
The best one is, as I understand, to keep the socket opened for some time after the timeout has elapsed,
just to allow the system to receive replies, but don't process them.
Another one is to modify timeout adjusting algorithm to allow some fluctuations in reply time.

My test setup to reproduce this behavior involves using "delayer.c" program from the Unbund test suite.
I have modified it slightly to be able to adjust delay at runtime by sending SIGUSR1/SIGUSR2 to the delayer process.
(the patch is attached).
In my example, one SIGUSR1 increases the delay by 20 milliseconds.
The trick with signals sending was nessesary to avoid restart of delayer process and closing its socket.

Then I start the delayer and nsd on machine A and configure unbound on machine B to use A as a resolver for one particular zone.

Then I send many concurrent queries for nonexistent random names within the configured zone, and Unbound quickly learns that
there is a good and fast connection to the machine B, and decreases the timeout.
The script used to generate queries is attached.

At some point, while still making many queries, I send SIGUSR1 to delayer process and it increases the delay before transmitting
the query to nsd. This reflects the situation when the destination server starts having some load problems.

Unbound closes its receive sockets prematurely, and replies from B hit the OpenBSD IP stack, causing UDP probe alerts. 

Here is a log that shows changes in Unbound infrastructure cache. 172.16.100.118 is the target server for the zone black.zone:

(while true ; do unbound-control-all lookup black.zone | grep 172.16.100.118 ; sleep 1; done)
172.16.100.118          not in infra cache.
172.16.100.118          rto 57 msec, ttl 899, ping 17 var 10 rtt 57, tA 0, tAAAA 0, tother 0, EDNS 0 probed.
172.16.100.118          rto 35 msec, ttl 898, ping 11 var 6 rtt 50, tA 0, tAAAA 0, tother 0, EDNS 0 probed.
172.16.100.118          rto 42 msec, ttl 897, ping 14 var 7 rtt 50, tA 0, tAAAA 0, tother 0, EDNS 0 probed.
172.16.100.118          rto 31 msec, ttl 896, ping 11 var 5 rtt 50, tA 0, tAAAA 0, tother 0, EDNS 0 probed.
172.16.100.118          rto 29 msec, ttl 895, ping 9 var 5 rtt 50, tA 0, tAAAA 0, tother 0, EDNS 0 probed.
172.16.100.118          rto 35 msec, ttl 894, ping 11 var 6 rtt 50, tA 0, tAAAA 0, tother 0, EDNS 0 probed.
172.16.100.118          rto 34 msec, ttl 893, ping 10 var 6 rtt 50, tA 0, tAAAA 0, tother 0, EDNS 0 probed.
172.16.100.118          rto 34 msec, ttl 892, ping 10 var 6 rtt 50, tA 0, tAAAA 0, tother 0, EDNS 0 probed.
172.16.100.118          rto 30 msec, ttl 891, ping 10 var 5 rtt 50, tA 0, tAAAA 0, tother 0, EDNS 0 probed.
T1: SIGUSR1 sent to delayer, delay += 20ms ...
172.16.100.118          rto 136 msec, ttl 890, ping 36 var 25 rtt 136, tA 0, tAAAA 0, tother 0, EDNS 0 probed.
172.16.100.118          rto 70 msec, ttl 889, ping 50 var 5 rtt 70, tA 0, tAAAA 0, tother 0, EDNS 0 probed.
172.16.100.118          rto 73 msec, ttl 888, ping 53 var 5 rtt 73, tA 0, tAAAA 0, tother 0, EDNS 0 probed.
172.16.100.118          rto 77 msec, ttl 887, ping 53 var 6 rtt 77, tA 0, tAAAA 0, tother 0, EDNS 0 probed.
172.16.100.118          rto 66 msec, ttl 886, ping 54 var 3 rtt 66, tA 0, tAAAA 0, tother 0, EDNS 0 probed.
172.16.100.118          rto 79 msec, ttl 885, ping 55 var 6 rtt 79, tA 0, tAAAA 0, tother 0, EDNS 0 probed.
172.16.100.118          rto 110 msec, ttl 884, ping 22 var 22 rtt 110, tA 0, tAAAA 0, tother 0, EDNS 0 probed.
172.16.100.118          rto 95 msec, ttl 883, ping 27 var 17 rtt 95, tA 0, tAAAA 0, tother 0, EDNS 0 probed.
T2: SIGUSR2 sent to delayer, delay -= 20ms ...
172.16.100.118          rto 42 msec, ttl 882, ping 18 var 6 rtt 50, tA 0, tAAAA 0, tother 0, EDNS 0 probed.
172.16.100.118          rto 64 msec, ttl 881, ping 24 var 10 rtt 64, tA 0, tAAAA 0, tother 0, EDNS 0 probed.
172.16.100.118          rto 49 msec, ttl 880, ping 9 var 10 rtt 50, tA 0, tAAAA 0, tother 0, EDNS 0 probed.
172.16.100.118          rto 49 msec, ttl 879, ping 9 var 10 rtt 50, tA 0, tAAAA 0, tother 0, EDNS 0 probed.
172.16.100.118          rto 49 msec, ttl 877, ping 9 var 10 rtt 50, tA 0, tAAAA 0, tother 0, EDNS 0 probed.

At the moment T1 I see the following in the kernel log of OpenBSD machine where Unbound runs:
Jun 28 13:25:27 ggd114 /bsd: udp_probe: em0: ac106476[53] ac106372[59728] udplen 106: 36c08503 00010000 00010001 126e6f6e 65786973 74656e74 2d323237 38343405 626c6163 6b047a6f 6e650000 010001c0 1f000600 0100001c 20002406 67676431...
Jun 28 13:25:27 ggd114 /bsd: udp_probe: em0: ac106476[53] ac106372[57241] udplen 106: 91748503 00010000 00010001 126e6f6e 65786973 74656e74 2d343835 39323805 626c6163 6b047a6f 6e650000 010001c0 1f000600 0100001c 20002406 67676431...
Jun 28 13:25:27 ggd114 /bsd: udp_probe: em0: ac106476[53] ac106372[10757] udplen 106: 2e728503 00010000 00010001 126e6f6e 65786973 74656e74 2d363333 30333905 626c6163 6b047a6f 6e650000 010001c0 1f000600 0100001c 20002406 67676431...
... potentially followed by more messages

The problem may not be visible on other systems with not so paranoic IP stack, but nevertheless they may send many "ICMP unreachable" messages, flooding their link.

Please tell me if this problem has a chance to be fixed.
-- 
Regards,
Ilya Bakulin
-------------- next part --------------
--- /var/tmp/ibaku/w-unbound/unbound-1.4.17/testcode/delayer.c  Wed Jul  7 15:13:36 2010
+++ /var/tmp/ibaku/w-unbound.old/unbound-1.4.17/testcode/delayer.c      Wed Jul  3 14:45:08 2013
@@ -343,6 +343,48 @@
 /** signal handler global info */
 static volatile int do_quit = 0;
 
+static struct timeval delay, reuse;
+
+static RETSIGTYPE delayer_sigusr(int sig) {
+       printf("got signal %d\n", sig);
+
+       if (sig == SIGUSR1)
+/*             delay.tv_sec+= 5; */
+               delay.tv_usec+= 20 * 1000;
+       else
+/*             delay.tv_sec-= 5; */
+               delay.tv_usec-= 20 * 1000;
+
+       reuse = delay; /* reuse is max(4*delay, 1 second) */
+       dl_tv_add(&reuse, &delay);
+       dl_tv_add(&reuse, &delay);
+       dl_tv_add(&reuse, &delay);
+       if(reuse.tv_sec == 0)
+               reuse.tv_sec = 1;
+
+}
+
+#if 0
+static struct timeval g_delay, g_reuse;
+
+static RETSIGTYPE delayer_sigusr(int sig) {
+       printf("got signal %d\n", sig);
+
+       if (sig == SIGUSR1)
+               g_delay.tv_usec+= 500;
+       else
+               g_delay.tv_usec-= 500;
+
+       g_reuse = g_delay; /* reuse is max(4*delay, 1 second) */
+       dl_tv_add(&g_reuse, &g_delay);
+       dl_tv_add(&g_reuse, &g_delay);
+       dl_tv_add(&g_reuse, &g_delay);
+       if(g_reuse.tv_sec == 0)
+               g_reuse.tv_sec = 1;
+
+}
+#endif
+
 /** signal handler for user quit */
 static RETSIGTYPE delayer_sigh(int sig)
 {
@@ -995,7 +1037,7 @@
        struct sockaddr_storage bind_addr, srv_addr;
        socklen_t bind_len, srv_len;
        struct ringbuf* ring = ring_create(memsize);
-       struct timeval delay, reuse;
+//     struct timeval delay, reuse;
        ldns_buffer* pkt;
        int i, s, listen_s;
 #ifndef S_SPLINT_S
@@ -1028,6 +1070,9 @@
 #ifdef SIGALRM
                signal(SIGALRM, delayer_sigh) == SIG_ERR ||
 #endif
+           signal(SIGUSR1, delayer_sigusr) == SIG_ERR ||
+           signal(SIGUSR2, delayer_sigusr) == SIG_ERR ||
+
                signal(SIGTERM, delayer_sigh) == SIG_ERR)
                fatal_exit("could not bind to signal");
        /* bind UDP port */
-------------- next part --------------
A non-text attachment was scrubbed...
Name: test.pl
Type: text/x-perl-script
Size: 552 bytes
Desc: not available
URL: <http://lists.nlnetlabs.nl/pipermail/unbound-users/attachments/20130703/58bcceeb/attachment.bin>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 243 bytes
Desc: OpenPGP digital signature
URL: <http://lists.nlnetlabs.nl/pipermail/unbound-users/attachments/20130703/58bcceeb/attachment-0001.bin>


More information about the Unbound-users mailing list