Bug 913564

Please run 'system-config-printer --debug' from a command line, and try to add the printer again.  When it fails in the same manner as described above, please paste in the output it gave.

Created attachment 700602 [details]
debug output - hp1020 selected

Created attachment 700603 [details]
debug output - uri selected

This seems to be the issue:

Call <method 'getPPDs2' of 'cups.Connection' objects>
...failure

Does /var/log/cups/error_log show any error at the time you do that?

Created attachment 700664 [details]
CUPS error log

Please run the command 'cupsctl --debug-logging', then try again.  This time there will be much more in the error_log file.

Afterwards, turn off debugging with 'cupsctl --no-debug-logging'.

Created attachment 700692 [details]
CUPS error log with cupsctl --debug-logging

Created attachment 701241 [details]
Replacement /usr/share/system-config-printer/asyncipp.py file

Please try this replacement /usr/share/systme-config-printer/asyncipp.py file.  Run 'system-config-printer --debug' again and attach the output.  Hopefully this will give us an idea what's going wrong and why it's being handled badly.

Created attachment 701254 [details]
debug output - asyncipp.py

...failure (IPPError(1280, 'server-error-internal-error'))

When I artificially create this failure at the same point, I get an error message in a pop-up dialog:

CUPS server error
There was an error during the CUPS operation: 'server-error-internal-error'.

I would at least expect to see that -- did you see that message?

In any case, server-error-internal-error tells us that something else is going on, but doesn't tell us what. :-(

Are you still seeing this issue?

did you see that message?
No.

Are you still seeing this issue?
Yes.

Created attachment 713917 [details]
Replacement /usr/share/system-config-printer/asyncipp.py file

Created attachment 713918 [details]
Replacement /usr/share/system-config-printer/asyncconn.py file

Please try the above two replacement files, for asyncipp.py and asyncconn.py.  Additionally, please update python-cups to the one here:
  https://koji.fedoraproject.org/koji/buildinfo?buildID=404342
(download the appropriate python-cups-1.9.63-1.*.rpm file for your architecture and run 'yum localupdate ./python-cups-1.9.63-...' to install it)

These things, together, should provide enough information to diagnose what's going wrong.  Please run 'system-config-printer --debug' as before and attach the output.

Created attachment 713939 [details]
debug output - asyncipp.py, asyncconn.py, python-cups-1.9.63-1

Thanks.  I've made some changes in system-config-printer-1.3.13: please try this test update, and run with --debug again to get another run of debug output.

yum --enablerepo=updates-testing update 'system-config-printer*'

Created attachment 730814 [details]
debug output - system-config-printer-1.3.13

Note: this time I got:

CUPS server error
There was an error during the CUPS operation: 'Success'.

after the "searching..." stuff.

That's... weird.  I can't see any path in the code that would do that. :-/

Time to look in detail at the system calls to see if I can see what libcups is actually doing.

Please run this (it's all one line):

strace 2>syscalls.txt -tt -s400 python -c 'import cups;cups.Connection().getPPDs2()'

and then run 'gzip syscalls.txt' and attach the resulting syscalls.txt.gz you end up with.

Created attachment 731140 [details]
strace 2>syscalls.txt -tt -s400 python -c 'import cups;cups.Connection().getPPDs2()'

strace 2>syscalls.txt -tt -s400 python -c 'import cups;cups.Connection().getPPDs2()'

What's happening is that the libcups library is timing out while waiting for the scheduler to come up with a list of available PPDs.

What does this say?:

time lpinfo -m >/dev/null
time lpinfo -m >/dev/null

(i.e. run it twice)

$ time lpinfo -m >/dev/null
lpinfo: Success

real    1m0.698s
user    0m0.004s
sys     0m0.149s
$ time lpinfo -m >/dev/null
lpinfo: Success

real    1m0.450s
user    0m0.005s
sys     0m0.142s

Another test to run:

1. In one terminal, run 'lpinfo -m'
2. In another terminal, wait for about 30 seconds and then run 'ps axf'

What I'm looking for is the process tree for cupsd: i.e. which programs is it still running?

Created attachment 743254 [details]
Output from ps axf

Thanks.  Well, it's foomatic that's taking the time.

What does this say?:

time /usr/lib/cups/driver/foomatic list >/dev/null

$ time /usr/lib/cups/driver/foomatic list >/dev/null
real    1m14.627s
user    0m4.820s
sys     0m41.701s

Another time:

real 1m50s

Thanks.  And this?:

/usr/lib/cups/driver/foomatic list |wc -l

FWIW, 'foomatic list' takes under 2s on this machine the second time (15s the first time).

3860

Created attachment 743261 [details]
Output from /usr/lib/cups/driver/foomatic list > xxx

This seems quite a time to be taking in syscalls:

sys     0m41.701s

That said, foomatic is slow and that's a known issue... but not one that seems to be in bugzilla at the moment.  I'll change the name of this bug to reflect that.

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.

This package has changed ownership in the Fedora Package Database.  Reassigning to the new owner of this component.

I tested the command on fully used F33 (all foomatic packages installed, 4411 foomatic drivers available) and it took 50s at the most (clean rawhide took 9s). Time consumption looks better now.

Since the classic drivers will be replaced by printer application in the future, upstream will not introduce new dependency to the project, I'm sorry.