Bug#279001: nscd problems with GETHOSTBYNAME and GETHOSTBYADDR
Package: nscd
Version: 2.3.2.ds1-18
System Description:
kernel = 2.4.27-1-k7
libc6 = 2.3.2.ds1-18
mozilla = 1.7.3-5
Symptom:
After completing an 'apt-get upgrade', I noticed that mozilla was
frequently taking a long amount of time to do a host name lookup. Even
sites visited a few minutes previously required 10+ seconds to complete
a host name lookup. Additionally, 'ping <hostname>' also takes an
inordinate amount of time in it's host lookup (see below).
My initial thinking was nscd and I've found some issues that may be the
cause of this problem. Note that I am using a cable modem on my home
connection.
*****************
Case 1 (Case 2 follows) - Hostname not in cache:
console command (debug output follows):
# ping www.drudgeport.com
<delay of about 6 seconds>
PING drudgereport.com (66.28.209.210) 56(84) bytes of data.
<delay of about 6 seconds>
64 bytes from 66.28.209.210.ha-hosting.com (66.28.209.210): icmp_seq=1
ttl=51 time=82.8 ms
...
Debug output (note this is the first time I've ping this host so I
expect the following output):
handle_request: request received (Version = 2) from PID 2299
2264: GETHOSTBYNAME (www.drudgereport.com)
2264: Haven't found "www.drudgereport.com" in hosts cache!
2264: handle_request: request received (Version = 2) from PID 2299
2264: GETHOSTBYADDR (66.28.209.210)
2264: Haven't found "66.28.209.210" in hosts cache!
2264: handle_request: request received (Version = 2) from PID 2299
2264: GETHOSTBYADDR (66.28.209.210)
***************
Case 2 - Hostname should be in cache...I'm repeating the ping <hostname>
command about 5 seconds after completing Case 1 above.
console command (debug output follows):
# ping www.drudgeport.com
<delay of about 6 seconds>
PING drudgereport.com (66.28.209.210) 56(84) bytes of data.
<delay of about 6 seconds>
64 bytes from 65.77.130.210.ha-hosting.com (65.77.130.210): icmp_seq=1
ttl=51 time=90.8 ms
...
Debug output:
2356: handle_request: request received (Version = 2) from PID 2364
2356: GETHOSTBYNAME (www.drudgereport.com)
2356: Haven't found "www.drudgereport.com" in hosts cache!
2360: handle_request: request received (Version = 2) from PID 2364
2360: GETHOSTBYADDR (66.28.209.210)
2360: Haven't found "66.28.209.210" in hosts cache!
2361: handle_request: request received (Version = 2) from PID 2364
2361: GETHOSTBYADDR (66.28.209.210)
2362: handle_request: request received (Version = 2) from PID 2364
2362: GETHOSTBYADDR (66.28.209.210)
Stack trace:
[pid 2357] getppid() = 2356
[pid 2357] poll( <unfinished ...>
[pid 2358] <... poll resumed> [{fd=3, events=POLLRDNORM,
revents=POLLRDNORM}],1, 15000) = 1
[pid 2356] <... accept resumed> 0, NULL) = 7
[pid 2358] accept(3, <unfinished ...>
[pid 2356] read(7, "\2\0\0\0\4\0\0\0\25\0\0\0", 12) = 12
[pid 2356] getsockopt(7, SOL_SOCKET, SO_PEERCRED,
"<\t\0\0\0\0\0\0\0\0\0\0", [12]) = 0
[pid 2356] read(7, "www.drudgereport.com\0", 21) = 21
[pid 2356] getpid() = 2356
[pid 2356] write(4, "2356: handle_request: request re"..., 67) = 67
[pid 2356] getpid() = 2356
[pid 2356] write(4, "2356: \tGETHOSTBYNAME (www.drudge"..., 44) = 44
[pid 2356] getpid() = 2356
[pid 2356] write(4, "2356: Haven\'t found \"www.drudger"..., 59) = 59
[pid 2356] gettimeofday({1099173622, 875148}, NULL) = 0
[pid 2356] getpid() = 2356
[pid 2356] open("/etc/resolv.conf", O_RDONLY) = 8
[pid 2356] fstat64(8, {st_mode=S_IFREG|0644, st_size=266, ...}) = 0
[pid 2356] old_mmap(NULL, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x40018000
[pid 2356] read(8, "# Dynamic resolv.conf(5) file fo"..., 4096) = 266
[pid 2356] read(8, "", 4096) = 0
[pid 2356] close(8) = 0
[pid 2356] munmap(0x40018000, 4096) = 0
[pid 2356] open("/etc/hosts", O_RDONLY) = 8
[pid 2356] fcntl64(8, F_GETFD) = 0
[pid 2356] fcntl64(8, F_SETFD, FD_CLOEXEC) = 0
[pid 2356] fstat64(8, {st_mode=S_IFREG|0644, st_size=309, ...}) = 0
[pid 2356] old_mmap(NULL, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x40018000
[pid 2356] read(8, "127.0.0.1\tlocalhost\tarrakis\n\n192"..., 4096) = 309
[pid 2356] read(8, "", 4096) = 0
[pid 2356] close(8) = 0
[pid 2356] munmap(0x40018000, 4096) = 0
[pid 2356] socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 8
[pid 2356] connect(8, {sa_family=AF_INET, sin_port=htons(53),
sin_addr=inet_addr("10.0.0.1")}, 28) = 0
[pid 2356] send(8, "]O\1\0\0\1\0\0\0\0\0\0\3www\fdrudgereport\3co"...,
38, 0) = 38
[pid 2356] gettimeofday({1099173622, 877606}, NULL) = 0
[pid 2356] poll( <unfinished ...>
[pid 2357] <... poll resumed> [{fd=5, events=POLLIN}], 1, 2000) = 0
[pid 2357] getppid() = 2356
[pid 2357] poll([{fd=5, events=POLLIN}], 1, 2000) = 0
[pid 2357] getppid() = 2356
[pid 2357] poll([{fd=5, events=POLLIN}], 1, 2000) = 0
[pid 2357] getppid() = 2356
[pid 2357] poll( <unfinished ...>
[pid 2356] <... poll resumed> [{fd=8, events=POLLIN}], 1, 5000) = 0
[pid 2356] socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 9
[pid 2356] connect(9, {sa_family=AF_INET, sin_port=htons(53),
sin_addr=inet_addr("66.235.59.6")}, 28) = 0
[pid 2356] send(9, "]O\1\0\0\1\0\0\0\0\0\0\3www\fdrudgereport\3co"...,
38, 0) = 38
[pid 2356] gettimeofday({1099173627, 880871}, NULL) = 0
[pid 2356] poll([{fd=9, events=POLLIN, revents=POLLIN}], 1, 3000) = 1
[pid 2356] ioctl(9, FIONREAD, [152]) = 0
[pid 2356] recvfrom(9,
"]O\201\200\0\1\0\3\0\2\0\2\3www\fdrudgereport\3co"...,1024, 0,
{sa_family=AF_INET, sin_port=htons(53),
sin_addr=inet_addr("66.235.59.6")}, [16]) = 152
[pid 2356] close(8) = 0
[pid 2356] close(9) = 0
[pid 2356] time(NULL) = 1099173628
[pid 2356] write(7,
"\2\0\0\0\1\0\0\0\21\0\0\0\1\0\0\0\2\0\0\0\4\0\0\0\2\0\0"..., 82) = 82
[pid 2356] close(7) = 0
[pid 2356] poll([{fd=3, events=POLLRDNORM}], 1, 0) = 0
[pid 2356] time(NULL) = 1099173628
[pid 2356] poll([{fd=3, events=POLLRDNORM}], 1, 0) = 0
[pid 2356] time(NULL) = 1099173628
[pid 2356] stat64("/etc/passwd", {st_mode=S_IFREG|0644, st_size=1151,
...}) = 0
[pid 2356] time(NULL) = 1099173628
[pid 2356] poll([{fd=3, events=POLLRDNORM}], 1, 0) = 0
[pid 2356] time(NULL) = 1099173628
[pid 2356] poll( <unfinished ...>
[pid 2360] <... accept resumed> 0, NULL) = 7
[pid 2356] <... poll resumed> [{fd=3, events=POLLRDNORM,
revents=POLLRDNORM}],1, 15000) = 1
[pid 2360] read(7, <unfinished ...>
[pid 2356] accept(3, <unfinished ...>
[pid 2360] <... read resumed> "\2\0\0\0\6\0\0\0\4\0\0\0", 12) = 12
[pid 2360] getsockopt(7, SOL_SOCKET, SO_PEERCRED,
"<\t\0\0\0\0\0\0\0\0\0\0", [12]) = 0
[pid 2360] read(7, "B\34\321\322", 4) = 4
[pid 2360] getpid() = 2360
[pid 2360] write(4, "2360: handle_request: request re"..., 67) = 67
[pid 2360] getpid() = 2360
[pid 2360] write(4, "2360: \tGETHOSTBYADDR (66.28.209."..., 37) = 37
[pid 2360] getpid() = 2360
[pid 2360] write(4, "2360: Haven\'t found \"66.28.209.2"..., 52) = 52
[pid 2360] open("/etc/hosts", O_RDONLY) = 8
[pid 2360] fcntl64(8, F_GETFD) = 0
[pid 2360] fcntl64(8, F_SETFD, FD_CLOEXEC) = 0
[pid 2360] fstat64(8, {st_mode=S_IFREG|0644, st_size=309, ...}) = 0
[pid 2360] old_mmap(NULL, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x40018000
[pid 2360] read(8, "127.0.0.1\tlocalhost\tarrakis\n\n192"..., 4096) = 309
[pid 2360] read(8, "", 4096) = 0
[pid 2360] close(8) = 0
[pid 2360] munmap(0x40018000, 4096) = 0
[pid 2360] socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 8
[pid 2360] connect(8, {sa_family=AF_INET, sin_port=htons(53),
sin_addr=inet_addr("10.0.0.1")}, 28) = 0
[pid 2360] send(8,
"G,\1\0\0\1\0\0\0\0\0\0\003210\003209\00228\00266\7in-a"..., 44, 0) = 44
[pid 2360] gettimeofday({1099173628, 128120}, NULL) = 0
[pid 2360] poll( <unfinished ...>
[pid 2357] <... poll resumed> [{fd=5, events=POLLIN}], 1, 2000) = 0
[pid 2357] getppid() = 2356
[pid 2357] poll([{fd=5, events=POLLIN}], 1, 2000) = 0
[pid 2357] getppid() = 2356
[pid 2357] poll( <unfinished ...>
[pid 2360] <... poll resumed> [{fd=8, events=POLLIN}], 1, 5000) = 0
[pid 2360] socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 9
[pid 2360] connect(9, {sa_family=AF_INET, sin_port=htons(53),
sin_addr=inet_addr("66.235.59.6")}, 28) = 0
[pid 2360] send(9,
"G,\1\0\0\1\0\0\0\0\0\0\003210\003209\00228\00266\7in-a"..., 44, 0) = 44
[pid 2360] gettimeofday({1099173633, 129966}, NULL) = 0
[pid 2360] poll([{fd=9, events=POLLIN, revents=POLLIN}], 1, 3000) = 1
[pid 2360] ioctl(9, FIONREAD, [140]) = 0
[pid 2360] recvfrom(9,
"G,\201\200\0\1\0\1\0\3\0\0\003210\003209\00228\00266\7"..., 1024, 0,
{sa_family=AF_INET, sin_port=htons(53),
sin_addr=inet_addr("66.235.59.6")}, [16]) = 140
[pid 2360] close(8) = 0
[pid 2360] close(9) = 0
[pid 2360] time(NULL) = 1099173633
[pid 2360] write(7,
"\2\0\0\0\1\0\0\0\35\0\0\0\0\0\0\0\2\0\0\0\4\0\0\0\1\0\0"..., 65) = 65
[pid 2360] close(7) = 0
[pid 2360] poll([{fd=3, events=POLLRDNORM}], 1, 0) = 0
[pid 2360] accept(3, <unfinished ...>
[pid 2361] <... accept resumed> 0, NULL) = 7
[pid 2361] read(7, "\2\0\0\0\6\0\0\0\4\0\0\0", 12) = 12
[pid 2361] getsockopt(7, SOL_SOCKET, SO_PEERCRED,
"<\t\0\0\0\0\0\0\0\0\0\0", [12]) = 0
[pid 2361] read(7, "B\34\321\322", 4) = 4
[pid 2361] getpid() = 2361
[pid 2361] write(4, "2361: handle_request: request re"..., 67) = 67
[pid 2361] getpid() = 2361
[pid 2361] write(4, "2361: \tGETHOSTBYADDR (66.28.209."..., 37) = 37
[pid 2361] write(7,
"\2\0\0\0\1\0\0\0\35\0\0\0\0\0\0\0\2\0\0\0\4\0\0\0\1\0\0"..., 65) = 65
[pid 2361] close(7) = 0
[pid 2361] poll([{fd=3, events=POLLRDNORM}], 1, 0) = 0
[pid 2361] accept(3, <unfinished ...>
[pid 2357] <... poll resumed> [{fd=5, events=POLLIN}], 1, 2000) = 0
[pid 2357] getppid() = 2356
[pid 2357] poll( <unfinished ...>
[pid 2362] <... accept resumed> 0, NULL) = 7
[pid 2362] read(7, "\2\0\0\0\6\0\0\0\4\0\0\0", 12) = 12
[pid 2362] getsockopt(7, SOL_SOCKET, SO_PEERCRED,
"<\t\0\0\0\0\0\0\0\0\0\0", [12]) = 0
[pid 2362] read(7, "B\34\321\322", 4) = 4
[pid 2362] getpid() = 2362
[pid 2362] write(4, "2362: handle_request: request re"..., 67) = 67
[pid 2362] getpid() = 2362
[pid 2362] write(4, "2362: \tGETHOSTBYADDR (66.28.209."..., 37) = 37
[pid 2362] write(7,
"\2\0\0\0\1\0\0\0\35\0\0\0\0\0\0\0\2\0\0\0\4\0\0\0\1\0\0"..., 65) = 65
[pid 2362] close(7) = 0
[pid 2362] poll([{fd=3, events=POLLRDNORM}], 1, 0) = 0
[pid 2362] accept(3, <unfinished ...>
[pid 2357] <... poll resumed> [{fd=5, events=POLLIN}], 1, 2000) = 0
[pid 2357] getppid() = 2356
[pid 2357] poll( <unfinished ...>
<END OF TRACE>
Thanks for your help,
Cliff
Reply to: