Bug 398486 - Okular cannot print to remote cups server
Summary: Okular cannot print to remote cups server
Status: RESOLVED WORKSFORME
Alias: None
Product: okular
Classification: Applications
Component: printing (show other bugs)
Version: 1.5.0
Platform: openSUSE Linux
: NOR normal
Target Milestone: ---
Assignee: Okular developers
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2018-09-11 09:53 UTC by lp
Modified: 2018-09-12 13:08 UTC (History)
2 users (show)

See Also:
Latest Commit:
Version Fixed In:
Sentry Crash Report:


Attachments
strace -o /tmp/log -f okular --print xanes.pdf (326.93 KB, application/gzip)
2018-09-11 09:55 UTC, lp
Details

Note You need to log in before you can comment on or make changes to this bug.
Description lp 2018-09-11 09:53:44 UTC
This bug is caused triggered by sing a remote server via the cups client.conf file, in my case ~/.cups/client.conf contains this line
  ServerName printers1:631
Using the system-wide client.conf with the same configuration gives the same error.

The symptoms are:

1. When opening the print dialog, okualr always set the default to "Print to file" irrespective of what is set via lpoptions. The list of printers is available via the drop-down menu and contains all the printers, although most of the printers options are greyed out.


2. When printing, no error is returned on screen, but 
   /usr/bin/lpr: No such file or directory
   is written in the terminal


3. Doing a strace of okular shows that lpr is invoked with wrong arguments:
   17461 execve("/usr/bin/lpr", ["/usr/bin/lpr", "-P", "", "-#1", "-J", "xanes.pdf", "-r", "/tmp/okular_YAmrVt.ps"], 0x7ffe48e5d8c8 /* 137 vars */ <unfinished ...>
Note the empty argument after "-P" which causes the error, as no printer is set.


4. Checking the strace I can see that the connection with the remote cups server is opened:
   17452 connect(16, {sa_family=AF_INET, sin_port=htons(631), sin_addr=inet_addr("134.157.17.150")}, 16) = -1 EINPROGRESS (Operation now in progress)
but the answers from the server look broken as they are essentially all NULL:
17452 recvfrom(16, "HTTP/1.1 200 OK\r\nDate: Tue, 11 S"..., 2048, 0, NULL, NULL) = 201
17452 recvfrom(16, "\2\0\0\0\0\0\0\1", 8, 0, NULL, NULL) = 8
17452 recvfrom(16, "\1", 1, 0, NULL, NULL) = 1
17452 recvfrom(16, "G", 1, 0, NULL, NULL) = 1
17452 recvfrom(16, "\0\22", 2, 0, NULL, NULL) = 2
17452 recvfrom(16, "attributes-charset", 18, 0, NULL, NULL) = 18
17452 recvfrom(16, "\0\5", 2, 0, NULL, NULL) = 2
17452 recvfrom(16, "utf-8", 5, 0, NULL, NULL) = 5
17452 recvfrom(16, "H", 1, 0, NULL, NULL) = 1
17452 recvfrom(16, "\0\33", 2, 0, NULL, NULL) = 2
 ...

(I have attached the full strace as  "log")


5. The cups server is fairly old (CUPS 1.4.2) and has a relatively large variety of printers installed. This is the output of "lpstat -t"
scheduler is running
system default destination: lafayette
device for dell3010-2: socket://dell3010-2:9100
device for depisan: socket://depisan:9100
device for destael: socket://destael:9100
device for dulac: socket://dulac:9100
device for duras: socket://duras:9100
device for ernaux: socket://ernaux:9100
device for hp2324-415: socket://hp2324-415:9100
device for hp2324-506: socket://hp2324-506:9100
device for hp4200: socket://hp4200:9100
device for lafayette: socket://lafayette:9100
device for leduc: socket://leduc:9100
device for minolta283: socket://minolta283:9100
device for yourcenar: socket://yourcenar:9100
dell3010-2 accepting requests since Tue 04 Sep 2018 18:47:12 CEST
depisan accepting requests since Tue 11 Sep 2018 11:45:42 CEST
destael accepting requests since Tue 11 Sep 2018 10:50:21 CEST
dulac accepting requests since Tue 11 Sep 2018 11:08:06 CEST
duras accepting requests since Tue 11 Sep 2018 10:17:20 CEST
ernaux accepting requests since Tue 11 Sep 2018 10:21:47 CEST
hp2324-415 accepting requests since Fri 07 Sep 2018 15:34:39 CEST
hp2324-506 accepting requests since Mon 10 Sep 2018 16:59:02 CEST
hp4200 accepting requests since Tue 17 Oct 2017 15:48:50 CEST
lafayette accepting requests since Tue 11 Sep 2018 11:07:35 CEST
leduc accepting requests since Mon 10 Sep 2018 16:57:25 CEST
minolta283 accepting requests since Tue 11 Sep 2018 11:11:52 CEST
yourcenar accepting requests since Tue 04 Sep 2018 18:47:43 CEST
printer dell3010-2 is idle.  enabled since Tue 04 Sep 2018 18:47:12 CEST
printer depisan is idle.  enabled since Tue 11 Sep 2018 11:45:42 CEST
        Ready to print.
printer destael is idle.  enabled since Tue 11 Sep 2018 10:50:21 CEST
        Ready to print.
printer dulac is idle.  enabled since Tue 11 Sep 2018 11:08:06 CEST
        Ready to print.
printer duras now printing duras-31692.  enabled since Tue 11 Sep 2018 10:17:20 CEST
        Connecting to printer...
printer ernaux is idle.  enabled since Tue 11 Sep 2018 10:21:47 CEST
        Ready to print.
printer hp2324-415 is idle.  enabled since Fri 07 Sep 2018 15:34:39 CEST
printer hp2324-506 is idle.  enabled since Mon 10 Sep 2018 16:59:02 CEST
printer hp4200 is idle.  enabled since Tue 17 Oct 2017 15:48:50 CEST
printer lafayette is idle.  enabled since Tue 11 Sep 2018 11:07:35 CEST
        Ready to print.
printer leduc is idle.  enabled since Mon 10 Sep 2018 16:57:25 CEST
printer minolta283 is idle.  enabled since Tue 11 Sep 2018 11:11:52 CEST
        Ready to print.
printer yourcenar is idle.  enabled since Tue 04 Sep 2018 18:47:43 CEST
duras-31692             aufort        15968256   Tue 31 Jul 2018 10:56:48 CEST
duras-31762             aufort          585728   Wed 08 Aug 2018 11:22:11 CEST
duras-31921             aufort          215040   Wed 29 Aug 2018 11:14:17 CEST


6. Printing by hand with lpr work fine, as do all non Qt5 applications.

I'm available to run any kind of test if necessary.

kind regards
Comment 1 lp 2018-09-11 09:55:03 UTC
Created attachment 114895 [details]
strace -o /tmp/log -f okular --print xanes.pdf

I have gzipped the strace as it was over 4000k
Comment 2 Michael Weghorn 2018-09-11 18:53:48 UTC
Thanks for your report. A few more questions:

A) Does printing work when you enable "Force rasterization" in the PDF options in the print dialog (this should make Okular use the "default" Qt way of printing).

B) Do other Qt/KDE applications work? And if so, how much works there? (e.g. I'd usually expect that printing itself should mostly to the same extent as with "Force rasterization" in Okular, and the greyed out options are probably always the same?)

c) What Qt version are you using? (There were quite some improvements to the Qt print dialog in Qt 5.11).
Comment 3 lp 2018-09-12 08:17:11 UTC
I giving the informations you requested below, however I solved the problem and it is a concurrency of problematic server configuration and maybe problematic printing client behaviour.

So. I inherited this server I can admin it but I have no idea how I was set up. I noticed in the server log that I was getting a lot messages like:
E [12/Sep/2018:03:42:14 +0200] Request from "134.157.17.66" using invalid Host: field "rutile1.impmc.jussieu.fr:631"
134.157.189.14 - - [12/Sep/2018:04:31:30 +0200] "POST / HTTP/1.1" 200 418 Create-Printer-Subscription client-error-not-possible
Which made me realize that the printing server is associated with two host names (rutile1 and printers1) on the same IP, but that the cups server was explicitly bound only to printers1. For some reason, even if I've put "printers1" in client.conf, the call to the connection to the server was done by IP, that was interpreted by the server as being on the other hostname (rutile1) and refused.

I've added a ServerAlias with the other host name in cupsd.conf and now everything seems to work. I'm not closing the issue directly, I'd rather let you decide if this is a bug in the printing library or not.

Thank you for you assistance!


1. No: I don't get the error from lpr, but the job does not get in the queue, this is what I get in the strace (I had to use a different printer because the other broke down):
858   setsockopt(19, SOL_SOCKET, SO_REUSEADDR, [1], 4) = 0
858   setsockopt(19, SOL_SOCKET, SO_REUSEPORT, [1], 4) = 0
858   setsockopt(19, SOL_TCP, TCP_NODELAY, [1], 4) = 0
858   fcntl(19, F_SETFD, FD_CLOEXEC)    = 0
858   fcntl(19, F_GETFL)                = 0x2 (flags O_RDWR)
858   fcntl(19, F_SETFL, O_RDWR|O_NONBLOCK) = 0
858   connect(19, {sa_family=AF_INET, sin_port=htons(631), sin_addr=inet_addr("134.157.17.150")}, 16) = -1 EINPROGRESS (Operation now in progress)
858   fcntl(19, F_SETFL, O_RDWR)        = 0
858   poll([{fd=19, events=POLLIN|POLLOUT}], 1, 250) = 1 ([{fd=19, revents=POLLOUT}])
858   getpeername(19, {sa_family=AF_INET, sin_port=htons(631), sin_addr=inet_addr("134.157.17.150")}, [256->16]) = 0
858   gettimeofday({tv_sec=1536738525, tv_usec=215459}, NULL) = 0
858   getpid()                          = 858
858   openat(AT_FDCWD, "/tmp/0035a5b9c0e80", O_RDWR|O_CREAT|O_EXCL|O_NOFOLLOW, 0600) = 20
858   sendto(19, "GET /printers/leduc.ppd HTTP/1.1"..., 137, 0, NULL, 0) = 137
858   poll([{fd=19, events=POLLIN}], 1, 60000) = 1 ([{fd=19, revents=POLLIN}])
858   recvfrom(19, "HTTP/1.1 400 Bad Request\r\nDate: "..., 2048, 0, NULL, NULL) = 555
858   close(20)                         = 0
858   unlink("/tmp/0035a5b9c0e80")      = 0
858   close(19)    


2. Neither, this was printing from kwrite, the strace is very similar:
socket(AF_INET, SOCK_STREAM, IPPROTO_IP) = 18
setsockopt(18, SOL_SOCKET, SO_REUSEADDR, [1], 4) = 0
setsockopt(18, SOL_SOCKET, SO_REUSEPORT, [1], 4) = 0
setsockopt(18, SOL_TCP, TCP_NODELAY, [1], 4) = 0
fcntl(18, F_SETFD, FD_CLOEXEC)          = 0
fcntl(18, F_GETFL)                      = 0x2 (flags O_RDWR)
fcntl(18, F_SETFL, O_RDWR|O_NONBLOCK)   = 0
connect(18, {sa_family=AF_INET, sin_port=htons(631), sin_addr=inet_addr("134.157.17.150")}, 16) = -1 EINPROGRESS (Operation now in progress)
fcntl(18, F_SETFL, O_RDWR)              = 0
poll([{fd=18, events=POLLIN|POLLOUT}], 1, 250) = 1 ([{fd=18, revents=POLLOUT}])
getpeername(18, {sa_family=AF_INET, sin_port=htons(631), sin_addr=inet_addr("134.157.17.150")}, [256->16]) = 0
gettimeofday({tv_sec=1536739185, tv_usec=653086}, NULL) = 0
getpid()                                = 1051
openat(AT_FDCWD, "/tmp/0041b5ba2be8f", O_RDWR|O_CREAT|O_EXCL|O_NOFOLLOW, 0600) = 19
sendto(18, "GET /printers/leduc.ppd HTTP/1.1"..., 137, 0, NULL, 0) = 137
poll([{fd=18, events=POLLIN}], 1, 60000) = 1 ([{fd=18, revents=POLLIN}])
recvfrom(18, "HTTP/1.1 400 Bad Request\r\nDate: "..., 2048, 0, NULL, NULL) = 555
close(19)                               = 0
unlink("/tmp/0041b5ba2be8f")            = 0
close(18)    


3. Version 5.11.5
Name        : libQt5Core5
Version     : 5.11.1
Release     : 4.1
Architecture: x86_64
Install Date: Thu 06 Sep 2018 15:42:26 CEST
Group       : Development/Libraries/X11
Size        : 5387516
License     : LGPL-2.1-with-Qt-Company-Qt-exception-1.1 or LGPL-3.0-only
Signature   : RSA/SHA256, Mon 03 Sep 2018 11:31:49 CEST, Key ID b88b2fd43dbdc284
Source RPM  : libqt5-qtbase-5.11.1-4.1.src.rpm
Build Date  : Mon 03 Sep 2018 11:17:12 CEST
Build Host  : lamb05
Relocations : (not relocatable)
Packager    : https://bugs.opensuse.org
Vendor      : openSUSE
URL         : https://www.qt.io
Comment 4 Michael Weghorn 2018-09-12 13:08:21 UTC
Thanks for the quick update and good to hear you could solve the issue.

(In reply to lp from comment #3)
>
> I've added a ServerAlias with the other host name in cupsd.conf and now
> everything seems to work. I'm not closing the issue directly, I'd rather let
> you decide if this is a bug in the printing library or not.

From what I understand, the underlying problem was mostly a configuration issue, so I'm closing this bug now.

Please just reopen or create a new one should the problem reappear.