Description of problem: If I symlink /lib/systemd/system/printer.target into /etc/systemd/system/multi-user.target.wants and reboot, cups will start on boot, as expected. However, it will only listen to localhost interfaces, although it has other interfaces configured in /etc/cups/cupsd.conf. This then prevents anyone from printing to this network print server, until something touches port 631 locally (i.e. nc -z localhost 631). Version-Release number of selected component (if applicable): cups-1.5.0-22.fc16.x86_64 How reproducible: Always. Steps to Reproduce: 1. Require printer.target in multi-user.target. 2. Reboot. Actual results: Cups not listening on network interfaces other than localhost. Expected results: This is a network print server. All ports 631 should be open. Additional info: This worked in F-15.
Please show the output of: systemctl status cups.service systemctl status cups.socket
Just after boot: ------------------------ [root@box ~]# systemctl status cups.service cups.service - CUPS Printing Service Loaded: loaded (/lib/systemd/system/cups.service; enabled) Active: active (running) since Fri, 25 Nov 2011 08:47:18 +1100; 1min 48s ago Main PID: 788 (cupsd) CGroup: name=systemd:/system/cups.service └ 788 /usr/sbin/cupsd -f [root@box ~]# systemctl status cups.socket cups.socket - CUPS Printing Service Sockets Loaded: loaded (/lib/systemd/system/cups.socket; enabled) Active: active (listening) since Fri, 25 Nov 2011 08:47:17 +1100; 1min 54s ago CGroup: name=systemd:/system/cups.socket ------------------------ Note only listening on localhost: ------------------------ [root@box ~]# netstat -anp | grep 631 tcp 0 0 127.0.0.1:631 0.0.0.0:* LISTEN 788/cupsd tcp 0 0 :::631 :::* LISTEN 1/init udp 0 0 0.0.0.0:631 0.0.0.0:* 788/cupsd ------------------------ If I then restart cups: ------------------------ [root@box ~]# service cups restart Redirecting to /bin/systemctl restart cups.service [root@box ~]# netstat -anp | grep 631 tcp 0 0 <eth0-IP>:631 0.0.0.0:* LISTEN 1714/cupsd tcp 0 0 127.0.0.1:631 0.0.0.0:* LISTEN 1714/cupsd tcp 0 0 :::631 :::* LISTEN 1/init tcp 0 0 ::1:49207 ::1:631 TIME_WAIT - udp 0 0 0.0.0.0:631 0.0.0.0:* 1714/cupsd ------------------------ So, clearly, on boot that other interface is not listened to, which is preventing people from printing to this network print server. If I execute "service cups stop", followed by "nc -z localhost 631", I will also get cups to listen to eth0 IP address. I wonder whether this has anything to do with /etc/hosts (although I do not see why it should - the cupsd.conf should be obeyed here). The "box" is not listed under localhost entries - only under the entry for eth0 IP.
It sounds like cupsd on the server is not picking up the fact that a network interface has been brought up. Do you see this every time? It would be really useful if you could run this command: su -c 'cupsctl LogLevel=debug2' This will cause cupsd to log much more information in /var/log/cups/error_log, including which network interfaces it believes itself to be using. Note that the act of changing this configuration option will effectively restart the service, so you may need to reboot in order to see the problem occur again. When it does occur again, please attach /var/log/cups/error_log. You might need to use 'xz' to compress it first. To turn off debugging, run: su -c 'cupsctl --no-debug-logging'
*** Bug 758906 has been marked as a duplicate of this bug. ***
Created attachment 541126 [details] gzipped coly of /var/log/cups.ewrror_log This is a gzipped form of /var/log/cups/error_log after running: swu -c 'cupsctl LogLevel=debug2 Yes cient printing fails every time until I run : systemctl restart cups.service I tried running thet command a part of: .bash_profile and that did not work
Corrected version of comment above: Created attachment 541126 [details] gzipped copy of /var/log/cups.error_log This is a gzipped form of /var/log/cups/error_log after running: su -c 'cupsctl LogLevel=debug2 Yes cient printing fails every time until I run : systemctl restart cups.service I tried running thet command a part of: .bash_profile and that did not work
Thank you Aaron for running that. I'll just answer Tim's question about reproducibility: it happens every time - no exceptions.
Aaron: could you please attach /etc/cups/cupsd.conf? Thanks.
Created attachment 541606 [details] Contents of /etc/cupsd.conf gzipped
Thanks. This is the problem: d [06/Dec/2011:00:20:30 -0600] select_timeout(0): 29 seconds to send browse update d [06/Dec/2011:00:20:32 -0600] select_timeout(0): 27 seconds to send browse update d [05/Dec/2011:18:20:39 -0600] select_timeout(0): 21620 seconds to send browse update d [05/Dec/2011:18:21:02 -0600] select_timeout(0): 21597 seconds to send browse update d [05/Dec/2011:18:22:02 -0600] select_timeout(0): 21537 seconds to send browse update Notice the timestamps: time has gone backwards between lines 2 and 3. So, either the system clock battery is flat or something is messing with the system time. My guess would be the clock battery. Bojan: perhaps you could run the same test as in comment #3, and we can see if it is a similar symptom or something different?
I see two problems with the cause being the system clock battery (don't you really mean the hardware clock battery). 1. When the hardware clock battery is low, normally you find that the system time becomes erratic. On my machine the system time and therefore the hardware time stays correct. 2, I ran the error_log test on Dec 5. So the changing of the timestamp to Dec 6 was really periodic instances if the time jumping forward. Despite oscillating between Dec 5 and Dec 6 the timestamps remain at the same time range on each day. So it seems strange that after the timestamps jump forward, when they jump back they jump to a time that matches where it left off on that run of cups, and vice verse. It seems to me that something is messing with the system time, but in a controlled fashion.
Do you have e.g. ntpd running?
(In reply to comment #13) > Do you have e.g. ntpd running? $ chronyc sources 210 Number of sources = 4 MS Name/IP address Stratum Poll LastRx Last sample ============================================================================ ^+ resolver02.as24220.net 2 10 496 -2697us[-2731us] +/- 59ms ^* a.pool.ntp.uq.edu.au 2 10 493 -144us[ -178us] +/- 462ms ^+ 119.148.74.67 3 6 52 +106ms[ +106ms] +/- 196ms ^+ pond.thecave.ws 2 10 634 -110us[ -144us] +/- 225ms
(In reply to comment #11) > So, either the system clock battery is flat or something is messing with the > system time. My guess would be the clock battery. Also, the hardware could be running UTC time, right? So, when chrony kicks in, it could be setting the system time to whatever is the local time. See, that time change is almost exactly 6 hours: 21620 / 3600 = 6.005555556 So, this is not an error. It's probably Aarons time being set by chrony or ntp.
Well I found a sort of solution to my printing problem. ntpd was not running. In fact it was not installed. After installation I enabled it and started it with systemctl. Now the following happens: 1. If I just reboot the server, printing does not work. 2. However as soon as I login to the server printing begins to wprk from the client. 3. If I log out from the server printing still works from the client. So a solution has been found to my problem . Thank you Tim. But does anyone know why I have to log in to the server for printing to start working. Do you need an account on a server for remote printing to work for you?
Created attachment 542362 [details] cupsd.conf
Created attachment 542364 [details] cups error, with debug at 2 I obtained this file by running "cupsctl LogLevel=debug2" as root, rebooting the system and then disabling debugging after boot with "cupsctl --no-debug-logging". Note that I checked whether cups listened on my eth0 interface after boot and, as expected, it did not.
As before, this brings up cups on my eth0 interface: nc -z localhost 631
From the error log file: --------------- E [08/Dec/2011:15:25:38 +1100] Unable to bind socket for address <IP-range>.1:631 - Cannot assign requested address. --------------- My guess is that this interface was not up at that time. So, the question is, how do we make cups require network interfaces to come up? Note, I'm not using NetworkManager, but the old network service to bring up interfaces. This is a server, so there are no dynamic interfaces or anything like that that NM would have to deal with. This service is turned on: --------------- # chkconfig --list network Note: This output shows SysV services only and does not include native systemd services. SysV configuration data might be overridden by native systemd configuration. network 0:off 1:off 2:on 3:on 4:on 5:on 6:off --------------- Maybe this is as simple as symlinking some more targets into multi-user.target.wants...
(In reply to comment #20) > Maybe this is as simple as symlinking some more targets into > multi-user.target.wants... BTW, I actually tried symlinking network.target into printer.target.wants, but that didn't work. Ordering? Or could it be that cups.service itself should require network to come up?
(In reply to comment #16) > Well I found a sort of solution to my printing problem. > ntpd was not running. In fact it was not installed. > After installation I enabled it and started it with systemctl. > > Now the following happens: > 1. If I just reboot the server, printing does not work. > 2. However as soon as I login to the server printing begins to wprk from the > client. > 3. If I log out from the server printing still works from the client. > > So a solution has been found to my problem . Thank you Tim. > But does anyone know why I have to log in to the server for printing to start > working. Do you need an account on a server for remote printing to work for > you? I have no explanation for that. This sort of seems outside of the scope of CUPS at this point. (In reply to comment #15) > Also, the hardware could be running UTC time, right? So, when chrony kicks in, > it could be setting the system time to whatever is the local time. > > See, that time change is almost exactly 6 hours: > > 21620 / 3600 = 6.005555556 > > So, this is not an error. It's probably Aarons time being set by chrony or ntp. Aaron: what's in /etc/adjtime, and what's in /etc/sysconfig/clock?
First , shame on you Tim for cancelling my needinfo when I was excited that I could issue it, by a very obscure process :-) It seems to me the fact that cups will not work from the client unless I am logged in to the server is a cups problem, but you are the expert so I won't argue about it. As to your questions: /etc/adjtime contains: 0.000000 1321916833 0.000000 1321916833 LOCAL /etc/sysconfig/clock contains: # The timezone of the system is defined by the contents of /etc/localtime. # This file is only for the evaluation of system-config-date, do not rely on its # contents elsewhere. ZONE="America/Chicago"
There is no joy in mudville. Printing from the client is crippled again but now it is fault of ntpd which will not run continuously. But that is a bug in a different component so it needs to be investigated separately. But it does leave me frustrated.
(In reply to comment #24) > it is fault of ntpd which will not run continuously If ntpd is giving you trouble, you can always try chrony. It is the Fedora default now anyway.
(In reply to comment #16) > But does anyone know why I have to log in to the server for printing to start > working. Do you need an account on a server for remote printing to work for > you? Aaron, When you say login, do you mean ssh to the server and log out. Like this: ssh <server> : Or do you mean login to cups on the server (as in, touch socket on port 631)? Is it possible that some of the login scripts on the server actually do touch port 631 on login? That would sound like the most logical explanation to me.
I mean login sitting at the machine. I will try chrony and see what results.
Aaron: I see, you have your system clock set to LOCAL time, rather than the recommended UTC time. Is there a reason for you to do that? If anything was messing around with time zones at that point, it would certainly explain why time suddenly went backwards and cupsd decided it had to wait for an extra six hours before sending a browse packet. Bojan: thanks for an insightful question; I had assumed that "log in to server" was ssh. Logging in at the console certainly does touch port 631 because gnome-settings-daemon wants to be able to monitor print jobs. Aaron, that suggests that cups is not in fact running on the server for you until that point. What does 'systemctl status cups.service' say? Bojan: this looks to be the problem on your system: d [08/Dec/2011:15:26:08 +1100] select_timeout(0): 86400 seconds to do nothing CUPS has decided there is nothing to do. It might be due to this: E [08/Dec/2011:15:25:38 +1100] Unable to bind socket for address [v1.::1]:631 - Address already in use. ... E [08/Dec/2011:15:25:38 +1100] Unable to bind socket for address <IP-range>.1:63 1 - Cannot assign requested address. ... which could conceivably be due to bug #760070.
Tim: I am confused. My hardware clock is set to utc time, but if I set the system time to UTC then the wrong time is displayed in the system. All the timestamps would be wrong. The time used by the system in my mind has to be local time. So explain what you mean by setting the system time to utc and how would I do that? In the error_log the time jumped backwards and forwards 6 hours which is the difference between local time and utc but but why would this time jump happen? Why would the cups software suddenly decide it had to operate on utc. Again the time jumped forward not backwards. Running systemctl status cups.service returns: cups.service - CUPS Printing Service Loaded: loaded (/lib/systemd/system/cups.service; enabled) Active: active (running) since Mon, 12 Dec 2011 13:57:47 -0600; 30min ago Main PID: 1313 (cupsd) CGroup: name=systemd:/system/cups.service └ 1313 /usr/sbin/cupsd -f
Aaron, Could you run "netstat -anp | grep 631" just after boot? If you see port 631 TCP bound to localhost only, could you run "nc -z localhost 631" to see whether it gets bound to your other IP address (i.e. run the same netstat again)? For this to work, don't log in locally - SSH into the machine instead. Tim, My problem is that TCP port 631 is not bound on boot (not UDP, as in bug #760070). It does get bound when I execute "nc -z localhost 631" on the machine, without restarting cups.
(In reply to comment #28) > E [08/Dec/2011:15:25:38 +1100] Unable to bind socket for address > <IP-range>.1:63 > 1 - Cannot assign requested address. Doesn't this mean that the address is not there (i.e. not that port is in use)? That's why I keep saying that ordering is the problem here (i.e. the network is not up when cups starts on boot - only localhost). BTW, my rpc.statd is bound to static port 4000: ------------------- # ps -ef | grep rpc.statd rpcuser 1337 1 0 Dec11 ? 00:00:00 /sbin/rpc.statd -p 4000 # grep STAT /etc/sysconfig/nfs STATDARG="-p 4000" ------------------- So, NFS lock service could not have interfered with cups on my box. In fact, there was an SELinux bug that was preventing rpc.statd from starting on my machine. Even then, cups would not bind to the network interface on boot - only localhost.
Bojan, This is what happens after boot. [root@saturn ~]# netstat -anp|grep 631 tcp 0 0 0.0.0.0:631 0.0.0.0:* LISTEN 688/cupsd tcp 0 0 :::631 :::* LISTEN 1/init udp 0 0 0.0.0.0:631 0.0.0.0:* 688/cupsd [root@saturn ~]# nc -z localhost 631 Connection to localhost 631 port [tcp/ipp] succeeded! [root@saturn ~]# netstat -anp|grep 631 tcp 0 0 0.0.0.0:631 0.0.0.0:* LISTEN 688/cupsd tcp 0 0 127.0.0.1:60219 127.0.0.1:631 TIME_WAIT - tcp 0 0 :::631 :::* LISTEN 1/init udp 0 0 0.0.0.0:631 0.0.0.0:* 688/cupsd What can we conclude from these results?
(In reply to comment #32) > What can we conclude from these results? That the problem you're experiencing is most likely different to mine, although it presents the same symptoms (inability to print to a network print server after boot). I think my problem is caused by network not being up when cups starts, so cups cannot bind to a specific IP address I have configured. Your configuration appears to bind to a "any" interface (i.e. 0.0.0.0 or ::), so there is a different root cause for your problem. Thanks for running that - much appreciated!
Bojan: agreed. I've marked Aaron's original bug report (bug #758906) as *not* a duplicate of this after all. Aaron: we'll continue with your problem in bug #758906 now. For *this* problem it looks like CUPS might be giving up too early when bind fails. It will see the relevant network interface later on when it's time to send a browse packet, but by that time I think it's decided that address is no good.
Ping...
This message is a reminder that Fedora 16 is nearing its end of life. Approximately 4 (four) weeks from now Fedora will stop maintaining and issuing updates for Fedora 16. It is Fedora's policy to close all bug reports from releases that are no longer maintained. At that time this bug will be closed as WONTFIX if it remains open with a Fedora 'version' of '16'. Package Maintainer: If you wish for this bug to remain open because you plan to fix it in a currently maintained version, simply change the 'version' to a later Fedora version prior to Fedora 16's end of life. Bug Reporter: Thank you for reporting this issue and we are sorry that we may not be able to fix it before Fedora 16 is end of life. If you would still like to see this bug fixed and are able to reproduce it against a later version of Fedora, you are encouraged to click on "Clone This Bug" and open it against that version of Fedora. Although we aim to fix as many bugs as possible during every release's lifetime, sometimes those efforts are overtaken by events. Often a more recent Fedora release includes newer upstream software that fixes bugs or makes them obsolete. The process we are following is described here: http://fedoraproject.org/wiki/BugZappers/HouseKeeping
Ping... This is an F-18 bug now...
This message is a reminder that Fedora 18 is nearing its end of life. Approximately 4 (four) weeks from now Fedora will stop maintaining and issuing updates for Fedora 18. It is Fedora's policy to close all bug reports from releases that are no longer maintained. At that time this bug will be closed as WONTFIX if it remains open with a Fedora 'version' of '18'. Package Maintainer: If you wish for this bug to remain open because you plan to fix it in a currently maintained version, simply change the 'version' to a later Fedora version prior to Fedora 18's end of life. Thank you for reporting this issue and we are sorry that we may not be able to fix it before Fedora 18 is end of life. If you would still like to see this bug fixed and are able to reproduce it against a later version of Fedora, you are encouraged change the 'version' to a later Fedora version prior to Fedora 18's end of life. Although we aim to fix as many bugs as possible during every release's lifetime, sometimes those efforts are overtaken by events. Often a more recent Fedora release includes newer upstream software that fixes bugs or makes them obsolete.
I have no idea whether this is still a problem in F-20, but the workaround in /etc/rc.d/rc.local (echo | socat - UNIX-CONNECT:/var/run/cups/cups.sock) that I have has been working so well, I really don't care about this bug any more. So, unless someone complains, I'm going to let it close.
Fedora 18 changed to end-of-life (EOL) status on 2014-01-14. Fedora 18 is no longer maintained, which means that it will not receive any further security or bug fix updates. As a result we are closing this bug. If you can reproduce this bug against a currently maintained version of Fedora please feel free to reopen this bug against that version. If you are unable to reopen this bug, please file a new report against the current release. If you experience problems, please add a comment to this bug. Thank you for reporting this bug and we are sorry it could not be fixed.