Polling busy loop #2988

Closed
michaelrsweet opened this Issue Nov 5, 2008 · 5 comments

Comments

Projects
None yet
1 participant
Collaborator

michaelrsweet commented Nov 5, 2008

Version: 1.3.9
CUPS.org User: twaugh.redhat

Very rarely (but twice now) I've seen cupsd stuck in a busy loop. Examining it with a debugger reveals:

poll() returned 1

the only pfd with revents has its read_cb callback called

this is a localhost connection over /var/run/cups/cups.sock

con->state == HTTP_POST_SEND

cupsdReadClient() therefore never reads from the descriptor

..and so we loop again

I haven't figured out why this occurs.

Collaborator

michaelrsweet commented Nov 5, 2008

CUPS.org User: twaugh.redhat

This is on Fedora 9, with cups-1.3.9-1.fc9.

Here is fdptr->data:

(gdb) p (cupsd_client_t)fdptr->data
$8 = {http = {fd = 30, blocking = 0, error = 0, activity = 1225908147,
state = HTTP_POST_SEND, status = HTTP_OK, version = HTTP_1_1,
keep_alive = HTTP_KEEPALIVE_ON, _hostaddr = {sin_family = 0, sin_port = 0,
sin_addr = {s_addr = 0}, sin_zero = "\000\000\000\000\000\000\000"},
hostname = "localhost", '\0' <repeats 246 times>, fields = {
'\0' <repeats 255 times>, '\0' <repeats 255 times>,
'\0' <repeats 255 times>, '\0' <repeats 255 times>,
'\0' <repeats 255 times>, '\0' <repeats 255 times>,
"75", '\0' <repeats 253 times>, '\0' <repeats 255 times>,
'\0' <repeats 255 times>, '\0' <repeats 255 times>,
"application/ipp", '\0' <repeats 240 times>, '\0' <repeats 255 times>,
'\0' <repeats 255 times>, "localhost", '\0' <repeats 246 times>,
'\0' <repeats 255 times> <repeats 11 times>,
"CUPS/1.3.9", '\0' <repeats 245 times>, '\0' <repeats 255 times>},
data = 0x0, data_encoding = HTTP_ENCODE_LENGTH, _data_remaining = 0,
used = 0,
buffer = "\003n-gb\003b\003es-natural-language\000\005en-gb\003b\003\003n-gb\003b\003l-language\000\005en-gb\003b\003\003\003\000\005en-gb\003ect: 100-continue\r\n\r\nct: 100-continue\r\n\r\n 100-continue\r\n\r\n", '\0' <repeats 1914 times>, auth_type = 0, md5_state = {count = {0, 0}, abcd = {0, 0, 0, 0},
buf = '\0' <repeats 63 times>}, nonce = '\0' <repeats 255 times>,
nonce_count = 0, tls = 0x0, encryption = HTTP_ENCRYPT_IF_REQUESTED,
input_set = 0x0, expect = HTTP_CONTINUE, cookie = 0x0,
---Type to continue, or q to quit---
_authstring = '\0' <repeats 255 times>,
userpass = '\0' <repeats 255 times>, digest_tries = 0, data_remaining = 0,
hostaddr = 0x7ff3d9b0b314, addrlist = 0x0,
wbuffer = '\0' <repeats 2047 times>, wused = 0, field_authorization = 0x0,
authstring = 0x0, gssmech = 0x0, gssctx = 0x0, gssname = 0x0},
request = 0x7ff3d9a708b0, response = 0x0, best = 0x7ff3d9a65140,
start = 1225908147, operation = HTTP_POST, bytes = 75, type = 0,
username = '\0' <repeats 255 times>, password = '\0' <repeats 32 times>,
uri = "/", '\0' <repeats 1022 times>, filename = 0x0, command = 0x0,
options = 0x0, query_string = 0x0, file = 32, file_ready = 0,
pipe_pid = 27833, sent_header = 0, got_fields = 0, field_col = 0,
language = 0x7ff3d9a3aad0, auto_ssl = 0, clientaddr = {addr = {
sa_family = 1, sa_data = '\0' <repeats 13 times>}, ipv4 = {
sin_family = 1, sin_port = 0, sin_addr = {s_addr = 0},
sin_zero = "\000\000\000\000\000\000\000"}, ipv6 = {sin6_family = 1,
sin6_port = 0, sin6_flowinfo = 0, sin6_addr = {__in6_u = {
__u6_addr8 = '\0' <repeats 15 times>, __u6_addr16 = {0, 0, 0, 0, 0,
0, 0, 0}, __u6_addr32 = {0, 0, 0, 0}}}, sin6_scope_id = 0}, un = {
sun_family = 1, sun_path = '\0' <repeats 107 times>},
pad = "\001", '\0' <repeats 254 times>},
servername = "localhost", '\0' <repeats 246 times>, serverport = 631,
gss_have_creds = 0, gss_output_token = {length = 0, value = 0x0},
gss_delegated_cred = 0x0, scon = 0x7ff3d9a7c510 "UNKNOWN SL", auid = 0}

Collaborator

michaelrsweet commented Nov 7, 2008

CUPS.org User: twaugh.redhat

More information, as this happened again today.

Prodding it with gdb so that con->http.state=HTTP_WAITING, just to see what httpGets says is there to read, it turns out that it returns NULL.

So the event on the file descriptor is just that the connection has closed.

Sure enough, event->events == EPOLLIN|EPOLLHUP so we even know this is the case before trying to read. (This is on a system with HAVE_EPOLL.)

I wonder if the solution is to have a 'default:' case in the switch(con->http.state) part to handle this.

Collaborator

michaelrsweet commented Nov 11, 2008

CUPS.org User: mike

Can you try the attached patch and let me know if it eliminates the problem for you?

Collaborator

michaelrsweet commented Nov 20, 2008

CUPS.org User: twaugh.redhat

I haven't seen the problem since applying the patch.

Collaborator

michaelrsweet commented Nov 20, 2008

"str2988.patch":

Index: scheduler/client.c

--- scheduler/client.c (revision 8107)
+++ scheduler/client.c (working copy)
@@ -1077,6 +1077,15 @@
break;

 default :
  •    if (!data_ready(con) && recv(con->http.fd, buf, 1, MSG_PEEK) < 1)
    
  • {
  • /*
  • \* Connection closed...
    
  • */
    
  •      cupsdCloseClient(con);
    
  • return;
    
  • }
    break; /* Anti-compiler-warning-code */
    }

michaelrsweet added this to the Stable milestone Mar 17, 2016

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment