[Gutsy SRU Request] Bad interaction with avahi

(1) has to be fixed in the avahi-daemon package. The startup links for /etc/init.d/avahi-daemon have to be renamed from S24avahi-daemon to S18avahi-daemon to start before CUPS (s19cupsys). Moving cupsys is not possible as it has to start before Samba, otherwise sharing printers via Samba will stop working. See current start order here:

till@till-laptop:~$ ls /etc/rc5.d/*cupsys*
/etc/rc5.d/S19cupsys
till@till-laptop:~$ ls /etc/rc5.d/*samba*
/etc/rc5.d/S20samba
till@till-laptop:~$ ls /etc/rc5.d/*avahi*
/etc/rc5.d/S24avahi-daemon
till@till-laptop:~$

(2) I cannot reproduce this on both Gutsy and Hardy.

If I force a logrotate

sudo /usr/sbin/logrotate -f /etc/logrotate.conf

I still get my local queues being mDNS-broadcasted. Check this with

avahi-browse -k -t -v -r -a

(You need to install the "avahi-utils" from universe to do so).

Can you also do this test and in addition post your /etc/cups/cupsd.conf?

Another question for (2): If your Mac clients do not see your printers, can you run

lpstat -r
lpstat -p

on your Linux server to check whether your CUPS daemon is working? Can you print from your Linux server or from a Linux client?

Can you bring CUPS into debug mode as shown on

https://wiki.ubuntu.com/DebuggingPrintingProblems

and then the next morning when the Macs stop seeing your printers again post your

Can you post your /var/log/cups/error_log

here?

I'll try to get more information on (2). I just ran "run-parts --report /etc/cron.daily", the printers still were in mdns afterwards. The printers do disappear at 06:25 every day though, i.e. at cron.daily time.

Note that manually running the daily cron job does not get your logs rotated. logrotate managesthe time intervals by itself, and so if the cron job runs more frequently, for example by manually running it, logrotate will still only rotate the CUPS logs only once in 24 hours, according to the configuration in /etc/logrotate.d/cupsys. To really force a rotation of the logs do

sudo /usr/sbin/logrotate -f /etc/logrotate.conf

Can you tell whether this keeps your printers visible or makes them disappearing?

Can you also post your /etc/cups/cuspd.conf, as I have asked for earlier?

Ah ok, forcing log rotation _makes_ the printers disappear from mdns!
The printers are still available on the server but are gone from all clients (including Linux).

The error_log shows a bad file descriptor error:

I [03/Dec/2007:00:11:54 +0100] Saving job cache file "/var/cache/cups/job.cache"...
D [03/Dec/2007:00:11:54 +0100] Discarding unused printer-state-changed event...
E [03/Dec/2007:00:11:54 +0100] cupsdSendBrowseList: sendto failed for browser 1 - Bad file descriptor.
I [03/Dec/2007:00:11:54 +0100] Loaded MIME database from '/usr/share/cups/mime:/etc/cups': 36 types, 40 filters...

I can reproduce the problem (2) and it looks like an upstream bug of CUPS.

For actually reproducing it you do not need to rotate all your log files. It is enough to do the following:

Edit /etc/cups/cupsd.conf, so that you have a line

BrowseAddress 192.168.1.255:631

The IP address must be the broadcast address of your local network, see "Bcast:" entry in the output of "ifconfig". Comment out (Preceed with a "#") any other "BrowseAddress" line. Change the "LogLevel" line to be

LogLevel debug

Now there are two methods to restart CUPS. Whenever you do

sudo /etc/init.d/cupsys restart

the CUPS daemon is actually stopped and restarted. In this case the above configuration works well and you printers continue to get broadcasted. Check with "lpstat -p" on a Linux or Mac client or with "avahi-browse -k -t -v -r -a" on any machine in your network (including the CUPS server).

But whenever you do

sudo /etc/init.d/cupsys force-reload

and that is what logrotate does, the CUPS daemon gets simply a HUP signal (like "sudo killall -HUP cupsd") and in this mode the above configuration fails with the error which you have seen in your error_log.

To work around this bug, use either

BrowseAddress @LOCAL

in case your printers should be advertised on all your local networks or in the case that you have only one local network or lines like

BrowseAddress @IF(eth0)

for each of the interfaces to which the printers should be advertised for the case they should be available only in selected networks. Do a full restart of the CUPS daemon after editing cupsd.conf:

sudo /etc/init.d/cupsys restart

Reported upstream as

http://www.cups.org/str.php?L2618

The broadcast address is correct (see the 'lan' interface below). The reason I'm not using @LOCAL or @IF(lan) is a different bug (http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=343535). My network setup has changed a bit since then but the bug apparently still exists: if i use @LOCAL or @IF(lan), I get no broadcast packets over 631.

$ ip a s
1: lo: <LOOPBACK,UP,10000> mtu 16436 qdisc noqueue
    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
    inet 127.0.0.1/8 scope host lo
2: dsl: <BROADCAST,MULTICAST,UP,10000> mtu 1500 qdisc pfifo_fast qlen 1000
    link/ether 00:40:f4:8b:2d:15 brd ff:ff:ff:ff:ff:ff
3: lan: <BROADCAST,MULTICAST,UP,10000> mtu 1500 qdisc pfifo_fast qlen 1000
    link/ether 00:40:f4:8b:2d:14 brd ff:ff:ff:ff:ff:ff
    inet 192.168.1.1/24 brd 192.168.1.255 scope global lan
4: unused: <BROADCAST,MULTICAST> mtu 1500 qdisc noop qlen 1000
    link/ether 00:40:f4:8b:2d:13 brd ff:ff:ff:ff:ff:ff
5: modem: <BROADCAST,MULTICAST,UP,10000> mtu 1500 qdisc pfifo_fast qlen 1000
    link/ether 00:40:f4:8b:2d:12 brd ff:ff:ff:ff:ff:ff
    inet 192.168.8.2/30 brd 192.168.8.3 scope global modem
14: ppp0: <POINTOPOINT,MULTICAST,NOARP,UP,10000> mtu 1456 qdisc htb qlen 3
    link/ppp
    inet 217.86.173.33 peer 217.5.98.2/32 scope global ppp0
% ip r s
217.5.98.2 dev ppp0 proto kernel scope link src 217.86.173.33
192.168.8.0/30 dev modem proto kernel scope link src 192.168.8.2
192.168.1.0/24 dev lan proto kernel scope link src 192.168.1.1
default dev ppp0 scope link

The machine also runs shorewall but there are no rules that limit traffic on the lan interface.
CUPS' error_log doesn't show any error message when trying @LOCAL or IF(lan). Just a few debug lines:
I [03/Dec/2007:21:22:15 +0100] Listening to 127.0.0.1:631 (IPv4)
I [03/Dec/2007:21:22:15 +0100] Listening to 192.168.1.1:631 (IPv4)
I [03/Dec/2007:21:22:15 +0100] Listening to /var/run/cups/cups.sock (Domain)
...
I [03/Dec/2007:21:22:15 +0100] Listening to 127.0.0.1:631 on fd 8...
I [03/Dec/2007:21:22:15 +0100] Listening to 192.168.1.1:631 on fd 9...
I [03/Dec/2007:21:22:15 +0100] Listening to /var/run/cups/cups.sock on fd 10...
I [03/Dec/2007:21:22:15 +0100] Resuming new connection processing...
D [03/Dec/2007:21:22:16 +0100] cupsdNetIFUpdate: "lo" = localhost...
D [03/Dec/2007:21:22:16 +0100] cupsdNetIFUpdate: "lan" = server.jknet...
D [03/Dec/2007:21:22:16 +0100] cupsdNetIFUpdate: "modem" = 192.168.8.2...
D [03/Dec/2007:21:22:16 +0100] cupsdNetIFUpdate: "ppp0" = 217.86.173.33...

Notably absent from this log is a line like:

I [03/Dec/2007:21:23:52 +0100] Sending browsing info to 192.168.1.255:631 (IPv4)

I only get that when specifying the broadcast address directly.

The problem of @LOCAL and @IF is another upstream bug which can be caused by your renaming of the interfaces to "lan", "wifi", ...

Okease file an upstream bug on

http://www.cups.org/str.php

Problem (2) got fixed upstream. See

http://www.cups.org/str.php?L2618

The patch (SVN rev 7111) is small and simple, so a fix of the Ubuntu CUPS package before the next upstream release or even an SRU for older Ubuntu versions is possible.

avahi (0.6.21-4ubuntu1) hardy; urgency=low

  * debian/rules, debian/avahi-daemon.postinst: Start the avahi-daemon before
    CUPS so that CUPS-shared printers appears in mDNS (LP: #173470, item 1).

 -- Till Kamppeter <email address hidden> Sun, 9 Dec 2007 23:33:41 +0000

cupsys (1.3.4-2ubuntu3) hardy; urgency=low

  * debian/patches/cups-stops-broadcasting-on-HUP-with-explicit-BrowseAddress.dpatch:
    CUPS stopped broadcasting on a HUP signal when using a fixed
    BrowseAddress (CUPS STR #2618, LP: #173470).

 -- Till Kamppeter <email address hidden> Mon, 10 Dec 2007 0:01:06 +0000

Till, it would be great if the avahi start change could be backported to Gutsy as a bugfix. Thanks.

Here is a debdiff with the cups patch from Hardy.

A debdiff for Gutsy's Avahi package.

Bruce, thank you for the debdiffs, I have now added the other needed items to make an SRU request from this report, especially the test case in the initial description.

Thanks, I didn't realise there was now a process.

I have uploaded the fixed packages to my PPA, only modification is the ~ppa1 suffix to make sure the official updates supersede them.

avahi sponsored and accepted into gutsy-proposed.

An older cupsys is still in -proposed and needs verification and moving to -updates first before we stack up yet another -proposed upload.

I uploaded the cupsys side of the fix to gutsy-proposed. Please test and give feedback here, thanks!

I have been talking with Martin on bug 152537 (see my original post there from 05/01/2008). Martin pointed out that my problem was more likely to be this bug.

I installed the Gutsy -proposed versions of Avahi on 05/01/2008 and it did not fix the problem.

This morning upon starting the office machines I verified printing - everything worked. I do not know why because I have made no changes, no updates to have caused this change in behaviour. Martin suggests it might by a race condition. At lunchtime I'll shut down the PCs and restart a few times to see what happens.

After my initial verification I have installed Kees' -updates and -proposed from this morning. Printing still works. I suspect that this was before Martin's upload of this morning.

Hilary

So, after multiple restarts of the print server and clients, everything continues to work fine.

This is before applying the suggested changes to CUPSYS of this morning, which I propose to do today. I'll report back.

-proposed upgrade to cupsys 1.3.2-1ubuntu7.4

Applied to server, client reboot - printing from client works
Applied to server, applied to client, client reboot - printing from client works
Reboot server, reboot client - printing from client works.

Printing from server works in all cases.

One thing I did notice is that the 'print test page' setting in the printing dialog remains active across multiple reboots of the client and continually prints test pages until disactivated. I would have thought that once selected and the confirmation dialog accepted, it should only print one test page and then stop the test cycle.

Thank you for the fix - it will save me a lot of hassle from users.

Hilary

Hilary, thanks for testing!

Hilary, did you also upgrade avahi?

Martin, I installed the -proposed versions of Avahi on 05/01/2008 and they did not fix the problem. If there have been Avahi updates since, I have installed them by default but didn't notice them. See my post above 09/01/2008. I still don't know why everything started suddenly to work, with apparantly no action on my part!

This morning I installed the 1.3.2-1ubuntu7.5 version on the server, printing remains active from the clients.

Hilary, is CUPS still starting before Avahi starts? Can you post the output of

ls -l /etc/init.d

here?

Hilary, can you post the output of

ls /etc/rc5.d/

here?

Till, here is the output of,

ls -l /etc/init.d

total 432
-rwxr-xr-x 1 root root 2701 2007-03-14 08:07 acpid
-rwxr-xr-x 1 root root 762 2007-08-31 04:48 acpi-support
-rwxr-xr-x 1 root root 9534 2007-09-04 04:52 alsa-utils
-rwxr-xr-x 1 root root 1084 2007-03-05 07:38 anacron
-rwxr-xr-x 1 root root 1460 2007-08-29 13:08 apcupsd
-rwxr-xr-x 1 root root 1667 2007-05-23 14:59 apmd
-rwxr-xr-x 1 root root 2793 2007-10-14 11:48 apparmor
-rwxr-xr-x 1 root root 3024 2007-03-10 11:16 apport
-rwxr-xr-x 1 root root 969 2007-02-20 14:41 atd
-rwxr-xr-x 1 root root 2460 2007-10-04 17:02 avahi-daemon
-rwxr-xr-x 1 root root 1109 2005-10-27 14:15 binfmt-support
-rwxr-xr-x 1 root root 6557 2007-03-30 16:48 bluetooth
-rwxr-xr-x 1 root root 3597 2007-04-10 23:45 bootclean
-rwxr-xr-x 1 root root 2121 2007-04-10 23:45 bootlogd
-rwxr-xr-x 1 root root 1768 2007-10-04 13:17 bootmisc.sh
-rwxr-xr-x 1 root root 1383 2007-03-27 14:37 brltty
-rwxr-xr-x 1 root root 2887 2007-04-10 23:45 checkfs.sh
-rwxr-xr-x 1 root root 9875 2007-04-10 23:45 checkroot.sh
-rwxr-xr-x 1 root root 2941 2007-08-04 00:21 consolekit
-rwxr-xr-x 1 root root 6355 2007-05-30 14:29 console-screen.sh
-rwxr-xr-x 1 root root 1612 2007-04-10 17:15 console-setup
-rwxr-xr-x 1 root root 1761 2006-12-20 15:46 cron
-rwxr-xr-x 1 root root 1937 2007-11-01 17:22 cupsys
-rwxr-xr-x 1 root root 4192 2007-10-05 13:44 dbus
-rwxr-xr-x 1 root root 1497 2007-06-12 16:46 dhcdbd
-rwxr-xr-x 1 root root 1223 2007-06-22 06:55 dns-clean
-rwxr-xr-x 1 root root 3136 2007-04-10 22:41 gdm
-rwxr-xr-x 1 root root 6607 2007-10-01 03:01 glibc.sh
-rwxr-xr-x 1 root root 2294 2007-10-08 20:46 hal
-rwxr-xr-x 1 root root 1228 2007-04-10 23:45 halt
-rwxr-xr-x 1 root root 5137 2005-04-21 12:10 hdparm
-rwxr-xr-x 1 root root 909 2007-04-10 23:45 hostname.sh
-rwxr-xr-x 1 root root 3576 2007-09-30 02:43 hotkey-setup
-rwxr-xr-x 1 root root 4569 2007-10-03 06:48 hwclockfirst.sh
-rwxr-xr-x 1 root root 4568 2007-10-03 06:48 hwclock.sh
-rwxr-xr-x 1 root root 1304 2007-06-03 00:48 keyboard-setup
-rwxr-xr-x 1 root root 944 2007-04-10 23:45 killprocs
-rwxr-xr-x 1 root root 1752 2007-09-17 22:54 klogd
-rwxr-xr-x 1 root root 2285 2007-09-19 01:01 laptop-mode
-rwxr-xr-x 1 root root 632 2007-07-13 14:57 libpam-foreground
-rwxr-xr-x 1 root root 349 2007-04-13 20:27 linux-restricted-modules-common
-rwxr-xr-x 1 root root 748 2006-01-23 19:47 loopback
-rwxr-xr-x 1 root root 1050 2007-07-28 21:52 makedev
-rwxr-xr-x 1 root root 1399 2007-04-03 16:03 module-init-tools
-rwxr-xr-x 1 root root 596 2007-10-04 13:17 mountall-bootclean.sh
-rwxr-xr-x 1 root root 2430 2007-10-04 13:17 mountall.sh
-rwxr-xr-x 1 root root 1465 2007-10-04 13:17 mountdevsubfs.sh
-rwxr-xr-x 1 root root 1460 2007-10-04 13:17 mountkernfs.sh
-rwxr-xr-x 1 root root 594 2007-10-04 13:17 mountnfs-bootclean.sh
-rwxr-xr-x 1 root root 1244 2007-10-04 13:17 mountoverflowtmp
-rwxr-xr-x 1 root root 2689 2007-04-10 23:45 mtab.sh
-rwxr-xr-x 1 root root 1772 2007-05-08 12:33 networking
-rwxr-xr-x 1 root root 5467 2007-08-13 14:57 nfs-common
-rwxr-xr-x 1 root root 4388 2007-08-13 14:57 nfs-kernel-server
-rwxr-xr-x 1 root root 860 2005-10-29 04:48 nvidia-kernel
-rwxr-xr-x 1 root root 2351 2007-03-07 22...

.. and here is the output of,

ls /etc/rc5.d/

README S11klogd S18portmap S20hotkey-setup S20powernowd S41apcupsd S98usplash
S05vbesave S12dbus S19cupsys S20makedev S20rsync S89anacron S99acpi-support
S10acpid S12hal S19spamassassin S20nfs-common S22consolekit S89atd S99laptop-mode
S10sysklogd S13gdm S20apmd S20nfs-kernel-server S24dhcdbd S89cron S99rc.local
S10xserver-xorg-input-wacom S18avahi-daemon S20apport S20nvidia-kernel S25bluetooth S90binfmt-support S99rmnologin

The fix on avahi only corrects the boot order so that avahi is started before CUPS during the system boot. Please reboot your system to test whether this will really happen now.

Avahi copied to -updates.

Copied to gutsy-updates.

After the most recent round of gutsy updates, CUPS fails to start on boot.

https://bugs.launchpad.net/ubuntu/+bug/183652

Any relation to this bugfix?

The previous SRU has led to bug 183652, so the change has been reverted. We won't touch this again in gutsy for now.

Since the cause for the crash is now understood and fixed (bug 183652), this got re-fixed in gutsy-proposed and needs another round of verification.

Was tested in bug 183652. Copied to gutsy-updates.