Endless loop in /usr/lib/udev/udev-configure-printer

[mvogt1]

This happend today:

• cups server did not print anymore
• a client is looping in connect->fd->close->connect

Cause is unknown. Maybe the cups server hit a rate limit because it prints:

Flooding server log:

Dec 11 04:37:32 cupsserver kernel: STATE_INVALID_DROP: IN=ens32 OUT= MAC=xx SRC=<clientip> DST=<cupsserver> LEN=40 TOS=0x00 PREC=0x00 TTL=64 ID=51545 DF PROTO=TCP SPT=43770 DPT=631 WINDOW=0 RES=0x00 RST URGP=0

The client is in an endless loop, this flooded the server, which prints the above message until the HD ist full, then
cups does not print anymore.

The endless loop of the client straced, from connect->close->to connect again.

connect(5, {sa_family=AF_INET, sin_port=htons(631),sin_addr=inet_addr("cupsserver")}, 16) = -1 EINPROGRESS (Operation now in progress)
fcntl(5, F_SETFL, O_RDWR)               = 0
poll([{fd=5, events=POLLIN|POLLOUT}], 1, 250) = 1 ([{fd=5, revents=POLLOUT}])
getpeername(5, {sa_family=AF_INET, sin_port=htons(631),sin_addr=inet_addr(10.x.y.z)}, [256->16]) = 0
uname({sysname="Linux", nodename="client.linux", ...}) = 0
sendto(5, "OPTIONS * HTTP/1.1\r\nConnection: Upgrade\r\nHost: cupsserver.domain.de:631\r\nUpgrade: TLS/1.1,TLS/1.0\r\nUser-Agent: CUPS/1.6.3 (Linux 3.10.0-1160.80.1.el7.x86_64; x86_64) IPP/2.0\r\n\r\n", 173, 0, NULL, 0) =
poll([{fd=5, events=POLLIN}], 1, 60000) = 1 ([{fd=5, revents=POLLIN}])
recvfrom(5, "HTTP/1.1 101 Switching Protocols\r\nDate: Mon, 12 Dec 2022 09:19:10 GMT\r\nServer: CUPS/1.6 IPP/2.1\r\nConnection: Keep-Alive\r\nKeep-Alive: timeout=30\r\nContent-Language: en_US\r\nConnection: Upgrade\r\
sendto(5, "\26\3\1\1\20\1\0\1\f\...)"
recvfrom(5, "\26\3\3\0:\2\0", 7, 0, NULL, NULL) = 7
recvfrom(5, "\0006\3\3\3034\210\241\33f\302\367Q\2217\307iT\32\220n\325\\17\0\1\1", 56, 0, NULL, NULL) = 56
recvfrom(5, "\26\3\3\26\326", 5, 0, NULL, NULL) = 5
recvfrom(5, "\v\0\26\322\0\26\317\010\f\6Bayern1\0210\17\6\3U\4\7\f\10M...)
recvfrom(5, "\26\3\3\0\4", 5, 0, NULL, NULL) = 5
recvfrom(5, "\16\0\0\0", 4, 0, NULL, NULL) = 4
sendto(5, "\26\3\3\1\6\2...)"
recvfrom(5, "\26\3\3\0\252", 5, 0, NULL, NULL) = 5
recvfrom(5, "\4\0\0\246\0\0\1,\0\...")
recvfrom(5, "\24\3\3\0\1", 5, 0, NULL, NULL) = 5
recvfrom(5, "\1", 1, 0, NULL, NULL)     = 1
recvfrom(5, "\26\3\3\0(", 5, 0, NULL, NULL) = 5
recvfrom(5, "\230/\230\351\257\7\201h\237\347A\v\12e\27\376", 40, 0, NULL, NULL) = 40
poll([{fd=5, events=POLLIN}], 1, 60000) = 1 ([{fd=5, revents=POLLIN}])
recvfrom(5, "\27\3\3\0\306", 5, 0, NULL, NULL) = 5
recvfrom(5, "\230/\23...")
sendto(5, "...)
close(5)                                = 0
socket(AF_INET, SOCK_STREAM, IPPROTO_IP) = 5
setsockopt(5, SOL_SOCKET, SO_REUSEADDR, [1], 4) = 0
setsockopt(5, SOL_SOCKET, SO_REUSEPORT, [1], 4) = 0
setsockopt(5, SOL_TCP, TCP_NODELAY, [1], 4) = 0
fcntl(5, F_SETFD, FD_CLOEXEC)           = 0
fcntl(5, F_GETFL)                       = 0x2 (flags O_RDWR)
fcntl(5, F_SETFL, O_RDWR|O_NONBLOCK)    = 0
connect(5, {sa_family=AF_INET, sin_port=htons(631),sin_addr=inet_addr("cupsserver")}, 16) = -1 EINPROGRESS (Operation now in progress)

When looking at the source code:

https://github.com/OpenPrinting/system-config-printer/blob/master/udev/udev-configure-printer.c

I dont see this loop, the pid is always the same, so its whithin this process.
The compiled version is from:

system-config-printer-1.4.8-2.el7.3.src.rpm

Which is rather old based on system-config-printer-1.4.1.tar.xz.

Restarting cups exited the client binary, no problem anymore.

The reason for the endless looping client is unknown.

[mvogt1]

When I restarted the cups process the client behaves like:

sendto(5, "OPTIONS * HTTP/1.1\r\nConnection: Upgrade\r\nHost: cupsserver.domain.de:631\r\nUpgrade: TLS/1.1,TLS/1.0\r\nUser-Agent: CUPS/1.6.3 (Linux 3.10.0-1160.80.1.el7.x86_64; x86_64) IPP/2.0\r\n\r\n", 173, 0, NULL, 0) = 173
poll([{fd=5, events=POLLIN}], 1, 60000) = 1 ([{fd=5, revents=POLLIN|POLLERR|POLLHUP}])
recvfrom(5, 0x1582dfc, 2048, 0, NULL, NULL) = -1 ECONNRESET (Connection reset by peer)
poll([{fd=5, events=POLLIN}], 1, 60000) = 1 ([{fd=5, revents=POLLIN|POLLHUP}])
recvfrom(5, "", 2048, 0, NULL, NULL)    = 0
close(5)                                = 0
sendto(3, "<51>Dec 12 14:49:56 udev-configure-printer: failed to send IPP request 16395", 76, MSG_NOSIGNAL, NULL, 0) = 76
exit_group(1)                           = ?
+++ exited with 1 +++

This maybe is helpfull.

The code for this part is:

static ipp_t *
cupsDoRequestOrDie (http_t *http,
                    ipp_t *request,
                    const char *resource)
{
  ipp_t *answer = cupsDoRequest (http, request, resource);
  if (answer == NULL)
    {
      syslog (LOG_ERR, "failed to send IPP request %d",
              ippGetOperation (request));
      exit (1);
    }

[...]

Which seems in the cups api:
https://github.com/apple/cups/blob/master/cups/request.c#L278

And this calls:
https://github.com/apple/cups/blob/master/cups/request.c#L80

And this is at least some loop, but I cannot tell if this is reached:
https://github.com/apple/cups/blob/master/cups/request.c#L193

So the client is in an endless loop until the cups server is restartet.