Possible race condition with creation of temporary queues for IPP printers.

[NJRoadfan]

System is running CUPS 2.3.3op2 on Raspberry Pi 400 with Debian "bullseye". The printer in question was created with the ippeveprinter program for testing purposes. The cups-browsed service is disabled. I am coding a program to query a printer's state in C. CUPS, ippeveprinter, and my application are all running on the same machine.

Occasionally if I attempt to connect to an IPP Everywhere printer and do an IPP_OP_GET_PRINTER_ATTRIBUTES request, CUPS returns a client-error-not-found in cases when it has to generate a temporary queue to service the request. Code flow is as follows:

cupsGetNamedDest()->cupsConnectDest()->ippNewRequest(IPP_OP_GET_PRINTER_ATTRIBUTES)->cupsDoRequest()

I am requesting the following attributes if it matters:
"printer-state"
"printer-state-message"
"printer-is-accepting-jobs"

Unfortunately, the request randomly fails and I can't find pin down a reason why. I suspect there is a short window of time between when the cupsConnectDest() call is made and the temporary queue is ready. Sometimes it doesn't complete by the time the cupsDoRequest() call is made and CUPS throws an error. I never encounter the failure with legacy permanent CUPS queues (including those created by cups-browsed) or if a temporary queue was already created by a previous cupsConnectDest() call and hasn't been removed by CUPS yet.

I plan on coding a workaround in the meantime (check if error is specifically client-error-not-found and proceeding or inserting a pause in code execution). With CUPS eventually going to an all temporary queue setup in the future, this problem may crop up more frequently with applications expecting an immediate response to their cupsDoRequest() calls.

Note: May be related to #347

[zdohnal]

Hi,

thank you for reporting the issue!

To be honest I would not combine CUPS API and IPP API when writing a new application unless it is necessary - printer-state and printer-is-accepting-jobs is in destination options, and there is similar option to printer-state-message - printer-state-reasons, so you don't need to do IPP request for them.
Or, if you especially want to use IPP API, then connect to the device itself via cupsConnectDest() instead of its representation in CUPS, by using flag CUPS_DEST_FLAGS_DEVICE.

To be clear about the future - local CUPS will support temporary queues and printer profiles, sharing CUPS will have permanent IPP queues (since they has to be shared and always accessible). I would suspect cupsConnectDest() would work reliably with permanent IPP queues. The current delay from #347 is because of PPD generator, which won't be in the future CUPS projects, so the window for this race condition won't be this big to happen it more frequently than now. And one important thing, #347 appeared with 2.4.x (unless Debian backported the change...)

However, your situation looks a bit different - the printer object is usually created quickly (#347 is about updating the printer with correct capabilities, because PPD is created from IPP there), so if the IPP response can't find it, it looks like cupsd is busy and didn't finish at least basic printer creation.

So I would recommend:

A. Try to use CUPS dest API only if it works for you

or

B. use the latest version 2.4.7 and see if it behaves the same - 2.3.3op2 is version from 2021, so there can be differences.

In case you will try the latest version, enable CUPS debug logging by cupsctl LogLevel=debug2, reproduce the issue and attach the debug logs here as a file.

[NJRoadfan]

Working on this now. Might be awhile until I return with the logs and get an install of 2.4.7 going. Looking at past logs there is an awful lot of this:

E [22/Jan/2024:15:59:19 -0500] [Client 362] Returning IPP client-error-not-possible for CUPS-Create-Local-Printer (ipp://localhost/) from localhost.

I switched the code to call cupsGetOption() for the attributes I am requesting and its actually worse. Now instead of occasionally failing when the queue needs to be created, it fails consistently. Note that I am querying the printer state once every 3-5 seconds or so.

[zdohnal]

@NJRoadfan Ok, I'm sorry for confusion - I used https://openprinting.github.io/cups/doc/cupspm.html and it said those options are in the options array by default, but they aren't in case of temporary queues. You would have to do IPP request at the moment :( . And this issue is present in the current code, because the issue happens when cupsConnectDest() sees the destination as local printer (after Create-Local-Printer), but the temporary queue is removed before you do IPP request.

@michaelrsweet is it a bug or is it expected for temp queues to miss those options? IIUC we generate options array for temp queues from DNS-SD txt record, which does not have such information - should we do a IPP Get-Printer-Attributes request to the actual destination (printer) for those attributes?

I always find it prone to errors to combine CUPS dest and IPP API, so shouldn't we get those options via functions like cupsGetNamedDest()?

Ad this bug - probably we can update p->state_time every time there is a request to create such local printer.

[zdohnal]

@michaelrsweet tbh updating state_time won't work if we don't get Create-Local-Printer request, and the request is not generated if destination has printer-uri-supported - the solution would be to do the request every time and then update printer-uri-supported accordingly, wdyt?

[michaelrsweet]

@zdohnal printer-uri-supported is only present for queues that exist/are setup. There is a possibility of a race condition because cupsd doesn't look for another queue using the specified device URI, so the real fix is for CUPS-Create-Local-Printer to prevent the race condition...

[zdohnal]

@michaelrsweet the scenario here is:

cupsConnectDest() ->       IPP Get-Printer-Attributes
                     ^
                     |
                   here cupsd deletes the temp queue

so CUPS-Create-Local-Printer is not sent, because cupsConnectDest() sees the queue as setup/created since it finds printer-uri-supported. So next IPP request fails, because cupsd removes the queue after cupsConnectDest() and temp queue removal depends on its idle time and its state (none of that is updated by cupsConnectDest()...). Would you mind explaining how checking in create_local_printer() would help here?

[NJRoadfan]

Following this. I've reimplemented my status check by doing the following as I don't need the IPP API for what I want to do:

cupsGetNamedDest()->cupsConnectDest()->cupsGetOption()

This will fail if a temporary queue isn't present in CUPS and needs to be created (because results from a cupsGetOption() call will be NULL). For error checking, I have the following in place:

const char *printerreason = cupsGetOption("printer-state-reasons", dest->num_options, dest->options);
if (!printerreason)
	{
		httpClose(http);
		cupsFreeDests(1, dest);

		if (cupsLastError() == IPP_STATUS_OK)
		{
			//Proceed, this is a temporary queue that is building and not yet ready. Get info on next call.
			return(1);
		}
		else
		{
			//Return failed, something is really wrong if we get here.
			return (0);
		}
	}

So far this has worked around the issue. I'm sticking with this method vs. the old IPP API method since it is consistent behavior that can be coded for.

Note: The reason for so much mixing of CUPS Destination API and IPP API is that I am updating a project that originally targeted very old versions of CUPS (pre-1.6). I have been attempting to update it to use current APIs and deal with the extensive changes coming in libcups3. The old code would actually see DNS-SD discovered printers, but couldn't print to them before updates.

[NJRoadfan]

Looking back, I just realized the above example is taking advantage of the fact that calling cupsConnectDest() forces creation of a temporary queue to get status information via the scheduler vs. connecting to the printer directly.

[NJRoadfan]

I have since rewritten my code to directly connect to a DNS-SD discovered printer now that I found the correct conditional statement to reliably detect them.

The "race condition" I was initially encountering wasn't because the temporary queue was removed before my call to cupsdoRequest(). It appeared to be the opposite, that is the temporary queue hadn't finished building yet (maybe _cupsCreateDest()isn't blocking?) , so CUPS throws an error.

Also, it appears that DNS-SD discovered printers without a temporary queue present do not return valid values for printer-state, printer-is-accepting-jobs, and printer-state-reasons if you attempt to retrieve those values with cupsGetOption() after a cupsGetDest2() or cupsGetNamedDest() call.

[michaelrsweet]

OK, I've pushed changes that will prevent the race condition for creating the printer:

[master 9383b37] Update CUPS-Create-Local-Printer to preserve the existing printer based on the device URI (Issue #871)

The query (Get-Printer-Attributes) can still block momentarily if the background thread is in the middle of updating the attributes, but that should take milliseconds. If not, please run cupsd in a debugger and do a backtrace ("t a a bt" will show the backtrace for all threads).

[michaelrsweet]

I'm going to close this as fixed; if you still have issues please comment here and we can re-open as needed.