[Dillo-dev] Starting dpis on FreeBSD: blackhole(4) timeouts

30 Jan 2010

      I'm using dillo on FreeBSD 9-CURRENT, and ever since the dpi framework was converted to use Internet domain sockets, I've been plagued by long delays when starting dpis because I'm using blackhole(4) by setting  net.inet.tcp.blackhole to be nonzero.  An example of the problem:

Nav_open_url: new url='dpi:/bm/'
Dpi_check_dpid_ids: Operation timed out
[dpid]: a_Misc_mksecret: e1ab7e05
Dpi_blocking_start_dpid: try 1
dpid started

where truss -faedD -s 128 dillo shows:

41523: 12.860150103 0.000110350 write(1,"Nav_open_url: new url='dpi:/bm/'\n",33) = 33 (0x21)
41523: 12.860414941 0.000037435 open("/root/.dillo/dpid_comm_keys",O_RDONLY,0666) = 4 (0x4)
41523: 12.860511880 0.000017599 fstat(4,{ mode=-rw------- ,inode=57842,size=14,blksize=4096 }) = 0 (0x0)
41523: 12.860635080 0.000034920 read(4,"5020 f9097805\n",4096) = 14 (0xe)
41523: 12.860728389 0.000018718 close(4)	 = 0 (0x0)
41523: 12.860826446 0.000016762 madvise(0x8036a8000,0x1000,0x5,0xfc0,0x2008,0x1) = 0 (0x0)
41523: 12.860962496 0.000029892 socket(PF_INET,SOCK_STREAM,0) = 4 (0x4)
41523: 12.861073963 0.000015086 setsockopt(0x4,0x6,0x1,0x7fffffffe2cc,0x4,0x1) = 0 (0x0)

*** long delay here ***

41523: 87.854362496 74.993148012 connect(4,{ AF_INET 127.0.0.1:5020 },16) ERR#60 'Operation timed out'
41523: 87.854777073 0.000028215 stat("/usr/share/nls/C/libc.cat",0x7fffffffdd90) ERR#2 'No such file or directory'
41523: 87.854968159 0.000026260 stat("/usr/share/nls/libc/C",0x7fffffffdd90) ERR#2 'No such file or directory'
41523: 87.855157289 0.000030171 stat("/usr/local/share/nls/C/libc.cat",0x7fffffffdd90) ERR#2 'No such file or directory'
41523: 87.855342508 0.000028774 stat("/usr/local/share/nls/libc/C",0x7fffffffdd90) ERR#2 'No such file or directory'
41523: 87.855672718 0.000116775 write(1,"Dpi_check_dpid_ids: Operation timed out\n",40) = 40 (0x28)
41523: 87.855797315 0.000024026 pipe(0x7fffffffe2e0) = 0 (0x0)
41523: 87.855956274 0.000014248 sigprocmask(SIG_BLOCK,SIGHUP|SIGINT|SIGQUIT|SIGABRT|SIGEMT|SIGKILL|SIGSYS|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2,0x0) = 0 (0x0)
41523: 87.867098751 0.011049728 fork()		 = 41861 (0xa385)
41523: 87.868057253 0.000017321 sigprocmask(SIG_SETMASK,0x0,0x0) = 0 (0x0)
41523: 87.868278789 0.000018158 close(6)	 = 0 (0x0)
41523: 87.868445291 0.000014806 read(5,0x7fffffffc290,8192) = 0 (0x0)
41523: 87.868540834 0.000016762 madvise(0x8036ed000,0x3000,0x5,0xec,0x6008,0x3) = 0 (0x0)
41523: 87.868635259 0.000017879 close(5)	 = 0 (0x0)
41523: 87.868838358 0.000086603 write(1,"Dpi_blocking_start_dpid: try 1\n",31) = 41861 (0xa385)
41861: 0.007480839 0.000052800 write(4,"5020 e1ab7e05\n",14) = 14 (0xe)
41861: 0.007616331 0.000027098 close(4)		 = 0 (0x0)
41861: 0.007730592 0.000027937 socket(PF_INET,SOCK_STREAM,0) = 4 (0x4)
41861: 0.007815798 0.000012851 setsockopt(0x4,0x6,0x1,0x7fffffffe7cc,0x4,0x7fffffffe57c) = 0 (0x0)
41861: 0.007892903 0.000012013 fcntl(4,F_GETFD,) = 0 (0x0)
41861: 0.007975595 0.000011733 fcntl(4,F_SETFD,FD_CLOEXEC) = 0 (0x0)
41861: 0.008087620 0.000020952 bind(4,{ AF_INET 127.0.0.1:5020 },16) ERR#48 'Address already in use'
41861: 0.008303849 0.000017880 bind(4,{ AF_INET 127.0.0.1:5021 },16) = 0 (0x0)
41861: 0.008372573 0.000014248 listen(0x4,0x5,0x10,0x30,0x4,0x7fffffffe57c) = 0 (0x0)
41861: 0.008458058 0.000019276 socket(PF_INET,SOCK_STREAM,0) = 5 (0x5)
41861: 0.008537677 0.000012012 setsockopt(0x5,0x6,0x1,0x7fffffffe7cc,0x4,0x7fffffffe57c) = 0 (0x0)
41861: 0.008611709 0.000011733 fcntl(5,F_GETFD,) = 0 (0x0)
41861: 0.008692725 0.000011454 fcntl(5,F_SETFD,FD_CLOEXEC) = 0 (0x0)
41861: 0.008794414 0.000016483 bind(5,{ AF_INET 127.0.0.1:5020 },16) ERR#48 'Address already in use'
41861: 0.008956725 0.000016483 bind(5,{ AF_INET 127.0.0.1:5021 },16) ERR#48 'Address already in use'
41861: 0.009117081 0.000016762 bind(5,{ AF_INET 127.0.0.1:5022 },16) = 0 (0x0)
41861: 0.009184128 0.000013130 listen(0x5,0x5,0x10,0x30,0x4,0x7fffffffe57c) = 0 (0x0)
41861: 0.009269055 0.000019276 socket(PF_INET,SOCK_STREAM,0) = 6 (0x6)
41861: 0.009348674 0.000011733 setsockopt(0x6,0x6,0x1,0x7fffffffe7cc,0x4,0x7fffffffe57c) = 0 (0x0)
41861: 0.009422706 0.000011454 fcntl(6,F_GETFD,) = 0 (0x0)
41861: 0.009503722 0.000011454 fcntl(6,F_SETFD,FD_CLOEXEC) = 0 (0x0)
41861: 0.009616865 0.000016483 bind(6,{ AF_INET 127.0.0.1:5020 },16) ERR#48 'Address already in use'
41861: 0.009778617 0.000016482 bind(6,{ AF_INET 127.0.0.1:5021 },16) ERR#48 'Address already in use'
41861: 0.009939252 0.000016203 bind(6,{ AF_INET 127.0.0.1:5022 },16) ERR#48 'Address already in use'
41861: 0.010118605 0.000016762 bind(6,{ AF_INET 127.0.0.1:5023 },16) = 0 (0x0)
41861: 0.010185932 0.000013131 listen(0x6,0x5,0x10,0x30,0x4,0x7fffffffe57c) = 0 (0x0)
41861: 0.010271417 0.000019276 socket(PF_INET,SOCK_STREAM,0) = 7 (0x7)
41861: 0.010351595 0.000012013 setsockopt(0x7,0x6,0x1,0x7fffffffe7cc,0x4,0x7fffffffe57c) = 0 (0x0)
41861: 0.010425906 0.000011454 fcntl(7,F_GETFD,) = 0 (0x0)
41861: 0.010507481 0.000011454 fcntl(7,F_SETFD,FD_CLOEXEC) = 0 (0x0)
41861: 0.010609728 0.000016203 bind(7,{ AF_INET 127.0.0.1:5020 },16) ERR#48 'Address already in use'
41861: 0.010770922 0.000016203 bind(7,{ AF_INET 127.0.0.1:5021 },16) ERR#48 'Address already in use'
41861: 0.010931557 0.000016483 bind(7,{ AF_INET 127.0.0.1:5022 },16) ERR#48 'Address already in use'
41861: 0.011091633 0.000016482 bind(7,{ AF_INET 127.0.0.1:5023 },16) ERR#48 'Address already in use'
41861: 0.011252268 0.000016762 bind(7,{ AF_INET 127.0.0.1:5024 },16) = 0 (0x0)
41861: 0.011319037 0.000013131 listen(0x7,0x5,0x10,0x30,0x4,0x7fffffffe57c) = 0 (0x0)
41861: 0.011404243 0.000018997 socket(PF_INET,SOCK_STREAM,0) = 8 (0x8)
41861: 0.011484141 0.000012012 setsockopt(0x8,0x6,0x1,0x7fffffffe7cc,0x4,0x7fffffffe57c) = 0 (0x0)
41861: 0.011558452 0.000011733 fcntl(8,F_GETFD,) = 0 (0x0)
41861: 0.011640027 0.000011454 fcntl(8,F_SETFD,FD_CLOEXEC) = 0 (0x0)
41861: 0.011742275 0.000016203 bind(8,{ AF_INET 127.0.0.1:5020 },16) ERR#48 'Address already in use'
41861: 0.011903748 0.000016483 bind(8,{ AF_INET 127.0.0.1:5021 },16) ERR#48 'Address already in use'
41861: 0.012063824 0.000016203 bind(8,{ AF_INET 127.0.0.1:5022 },16) ERR#48 'Address already in use'
41861: 0.012224179 0.000016482 bind(8,{ AF_INET 127.0.0.1:5023 },16) ERR#48 'Address already in use'
41861: 0.012384256 0.000016483 bind(8,{ AF_INET 127.0.0.1:5024 },16) ERR#48 'Address already in use'
41861: 0.012544611 0.000016482 bind(8,{ AF_INET 127.0.0.1:5025 },16) = 0 (0x0)
41861: 0.012611659 0.000013130 listen(0x8,0x5,0x10,0x30,0x4,0x7fffffffe57c) = 0 (0x0)
41861: 0.012697424 0.000019556 socket(PF_INET,SOCK_STREAM,0) = 9 (0x9)
41861: 0.012777322 0.000012012 setsockopt(0x9,0x6,0x1,0x7fffffffe7cc,0x4,0x7fffffffe57c) = 0 (0x0)
41861: 0.012851634 0.000011734 fcntl(9,F_GETFD,) = 0 (0x0)
41861: 0.012932929 0.000011454 fcntl(9,F_SETFD,FD_CLOEXEC) = 0 (0x0)
41861: 0.013034897 0.000015924 bind(9,{ AF_INET 127.0.0.1:5020 },16) ERR#48 'Address already in use'
41861: 0.013196370 0.000016203 bind(9,{ AF_INET 127.0.0.1:5021 },16) ERR#48 'Address already in use'
41861: 0.013356726 0.000016483 bind(9,{ AF_INET 127.0.0.1:5022 },16) ERR#48 'Address already in use'
41861: 0.013517081 0.000016482 bind(9,{ AF_INET 127.0.0.1:5023 },16) ERR#48 'Address already in use'
41861: 0.013677157 0.000016482 bind(9,{ AF_INET 127.0.0.1:5024 },16) ERR#48 'Address already in use'
41861: 0.013837234 0.000016483 bind(9,{ AF_INET 127.0.0.1:5025 },16) ERR#48 'Address already in use'
41861: 0.013997310 0.000016483 bind(9,{ AF_INET 127.0.0.1:5026 },16) = 0 (0x0)
41861: 0.014064078 0.000013130 listen(0x9,0x5,0x10,0x30,0x4,0x7fffffffe57c) = 0 (0x0)
41861: 0.014149284 0.000018996 socket(PF_INET,SOCK_STREAM,0) = 10 (0xa)
41861: 0.014229183 0.000011733 setsockopt(0xa,0x6,0x1,0x7fffffffe7cc,0x4,0x7fffffffe57c) = 0 (0x0)
41861: 0.014303773 0.000011733 fcntl(10,F_GETFD,) = 0 (0x0)
41861: 0.014385348 0.000011733 fcntl(10,F_SETFD,FD_CLOEXEC) = 0 (0x0)
41861: 0.014487316 0.000016203 bind(10,{ AF_INET 127.0.0.1:5020 },16) ERR#48 'Address already in use'
41861: 0.014648510 0.000016203 bind(10,{ AF_INET 127.0.0.1:5021 },16) ERR#48 'Address already in use'
41861: 0.014808865 0.000016482 bind(10,{ AF_INET 127.0.0.1:5022 },16) ERR#48 'Address already in use'
41861: 0.014968942 0.000016483 bind(10,{ AF_INET 127.0.0.1:5023 },16) ERR#48 'Address already in use'
41861: 0.015129018 0.000016483 bind(10,{ AF_INET 127.0.0.1:5024 },16) ERR#48 'Address already in use'
41861: 0.015297475 0.000016483 bind(10,{ AF_INET 127.0.0.1:5025 },16) ERR#48 'Address already in use'
41861: 0.015457831 0.000016483 bind(10,{ AF_INET 127.0.0.1:5026 },16) ERR#48 'Address already in use'
41861: 0.015618186 0.000016482 bind(10,{ AF_INET 127.0.0.1:5027 },16) = 0 (0x0)
41861: 0.015685234 0.000013130 listen(0xa,0x5,0x10,0x30,0x4,0x7fffffffe57c) = 0 (0x0)
41861: 0.015770999 0.000019556 socket(PF_INET,SOCK_STREAM,0) = 11 (0xb)
41861: 0.015851177 0.000012013 setsockopt(0xb,0x6,0x1,0x7fffffffe7cc,0x4,0x7fffffffe57c) = 0 (0x0)
41861: 0.015925767 0.000011733 fcntl(11,F_GETFD,) = 0 (0x0)
41861: 0.016007342 0.000011733 fcntl(11,F_SETFD,FD_CLOEXEC) = 0 (0x0)
41861: 0.016109310 0.000016203 bind(11,{ AF_INET 127.0.0.1:5020 },16) ERR#48 'Address already in use'
41861: 0.016270783 0.000016482 bind(11,{ AF_INET 127.0.0.1:5021 },16) ERR#48 'Address already in use'
41861: 0.016431139 0.000016204 bind(11,{ AF_INET 127.0.0.1:5022 },16) ERR#48 'Address already in use'
41861: 0.016591494 0.000016482 bind(11,{ AF_INET 127.0.0.1:5023 },16) ERR#48 'Address already in use'
41861: 0.016751850 0.000016483 bind(11,{ AF_INET 127.0.0.1:5024 },16) ERR#48 'Address already in use'
41861: 0.016911926 0.000016482 bind(11,{ AF_INET 127.0.0.1:5025 },16) ERR#48 'Address already in use'
41861: 0.017072282 0.000016483 bind(11,{ AF_INET 127.0.0.1:5026 },16) ERR#48 'Address already in use'
41861: 0.017232637 0.000016482 bind(11,{ AF_INET 127.0.0.1:5027 },16) ERR#48 'Address already in use'
41861: 0.017392993 0.000016762 bind(11,{ AF_INET 127.0.0.1:5028 },16) = 0 (0x0)
41861: 0.017459761 0.000012851 listen(0xb,0x5,0x10,0x30,0x4,0x7fffffffe57c) = 0 (0x0)
41861: 0.017559215 0.000015086 sigaction(SIGCHLD,{ 0x401f70 SA_NOCLDSTOP ss_t },0x0) = 0 (0x0)
41861: 0.017650847 0.000013968 sigprocmask(SIG_SETMASK,0x0,0x0) = 0 (0x0)
41861: 0.017851710 0.000086324 write(1,"dpid started\n",13) = 13 (0xd)

The particular example of the problem is in is in src/IO/dpi.c:

    463    if (Dpi_read_comm_keys(&dpid_port) != -1) {
    464       sin.sin_port = htons(dpid_port);
    465       if ((sock_fd = Dpi_make_socket_fd()) == -1) {
    466          MSG("Dpi_check_dpid_ids: sock_fd=%d %s\n", sock_fd, dStrerror(errno));
    467       } else if (connect(sock_fd, (struct sockaddr *)&sin, sin_sz) == -1) {
    468          MSG("Dpi_check_dpid_ids: %s\n", dStrerror(errno));

Can we change this behavior, here and elsewhere, before the release, to avoid long delays for those who are using blackhole(4) or the equivalent for some added measure of security?

Regards,
          b.

[Dillo-dev] Starting dpis on FreeBSD: blackhole(4) timeouts

bf2006a＠yahoo.com