Bug 354071

I just tried this out, and it works for me in rawhide.  Here's how I tested it:

1. Fresh install with default CUPS configuration.
2. Disable networking by right-clicking on the nm-applet icon and unchecking the
box.
3. Stop CUPS:
/sbin/service cups stop
4. Remove cached remote printers:
rm -f /var/cache/cups/remote.cache
5. Start CUPS:
/sbin/service cups start

At this point, CUPS has never seen the network interface, and has no
recollection of any remote printers.

6. Start gedit and click Print...
7. Only locally-connected printers shown
8. Right-click on nm-applet icon and enable networking
9. Wait (up to 30 seconds -- this is the default BrowseInterval, and is how long
the remote print server might take to broadcast a browse packet)
10. Remote printers appear in print dialog

cups-1.3.3-3.fc8

Ok It happened to me again this morning.

I brought my laptop in this morning and NetworkManager hooked to the wired
network, and I get no printers listed.

Looking at the cups error log I see this error every minute.

E [05/Nov/2007:09:19:16 -0500] [cups-polld cups.boston.redhat.com:631] Unable to
connect to cups.boston.redhat.com on port 631: Host name lookup failure
E [05/Nov/2007:09:20:26 -0500] [cups-polld cups.boston.redhat.com:631] Unable to
connect to cups.boston.redhat.com on port 631: Host name lookup failure

I attempt to telnet to this port and I get it fine.  So name resolution is
working fine on the box.  I am not running nscd or named at the time I tried
this out.  The code is calling getaddrinfo so this seems to somehow have cached
some data/error and is not clearing itself up.

I think this is a bug in getaddrinfo.

BTW /etc/cups/cupsd.conf has the following line in it.

BrowsePoll cups.boston.redhat.com:631

Okay, I can reproduce *this* (with BrowsePoll).  getaddrinfo() doesn't seem to
be asking any nameserver in particular.  Here is what strace says cups-polld is
doing every 30s:

Process 5031 attached - interrupt to quit
restart_syscall(<... resuming interrupted call ...>) = 0
rt_sigaction(SIGPIPE, {SIG_IGN}, NULL, 8) = 0
socket(PF_NETLINK, SOCK_RAW, 0)         = 6
bind(6, {sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 0
getsockname(6, {sa_family=AF_NETLINK, pid=5031, groups=00000000}, [12]) = 0
sendto(6, "\24\0\0\0\26\0\1\3\251</G\0\0\0\0\0\0\0\0", 20, 0,
{sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 20
recvmsg(6, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000},
msg_iov(1)=[{"0\0\0\0\24\0\2\0\251</G\247\23\0\0\2\10\200\376\1\0\0\0\10\0\1\0\177\0\0\1"...,
4096}], msg_controllen=0, msg_flags=0}, 0) = 168
recvmsg(6, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000},
msg_iov(1)=[{"@\0\0\0\24\0\2\0\251</G\247\23\0\0\n\200\200\376\1\0\0\0\24\0\1\0\0\0\0\0"...,
4096}], msg_controllen=0, msg_flags=0}, 0) = 192
recvmsg(6, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000},
msg_iov(1)=[{"\24\0\0\0\3\0\2\0\251</G\247\23\0\0\0\0\0\0\1\0\0\0\24\0\1\0\0\0\0\0"...,
4096}], msg_controllen=0, msg_flags=0}, 0) = 20
close(6)                                = 0
open("/etc/hosts", O_RDONLY|0x80000 /* O_??? */) = 6
fstat(6, {st_mode=S_IFREG|0644, st_size=197, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) =
0x2aaaaadcc000
read(6, "# Do not remove the following li"..., 4096) = 197
read(6, "", 4096)                       = 0
close(6)                                = 0
munmap(0x2aaaaadcc000, 4096)            = 0
open("/etc/hosts", O_RDONLY|0x80000 /* O_??? */) = 6
fstat(6, {st_mode=S_IFREG|0644, st_size=197, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) =
0x2aaaaadcc000
read(6, "# Do not remove the following li"..., 4096) = 197
read(6, "", 4096)                       = 0
close(6)                                = 0
munmap(0x2aaaaadcc000, 4096)            = 0
socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 6
connect(6, {sa_family=AF_INET, sin_port=htons(53),
sin_addr=inet_addr("0.0.0.0")}, 28) = 0
fcntl(6, F_GETFL)                       = 0x2 (flags O_RDWR)
fcntl(6, F_SETFL, O_RDWR|O_NONBLOCK)    = 0
poll([{fd=6, events=POLLOUT, revents=POLLOUT}], 1, 0) = 1
sendto(6, "\22q\1\0\0\1\0\0\0\0\0\0\10cyberelk\3elk\0\0\34\0\1", 30,
MSG_NOSIGNAL, NULL, 0) = 30
poll([{fd=6, events=POLLIN, revents=POLLERR}], 1, 5000) = 1
close(6)                                = 0
socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 6
connect(6, {sa_family=AF_INET, sin_port=htons(53),
sin_addr=inet_addr("0.0.0.0")}, 28) = 0
fcntl(6, F_GETFL)                       = 0x2 (flags O_RDWR)
fcntl(6, F_SETFL, O_RDWR|O_NONBLOCK)    = 0
poll([{fd=6, events=POLLOUT, revents=POLLOUT}], 1, 0) = 1
sendto(6, "\22q\1\0\0\1\0\0\0\0\0\0\10cyberelk\3elk\0\0\34\0\1", 30,
MSG_NOSIGNAL, NULL, 0) = 30
poll([{fd=6, events=POLLIN, revents=POLLERR}], 1, 5000) = 1
close(6)                                = 0
socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 6
connect(6, {sa_family=AF_INET, sin_port=htons(53),
sin_addr=inet_addr("0.0.0.0")}, 28) = 0
fcntl(6, F_GETFL)                       = 0x2 (flags O_RDWR)
fcntl(6, F_SETFL, O_RDWR|O_NONBLOCK)    = 0
poll([{fd=6, events=POLLOUT, revents=POLLOUT}], 1, 0) = 1
sendto(6, "\231\'\1\0\0\1\0\0\0\0\0\0\10cyberelk\3elk\3elk\0\0\34"..., 34,
MSG_NOSIGNAL, NULL, 0) = 34
poll([{fd=6, events=POLLIN, revents=POLLERR}], 1, 5000) = 1
close(6)                                = 0
socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 6
connect(6, {sa_family=AF_INET, sin_port=htons(53),
sin_addr=inet_addr("0.0.0.0")}, 28) = 0
fcntl(6, F_GETFL)                       = 0x2 (flags O_RDWR)
fcntl(6, F_SETFL, O_RDWR|O_NONBLOCK)    = 0
poll([{fd=6, events=POLLOUT, revents=POLLOUT}], 1, 0) = 1
sendto(6, "\231\'\1\0\0\1\0\0\0\0\0\0\10cyberelk\3elk\3elk\0\0\34"..., 34,
MSG_NOSIGNAL, NULL, 0) = 34
poll([{fd=6, events=POLLIN, revents=POLLERR}], 1, 5000) = 1
close(6)                                = 0
socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 6
connect(6, {sa_family=AF_INET, sin_port=htons(53),
sin_addr=inet_addr("0.0.0.0")}, 28) = 0
fcntl(6, F_GETFL)                       = 0x2 (flags O_RDWR)
fcntl(6, F_SETFL, O_RDWR|O_NONBLOCK)    = 0
poll([{fd=6, events=POLLOUT, revents=POLLOUT}], 1, 0) = 1
sendto(6, "\22\21\1\0\0\1\0\0\0\0\0\0\10cyberelk\3elk\0\0\1\0\1", 30,
MSG_NOSIGNAL, NULL, 0) = 30
poll([{fd=6, events=POLLIN, revents=POLLERR}], 1, 5000) = 1
close(6)                                = 0
socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 6
connect(6, {sa_family=AF_INET, sin_port=htons(53),
sin_addr=inet_addr("0.0.0.0")}, 28) = 0
fcntl(6, F_GETFL)                       = 0x2 (flags O_RDWR)
fcntl(6, F_SETFL, O_RDWR|O_NONBLOCK)    = 0
poll([{fd=6, events=POLLOUT, revents=POLLOUT}], 1, 0) = 1
sendto(6, "\22\21\1\0\0\1\0\0\0\0\0\0\10cyberelk\3elk\0\0\1\0\1", 30,
MSG_NOSIGNAL, NULL, 0) = 30
poll([{fd=6, events=POLLIN, revents=POLLERR}], 1, 5000) = 1
close(6)                                = 0
socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 6
connect(6, {sa_family=AF_INET, sin_port=htons(53),
sin_addr=inet_addr("0.0.0.0")}, 28) = 0
fcntl(6, F_GETFL)                       = 0x2 (flags O_RDWR)
fcntl(6, F_SETFL, O_RDWR|O_NONBLOCK)    = 0
poll([{fd=6, events=POLLOUT, revents=POLLOUT}], 1, 0) = 1
sendto(6, "t|\1\0\0\1\0\0\0\0\0\0\10cyberelk\3elk\3elk\0\0\1"..., 34,
MSG_NOSIGNAL, NULL, 0) = 34
poll([{fd=6, events=POLLIN, revents=POLLERR}], 1, 5000) = 1
close(6)                                = 0
socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 6
connect(6, {sa_family=AF_INET, sin_port=htons(53),
sin_addr=inet_addr("0.0.0.0")}, 28) = 0
fcntl(6, F_GETFL)                       = 0x2 (flags O_RDWR)
fcntl(6, F_SETFL, O_RDWR|O_NONBLOCK)    = 0
poll([{fd=6, events=POLLOUT, revents=POLLOUT}], 1, 0) = 1
sendto(6, "t|\1\0\0\1\0\0\0\0\0\0\10cyberelk\3elk\3elk\0\0\1"..., 34,
MSG_NOSIGNAL, NULL, 0) = 34
poll([{fd=6, events=POLLIN, revents=POLLERR}], 1, 5000) = 1
close(6)                                = 0
write(2, "ERROR: [cups-polld cyberelk.elk:"..., 109) = 109
rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
rt_sigaction(SIGCHLD, NULL, {SIG_DFL}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
nanosleep({30, 0},  <unfinished ...>
Process 5031 detached

Running 'tcpdump -nilo' confirms that the local 0.0.0.0 name query packets that
get sent are just getting dropped; nothing is listening on port 53 on this machine.

However, /etc/resolv.conf points to a perfectly good name server, 192.168.1.1. 
This name server happened to be down (in fact, the network interface for
192.168.1.0/24 was down) when cups-polld started.  Does glibc cache information
about unreachable name servers or something?

Based on the date this bug was created, it appears to have been reported
during the development of Fedora 8. In order to refocus our efforts as
a project we are changing the version of this bug to '8'.

If this bug still exists in rawhide, please change the version back to
rawhide.
(If you're unable to change the bug's version, add a comment to the bug
and someone will change it for you.)

Thanks for your help and we apologize for the interruption.

The process we're following is outlined here:
http://fedoraproject.org/wiki/BugZappers/F9CleanUp

We will be following the process here:
http://fedoraproject.org/wiki/BugZappers/HouseKeeping to ensure this
doesn't happen again.

Applications do not automatically notice if /etc/resolv.conf changes.  Only nscd does.  The overhead is simply to high.  If somehow the program starts up when no /etc/resolv.conf file exists something like described in the comments happens.  It might be worthwhile to determine when /etc/resolv.conf was read and why it wasn't there.

There is one alternative.  Programs can invalidate their resolver setting by calling _res_init().  This has to be done by the program itself?  Does cups do this?  When?

I don't think there is anything wrong in glibc.  If you want the change of a nameserver happen automatically and transparently then use nscd.

Filed upstream with patch.

Ulrich: is res_init() (no underscores) from libresolv sufficient, or does it need to be __res_init()?

(In reply to comment #8)
> Ulrich: is res_init() (no underscores) from libresolv sufficient, or does it
> need to be __res_init()?

Doesn't matter, see <resolv.h>.  res_init is mapped to __res_init.  So, use res_init, it's perhaps a bit more correct.

Next F-9 update will fix this.

cups-1.3.9-1.fc9 has been submitted as an update for Fedora 9.
http://admin.fedoraproject.org/updates/cups-1.3.9-1.fc9

cups-1.3.9-1.fc9 has been pushed to the Fedora 9 stable repository.  If problems still persist, please make note of it in this bug report.

Reopening as this still fails with 1.3.9-1.fc9.  The patch got broken after being sent upstream it seems.

cups-1.3.9-4.fc10 has been submitted as an update for Fedora 10.
http://admin.fedoraproject.org/updates/cups-1.3.9-4.fc10

cups-1.3.9-2.fc9 has been submitted as an update for Fedora 9.
http://admin.fedoraproject.org/updates/cups-1.3.9-2.fc9

cups-1.3.9-4.fc10 has been pushed to the Fedora 10 testing repository.  If problems still persist, please make note of it in this bug report.
 If you want to test the update, you can install it with 
 su -c 'yum --enablerepo=updates-testing update cups'.  You can provide feedback for this update here: http://admin.fedoraproject.org/updates/F10/FEDORA-2008-10895

cups-1.3.9-2.fc9 has been pushed to the Fedora 9 testing repository.  If problems still persist, please make note of it in this bug report.
 If you want to test the update, you can install it with 
 su -c 'yum --enablerepo=updates-testing-newkey update cups'.  You can provide feedback for this update here: http://admin.fedoraproject.org/updates/F9/FEDORA-2008-10917

cups-1.3.9-4.fc10 has been pushed to the Fedora 10 stable repository.  If problems still persist, please make note of it in this bug report.

cups-1.3.9-2.fc9 has been pushed to the Fedora 9 stable repository.  If problems still persist, please make note of it in this bug report.

*** Bug 670494 has been marked as a duplicate of this bug. ***