CUPS put incorrect Reason to printers.conf

[ValdikSS]

Describe the bug

I'm not really sure how did this happen, but I ended up with broken printer due to incorrect IPP job-printer-state-reasons keyword, caused by the following data in printers.conf:

Reason DEBUG:
Reason Ghostscript
Reason using
Reason Any-Part-of-Pixel
Reason method
Reason to
Reason fill
Reason paths.

Prior to this, I did the following to replace the PPD file and clear its data:

systemctl stop cups; rm /var/cache/cups/*; cp /tmp/ppd.ppd /etc/cups/ppd/Canon_LASER_SHOT_LBP-1120.ppd; systemctl start cups

However I did not clean the jobs from /var/spool/cups/, and the c00009 job file also contains this text.

System Information:

• OS and its version: Debian 12
• CUPS version: 2.4.2-3+deb12u9 with additional patches

Canon_LASER_SHOT_LBP-1120.ipptool.txt
printers.conf.txt
c00009.zip

[ValdikSS]

Happened again:

# Printer configuration file for CUPS v2.4.2
# Written by cupsd
# DO NOT EDIT THIS FILE WHEN CUPSD IS RUNNING
NextPrinterId 25
<Printer Canon_LASER_SHOT_LBP-1120>
PrinterId 23
UUID urn:uuid:434e980d-d5f3-3649-458c-4165cc5f0899
Info Canon LASER SHOT LBP-1120
Location 
MakeModel Canon LBP1120, captppd 
DeviceURI captusb://Canon/LASER%20SHOT%20LBP-1120?drv=capt&serial=0441BFZ2
State Stopped
StateMessage Backend /usr/lib/cups/backend/captusb does not exist!
StateTime 1766883821
ConfigTime 1766863877
Reason DEBUG:
Reason Color
Reason Manager:
Reason Calibration
Reason Mode/Off
Type 8392708
Accepting Yes
Shared Yes
JobSheets none none
QuotaPeriod 0
PageLimit 0
KLimit 0
OpPolicy default
ErrorPolicy retry-job
</Printer>

[michaelrsweet]

More than likely the output of two filters is getting mixed in the responses, more than likely a STATE: message is missing a newline, leading to the DEBUG: message from the Ghostscript-based filter being interpreted as state keywords.

There isn't anything we can do to "fix" this, and it shouldn't prevent the queue from working (you just have some odd state keywords...)

[ValdikSS]

and it shouldn't prevent the queue from working (you just have some odd state keywords...)

Well, it is. I can't use this printer over IPP in this state, Gnome's Evince stalls at 'getting printer information' for example.

[ValdikSS]

I'll make a patch to filter out any Reason first word of which ends with a colon.

[tillkamppeter]

I have checked whether cups-filters in version 1.x and 2.x (and also libcupsfilters) produce broken "STATE:" messages, but the filters do not produce "STATE:" at all and the parallel and serial backends (which are not use here) only produce correct "STATE:" messages with newlines at their ends.

But seeing your printers.conf I see that you use a driver for Canon laser printers, using a captusb backend (and probably also a some driver filter, I did not check, see cupsFilter(2): lines in the PPD). The broken "STATE:" lines most probably come from there (@michaelrsweet has probably already checked that they do not come from CUPS).

@ValdikSS please check, probably this is a bug in the Canon driver.

Filtering away all "Reason" lines starting from the first one which ends with a colon would be a workaround.

[ValdikSS]

please check, probably this is a bug in the Canon driver.

This is an open-source driver https://github.com/darkvision77/captppd/

It sets STATE: with the following code:

void StateReporter::SetReason(std::string_view reason, bool set) {
    bool contains = std::ranges::find(this->reasons.cbegin(), this->reasons.cend(), reason) != this->reasons.cend();
    if (set == contains) {
        return;
    }
    this->stream << "STATE: " << (set ? '+' : '-') << reason << std::endl;
    if (set) {
        this->reasons.insert(reason);
    } else {
        this->reasons.erase(reason);
    }
}

(with the end of line)

And it sets only the following known-keyword states:

$ grep -r SetReason
captbackend/Core/StateReporter.cpp:        this->SetReason("other-error", serviceCall);
captbackend/Core/StateReporter.cpp:        this->SetReason("unknown-error", fatal && !serviceCall);
captbackend/Core/StateReporter.cpp:    this->SetReason("other-error", false);
captbackend/Core/StateReporter.cpp:    this->SetReason("unknown-error", false);
captbackend/Core/StateReporter.cpp:    this->SetReason("media-empty-error", (status.Engine & EngineReadyStatus::NO_PRINT_PAPER) != 0);
captbackend/Core/StateReporter.cpp:    this->SetReason("media-needed-error", (status.Engine & EngineReadyStatus::NO_PRINT_PAPER) != 0);
captbackend/Core/StateReporter.cpp:    this->SetReason("media-jam-error", (status.Engine & EngineReadyStatus::JAM) != 0);
captbackend/Core/StateReporter.cpp:    this->SetReason("toner-empty-error", (status.Engine & EngineReadyStatus::NO_CARTRIDGE) != 0);
captbackend/Core/StateReporter.cpp:    this->SetReason("door-open-error", (status.Engine & EngineReadyStatus::DOOR_OPEN) != 0);
captbackend/Core/StateReporter.cpp:    this->SetReason("resuming", waiting);
captbackend/Core/StateReporter.cpp:void StateReporter::SetReason(std::string_view reason, bool set) {
captbackend/Core/StateReporter.hpp:    void SetReason(std::string_view reason, bool set);
captbackend/main.cpp:        reporter.SetReason("connecting-to-device", true);
captbackend/main.cpp:        reporter.SetReason("connecting-to-device", false);

So I've no idea how GhostScript or Color Manager DEBUG: logging could end up there.

[ValdikSS]

I believe the Reason is set here:

cups/scheduler/job.c

Lines 5228 to 5239 in 398fc2c

	else if (loglevel == CUPSD_LOG_STATE)
	{
	cupsdLogJob(job, CUPSD_LOG_DEBUG, "STATE: %s", message);
	if (!strcmp(message, "paused"))
	{
	cupsdStopPrinter(job->printer, 1);
	return;
	}
	else if (message[0] && cupsdSetPrinterReasons(job->printer, message))
	{
	event |= CUPSD_EVENT_PRINTER_STATE;

I also checked cupsdStatBufUpdate and don't see how such a Reason could be set, unless something like STATE: DEBUG: … is supplied.

[tillkamppeter]

Each filter and backend is outputting messages on stderr. CUPS captures them and adds them, with timestamp, to error_log.

What can have happened is that messages got output at the same time, by filter/backend processes running in parallel, and mixed.

So we must find out into which "STATE:" message the Ghostscript message is mixing.

[tillkamppeter]

Seeing the initial posting and the 1st comment after that, the following 2 messages, both from filters, get dropped right after the "STATE:" ouput:

• DEBUG: Ghostscript using Any-Part-of-Pixel method to fill paths.
• DEBUG: Color Manager: Calibration Mode/Off

So CUPS must have read something like

• STATE: DEBUG: Ghostscript using Any-Part-of-Pixel method to fill paths.
• STATE: DEBUG: Color Manager: Calibration Mode/Off

from stderr.

meaning that when the filter started to output a message there was already "STATE: " witjout newline and also without any actual reason on stderr.

[ValdikSS]

Hmm, I assume C++ << overload is not a "single string" safe?

In other words, it's something like this

printf("STATE: ");
printf(set ? '+' : '-');
puts(reason);

instead of something like this

printf("STATE: %s %s\n", set ? '+' : '-', reason);

which makes it suspectible to race condition, when the application wrote only STATE: and then the other filter started to write as well.

Does this sounds sane? Could this be a possible reason?
Or does it flush only after std::endl?

[tillkamppeter]

@ValdikSS unfortunately, I am not a C++ expert. @michaelrsweet ?

@ValdikSS but you can do a test. You could modify the code of the CAPT driver dropping the whole line (including \n) into a string buffer with snprintf() and then stream out the whole thing atomically ...

[ValdikSS]

This is probably the reason for this Reason :D

Fixed in captppd: darkvision77/captppd@3079d23