Race condition in CUPS USB backend with bi-dir communication

[darkvision77]

I have a printer that uses the bi-dir protocol. For it, I made a minimal filter that sends a command (4 bytes) to the printer, calls CUPS_SC_CMD_DRAIN_OUTPUT, and reads the response (22 bytes):

void drainOutput() {
    std::println(stderr, "DEBUG: drainOutput()");
    char buff[1024];
    int len = sizeof(buff);

    cups_sc_status_t status = cupsSideChannelDoRequest(
        CUPS_SC_CMD_DRAIN_OUTPUT, buff, &len, 5000
    );
    if (status != CUPS_SC_STATUS_OK) {
        throw std::runtime_error(std::format("cupsSideChannelDoRequest failed ({})", scStatusStr(status)));
    }
    assert(len == 0);
}

void writePrinter(std::span<const char> data) {
    std::println(stderr, "DEBUG: writePrinter({}, {})", data.size(), data);
    std::cout.write(data.data(), data.size());
    std::cout.flush();
    drainOutput();
    std::println(stderr, "DEBUG: Write {} bytes", data.size());
}

void readPrinter(std::span<char> dest) {
    std::println(stderr, "DEBUG: readPrinter({})", dest.size());
    std::size_t total = 0;
    while (total < dest.size()) {
        ssize_t read = cupsBackChannelRead(dest.data() + total, dest.size() - total, 5000);
        if (read == -1) {
            throw std::runtime_error("cupsBackChannelRead failed");
        }
        total += read;
        std::println(stderr, "DEBUG: Read {} bytes (total={})", read, total);
    }
}

The filter works fine for a while, but then an error occurs:

/* cups log */
// OK
[filter] Iter 20/10000
[filter] writePrinter(4, [160, 160, 4, 0])
[usb   ] Read 4 bytes of print data...
[usb   ] CUPS_SC_CMD_DRAIN_OUTPUT received from driver...
[usb   ] Wrote 4 bytes of print data...
[filter] Write 4 bytes
[filter] readPrinter(22)
[usb   ] Read 6 bytes of back-channel data...
[usb   ] Read 16 bytes of back-channel data...
[filter] Read 22 bytes (total=22)

// Fail:
[filter] Iter 21/10000
[filter] writePrinter(4, [160, 160, 4, 0])
[usb   ] Read 4 bytes of print data...
[usb   ] Wrote 4 bytes of print data...
// ^^^ usb backend decided to send the data to the printer without waiting for the sidechannel command.
[usb   ] CUPS_SC_CMD_DRAIN_OUTPUT received from driver...
[usb   ] Read 6 bytes of back-channel data...
[usb   ] Read 16 bytes of back-channel data...
[filter] Filter error: cupsSideChannelDoRequest failed (CUPS_SC_STATUS_TIMEOUT)

Here is a timeline:

1. The usb backend read the filter data and sent it to the printer before CUPS_SC_CMD_DRAIN_OUTPUT. Thus, print_fd, from which the usb backend reads the filter output, is empty.
2. The reading stream enters a new iteration of reading and selects an infinite timeout, since the sidechannel command has not yet been processed and g.drain_output is 0.
3. The reading stream enters an infinite wait for new data from the filter.
4. And at this point, CUPS_SC_CMD_DRAIN_OUTPUT is processed (this is where the race condition lies).
5. The filter waits for a response to its sidechannel command, whereas the response to it occurs in the reading stream, which is waiting for data from the filter.
6. This results in a deadlock, but cupsSideChannelDoRequest in the filter times out and execution continues with an error.

An error is obviously not normal. Filter developers have to ignore it in order for execution to continue normally:
https://github.com/mounaiban/captdriver/blob/62719249ac34633338be54bc74beddd0e7003d38/src/capt-command.c#L72-L83

Therefore, the time required for the write is unpredictable: from zero to the timeout value.
In particular, with Canon CAPT printers, this can lead to the entire job being ruined, because raster data is being streamed to printer and this operation is time critical.

To fix this, I found the following solution:
When the backend receives CUPS_SC_CMD_DRAIN_OUTPUT, it sets the g.drain_output flag to 1.
All I did was move the response to the command to sidechannel_thread (where g.drain_output is set to 1), so as not to depend on the reading thread.

[michaelrsweet]

Will look at potential compatibility issues.

That said, even with this change you can't depend on the ordering. The read thread continuously reads - there is no way to externally trigger a read, and they are not synchronized with writes. This change allows the driver to wait for the output to be written but doesn't delay any read data which is sent over a non-blocking pipe.

[ValdikSS]

That's fine in this case, this model series does not send any data on its own, only as a reply to the request.

[SagarJadhav30]

The issue is caused by a race condition between the CUPS USB backend’s read thread and side-channel handling. CUPS_SC_CMD_DRAIN_OUTPUT was acknowledged from the read thread, which can block indefinitely when no print data is pending, causing a deadlock and timeout in the filter. The correct fix is to send the side-channel response directly from the side-channel thread when g.drain_output is set, fully decoupling control-plane signaling from data I/O. This eliminates nondeterministic write latency and prevents time-critical raster corruption, while respecting CUPS’ asynchronous I/O model.