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
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?
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.
