Bug 758906 - Cups printing fails when F16 system boots
Summary: Cups printing fails when F16 system boots
Keywords:
Status: CLOSED WORKSFORME
Alias: None
Product: Fedora
Classification: Fedora
Component: cups
Version: 16
Hardware: i686
OS: Linux
unspecified
medium
Target Milestone: ---
Assignee: Tim Waugh
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2011-11-30 23:10 UTC by Aaron Konstam
Modified: 2011-12-14 13:06 UTC (History)
2 users (show)

Fixed In Version:
Clone Of:
Environment:
Last Closed: 2011-12-14 13:06:56 UTC
Type: ---
Embargoed:


Attachments (Terms of Use)
/var/log/cups/error_log from my print server (6.26 KB, application/x-gzip)
2011-12-13 21:33 UTC, Aaron Konstam
no flags Details

Description Aaron Konstam 2011-11-30 23:10:47 UTC
Description of problem:
When the F16 system boots printing on printer client is disabled

Version-Release number of selected component (if applicable):
cups-1.5.0.22w.FC16.i686

How reproducible:
Everytime

Steps to Reproduce:
1.Boot system that is print client
2.Try to print
3.
  
Actual results:
The printer on the server is not seen on the client.

Expected results:
The printer is detected on the client and printing can occur.

Additional info:
On the server running systemctl status cups.service returns:
cups.service - CUPS Printing Service
      Loaded: loaded (/lib/systemd/system/cups.service; enabled)
       Active: active (running) since Sat, 26 Nov 2011 22:51:07 -0600
     Main PID: 687 (cupsd)
       CGroup: name=systemd:/system/cups.service
               └ 687 /usr/sbin/cupsd -f

Running netstat -anp |grep 631

tcp        0      0 0.0.0.0:631                 0.0.0.0:*                   LISTEN      715/cupsd           
tcp        0      0 :::631                      :::*                        LISTEN      1/init              
udp        0      0 0.0.0.0:631                 0.0.0.0:*                               715/cupsd           
unix  2      [ ACC ]     STREAM     LISTENING     9631   1/init              /run/systemd/stdout-syslog-bridge

If I run: systemctl restart cups.service printing is possible on the client

The printer is continously available on the print server.

running netstat -apn on the client when the printer is not available gived:

tcp        0      0 127.0.0.1:631               0.0.0.0:*                   LISTEN      -                   
tcp        0      0 ::1:631                     :::*                        LISTEN      -                   
udp        0      0 0.0.0.0:631                 0.0.0.0:*                               -                   
unix  3      [ ]         STREAM     CONNECTED     16319  1554/dbus-daemon    @/tmp/dbus-pc9bCO6WNR
unix  3      [ ]         STREAM     CONNECTED     16318  2187/deja-dup-monit 
unix  3      [ ]         STREAM     CONNECTED     16313  1554/dbus-daemon    @/tmp/dbus-pc9bCO6WNR
unix  3      [ ]         STREAM     CONNECTED     16312  2187/deja-dup-monit 
unix  3      [ ]         STREAM     CONNECTED     14631  1554/dbus-daemon    @/tmp/dbus-pc9bCO6WNR

This output doesw not change when the cups.service is started on the server.

Comment 1 Tim Waugh 2011-12-01 09:23:34 UTC
Could you please clarify whether you need to restart cups.service on the client, or on the server?

Comment 2 Aaron Konstam 2011-12-01 13:50:13 UTC
I am sorry. I thought  I made that clear. It is on the server that I have to restart cups.

Comment 3 Aaron Konstam 2011-12-01 13:57:08 UTC
I need to add that the server is running F16 and the client is running F14.

Comment 4 Tim Waugh 2011-12-05 11:43:01 UTC
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'

Comment 5 Tim Waugh 2011-12-05 12:00:08 UTC
Seems to be a duplicate of bug #756550 actually. (Would still like that error_log...)

*** This bug has been marked as a duplicate of bug 756550 ***

Comment 6 Tim Waugh 2011-12-13 09:33:04 UTC
Marking this as *not* a duplicate (see bug #756550 comment #33).

Comment 7 Tim Waugh 2011-12-13 11:10:17 UTC
Aaron, let's try setting the clock to UTC and see if that affects the problem.

(In reply to bug #756550 comment #29)
> 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.

What I mean is that the hardware clock should be set to UTC time (this is the Fedora default), so that it is independent of the timezone.  The OS will take care of showing you the correct local time (i.e. applying the timezone correction).

To do this, run:

  system-config-date

In the "Time Zone" tab, put a tick in the "System clock uses UTC" checkbox.

Now in the "Date and Time" tab, put a tick in the "Synchronise date and time over the network" checkbox.  If there are no NTP servers listed, add these:

0.fedora.pool.ntp.org
1.fedora.pool.ntp.org
2.fedora.pool.ntp.org
3.fedora.pool.ntp.org

Under 'Advanced Options', put a tick in the "Speed up initial synchronization" checkbox.

Now reboot.  You should find that 'date' shows you the correct time.

Comment 8 Aaron Konstam 2011-12-13 14:58:58 UTC
Tim,
Look I know that it is confusing to deal with two users with similar problems a the same time,

However, as I said before that my hardware clock is already set to utc.

Clicking on the "System clock uses UTC" checkbox" is confusing since this actually sets the hardware time to utc and not the system time. That is what it seems to be doing. That checkbox label should be changed.

The other things you asked me to do had already been done with this exception. I have found that on my machine ntpd refuses to keep running so I took Bojan's suggestion and am using chrony instead of ntpd. In the window that says it is starting ntp but ntpd does not start. That may be because I have used systemctl to disable it.


Printing from the client works initially then stops working until I run:
systemctl restart cups.service

cupsd is still running when the printing stops working.
I am pretty sure that the status for cups.service is still active on the server.
I have used cups and Linux for at more than a decade. At one time as the system administrator I managed a system with one print server, 80 clients and at least 5 printers and I have never seen cups act as it does on my machine. I should point out that I can only run my F16 server in failsafe mode. I don't know if that makes a difference.

Comment 9 Tim Waugh 2011-12-13 15:50:09 UTC
Aaron, I am simply trying to help, and to find the cause of the bug.  The way to do that is to try changing things one at a time until it behaves differently, and think about why that is.

I asked you to change your hardware clock to UTC because of bug #756550 comment #23, in which you gave the contents of /etc/adjtime:

0.000000  1321916833 0.000000
1321916833
LOCAL

As you can see from the hwclock(8) man page, this means that the hardware clock is set to local time.

However, the default Fedora setting is for this to be set to UTC.  This is what I have here, and CUPS is working correctly for me.  That's why I'm trying to change that aspect first, and see if that eliminates the problem.

So, given that you've tried that, let's look at what happened:

(In reply to comment #8)
> Printing from the client works initially then stops working until I run:
> systemctl restart cups.service

So, my first question is: did *browsing* work?  Were the clients seeing browse packets from CUPS, or were they just remembering the queues from before the server rebooted?

It sounds very much like browsing was not working, and that the clients had queues from before the reboot which eventually timed out.

> I should
> point out that I can only run my F16 server in failsafe mode. I don't know if
> that makes a difference.

I don't think that's relevant, no.  The thing about logging in causing CUPS to work would be the same regardless of whether failsafe mode is being used, I believe (i.e. gnome-settings-daemon runs in both modes).

I would very much like to see the CUPS debugging output now this change has been made, so see what is different and why.

Please could you provide:

1. The new output of 'cat /etc/adjtime', to make sure the change had the effect I intended it to

2. The debugging log from booting with this new configuration:

cupsctl LogLevel=debug2
systemctl stop cups.service
>/var/log/cups/error_log
reboot

Then after it has booted, wait for about 2 minutes on the clients.  What does 'lpstat -s' say on a client now?

If possible, log in to the server remotely to fetch the /var/log/cups/error_log file at that point. (If not possible, just log in at the console and do it.)

Last test: after logging in at the console, does browsing now work?

Comment 10 Aaron Konstam 2011-12-13 21:33:51 UTC
Created attachment 546411 [details]
/var/log/cups/error_log from my print server

Comment 11 Aaron Konstam 2011-12-13 21:42:20 UTC
Tim,
I know you are trying to help me and I appreciate it.

Test output:


 cat /etc/adjtime
0.000709 1323789361 0.000000
1323789361
UTC

{You got the output you wanted. However, the hardware clock has always been utc.
Maybe I learned something.]

lpstat -s
system default destination: DESKJET-990C
device for DESKJET-990C: ipp://192.168.1.68:631/printers/DESKJET-990C

Browsing now works on the client. I have attached the error_log gzipped to this report.

Maybe you have fixed things. Let us wait a day or so to see if the Browsing craps out.

Again I appreciate your help.

Comment 12 Aaron Konstam 2011-12-14 02:16:08 UTC
Well, I think you solved the problem. Also I think I have worked out the reason
adjtime recording the time was LOCAL led to the problem occurring.

Some of the software knew that the hardware clock was utc without looking at adjtime or some other system file. Some software became confused by the LOCAL designation. Some part of the cups software is in this latter category. As you said the browsing software got confused. This must also be why ntpd quit running,

I think we can say the problem is solved and close the bugzilla. If a problem pops up again we can go at it once more. But I don't want to waste anymore of your time at this point.


Once again, thanks for the help.

Comment 13 Tim Waugh 2011-12-14 13:06:56 UTC
Glad it's working now.

It's still a bit of a puzzle that the timezone was being changed.  Please keep a look-out for that in other applications, in case there is something strange still going on.

(Not sure of the best "resolution": WORKSFORME seems closest.)


Note You need to log in before you can comment on or make changes to this bug.