parallel goes into endless loop

Never heard about such behavior, seems really to be the best to attach it with gdb. Can you do that? I do not have a parallel port printer.

On 02/20/2012 08:11 PM, Till Kamppeter wrote:
> Never heard about such behavior, seems really to be the best to attach
> it with gdb. Can you do that? I do not have a parallel port printer.
>

Yes, I can do it. Just need to find the time. For now I reverted back my
cups version.

Thanks,
Bernd

I seem to suffer from the same problem, so here is what I could find out so far. Attached with strace, this is the only thing that eats up all CPU power:

[...]
select(6, [0 4], [], NULL, {5, 0}) = 2 (in [0 4], left {4, 999998})
poll([{fd=4, events=POLLIN}], 1, 1000) = 1 ([{fd=4, revents=POLLIN|POLLHUP}])
read(4, "", 16388) = 0
select(6, [0 4], [], NULL, {5, 0}) = 2 (in [0 4], left {4, 999997})
poll([{fd=4, events=POLLIN}], 1, 1000) = 1 ([{fd=4, revents=POLLIN|POLLHUP}])
read(4, "", 16388) = 0
select(6, [0 4], [], NULL, {5, 0}) = 2 (in [0 4], left {4, 999998})
poll([{fd=4, events=POLLIN}], 1, 1000) = 1 ([{fd=4, revents=POLLIN|POLLHUP}])
read(4, "", 16388) = 0
[...]

In gdb, I only managed to get this:

Thread 1 (Thread 0x7fcc62d7d740 (LWP 20393)):
#0 0x00007fcc62723d10 in __read_nocancel () from /lib/x86_64-linux-gnu/libpthread.so.0
#1 0x00007fcc6296b7c4 in cupsSideChannelRead () from /usr/lib/x86_64-linux-gnu/libcups.so.2
#2 0x00007fcc62dac950 in main ()

Maybe it's related that with this cups version all command line tools like lpq and lpstat ceased to work, too. I can see the usual linefeeds, but all lines are empty. For example, "lpstat -t" gives 12 empty lines. I also used strace to get a clue, and it seems that the server gives empty strings via the socket.

Stracing "lpq -a -l" ends with this:

socket(PF_FILE, SOCK_STREAM, 0) = 4
setsockopt(4, SOL_SOCKET, SO_REUSEADDR, [1], 4) = 0
setsockopt(4, SOL_TCP, TCP_NODELAY, [1], 4) = -1 EOPNOTSUPP (Operation not supported)
fcntl(4, F_SETFD, FD_CLOEXEC) = 0
connect(4, {sa_family=AF_FILE, path="/var/run/cups/cups.sock"}, 26) = 0
sendto(4, "POST / HTTP/1.1\r\nContent-Length: 260\r\nContent-Type: application/ipp\r\nHost: localhost\r\nUser-Agent: CUPS/1.5.2\r\nExpect: 100-continue\r\n\r\n", 134, 0, NULL, 0) = 134
sendto(4, "\1\1\0\n\0\0\0\1\1G\0\22attributes-charset\0\5utf-8H\0\33attributes-natural-language\0\5de-deE\0\vprinter-uri\0\20ipp://localhost/D\0\24requested-attributes\0\6copiesD\0\0\0\6job-idD\0\0\0\fjob-k-octetsD\0\0\0\10job-nameD\0\0\0\31job-originating-user-nameD\0\0\0\17job-printer-uriD\0\0\0\fjob-priorityD\0\0\0\tjob-state\3", 260, 0, NULL, 0) = 260
poll([{fd=4, events=POLLIN}], 1, 1000) = 1 ([{fd=4, revents=POLLIN}])
poll([{fd=4, events=POLLIN}], 1, 60000) = 1 ([{fd=4, revents=POLLIN}])
recvfrom(4, "HTTP/1.1 100 Continue\r\n\r\nHTTP/1.1 200 OK\r\nDate: Thu, 08 Mar 2012 22:06:31 GMT\r\nServer: CUPS/1.5\r\nConnection: Keep-Alive\r\nKeep-Alive: timeout=30\r\nContent-Language: en_US\r\nContent-Type: application/ipp\r\nContent-Length: 75\r\n\r\n\1\1\0\0\0\0\0\1\1G\0\22attributes-charset\0\5utf-8H\0\33attributes-natural-language\0\5de-de\3", 2048, 0, NULL, NULL) = 298
fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 3), ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f88eb555000
write(1, "\n", 1
) = 1
close(4) = 0
exit_group(0) = ?

This is the only communication through the socket, and that single line feed is the only thing it writes to stdout.
At the same time, the cups debug log says:

D [08/Mar/2012:23:15:16 +0100] cupsdAcceptClient: 18 from localhost (Domain)
D [08/Mar/2012:23:15:16 +0100] cupsdReadClient: 18 POST / HTTP/1.1
D [08/Mar/2012:23:15:16 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [08/Mar/2012:23:15:16 +0100] cupsdAuthorize: No authentication data provided.
D [08/Mar/2012:23:15:16 +0100] cupsdReadClient: 18 1.1 Get-Jobs 1
D [08/Mar/2012:23:15:16 +0100] Get-Jobs ipp://localhost/
D [08/Mar/2012:23:15:16 +0100] Returning IPP successful-ok for Get-Jobs (ipp://localhost/) from localhost
D [08/Mar/2012:23:15:16 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [08/Mar/2012:23:15:16 +0100] cupsdReadClient: 18 WAITING Closing on EOF
D [08/Mar/2012:23:15:16 +0100] cupsdCloseClient: 18
D [08/Mar/2012:23:15:16 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"

Still unsure if this is caused by the same bug or if I should report new one.

I just compiled parallel.c with debug symbols, installed it and spooled a test page. After it reached the endless loop, I attached gdb to the process and got this backtrace:

#0 0x00007f20b4d26a93 in select () from /lib/x86_64-linux-gnu/libc.so.6
#1 0x00007f20b56901bd in run_loop (print_fd=0, device_fd=5, use_bc=0, update_state=1) at parallel.c:629
#2 0x00007f20b568f8bd in main (argc=6, argv=0x7fff1e9353d8) at parallel.c:261

Stepping through the program shows this loop:

run_loop (print_fd=0, device_fd=5, use_bc=0, update_state=1) at parallel.c:663
663 continue;
614 FD_ZERO(&input);
615 if (!print_bytes)
616 FD_SET(print_fd, &input);
617 if (use_bc)
619 if (!print_bytes)
620 FD_SET(CUPS_SC_FD, &input);
622 FD_ZERO(&output);
623 if (print_bytes)
626 timeout.tv_sec = 5;
627 timeout.tv_usec = 0;
629 if (select(nfds, &input, &output, NULL, &timeout) < 0)
655 if (FD_ISSET(CUPS_SC_FD, &input))
662 side_cb(print_fd, device_fd, use_bc);
side_cb (print_fd=0, device_fd=5, use_bc=0) at parallel.c:797
797 {
804 datalen = sizeof(data);
806 if (cupsSideChannelRead(&command, &status, data, &datalen, 1.0))
807 return (-1);
851 }

This snippet repeats forever.

The parallel CUPS backend is in the cups-filters package from Precise on, moving ...

Ulf, can you apply the attached patch to parallel.c and see whether it solves the problem? Thanks.

Yeah, the patch helps! Printing works again.

The other problem (authistic lpq and lpstat) remains and seems completely unrelated, so I will file another bug for that.

Ulf, thank you, so the patch will get forwarded upstream and added to our package. Thank you very much for the debugging work.

The lpstat problem is already solved upstream (http://www.cups.org/str.php?L4033), this will also go into our package.

One thing about where the stuff goes:

The parallel backend is upstream twice: For Ubuntu and Debian it is in cups-filters and for all the other distros in cups. I will apply the patch to cups-filters and report the problem to cups. From CUPS 1.6.x on it will be only in cups-filters.

The lpstat problem is in cups.

Fix committed to cups-filters upstream.

I have fixed the problem in cups-filters upstream (1.0.5) now. A Precise package is on its way.

Thank you very much for all your work on finding this, Ulf!

This bug was fixed in the package cups-filters - 1.0.5-1

---------------
cups-filters (1.0.5-1) unstable; urgency=low

  * New upstream release
    - cups-filters 1.0.5 release
    - pdftops: Added insertion of workaround PostScript code for printers
      with bugs in their PS interpreters (LP: #950713, LP: #951627).
    - parallel backend: Break infinite loop (LP: #936647).
    - texttopdf: Complete the implementation of fontconfig-based font
      selection (Closes: #663070).
 -- Martin Pitt <email address hidden> Wed, 14 Mar 2012 11:43:22 +0100