Ubuntu
cups package

ppd updating unexpectedly after printing job finished

Bug #1838229 reported by Zhu Yijun
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
cups (Ubuntu)
New
Undecided
Unassigned

Bug Description

Ubuntu 16.04LTS
OS Version： 16.04.5
CUPS Version： 2.1.3
Ghostscript Version： 9.18

<Bug Description>
ppd updating unexpectedly after printing job finished

<Detail>
We(RICOH printer driver developer) got a bug report from the users of our printer:
We changed the UI setting(DefaultRICyan, DefaultRIMagenta, DefaultRIYellow, DefaultRIBlack) of the RICOH driver.
And confirmed the PPD setting(DefaultRICyan, DefaultRIMagenta, DefaultRIYellow, DefaultRIBlack) in etc/cups/ppds/XXXX.ppd was changed correctly before printing.
When the printing job completed, We expected the PPD file is same with the one before printing.
But after printing job completed, a part of setting in etc/cups/ppds/XXXX.ppd(DefaultRICyan, DefaultRIMagenta, DefaultRIYellow, DefaultRIBlack) was changed unexpectedly.
It seems be changed to the value in /usr/share/ppd/ricoh/XXXX.ppd.

According to the "CUPS Error Log" and the open source of CUPS, it seems that CUPS Updated the PPD Setting after the printing job.
We doubt that CUPS didn't find a part of the keyword we changed in the PPD file.

Error Log
======================================================
D [19/Jul/2019:19:05:52 +0800] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [19/Jul/2019:19:05:52 +0800] [Job 2] PID 2714 (/usr/lib/cups/filter/gstoraster) exited with no errors.
D [19/Jul/2019:19:05:52 +0800] [Job 2] CUPS_SC_CMD_SNMP_GET_NEXT: 25 (.1.3.6.1.2.1.43.8.2.1.13)
D [19/Jul/2019:19:05:52 +0800] [Job 2] Returning .1.3.6.1.2.1.43.8.2.1.13.1.1
D [19/Jul/2019:19:05:52 +0800] [Job 2] CUPS_SC_CMD_SNMP_GET_NEXT: 29 (.1.3.6.1.2.1.43.8.2.1.13.1.1)
D [19/Jul/2019:19:05:52 +0800] [Job 2] Returning .1.3.6.1.2.1.43.8.2.1.14.1.1 1
D [19/Jul/2019:19:05:52 +0800] [Job 2] CUPS_SC_CMD_SNMP_GET_NEXT: 25 (.1.3.6.1.2.1.43.8.2.1.13)
D [19/Jul/2019:19:05:52 +0800] [Job 2] Returning .1.3.6.1.2.1.43.8.2.1.13.1.1
D [19/Jul/2019:19:05:52 +0800] [Job 2] CUPS_SC_CMD_SNMP_GET_NEXT: 29 (.1.3.6.1.2.1.43.8.2.1.13.1.1)
D [19/Jul/2019:19:05:52 +0800] [Job 2] Returning .1.3.6.1.2.1.43.8.2.1.14.1.1 1
D [19/Jul/2019:19:05:52 +0800] [Job 2] CUPS_SC_CMD_SNMP_GET_NEXT: 34 (.1.3.6.1.4.1.367.3.2.1.2.11.3.1.2)
D [19/Jul/2019:19:05:52 +0800] [Job 2] Returning .1.3.6.1.4.1.367.3.2.1.2.11.3.1.2.1
D [19/Jul/2019:19:05:52 +0800] [Job 2] CUPS_SC_CMD_SNMP_GET_NEXT: 36 (.1.3.6.1.4.1.367.3.2.1.2.11.3.1.2.1)
D [19/Jul/2019:19:05:52 +0800] [Job 2] Returning .1.3.6.1.4.1.367.3.2.1.2.11.3.1.2.2
D [19/Jul/2019:19:05:52 +0800] [Job 2] CUPS_SC_CMD_SNMP_GET_NEXT: 36 (.1.3.6.1.4.1.367.3.2.1.2.11.3.1.2.2)
D [19/Jul/2019:19:05:52 +0800] [Job 2] Returning .1.3.6.1.4.1.367.3.2.1.2.13.3.0
D [19/Jul/2019:19:05:52 +0800] [Job 2] CUPS_SC_CMD_SNMP_GET: 38 (.1.3.6.1.4.1.367.3.2.1.2.18.2.1.7.1.1)
D [19/Jul/2019:19:05:52 +0800] [Job 2] Returning .1.3.6.1.4.1.367.3.2.1.2.18.2.1.7.1.1 6
D [19/Jul/2019:19:05:52 +0800] [Job 2] PPD: DefaultRIBlack=5 ※ppd loading unexpectedly
D [19/Jul/2019:19:05:52 +0800] [Job 2] CUPS_SC_CMD_SNMP_GET: 38 (.1.3.6.1.4.1.367.3.2.1.2.18.2.1.7.1.2)
D [19/Jul/2019:19:05:52 +0800] [Job 2] Returning .1.3.6.1.4.1.367.3.2.1.2.18.2.1.7.1.2 6
D [19/Jul/2019:19:05:52 +0800] [Job 2] PPD: DefaultRICyan=5 ※ppd loading unexpectedly
D [19/Jul/2019:19:05:52 +0800] [Job 2] CUPS_SC_CMD_SNMP_GET: 38 (.1.3.6.1.4.1.367.3.2.1.2.18.2.1.7.1.3)
D [19/Jul/2019:19:05:52 +0800] [Job 2] Returning .1.3.6.1.4.1.367.3.2.1.2.18.2.1.7.1.3 6
D [19/Jul/2019:19:05:52 +0800] [Job 2] PPD: DefaultRIMagenta=5 ※ppd loading unexpectedly
D [19/Jul/2019:19:05:52 +0800] [Job 2] CUPS_SC_CMD_SNMP_GET: 38 (.1.3.6.1.4.1.367.3.2.1.2.18.2.1.7.1.4)
D [19/Jul/2019:19:05:52 +0800] [Job 2] Returning .1.3.6.1.4.1.367.3.2.1.2.18.2.1.7.1.4 6
D [19/Jul/2019:19:05:52 +0800] [Job 2] PPD: DefaultRIYellow=5 ※ppd loading unexpectedly
D [19/Jul/2019:19:05:52 +0800] [Job 2] Waiting for status monitor to stop
D [19/Jul/2019:19:05:53 +0800] [Job 2] Status monitor stopped
D [19/Jul/2019:19:05:53 +0800] [Job 2] Job finished
...
I [19/Jul/2019:19:05:53 +0800] Expiring subscriptions...
D [19/Jul/2019:19:05:53 +0800] cupsdMarkDirty(---J-)
D [19/Jul/2019:19:05:53 +0800] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [19/Jul/2019:19:05:53 +0800] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [19/Jul/2019:19:05:53 +0800] cupsdMarkDirty(----S)
D [19/Jul/2019:19:05:53 +0800] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [19/Jul/2019:19:05:53 +0800] cupsdMarkDirty(---J-)
D [19/Jul/2019:19:05:53 +0800] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [19/Jul/2019:19:05:53 +0800] cupsdMarkDirty(---J-)
D [19/Jul/2019:19:05:53 +0800] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
I [19/Jul/2019:19:05:53 +0800] Updating keywords in PPD file for SG7200shiji...
D [19/Jul/2019:19:05:53 +0800] *DefaultRIBlack: 5 ※ppd updated unexpectedly
D [19/Jul/2019:19:05:53 +0800] *DefaultRICyan: 5 ※ppd updated unexpectedly
D [19/Jul/2019:19:05:53 +0800] *DefaultRIMagenta: 5 ※ppd updated unexpectedly
D [19/Jul/2019:19:05:53 +0800] *DefaultRIYellow: 5 ※ppd updated unexpectedly
D [19/Jul/2019:19:05:53 +0800] cupsdMarkDirty(P----)
D [19/Jul/2019:19:05:53 +0800] cupsdSetBusyState: newbusy="Dirty files", busy="Printing jobs and dirty files"
D [19/Jul/2019:19:05:53 +0800] load_ppd: Loading /etc/cups/ppd/SG7200shiji.ppd...
D [19/Jul/2019:19:05:53 +0800] load_ppd: Saving /var/cache/cups/SG7200shiji.data...
D [19/Jul/2019:19:05:53 +0800] cupsdRegisterPrinter(p=0x5633a59fcda0(SG7200shiji))
D [19/Jul/2019:19:05:53 +0800] [Job 2] Removing document files.
...
======================================================

CUPS Open Source
<download URL> https://github.com/apple/cups/releases/tag/v2.2.11
commandtops.c
======================================================
...
static int /* O - Exit status */
auto_configure(ppd_file_t *ppd, /* I - PPD file */
               const char *user) /* I - Printing user */
{
   ...
   /*
    * Read the response data...
    */

    bufptr = buffer;
    buffer[0] = '\0';
    while ((bytes = cupsBackChannelRead(bufptr, sizeof(buffer) - (size_t)(bufptr - buffer) - 1, 10.0)) > 0)
    {
     /*
      * No newline at the end? Go on reading ...
      */

      bufptr += bytes;
      *bufptr = '\0';

      if (bytes == 0 ||
          (bufptr > buffer && bufptr[-1] != '\r' && bufptr[-1] != '\n'))
 continue;

     /*
      * Trim whitespace and control characters from both ends...
      */

      bytes = bufptr - buffer;

      for (bufptr --; bufptr >= buffer; bufptr --)
        if (isspace(*bufptr & 255) || iscntrl(*bufptr & 255))
   *bufptr = '\0';
 else
   break;

      for (bufptr = buffer; isspace(*bufptr & 255) || iscntrl(*bufptr & 255);
    bufptr ++);

      if (bufptr > buffer)
      {
        _cups_strcpy(buffer, bufptr);
 bufptr = buffer;
      }

      fprintf(stderr, "DEBUG: Got %d bytes.\n", (int)bytes);

     /*
      * Skip blank lines...
      */

      if (!buffer[0])
        continue;

     /*
      * Check the response...
      */

      if ((bufptr = strchr(buffer, ':')) != NULL)
      {
       /*
        * PostScript code for this option in the PPD is broken; show the
        * interpreter's error message that came back...
        */

 fprintf(stderr, "DEBUG%s\n", bufptr);
 break;
      }

     /*
      * Verify the result is a valid option choice...
      */

      if (!ppdFindChoice(option, buffer))
      {
 if (!strcasecmp(buffer, "Unknown"))
   break;

 bufptr = buffer;
 buffer[0] = '\0';
        continue;
      }

     /*
      * Write out the result and move on to the next option...
      */

      fprintf(stderr, "PPD: Default%s=%s\n", option->keyword, buffer);
      break;
    }

   /*
    * Printer did not answer this option's query
    */
   ...
}

...
PPD File
<Before Printing>
======================================================
----->>>
*PPD-Adobe: "4.3"
...
*OpenGroup: AdjustColorDensity/Adjust Color Density
*OpenUI *RICyan/C: PickOne
*OrderDependency: 130 AnySetup *RICyan
*DefaultRICyan: 1 ※ppd loading target keyword(expected result)
*RICyan 1/1: "%% RICyan=1"
*RICyan 2/2: "%% RICyan=2"
*RICyan 3/3: "%% RICyan=3"
*RICyan 4/4: "%% RICyan=4"
*RICyan 5/5: "%% RICyan=5"
*RICyan 6/6: "%% RICyan=6"
*RICyan 7/7: "%% RICyan=7"
*RICyan 8/8: "%% RICyan=8"
*RICyan 9/9: "%% RICyan=9"
*CloseUI: *RICyan
*OpenUI *RIMagenta/M: PickOne
*OrderDependency: 130 AnySetup *RIMagenta
*DefaultRIMagenta: 1 ※ppd loading target keyword(expected result)
*RIMagenta 1/1: "%% RIMagenta=1"
*RIMagenta 2/2: "%% RIMagenta=2"
*RIMagenta 3/3: "%% RIMagenta=3"
*RIMagenta 4/4: "%% RIMagenta=4"
*RIMagenta 5/5: "%% RIMagenta=5"
*RIMagenta 6/6: "%% RIMagenta=6"
*RIMagenta 7/7: "%% RIMagenta=7"
*RIMagenta 8/8: "%% RIMagenta=8"
*RIMagenta 9/9: "%% RIMagenta=9"
*CloseUI: *RIMagenta
*OpenUI *RIYellow/Y: PickOne
*OrderDependency: 130 AnySetup *RIYellow
*DefaultRIYellow: 1 ※ppd loading target keyword(expected result)
*RIYellow 1/1: "%% RIYellow=1"
*RIYellow 2/2: "%% RIYellow=2"
*RIYellow 3/3: "%% RIYellow=3"
*RIYellow 4/4: "%% RIYellow=4"
*RIYellow 5/5: "%% RIYellow=5"
*RIYellow 6/6: "%% RIYellow=6"
*RIYellow 7/7: "%% RIYellow=7"
*RIYellow 8/8: "%% RIYellow=8"
*RIYellow 9/9: "%% RIYellow=9"
*CloseUI: *RIYellow
*OpenUI *RIBlack/K: PickOne
*OrderDependency: 130 AnySetup *RIBlack
*DefaultRIBlack: 1 ※ppd loading target keyword(expected result)
*RIBlack 1/1: "%% RIBlack=1"
*RIBlack 2/2: "%% RIBlack=2"
*RIBlack 3/3: "%% RIBlack=3"
*RIBlack 4/4: "%% RIBlack=4"
*RIBlack 5/5: "%% RIBlack=5"
*RIBlack 6/6: "%% RIBlack=6"
*RIBlack 7/7: "%% RIBlack=7"
*RIBlack 8/8: "%% RIBlack=8"
*RIBlack 9/9: "%% RIBlack=9"
*CloseUI: *RIBlack
*CloseGroup: AdjustColorDensity
...
======================================================

<After Printing>
======================================================
----->>>
*PPD-Adobe: "4.3"
...
*DefaultRICyan: 5 ※ppd updated unexpectedly
*DefaultRIMagenta: 5 ※ppd updated unexpectedly
*DefaultRIYellow: 5 ※ppd updated unexpectedly
*DefaultRIBlack: 5 ※ppd updated unexpectedly
*OpenGroup: AdjustColorDensity/Adjust Color Density
*OpenUI *RICyan/C: PickOne
*OrderDependency: 130 AnySetup *RICyan
*RICyan 1/1: "%% RICyan=1"
*RICyan 2/2: "%% RICyan=2"
*RICyan 3/3: "%% RICyan=3"
*RICyan 4/4: "%% RICyan=4"
*RICyan 5/5: "%% RICyan=5"
*RICyan 6/6: "%% RICyan=6"
*RICyan 7/7: "%% RICyan=7"
*RICyan 8/8: "%% RICyan=8"
*RICyan 9/9: "%% RICyan=9"
*CloseUI: *RICyan
*OpenUI *RIMagenta/M: PickOne
*OrderDependency: 130 AnySetup *RIMagenta
*RIMagenta 1/1: "%% RIMagenta=1"
*RIMagenta 2/2: "%% RIMagenta=2"
*RIMagenta 3/3: "%% RIMagenta=3"
*RIMagenta 4/4: "%% RIMagenta=4"
*RIMagenta 5/5: "%% RIMagenta=5"
*RIMagenta 6/6: "%% RIMagenta=6"
*RIMagenta 7/7: "%% RIMagenta=7"
*RIMagenta 8/8: "%% RIMagenta=8"
*RIMagenta 9/9: "%% RIMagenta=9"
*CloseUI: *RIMagenta
*OpenUI *RIYellow/Y: PickOne
*OrderDependency: 130 AnySetup *RIYellow
*RIYellow 1/1: "%% RIYellow=1"
*RIYellow 2/2: "%% RIYellow=2"
*RIYellow 3/3: "%% RIYellow=3"
*RIYellow 4/4: "%% RIYellow=4"
*RIYellow 5/5: "%% RIYellow=5"
*RIYellow 6/6: "%% RIYellow=6"
*RIYellow 7/7: "%% RIYellow=7"
*RIYellow 8/8: "%% RIYellow=8"
*RIYellow 9/9: "%% RIYellow=9"
*CloseUI: *RIYellow
*OpenUI *RIBlack/K: PickOne
*OrderDependency: 130 AnySetup *RIBlack
*RIBlack 1/1: "%% RIBlack=1"
*RIBlack 2/2: "%% RIBlack=2"
*RIBlack 3/3: "%% RIBlack=3"
*RIBlack 4/4: "%% RIBlack=4"
*RIBlack 5/5: "%% RIBlack=5"
*RIBlack 6/6: "%% RIBlack=6"
*RIBlack 7/7: "%% RIBlack=7"
*RIBlack 8/8: "%% RIBlack=8"
*RIBlack 9/9: "%% RIBlack=9"
*CloseUI: *RIBlack
*CloseGroup: AdjustColorDensity
...
======================================================

Our questiong is:
1. Why CUPS loaded unexceptedly PPD file but not the etc/cups/ppds/XXXX.ppd?
And after printing job, even the kewords((DefaultRICyan, DefaultRIMagenta, DefaultRIYellow, DefaultRIBlack)) location in the PPD file were also changed.
2. If this is the problem of CUPS, do CUPS have any plan to solve it?
3. Do you have any workaround before the problem be fixed?

Revision history for this message
Zhu Yijun (annchu) wrote :

This problem makes the settings of the driver UI saving failed and inconvenient to users. Please tell us the reasons for this problem in order to solve the problem.

And our PPD file contains repetitive KeyWords as below, we wonder if it is the reason of the problem. Please confirm and We are looking forward for your reply.

PPD Files Detail(repetitive KeyWords of "RIBlack","RICyan", "RIMagenta", "RIYellow")
-------------------------------------------------------------------
*PJLINQ RIBlack: "GAMMAK"
*PJLINQ RICyan: "GAMMAC"
*PJLINQ RIMagenta: "GAMMAM"
*PJLINQ RIYellow: "GAMMAY"
*SNMPOID RIBlack: ".1.3.6.1.4.1.367.3.2.1.2.18.2.1.7.1.1"
*SNMPOID RICyan: ".1.3.6.1.4.1.367.3.2.1.2.18.2.1.7.1.2"
*SNMPOID RIMagenta: ".1.3.6.1.4.1.367.3.2.1.2.18.2.1.7.1.3"
*SNMPOID RIYellow: ".1.3.6.1.4.1.367.3.2.1.2.18.2.1.7.1.4"
...
 *OpenGroup: AdjustColorDensity/Adjust Color Density
 *OpenUI *RICyan/C: PickOne
 *OrderDependency: 130 AnySetup *RICyan
 *DefaultRICyan: 1 ※ppd loading target keyword(expected result)
 *RICyan 1/1: "%% RICyan=1"
 *RICyan 2/2: "%% RICyan=2"
 *RICyan 3/3: "%% RICyan=3"
 *RICyan 4/4: "%% RICyan=4"
 *RICyan 5/5: "%% RICyan=5"
 *RICyan 6/6: "%% RICyan=6"
 *RICyan 7/7: "%% RICyan=7"
 *RICyan 8/8: "%% RICyan=8"
 *RICyan 9/9: "%% RICyan=9"
 *CloseUI: *RICyan
 *OpenUI *RIMagenta/M: PickOne
 *OrderDependency: 130 AnySetup *RIMagenta
 *DefaultRIMagenta: 1 ※ppd loading target keyword(expected result)
 *RIMagenta 1/1: "%% RIMagenta=1"
 *RIMagenta 2/2: "%% RIMagenta=2"
 *RIMagenta 3/3: "%% RIMagenta=3"
 *RIMagenta 4/4: "%% RIMagenta=4"
 *RIMagenta 5/5: "%% RIMagenta=5"
 *RIMagenta 6/6: "%% RIMagenta=6"
 *RIMagenta 7/7: "%% RIMagenta=7"
 *RIMagenta 8/8: "%% RIMagenta=8"
 *RIMagenta 9/9: "%% RIMagenta=9"
 *CloseUI: *RIMagenta
 *OpenUI *RIYellow/Y: PickOne
 *OrderDependency: 130 AnySetup *RIYellow
 *DefaultRIYellow: 1 ※ppd loading target keyword(expected result)
 *RIYellow 1/1: "%% RIYellow=1"
 *RIYellow 2/2: "%% RIYellow=2"
 *RIYellow 3/3: "%% RIYellow=3"
 *RIYellow 4/4: "%% RIYellow=4"
 *RIYellow 5/5: "%% RIYellow=5"
 *RIYellow 6/6: "%% RIYellow=6"
 *RIYellow 7/7: "%% RIYellow=7"
 *RIYellow 8/8: "%% RIYellow=8"
 *RIYellow 9/9: "%% RIYellow=9"
 *CloseUI: *RIYellow
 *OpenUI *RIBlack/K: PickOne
 *OrderDependency: 130 AnySetup *RIBlack
 *DefaultRIBlack: 1 ※ppd loading target keyword(expected result)
 *RIBlack 1/1: "%% RIBlack=1"
 *RIBlack 2/2: "%% RIBlack=2"
 *RIBlack 3/3: "%% RIBlack=3"
 *RIBlack 4/4: "%% RIBlack=4"
 *RIBlack 5/5: "%% RIBlack=5"
 *RIBlack 6/6: "%% RIBlack=6"
 *RIBlack 7/7: "%% RIBlack=7"
 *RIBlack 8/8: "%% RIBlack=8"
 *RIBlack 9/9: "%% RIBlack=9"
 *CloseUI: *RIBlack
 *CloseGroup: AdjustColorDensity
 ...

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.