Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

lpstat -e and an error message #352

Closed
debiantriage opened this issue Mar 13, 2022 · 18 comments
Closed

lpstat -e and an error message #352

debiantriage opened this issue Mar 13, 2022 · 18 comments
Assignees
Labels
bug Something isn't working priority-medium
Milestone

Comments

@debiantriage
Copy link

With the cups service stopped:

brian@desktop:~$ lpstat -a
lpstat: Bad file descriptor

brian@desktop:~$ lpstat -e
brian@desktop:~$

Doesn't this leave some doubt as to whether there are any available destinations on the local network or cups is stopped?

@michaelrsweet
Copy link
Member

@debiantriage What version of CUPS is this with? It looks like the domain socket file is still present after cupsd is stopped, and if so that'd be a systemd bug... :/

@zdohnal
Copy link
Member

zdohnal commented Mar 14, 2022

@michaelrsweet I can reproduce it on Fedora 36 (CUPS-2.4.1), all units - path, socket and service - are down, but lpstat -e returns 0 and without any message - investigating...

[zdohnal@fedora]-[~/repo_upstream/ipp-usb (add_etc_quirks $=)]
93>>>lpstat -a
lpstat: Bad file descriptor
[zdohnal@fedora]-[~/repo_upstream/ipp-usb (add_etc_quirks $=)]
94>>>lpstat -e
[zdohnal@fedora]-[~/repo_upstream/ipp-usb (add_etc_quirks $=)]
95>>>systemctl status cups.service
○ cups.service - CUPS Scheduler
     Loaded: loaded (/usr/lib/systemd/system/cups.service; disabled; vendor preset: disabled)
     Active: inactive (dead) since Mon 2022-03-14 14:48:48 CET; 3min 19s ago
TriggeredBy: ○ cups.path
             ○ cups.socket
       Docs: man:cupsd(8)
    Process: 55652 ExecStart=/usr/sbin/cupsd -l (code=exited, status=0/SUCCESS)
   Main PID: 55652 (code=exited, status=0/SUCCESS)
     Status: "Scheduler is running..."
        CPU: 37ms

Mar 14 14:32:25 fedora cupsd[55652]: Expiring subscriptions...
Mar 14 14:48:48 fedora cupsd[55652]: Scheduler shutting down normally.
Mar 14 14:48:48 fedora cupsd[55652]: Discarding unused server-stopped event...
Mar 14 14:48:48 fedora systemd[1]: Stopping cups.service - CUPS Scheduler...
Mar 14 14:48:48 fedora cupsd[55652]: Expiring subscriptions...
Mar 14 14:48:48 fedora cupsd[55652]: Creating KeepAlive/PID file "/var/cache/cups/org.cups.cupsd".
Mar 14 14:48:48 fedora cupsd[55652]: Saving job.cache...
Mar 14 14:48:48 fedora cupsd[55652]: cupsdStopSelect()
Mar 14 14:48:48 fedora systemd[1]: cups.service: Deactivated successfully.
Mar 14 14:48:48 fedora systemd[1]: Stopped cups.service - CUPS Scheduler.
[zdohnal@fedora]-[~/repo_upstream/ipp-usb (add_etc_quirks $=)]
96>>>systemctl status cups.socket
○ cups.socket - CUPS Scheduler
     Loaded: loaded (/usr/lib/systemd/system/cups.socket; enabled; vendor preset: enabled)
     Active: inactive (dead) since Mon 2022-03-14 14:48:48 CET; 3min 23s ago
   Triggers: ● cups.service
     Listen: /run/cups/cups.sock (Stream)

Mar 14 13:59:36 fedora systemd[1]: Listening on cups.socket - CUPS Scheduler.
Mar 14 14:48:48 fedora systemd[1]: cups.socket: Deactivated successfully.
Mar 14 14:48:48 fedora systemd[1]: Closed cups.socket - CUPS Scheduler.
[zdohnal@fedora]-[~/repo_upstream/ipp-usb (add_etc_quirks $=)]
97>>>systemctl status cups.path
○ cups.path - CUPS Scheduler
     Loaded: loaded (/usr/lib/systemd/system/cups.path; enabled; vendor preset: enabled)
     Active: inactive (dead) since Mon 2022-03-14 14:48:48 CET; 3min 26s ago
   Triggers: ● cups.service

Mar 14 13:59:36 fedora systemd[1]: Started cups.path - CUPS Scheduler.
Mar 14 14:48:48 fedora systemd[1]: cups.path: Deactivated successfully.
Mar 14 14:48:48 fedora systemd[1]: Stopped cups.path - CUPS Scheduler.

@zdohnal zdohnal added bug Something isn't working priority-medium labels Mar 14, 2022
@zdohnal zdohnal self-assigned this Mar 14, 2022
@zdohnal zdohnal added this to the 2.4.2 milestone Mar 14, 2022
@michaelrsweet
Copy link
Member

@zdohnal With the CUPS service disabled, does the domain socket file (/run/cups/cups.sock) still exist? If so, that is a systemd bug for sure! The domain socket file should only be present when the service is enabled (and ordinarily would fire up an instance of cupsd)...

@zdohnal
Copy link
Member

zdohnal commented Mar 14, 2022

@michaelrsweet disabling socket unit does not remove the domain socket file at all - disabling/enabling unit removes/adds the unit into /etc/systemd/system/*.target.wants/ , stopping/starting the socket unit does not remove/add the domain socket file either - the domain socket exists, but since the unit covering it is not active, it refuses requests... at least that's how I understand it. I would need to get a systemd person for gory details if needed.

To sum it up, existence of the domain socket doesn't mean cupsd will be triggered if a request comes to it. If the socket unit is deactivated, systemd probably drops anything which is sent to /run/cups/cups.sock.

The reason why we don't get any error is that we don't check whether cupsGetDests() returns something at all... I'll push the fix at the moment. It looks like this:

diff --git a/systemv/lpstat.c b/systemv/lpstat.c
index 7cb1eeb53..c11000540 100644
--- a/systemv/lpstat.c
+++ b/systemv/lpstat.c
@@ -246,6 +246,13 @@ main(int  argc,                            /* I - Number of command-line arguments */
                 cups_dest_t *temp = NULL, *dest;
                 int j, num_temp = cupsGetDests(&temp);
 
+                if (cupsLastError() > IPP_STATUS_OK_CONFLICTING)
+                {
+                  _cupsLangPrintf(stderr, "lpstat: %s", cupsLastErrorString());
+                  cupsFreeDests(num_temp, temp);
+                  return (1);
+                }
+
                 op = 'e';
 
                 for (j = num_temp, dest = temp; j > 0; j --, dest ++)

@michaelrsweet
Copy link
Member

@zdohnal When CUPS is configured to use systemd, it leaves the creation and removal of sockets (including the domain socket/file) up to systemd. Standard UNIX programming practice is to REMOVE the socket file when the service is disabled/not running, and the presence of the domain socket file tells a potential client that the service is running (or will be run when you connect).

So yes, it is important to report the errors in lpstat, but the error wouldn't happen if systemd would just remove the f'ing domain socket file!

@zdohnal
Copy link
Member

zdohnal commented Mar 14, 2022

@michaelrsweet aha, ok - I didn't know about this programming practice... I'll contact systemd guys whether this behavior is intended.

However:

37>>>sudo rm -f /run/cups/cups.sock
[zdohnal@fedora]-[~/repo_upstream/upstream_cups (master *=)]
38>>>ls /run/cups/cups.sock 
ls: cannot access '/run/cups/cups.sock': No such file or directory
[zdohnal@fedora]-[~/repo_upstream/upstream_cups (master *=)]
40>>>lpstat -e
[zdohnal@fedora]-[~/repo_upstream/upstream_cups (master *=)]

Either the domain socket lingers somewhere (and my stupid reproducer doesn't do the trick), or the incorrect behavior happens even if domain socket is not present.

@zdohnal
Copy link
Member

zdohnal commented Mar 14, 2022

@michaelrsweet created https://bugzilla.redhat.com/show_bug.cgi?id=2063891 - we will see whether it is intended from systemd folks...

@debiantriage
Copy link
Author

@michaelrsweet @zdohnal I found

https://bugzilla.redhat.com/show_bug.cgi?id=802748

The systemd.socket manaual describes a RemoveOnStop option. Does that help?

@michaelrsweet
Copy link
Member

michaelrsweet commented Mar 14, 2022

@debiantriage Yes, and we should definitely be using it; launchd and other (historical) init replacement programs that support listening on sockets on behalf of services ALL have implemented this functionality by default, so I'm stunned that it isn't also the default for systemd, but then systemd does some odd unexpected things with services anyways... :/

@debiantriage
Copy link
Author

@michaelrsweet I added RemoveOnStop=on to /lib/systemd/system/cups.socket and restarted the systemd daemon. cups.sock is removed when cups is stopped but lpstat -estill has an empty output.

@michaelrsweet
Copy link
Member

@debiantriage Hmm, can you run lpstat with strace to see when it gives up?

strace lpstat -e 2>strace.txt

@debiantriage
Copy link
Author

@michaelrsweet This is on cups 2.3.3op2-3. strace.txt attached.
strace.txt

@zdohnal
Copy link
Member

zdohnal commented Mar 15, 2022

@debiantriage great find! I was looking into the manpage myself, but I haven't seen the tree for the forest...

Confirmed the behavior with 2.4.1 in Fedora - after adding RemoveOnStop=on the socket is no more, but it does not change the behavior of lpstat -e:

[zdohnal@fedora]-[~/repo_upstream/ipp-usb (fix_spacing $=)]
25>>>cat /etc/systemd/system/cups.socket
[Unit]
Description=CUPS Scheduler
PartOf=cups.service

[Socket]
ListenStream=/run/cups/cups.sock
RemoveOnStop=on

[Install]
WantedBy=sockets.target

14>>>sudo systemctl daemon-reload
[zdohnal@fedora]-[~/repo_upstream/ipp-usb (fix_spacing $=)]
15>>>systemctl status cups.socket
○ cups.socket - CUPS Scheduler
     Loaded: loaded (/etc/systemd/system/cups.socket; enabled; vendor preset: enabled)
     Active: inactive (dead) since Mon 2022-03-14 16:10:25 CET; 15h ago
   Triggers: ● cups.service
     Listen: /run/cups/cups.sock (Stream)
        CPU: 0

Mar 14 15:51:48 fedora systemd[1]: Listening on cups.socket - CUPS Scheduler.
Mar 14 16:10:25 fedora systemd[1]: cups.socket: Deactivated successfully.
Mar 14 16:10:25 fedora systemd[1]: Closed cups.socket - CUPS Scheduler.
[zdohnal@fedora]-[~/repo_upstream/ipp-usb (fix_spacing $=)]
16>>>systemctl status cups.service
○ cups.service - CUPS Scheduler
     Loaded: loaded (/usr/lib/systemd/system/cups.service; disabled; vendor preset: disabled)
     Active: inactive (dead) since Mon 2022-03-14 15:18:32 CET; 16h ago
TriggeredBy: ○ cups.socket
             ○ cups.path
       Docs: man:cupsd(8)
   Main PID: 71490 (code=exited, status=0/SUCCESS)
     Status: "Scheduler is running..."
        CPU: 0

Mar 14 15:16:55 fedora cupsd[71490]: Expiring subscriptions...
Mar 14 15:18:32 fedora cupsd[71490]: Scheduler shutting down normally.
Mar 14 15:18:32 fedora cupsd[71490]: Discarding unused server-stopped event...
Mar 14 15:18:32 fedora cupsd[71490]: Expiring subscriptions...
Mar 14 15:18:32 fedora cupsd[71490]: Creating KeepAlive/PID file "/var/cache/cups/org.cups.cupsd".
Mar 14 15:18:32 fedora systemd[1]: Stopping cups.service - CUPS Scheduler...
Mar 14 15:18:32 fedora cupsd[71490]: Saving job.cache...
Mar 14 15:18:32 fedora cupsd[71490]: cupsdStopSelect()
Mar 14 15:18:32 fedora systemd[1]: cups.service: Deactivated successfully.
Mar 14 15:18:32 fedora systemd[1]: Stopped cups.service - CUPS Scheduler.
[zdohnal@fedora]-[~/repo_upstream/ipp-usb (fix_spacing $=)]
17>>>systemctl status cups.path
○ cups.path - CUPS Scheduler
     Loaded: loaded (/usr/lib/systemd/system/cups.path; enabled; vendor preset: enabled)
     Active: inactive (dead) since Mon 2022-03-14 14:48:48 CET; 16h ago
   Triggers: ● cups.service

Mar 14 13:59:36 fedora systemd[1]: Started cups.path - CUPS Scheduler.
Mar 14 14:48:48 fedora systemd[1]: cups.path: Deactivated successfully.
Mar 14 14:48:48 fedora systemd[1]: Stopped cups.path - CUPS Scheduler.
[zdohnal@fedora]-[~/repo_upstream/ipp-usb (fix_spacing $=)]
18>>>sudo systemctl start cups.socket
[zdohnal@fedora]-[~/repo_upstream/ipp-usb (fix_spacing $=)]
19>>>systemctl status cups.socket
● cups.socket - CUPS Scheduler
     Loaded: loaded (/etc/systemd/system/cups.socket; enabled; vendor preset: enabled)
     Active: active (listening) since Tue 2022-03-15 07:30:32 CET; 4s ago
      Until: Tue 2022-03-15 07:30:32 CET; 4s ago
   Triggers: ● cups.service
     Listen: /run/cups/cups.sock (Stream)
        CPU: 0
     CGroup: /system.slice/cups.socket

Mar 15 07:30:32 fedora systemd[1]: Listening on cups.socket - CUPS Scheduler.
[zdohnal@fedora]-[~/repo_upstream/ipp-usb (fix_spacing $=)]
20>>>ls -lah /run/cups/cups.sock
srw-rw-rw-. 1 root root 0 Mar 15 07:30 /run/cups/cups.sock
[zdohnal@fedora]-[~/repo_upstream/ipp-usb (fix_spacing $=)]
21>>>sudo systemctl stop cups.socket
[zdohnal@fedora]-[~/repo_upstream/ipp-usb (fix_spacing $=)]
22>>>ls -lah /run/cups/cups.sock
ls: cannot access '/run/cups/cups.sock': No such file or directory
[zdohnal@fedora]-[~/repo_upstream/ipp-usb (fix_spacing $=)]
23>>>lpstat -a
lpstat: Bad file descriptor
[zdohnal@fedora]-[~/repo_upstream/ipp-usb (fix_spacing $=)]
24>>>lpstat -e
[zdohnal@fedora]-[~/repo_upstream/ipp-usb (fix_spacing $=)]

@zdohnal
Copy link
Member

zdohnal commented Mar 15, 2022

The directive is applied in the commit 3448c52 .

@zdohnal
Copy link
Member

zdohnal commented Mar 15, 2022

Ok, the difference between RemoveOnStop and without is (from strace):

Without RemoveOnStop:

109023 08:45:55.830439 access("/run/cups/cups.sock", R_OK) = 0 <0.000015>
...
109023 08:45:55.831407 connect(3, {sa_family=AF_UNIX, sun_path="/run/cups/cups.sock"}, 22) = -1 ECONNREFUSED (Connection refused) <0.000018>

so the access syscall passes, but the connect syscall fails with Connection refused.

With RemoveOnStop=on:

101312 07:40:50.508978 access("/run/cups/cups.sock", R_OK) = -1 ENOENT (No such file or directory) <0.000048>
...
101312 07:40:50.509856 connect(3, {sa_family=AF_INET6, sin6_port=htons(631), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_scope_id=0}, 28) = -1 EINPROGRESS (Operation now in progress) <0.000165>
101312 07:40:50.510062 fcntl(3, F_SETFL, O_RDWR) = 0 <0.000009>
101312 07:40:50.510089 poll([{fd=3, events=POLLIN|POLLOUT}], 1, 100) = 1 ([{fd=3, revents=POLLIN|POLLOUT|POLLERR|POLLHUP}]) <0.000010>
101312 07:40:50.510127 close(3)         = 0 <0.000025>
...
101312 07:40:50.510398 connect(3, {sa_family=AF_INET, sin_port=htons(631), sin_addr=inet_addr("127.0.0.1")}, 16) = -1 EINPROGRESS (Operation now in progress) <0.000107>
101312 07:40:50.510532 fcntl(3, F_SETFL, O_RDWR) = 0 <0.000009>
101312 07:40:50.510559 poll([{fd=3, events=POLLIN|POLLOUT}], 1, 250) = 1 ([{fd=3, revents=POLLIN|POLLOUT|POLLERR|POLLHUP}]) <0.000009>
101312 07:40:50.510592 close(3)         = 0 <0.000014>

The program is not able to find cups.sock, but then tries IPv4+IPv6 for locahost, which end with EINPROGRESS. Looking into it further.

@michaelrsweet
Copy link
Member

@zdohnal The EINPROGRESS is because those sockets are connecting asynchronously. We might need to update httpAddrConnect2 to set errno to EHOSTUNREACH if none of the sockets are able to connect, but the output you are seeing is consistent with a TCP/IP connection attempt on multiple addresses.

@grobe0ba
Copy link

I'm not entirely sure if this is related to this specific issue or not, but
I think there is something seriously wrong with the connection handling in
2.3.3ob2. This is on RHEL 8.5, with the complication of two different cups
versions on one host. One of these is from NetBSD's pkgsrc (a multi-platform
package management system) and one version is that provided by RHEL. The
pkgsrc version is 2.3.3ob2, the RHEL version 2.2.6.

These two installations share no configuration and are entirely separate,
with different configuration directories, etc. Neither scheduler is running
on the host, and they are not meant to be. CUPS is installed only to provide
access to a remote print server, running RHEL 8.5 with only the RHEL provided
version of 2.2.6.

If I run the local 2.2.6 scheduler, both versions of lpstat will connect
successfully to /var/run/cups/cups.sock, report the scheduler is running,
no default options, etc., as it is unconfigured.

Using the 2.3.3ob2 lpstat to connect via a TCP socket results in the
connections failing, and reports of a bad file descriptor. The 2.2.6 lpstat
connects successfully with no issues at all.

Below are a trial run along with an strace using the 2.3.3ob2 lpstat. If this
should be opened in a different issue, or if I should just go away with my
stupid multiple version shenanigans, please let me know.

Any help would be appreciated.

$  ls .cups/client.conf /usr/pkg/etc/cups/client.conf /etc/cups/client.conf /var/run/cups/cups.sock
ls: cannot access '.cups/client.conf': No such file or directory
ls: cannot access '/usr/pkg/etc/cups/client.conf': No such file or directory
ls: cannot access '/etc/cups/client.conf': No such file or directory
ls: cannot access '/var/run/cups/cups.sock': No such file or directory
                                                                                                                                                                                                                    
$  env|grep CUPS                                                           
CUPS_SERVER=10.0.2.9:631
                                                                                                                                                                                                                    
$  /usr/pkg/bin/lpstat -t
scheduler is not running
no system default destination
lpstat: Bad file descriptor
lpstat: Bad file descriptor
lpstat: Bad file descriptor
lpstat: Bad file descriptor
lpstat: Bad file descriptor
                                                                                                                                                                                                                    
$  /usr/bin/lpstat -t
scheduler is running
system default destination: HLL2370DW
device for HLL2370DW: https://10.0.2.7/ipp
HLL2370DW accepting requests since Wed 27 Apr 2022 10:52:55 PM CDT
printer HLL2370DW is idle.  enabled since Wed 27 Apr 2022 10:52:55 PM CDT
                                                                                                                                                                                                                    
$  pkg_info cups-base|head -n1
Information for cups-base-2.3.3op2nb5:
                                                                                                                                                                                                                    
$  rpm -qi cups |grep Version
Version     : 2.2.6
                                                                                                                                                                                                                    
$  ssh 10.0.2.9 rpm -qi cups|grep Version
Version     : 2.2.6
                                                                                                                                                                                                                    
$ 
execve("/usr/pkg/bin/lpstat", ["lpstat", "-t"], 0x7ffea52d3b48 /* 86 vars */) = 0
...
openat(AT_FDCWD, "/usr/pkg/etc/cups/client.conf", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/home/grobe0ba/.cups/client.conf", O_RDONLY) = -1 ENOENT (No such file or directory)
socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3
connect(3, {sa_family=AF_UNIX, sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)
close(3)                                = 0
socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3
connect(3, {sa_family=AF_UNIX, sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)
close(3)                                = 0
openat(AT_FDCWD, "/etc/nsswitch.conf", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=3069, ...}) = 0
read(3, "# Generated by authselect on Thu"..., 4096) = 3069
read(3, "", 4096)                       = 0
close(3)                                = 0
openat(AT_FDCWD, "/usr/pkg/lib/libnss_sss.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=60639, ...}) = 0
mmap(NULL, 60639, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7fa4dcada000
close(3)                                = 0
openat(AT_FDCWD, "/lib64/libnss_sss.so.2", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\320\32\0\0\0\0\0\0"..., 832) = 832
lseek(3, 38600, SEEK_SET)               = 38600
read(3, "\4\0\0\0\20\0\0\0\5\0\0\0GNU\0\2\0\0\300\4\0\0\0\3\0\0\0\0\0\0\0", 32) = 32
fstat(3, {st_mode=S_IFREG|0755, st_size=46272, ...}) = 0
lseek(3, 38600, SEEK_SET)               = 38600
read(3, "\4\0\0\0\20\0\0\0\5\0\0\0GNU\0\2\0\0\300\4\0\0\0\3\0\0\0\0\0\0\0", 32) = 32
mmap(NULL, 2138968, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fa4caa0d000
mprotect(0x7fa4caa17000, 2093056, PROT_NONE) = 0
mmap(0x7fa4cac16000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x9000) = 0x7fa4cac16000
close(3)                                = 0
mprotect(0x7fa4cac16000, 4096, PROT_READ) = 0
munmap(0x7fa4dcada000, 60639)           = 0
openat(AT_FDCWD, "/var/lib/sss/mc/passwd", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0664, st_size=9253600, ...}) = 0
mmap(NULL, 9253600, PROT_READ, MAP_SHARED, 3, 0) = 0x7fa4ca139000
fstat(3, {st_mode=S_IFREG|0664, st_size=9253600, ...}) = 0
getuid()                                = 1000
rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7fa4d8767c20}, NULL, 8) = 0
brk(NULL)                               = 0x562200c3d000
brk(0x562200c5f000)                     = 0x562200c5f000
socket(AF_INET, SOCK_STREAM, IPPROTO_IP) = 4
setsockopt(4, SOL_SOCKET, SO_REUSEADDR, [1], 4) = 0
setsockopt(4, SOL_SOCKET, SO_REUSEPORT, [1], 4) = 0
setsockopt(4, SOL_TCP, TCP_NODELAY, [1], 4) = 0
fcntl(4, F_SETFD, FD_CLOEXEC)           = 0
fcntl(4, F_GETFL)                       = 0x2 (flags O_RDWR)
fcntl(4, F_SETFL, O_RDWR|O_NONBLOCK)    = 0
connect(4, {sa_family=AF_INET, sin_port=htons(631), sin_addr=inet_addr("10.0.2.9")}, 16) = -1 EINPROGRESS (Operation now in progress)
fcntl(4, F_SETFL, O_RDWR)               = 0
poll([{fd=4, events=POLLIN|POLLOUT}], 1, 250) = 1 ([{fd=4, revents=POLLOUT}])
getpeername(4, NULL, NULL)              = -1 EFAULT (Bad address)
close(4)                                = 0
openat(AT_FDCWD, "/usr/share/locale/locale.alias", O_RDONLY|O_CLOEXEC) = 4
fstat(4, {st_mode=S_IFREG|0644, st_size=2997, ...}) = 0
read(4, "# Locale name alias data base.\n#"..., 4096) = 2997
read(4, "", 4096)                       = 0
close(4)                                = 0
openat(AT_FDCWD, "/usr/share/locale/en_US.UTF-8/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale/en_US.utf8/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale/en_US/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale/en.UTF-8/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale/en.utf8/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/share/locale/en/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
close(-1)                               = -1 EBADF (Bad file descriptor)
socket(AF_INET, SOCK_STREAM, IPPROTO_IP) = 4
setsockopt(4, SOL_SOCKET, SO_REUSEADDR, [1], 4) = 0
setsockopt(4, SOL_SOCKET, SO_REUSEPORT, [1], 4) = 0
setsockopt(4, SOL_TCP, TCP_NODELAY, [1], 4) = 0
fcntl(4, F_SETFD, FD_CLOEXEC)           = 0
fcntl(4, F_GETFL)                       = 0x2 (flags O_RDWR)
fcntl(4, F_SETFL, O_RDWR|O_NONBLOCK)    = 0
connect(4, {sa_family=AF_INET, sin_port=htons(631), sin_addr=inet_addr("10.0.2.9")}, 16) = -1 EINPROGRESS (Operation now in progress)
fcntl(4, F_SETFL, O_RDWR)               = 0
poll([{fd=4, events=POLLIN|POLLOUT}], 1, 250) = 1 ([{fd=4, revents=POLLOUT}])
getpeername(4, NULL, NULL)              = -1 EFAULT (Bad address)
close(4)                                = 0
close(-1)                               = -1 EBADF (Bad file descriptor)
access("/usr/pkg/share/locale/en_US/cups_en_US.po", F_OK) = -1 ENOENT (No such file or directory)
access("/usr/pkg/share/locale/en/cups_en.po", F_OK) = 0
openat(AT_FDCWD, "/usr/pkg/share/locale/en/cups_en.po", O_RDONLY) = 4
fcntl(4, F_GETFD)                       = 0
fcntl(4, F_SETFD, FD_CLOEXEC)           = 0
read(4, "#\n# English message catalog for "..., 4096) = 4096
read(4, "               REF: Pages 52-54,"..., 4096) = 4096
read(4, "Protocols contains both PJL and "..., 4096) = 4096
read(4, "sing option %s in UIConstraints "..., 4096) = 4096
read(4, " \"\"\n\"      **FAIL**  Bad Product"..., 4096) = 4096
read(4, "\"\n\"                REF: Page 60,"..., 4096) = 4096
read(4, "se auto-typed).\"\nmsgstr \"  -i mi"..., 4096) = 4096
read(4, "econds %u (RFC 8011 section 5.1."..., 4096) = 4096
read(4, "\"\\\"%s\\\": Bad text value \\\"%s\\\" -"..., 4096) = 4096
read(4, "format\nmsgid \"%s: Error - expect"..., 4096) = 4096
read(4, "rmat\nmsgid \"%s: Missing version "..., 4096) = 4096
read(4, "E 1284 device ID\"\n\nmsgid \"--doma"..., 4096) = 4096
read(4, "\nmsgstr \"--txt-* regex          "..., 4096) = 4096
read(4, "ilters,none,profiles}\\n\"\n\"      "..., 4096) = 4096
read(4, " a copy of the print file(s)\"\nms"..., 4096) = 4096
read(4, "                    Show models\""..., 4096) = 4096
read(4, "er operation policy\"\nmsgstr \"\"\n\""..., 4096) = 4096
read(4, "urrent or specified users\"\n\nmsgi"..., 4096) = 4096
read(4, "r \"2.25x5.50\\\"\"\n\nmsgid \"2.38x5.5"..., 4096) = 4096
read(4, " Edge\"\n\nmsgid \"A1\"\nmsgstr \"A1\"\n\n"..., 4096) = 4096
read(4, "gid \"Bad job-sheets value \\\"%s\\\""..., 4096) = 4096
read(4, "gid \"Destination \\\"%s\\\" is not a"..., 4096) = 4096
read(4, "Long Edge\"\n\nmsgid \"Envelope PRC4"..., 4096) = 4096
brk(NULL)                               = 0x562200c5f000
brk(0x562200c80000)                     = 0x562200c80000
read(4, " boolean value not 1 byte.\"\nmsgs"..., 4096) = 4096
read(4, "msgid \"JIS B3\"\nmsgstr \"JIS B3\"\n\n"..., 4096) = 4096
read(4, "attribute.\"\n\nmsgid \"Missing opti"..., 4096) = 4096
read(4, "\"\nmsgstr \"Non-continuous (Web se"..., 4096) = 4096
read(4, "tr \"Printer Paused\"\n\nmsgid \"Prin"..., 4096) = 4096
read(4, "ribute cannot be supplied in a j"..., 4096) = 4096
read(4, "nsparency\"\n\nmsgid \"Tray\"\nmsgstr "..., 4096) = 4096
read(4, "yet valid).\"\n\nmsgid \"Unable to e"..., 4096) = 4096
read(4, "ata\"\nmsgstr \"Unable to write pri"..., 4096) = 4096
read(4, "d [options]\"\n\nmsgid \"Usage: cups"..., 4096) = 4096
read(4, "er to become available.\"\n\nmsgid "..., 4096) = 4096
read(4, "RANSLATORS: Silicone\nmsgid \"coat"..., 4096) = 4096
read(4, "ith the -v option.\"\n\nmsgid \"cups"..., 4096) = 4096
read(4, "tate-reasons.errors-detected\"\nms"..., 4096) = 4096
read(4, "te.edge-stitch-bottom\"\nmsgstr \"E"..., 4096) = 4096
read(4, " \"finishing-template.jdf-f16-8\"\n"..., 4096) = 4096
read(4, "RANSLATORS: JDF F64-1\nmsgid \"fin"..., 4096) = 4096
read(4, " \"finishing-template.staple-top-"..., 4096) = 4096
read(4, "ishings.63\"\nmsgstr \"Trim Job\"\n\n#"..., 4096) = 4096
read(4, "\"Signature\"\n\n#. TRANSLATORS: Ins"..., 4096) = 4096
read(4, "pe.group\"\nmsgstr \"Group\"\n\n#. TRA"..., 4096) = 4096
read(4, "ttribute missing.\"\nmsgstr \"job-p"..., 4096) = 4096
brk(NULL)                               = 0x562200c80000
brk(0x562200ca6000)                     = 0x562200ca6000
read(4, ": Digital Signature Did Not Veri"..., 4096) = 4096
read(4, "ate-reasons.job-saved-with-error"..., 4096) = 4096
read(4, "-type.semi-gloss\"\nmsgstr \"Semi-g"..., 4096) = 4096
read(4, "s on line %d.\"\nmsgstr \"lpadmin: "..., 4096) = 4096
read(4, "tr \"Material Nozzle Diameter\"\n\n#"..., 4096) = 4096
read(4, "ORS: Buff\nmsgid \"media-color.buf"..., 4096) = 4096
read(4, "ght-gold\"\nmsgstr \"Light Gold\"\n\n#"..., 4096) = 4096
read(4, "\"\n\n#. TRANSLATORS: Hagaki\nmsgid "..., 4096) = 4096
read(4, "-print-film\"\nmsgstr \"Back Print "..., 4096) = 4096
read(4, "r \"Windowed Envelope\"\n\n#. TRANSL"..., 4096) = 4096
read(4, "i Part Form\nmsgid \"media-type.mu"..., 4096) = 4096
read(4, "ransparency\nmsgid \"media-type.tr"..., 4096) = 4096
read(4, "LATORS: CEnvelope 3\nmsgid \"media"..., 4096) = 4096
read(4, "a_10x14_10x14in\"\nmsgstr \"10 x 14"..., 4096) = 4096
read(4, "LATORS: Quarto\nmsgid \"media.na_q"..., 4096) = 4096
read(4, " of class %s:\"\n\n#. TRANSLATORS: "..., 4096) = 4096
read(4, "printer-queue-order-changed\"\nmsg"..., 4096) = 4096
read(4, "\nmsgstr \"My Mailbox\"\n\n#. TRANSLA"..., 4096) = 4096
read(4, "s.\"\n\n#, c-format\nmsgid \"ppdc: Ba"..., 4096) = 4096
read(4, "e after PCFileName on line %d of"..., 4096) = 4096
read(4, "sgid \"ppdc: Missing #if on line "..., 4096) = 4096
read(4, "out\"\n\n#. TRANSLATORS: Top-bottom"..., 4096) = 4096
read(4, "TRANSLATORS: Saturation\nmsgid \"p"..., 4096) = 4096
brk(NULL)                               = 0x562200ca6000
brk(0x562200cc7000)                     = 0x562200cc7000
read(4, "ons.bander-interlock-closed\"\nmsg"..., 4096) = 4096
read(4, "nder-full\"\nmsgstr \"Binder Full\"\n"..., 4096) = 4096
read(4, "e\nmsgid \"printer-state-reasons.c"..., 4096) = 4096
read(4, "\n\n#. TRANSLATORS: Die Cutter The"..., 4096) = 4096
read(4, "der Life Almost Over\"\n\n#. TRANSL"..., 4096) = 4096
read(4, "er Empty\nmsgid \"printer-state-re"..., 4096) = 4096
read(4, "\n#. TRANSLATORS: Input Media Siz"..., 4096) = 4096
read(4, "d \"printer-state-reasons.inserte"..., 4096) = 4096
read(4, "gid \"printer-state-reasons.make-"..., 4096) = 4096
read(4, "S: Envelope Maker Turned Off\nmsg"..., 4096) = 4096
read(4, "te Ink Receptacle Full\"\n\n#. TRAN"..., 4096) = 4096
read(4, "msgid \"printer-state-reasons.mov"..., 4096) = 4096
read(4, "re\nmsgid \"printer-state-reasons."..., 4096) = 4096
read(4, "sgid \"printer-state-reasons.punc"..., 4096) = 4096
read(4, "ange\nmsgid \"printer-state-reason"..., 4096) = 4096
read(4, "tion Cutter Under Temperature\"\n\n"..., 4096) = 4096
read(4, "-rotator-resource-added\"\nmsgstr "..., 4096) = 4096
read(4, "ower Saver\"\n\n#. TRANSLATORS: Sli"..., 4096) = 4096
read(4, "pened\nmsgid \"printer-state-reaso"..., 4096) = 4096
read(4, "sgid \"printer-state-reasons.stap"..., 4096) = 4096
read(4, "LATORS: Stitcher Missing\nmsgid \""..., 4096) = 4096
read(4, "ate-reasons.subunit-motor-failur"..., 4096) = 4096
read(4, "-reasons.trimmer-life-almost-ove"..., 4096) = 4096
read(4, "losed\"\n\n#. TRANSLATORS: Wrapper "..., 4096) = 4096
read(4, "ANSLATORS: Top\nmsgid \"punching-r"..., 4096) = 4096
read(4, "n Template\nmsgid \"subscription-p"..., 4096) = 4096
read(4, "service_regtype}       DNS-SD re"..., 4096) = 649
read(4, "", 4096)                       = 0
close(4)                                = 0
fstat(1, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0
socket(AF_INET, SOCK_STREAM, IPPROTO_IP) = 4
setsockopt(4, SOL_SOCKET, SO_REUSEADDR, [1], 4) = 0
setsockopt(4, SOL_SOCKET, SO_REUSEPORT, [1], 4) = 0
setsockopt(4, SOL_TCP, TCP_NODELAY, [1], 4) = 0
fcntl(4, F_SETFD, FD_CLOEXEC)           = 0
fcntl(4, F_GETFL)                       = 0x2 (flags O_RDWR)
fcntl(4, F_SETFL, O_RDWR|O_NONBLOCK)    = 0
connect(4, {sa_family=AF_INET, sin_port=htons(631), sin_addr=inet_addr("10.0.2.9")}, 16) = -1 EINPROGRESS (Operation now in progress)
fcntl(4, F_SETFL, O_RDWR)               = 0
poll([{fd=4, events=POLLIN|POLLOUT}], 1, 250) = 1 ([{fd=4, revents=POLLOUT}])
getpeername(4, NULL, NULL)              = -1 EFAULT (Bad address)
close(4)                                = 0
close(-1)                               = -1 EBADF (Bad file descriptor)
write(2, "lpstat: Bad file descriptor\n", 28lpstat: Bad file descriptor
) = 28
socket(AF_INET, SOCK_STREAM, IPPROTO_IP) = 4
setsockopt(4, SOL_SOCKET, SO_REUSEADDR, [1], 4) = 0
setsockopt(4, SOL_SOCKET, SO_REUSEPORT, [1], 4) = 0
setsockopt(4, SOL_TCP, TCP_NODELAY, [1], 4) = 0
fcntl(4, F_SETFD, FD_CLOEXEC)           = 0
fcntl(4, F_GETFL)                       = 0x2 (flags O_RDWR)
fcntl(4, F_SETFL, O_RDWR|O_NONBLOCK)    = 0
connect(4, {sa_family=AF_INET, sin_port=htons(631), sin_addr=inet_addr("10.0.2.9")}, 16) = -1 EINPROGRESS (Operation now in progress)
fcntl(4, F_SETFL, O_RDWR)               = 0
poll([{fd=4, events=POLLIN|POLLOUT}], 1, 250) = 1 ([{fd=4, revents=POLLOUT}])
getpeername(4, NULL, NULL)              = -1 EFAULT (Bad address)
close(4)                                = 0
close(-1)                               = -1 EBADF (Bad file descriptor)
write(2, "lpstat: Bad file descriptor\n", 28lpstat: Bad file descriptor
) = 28
socket(AF_INET, SOCK_STREAM, IPPROTO_IP) = 4
setsockopt(4, SOL_SOCKET, SO_REUSEADDR, [1], 4) = 0
setsockopt(4, SOL_SOCKET, SO_REUSEPORT, [1], 4) = 0
setsockopt(4, SOL_TCP, TCP_NODELAY, [1], 4) = 0
fcntl(4, F_SETFD, FD_CLOEXEC)           = 0
fcntl(4, F_GETFL)                       = 0x2 (flags O_RDWR)
fcntl(4, F_SETFL, O_RDWR|O_NONBLOCK)    = 0
connect(4, {sa_family=AF_INET, sin_port=htons(631), sin_addr=inet_addr("10.0.2.9")}, 16) = -1 EINPROGRESS (Operation now in progress)
fcntl(4, F_SETFL, O_RDWR)               = 0
poll([{fd=4, events=POLLIN|POLLOUT}], 1, 250) = 1 ([{fd=4, revents=POLLOUT}])
getpeername(4, NULL, NULL)              = -1 EFAULT (Bad address)
close(4)                                = 0
close(-1)                               = -1 EBADF (Bad file descriptor)
write(2, "lpstat: Bad file descriptor\n", 28lpstat: Bad file descriptor
) = 28
socket(AF_INET, SOCK_STREAM, IPPROTO_IP) = 4
setsockopt(4, SOL_SOCKET, SO_REUSEADDR, [1], 4) = 0
setsockopt(4, SOL_SOCKET, SO_REUSEPORT, [1], 4) = 0
setsockopt(4, SOL_TCP, TCP_NODELAY, [1], 4) = 0
fcntl(4, F_SETFD, FD_CLOEXEC)           = 0
fcntl(4, F_GETFL)                       = 0x2 (flags O_RDWR)
fcntl(4, F_SETFL, O_RDWR|O_NONBLOCK)    = 0
connect(4, {sa_family=AF_INET, sin_port=htons(631), sin_addr=inet_addr("10.0.2.9")}, 16) = -1 EINPROGRESS (Operation now in progress)
fcntl(4, F_SETFL, O_RDWR)               = 0
poll([{fd=4, events=POLLIN|POLLOUT}], 1, 250) = 1 ([{fd=4, revents=POLLOUT}])
getpeername(4, NULL, NULL)              = -1 EFAULT (Bad address)
close(4)                                = 0
close(-1)                               = -1 EBADF (Bad file descriptor)
write(2, "lpstat: Bad file descriptor\n", 28lpstat: Bad file descriptor
) = 28
socket(AF_INET, SOCK_STREAM, IPPROTO_IP) = 4
setsockopt(4, SOL_SOCKET, SO_REUSEADDR, [1], 4) = 0
setsockopt(4, SOL_SOCKET, SO_REUSEPORT, [1], 4) = 0
setsockopt(4, SOL_TCP, TCP_NODELAY, [1], 4) = 0
fcntl(4, F_SETFD, FD_CLOEXEC)           = 0
fcntl(4, F_GETFL)                       = 0x2 (flags O_RDWR)
fcntl(4, F_SETFL, O_RDWR|O_NONBLOCK)    = 0
connect(4, {sa_family=AF_INET, sin_port=htons(631), sin_addr=inet_addr("10.0.2.9")}, 16) = -1 EINPROGRESS (Operation now in progress)
fcntl(4, F_SETFL, O_RDWR)               = 0
poll([{fd=4, events=POLLIN|POLLOUT}], 1, 250) = 1 ([{fd=4, revents=POLLOUT}])
getpeername(4, NULL, NULL)              = -1 EFAULT (Bad address)
close(4)                                = 0
close(-1)                               = -1 EBADF (Bad file descriptor)
write(2, "lpstat: Bad file descriptor\n", 28lpstat: Bad file descriptor
) = 28
write(1, "scheduler is not running\nno syst"..., 55scheduler is not running
no system default destination
) = 55
exit_group(1)                           = ?
+++ exited with 1 +++

@michaelrsweet
Copy link
Member

Pushed some fixes for this.

zdohnal added a commit to zdohnal/cups that referenced this issue Oct 13, 2023
Some kernel versions (seen in CentOS Stream 9.2 for some setups)
return `EINPROGRESS` when client tries to connect to localhost:631
and cupsd is not running, and the following `poll()` times out,
which causes delays for the application using libcups.

The PR is my understanding of
OpenPrinting#352 (comment)
where you mention setting errno to EHOSTUNREACH if none of the addresses
can be connected at the moment. The problem here is the code sets
EHOSTUNREACH if the last errno was EINPROGRESS, but implementing saving
of errnos for previous connection attempts looked not worthy of effort,
since the final result is the same (client cannot connect on that
address at the moment).

I've implemented the same behavior for WIN32 too.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working priority-medium
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants