qzind / tray

Browser plugin for sending documents and raw commands to a printer or attached device.
https://qz.io
Other
837 stars 272 forks source link

Fail during install: NoSuchAlgorithmException: unrecognized algorithm name #814

Closed tresf closed 3 years ago

tresf commented 3 years ago

OS version: Windows 7 64-bit QZ Tray version: (TBD) Java version: (TBD)

Possibly related: https://bugs.java.com/bugdatabase/view_bug.do?bug_id=JDK-8266261

openjdk version "1.8.0_292"
OpenJDK Runtime Environment (AdoptOpenJDK)(build 1.8.0_292-b10)
OpenJDK Client VM (AdoptOpenJDK)(build 25.292-b10, mixed mode)
Output folder: C:\Program Files\QZ Tray
[...]
[ERROR] 2021-05-26 14:21:45,820 @ qz.utils.ArgParser:?
        Installation step CERTGEN failed
java.security.KeyStoreException: Key protection  algorithm not found: java.security.UnrecoverableKeyException: Encrypt Private Key failed: unrecognized algorithm name: PBEWithSHA1AndDESede
        at sun.security.pkcs12.PKCS12KeyStore.setKeyEntry(PKCS12KeyStore.java:677)
        at sun.security.pkcs12.PKCS12KeyStore.engineSetKeyEntry(PKCS12KeyStore.java:577)
        at java.security.KeyStore.setKeyEntry(KeyStore.java:1140)
        at qz.installer.certificate.CertificateManager.createKeyStore(Unknown Source)
        at qz.installer.certificate.CertificateManager.<init>(Unknown Source)
        at qz.installer.Installer.certGen(Unknown Source)
        at qz.utils.ArgParser.processInstallerArgs(Unknown Source)
        at qz.utils.ArgParser.intercept(Unknown Source)
        at qz.ws.PrintSocketServer.main(Unknown Source)
Caused by: java.security.UnrecoverableKeyException: Encrypt Private Key failed: unrecognized algorithm name: PBEWithSHA1AndDESede
        at sun.security.pkcs12.PKCS12KeyStore.encryptPrivateKey(PKCS12KeyStore.java:921)
        at sun.security.pkcs12.PKCS12KeyStore.setKeyEntry(PKCS12KeyStore.java:614)
        ... 8 more
Caused by: java.security.NoSuchAlgorithmException: unrecognized algorithm name: PBEWithSHA1AndDESede
        at sun.security.x509.AlgorithmId.get(AlgorithmId.java:448)
        at sun.security.pkcs12.PKCS12KeyStore.mapPBEAlgorithmToOID(PKCS12KeyStore.java:938)
        at sun.security.pkcs12.PKCS12KeyStore.encryptPrivateKey(PKCS12KeyStore.java:895)
        ... 9 more
Installation failed during certgen step.  Please check log for details.

Capture135

selcip commented 3 years ago

The same happened to me but in 2.1.3 on Windows 10 Pro 20H2

Screenshot 2021-05-26 145613

tresf commented 3 years ago

The same happened to me but in 2.1.3 on Windows 10 Pro 20H2

Does it still happen on AdoptOpenJDK 11.0.11+9? https://adoptopenjdk.net/

I just tested on Windows 7 x64 using AdoptOpenJDK 11.0.11+9 and it did not throw this error.

tresf commented 3 years ago

Also, can you copy and paste the full logs please?

tresf commented 3 years ago

I was able to reproduce with AdoptOpenJDK 8. Please uninstall AdoptOpenJDK 8 and install AdoptOpenJDK 11.

selcip commented 3 years ago

Where can i find the logs?

Also, i tried installing AdoptOpenJDK 11 but it didn't seem to do anything. I'm installing from the latest prebuilt binary

tresf commented 3 years ago

i tried installing AdoptOpenJDK 11 but it didn't seem to do anything. I'm installing from the latest prebuilt binary

I believe you'll need to uninstall all versions of Java 8.

Where can i find the logs?

I don't think I need them any longer, I was able to reproduce (I've added them to the original post), but for the future, just re-run the installer and copy/paste.

selcip commented 3 years ago

Alright, thanks! It worked perfectly now

I removed all version of Java, installed AdoptOpenJDK 11 and installed from the 2.1.3+1 windows release.

tresf commented 3 years ago

Thanks. Sorry for this oddball bug. I'm working on a possible workaround. It's a regression introduced with Java 8. Here's Amazon's documentation of it which explains it very clearly I feel.

https://github.com/corretto/corretto-8/issues/306

tresf commented 3 years ago

I tried to apply Amazon's workaround but it didn't work. I expect Java 8 users to continue to suffer until we have a workaround (or until it's patched). Meanwhile, people can downgrade to Java 8, but a version that's older than 8u291.

lutkerd commented 3 years ago

I'm surprised the 2nd work around of clearing out the table didn't work. You should be able to call clearAlgorithms() after all JARs are loaded and verified, then the next time a algorithm is needed it will re-initialize the table. If your CertificateManager code is getting invoked during validation, it would fail since the SunJCE provider is not available at all. So this must be done before it has started or after it is 100% completed.

public static void clearAlgorithms() {
        try {
            Class<?> clazz = sun.security.x509.AlgorithmId.class;
            java.lang.reflect.Field f1 = clazz.getDeclaredField("oidTable");
            f1.setAccessible(true);
            f1.set(clazz, null);
            java.lang.reflect.Field f2 = clazz.getDeclaredField("initOidTable");
            f2.setAccessible(true);
            f2.set(clazz, false);
        } catch (Exception e) {
            System.out.println(e);
            e.printStackTrace();
        }
    }
tresf commented 3 years ago

I'm surprised the 2nd work around of clearing out the table didn't work. You should be able to call clearAlgorithms() after all JARs are loaded and verified, then the next time a algorithm is needed it will re-initialize the table. If your CertificateManager code is getting invoked during validation, it would fail since the SunJCE provider is not available at all. So this must be done before it has started or after it is 100% completed.

public static void clearAlgorithms() {
       try {
           Class<?> clazz = sun.security.x509.AlgorithmId.class;
           java.lang.reflect.Field f1 = clazz.getDeclaredField("oidTable");
           f1.setAccessible(true);
           f1.set(clazz, null);
           java.lang.reflect.Field f2 = clazz.getDeclaredField("initOidTable");
           f2.setAccessible(true);
           f2.set(clazz, false);
       } catch (Exception e) {
           System.out.println(e);
           e.printStackTrace();
       }
   }

@lutkerd thanks kindly for jumping on over and lending a hand. First thing I noticed is the fields have changed from JDK8-JDK11 so I'd put a version guard around that but I'm still uncertain as to this point...

So this must be done before it has started or after it is 100% completed.

What does "invoked during validation" mean? In our case, this may be exactly what is occuring, but I don't know exactly how to wait until "it is 100% completed".

This specific task is invoked by a desktop installer, so it's getting run right away with the start of the JVM on the main thread.

main(String ... args)
   --> Installer.getInstance().certGen()
      --> CertificateManager()

Is there some form of signal I can listen upon to know when it's completed?

lutkerd commented 3 years ago

JDK11 has some small changes, so you can just skip the clearing f2 if there is a NoSuchFieldException thrown by clazz.getDeclaredField("initOidTable");

When class verification is happening in 8u292, they use a subset of providers, set through Providers.beginThreadProviderList and the previous list is restored by a call to Providers.endThreadProviderList. These calls can be nested or happen multiple times as more jars are required, so you may to wait until all of the endThreadProviderList calls are made before you clear the table. Unfortunately, I don't think there is an event for easy thing to check to see if loading is completed.

If you add -Djava.security.debug=jca.ProviderList to your command line you will see a few hundred lines of output, but among those would be the logging from those 2 functions. Here is the filtered output from the reproducer we wrote with the logging enabled.

% ./amazon-corretto-8.jdk-292/Contents/Home/bin/java -Djava.security.debug=jca.ProviderList -cp bcprov-jdk15on-168.jar:./ BCRepro 2>&1|grep -E "ThreadLocal providers|Exception|JCE"

ProviderList: provider configuration: [sun.security.provider.Sun, sun.security.rsa.SunRsaSign, sun.security.ec.SunEC, com.sun.net.ssl.internal.ssl.Provider, com.sun.crypto.provider.SunJCE, sun.security.jgss.SunProvider, com.sun.security.sasl.Provider, org.jcp.xml.dsig.internal.dom.XMLDSigRI, sun.security.smartcardio.SunPCSC, apple.security.AppleProvider]
ProviderList: ThreadLocal providers: [sun.security.provider.Sun, sun.security.rsa.SunRsaSign, sun.security.ec.SunEC, sun.security.provider.VerificationProvider]
ProviderList: Disabling ThreadLocal providers
ProviderList: ThreadLocal providers: [sun.security.provider.Sun, sun.security.rsa.SunRsaSign, sun.security.ec.SunEC, sun.security.provider.VerificationProvider]
ProviderList: Disabling ThreadLocal providers
ProviderList: ThreadLocal providers: [sun.security.provider.Sun, sun.security.rsa.SunRsaSign, sun.security.ec.SunEC, sun.security.provider.VerificationProvider]
ProviderList: Disabling ThreadLocal providers
ProviderList: ThreadLocal providers: [sun.security.provider.Sun, sun.security.rsa.SunRsaSign, sun.security.ec.SunEC, sun.security.provider.VerificationProvider]
java.lang.Exception: Debug Info. Call trace:
ProviderList: Disabling ThreadLocal providers
Exception in thread "main" java.security.NoSuchAlgorithmException: unrecognized algorithm name: PBEWithSHA1AndDESede

You want to make sure you see com.sun.crypto.provider.SunJCE in your complete ProviderList, that would be coming from java.security or an override you are passing on the command line. Then you should see that you are calling clearAlgorithms outside of any ThreadLocal provider messages to ensure that the complete list is being used. Adding some simple logging or System.out calls to your code should show the timing.

tresf commented 3 years ago

I'm surprised the 2nd work around of clearing out the table didn't work.

@lutkerd You're right, it works. I began combing through the logs using the recommended flag only to realize it's working. 🤦 I'm not sure what I mucked in my previous tests, but I can confirm that adding clearAlgorithms() works against AdoptOpenJDK8 8u292.

I've explicitly set the patch to only apply on known broken JDK versions, only reset initOidTable if on JDK8. Patch ready in #819.

tresf commented 3 years ago

Another oddity is the bug is not reproducible for me under AdoptOpenJDK 11.0.11 despite the bug report stating that it is present there. I'm applying the workaround to that version incase it affects other non-Adopt provided JDKs, but I'm uncertain as to the cause of this discrepancy. For the time being, we recommend AdoptOpenJDK 11 to our users which is why I think we've dodged this hard-crash on mass, but I'm a bit confused as to how. 😅

lutkerd commented 3 years ago

The bug is that the list of providers is getting cached during JAR verification using a subset of security providers, which has the symptom of NoSuchAlgorithmException when it used to work. The algorithm in question, PBEWithSHA1AndDESede, is from SunJCE which used during verification for JDK11, but not on JDK8. https://github.com/corretto/corretto-11/blob/develop/src/java.base/share/classes/sun/security/jca/Providers.java#L84

With JDK11 you would see algorithms from providers not in the list above cause the exception, such as when using BouncyCastle as a provider, those algorithms would never get added to the cache.

The fixes going into JDK8 and JDK11 are to not require initializing the table during jar verification, but then JDK8 is also getting a backport for using SunJCE during jar verification.

tresf commented 3 years ago

Thanks. AFAIK, we don't use any BouncyCastle-only providers, but I'll leave the patch in for 11.0.11 to avoid a regression if this ever changes in the future. Thanks for the explanation.