Bug 574 - testbound cannot open ports
testbound cannot open ports
Status: RESOLVED FIXED
Product: unbound
Classification: Unclassified
Component: server
unspecified
Other Linux
: P5 enhancement
Assigned To: unbound team
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2014-04-07 16:39 CEST by Jonathan Davies
Modified: 2014-04-08 09:15 CEST (History)
1 user (show)

See Also:


Attachments
unbound make test (16.33 KB, text/x-log)
2014-04-07 16:39 CEST, Jonathan Davies
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Jonathan Davies 2014-04-07 16:39:05 CEST
Created attachment 252 [details]
unbound make test

Hello,

I'm trying to enable the full test suite (make test) in the Ubuntu/Debian package build process.

The unittests work, however, testbound seems to be failing like this:

$ ./testbound -p testdata/acl.rpl
[1396881285] unbound[22533:0] info: Start of unbound 1.4.22 testbound program.
[1396881285] unbound[22533:0] info: Scenario has 5 steps
[1396881285] unbound[22533:0] info: Scenario: Test access control list

testbound is starting: [unbound] [-d] [-c] [/tmp/testbound_22533_cfg.tmp]
[1396881285] unbound[22533:0] fatal error: could not open ports

The selftest works fine however:

$ ./testbound -s
selftest successful

Attached is a full log of the build process.

This is within a fresh build chroot with pbuilder and on a new Ubuntu 14.04 LTS/trusty cloud instance.
Comment 1 Wouter Wijngaards 2014-04-07 16:47:29 CEST
Hi Jonathan,

Can you rerun the testbound with additional commandline arguments  '-o -vvvvv'  that will print many verbose information lines.  And those could be informative.  Not sure how it could not be able to open ports (which are not opened by testbound).

Best regards,
   Wouter
Comment 2 Jonathan Davies 2014-04-07 16:53:28 CEST
How should I be running this? Putting '-o -vvvvv' either side of the acl.rpl option doesn't seem to make it print much else:

ubuntu@buildd:~/unbound/unbound-1.4.22 $ ./testbound -o -vvvvv -p testdata/acl.rpl
[1396882314] unbound[4407:0] info: Start of unbound 1.4.22 testbound program.
[1396882314] unbound[4407:0] info: Scenario has 5 steps
[1396882314] unbound[4407:0] info: Scenario: Test access control list

testbound is starting: [unbound] [-d] [-vvvvv] [-c] [/tmp/testbound_4407_cfg.tmp]
[1396882314] unbound[4407:0] notice: Start of unbound 1.4.22.
[1396882314] unbound[4407:0] fatal error: could not open ports
Comment 3 Wouter Wijngaards 2014-04-07 16:57:17 CEST
This:

./testbound -o -vvvv -p testdata/acl.rpl

gives me a very long list of output.  But maybe this is because there is very little other to printout because the error starts so soon.

Best regards,
   Wouter
Comment 4 Wouter Wijngaards 2014-04-07 17:01:37 CEST
Hi Jonathan,

As far as I can see, it is failing in daemon/daemon.c:daemon_open_shared_ports, but the calls to listening_ports_open() go to testcode/fake_event.c that has return calloc(1,1) for them, and the remote-stuff is disabled in config.  Therefore it could only fail if calloc() fails?  And that strikes me as very strange.

How strange, I cannot explain why it would fail that way.  strace can perhaps say more about what is happening?

Best regards,
   Wouter
Comment 5 Jonathan Davies 2014-04-07 17:08:37 CEST
Here's the strace output:

$ strace ./testbound -p testdata/acl.rpl
execve("./testbound", ["./testbound", "-p", "testdata/acl.rpl"], [/* 30 vars */]) = 0
brk(0)                                  = 0x7f1901b6e000
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f18ffc4d000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=22848, ...}) = 0
mmap(NULL, 22848, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f18ffc47000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/x86_64-linux-gnu/libpthread.so.0", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0po\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=141574, ...}) = 0
mmap(NULL, 2217264, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f18ff80f000
mprotect(0x7f18ff828000, 2093056, PROT_NONE) = 0
mmap(0x7f18ffa27000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x18000) = 0x7f18ffa27000
mmap(0x7f18ffa29000, 13616, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f18ffa29000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\320\37\2\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=1845024, ...}) = 0
mmap(NULL, 3953344, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f18ff449000
mprotect(0x7f18ff605000, 2093056, PROT_NONE) = 0
mmap(0x7f18ff804000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1bb000) = 0x7f18ff804000
mmap(0x7f18ff80a000, 17088, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f18ff80a000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/x86_64-linux-gnu/libssl.so.1.0.0", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\20.\1\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=382984, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f18ffc46000
mmap(NULL, 2478288, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f18ff1eb000
mprotect(0x7f18ff23f000, 2097152, PROT_NONE) = 0
mmap(0x7f18ff43f000, 36864, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x54000) = 0x7f18ff43f000
mmap(0x7f18ff448000, 208, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f18ff448000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/x86_64-linux-gnu/libcrypto.so.1.0.0", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\300\355\5\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=1926432, ...}) = 0
mmap(NULL, 4036760, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f18fee11000
mprotect(0x7f18fefc2000, 2093056, PROT_NONE) = 0
mmap(0x7f18ff1c1000, 155648, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1b0000) = 0x7f18ff1c1000
mmap(0x7f18ff1e7000, 14488, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f18ff1e7000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/x86_64-linux-gnu/libdl.so.2", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\320\16\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=14664, ...}) = 0
mmap(NULL, 2109744, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f18fec0d000
mprotect(0x7f18fec10000, 2093056, PROT_NONE) = 0
mmap(0x7f18fee0f000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2000) = 0x7f18fee0f000
close(3)                                = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f18ffc45000
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f18ffc43000
arch_prctl(ARCH_SET_FS, 0x7f18ffc43740) = 0
mprotect(0x7f18ff804000, 16384, PROT_READ) = 0
mprotect(0x7f18fee0f000, 4096, PROT_READ) = 0
mprotect(0x7f18ff1c1000, 110592, PROT_READ) = 0
mprotect(0x7f18ff43f000, 12288, PROT_READ) = 0
mprotect(0x7f18ffa27000, 4096, PROT_READ) = 0
mprotect(0x7f18ffed5000, 4096, PROT_READ) = 0
mprotect(0x7f18ffc4f000, 4096, PROT_READ) = 0
munmap(0x7f18ffc47000, 22848)           = 0
set_tid_address(0x7f18ffc43a10)         = 17844
set_robust_list(0x7f18ffc43a20, 24)     = 0
futex(0x7fff3e2c4340, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 1, NULL, 7f18ffc43740) = -1 EAGAIN (Resource temporarily unavailable)
rt_sigaction(SIGRTMIN, {0x7f18ff8159f0, [], SA_RESTORER|SA_SIGINFO, 0x7f18ff81f340}, NULL, 8) = 0
rt_sigaction(SIGRT_1, {0x7f18ff815a80, [], SA_RESTORER|SA_RESTART|SA_SIGINFO, 0x7f18ff81f340}, NULL, 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1], NULL, 8) = 0
getrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM64_INFINITY}) = 0
brk(0)                                  = 0x7f1901b6e000
brk(0x7f1901b8f000)                     = 0x7f1901b8f000
write(2, "[1396883286] unbound[17844:0] in"..., 79[1396883286] unbound[17844:0] info: Start of unbound 1.4.22 testbound program.
) = 79
open("testdata/acl.rpl", O_RDONLY)      = 3
open("/tmp/testbound_17844_cfg.tmp", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 4
fstat(4, {st_mode=S_IFREG|0664, st_size=0, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f18ffc4c000
fstat(3, {st_mode=S_IFREG|0664, st_size=863, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f18ffc4b000
read(3, "; config options\nserver:\n\thide-i"..., 4096) = 863
write(4, "server:\tuse-syslog: no\n\t\tdirecto"..., 304) = 304
close(4)                                = 0
munmap(0x7f18ffc4c000, 4096)            = 0
write(2, "[1396883286] unbound[17844:0] in"..., 57[1396883286] unbound[17844:0] info: Scenario has 5 steps
) = 57
close(3)                                = 0
munmap(0x7f18ffc4b000, 4096)            = 0
write(2, "[1396883286] unbound[17844:0] in"..., 72[1396883286] unbound[17844:0] info: Scenario: Test access control list

) = 72
write(2, "testbound is starting:", 22testbound is starting:)  = 22
write(2, " [unbound]", 10 [unbound])              = 10
write(2, " [-d]", 5 [-d])                    = 5
write(2, " [-c]", 5 [-c])                    = 5
write(2, " [/tmp/testbound_17844_cfg.tmp]", 31 [/tmp/testbound_17844_cfg.tmp]) = 31
write(2, "\n", 1
)                       = 1
rt_sigaction(SIGTERM, {0x7f18ffc988c0, [TERM], SA_RESTORER|SA_RESTART, 0x7f18ff47fff0}, {SIG_DFL, [], 0}, 8) = 0
rt_sigaction(SIGQUIT, {0x7f18ffc988c0, [QUIT], SA_RESTORER|SA_RESTART, 0x7f18ff47fff0}, {SIG_DFL, [], 0}, 8) = 0
rt_sigaction(SIGHUP, {0x7f18ffc988c0, [HUP], SA_RESTORER|SA_RESTART, 0x7f18ff47fff0}, {SIG_DFL, [], 0}, 8) = 0
rt_sigaction(SIGPIPE, {SIG_IGN, [PIPE], SA_RESTORER|SA_RESTART, 0x7f18ff47fff0}, {SIG_DFL, [], 0}, 8) = 0
rt_sigaction(SIGINT, {0x7f18ffc988c0, [INT], SA_RESTORER|SA_RESTART, 0x7f18ff47fff0}, {SIG_DFL, [], 0}, 8) = 0
open("/usr/lib/ssl/openssl.cnf", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=10835, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f18ffc4c000
read(3, "#\n# OpenSSL example configuratio"..., 4096) = 4096
read(3, "Netscape crash on BMPStrings or "..., 4096) = 4096
read(3, " this to avoid interpreting an e"..., 4096) = 2643
read(3, "", 4096)                       = 0
close(3)                                = 0
munmap(0x7f18ffc4c000, 4096)            = 0
futex(0x7f18fee100d0, FUTEX_WAKE_PRIVATE, 2147483647) = 0
open("/usr/lib/x86_64-linux-gnu/openssl-1.0.0/engines/libgost.so", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\320T\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=89112, ...}) = 0
mmap(NULL, 2184224, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f18fe9f7000
mprotect(0x7f18fea0b000, 2093056, PROT_NONE) = 0
mmap(0x7f18fec0a000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x13000) = 0x7f18fec0a000
close(3)                                = 0
mprotect(0x7f18fec0a000, 4096, PROT_READ) = 0
brk(0x7f1901bb0000)                     = 0x7f1901bb0000
open("/usr/share/zoneinfo/UTC", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=118, ...}) = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=118, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f18ffc4c000
read(3, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\1\0\0\0\1\0\0\0\0"..., 4096) = 118
lseek(3, -62, SEEK_CUR)                 = 56
read(3, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\1\0\0\0\1\0\0\0\0"..., 4096) = 62
close(3)                                = 0
munmap(0x7f18ffc4c000, 4096)            = 0
open("/dev/urandom", O_RDONLY|O_NOCTTY|O_NONBLOCK) = 3
fstat(3, {st_mode=S_IFCHR|0666, st_rdev=makedev(1, 9), ...}) = 0
poll([{fd=3, events=POLLIN}], 1, 10)    = 1 ([{fd=3, revents=POLLIN}])
read(3, "\216t\256\356J\273\6vP\253\245\377j\211V\307\226m\241\220K\346cAx\331\32\254x[\347\10", 32) = 32
close(3)                                = 0
getuid()                                = 1000
gettimeofday({1396883286, 440691}, NULL) = 0
mmap(NULL, 266240, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f18ffc02000
open("/tmp/testbound_17844_cfg.tmp", O_RDONLY) = 3
ioctl(3, SNDCTL_TMR_TIMEBASE or SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, 0x7fff3e2c2450) = -1 ENOTTY (Inappropriate ioctl for device)
fstat(3, {st_mode=S_IFREG|0664, st_size=304, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f18ffc4c000
read(3, "server:\tuse-syslog: no\n\t\tdirecto"..., 8192) = 304
read(3, "", 4096)                       = 0
read(3, "", 8192)                       = 0
ioctl(3, SNDCTL_TMR_TIMEBASE or SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, 0x7fff3e2c2450) = -1 ENOTTY (Inappropriate ioctl for device)
close(3)                                = 0
munmap(0x7f18ffc4c000, 4096)            = 0
brk(0x7f1901bd2000)                     = 0x7f1901bd2000
getrlimit(RLIMIT_NOFILE, {rlim_cur=1024, rlim_max=4*1024}) = 0
write(2, "[1396883286] unbound[17844:0] fa"..., 64[1396883286] unbound[17844:0] fatal error: could not open ports
) = 64
unlink("/tmp/testbound_17844_cfg.tmp")  = 0
exit_group(1)                           = ?
+++ exited with 1 +++
Comment 6 Jonathan Davies 2014-04-07 17:09:53 CEST
Sorry, I realized I should of attached that in a text file.
Comment 7 Wouter Wijngaards 2014-04-07 17:13:52 CEST
Hi Jonathan,

Fine, that is not a problem.  Okay, so after printing it is up, nothing happens according to strace.  Do you have valgrind perhaps?  Still that likely shows nothing too... Can I perhaps (tomorrow?) give you a version of unbound that has extra print statements (log_info("print at this spot 1");) littered throughout those code points to see where it exits with a failure from daemon/daemon.c daemon_open_shared_ports() ?

Best regards,
   Wouter
Comment 8 Jonathan Davies 2014-04-07 17:39:45 CEST
Hello Wouter,

I've
Comment 9 Jonathan Davies 2014-04-07 17:41:25 CEST
Hello Wouter,

I've never used valgrind before, but I have installed it on the system in question. How would you like me to run it?

Also have to put in any patches you need to track down this issue.

Thanks,
Jonathan
Comment 10 Jonathan Davies 2014-04-07 19:23:59 CEST
OK, I've figured out where the problem is:

For some reason, Debian appears to have decided to set:

cfg->remote_control_enable = 1;

...in util/config_file.c, as they seem to disable the chroot functionality by default (for reasons I do not know). This makes daemon_open_shared_ports() fail at its last if() statement.
Comment 11 Jonathan Davies 2014-04-07 19:55:10 CEST
I've worked around this change by Debian by setting in testcode/testbound.c:

fprintf(cfg, "remote-control:   control-enable: no\n");

..for the auto-generated config file and everything now works.
Comment 12 Wouter Wijngaards 2014-04-08 09:15:09 CEST
Hi Jonathan,

Thank you for the code, I have applied it.  I hope that fixes the Ubuntu build :-)

Best regards, Wouter