search

OpenPrinting / cups

OpenPrinting CUPS Sources
https://openprinting.github.io/cups
Apache License 2.0
1.07k stars 192 forks source link

lpr fails with lpr: success #137

Closed rewolff closed 3 years ago

rewolff commented 3 years ago

In case you say I should use cups-native programs... I have calls to lpr executable throughout my interanally developed systems, Not really one place to change things.

Since the upgrade to ubuntu 20.04: printing sometimes fails with: "lpr: success". The cups error log then gets 22 warnings printed. When I retry: It suddenly works (often), and then there are no warnings.

W [04/Dec/2020:15:28:00 +0100] No limit for Validate-Job defined in policy default and no suitable template found.
W [04/Dec/2020:15:28:00 +0100] No limit for Cancel-Jobs defined in policy default - using Pause-Printer's policy.
W [04/Dec/2020:15:28:00 +0100] No limit for Cancel-My-Jobs defined in policy default - using Send-Document's policy.
W [04/Dec/2020:15:28:00 +0100] No limit for Close-Job defined in policy default - using Send-Document's policy.
W [04/Dec/2020:15:28:00 +0100] No JobPrivateAccess defined in policy default - using defaults.
W [04/Dec/2020:15:28:00 +0100] No JobPrivateValues defined in policy default - using defaults.
W [04/Dec/2020:15:28:00 +0100] No SubscriptionPrivateAccess defined in policy default - using defaults.
W [04/Dec/2020:15:28:00 +0100] No SubscriptionPrivateValues defined in policy default - using defaults.
W [04/Dec/2020:15:28:00 +0100] No limit for Validate-Job defined in policy authenticated - using Print-Job's policy.
W [04/Dec/2020:15:28:00 +0100] No limit for Cancel-Jobs defined in policy authenticated - using Pause-Printer's policy.
W [04/Dec/2020:15:28:00 +0100] No limit for Cancel-My-Jobs defined in policy authenticated - using Send-Document's policy.
W [04/Dec/2020:15:28:00 +0100] No limit for Close-Job defined in policy authenticated - using Send-Document's policy.
W [04/Dec/2020:15:28:00 +0100] No JobPrivateAccess defined in policy authenticated - using defaults.
W [04/Dec/2020:15:28:00 +0100] No JobPrivateValues defined in policy authenticated - using defaults.
W [04/Dec/2020:15:28:00 +0100] No SubscriptionPrivateAccess defined in policy authenticated - using defaults.
W [04/Dec/2020:15:28:00 +0100] No SubscriptionPrivateValues defined in policy authenticated - using defaults.
W [04/Dec/2020:15:28:00 +0100] DNS-SD registration of "DYMO LabelWriter 450 @ abra2" failed: Local name collision
W [04/Dec/2020:15:28:00 +0100] DNS-SD registration of "DYMO LabelWriter 450 @ abra2" failed: Local name collision
W [04/Dec/2020:15:28:00 +0100] DNS-SD registration of "DYMO LabelWriter 450 @ abra2" failed: Local name collision
W [04/Dec/2020:15:28:00 +0100] DNS-SD registration of "DYMO LabelWriter 450 @ abra2" failed: Local name collision
W [04/Dec/2020:15:28:01 +0100] CreateProfile failed: org.freedesktop.ColorManager.AlreadyExists:profile id \'Samsung_CLX_4190_Series_SEC001599A93C91_-Gray..\' already exists
W [04/Dec/2020:15:28:01 +0100] CreateProfile failed: org.freedesktop.ColorManager.AlreadyExists:profile id \'Samsung_CLX_4190_Series_SEC001599A93C91_-DeviceN..\' already exists
michaelrsweet commented 3 years ago

Please attach a copy of your cupsd.conf and error_log files. This looks like cupsd might be crashing...

@tillkamppeter Can you weigh in here? Anything he can look for on his system to help determine a cause?

rewolff commented 3 years ago 
LogLevel warn
MaxLogSize 0
MaxJobs 100
SystemGroup lpadmin
# Allow remote access
Port 631
Listen /var/run/cups/cups.sock
Browsing On
BrowseLocalProtocols dnssd
#BrowseAddress @LOCAL
DefaultAuthType Basic
<Location />
  # Allow remote access...
  Order allow,deny
  Allow all
</Location>
<Location /admin>
</Location>
<Location /admin/conf>
  AuthType Default
  Require user @SYSTEM
</Location>
<Policy default>
  <Limit Send-Document Send-URI Hold-Job Release-Job Restart-Job Purge-Jobs Set-Job-Attributes Create-Job-Subscription Renew-Subscription Cancel-Subscription Get-Notifications Reprocess-Job Cancel-Current-Job Suspend-Current-Job Resume-Job CUPS-Move-Job CUPS-Get-Document>
    Require user @OWNER @SYSTEM
    Order deny,allow
  </Limit>
  <Limit CUPS-Add-Modify-Printer CUPS-Delete-Printer CUPS-Add-Modify-Class CUPS-Delete-Class CUPS-Set-Default CUPS-Get-Devices>
    AuthType Default
    Require user @SYSTEM
    Order deny,allow
  </Limit>
  <Limit Pause-Printer Resume-Printer Enable-Printer Disable-Printer Pause-Printer-After-Current-Job Hold-New-Jobs Release-Held-New-Jobs Deactivate-Printer Activate-Printer Restart-Printer Shutdown-Printer Startup-Printer Promote-Job Schedule-Job-After CUPS-Accept-Jobs CUPS-Reject-Jobs>
    AuthType Default
    Require user @SYSTEM
    Order deny,allow
  </Limit>
  <Limit Cancel-Job CUPS-Authenticate-Job>
    Require user @OWNER @SYSTEM
    Order deny,allow
  </Limit>
  <Limit All>
    Order deny,allow
  </Limit>
</Policy>
<Policy authenticated>
  <Limit Create-Job Print-Job Print-URI>
    AuthType Default
    Order deny,allow
  </Limit>
  <Limit Send-Document Send-URI Hold-Job Release-Job Restart-Job Purge-Jobs Set-Job-Attributes Create-Job-Subscription Renew-Subscription Cancel-Subscription Get-Notifications Reprocess-Job Cancel-Current-Job Suspend-Current-Job Resume-Job CUPS-Move-Job CUPS-Get-Document>
    AuthType Default
    Require user @OWNER @SYSTEM
    Order deny,allow
  </Limit>
  <Limit CUPS-Add-Modify-Printer CUPS-Delete-Printer CUPS-Add-Modify-Class CUPS-Delete-Class CUPS-Set-Default>
    AuthType Default
    Require user @SYSTEM
    Order deny,allow
  </Limit>
  <Limit Pause-Printer Resume-Printer Enable-Printer Disable-Printer Pause-Printer-After-Current-Job Hold-New-Jobs Release-Held-New-Jobs Deactivate-Printer Activate-Printer Restart-Printer Shutdown-Printer Startup-Printer Promote-Job Schedule-Job-After CUPS-Accept-Jobs CUPS-Reject-Jobs>
    AuthType Default
    Require user @SYSTEM
    Order deny,allow
  </Limit>
  <Limit Cancel-Job CUPS-Authenticate-Job>
    AuthType Default
    Require user @OWNER @SYSTEM
    Order deny,allow
  </Limit>
  <Limit All>
    Order deny,allow
  </Limit>
</Policy>

It works a few seconds later. So that would mean that systemd is restarting cupsd? Wouldn't systemd log something somewhere that we could look for?

rewolff commented 3 years ago

The error log is currently: (i.e. it happened precisely once since the logfile was rotated. 

W [13/Mar/2021:00:00:02 +0100] No limit for Validate-Job defined in policy default and no suitable template found.
W [13/Mar/2021:00:00:02 +0100] No limit for Cancel-Jobs defined in policy default - using Pause-Printer's policy.
W [13/Mar/2021:00:00:02 +0100] No limit for Cancel-My-Jobs defined in policy default - using Send-Document's policy.
W [13/Mar/2021:00:00:02 +0100] No limit for Close-Job defined in policy default - using Send-Document's policy.
W [13/Mar/2021:00:00:02 +0100] No JobPrivateAccess defined in policy default - using defaults.
W [13/Mar/2021:00:00:02 +0100] No JobPrivateValues defined in policy default - using defaults.
W [13/Mar/2021:00:00:02 +0100] No SubscriptionPrivateAccess defined in policy default - using defaults.
W [13/Mar/2021:00:00:02 +0100] No SubscriptionPrivateValues defined in policy default - using defaults.
W [13/Mar/2021:00:00:02 +0100] No limit for Validate-Job defined in policy authenticated - using Print-Job's policy.
W [13/Mar/2021:00:00:02 +0100] No limit for Cancel-Jobs defined in policy authenticated - using Pause-Printer's policy.
W [13/Mar/2021:00:00:02 +0100] No limit for Cancel-My-Jobs defined in policy authenticated - using Send-Document's policy.
W [13/Mar/2021:00:00:02 +0100] No limit for Close-Job defined in policy authenticated - using Send-Document's policy.
W [13/Mar/2021:00:00:02 +0100] No JobPrivateAccess defined in policy authenticated - using defaults.
W [13/Mar/2021:00:00:02 +0100] No JobPrivateValues defined in policy authenticated - using defaults.
W [13/Mar/2021:00:00:02 +0100] No SubscriptionPrivateAccess defined in policy authenticated - using defaults.
W [13/Mar/2021:00:00:02 +0100] No SubscriptionPrivateValues defined in policy authenticated - using defaults.
W [13/Mar/2021:00:00:02 +0100] DNS-SD registration of "DYMO LabelWriter 450 @ abra2" failed: Local name collision
W [13/Mar/2021:00:00:02 +0100] DNS-SD registration of "DYMO LabelWriter 450 @ abra2" failed: Local name collision
W [13/Mar/2021:00:00:02 +0100] DNS-SD registration of "DYMO LabelWriter 450 @ abra2" failed: Local name collision
W [13/Mar/2021:00:00:02 +0100] DNS-SD registration of "DYMO LabelWriter 450 @ abra2" failed: Local name collision

Oh, wait! This is "startup chatter" from cupsd? This happens often precisely at midnight....

So in that case, cupsd was restarted when I see the error.

In an older log:

E [11/Mar/2021:11:38:02 +0100] [Client 28] Unable to encrypt connection: A TLS fatal alert has been received.
E [11/Mar/2021:11:38:06 +0100] [Client 29] Unable to encrypt connection: A TLS fatal alert has been received.
E [11/Mar/2021:11:38:16 +0100] [Client 33] Unable to encrypt connection: A TLS fatal alert has been received.
W [11/Mar/2021:11:41:47 +0100] No limit for Validate-Job defined in policy default and no suitable template found.
...

So 4 and then 10 seconds later we have a TLS error, and then 3.5 minutes later we see the restart.... I think those are unrelated.

tillkamppeter commented 3 years ago

At least if systemd is used a crashed (or prematurely terminating) daemon is immediately started again. Especially if you have some broken line in the config files which makes CUPS terminate, you get thousands of the error message in the logs. Unfortunately, I do not know whether one can make systemd stop if the restarts get too frequent (like with the error in a config file).

systemd logs into /var/log/syslog and you can also filter and find log messages with journalctl.

For your error_log you should set LogLevel debug (simply run cupsctl --debug-logging) then you get more information on what happens before the crash.

To analyse a crash of cupsd, you should run it without the systemd harness. Run the command

sudo systemctl stop cups

to stop the systemd-controlled CUPS and then run

sudo /usr/sbin/cupsd -f

to get a "free" CUPS. Then, in a second terminal, run the command which crashed CUPS. Due to the fact that CUPS does not restart now you can simply have a look at the very last lines of your error_log (and post those here).

rewolff commented 3 years ago

You are right! There it is! 

Mar 11 11:52:19 abra2 cupsd[3520926]: free(): invalid pointer
Mar 11 11:52:19 abra2 systemd[1]: cups.service: Main process exited, code=dumped, status=6/ABRT
Mar 11 11:52:19 abra2 systemd[1]: cups.service: Failed with result 'core-dump'.

The error log does NOT contain any lines pertaining to the error. In the case at hand at 52:19 we see a "free(): invalid pointer" from cupsd in /var/log/syslog and then the standard startup messages in cups/error.log .

michaelrsweet commented 3 years ago

This looks like the printer-alert bug that is fixed in 2.3.3op1. @tillkamppeter did the fix for issue #43 get pushed to Ubuntu 20.04’s CUPS?

tillkamppeter commented 3 years ago

Ubuntu 20.04 received the last update on CUPS on 2020-04-27, so issue #43 is most probably not fixed there.

tillkamppeter commented 3 years ago

Seems that the bug got also reported to Ubuntu:

https://bugs.launchpad.net/ubuntu/+source/cups/+bug/1846334/ https://bugs.launchpad.net/ubuntu/+source/cups/+bug/1915181/

But it is currently only fixed from Hirsute (21.04) on.

michaelrsweet commented 3 years ago

@tillkamppeter Since this is fixed in OpenPrinting CUPS, I'll close this bug out. I don't know whether you can get an update queued for the older Ubuntu releases, but given this is a scheduler crash without a workaround it would seem to be important to fix, at least for 20.04 LTS.