Gentoo Websites Logo
Go to: Gentoo Home Documentation Forums Lists Bugs Planet Store Wiki Get Gentoo!
Bug 430498 - net-print/cups-bjnp-1.0 and net-print/cups-1.6.1: Failed to read side-channel request!
Summary: net-print/cups-bjnp-1.0 and net-print/cups-1.6.1: Failed to read side-channel...
Status: RESOLVED FIXED
Alias: None
Product: Gentoo Linux
Classification: Unclassified
Component: [OLD] Printing (show other bugs)
Hardware: All Linux
: Normal normal (vote)
Assignee: Printing Team
URL:
Whiteboard:
Keywords:
Depends on:
Blocks: cups-1.6-stable
  Show dependency tree
 
Reported: 2012-08-08 21:46 UTC by Martin von Gagern
Modified: 2013-05-13 20:07 UTC (History)
0 users

See Also:
Package list:
Runtime testing required: ---


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Martin von Gagern 2012-08-08 21:46:44 UTC
I'm trying to get a Canon PIXMA 885 printer to work over IP using cups and bjnp. Hoever, printing the test page fails (the printer does nothing), and cups prints an error message: "Failed to read side-channel request!"

I just traced this message to its apparent origin. strace includes these lines:

select(8, [0 4 7], [], NULL, {3, 0})    = 2 (in [0 4], left {2, 999997})
write(5, "21:02:50.913 cupsSideChannelRead(command=0x7fff52b0c02c,"
         " status=0x7fff52b0c028, data=0x7fff52b0b200,"
         " datalen=0x7fff52b0c024(2048), timeout=1.000)\n", 146) = 146
poll([{fd=4, events=POLLIN}], 1, 1000)  = 1 ([{fd=4, revents=POLLIN|POLLHUP}])
read(4, "", 65540)                      = 0
write(5, "21:02:50.913 cupsSideChannelRead: Short read of 0 bytes\n", 56) = 56
write(2, "WARNING: Failed to read side-channel request!\n", 46) = 46

cupsSideChannelRead is a function in libcups.so. It operates on a unix domain socket which is already opened by the time the bjnp process gets executed. Apparently cups uses that to communicate with its backends. So the select syscall in the main bjnp run loop returns that socket as readable, as does the poll syscall in cupsSideChannelRead itself. However, actually trying to read any data from it fails. It seems the socket was opened in non-blocking mode, so we get a zero-length read instead of blocking behaviour.

The BUGS section of the poll(2) man page states:
  “See the discussion of spurious readiness notifications under the BUGS
   section of select(2).”
And there one can read:
  “Under Linux, select() may report a socket file descriptor as "ready for
   reading", while nevertheless a subsequent read blocks. This could for
   example happen when data has arrived but upon examination has wrong
   checksum and is discarded. There may be other circumstances in which a
   file descriptor is spuriously reported as ready. Thus it may be safer to
   use O_NONBLOCK on sockets that should not block.”
So it might well be that this (kernel?) bug is the cause for the spurious ready we see here. Nevertheless it would be great if this problem could be worked around somehow, to avoid error messages due to a known kernel bug.

bjnp_backendRunLoop knows about a side-channel command called CUPS_SC_CMD_NONE. When it receives such a command, it will simply discard it. So one possible solution to this problem might be adjusting cups code itself to return that command instead of a CUPS_SC_STATUS_BAD_MESSAGE error if zero bytes were read. Another alternative would be introducing a new status value CUPS_SC_STATUS_ZERO_READ or similar to indicate such a situation. However, both of these changes modify current ABI and API (CUPS_SC_CMD_NONE is an undocumented [1] enum constant internal to cups), so the clean way to deal with this would be introducing a new function name, and have the old name as a wrapper for the new one, changing this new behaviour back into CUPS_SC_STATUS_BAD_MESSAGE for compatibility. Quite a big overhead for such a small issue, but I can think of no better alternative just now. Perhaps if someone knew about a reliable way to avoid these spurious readiness things in the first place…

The sad thing is: after understanding this warning, it appears to be completely irrelevant for my actual problem of getting my printer to work. A failed side-channel read will cause bjnp to print a warning, but apart from that the actual behaviour is exactly the same as if no side-channel read had been performed at all. Even if I get rid of that warning, my printer still won't work. I fear I might have to compile the Canon proprietary drivers. :-(

[1] http://www.cups.org/documentation.php/api-filter.html
Comment 1 Martin von Gagern 2012-08-09 06:29:58 UTC
Arg! Seems I had been too tired while I diagnosed this issue. A read returning 0 is an indication of a closed socket. A spurious readiness due to the described bug would have resulted in a return value of -1 combined with a suitable errno of EWOULDBLOCK or EAGAIN. So the question is, why does cupsd close the side-channel socket while its child is still alive?
Comment 2 Andreas K. Hüttel gentoo-dev 2013-05-13 20:07:58 UTC
From the cups-bjnp sourceforge page:

The version 1.1 adds support for printing over Ipv6 and fixes some bugs (the "failed to read side channel" error message).
Version 1.2 only fixes a compilation error. No other fixes

Since we only have 1.1 in tree now and this bug was reported against 1.0, I consider this fixed.