multiple cups-polld running simultaneously

Bug #67680 reported by Mathieu Alorent
6
Affects Status Importance Assigned to Milestone
cupsys (Ubuntu)
New
Medium
Unassigned

Bug Description

hi,

I have to cups server in 2 different location. I have set up my master print server to retrieve printers of the second by adding this lines to /etc/cups/cups.d/browse.conf

"Browsing on
BrowsePoll jacinthe.seyssins.gripp.fr"

I can see and use the printers from the slave cups server...

the problem is that after a few days, the bandwith consumption growth gradually...

I've found that multiple IPP connection are established and multiple cups-poll process are running simultaneously.

mathieu@mistouflon:~$ netstat |grep ipp | grep jac
tcp 0 0 mistouflon.sorgue:40890 jacinthe.seyssins.g:ipp ESTABLISHED
tcp 0 472 mistouflon.sorgue:47368 jacinthe.seyssins.g:ipp ESTABLISHED
tcp 0 0 mistouflon.sorgue:47369 jacinthe.seyssins.g:ipp ESTABLISHED
tcp 0 0 mistouflon.sorgue:47367 jacinthe.seyssins.g:ipp ESTABLISHED
tcp 0 0 mistouflon.sorgue:47385 jacinthe.seyssins.g:ipp ESTABLISHED
tcp 0 489 mistouflon.sorgue:41092 jacinthe.seyssins.g:ipp ESTABLISHED
tcp 0 0 mistouflon.sorgue:43143 jacinthe.seyssins.g:ipp ESTABLISHED
tcp 0 0 mistouflon.sorgue:50994 jacinthe.seyssins.g:ipp ESTABLISHED

mathieu@mistouflon:~$ ps ax | grep cu
22939 ? Ss 76:10 gnome-cups-icon --sm-client-id default3
23496 ? S 0:16 cups-polld jacinthe.seyssins.gripp.fr 631 30 631
31935 ? SN 0:09 cups-polld jacinthe.seyssins.gripp.fr 631 30 631
 5219 ? SN 0:06 cups-polld jacinthe.seyssins.gripp.fr 631 30 631
13046 ? SN 0:04 cups-polld jacinthe.seyssins.gripp.fr 631 30 631
19678 ? SN 0:03 cups-polld jacinthe.seyssins.gripp.fr 631 30 631
24967 ? SN 0:02 cups-polld jacinthe.seyssins.gripp.fr 631 30 631
28033 ? SN 0:01 cups-polld jacinthe.seyssins.gripp.fr 631 30 631
30397 ? S 0:00 cups-polld jacinthe.seyssins.gripp.fr 631 30 631
30523 pts/1 S+ 0:00 grep cu

Stopping cups doesn't kill these processes :

mathieu@mistouflon:~$ sudo /etc/init.d/cupsys stop
 * Stopping Common Unix Printing System: cupsd [ ok ]
mathieu@mistouflon:~$ ps ax | grep cu
22939 ? Ss 76:10 gnome-cups-icon --sm-client-id default3
23496 ? S 0:16 cups-polld jacinthe.seyssins.gripp.fr 631 30 631
31935 ? SN 0:09 cups-polld jacinthe.seyssins.gripp.fr 631 30 631
 5219 ? SN 0:06 cups-polld jacinthe.seyssins.gripp.fr 631 30 631
13046 ? SN 0:04 cups-polld jacinthe.seyssins.gripp.fr 631 30 631
19678 ? SN 0:03 cups-polld jacinthe.seyssins.gripp.fr 631 30 631
24967 ? SN 0:02 cups-polld jacinthe.seyssins.gripp.fr 631 30 631
28033 ? SN 0:01 cups-polld jacinthe.seyssins.gripp.fr 631 30 631
30397 ? S 0:00 cups-polld jacinthe.seyssins.gripp.fr 631 30 631
30523 pts/1 S+ 0:00 grep cu

I have to kill them manually

mathieu@mistouflon:~$ sudo pkill cups-polld
mathieu@mistouflon:~$ ps ax | grep cu
22939 ? Ssl 76:10 gnome-cups-icon --sm-client-id default3
30532 pts/1 S+ 0:00 grep cu
mathieu@mistouflon:~$ sudo /etc/init.d/cupsys start
 * Starting Common Unix Printing System: cupsd [ ok ]
mathieu@mistouflon:~$ netstat |grep ipp | grep jac
tcp 0 0 mistouflon.sorgue:40890 jacinthe.seyssins.g:ipp TIME_WAIT
tcp 0 0 mistouflon.sorgue:47369 jacinthe.seyssins.g:ipp TIME_WAIT
tcp 0 0 mistouflon.sorgue:47367 jacinthe.seyssins.g:ipp TIME_WAIT
tcp 0 0 mistouflon.sorgue:47385 jacinthe.seyssins.g:ipp TIME_WAIT
tcp 0 420 mistouflon.sorgue:41112 jacinthe.seyssins.g:ipp ESTABLISHED
tcp 0 0 mistouflon.sorgue:41092 jacinthe.seyssins.g:ipp TIME_WAIT
tcp 0 0 mistouflon.sorgue:43143 jacinthe.seyssins.g:ipp TIME_WAIT
tcp 0 0 mistouflon.sorgue:50994 jacinthe.seyssins.g:ipp TIME_WAIT
mathieu@mistouflon:~$ netstat |grep ipp | grep jac
tcp 0 0 mistouflon.sorgue:41112 jacinthe.seyssins.g:ipp ESTABLISHED

is that normal ? is it a bug or a misconfiguration ?

regards
Mathieu

Revision history for this message
Matthew L. Dailey (matthew-l-dailey) wrote :

We were having the same problems here and it turned out that when cupsd was spawning off the cups-polld process, it was still running as root, so although cupsd was running as cupsys, cups-polld was running as root. When the init script killed cupsd (either though stop or restart), the cups-polld process was not killed. After many restarts, there could be several of these processes churning along in the background. The solution is (hopefully) simple. I've patched my init script to run the cupsd daemon initially as the cupsys user. I didn't experience any other issues related to this on our setups, but I'll continue testing. Our environment is Ubuntu Edgy with cupsys 1.2.4-2ubuntu3.

--- cupsys.orig 2006-10-09 12:54:23.000000000 -0400
+++ cupsys 2006-12-05 15:43:22.000000000 -0500
@@ -3,6 +3,7 @@
 PATH=/usr/local/sbin:/usr/local/bin:/sbin:/bin:/usr/sbin:/usr/bin
 DAEMON=/usr/sbin/cupsd
 NAME=cupsd
+CHUID=cupsys
 PIDFILE=/var/run/cups/$NAME.pid
 DESC="Common Unix Printing System"

@@ -46,7 +47,7 @@
          modprobe -q ppdev || true # for ISO-1284 device name detection
        fi

- start-stop-daemon --start --quiet --oknodo --pidfile "$PIDFILE" --exec $DAEMON
+ start-stop-daemon --start --quiet --oknodo --chuid ${CHUID} --pidfile "$PIDFILE" --exec $DAEMON
        log_end_msg $?
        ;;
   stop)
@@ -57,7 +58,7 @@
   restart|force-reload)
        log_begin_msg "Restarting $DESC: $NAME"
        if start-stop-daemon --stop --quiet --retry 5 --oknodo --pidfile $PIDFILE --name $NAME; then
- start-stop-daemon --start --quiet --pidfile "$PIDFILE" --exec $DAEMON
+ start-stop-daemon --start --quiet --chuid ${CHUID} --pidfile "$PIDFILE" --exec $DAEMON
        fi
        log_end_msg $?
        ;;

Revision history for this message
Mathieu Alorent (kumy) wrote :

Hi,

Thanks for your patch, I've tested it, but I get this messages in my logs (/var/log/cups/error_log)

E [06/Dec/2006:15:06:31 +0100] Unable to bind socket for address :::631 - Permission denied.
E [06/Dec/2006:15:06:31 +0100] Unable to bind socket for address 0.0.0.0:631 - Permission denied.
E [06/Dec/2006:15:06:31 +0100] cupsdStartBrowsing: Unable to bind broadcast socket - Permission denied.

I'll try to correct it in a few hours, when people will leave our office... I'll give you more informations later... :)

Regards
Mathieu

Revision history for this message
Mathieu Alorent (kumy) wrote :

I can't get it working :'(

If I use your patch, I can only print from the server. The printers are not polled to the clients.

Moreover, cups takes 100% of CPU when running like this.

with your patch, [cups-polld] is effectively running as cupsys
ps axu | grep cup
mathieu 21783 0.0 0.0 3912 768 pts/1 S+ 17:08 0:00 tail -f /var/log/cups/error_log
cupsys 23636 89.8 0.0 40208 4068 ? Rs 17:23 3:40 /usr/sbin/cupsd
cupsys 23637 0.0 0.0 18304 1600 ? S 17:23 0:00 cups-polld jacinthe.seyssins.gripp.fr 631 30 631

and without it, it runs as root :(
ps axu | grep cup
mathieu 21783 0.0 0.0 3912 768 pts/1 S+ 17:08 0:00 tail -f /var/log/cups/error_log
cupsys 24634 7.0 0.0 39936 3664 ? Ss 17:27 0:00 /usr/sbin/cupsd
root 24635 0.0 0.0 18300 1592 ? S 17:27 0:00 cups-polld jacinthe.seyssins.gripp.fr 631 30 631

So, i'm still using my crontab's workaround :
0 0 * * * sudo /etc/init.d/cupsys stop && sudo pkill cups-polld && sudo /etc/init.d/cupsys start

We're using Dapper and cupsys 1.2.2-0ubuntu0.6.06

Revision history for this message
Matthew L. Dailey (matthew-l-dailey) wrote :

After running with my patch for a while, I saw the same behavior - cupsd running at 100% CPU. In our environment, we're running only clients, so the inability to bind port 631 wasn't immediately a problem. So, it looks like my "quick fix" is a bust.

My next thought is that this might actually be a CUPS problem. I looked through the source code a bit and in scheduler/dirsvc.c, the poller is spawned with:
    if (cupsdStartProcess(polld, argv, envp, -1, -1, statusfds[1], -1,
                          0, &(pollp->pid)) < 0)

And the actual cupsdStartProcess function in scheduler/process.c takes these arguments:
cupsdStartProcess(
    const char *command, /* I - Full path to command */
    char *argv[], /* I - Command-line arguments */
    char *envp[], /* I - Environment */
    int infd, /* I - Standard input file descriptor */
    int outfd, /* I - Standard output file descriptor */
    int errfd, /* I - Standard error file descriptor */
    int backfd, /* I - Backchannel file descriptor */
    int root, /* I - Run as root? */
    int *pid) /* O - Process ID */

This would seem to indicate that the polld process shouldn't be spawned as root (argument 8 = 0 ), but it is. I'm not much of a C programmer, so I could be completely off-base here, but this seems to be at least close to the problem. I may post this to the CUPS list and see if anyone knows anything about it.

Revision history for this message
David Kågedal (dkagedal) wrote :

See bug #30965 for more infor about the 100% usage, and some notes about the lingering cups-polld processes.

I get 100% CPU usage without patching anything, I only have to enable BrowsePoll.

Maybe the reason for the 100% CPU usage is that it can't connect properly to the spawned cups-polld, because of socket permissions (just guessing here). This could explain why it's spinning in select().

Changed in cupsys:
importance: Undecided → Medium
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.