Issue #2503: Smartcard token key changeover with externalReg enabled fails during rollback - dogtagpki

dogtagpki

#2503 Smartcard token key changeover with externalReg enabled fails during rollback

Closed: Invalid Opened Oct 6, 2016 by rpattath.

Smartcard token key changeover with externalReg enabled fails during rollback

Steps to Reproduce:

1. Enable externalReg
2. Create master key on hsm following instructions in
https://bugzilla.redhat.com/show_bug.cgi?id=1186896#c24 (master key name is
hsm-master-5
3. Add the following to TKS CS.cfg
tks.mk_mappings.#02#01=NHSM-RPATTATH-SOFTCARD:hsm-master-5
tks.defKeySet.mk_mappings.#02#01=NHSM-RPATTATH-SOFTCARD:hsm-master-5
4. Make the following changes to TPS CS.cfg
op.enroll.externalRegAddToToken.update.symmetricKeys.enable=true
op.enroll.externalRegAddToToken.update.symmetricKeys.requiredVersion=2
5. Enroll a smartcard token with user of externalRegAddToToken token type and
the certs to be recovered added to the user.
6. Change TPS Cs.cfg to the following
op.enroll.externalRegAddToToken.update.symmetricKeys.enable=true
op.enroll.externalRegAddToToken.update.symmetricKeys.requiredVersion=1
7. Enroll the smartcard again
8. Change TPS Cs.cfg to the following
op.enroll.externalRegAddToToken.update.symmetricKeys.enable=false
op.enroll.externalRegAddToToken.update.symmetricKeys.requiredVersion=1
9. Enroll the smartcard again

Actual results:

5. Enrollment with keychange is successful and the certs/keys are revoked and
Key on the token is 0201
7. Enrollment with keychange is successful and the certs/keys are revoked and
Key on the token is 0101
9. Enrollment fails

Expected results:

Enrollment should be successful in all the the above steps

Additional info:

tps debug log during failure
[root@nocp4 rpattath]# cat /var/log/pki/pki-tps-rpattath-Sep30-2016/tps/debug |
grep "05/Oct/2016:12:29:23"
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSConnection.read: Reading:
s=38&msg_type=10&pdu_size=2&pdu_data=%90%00
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSMessage.createMessage:
message: s=38&msg_type=10&pdu_size=2&pdu_data=<do not
print>&pdu_size=2&pdu_data=%90%00
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSMessage msg_type: 10
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSMessage operation: null
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSMessage extensions: null
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSSession.read() message
created
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: APDUResponse.checkResult : sw1:
0x90 sw2: 0x0
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.importprivateKeyPKCS8 successful, leaving...
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.enrollOneCertificate:: enrollment ends
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: In TPSProcessor.statusUpdate
status: 90 info: PROGRESS_ENROLL_CERT
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSConnection.write: Writing:
s=64&msg_type=14&current_state=90&next_task_name=PROGRESS_ENROLL_CERT
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSSession.read() about to call
read on connection : org.dogtagpki.tps.TPSConnection@779f2c79
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSConnection read()
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSConnection.read: Reading:
s=28&msg_type=15&current_state=90
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSMessage.createMessage:
message: s=28&msg_type=15&current_state=90
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSMessage msg_type: 15
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSMessage operation: null
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSMessage extensions: null
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: statusValue: 90
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: statusInt: 90
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSSession.read() message
created
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.enrollOneCertificate ends
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.externalRegRecover:after generateCertificate() with
MODE_RECOVERY
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.externalRegRecover:ends
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSEnrollProcessor.enroll: after
externalRegRecover status is:STATUS_ERROR_RECOVERY_IS_PROCESSED
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: LDAPDatabase:
addRecord("20161005122923126000.27")
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: In
LdapBoundConnFactory::getConn()
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: masterConn is connected: true
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: getConn: conn is connected true
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: getConn: mNumConns now 2
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: LDAPDatabase: adding
cn=20161005122923126000.27,ou=Activities,o=pki-tps-rpattath-Sep30-2016-TPS
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: returnConn: mNumConns now 3
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.buildTokenLabel: entering...
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.buildTokenLabel: pattern: $auth.cn$
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSProcessor.mapPattern: pattern
=$auth.cn$
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSProcessor.mapPattern: found
match: key: auth.cn mapped to: pkiuser4
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSProcessor.mapPattern: pattern
=pkiuser4
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSProcessor.mapPattern:
returning: pkiuser4
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.buildTokenLabel: returning: pkiuser4
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSEnrollProcessor.enroll:
getOldObjectVersion: returning: 288
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSEnrollProcessor.enroll:
Setting objectVersion to: 289
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: PKCS11Obj.setObjectVersion:
setting to: 289
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSProcessor.setupSecureChannel:
No arguments entering...
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSProcessor.getChannelDefKeyVersion: 0
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSProcessor.getChannelDefKeyIndex: 0
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSProcessor.getTKSConectorID:
returning: tks1
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSProcessor.setupSecureChannel:
keyVersion: 0 keyIndex: 0
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TKSRemoteRequestHandler:
computeRandomData(): begins.
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TKSRemoteRequestHandler:
computeRandomData(): sending request to tks.
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: HttpConnector: send(): begins
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: In HttpConnFactory.getConn
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: HttpgetConn: mNumConns now 0
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: HttpConnection.doSend: with
String content length: 14
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: HttpConnection: Connecting to
nocp4.idm.lab.eng.rdu2.redhat.com:23443 with timeout 30s
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: HttpConnection: Connected to
nocp4.idm.lab.eng.rdu2.redhat.com:23443
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: HttpConnection.doSend: sending
request
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: HttpConnection.doSend: server
returned status 200
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: In HttpConnFactory.returnConn
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: HttpreturnConn: mNumConns now 1
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: RemoteRequestHandler:
parseResponse(): begins:
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: RemoteRequestHandler:
parseResponse(): # of elements:2
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TKSRemoteRequestHandler:
computeRandomData(): got status = 0
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TKSRemoteRequestHandler:
computeRandomData(): got IRemoteRequest.TKS_RESPONSE_RandomData
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TKSRemoteRequestHandler:
computeRandomData(): ends.
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSProcessor.setupSecureChannel:
obtained randomData
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: In
TPS_Processor.initializeUpdate.
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSConnection.write: Writing:
s=71&msg_type=9&pdu_size=13pdu_data=<do not print>
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSSession.read() about to call
read on connection : org.dogtagpki.tps.TPSConnection@779f2c79
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSConnection read()
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSConnection.read: Reading...
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSMessage.createMessage:
message: s=117&msg_type=10&pdu_size=30&pdu_data=<do not print>&pdu_size=30&pdu_
data=%00%00A%06%24%0E%03%26u%C1%01%01%14%5C%FA%29%7B%CC%F94%18%3E%B0%8A%2D%B4%D
B%D7%90%00
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSMessage msg_type: 10
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSMessage operation: null
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSMessage extensions: null
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSSession.read() message
created
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: APDUResponse.checkResult : sw1:
0x90 sw2: 0x0
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSProcessor.setupSecureChannel:
diversification data: 00%00%41%06%24%0E%03%26%75%C1%
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSProcessor.setupSecureChannel:
key info data: 01%01%
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSProcessor.setupSecureChannel:
card cryptogram: extracted
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSProcessor.setupSecureChannel:
card challenge: extracted
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSProcessor.generateSecureChannel: entering.. keyInfoData: 01%01%
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSProcessor.generateSecureChannel: isSCP02: false
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPsProcessor.checkCUIDMatchesKDD:  CUID 4090614575C1240E0326 KDD:
00004106240E032675C1
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPsProcessor.checkCUIDMatchesKDD:  config to check:
op.enroll.externalRegAddToToken.cuidMustMatchKDD
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPsProcessor.checkCUIDMatchesKDD:  config result: false
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPsProcessor.checkCUIDMatchesKDD:  returning result: true
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: checkCardGPKeyVersionIsInRange:
entering: keyInfoData: 0101
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: checkCardGPKeyVersionIsInRange:
config to check: op.enroll.externalRegAddToToken.enableBoundedGPKeyVersion
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: checkCardGPKeyVersionIsInRange:
returning: true
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: checkCardGPKeyVersionIsInRange:
config to check: minConfig: op.enroll.externalRegAddToToken.minimumGPKeyVersion
maxConfig: op.enroll.externalRegAddToToken.maximumGPKeyVersion
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: checkCardGPKeyVersionIsInRange:
minVersion: 01 maxVersion: FF
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: checkCardGPKeyVersionIsInRange:
Version reported from key Info Data: 01
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: checkCardGPKeyVersionIsInRange:
versionMinCompare: 0 versionMaxCompare: -54
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: checkCardGPKeyVersionIsInRange:
Version : 01 is in range of: 01 and: FF
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: checkCardGPKeyVersionIsInRange:
Returning result of: true
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
checkCardGPKeyVersionMatchesTokenDB:  config to check:
op.enroll.externalRegAddToToken.validateCardKeyInfoAgainstTokenDB
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
checkCardGPKeyVersionMatchesTokenDB:  config result: true
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPProcessor.getKeyInfioFromTokenDB: returning: 0101
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
checkCardGPKeyVersionMatchesTokenDB:  keyInfoFromTokenDB: 0101
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
checkCardGPKeyVersionMatchesTokenDB:  keyInfoFromToken: 0101
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
checkCardGPKeyVersionMatchesTokenDB:  Key Info in the DB IS the same as the one
from the token!
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
checkCardGPKeyVersionMatchesTokenDB:  returning result: true
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSProcessor.getSharedSecretTransportKeyName: calculated key name: sharedSecret
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
SecureChannelProtocol.getSharedSecretKeyName: Entering...
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
SecureChannelProtocol.getSymKeyByName:Searching for sym key: sharedSecret
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
SecureChannelProtocol.getSymKeyByName:Found key: sharedSecret
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSEngine.computeSessionKey
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TKSRemoteRequestHandler:
computeSessionKey(): begins.
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TKSRemoteRequestHandler.computeSessionKey: sending request to TKS
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: HttpConnector: send(): begins
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: In HttpConnFactory.getConn
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: HttpgetConn: mNumConns now 0
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: HttpConnection.doSend: with
String content length: 250
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: HttpConnection: Connecting to
nocp4.idm.lab.eng.rdu2.redhat.com:23443 with timeout 30s
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: HttpConnection: Connected to
nocp4.idm.lab.eng.rdu2.redhat.com:23443
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: HttpConnection.doSend: sending
request
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: HttpConnection.doSend: server
returned status 200
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: In HttpConnFactory.returnConn
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: HttpreturnConn: mNumConns now 1
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: RemoteRequestHandler:
parseResponse(): begins:
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: RemoteRequestHandler:
parseResponse(): # of elements:7
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TKSRemoteRequestHandler:
computeSessionKey(): got status = 0
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TKSRemoteRequestHandler:
computeSessionKey(): got IRemoteRequest.TKS_RESPONSE_SessionKey
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TKSRemoteRequestHandler:
computeSessionKey(): got IRemoteRequest.TKS_RESPONSE_EncSessionKey
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TKSRemoteRequestHandler:
computeSessionKey(): got IRemoteRequest.TKS_RESPONSE_DRM_Trans_DesKey
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TKSRemoteRequestHandler:
computeSessionKey(): got IRemoteRequest.TKS_RESPONSE_KEK_DesKey
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TKSRemoteRequestHandler:
computeSessionKey(): got IRemoteRequest.TKS_RESPONSE_KeyCheck
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TKSRemoteRequestHandler:
computeSessionKey(): got IRemoteRequest.TKS_RESPONSE_HostCryptogram
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TKSRemoteRequestHandler:
computeSessionKey(): ends.
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
SecureChannelProtocol.unwrapWrappedSymKeyOnToken:Entering...
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
SecureChannelProtocol.makeDes3KeyDerivedFromDes2: Entering ...
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
SecureChannelProtocol.extractDes2FromDes3: Entering:
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
SecureChannelProtocol.makeDes3KeyDerivedFromDes2: extracted8 key
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
SecureChannelProtocol.unwrapWrappedSymKeyOnToken:Returning symkey...
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSProcessor.generateSecureChannel: retrieved session key:
org.mozilla.jss.pkcs11.PK11SymKey@652ee77d
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
SecureChannelProtocol.unwrapWrappedSymKeyOnToken:Entering...
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
SecureChannelProtocol.makeDes3KeyDerivedFromDes2: Entering ...
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
SecureChannelProtocol.extractDes2FromDes3: Entering:
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
SecureChannelProtocol.makeDes3KeyDerivedFromDes2: extracted8 key
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
SecureChannelProtocol.unwrapWrappedSymKeyOnToken:Returning symkey...
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSProcessor.generateSecureChannel: retrieved enc session key
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: SecureChannel.SecureChannel: For
SCP01.
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
SecureChannel.externalAuthenticate: entering.
&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
SecureChannel.externalAuthenticate: about to call computeAPDUMac.
&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: SecureChannel.computeAPDUMac:
got data To MAC
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: SecureChannel.computeAPDUMac:
MAC computed
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSConnection.write: Writing:
s=95&msg_type=9&pdu_size=21pdu_data=<do not print>
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSSession.read() about to call
read on connection : org.dogtagpki.tps.TPSConnection@779f2c79
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSConnection read()
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSConnection.read: Reading:
s=38&msg_type=10&pdu_size=2&pdu_data=%90%00
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSMessage.createMessage:
message: s=38&msg_type=10&pdu_size=2&pdu_data=<do not
print>&pdu_size=2&pdu_data=%90%00
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSMessage msg_type: 10
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSMessage operation: null
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSMessage extensions: null
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSSession.read() message
created
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: APDUResponse.checkResult : sw1:
0x90 sw2: 0x0
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
SecureChannel.externalAuthenticate: Successfully completed, exiting ...
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: In TPSProcessor.statusUpdate
status: 92 info: PROGRESS_WRITE_OBJECTS
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSConnection.write: Writing:
s=66&msg_type=14&current_state=92&next_task_name=PROGRESS_WRITE_OBJECTS
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSSession.read() about to call
read on connection : org.dogtagpki.tps.TPSConnection@779f2c79
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSConnection read()
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSConnection.read: Reading:
s=28&msg_type=15&current_state=92
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSMessage.createMessage:
message: s=28&msg_type=15&current_state=92
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSMessage msg_type: 15
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSMessage operation: null
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSMessage extensions: null
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: statusValue: 92
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: statusInt: 92
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSSession.read() message
created
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.cleanObjectListBeforeExternalRecovery :: begins
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.cleanObjectListBeforeExternalRecovery :number of certs to
recover=3
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.cleanObjectListBeforeExternalRecovery : getting config :
op.enroll.externalRegAddToToken.keyGen.keyType.num
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.cleanObjectListBeforeExternalRecovery : config keyTypeNum: 0
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.cleanObjectListBeforeExternalRecovery : pkcs11obj num_objs
=36
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.isInCertsToRecoverList : begins checking for cert, serial:68
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.isInCertsToRecoverList : ends. returning: true
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.cleanObjectListBeforeExternalRecovery : cert found in
recovery list, to be retained. id:0
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.isInCertsToRecoverList : begins checking for cert, serial:70
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.isInCertsToRecoverList : ends. returning: true
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.cleanObjectListBeforeExternalRecovery : cert found in
recovery list, to be retained. id:1
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.isInCertsToRecoverList : begins checking for cert, serial:72
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.isInCertsToRecoverList : ends. returning: true
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.cleanObjectListBeforeExternalRecovery : cert found in
recovery list, to be retained. id:2
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.isInCertsToRecoverList : begins checking for cert, serial:68
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.isInCertsToRecoverList : ends. returning: true
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.cleanObjectListBeforeExternalRecovery : cert found in
recovery list, to be retained. id:3
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.isInCertsToRecoverList : begins checking for cert, serial:70
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.isInCertsToRecoverList : ends. returning: true
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.cleanObjectListBeforeExternalRecovery : cert found in
recovery list, to be retained. id:4
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.isInCertsToRecoverList : begins checking for cert, serial:72
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.isInCertsToRecoverList : ends. returning: true
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.cleanObjectListBeforeExternalRecovery : cert found in
recovery list, to be retained. id:5
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.isInCertsToRecoverList : begins checking for cert, serial:68
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.isInCertsToRecoverList : ends. returning: true
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.cleanObjectListBeforeExternalRecovery : cert found in
recovery list, to be retained. id:6
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.isInCertsToRecoverList : begins checking for cert, serial:70
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.isInCertsToRecoverList : ends. returning: true
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.cleanObjectListBeforeExternalRecovery : cert found in
recovery list, to be retained. id:7
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.isInCertsToRecoverList : begins checking for cert, serial:72
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.isInCertsToRecoverList : ends. returning: true
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.cleanObjectListBeforeExternalRecovery : cert found in
recovery list, to be retained. id:8
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.cleanObjectListBeforeExternalRecovery : ends. Returning
status: STATUS_NO_ERROR
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.writeFinalPKCS11ObjectToToken:  entering...
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.writeFinalPKCS11ObjectToToken:  config to check:
op.enroll.externalRegAddToToken.pkcs11obj.compress.enable
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]:
TPSEnrollProcessor.writeFinalPKCS11ObjectToToken:  doCompress: true
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: PKCS11Obj:getRawData:
objectCount: 36
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: PKCSObj:getRawData: found cert
object: id: 0 u_id: 0
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: PKCSObj:getRawData: found public
key object: id: 0
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: PKCSObj:getRawData: found
private key object: id: 0
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: PKCSObj:getRawData: found cert
object: id: 1 u_id: 1
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: PKCSObj:getRawData: found public
key object: id: 1
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: PKCSObj:getRawData: found
private key object: id: 1
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: PKCSObj:getRawData: found cert
object: id: 2 u_id: 2
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: PKCSObj:getRawData: found public
key object: id: 2
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: PKCSObj:getRawData: found
private key object: id: 2
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: PKCSObj:getRawData: found cert
object: id: 3 u_id: 3
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: PKCSObj:getRawData: found public
key object: id: 3
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: PKCSObj:getRawData: found
private key object: id: 3
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: PKCSObj:getRawData: found cert
object: id: 4 u_id: 4
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: PKCSObj:getRawData: found public
key object: id: 4
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: PKCSObj:getRawData: found
private key object: id: 4
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: PKCSObj:getRawData: found cert
object: id: 5 u_id: 5
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: PKCSObj:getRawData: found public
key object: id: 5
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: PKCSObj:getRawData: found
private key object: id: 5
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: PKCSObj:getRawData: found cert
object: id: 6 u_id: 6
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: PKCSObj:getRawData: found public
key object: id: 6
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: PKCSObj:getRawData: found
private key object: id: 6
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: PKCSObj:getRawData: found cert
object: id: 7 u_id: 7
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: PKCSObj:getRawData: found public
key object: id: 7
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: PKCSObj:getRawData: found
private key object: id: 7
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: PKCSObj:getRawData: found cert
object: id: 8 u_id: 8
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: PKCSObj:getRawData: found public
key object: id: 8
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: PKCSObj:getRawData: found
private key object: id: 8
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: PKCS11Obj.getCompressedData:
before compress length = 9130
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: PKCS11Obj.getCompressedData:
sizeof src_buffer = 9130
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: PKCS11Obj.getCompressedData:
data size = 9130
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: Original: 9130
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: Compressed: 2354
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: PKCS11Obj.getRawHeaderData:
formatVersion: 256 objectVersion: 289
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: PKCS11Obj.getRawHeaderData:
returning: 01%00%01%21%40%90%61%45%75%C1%24%0E%03%26%00%01%09%32%00%14%
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: PKCS11Obj.getCompressedData:
PKCS11 Data: ends
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: SecureChannel.createObject:
entering...
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: SecureChannel.computeAPDU:
entering..
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: SecureChannel.computeAPDUMac:
got data To MAC
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: SecureChannel.computeAPDUMac:
MAC computed
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: SecureChannel.computeAPDU:
Successfully encrypted apdu data.
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSConnection.write: Writing:
s=119&msg_type=9&pdu_size=29pdu_data=<do not print>
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSSession.read() about to call
read on connection : org.dogtagpki.tps.TPSConnection@779f2c79
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSConnection read()
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSConnection.read: Reading:
s=38&msg_type=10&pdu_size=2&pdu_data=%9C%01
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSMessage.createMessage:
message: s=38&msg_type=10&pdu_size=2&pdu_data=<do not
print>&pdu_size=2&pdu_data=%9C%01
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSMessage msg_type: 10
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSMessage operation: null
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSMessage extensions: null
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSSession.read() message
created
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: APDUResponse.checkResult : sw1:
0x9c sw2: 0x1
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSSession.process: Message
processing failed: SecureChannel.createObject. Failed to create object on
token.
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSConnection.write: Writing:
s=42&msg_type=13&operation=1&result=1&message=7
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: TPSSession.process: leaving:
result: 1 status: STATUS_ERROR_MAC_ENROLL_PDU
[05/Oct/2016:12:29:23][http-bio-25080-exec-1]: After session.process() exiting
...

mharmsen commented Oct 12, 2016

CLOSING AS NOT A BUG

Roshni 2016-10-10 14:25:08 EDT

I am not able to reproduce this issue with fresh TPS instance.

Metadata Update from @rpattath:
- Issue set to the milestone: 10.3.6

Feb 27, 2017

dmoluguw commented Oct 4, 2020

Dogtag PKI is moving from Pagure issues to GitHub issues. This means that existing or new
issues will be reported and tracked through Dogtag PKI's GitHub Issue tracker.

This issue has been cloned to GitHub and is available here:
https://github.com/dogtagpki/pki/issues/2623

If you want to receive further updates on the issue, please navigate to the
GitHub issue and click on Subscribe button.

Thank you for understanding, and we apologize for any inconvenience.

Metadata

Assignee

None

Tags

None

Blocking

None

Depending on

None

Priority

Normal

type

defect

component

TPS

rhbz

https://bugzilla.redhat.com/show_bug.cgi?id=1382077

origin

version

None

feature

None

proposedpriority

None

proposedmilestone

None

reviewer

None

dogtagpki

#2503 Smartcard token key changeover with externalReg enabled fails during rollback Closed: Invalid Opened Oct 6, 2016 by rpattath.

Metadata

#2503 Smartcard token key changeover with externalReg enabled fails during rollback

Closed: Invalid Opened Oct 6, 2016 by rpattath.