PKCS11.C_SignFinal(Native Method) is failing with message CKR_DATA_INVALID and losing session , asking pin again and again in JRE>=jre8.1_161 version #1966
Comments
|
Please note i am using the latest .20 version of opensc-pkcs11 dll. |
|
The above does not show any use of OpenSC. What type of card? |
|
Hi Dengert, Here C_SignFinal is a native invocation. I am new to using opensc, can you please tell me the exact windows64, registry entries , which are required to generate the log? Is it enough to add the registry on environment variable, or I need to load the PKCS11_SPY using java program. |
|
PIV card-type=14004 |
|
The environment variable OPENSC_DEBUG=3 should have created a log to stderr. You found the card type of 14004, so I assume you found it in the log or stderr?
The PKCS11_SPY is a PKCS11 module that writes a log file and then calls the real PKCS11 module that does the work. So you can point the Java PKCS11 configuration code at the Spy module: C:\Program Files\OpenSC Project\PKCS11-Spy\pkcs11-spy.dll You can use Note: when running on a 64 but machine there is also this location used by the 32 bit versions: There is one other thing about the PIV card. The card enforces a "PIN Always" policy on the card that requires the PIN to be entered just before a Sign operation when using the "Sign key". Some applications, and maybe your Java application do not know how to handle the PIN Always policy which PKCS11 presents as a key attribute of CKA_ALWAYS_AUTHENTICATE. An application should then ask the user again for PIN and call C_Login again. The PKCS11-Spy log would show if the application understands CKA_ALWAYS_AUTHENTICATE. Try using your card with pkcs11-tool --test --login. This will try to use all the keys on the card and prompt you several times for you PIN. pkcs11-tool handles the CKA_ALWAYS_AUTHENTICATE attribute. If the failure is Java does not support CKA_ALWAYS_AUTHENTICATE, and you and your employer are willing to violate the NIST PIV policy of having user's enter PIN before every use of the Sign key OpenSC does have a workaround. (But this does not work when using a PIN pad reader which further protect the PIN.) See https://github.com/OpenSC/OpenSC/blob/master/etc/opensc.conf.example.in#L894 and add the |
|
Actually, last I checked Java did not understand That's one reason why I maintain my own fork of OpenSC , which has that %#^# software-level enforcement of Re. Policy - it's the card's job to enforce it or not. Not the middleware's. |
|
regarding - See https://github.com/OpenSC/OpenSC/blob/master/etc/opensc.conf.example.in#L894 and add the framework pkcs15 { } stanza to the opensc-conf file with line 897 uncommentted pin_cache_ignore_user_consent = true; --> As I am loading the opensc-pkcs11.dll using java program, and I am not sure how should I pass the parameters CKA_ALWAYS_AUTHENTICATE, & pin_cache_ignore_user_consent = true . And the type of card I got by running the tools provided by the opensc. some how logs are not getting generated when executing from Java program. |
|
From what Moose says, Java does not understand CKA_ALWAYS_AUTHENTICATE. skip that for now, In the two opensc.conf files most likely these: This should work. If not uncomment the two debug lines and add a path if you want to debug_file: Don't run in production with the debug lines uncommented. PINs will show up in the debug_file and SPY output. You may want to XXXXX them out before posting on the list. "I should load the PKCS11-Spy.dll rather than opensc-pkcs11.dll from java program while configuring the PKCS provider" - Yes. |
|
Thanks for the valuable inputs - 2055: C_GetSessionInfo and after this there is another call - with following data |
|
logs from opensc-debug.txt - |
HI Mouse, |
|
I myself don't work on Windows, so I don't build DLLs. It should be possible to build Windows binaries, including DLL, the same way as this repo does it. https://GitHub.com/mouse07410/OpenSC.git |
|
Both were dealing with accessing PIV cards. At one time it looked like one or both might be uing teh Sign cert that requires special handling because of the "PIN Always" - "CKA_ALWAYS_AUTHENTICATE" issue. @jalajpachouly |
|
I also need more of the SPY log, to see how it got to the C_SignFinal. |
|
Two more tests. |
|
As issue was working in JRE 8.1_RU151 and not working in JRE 8.1 RU221, hence i started downgrading the JRE to narrow down the issue. Hope I could have started in ascending order , but finally I was able to track down the culprit JRE version, that is JRE 8.1 RU 161 , which has introduced this issue. There are some significant changes related to security. I am suspecting the below mentioned changes which seems causing the issue - security-libs/javax.crypto RSA public key validation Here is the release notes for JRE8.1 RU 161 |
|
Are using using SHA1? Its out of date, and Java might reject it. Check there release notes. That still does not help us to see if OpenSC has a problem or your card has a bad key. Spy log, and or opensc-debug log would help. If it can not produce these logs, it could be as you said it is rejecting something in the java code. If you get the private key and certificate out of sync that could be your problem. How did you generate the keys on the card? The pkcs11-tool runs would show if the keys match the certificate and can be verified. PIV specs only say how to generate a key pair on the card and this is the only time it will return the public key. Some vendors provide a way to write a private key on the card. PIV driver parses certificate to find public key to determine algorithm, key size, and namedCurve. |
|
Hi Dengert, Card Capability Container: RSA PKCS #1 v1.5 with SHA-256, signed by PIV Content Signer 1 Security Object: Employee Affiliation: Employee Expiration date: 20301231 (2030DEC31) Agency Card Serial Number: 0000012345 Issuer Identification: TSTISR320161719 Discovery Object: |
|
Spy -dll logs. opensc-debug logs Please see if this is similar to - #1531 |
|
You may have a defective reader. A valid looking crypto operations in your opensc-debug.log A line 29104 is a crypto operation that fails: The "10" says this is a chained operation, so 90 00 should have been received, not 61 14 Outgoing APDU (5 bytes): 00 C0 00 00 14 (get response that should not be needed here) There is a chance there is a bug in OpenSC or the card when using T=0, but based on line 15 and the following reviews of the device which appears to be the same as yours: Customer reviews that sound like the same problem: Do you have any other readers? |
|
Hi Dengert, Thanks for the updates Regards |
|
As I noted, some of the crypto operations worked. Some did not. So this could be an intermittent problem. I don't think this is a java problem, the failed crypto chaining operation looks strange. I dont thing it is a login problem. 6D 00 is SC_ERROR_INS_NOT_SUPPORTED. Also note that the opensc-debug.log says you are using OpenSC 0.19.0 Can you try with 0.20.0? |
|
we have seen this issue in .20 also, when we downgrade the JRE version to 8.1_151 , it works smooth. |
|
With the reader you have, try `force_protocol = "T1";' in opensc.conf See example: Please try 'pkcs11-tool --test --login` to see if this fails or not. If it fails can you send the opensc-debug.log. |
|
Looking closer at the failing sequence, this may be a thread locking problem, as it appears line 29040 is is the start of the apdu that is returning the 61 14 in the middle of the chained signature operation. which then fails. Some how these commands are being intermixed, and the card cant handle the sequence. Any other developer any other ideas? |
|
Case 1 - Log for 'pkcs11-tool --test --login Case 2- Running application with new reader , I see java crash in all the runs , i also tried to set orce_protocol = "T1"; but getting crash, even removing the token , still we see the crash with new Reader.
Crash logs - |
|
I also used the opensc .20 in above runs. |
jalajpachouly
changed the title
jalajpachouly
changed the title
|
Did you see #1966 (comment) ? This looks like a thread issue. OpenSC supports threads, but it does not write much in the debug log. It is not clear if Java made some change in jre8.1_161 that would cause it to misuse threads in PKCS11 or if OpenSC is not doing something correctly. OpenSC can be configured without threads... What would it take to reproduce the problem? Can you do some additional debugging. See https://docs.oracle.com/javase/8/docs/technotes/guides/security/p11guide.html#TroubleShoot |
|
For general SunPKCS11 provider debugging info: -Djava.security.debug=sunpkcs11 -Djava.security.debug=pkcs11keystore I am not building the dll. OpenSC can be configured without threads... |
|
Reproducing the issue - Load the pkcs11 provider using opensc-pkcs11 dll, using stand alone java client program and use JRE 8.1_161 version or higher version , use https communication to the tomcat remote server , you will be able to login and later connection will be destroyed as your session becomes invalid in few seconds, due to failure in the opensc dll SignFinal method. |
|
Would you like to try my fork to see if it's any better for Java access? |
|
I have been looking at opensc-debug.log from 2020-03-02 -3:29:01.877. around line 29036 you will see threads 10160 and 8552 issuing APDUs. 10160 is doing a C_GetSessionInfo that will endup quering the card to check the login state, and if it is still inserted. 8552 is doing a signature operation that consists of requires multiple APDUs. The two are intermingling the APDUs, and causeing havic! This should not have happened OpenSC should have been using thread locking to not allow this to happen. The sc_plcs11_lock and sc_pkcs11_unlock should prevent 2 threads from running at the same time using opensc code. But there is not enough debugging to see what is happening. It could be it used to work as expected It could be java changed what it passed to OpenSC to handle locking. It could be it never worked as expected, but java did not use multiple threads like it does in the latest release. I have been working on a test code to add debugging so we can see what is going on. and will submit it as a PR so it will also get built, and you can then download the .msi files to try. Should have it in a hour or so. |
this is test code to help debut issue OpenSC#1966 it is being submitted as a PR to get the windows artifacts so user can test it. It will show what is passed to C_Initialize by Java and show enter and leave log messages for sc_pkcs11_lock and sc_pkcs11_unlock if thay are actualling using teh mutex. On branch PKCS11-lock Changes to be committed: modified: pkcs11-global.c
|
@jalajpachouly Can you test the change from #1975 Find the image you want, most likely 2017 release 64 bit, and maybe the 32 bit too. If you want to run a windows debuger these might be helpful too: https://ci.appveyor.com/api/buildjobs/79oo1lxqmqghciv4/artifacts/OpenSC-0.20.0_win32-Debug.zip Then send another opensc-debug.log |
|
OK, |
|
P:8464; T:8232 2020-03-08 01:23:45.256 [opensc-pkcs11] pkcs15-sec.c:707:sc_pkcs15_compute_signature: use_key() failed: -1211 (Security status not satisfied) is this card is no more valid with JRE starting 8.1_161 ? |
|
This is a threads issue and not a "card is no more valid" issue. The debugging code in this PR shows in opensc-debug.txt from above, line 18 shows: The global_lock should not be null. And if locking was working, every call to sc_pkcs11_lock, The trick with using the debug log is I have pushed another commit for testing. It is being compiled. I will see it it works under FireFox windows 10. |
|
Hi Dengert, |
|
The opensc-debug.txt looks good. lines 17-21 are as expected. Java is asking the PKCS11 module to do OS locking internally, and OpenSC was built and is using its internal version for Windows in the
When you say "when I enable debugging" do you mean enabling Java debugging, or do you mean enabling OpenSC debugging? |
|
I mean OpenSC debugging |
|
Hi Dengert, |
|
The version you have is built on top of master from 2020-03-06. It contains 206 commits since 0.20.0 was released. So the choice is yours as to when you deploy in production. I would wait at least until the PR is committed. So far we have shown it fixes your problem. You should also make a comment in #1975 that it fixes your problem. I would also change the name of the issue to something like: "Java JRE>=jre8.1_161 exposes OpenSC PKCS11 failure to use thread locking on Windows is some cases" |
|
Can you please share the link from where I can get the fixed version , which I can deploy to production environment? By when PR commit will complete? |
|
I've (accidentally) pushed a fix to master, binaries should soon be available at |
|
Thanks for the prompt response -as per the above link I have installed version 0.20.0.206, and it is working fine, I am using the same for the production, please let me know if you have any concerns? |
|
@dengert what is the version 0.20.0.206 or .207? The content of the #1975? Is it something we should merge? The subset of that excluding the logging? |
I think he was counting number of commits past 0.20.0.
@frankmorgner said in: #1966 (comment) that he accidentally committed a fix. i.e. f1bcadfbe He commented in: #1975 (comment) So #1975 in not needed and the logging is not really needed either. |
|
ok, so we should be good and this issue can be closed. Thanks for clarifications! |
This is how I am loading the pkcs11 dll.
String configName = "/opt/bar/cfg/pkcs11.cfg";
Provider p = Security.getProvider("SunPKCS11");
p = p.configure(configName);
Security.addProvider(p);
I am able to use smart card authentication , but after little usage suddenly gets logout from the application and also see smart card pin popup, looks like smart card session is lost.
Error is like this -
Feb 27, 2020 10:17:00 PM STDERR: javax.net.ssl.SSLException: sun.security.pkcs11.wrapper.PKCS11Exception: CKR_DATA_INVALID
Feb 27, 2020 10:17:00 PM STDERR: at java.base/sun.security.ssl.Alert.createSSLException(Alert.java:133)
Feb 27, 2020 10:17:00 PM STDERR: at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:321)
Feb 27, 2020 10:17:00 PM STDERR: at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:264)
Feb 27, 2020 10:17:00 PM STDERR: at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:259)
Feb 27, 2020 10:17:00 PM STDERR: at java.base/sun.security.ssl.SSLSocketImpl.handleException(SSLSocketImpl.java:1314)
Feb 27, 2020 10:17:00 PM STDERR: at java.base/sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:408)
Feb 27, 2020 10:17:00 PM STDERR: at java.base/sun.net.www.protocol.https.HttpsClient.afterConnect(HttpsClient.java:567)
Feb 27, 2020 10:17:00 PM STDERR: at java.base/sun.net.www.protocol.https.AbstractDelegateHttpsURLConnection.connect(AbstractDelegateHttpsURLConnection.java:185)
Feb 27, 2020 10:17:00 PM STDERR: at java.base/sun.net.www.protocol.http.HttpURLConnection.getOutputStream0(HttpURLConnection.java:1362)
Feb 27, 2020 10:17:00 PM STDERR: at java.base/sun.net.www.protocol.http.HttpURLConnection.getOutputStream(HttpURLConnection.java:1337)
Feb 27, 2020 10:17:00 PM STDERR: at java.base/sun.net.www.protocol.https.HttpsURLConnectionImpl.getOutputStream(HttpsURLConnectionImpl.java:246)
Feb 27, 2020 10:17:00 PM STDERR: at java.base/java.lang.Thread.run(Thread.java:834)
Feb 27, 2020 10:17:00 PM STDERR: Caused by: java.security.ProviderException: sun.security.pkcs11.wrapper.PKCS11Exception: CKR_DATA_INVALID
Feb 27, 2020 10:17:00 PM STDERR: at jdk.crypto.cryptoki/sun.security.pkcs11.P11Signature.engineSign(P11Signature.java:646)
Feb 27, 2020 10:17:00 PM STDERR: at java.base/java.security.Signature$Delegate.engineSign(Signature.java:1402)
Feb 27, 2020 10:17:00 PM STDERR: at java.base/java.security.Signature.sign(Signature.java:711)
Feb 27, 2020 10:17:00 PM STDERR: at java.base/sun.security.ssl.CertificateVerify$T12CertificateVerifyMessage.(CertificateVerify.java:582)
Feb 27, 2020 10:17:00 PM STDERR: at java.base/sun.security.ssl.CertificateVerify$T12CertificateVerifyProducer.produce(CertificateVerify.java:740)
Feb 27, 2020 10:17:00 PM STDERR: at java.base/sun.security.ssl.SSLHandshake.produce(SSLHandshake.java:436)
Feb 27, 2020 10:17:00 PM STDERR: at java.base/sun.security.ssl.ServerHelloDone$ServerHelloDoneConsumer.consume(ServerHelloDone.java:182)
Feb 27, 2020 10:17:00 PM STDERR: at java.base/sun.security.ssl.SSLHandshake.consume(SSLHandshake.java:392)
Feb 27, 2020 10:17:00 PM STDERR: at java.base/sun.security.ssl.HandshakeContext.dispatch(HandshakeContext.java:450)
Feb 27, 2020 10:17:00 PM STDERR: at java.base/sun.security.ssl.HandshakeContext.dispatch(HandshakeContext.java:427)
Feb 27, 2020 10:17:00 PM STDERR: at java.base/sun.security.ssl.TransportContext.dispatch(TransportContext.java:178)
Feb 27, 2020 10:17:00 PM STDERR: at java.base/sun.security.ssl.SSLTransport.decode(SSLTransport.java:164)
Feb 27, 2020 10:17:00 PM STDERR: at java.base/sun.security.ssl.SSLSocketImpl.decode(SSLSocketImpl.java:1152)
Feb 27, 2020 10:17:00 PM STDERR: at java.base/sun.security.ssl.SSLSocketImpl.readHandshakeRecord(SSLSocketImpl.java:1063)
Feb 27, 2020 10:17:00 PM STDERR: at java.base/sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:402)
Feb 27, 2020 10:17:00 PM STDERR: ... 20 more
Feb 27, 2020 10:17:00 PM STDERR: Caused by: sun.security.pkcs11.wrapper.PKCS11Exception: CKR_DATA_INVALID
Feb 27, 2020 10:17:00 PM STDERR: at jdk.crypto.cryptoki/sun.security.pkcs11.wrapper.PKCS11.C_SignFinal(Native Method)
Feb 27, 2020 10:17:00 PM STDERR: at jdk.crypto.cryptoki/sun.security.pkcs11.P11Signature.engineSign(P11Signature.java:604)
The text was updated successfully, but these errors were encountered: