endless poll loop in http_write when POLLHUP is returned

[vliaskov]

Describe the bug

Customer observes that cupsd occasionally gets stuck in a poll() loop. strace shows:

poll([{fd=30, events=POLLOUT}], 1, 10000) = 1 ([{fd=30, revents=POLLOUT|POLLHUP}])
poll([{fd=30, events=POLLOUT}], 1, 10000) = 1 ([{fd=30, revents=POLLOUT|POLLHUP}])
poll([{fd=30, events=POLLOUT}], 1, 10000) = 1 ([{fd=30, revents=POLLOUT|POLLHUP}])

If POLLHUP is received (i.e. the connection's other end was closed?), should we continue polling? Should POLLHUP be checked in the revents to break the loop? I haven't yet found an obvious upstream fix for this, so I am opening the bug.

Backtrace of the cupsd process:

(gdb) bt
#0  0x00007f828cb92963 in ?? () at ../sysdeps/wordsize-64/../../io/fts.c:1062 from /lib64/libc.so.6
#1  0x00007f828cf2d903 in poll (__timeout=<optimized out>, __nfds=1, __fds=0x7ffeabd1c3d8) at /usr/include/bits/poll2.h:46
#2  http_write (http=http@entry=0x557afca93d00, buffer=buffer@entry=0x7ffeabd1c420 "20b\r\n", length=5) at http.c:4690
#3  0x00007f828cf2daa4 in http_write_chunk (http=0x557afca93d00, 
    buffer=0x557afca964f8 "/printers/bamp0027ls\">bamp0027ls</A></TD><TD>bamp0027ls</TD><TD>BAM</TD><TD>LaserSoft printer</TD><TD>bampadm - retry-current-job</TD><TD>Idle</TD></TR>\n\n<TR><TD><A HREF=\"/printers/bamp0028\">bamp0028<"..., length=523) at http.c:4820
#4  0x00007f828cf2de35 in httpFlushWrite (http=0x557afca93d00) at http.c:704
#5  0x0000557aea021a79 in cupsdWriteClient (con=0x557afcd38560) at client.c:2727
#6  0x0000557aea04adfb in cupsdDoSelect (timeout=timeout@entry=1) at select.c:489
#7  0x0000557aea019b5e in main (argc=<optimized out>, argv=<optimized out>) at main.c:831

To Reproduce

Unfortunately, I am still not clear on how to reproduce this. Probably clients need to be closed while cupsd is sending data to them. I will update if I have an exact reproducer from the customer.

If there are ideas on how to stress test this let me know. Is there an existing testcase that would stress this scenario?

Expected behavior
Cups should not keep polling indefinitely if the other side has hung up.

System Information:

• OS and its version: SLE15-SP4, x86_64
• CUPS version 2.2.7 (2.2.7-150000.3.46.1)

[zdohnal]

Hi @vliaskov ,

actually we have a RHEL customer experiencing issues with CUPS due the same reason - poll() gets POLLOUT|POLLHUP from kernel (in their case CUPS API function fails to connect to local cupsd after the first successful job) - I have a patch verified by the customer and I will send PR this week.
@michaelrsweet the core of the patch is basically similar as we did in #156 for Solaris - check the socket option SO_ERROR in case we get combinations POLLOUT|POLLHUP or POLLIN|POLLHUP and if it is fine, remove the POLLHUP from returned poll events and proceed with clear POLLOUT/POLLIN. I've looked whether such event combinations are expected to come from kernel, and though POLLIN|POLLHUP are quite common and valid combinations, POLLOUT|POLLHUP was not allowed in older versions of poll() man pages, but it is not mentioned in the current man page anymore, so it looks like a new allowed combination as well.
I got this idea how to handle such issues from more senior colleague, but he is not from Kernel team - I can try to reach out Kernel team if you think it is a kernel issue.

[michaelrsweet]

@zdohnal If the POLLHUP is showing up in revents before all data has been read from the socket, IMHO that would be a bug or at least inconsistent with other Unix operating systems. Happy to review whatever fix you come up with...

[zdohnal]

@vliaskov actually the revents are the same, but it happens in a different place for you - can you compile CUPS with debug-printfs, set cupsd to use debug printfs (by passing CUPS_DEBUG_LOG (location of log file), CUPS_DEBUG_FILTER (which messages to get - .*) and CUPS_DEBUG_LEVEL (0-9 - set it to 9) env variables to cupsd), enable debug logging via LogLevel in cupsd.conf and strace the cupsd when it happens?
In the end please attach strace log and file with debug printfs. Thank you!

[zdohnal]

From the logs you showed it looks poll() returns nfds, so we shouldn't iterate in http_write with poll() callings... other polls can happen in send() and seeing debug_printfs can help.

[vliaskov]

thank you for the input and suggestions @zdohnal . Sorry for the delay, I was on vacation. I will ask the customer for logs (they already had some but I think that the CUPS_DEBUG_FILTER .* will provide more info). Unfortunately the customer has a massive amount of queues and they claim that even CUPS_DEBUG_LEVEL=8 (debug) is not feasible for them without creating huge files, let alone CUPS_DEBUG_LEVEL=9 (debug2) . CUPS_DEBUG_LEVEL=7 (info) will be possible, not sure about the higher levels. I am also not sure what the file size limit is for github attachments.

By the way, if there is a draft of the patch mentioned in #827 (comment) that can be used for testing, please point me to it. Although as you say the poll hangs happen at a different place in this case, so the patch is perhaps not covering this case...

[zdohnal]

@vliaskov hmm... can you patch the debug_printfs in http_write() to be used in info level? I'm primary interested in those messages, so I would like to see their output - and then enable debug printfs for cupsd for CUPS_DEBUG_LEVEL=7?

Additionally, just to be sure it would be great to add new debug_printfs at info level in http_write to get more idea about the execution.
Please a debug printfs in similar way (pseudocode, I haven't compile it, but it demonstrate where to put the printfs - line numbers are from current upstream master):

http_write():
+              int i = 1;
4253       do
4254       {
4255         pfd.fd     = http->fd;
4256         pfd.events = POLLOUT;
4257 
+                int k = 1;
4258         do
4259         {
4260           nfds = poll(&pfd, 1, http->wait_value);
+                  debug_printf("7http_write: in poll loop - run %d.%d, nfds %d, errno %s", i, k++, nfds, strerror(errno));
4261         }
4262 #  ifdef _WIN32
4263         while (nfds < 0 && (WSAGetLastError() == WSAEINTR || WSAGetLastError() == WSAEWOULDBLOCK));
4264 #  else
4265         while (nfds < 0 && (errno == EINTR || errno == EAGAIN));
4266 #  endif // _WIN32
4267 
4268         if (nfds < 0)
4269         {
+                  debug_printf("7http_write: %d nfds %d, errno %s", i, nfds, strerror(errno));
4270           http->error = errno;
4271           return (-1);
4272         }
4273         else if (nfds == 0 && (!http->timeout_cb || !(*http->timeout_cb)(http, http->timeout_data)))
4274         {
4275 #ifdef _WIN32
4276           http->error = WSAEWOULDBLOCK;
4277 #else
4278           http->error = EWOULDBLOCK;
4279 #endif // _WIN32
+                  debug_printf("7http_write: %d nfds %d, errno %s", i, nfds, strerror(http->error));
4280           return (-1);
4281         }
+                debug_printf("7http_write: end of loop %d for getting nfds", i++);
4282       }
4283       while (nfds <= 0);
4284     }
4285 
4286     if (http->tls)
+            {
+              debug_printf("7http_write: send via TLS");
4287       bytes = _httpTLSWrite(http, buffer, (int)length);
+            }
4288     else
+            {
+              debug_printf("7http_write: send unencrypted");
4289       bytes = send(http->fd, buffer, length, 0);
+             }
...
4310         continue;
4311       }
4312 
4313 #else
+              debug_printf("7http_write: error writing data (%s).", strerror(errno));
4314       if (errno == EINTR)
4315       {
4316         continue;
4317       }

Additionally, just to be sure in case if a TLS library is in play, add/change debug printf in _httpTLSWrite() CUPS implementation for your TLS library - it would be interesting to see the result and errno coming from TLS function such as gnutls_record_send() (but this depend on what TLS library you use).

After that, enable cupsd logging at debug2 (LogLevel debug2 in /etc/cups/cupsd.conf), restart it and attach strace (strace -p <cupsd pid> -v -f -tt -T -yy -Y -o cupsd.strace -s 4092).

It would be great to see all those files, because it will give us idea what's going on - IMO either glibc (send()) or TLS library (depends on what library you use to compile with CUPS in SUSE - it is GNUTLS in RHEL) does not take kindly to a descriptor with POLLHUP.

Ad the patch - the core of the patch is to check SO_ERROR socket option on the descriptor (the same way as we do in cups/http-addrlist.c, httpAddrConnect2() for __sun), and if there is no error there, remove the POLLHUP from revents, which is later checked by the function. But we don't check revents in http_write(), so such patch is useless IMHO...

[vliaskov]

Thank you. Btw, do you mean to use debug_printf or DEBUG_printf in the patch above? Just making sure we use the desired debug function .

We also use GNUTLS, there are already DEBUG_printf calls for the errno, do you want changes below?

int                                     /* O - Bytes written */
_httpTLSWrite(http_t     *http,         /* I - Connection to server */
              const char *buf,          /* I - Buffer holding data */
              int        len)           /* I - Length of buffer */
{
  ssize_t       result;                 /* Return value */


  DEBUG_printf(("2http_write_ssl(http=%p, buf=%p, len=%d)", http, buf, len));

  result = gnutls_record_send(http->tls, buf, (size_t)len);

  if (result < 0 && !errno)
  {
   /*
    * Convert GNU TLS error to errno value...
    */

    switch (result)
    {
      case GNUTLS_E_INTERRUPTED :
          errno = EINTR;
          break;

      case GNUTLS_E_AGAIN :
          errno = EAGAIN;
          break;

      default :
          errno = EPIPE;
          break;
    }

    result = -1;
  }

  DEBUG_printf(("3http_write_ssl: Returning %d.", (int)result));

  return ((int)result);
}

[zdohnal]

DEBUG_printf(), because that's the one which is available for whole library. I found debug_printf() only in snmp backend.

Ad gnutls - it would be great to see result and errno which come straight from gnutls call, so put the debug printf right after the command and print result and strerror(errno).

[vliaskov]

DEBUG_printf(), because that's the one which is available for whole library. I found debug_printf() only in snmp backend.

Ad gnutls - it would be great to see result and errno which come straight from gnutls call, so put the debug printf right after the command and print result and strerror(errno).

understood, thanks.

[vliaskov]

Customer is having issues with huge log files (and the issue takes at least a few hours to trigger).

@zdohnal can you suggest a more restrictive CUPS_DEBUG_FILTER setting (not the capture-all setting ".*") that would still provide useful information to you for debugging, while avoiding capturing everything? Or is that not possible?

[zdohnal]

IMO you can try filter it by 'http_write' - it should give us the more narrowed data.