A "Limit All Cancel-Jobs" policy makes "lpstat -p" unsuccessful with 3 minutes hangup

[jsmeix]

It happens on latest CUPS 2.3b4 and also on CUPS 2.2 down to CUPS 1.7.5.

I seems it is basically still the same as #4659

When I have in /etc/cups/cupsd.conf

<Policy allowallforanybody>
  JobPrivateAccess all
  JobPrivateValues none
  SubscriptionPrivateAccess all
  SubscriptionPrivateValues none
  <Limit All Cancel-Jobs>
    Order deny,allow
    Allow from all
  </Limit>
</Policy>
DefaultPolicy allowallforanybody

I get

# time lpstat -p
lpstat: Success

real    3m0.404s
user    0m0.025s
sys     0m0.025s

Actually lpstat is not successful because it does not show my local queues.

With 'LogLevel debug2' I see in /var/log/cups/error_log
(during that "lpstat -p") three times a one minute timeout (excerpts):

d [17/Apr/2018:15:49:45 +0200] select_timeout: JobHistoryUpdate=0
d [17/Apr/2018:15:49:45 +0200] select_timeout(0): 300 seconds to timeout a client connection
d [17/Apr/2018:15:50:44 +0200] [Client 1] cupsdReadClient: error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=0, request=0x559939dbeb40(IPP_STATE_DATA), file=-1
--
d [17/Apr/2018:15:50:45 +0200] select_timeout: JobHistoryUpdate=0
d [17/Apr/2018:15:50:45 +0200] select_timeout(0): 300 seconds to timeout a client connection
d [17/Apr/2018:15:51:45 +0200] [Client 2] cupsdReadClient: error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=0, request=0x559939dce3b0(IPP_STATE_DATA), file=-1
--
d [17/Apr/2018:15:51:46 +0200] select_timeout: JobHistoryUpdate=0
d [17/Apr/2018:15:51:46 +0200] select_timeout(0): 300 seconds to timeout a client connection
d [17/Apr/2018:15:52:45 +0200] [Client 3] cupsdReadClient: error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=0, request=0x559939dd9950(IPP_STATE_DATA), file=-1

In contrast when "Limit All" is on its own
clients like "lpstat -p" do no longer hang up:

<Policy allowallforanybody>
  JobPrivateAccess all
  JobPrivateValues none
  SubscriptionPrivateAccess all
  SubscriptionPrivateValues none
  <Limit All>
    Order deny,allow
    Allow from all
  </Limit>
  <Limit Cancel-Jobs>
    Order deny,allow
    Allow from all
  </Limit>
</Policy>
DefaultPolicy allowallforanybody

I get

# time lpstat -p
printer postscript is idle.  enabled since ...
printer pstest is idle.  enabled since ...

real    0m0.383s
user    0m0.034s
sys     0m0.026s

I know that the extra "Limit Cancel-Jobs" is no longer needed
according to #4659
so that with a simple

<Policy allowallforanybody>
  JobPrivateAccess all
  JobPrivateValues none
  SubscriptionPrivateAccess all
  SubscriptionPrivateValues none
  <Limit All>
    Order deny,allow
    Allow from all
  </Limit>
</Policy>
DefaultPolicy allowallforanybody

things work.

Nevertheless I like to report this issue because it may indicate
a more general problem in the IPP communication
(i.e. why are there those timeouts/hangups).

With "Limit All Cancel-Jobs" I get in error_log

d [17/Apr/2018:16:16:08 +0200] cupsdAddPolicyOp(p=0x55a78dfd3190, po=0x55a78dfd5d00, op=38(Cancel-Jobs))
d [17/Apr/2018:16:16:08 +0200] cupsdFindPolicyOp(p=0x55a78dfd3190, op=38(Cancel-Jobs))
d [17/Apr/2018:16:16:08 +0200] cupsdAddPolicyOp(p=0x55a78dfd3c40, po=0x55a78dfd9f90, op=38(Cancel-Jobs))
d [17/Apr/2018:16:16:08 +0200] cupsdFindPolicyOp(p=0x55a78dfd3c40, op=38(Cancel-Jobs))
d [17/Apr/2018:16:16:08 +0200] cupsdAddPolicyOp(p=0x55a78dfd8000, po=0x55a78dfde220, op=38(Cancel-Jobs))
d [17/Apr/2018:16:16:08 +0200] cupsdFindPolicyOp(p=0x55a78dfd8000, op=38(Cancel-Jobs))
d [17/Apr/2018:16:16:08 +0200] cupsdAddPolicyOp(p=0x55a78dfdc290, po=(nil), op=38(Cancel-Jobs))
d [17/Apr/2018:16:16:08 +0200] cupsdFindPolicyOp(p=0x55a78dfdc290, op=38(Cancel-Jobs))

With plain "Limit All" I get in error_log

d [17/Apr/2018:16:28:58 +0200] cupsdAddPolicyOp(p=0x557d07b5c190, po=0x557d07b5ed00, op=38(Cancel-Jobs))
d [17/Apr/2018:16:28:58 +0200] cupsdFindPolicyOp(p=0x557d07b5c190, op=38(Cancel-Jobs))
d [17/Apr/2018:16:28:58 +0200] cupsdAddPolicyOp(p=0x557d07b5cc40, po=0x557d07b62f90, op=38(Cancel-Jobs))
d [17/Apr/2018:16:28:58 +0200] cupsdFindPolicyOp(p=0x557d07b5cc40, op=38(Cancel-Jobs))
d [17/Apr/2018:16:28:58 +0200] cupsdAddPolicyOp(p=0x557d07b61000, po=0x557d07b67220, op=38(Cancel-Jobs))
d [17/Apr/2018:16:28:58 +0200] cupsdFindPolicyOp(p=0x557d07b61000, op=38(Cancel-Jobs))

[michaelrsweet]

The policy search is failing - might be an issue with the hash function...

[michaelrsweet]

Nope, looks like the "All" value didn't actually get added to the list... Fix coming up in a sec...

[michaelrsweet]

[master 0873f68] Fix policy limits using All (Issue #5296)

[branch-2.2 417d0e1] Fix policy limits using All (Issue #5296)

[jsmeix]

Wow - that was fast!
Many thanks for the fix.
I tested it with CUPS 2.3b4 and it works for me.

FYI:
For my patch I used only the actually relevant code change:

--- scheduler/conf.c.orig       2018-03-23 21:39:17.000000000 +0100
+++ scheduler/conf.c    2018-04-18 13:38:45.000000000 +0200
@@ -3853,7 +3853,7 @@ read_policy(cups_file_t *fp,              /* I - Con
         if (num_ops < (int)(sizeof(ops) / sizeof(ops[0])))
        {
          if (!_cups_strcasecmp(value, "All"))
-           ops[num_ops] = IPP_ANY_OPERATION;
+           ops[num_ops ++] = IPP_ANY_OPERATION;
          else if ((ops[num_ops] = ippOpValue(value)) == IPP_BAD_OPERATION)
            cupsdLogMessage(CUPSD_LOG_ERROR,
                            "Bad IPP operation name \"%s\" on line %d of %s.",