Bug 12924

Do we have any more detail than this?

Anything in the log files?

(In reply to Michael Tremer from comment #1)
> Do we have any more detail than this?
> 
> Anything in the log files?

From Thomas' error_log:

E [01/Sep/2022:00:08:42 +0200] [Client 606] Unable to encrypt connection: Unable to create server credentials.
E [01/Sep/2022:00:08:44 +0200] [Client 608] Unable to encrypt connection: Unable to create server credentials.
E [01/Sep/2022:00:08:45 +0200] [Client 609] Unable to encrypt connection: Unable to create server credentials.
[…]

And this is what I see in the CUPS error_log:

[root@ipfireAPU bin]# cat /var/log/cups/error_log
I [31/Aug/2022:11:29:09 -0500] Please move "SystemGroup sys root" on line 12 of /var/ipfire/cups/cupsd.conf to the /var/ipfire/cups/cups-files.conf file; this will become an error in a future release.
I [31/Aug/2022:11:29:09 -0500] Listening to 0.0.0.0:631 (IPv4)
I [31/Aug/2022:11:29:09 -0500] Listening to [v1.::]:631 (IPv6)
I [31/Aug/2022:11:29:09 -0500] Listening to /var/run/cups/cups.sock (Domain)
E [31/Aug/2022:11:29:09 -0500] Unknown directive BrowseOrder on line 20 of /var/ipfire/cups/cupsd.conf.
E [31/Aug/2022:11:29:09 -0500] Unknown directive BrowseAllow on line 21 of /var/ipfire/cups/cupsd.conf.
W [31/Aug/2022:11:29:09 -0500] No limit for Validate-Job defined in policy default and no suitable template found.
W [31/Aug/2022:11:29:09 -0500] No limit for Cancel-Jobs defined in policy default - using Pause-Printer's policy.
W [31/Aug/2022:11:29:09 -0500] No limit for Cancel-My-Jobs defined in policy default - using Send-Document's policy.
W [31/Aug/2022:11:29:09 -0500] No limit for Close-Job defined in policy default - using Send-Document's policy.
W [31/Aug/2022:11:29:09 -0500] No limit for CUPS-Get-Document defined in policy default - using Send-Document's policy.
W [31/Aug/2022:11:29:09 -0500] No JobPrivateAccess defined in policy default - using defaults.
W [31/Aug/2022:11:29:09 -0500] No JobPrivateValues defined in policy default - using defaults.
W [31/Aug/2022:11:29:09 -0500] No SubscriptionPrivateAccess defined in policy default - using defaults.
W [31/Aug/2022:11:29:09 -0500] No SubscriptionPrivateValues defined in policy default - using defaults.
I [31/Aug/2022:11:29:09 -0500] Remote access is enabled.
I [31/Aug/2022:11:29:09 -0500] Loaded configuration file "/var/ipfire/cups/cupsd.conf"
I [31/Aug/2022:11:29:09 -0500] Using default TempDir of /var/spool/cups/tmp...
I [31/Aug/2022:11:29:09 -0500] Configured for up to 100 clients.
I [31/Aug/2022:11:29:09 -0500] Allowing up to 100 client connections per host.
I [31/Aug/2022:11:29:09 -0500] Using policy "default" as the default.
I [31/Aug/2022:11:29:09 -0500] Full reload is required.
I [31/Aug/2022:11:29:09 -0500] Loaded MIME database from "/usr/share/cups/mime" and "/var/ipfire/cups": 78 types, 114 filters...
I [31/Aug/2022:11:29:09 -0500] Generating printcap /etc/printcap...
I [31/Aug/2022:11:29:09 -0500] Full reload complete.
I [31/Aug/2022:11:29:09 -0500] Cleaning out old files in "/var/spool/cups/tmp".
I [31/Aug/2022:11:29:09 -0500] Cleaning out old files in "/var/cache/cups".
I [31/Aug/2022:11:29:09 -0500] Listening to 0.0.0.0:631 on fd 6...
I [31/Aug/2022:11:29:09 -0500] Listening to [v1.::]:631 on fd 7...
I [31/Aug/2022:11:29:09 -0500] Listening to /var/run/cups/cups.sock on fd 8...
I [31/Aug/2022:11:29:09 -0500] Resuming new connection processing...
E [31/Aug/2022:11:39:57 -0500] [Client 1] Unable to encrypt connection: Unable to create server credentials.
E [31/Aug/2022:11:39:58 -0500] [Client 2] Unable to encrypt connection: Unable to create server credentials.
E [31/Aug/2022:11:39:58 -0500] [Client 3] Unable to encrypt connection: Unable to create server credentials.
E [31/Aug/2022:11:39:58 -0500] [Client 4] Unable to encrypt connection: Unable to create server credentials.
E [31/Aug/2022:11:39:58 -0500] [Client 5] Unable to encrypt connection: Unable to create server credentials.
E [31/Aug/2022:11:39:59 -0500] [Client 6] Unable to encrypt connection: Unable to create server credentials.
I [31/Aug/2022:11:40:18 -0500] Defaulting to "DNSSDHostName ipfireAPU.local".
E [31/Aug/2022:11:40:31 -0500] [Client 7] Unable to encrypt connection: Unable to create server credentials.
E [31/Aug/2022:11:40:31 -0500] [Client 8] Unable to encrypt connection: Unable to create server credentials.
E [31/Aug/2022:11:40:32 -0500] [Client 9] Unable to encrypt connection: Unable to create server credentials.
E [31/Aug/2022:11:40:32 -0500] [Client 10] Unable to encrypt connection: Unable to create server credentials.
E [31/Aug/2022:11:40:32 -0500] [Client 11] Unable to encrypt connection: Unable to create server credentials.
E [31/Aug/2022:11:40:33 -0500] [Client 12] Unable to encrypt connection: Unable to create server credentials.
I [31/Aug/2022:12:57:42 -0500] [Client 17] Started "/usr/lib/cups/cgi-bin/help.cgi" (pid=25011, file=16)
E [31/Aug/2022:12:57:53 -0500] [Client 19] Unable to encrypt connection: Unable to create server credentials.
E [31/Aug/2022:12:57:54 -0500] [Client 20] Unable to encrypt connection: Unable to create server credentials.
E [31/Aug/2022:12:57:55 -0500] [Client 21] Unable to encrypt connection: Unable to create server credentials.
E [31/Aug/2022:17:29:19 -0500] [Client 22] Unable to encrypt connection: Unable to create server credentials.
E [31/Aug/2022:17:29:20 -0500] [Client 23] Unable to encrypt connection: Unable to create server credentials.
E [31/Aug/2022:17:29:20 -0500] [Client 24] Unable to encrypt connection: Unable to create server credentials.
E [31/Aug/2022:17:29:20 -0500] [Client 25] Unable to encrypt connection: Unable to create server credentials.
E [31/Aug/2022:17:29:20 -0500] [Client 26] Unable to encrypt connection: Unable to create server credentials.
E [31/Aug/2022:17:29:21 -0500] [Client 27] Unable to encrypt connection: Unable to create server credentials.
E [31/Aug/2022:17:30:31 -0500] [Client 29] Unable to encrypt connection: Unable to create server credentials.
E [31/Aug/2022:17:30:32 -0500] [Client 30] Unable to encrypt connection: Unable to create server credentials.
E [31/Aug/2022:17:30:33 -0500] [Client 31] Unable to encrypt connection: Unable to create server credentials.
E [31/Aug/2022:17:31:34 -0500] [Client 32] Unable to encrypt connection: Unable to create server credentials.
E [31/Aug/2022:17:31:35 -0500] [Client 33] Unable to encrypt connection: Unable to create server credentials.
E [31/Aug/2022:17:31:36 -0500] [Client 34] Unable to encrypt connection: Unable to create server credentials.
E [31/Aug/2022:17:37:49 -0500] [Client 35] Unable to encrypt connection: Unable to create server credentials.
E [31/Aug/2022:17:37:49 -0500] [Client 36] Unable to encrypt connection: Unable to create server credentials.
E [31/Aug/2022:17:37:49 -0500] [Client 37] Unable to encrypt connection: Unable to create server credentials.
E [31/Aug/2022:17:37:50 -0500] [Client 38] Unable to encrypt connection: Unable to create server credentials.
E [31/Aug/2022:17:37:50 -0500] [Client 39] Unable to encrypt connection: Unable to create server credentials.
E [31/Aug/2022:17:37:51 -0500] [Client 40] Unable to encrypt connection: Unable to create server credentials.
I [31/Aug/2022:17:44:37 -0500] [Client 42] Started "/usr/lib/cups/cgi-bin/classes.cgi" (pid=8590, file=15)
I [31/Aug/2022:17:44:39 -0500] [Client 42] Started "/usr/lib/cups/cgi-bin/jobs.cgi" (pid=8591, file=15)
I [31/Aug/2022:17:44:40 -0500] [Client 42] Started "/usr/lib/cups/cgi-bin/printers.cgi" (pid=8592, file=15)
I [31/Aug/2022:17:44:42 -0500] [Client 42] Started "/usr/lib/cups/cgi-bin/jobs.cgi" (pid=8593, file=15)
I [31/Aug/2022:17:44:46 -0500] [Client 42] Started "/usr/lib/cups/cgi-bin/help.cgi" (pid=8594, file=15)
I [31/Aug/2022:17:44:50 -0500] [Client 42] Started "/usr/lib/cups/cgi-bin/classes.cgi" (pid=8595, file=15)
E [31/Aug/2022:17:44:56 -0500] [Client 48] Unable to encrypt connection: Unable to create server credentials.

What is it trying to connect to?

Can we tcpdump the connection and strace cupsd?

(In reply to Michael Tremer from comment #4)
> What is it trying to connect to?
> 
> Can we tcpdump the connection and strace cupsd?

I don't know about Thomas, but I get an error when clicking on the Administration tab at the top of the CUPS webgui. (e.g., https://192.168.1.1:631/admin)

(In reply to Jon from comment #5)
> I don't know about Thomas, but I get an error when clicking on the
> Administration tab at the top of the CUPS webgui. (e.g.,
> https://192.168.1.1:631/admin)

And then it doesn't even open?

Created attachment 1082 [details]
Safari Error

It opens with a safari error.

If I go to:
http://192.168.6.1:631
I get the normal/standard "OpenPrinting CUPS 2.4.2" webgui page.  All looks good.

If I go to the HTTPS version at:
https://192.168.6.1:631
I get a Safari page that has an error message (see attachment)
-and-
I see this in the CUPS error_log
E [01/Sep/2022:12:44:49 -0500] [Client 123] Unable to encrypt connection: Unable to create server credentials.

If I go to:
https://192.168.6.1:631/admin
I get the same Safari error message as above.
-and- 
I see the same message in the CUPS error_log

https://git.ipfire.org/?p=ipfire-2.x.git;a=commit;h=d1c8c9ef6071383b434872bfbc63d0e5ca3c3edf

Reverted the CUPS update to prevent releasing a faulty version.

Since we have a good idea what is going wrong, can we try to compile the package with --with-tls=gnutls and see if this works as before again?

I would prefer to use OpenSSL wherever possible, so we might need to report something upstream and see if we can help to get it fixed.

I wasn't aware of this bug and that cups had been reverted so in March 2023 I noticed that there was a newer version of cups and submitted a patch to update it it which brought it back to the version that caused this bug in the first place.

I could raise a patch to revert cups back to version 2.4.1 for CU175

Interestingly, I have noticed that the lfs file has --enable-gnutls but this was no longer used by the cups configure file in version 2.4.1 onwards. It was still used in the previous cups version in IPFire which was 2.3.3

Maybe I should raise a patch with the current --with-tls=gnutls option and maybe someone can test the .ipfire package that I create to see if the problem is solved.

Also discovered that the option --enable-avahi is no longer available in cups.

It has been changed to --with-dnssd=avahi so I will also change that option in my patch submission.

Checking through the build log with version cups-2.4.2 it flags up that those two options are unrecognised.

In the configure it then looks for avahi and finds it is present and therefore uses it. So the --enable-avahi not being valid has not made any difference.

--enable-gnutls not being valid meant that openssl was found and selected, although this muslt also have been the case for cups-2.4.1 but the problem did not exist. That suggests something in openssl changed that caused the problem.

Found that this bug has been flagged up in the cups issue section in their github repo - raised on Nov 12th 2022.

There it says that the problem is

"This happens because the default server keychain path is always set to the MacOS one when building with OpenSSL. The following patch fixes this"

The patch has been committed on Jan 17th 2023 and the issue closed but a new cups release has not yet been made.

As @michael prefers to have openssl rather than gnutls then I will look at taking the cups patch fix and applying it to the IPFire cups build and set --with-tls=openssl

Then that .ipfire package can be tested to see if it works correctly.

Created attachment 1149 [details]
cups .ipfire package for testing of fix

Here is the cups-2.4.2-34.ipfire addon package. This is using openssl but with the fix that cups applied.

@Jon would you be able to test this? You would need to uninstall cups on your system? Only cups needs to be removed, leave all the dependencies as they are as the cups rootfile was not changed so no library links have been modified.

Then you would need to install this .ipfire package as per the details in

https://wiki.ipfire.org/devel/ipfire-2-x/addon-howto#testing-the-install-uninstall-update-routines-and-addon-itself

I was about to send the below, but then cups stopped after one or two minutes.  cups does restart.

The date now is Sun Apr 23 04:26:08 PM CDT 2023
[root@ipfireAPU ~] # /etc/rc.d/init.d/cups status
cupsd is running with Process ID(s) 2882.

[root@ipfireAPU ~] # /etc/rc.d/init.d/cups status
/usr/sbin/cupsd is not running.
[root@ipfireAPU ~] # 
[root@ipfireAPU ~] # /etc/rc.d/init.d/cups start
Starting CUPS Printserver...                                                                                   [  OK  ]
[root@ipfireAPU ~] # /etc/rc.d/init.d/cups status
cupsd is running with Process ID(s) 3900.
[root@ipfireAPU ~] # 

Ugh!  It just stopped again.  I was just clicking on links on the cups WebGUI.

I need to dig thru logs...

====
The above error seems OK.  I can access all of the admin pages OK.  I did not try changing anything since cups is not setup or talking to a printer.

But the cups service did not "start" after pakfire install.  I did a `/etc/rc.d/init.d/cups start`.

(the cups starts as expected on ipfire reboot)

cups does not appear on the Status > Services "Add-On - Services" section.  And it did not appear after an ipfire reboot.

http://192.168.6.1:631 (not https) http://192.168.6.1:631/admin and does not work.  I think this is A-OK.

here are the errors in the messages log:

Apr 23 16:20:01 ipfireAPU kernel: cupsd[7005]: segfault at 7e16e0a02d70 ip 00007e16e0a02d70 sp 00007fffae271d08 error 15 in libc.so.6[7e16e0a02000+2000] likely on CPU 3 (core 3, socket 0)
Apr 23 16:28:54 ipfireAPU kernel: cupsd[2882]: segfault at 70a6ddd38d70 ip 000070a6ddd38d70 sp 00007ffdbc4337a8 error 15 in libc.so.6[70a6ddd38000+2000] likely on CPU 0 (core 0, socket 0)
Apr 23 16:37:29 ipfireAPU kernel: cupsd[3900]: segfault at 649a04717390 ip 0000649a04717390 sp 00007ffed587ac38 error 15 likely on CPU 3 (core 3, socket 0)

This is tested on: 
APU4D4
IPFire 2.27 (x86_64) - Core-Update 174 (stable)

forgot the last line:

Apr 23 16:37:29 ipfireAPU kernel: Code: 00 00 04 74 71 04 9a 64 00 00 00 00 00 00 00 00 00 00 34 6e 71 04 9a 64 00 00 00 00 00 00 00 00 00 00 24 74 71 04 9a 64 00 00 <00> 00 00 00 00 00 00 00 a1 00 00 00 00 00 00 00 70 ed 45 3b c9 75

I can't tell if you tested the https connection or not but having a segfault is definitely not good. It looks to be related to a c library.

Having thought about it a potential problem could be that you will have installed it on your working system which will be CU174 but I built the package on my build system which is on next (will become CU175).

I saw that you are testing cups without any printer actually connected. In that case I should be able to do the same testing on my vm testbed.

I will test out installing the .ipfire package onto a CU174 vm but also onto a CU175 installed vm and see if I get the same seg fault issue you have found.

From what I have found error 15 in the segfault means that the program tried to write into a section of protected memory.
I suspect this is because the cups was built in a CU175 build and not a CU174 build.

Follow the uninstall section of the wiki link for the addon build and then you can re-install the standard cups again.

Ran CU174 vm with the existing cups install cups-2.4.2-33.

http connection worked and https connection gave following error message on SeaMonkey

Secure Connection Failed
The document contains no data.


I then installed my built .ipfire file cups-2.4.2-34 using the fix patch.

cups started without problems. I did not see the segfault problem that @Jon experienced.

http connection worked but https still gave an error message but a different one. The message now was

Certificate extension value is invalid.
Error code: SEC_ERROR_EXTENSION_VALUE_INVALID

Then installed the CU175 build iso and then installed the cups-2.4.2-34.ipfire file.

Same error message received with https

Certificate extension value is invalid.
Error code: SEC_ERROR_EXTENSION_VALUE_INVALID

I will now do a fresh build of cups but using --with-tls=gnutls and see how that build then works with https.

Found an issue entry in the cups repo for the error message SEC_ERROR_EXTENSION_VALUE_INVALID

Patch has been created and merged for that issue. Will finish testing the --with-tls=gnutls option but will then go back to --with-tls=openssl with this next patch fix.

Hopefully it is the last.

Created attachment 1150 [details]
dbus error

I was digging through the logs this morning and came across this.  I attached a screen shot since I didn't want to go off on too big of a tangent.  (sorry if this is noise)

During the install of CUPS (the pakfire version 33 and NOT the new updated version 34) there is a dbus error.  See attached file.

Keep in mind the cups test and the dbus error are on my test box.  And it is used for testing odd things and I may have messed it up.  I do not want to rebuild it at the moment since I am trying to test something unrelated to cups.

I can document the dbus error in a new BZ bug if needed

(In reply to Jon from comment #22)
> Created attachment 1150 [details]
> dbus error
> 
> I was digging through the logs this morning and came across this.  I
> attached a screen shot since I didn't want to go off on too big of a
> tangent.  (sorry if this is noise)
> 
> During the install of CUPS (the pakfire version 33 and NOT the new updated
> version 34) there is a dbus error.  See attached file.

That looks like something got messed up somewhere. I also did a pakfire version 33 install and I did not have that problem with dbus.

I would see if the /usr/share/dbus-1/system.conf file actually does exist and/or if the permissions/ownership look correct.

> 
> Keep in mind the cups test and the dbus error are on my test box.  And it is
> used for testing odd things and I may have messed it up.  I do not want to
> rebuild it at the moment since I am trying to test something unrelated to
> cups.
> 
> I can document the dbus error in a new BZ bug if needed

I would suggest that you need to repeat the install on that box to see if it is reproducible otherwise if you repeat and it works without a problem it will be difficult to fault find.
Do that when you have finished your existing testing.

Based on your input I was able to test out the cups webui interface. I am hopeful I will get a working solution.

I looked for the same error on my production box (which has cups installed) and it appears there also.  The bug appear when adding cups.

I am going to open a new bug report

Installing cups built with --with-tls=gnutls ended up with the same https problem showing up with the following error:-

Secure Connection Failed
The document contains no data.

Cups has a patch for cups/tls-openssl.c to fix the problem with SEC_ERROR_EXTENSION_VALUE_INVALID

Unfortunately the patch is based on a version of tls-openssl.c that is significantly different to what was in cups-2.4.2

Tried creating a patch based on the diff between tls-openssl.c in cups-2.4.2 and at the current master stage.
However this still ended up with the SEC_ERROR_EXTENSION_VALUE_INVALID error message.

Trying now to create a source tarball from the Master stage of the cups github repo and build with that version (commit 7460236)

CUPS 2.4.1? Where is that from?

The latest release on the website is 2.3.3: https://github.com/apple/cups/releases

(In reply to Michael Tremer from comment #27)
> CUPS 2.4.1? Where is that from?
> 
> The latest release on the website is 2.3.3:
> https://github.com/apple/cups/releases

At end of 2019 cups was forked and that repo is only being used for macOS and iOS.

That github site in its Readme says that for the version of cups for other OS's the repo is https://openprinting.github.io/cups/

The build based on the latest commit in the cups repo also ends up with the 

SEC_ERROR_EXTENSION_VALUE_INVALID

error message.

I have also tested it with Firefox (have been testing with SeaMonkey) and the same happens with it.

I will now do a build of the previous version 2.4.1 and just confirm that it works on my testbed.

So I built the previous cups-2.4.1 version and installed the .ipfire package and still can't access the https admin page.

All the http pages are fine.

The admin page comes back with

Secure Connection Failed
The document contains no data.

I remembered to look in the /var/log/cups/error_log file.

The error message there is

Unable to encrypt connection: ASN1 parser: Error in TAG.

I have no idea what that means and searching hasn't helped me. I checked the cups issues page and it has nothing with ASN1 parser.

I got cups-2.4.1 https working. I had to delete the self signed certificates from the backup. It looks like they are created differently in 2.4.2 and that was what was causing the ASN1 parser error.

Having got 2.4.1 working I will go back and have a look at some of the other options I tested earlier. Maybe some of my problems there were related to incorrect certificates.

I have now got cup-2.4.2, with the two patches to fix openssl certificate issues, to work with https.

The problem I had previously was that my certificates were created when I first used version 2.4.2 without the patches and they therefore had error in them. After creating them they are saved in the backup and restored every time a new install occurs so the patches when first applied didn't help because the certificates were not re-created.

I will now put a patch submission together for this.

Patch fix submitted to dev mailing list and patchwork.

https://lists.ipfire.org/pipermail/development/2023-April/015815.html
https://patchwork.ipfire.org/project/ipfire/patch/20230426123229.4385-1-adolf.belka@ipfire.org/

Patch has been committed into next (will be CU175)

https://git.ipfire.org/?p=ipfire-2.x.git;a=commit;h=25ac6657c10f4c8af026ecf5c165e1ddf2768540

https://blog.ipfire.org/post/ipfire-2-27-core-update-175-is-available-for-testing

I have done a test of this and I am able to access the administration pages which use https and edit the config file from the web interface.

So this looks to be fixed.

It would be good if the bug reporter could test and confirm this.

Access via HTTP pages seem OK and access via HTTPS seems OK.

No errors in the cups log at `/var/log/cups/error_log`.

I created a cups printer and that seems to be OK.

Hopefully Thomas will reply back:

https://community.ipfire.org/t/cups-broken-in-current-testing-build-170/8492/17?u=jon

Fix verified by @jon and myself.

CU175 released

https://blog.ipfire.org/post/ipfire-2-27-core-update-175-released