search

nowina-solutions / nexu

87 stars 51 forks source link

PKCS#11: Failure removing and inserting SmartCard token #19

Open Ichigo85 opened 5 years ago

Ichigo85 commented 5 years ago

Hello, We are using different YubiKey SmartCards to authenticate user and sign documents, using PKCS#11 OpenSC module, sometimes on the same pc. What I discovered is that the first key inserted after starting NexU works fine and signs differents documents without problems. If I remove the first key and use the second one, or even if I insert the same key again, NexU can't sign anymore and I have to restart it. After some search I came to this debug log 

 1 matching product adapters
2018-11-16 16:53:49,108 [INFO|lu.nowina.nexu.generic.Pkcs11SignatureTokenAdapter|Pkcs11SignatureTokenAdapter|Thread-29] Lib C:\Windows\System32\opensc-pkcs11.dll
2018-11-16 16:53:51,087 [DEBUG|eu.europa.esig.dss.token.AbstractSignatureTokenConnection|Pkcs11SignatureTokenAdapter|Thread-29] PKCS11 Config :
name = SmartCard1ae86c12-9800-4936-b3a8-375b1db2a101
library = "C:\\Windows\\System32\\opensc-pkcs11.dll"
slotListIndex = 0
SunPKCS11 loading ---DummyConfig-2---
sunpkcs11: Initializing PKCS#11 library C:\Windows\System32\opensc-pkcs11.dll
Information for provider SunPKCS11-SmartCard1ae86c12-9800-4936-b3a8-375b1db2a101
Library info:
  cryptokiVersion: 2.20
  manufacturerID: OpenSC Project
  flags: 0
  libraryDescription: OpenSC smartcard framework
  libraryVersion: 164.168
All slots: 0
Slots with tokens: 0
Slot info for slot 0:
  slotDescription: Yubico Yubikey NEO OTP+U2F+CCID 0
  manufacturerID: Yubico
  flags: CKF_TOKEN_PRESENT | CKF_REMOVABLE_DEVICE | CKF_HW_SLOT
  hardwareVersion: 0.00
  firmwareVersion: 0.00

....
MORE LOGS
.....

2018-11-16 16:55:16,087 [INFO|CardDetector|CardDetector|Thread-29] Found card in terminal 0 with ATR 3BFC1300008131FE15597562696B65794E454F7233E1.
2018-11-16 16:55:16,088 [INFO|lu.nowina.nexu.view.core.UIOperation|UIOperation|Thread-29] Loading /fxml/product-selection.fxml view
2018-11-16 16:55:16,137 [INFO|lu.nowina.nexu.StandaloneUIDisplay|StandaloneUIDisplay|Thread-29] Display BorderPane@70dde16 in display lu.nowina.nexu.StandaloneUIDisplay@727e6c5d from Thread Thread-29
2018-11-16 16:55:16,137 [INFO|lu.nowina.nexu.StandaloneUIDisplay|StandaloneUIDisplay|Thread-29] Wait on Thread Thread-29
2018-11-16 16:55:16,138 [INFO|lu.nowina.nexu.InternalAPI|InternalAPI|JavaFX Application Thread] Product is instance of KeystoreProductAdapter
2018-11-16 16:55:16,138 [INFO|lu.nowina.nexu.view.core.UIOperation|UIOperation|Thread-29] Thread Thread-29 wait on ProductSelectionController
2018-11-16 16:55:16,139 [INFO|lu.nowina.nexu.InternalAPI|InternalAPI|JavaFX Application Thread] Product is instance of WindowsKeystoreProductAdapter
2018-11-16 16:55:16,140 [INFO|lu.nowina.nexu.StandaloneUIDisplay|StandaloneUIDisplay|JavaFX Application Thread] Display BorderPane@70dde16 in display lu.nowina.nexu.StandaloneUIDisplay@727e6c5d from Thread JavaFX Application Thread
2018-11-16 16:55:16,141 [INFO|lu.nowina.nexu.StandaloneUIDisplay|StandaloneUIDisplay|JavaFX Application Thread] Loading ui BorderPane@70dde16 is a new Stage javafx.stage.Stage@8fae795
2018-11-16 16:55:18,898 [INFO|lu.nowina.nexu.view.core.UIOperation|UIOperation|JavaFX Application Thread] Notify from JavaFX Application Thread on ProductSelectionController
2018-11-16 16:55:18,899 [INFO|lu.nowina.nexu.view.core.UIOperation|UIOperation|Thread-29] Thread Thread-29 resumed on ProductSelectionController
2018-11-16 16:55:18,900 [INFO|lu.nowina.nexu.flow.operation.CreateTokenOperation|CreateTokenOperation|Thread-29] 1 matching product adapters
2018-11-16 16:55:18,902 [INFO|lu.nowina.nexu.StandaloneUIDisplay|StandaloneUIDisplay|JavaFX Application Thread] Hide stage javafx.stage.Stage@8fae795 and create new stage
2018-11-16 16:55:22,397 [INFO|lu.nowina.nexu.generic.Pkcs11SignatureTokenAdapter|Pkcs11SignatureTokenAdapter|Thread-29] Lib C:\Windows\System32\opensc-pkcs11.dll
2018-11-16 16:55:26,885 [DEBUG|eu.europa.esig.dss.token.AbstractSignatureTokenConnection|Pkcs11SignatureTokenAdapter|Thread-29] PKCS11 Config :
name = SmartCardcaa1256a-25a3-4124-9ebf-1749203f4a73
library = "C:\\Windows\\System32\\opensc-pkcs11.dll"
slotListIndex = 0
SunPKCS11 loading ---DummyConfig-3---
sunpkcs11: Initializing PKCS#11 library C:\Windows\System32\opensc-pkcs11.dll
Information for provider SunPKCS11-SmartCardcaa1256a-25a3-4124-9ebf-1749203f4a73
Library info:
  cryptokiVersion: 2.20
  manufacturerID: OpenSC Project
  flags: 0
  libraryDescription: OpenSC smartcard framework
  libraryVersion: 164.168
All slots: 0
Slots with tokens: 0
2018-11-16 16:56:20,811 [ERROR|lu.nowina.nexu.flow.GetCertificateFlow|GetCertificateFlow|Thread-29] Flow error
eu.europa.esig.dss.DSSException: Can't initialize Sun PKCS#11 security provider. Reason: PKCS11 not found
        at eu.europa.esig.dss.token.Pkcs11SignatureToken.getKeyStore(Pkcs11SignatureToken.java:196)
        at eu.europa.esig.dss.token.AbstractKeyStoreTokenConnection.getKeys(AbstractKeyStoreTokenConnection.java:23)
        at lu.nowina.nexu.generic.Pkcs11SignatureTokenAdapter.getKeys(Pkcs11SignatureTokenAdapter.java:114)
        at lu.nowina.nexu.flow.operation.SelectPrivateKeyOperation.perform(SelectPrivateKeyOperation.java:89)
        at lu.nowina.nexu.flow.GetCertificateFlow.process(GetCertificateFlow.java:104)
        at lu.nowina.nexu.flow.GetCertificateFlow.process(GetCertificateFlow.java:49)
        at lu.nowina.nexu.flow.Flow.execute(Flow.java:55)
        at lu.nowina.nexu.InternalAPI.lambda$executeRequest$0(InternalAPI.java:195)
        at java.util.concurrent.FutureTask.run(Unknown Source)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
        at java.lang.Thread.run(Unknown Source)
Caused by: java.security.KeyStoreException: PKCS11 not found
        at java.security.KeyStore.getInstance(Unknown Source)
        at eu.europa.esig.dss.token.Pkcs11SignatureToken.getKeyStore(Pkcs11SignatureToken.java:169)
        ... 11 more
Caused by: java.security.NoSuchAlgorithmException: no such algorithm: PKCS11 for provider SunPKCS11-SmartCardcaa1256a-25a3-4124-9ebf-1749203f4a73
        at sun.security.jca.GetInstance.getService(Unknown Source)
        at sun.security.jca.GetInstance.getInstance(Unknown Source)
        at java.security.Security.getImpl(Unknown Source)
        ... 13 more
2018-11-16 16:56:20,822 [INFO|lu.nowina.nexu.view.core.UIOperation|UIOperation|Thread-29] Loading /fxml/provide-feedback.fxml view
2018-11-16 16:56:20,900 [INFO|lu.nowina.nexu.StandaloneUIDisplay|StandaloneUIDisplay|Thread-29] Display BorderPane@511cdcc6 in display lu.nowina.nexu.StandaloneUIDisplay@727e6c5d from Thread Thread-29
2018-11-16 16:56:20,901 [INFO|lu.nowina.nexu.StandaloneUIDisplay|StandaloneUIDisplay|Thread-29] Wait on Thread Thread-29
2018-11-16 16:56:20,901 [INFO|lu.nowina.nexu.StandaloneUIDisplay|StandaloneUIDisplay|JavaFX Application Thread] Display BorderPane@511cdcc6 in display lu.nowina.nexu.StandaloneUIDisplay@727e6c5d from Thread JavaFX Application Thread
2018-11-16 16:56:20,901 [INFO|lu.nowina.nexu.view.core.UIOperation|UIOperation|Thread-29] Thread Thread-29 wait on ProvideFeedbackController
2018-11-16 16:56:20,902 [INFO|lu.nowina.nexu.StandaloneUIDisplay|StandaloneUIDisplay|JavaFX Application Thread] Loading ui BorderPane@511cdcc6 is a new Stage javafx.stage.Stage@1c1b3ec6
2018-11-16 16:56:23,456 [INFO|lu.nowina.nexu.view.core.UIOperation|UIOperation|JavaFX Application Thread] Notify from JavaFX Application Thread on ProvideFeedbackController
2018-11-16 16:56:23,458 [INFO|lu.nowina.nexu.view.core.UIOperation|UIOperation|Thread-29] Thread Thread-29 resumed on ProvideFeedbackController
2018-11-16 16:56:23,462 [INFO|lu.nowina.nexu.StandaloneUIDisplay|StandaloneUIDisplay|JavaFX Application Thread] Hide stage javafx.stage.Stage@1c1b3ec6 and create new stage
2018-11-16 16:56:28,783 [INFO|lu.nowina.nexu.StandaloneUIDisplay|StandaloneUIDisplay|JavaFX Application Thread] Hide stage javafx.stage.Stage@2b4c6348 and create new stage
2018-11-16 16:56:28,783 [ERROR|lu.nowina.nexu.InternalAPI|InternalAPI|qtp1396051344-44] Cannot execute request
java.util.concurrent.ExecutionException: eu.europa.esig.dss.DSSException: Can't initialize Sun PKCS#11 security provider. Reason: PKCS11 not found
        at java.util.concurrent.FutureTask.report(Unknown Source)
        at java.util.concurrent.FutureTask.get(Unknown Source)
        at lu.nowina.nexu.InternalAPI.executeRequest(InternalAPI.java:200)
        at lu.nowina.nexu.InternalAPI.getCertificate(InternalAPI.java:233)
        at lu.nowina.nexu.rest.RestHttpPlugin.getCertificates(RestHttpPlugin.java:165)
        at lu.nowina.nexu.rest.RestHttpPlugin.process(RestHttpPlugin.java:76)
        at lu.nowina.nexu.jetty.RequestProcessor.httpPlugin(RequestProcessor.java:183)
        at lu.nowina.nexu.jetty.RequestProcessor.handle(RequestProcessor.java:141)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:119)
        at org.eclipse.jetty.server.Server.handle(Server.java:517)
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:306)
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:242)
        at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:245)
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:95)
        at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:192)
        at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:245)
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:95)
        at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:75)
        at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceAndRun(ExecuteProduceConsume.java:213)
        at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:147)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:654)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:572)
        at java.lang.Thread.run(Unknown Source)
Caused by: eu.europa.esig.dss.DSSException: Can't initialize Sun PKCS#11 security provider. Reason: PKCS11 not found
        at eu.europa.esig.dss.token.Pkcs11SignatureToken.getKeyStore(Pkcs11SignatureToken.java:196)
        at eu.europa.esig.dss.token.AbstractKeyStoreTokenConnection.getKeys(AbstractKeyStoreTokenConnection.java:23)
        at lu.nowina.nexu.generic.Pkcs11SignatureTokenAdapter.getKeys(Pkcs11SignatureTokenAdapter.java:114)
        at lu.nowina.nexu.flow.operation.SelectPrivateKeyOperation.perform(SelectPrivateKeyOperation.java:89)
        at lu.nowina.nexu.flow.GetCertificateFlow.process(GetCertificateFlow.java:104)
        at lu.nowina.nexu.flow.GetCertificateFlow.process(GetCertificateFlow.java:49)
        at lu.nowina.nexu.flow.Flow.execute(Flow.java:55)
        at lu.nowina.nexu.InternalAPI.lambda$executeRequest$0(InternalAPI.java:195)
        at java.util.concurrent.FutureTask.run(Unknown Source)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
        ... 1 more
Caused by: java.security.KeyStoreException: PKCS11 not found
        at java.security.KeyStore.getInstance(Unknown Source)
        at eu.europa.esig.dss.token.Pkcs11SignatureToken.getKeyStore(Pkcs11SignatureToken.java:169)
        ... 11 more
Caused by: java.security.NoSuchAlgorithmException: no such algorithm: PKCS11 for provider SunPKCS11-SmartCardcaa1256a-25a3-4124-9ebf-1749203f4a73
        at sun.security.jca.GetInstance.getService(Unknown Source)
        at sun.security.jca.GetInstance.getInstance(Unknown Source)
        at java.security.Security.getImpl(Unknown Source)
        ... 13 more
2018-11-16 16:56:49,227 [DEBUG|CardDetector|CardDetector|Thread-5] Context was released successfully.

and understood that OpenSC PKCS#11 library does not reinitialize slot, or doesn't detect the key anymore, but NexU does detect the key. That is because Slot info for slot 0 after removing becomes Slot info for slot 0: slotDescription: Virtual hotplug slot
manufacturerID: OpenSC Project flags: CKF_REMOVABLE_DEVICE | CKF_HW_SLOT

and what's important is that CKF_TOKEN_PRESENT flag is missing, as OpenSC library did not recognize any key inserted.

OpenSC version: 0.17 Win x64 (newer version not working with NexU) NexU version: 1.22

Any help?

Ichigo85 commented 5 years ago

Hello, I made a fork of Nexu and solved this issue, you can find it here. Briefly, I modified Pkcs11SignatureTokenAdapter#close method to finalize and clean PKCS#11 module every time. I'll make some more tests, anyway please let me know if it's a valid solution for you.