[stunnel-users] Problem with name resolving when using delay option

Maksymilian Kowalik bass100 at wp.pl
Tue Mar 24 16:26:54 CET 2009 

Hi,

I think this problem might have been already reported here 
http://stunnel.mirt.net/pipermail/stunnel-users/2006-January/000948.html
but the guy posting it did not send any details.
My problem looks exactly the same. I have two hosts, both having dynamic 
IPs.

Config on host1

cert = /etc/stunnel/certs/host1.no-ip.info.crt
key = /etc/stunnel/certs/host1.no-ip.info.key
sslVersion = SSLv3
chroot = /var/lib/stunnel4/
setuid = stunnel4
setgid = stunnel4
pid = /stunnel4.pid
socket = l:TCP_NODELAY=1
socket = r:TCP_NODELAY=1
compression = rle
verify = 3
CApath = /trusted-certs
debug = 7
output = /var/log/stunnel4/stunnel.log
client = yes
[service1]
accept  = 192.168.0.10:32155
connect = host2.no-ip.info:1443
delay = yes


Config on host2

cert = /etc/stunnel/certs/host2.no-ip.info.crt
key = /etc/stunnel/certs/host2.no-ip.info.key
sslVersion = SSLv3
chroot = /var/lib/stunnel4/
setuid = stunnel4
setgid = stunnel4
pid = /stunnel4.pid
socket = l:TCP_NODELAY=1
socket = r:TCP_NODELAY=1
compression = rle
verify = 3
CApath = /trusted-certs
debug = 7
output = /var/log/stunnel4/stunnel.log
[service1]
accept  = 192.168.0.10:1443
connect = 192.168.0.10:32150

When I comment out "delay = yes" from config on host1 everything works 
fine (until the IP changes).
When I try to take advantage from using this option, the name cannot be 
resolved at the connection time.
Here's what I see in logs:

2009.03.24 15:55:37 LOG5[24255:3082798784]: stunnel 4.18 on 
i486-pc-linux-gnu with OpenSSL 0.9.8c 05 Sep 2006
2009.03.24 15:55:37 LOG5[24255:3082798784]: Threading:PTHREAD SSL:ENGINE 
Sockets:POLL,IPv6 Auth:LIBWRAP
2009.03.24 15:55:37 LOG6[24255:3082798784]: file ulimit = 1024 (can be 
changed with 'ulimit -n')
2009.03.24 15:55:37 LOG6[24255:3082798784]: poll() used - no FD_SETSIZE 
limit for file descriptors
2009.03.24 15:55:37 LOG5[24255:3082798784]: 500 clients allowed
2009.03.24 15:55:37 LOG7[24255:3082798784]: FD 4 in non-blocking mode
2009.03.24 15:55:37 LOG7[24255:3082798784]: FD 5 in non-blocking mode
2009.03.24 15:55:37 LOG7[24255:3082798784]: FD 6 in non-blocking mode
2009.03.24 15:55:37 LOG7[24255:3082798784]: SO_REUSEADDR option set on 
accept socket
2009.03.24 15:55:37 LOG7[24255:3082798784]: service1 bound to 
192.168.0.10:32155
2009.03.24 15:55:37 LOG7[24256:3082798784]: Created pid file /stunnel4.pid
2009.03.24 15:56:13 LOG7[24256:3082798784]: service1 accepted FD=7 from 
192.168.0.10:44515
2009.03.24 15:56:13 LOG7[24256:3082570672]: service1 started
2009.03.24 15:56:13 LOG7[24256:3082570672]: FD 7 in non-blocking mode
2009.03.24 15:56:13 LOG7[24256:3082570672]: TCP_NODELAY option set on 
local socket
2009.03.24 15:56:13 LOG7[24256:3082570672]: FD 8 in non-blocking mode
2009.03.24 15:56:13 LOG7[24256:3082570672]: FD 9 in non-blocking mode
2009.03.24 15:56:13 LOG7[24256:3082798784]: Cleaning up the signal pipe
2009.03.24 15:56:13 LOG6[24256:3082798784]: Child process 24267 finished 
with code 0
2009.03.24 15:56:13 LOG7[24256:3082570672]: Connection from 
192.168.0.10:44515 permitted by libwrap
2009.03.24 15:56:13 LOG5[24256:3082570672]: service1 connected from 
192.168.0.10:44515
2009.03.24 15:56:14 LOG7[24256:3082798784]: service1 accepted FD=9 from 
192.168.0.10:44516
2009.03.24 15:56:14 LOG7[24256:3082501040]: service1 started
2009.03.24 15:56:14 LOG7[24256:3082501040]: FD 9 in non-blocking mode
2009.03.24 15:56:14 LOG7[24256:3082501040]: TCP_NODELAY option set on 
local socket
2009.03.24 15:56:14 LOG7[24256:3082501040]: FD 10 in non-blocking mode
2009.03.24 15:56:14 LOG7[24256:3082501040]: FD 11 in non-blocking mode
2009.03.24 15:56:14 LOG7[24256:3082798784]: Cleaning up the signal pipe
2009.03.24 15:56:14 LOG6[24256:3082798784]: Child process 24269 finished 
with code 0
2009.03.24 15:56:14 LOG7[24256:3082501040]: Connection from 
192.168.0.10:44516 permitted by libwrap
2009.03.24 15:56:14 LOG5[24256:3082501040]: service1 connected from 
192.168.0.10:44516
2009.03.24 15:56:15 LOG7[24256:3082798784]: service1 accepted FD=11 from 
192.168.0.10:44517
2009.03.24 15:56:15 LOG7[24256:3082431408]: service1 started
2009.03.24 15:56:15 LOG7[24256:3082431408]: FD 11 in non-blocking mode
2009.03.24 15:56:15 LOG7[24256:3082431408]: TCP_NODELAY option set on 
local socket
2009.03.24 15:56:15 LOG7[24256:3082431408]: FD 12 in non-blocking mode
2009.03.24 15:56:15 LOG7[24256:3082431408]: FD 13 in non-blocking mode
2009.03.24 15:56:15 LOG7[24256:3082798784]: Cleaning up the signal pipe
2009.03.24 15:56:15 LOG6[24256:3082798784]: Child process 24271 finished 
with code 0
2009.03.24 15:56:15 LOG7[24256:3082431408]: Connection from 
192.168.0.10:44517 permitted by libwrap
2009.03.24 15:56:15 LOG5[24256:3082431408]: service1 connected from 
192.168.0.10:44517
2009.03.24 15:56:45 LOG7[24256:3082798784]: service1 accepted FD=13 from 
192.168.0.10:44520
2009.03.24 15:56:45 LOG7[24256:3082361776]: service1 started
2009.03.24 15:56:45 LOG7[24256:3082361776]: FD 13 in non-blocking mode
2009.03.24 15:56:45 LOG7[24256:3082361776]: TCP_NODELAY option set on 
local socket
2009.03.24 15:56:45 LOG7[24256:3082361776]: FD 14 in non-blocking mode
2009.03.24 15:56:45 LOG7[24256:3082361776]: FD 15 in non-blocking mode
2009.03.24 15:56:45 LOG7[24256:3082798784]: Cleaning up the signal pipe
2009.03.24 15:56:45 LOG6[24256:3082798784]: Child process 24277 finished 
with code 0
2009.03.24 15:56:45 LOG7[24256:3082361776]: Connection from 
192.168.0.10:44520 permitted by libwrap
2009.03.24 15:56:45 LOG5[24256:3082361776]: service1 connected from 
192.168.0.10:44520
2009.03.24 15:56:53 LOG3[24256:3082570672]: Error resolving 
'host2.no-ip.info': Temporary failure in name resolution (EAI_AGAIN)
2009.03.24 15:56:53 LOG3[24256:3082570672]: No host resolved
2009.03.24 15:56:53 LOG5[24256:3082570672]: Connection reset: 0 bytes 
sent to SSL, 0 bytes sent to socket
2009.03.24 15:56:53 LOG7[24256:3082570672]: service1 finished (3 left)
2009.03.24 15:56:54 LOG3[24256:3082501040]: Error resolving 
'host2.no-ip.info': Temporary failure in name resolution (EAI_AGAIN)
2009.03.24 15:56:54 LOG3[24256:3082501040]: No host resolved
2009.03.24 15:56:54 LOG5[24256:3082501040]: Connection reset: 0 bytes 
sent to SSL, 0 bytes sent to socket
2009.03.24 15:56:54 LOG7[24256:3082501040]: service1 finished (2 left)
2009.03.24 15:56:55 LOG3[24256:3082431408]: Error resolving 
'host2.no-ip.info': Temporary failure in name resolution (EAI_AGAIN)
2009.03.24 15:56:55 LOG3[24256:3082431408]: No host resolved
2009.03.24 15:56:55 LOG5[24256:3082431408]: Connection reset: 0 bytes 
sent to SSL, 0 bytes sent to socket
2009.03.24 15:56:55 LOG7[24256:3082431408]: service1 finished (1 left)
2009.03.24 15:57:08 LOG7[24256:3082798784]: service1 accepted FD=8 from 
192.168.0.10:44523
2009.03.24 15:57:08 LOG7[24256:3082431408]: service1 started
2009.03.24 15:57:08 LOG7[24256:3082431408]: FD 8 in non-blocking mode
2009.03.24 15:57:08 LOG7[24256:3082431408]: TCP_NODELAY option set on 
local socket
2009.03.24 15:57:08 LOG7[24256:3082431408]: FD 9 in non-blocking mode
2009.03.24 15:57:08 LOG7[24256:3082431408]: FD 10 in non-blocking mode
2009.03.24 15:57:08 LOG7[24256:3082431408]: Connection from 
192.168.0.10:44523 permitted by libwrap
2009.03.24 15:57:08 LOG5[24256:3082431408]: service1 connected from 
192.168.0.10:44523
2009.03.24 15:57:08 LOG7[24256:3082798784]: Cleaning up the signal pipe
2009.03.24 15:57:08 LOG6[24256:3082798784]: Child process 24287 finished 
with code 0

The most mysterious thing appeared when I tried to look at the IP 
traffic (filtered by port 53).
When the option "delay = yes" is commented out the queries go to the DNS 
server pointed out by /etc/resolv.conf

16:05:15.749809 IP 192.168.1.1.51699 > 192.168.1.1.domain:  49408+ AAAA? 
host2.no-ip.info. (36)
16:05:15.752235 IP 192.168.1.1.51700 > 192.168.1.1.domain:  56584+ PTR? 
1.1.168.192.in-addr.arpa. (42)
16:05:15.752539 IP localhost.20244 > localhost.domain:  56140 PTR? 
1.1.168.192.in-addr.arpa. (42)
16:05:15.752855 IP localhost.domain > localhost.20244:  56140 NXDomain*- 
0/1/0 (94)
16:05:15.753064 IP 192.168.1.1.domain > 192.168.1.1.51700:  56584 
NXDomain* 0/0/0 (42)
16:05:15.955763 IP 192.168.1.1.domain > 192.168.1.1.51699:  49408 0/0/0 
(36)
16:05:15.956214 IP 192.168.1.1.51700 > 192.168.1.1.domain:  63679+ AAAA? 
host2.no-ip.info. (36)
16:05:15.956438 IP 192.168.1.1.domain > 192.168.1.1.51700:  63679 0/0/0 
(36)
16:05:15.956610 IP 192.168.1.1.51700 > 192.168.1.1.domain:  39727+ A? 
host2.no-ip.info. (36)


When trying to use the desired option, the queries go to localhost 
(/etc/resolv.conf is simply ignored!)

16:08:13.792535 IP localhost.51701 > localhost.domain:  48817+ AAAA? 
host2.no-ip.info. (36)
16:08:14.221600 IP localhost.51703 > localhost.domain:  51321+ AAAA? 
host2.no-ip.info. (36)
16:08:15.169435 IP localhost.51704 > localhost.domain:  15416+ AAAA? 
host2.no-ip.info. (36)
16:08:18.792895 IP localhost.51701 > localhost.domain:  48817+ AAAA? 
host2.no-ip.info. (36)
16:08:19.220980 IP localhost.51703 > localhost.domain:  51321+ AAAA? 
host2.no-ip.info. (36)
16:08:20.169209 IP localhost.51704 > localhost.domain:  15416+ AAAA? 
host2.no-ip.info. (36)
16:08:23.794243 IP localhost.51705 > localhost.domain:  1184+ AAAA? 
host2.no-ip.info. (36)
16:08:24.222325 IP localhost.51706 > localhost.domain:  26618+ AAAA? 
host2.no-ip.info. (36)
16:08:25.170567 IP localhost.51708 > localhost.domain:  43639+ AAAA? 
host2.no-ip.info. (36)
16:08:28.795332 IP localhost.51705 > localhost.domain:  1184+ AAAA? 
host2.no-ip.info. (36)
16:08:29.223410 IP localhost.51706 > localhost.domain:  26618+ AAAA? 
host2.no-ip.info. (36)
16:08:30.171643 IP localhost.51708 > localhost.domain:  43639+ AAAA? 
host2.no-ip.info. (36)
16:08:33.796674 IP localhost.51709 > localhost.domain:  30282+ A? 
host2.no-ip.info. (36)
16:08:34.224718 IP localhost.51710 > localhost.domain:  46924+ A? 
host2.no-ip.info. (36)

Anyone faced such a mystery?
Probably the problem lays somewhere in linux libs, but I'm a begginer 
and don't know where to start digging.

Exactly the same bahavior was observed on two different machines 
(stunnel clients) - both were Debians 4.0
Linux host1 2.6.18-6-686 #1 SMP Sat Dec 27 09:31:05 UTC 2008 i686 
GNU/Linux
libc-2.3.6
One had stunnel 4.18 apt-get installed, and on the other one I compiled 
stunnel 4.26.
host1:~# cat /etc/resolv.conf
nameserver 192.168.1.1

Best regards,
Maks K.

----------------------------------------------------
Zobacz przygody bardzo odważnej myszki!
DZIELNY DESPERO - w kinach od 27 marca. Zobacz zwiastun filmu: 
http://klik.wp.pl/?adr=http%3A%2F%2Fcorto.www.wp.pl%2Fas%2Fdzielnydespero.html&sid=672

More information about the stunnel-users mailing list