You might want to play with changing "false" to "true in the CS.cfg for op.enroll.userKey.update.applet.emptyToken.enable=false or the op.format... equivalent , etc. /From: Julius Adewumi/ /(a)GDC4S.com/ /Ph:480-441-6768/ /Contract Corp:MTSI/ ------------------------------------------------------------------------ *From:* pki-users-bounces(a)redhat.com [mailto:pki-users-bounces@redhat.com] *On Behalf Of *Zach Casper *Sent:* Tuesday, December 23, 2008 12:00 PM *To:* pki-users(a)redhat.com *Subject:* RE: [Pki-users] ESC Format / Enroll Error Tps-debug log shows the following: RA_Format_Processor::Process – applet upgrade failed Tps-error log show the following: RA_Processor::SetupSecureChannel – Failed to create a secure channel 0- potentially due to an RA/TKS key mismatch or differing RA/TKS key versions. RA_Processor::UpgradeApplet -0 channel create failure And a series of Bad Response when trying to SelectApplet or GetStatus zach _____________________________________________ *From:* Jack Magne [mailto:jmagne@redhat.com] *Sent:* Tuesday, December 23, 2008 1:10 PM *To:* Zach Casper *Subject:* Re: [Pki-users] ESC Format / Enroll Error The first step would be to take a look at the tps log or smart card server. These can be found at: /var/lib/pki-tps/logs/tps-debug.log Search the bottom of the log for error 19 and it should give you an idea of what TPS was trying to do at the time. Zach Casper wrote: > > We have an Infineon Smart Card and currently we are unable to > Format/Enroll due to the following ESC Error > > “Formatting of smart card failed. Error: The Smart Card Server cannot > upgrade the software on your smart card.” > > And Diagnostics show this error: > > “Attempting to Format Key, ID: ####### - Key Format failure, Error: 19.” > > This card comes up as “Formatted” because we’ve manually installed a > version of the Dogtag applet prior to using ESC & Dogtag. > > Any advice on how we can troubleshoot? > > -- > > Zach Casper > > Envieta LLC > > ---------------------------------------- > > ------------------------------------------------------------------------ > > _______________________________________________ > Pki-users mailing list > Pki-users(a)redhat.com > https://www.redhat.com/mailman/listinfo/pki-users > ------------------------------------------------------------------------ _______________________________________________ Pki-users mailing list Pki-users(a)redhat.com https://www.redhat.com/mailman/listinfo/pki-users

tps-error.log ... [2008-12-23 12:09:39] ba5de4e0 RA_Processor::SetupSecureChannel - Failed to create a secure channel - potentially due to an RA/TKS key mismatch or differing RA/TKS key versions. [2008-12-23 12:09:39] ba5de4e0 RA_Processor::UpgradeApplet - channel creation failure [2008-12-23 12:10:20] ba5cb398 RA_Processor::SetupSecureChannel - Failed to create a secure channel - potentially due to an RA/TKS key mismatch or differing RA/TKS key versions. [2008-12-23 12:10:20] ba5cb398 RA_Processor::UpgradeApplet - channel creation failure [2008-12-23 12:11:14] b8e04520 RA_Processor::SetupSecureChannel - Failed to create a secure channel - potentially due to an RA/TKS key mismatch or differing RA/TKS key versions. [2008-12-23 12:11:14] b8e04520 RA_Processor::UpgradeApplet - channel creation failure [2008-12-23 12:39:38] ba5c00e0 RA_Processor::SetupSecureChannel - Failed to create a secure channel - potentially due to an RA/TKS key mismatch or differing RA/TKS key versions. [2008-12-23 12:39:38] ba5c00e0 RA_Processor::UpgradeApplet - channel creation failure [2008-12-23 12:44:27] ba5b14c8 RA_Processor::SetupSecureChannel - Failed to create a secure channel - potentially due to an RA/TKS key mismatch or differing RA/TKS key versions. [2008-12-23 12:44:27] ba5b14c8 RA_Processor::UpgradeApplet - channel creation failure [2008-12-23 12:45:54] ba5f2590 RA_Processor::SetupSecureChannel - Failed to create a secure channel - potentially due to an RA/TKS key mismatch or differing RA/TKS key versions. [2008-12-23 12:45:54] ba5f2590 RA_Processor::UpgradeApplet - channel creation failure tps-debug.log ... [2008-12-23 12:45:54] ba5f2590 RA_Format_Processor::Process - Authenticate returns: 0 [2008-12-23 12:45:54] ba5f2590 AP_Session::WriteMsg - Sent 's=67&msg_type=14&current_state=10&next_task_name=PROGRESS_APPLET_UPGRADE' [2008-12-23 12:45:54] ba5f2590 RA_Processor::UpgradeApplet - path = /usr/share/pki/tps/applets/1.3.44724DDE.ijc [2008-12-23 12:45:54] ba5f2590 AP_Session::WriteMsg - pdu_len='12' [2008-12-23 12:45:54] ba5f2590 AP_Session::WriteMsg - Sent 's=68&msg_type=9&pdu_size=12&pdu_data=%00%A4%04%00%07%A0%00%00%00%03%00%00' [2008-12-23 12:45:54] ba5f2590 AP_Session::ReadMsg - decoded pdu = (length='20') [2008-12-23 12:45:54] ba5f2590 AP_Session::ReadMsg - 6f 10 84 08 a0 00 00 00 03 00 [2008-12-23 12:45:54] ba5f2590 AP_Session::ReadMsg - 00 00 a5 04 9f 65 01 ff 90 00 [2008-12-23 12:45:54] ba5f2590 AP_Session::ReadMsg - [2008-12-23 12:45:54] ba5f2590 AP_Session::WriteMsg - pdu_len='13' [2008-12-23 12:45:54] ba5f2590 AP_Session::WriteMsg - Sent 's=71&msg_type=9&pdu_size=13&pdu_data=%80%50%01%01%08%56%F5%29%9D%7B%8F%6F%A7' [2008-12-23 12:45:54] ba5f2590 AP_Session::ReadMsg - decoded pdu = (length='2') [2008-12-23 12:45:54] ba5f2590 AP_Session::ReadMsg - 6a 86 [2008-12-23 12:45:54] ba5f2590 RA_Format_Processor::Process - applet upgrade failed [2008-12-23 12:45:54] ba5f2590 AP_Session::WriteMsg - pdu_len='12' [2008-12-23 12:45:54] ba5f2590 AP_Session::WriteMsg - Sent 's=68&msg_type=9&pdu_size=12&pdu_data=%00%A4%04%00%07%62%76%01%FF%00%00%00' [2008-12-23 12:45:54] ba5f2590 AP_Session::ReadMsg - decoded pdu = (length='2') [2008-12-23 12:45:54] ba5f2590 AP_Session::ReadMsg - 90 00 [2008-12-23 12:45:54] ba5f2590 AP_Session::WriteMsg - Sent 's=43&msg_type=13&operation=5&result=1&message=19' zach _____________________________________________ *From:* Jack Magne [mailto:jmagne@redhat.com] *Sent:* Tuesday, December 23, 2008 2:38 PM *To:* Adewumi, Julius-p99373 *Cc:* Zach Casper; pki-users(a)redhat.com *Subject:* Re: [Pki-users] ESC Format / Enroll Error You are having a problem creating a secure channel. Perhaps posting a snippet of the log might help. Adewumi, Julius-p99373 wrote: > You might want to play with changing "false" to "true in the CS.cfg for > op.enroll.userKey.update.applet.emptyToken.enable=false or the > op.format... equivalent , etc. > > /From: Julius Adewumi/ > /(a)GDC4S.com/ > /Ph:480-441-6768/ > /Contract Corp:MTSI/ > > > ------------------------------------------------------------------------ > *From:* pki-users-bounces(a)redhat.com > [mailto:pki-users-bounces@redhat.com] *On Behalf Of *Zach Casper > *Sent:* Tuesday, December 23, 2008 12:00 PM > *To:* pki-users(a)redhat.com > *Subject:* RE: [Pki-users] ESC Format / Enroll Error > > Tps-debug log shows the following: > > RA_Format_Processor::Process – applet upgrade failed > > Tps-error log show the following: > > RA_Processor::SetupSecureChannel – Failed to create a secure channel > 0- potentially due to an RA/TKS key mismatch or differing RA/TKS key > versions. > > RA_Processor::UpgradeApplet -0 channel create failure > > And a series of Bad Response when trying to SelectApplet or GetStatus > > zach > > _____________________________________________ > *From:* Jack Magne [mailto:jmagne@redhat.com] > *Sent:* Tuesday, December 23, 2008 1:10 PM > *To:* Zach Casper > *Subject:* Re: [Pki-users] ESC Format / Enroll Error > > The first step would be to take a look at the tps log or smart card > server. > > These can be found at: > > /var/lib/pki-tps/logs/tps-debug.log > > Search the bottom of the log for error 19 and it should give you an idea > > of what TPS was trying to do at the time. > > Zach Casper wrote: > > > > > > We have an Infineon Smart Card and currently we are unable to > > > Format/Enroll due to the following ESC Error > > > > > > “Formatting of smart card failed. Error: The Smart Card Server cannot > > > upgrade the software on your smart card.” > > > > > > And Diagnostics show this error: > > > > > > “Attempting to Format Key, ID: ####### - Key Format failure, Error: 19.” > > > > > > This card comes up as “Formatted” because we’ve manually installed a > > > version of the Dogtag applet prior to using ESC & Dogtag. > > > > > > Any advice on how we can troubleshoot? > > > > > > -- > > > > > > Zach Casper > > > > > > Envieta LLC > > > > > > ---------------------------------------- > > > > > > ------------------------------------------------------------------------ > > > > > > _______________________________________________ > > > Pki-users mailing list > > > Pki-users(a)redhat.com > > > https://www.redhat.com/mailman/listinfo/pki-users > > > > > ------------------------------------------------------------------------ > > _______________________________________________ > Pki-users mailing list > Pki-users(a)redhat.com > https://www.redhat.com/mailman/listinfo/pki-users > ------------------------------------------------------------------------ _______________________________________________ Pki-users mailing list Pki-users(a)redhat.com https://www.redhat.com/mailman/listinfo/pki-users

Could there be an issue with the default key our card is loaded with (VISA Key) not being able to create the secure connection? What are the default key(s) used/needed by Dogtag? _____________________________________________ *From:* Jack Magne [mailto:jmagne@redhat.com] *Sent:* Tuesday, December 23, 2008 5:35 PM *To:* Zach Casper *Cc:* pki-users(a)redhat.com *Subject:* Re: [Pki-users] ESC Format / Enroll Error I'll have to take a closer look later but there is a quick thing you can try. Also, remember depending upon your card, if you make too many failed attempts at a secure channel, the card can lock itself up. In /var/lib/pki-tps/conf/CS.cfg you will have a block like this: channel.defKeyVersion=1 channel. defKeyIndex=1 We have experimented with some other cards where the following works: channel.defKeyVersion=0 channel.defKeyIndex=0 Zach Casper wrote: > > tps-error.log > ... > [2008-12-23 12:09:39] ba5de4e0 RA_Processor::SetupSecureChannel - > Failed to create a secure channel - potentially due to an RA/TKS key > mismatch or differing RA/TKS key versions. > [2008-12-23 12:09:39] ba5de4e0 RA_Processor::UpgradeApplet - channel > creation failure > [2008-12-23 12:10:20] ba5cb398 RA_Processor::SetupSecureChannel - > Failed to create a secure channel - potentially due to an RA/TKS key > mismatch or differing RA/TKS key versions. > [2008-12-23 12:10:20] ba5cb398 RA_Processor::UpgradeApplet - channel > creation failure > [2008-12-23 12:11:14] b8e04520 RA_Processor::SetupSecureChannel - > Failed to create a secure channel - potentially due to an RA/TKS key > mismatch or differing RA/TKS key versions. > [2008-12-23 12:11:14] b8e04520 RA_Processor::UpgradeApplet - channel > creation failure > [2008-12-23 12:39:38] ba5c00e0 RA_Processor::SetupSecureChannel - > Failed to create a secure channel - potentially due to an RA/TKS key > mismatch or differing RA/TKS key versions. > [2008-12-23 12:39:38] ba5c00e0 RA_Processor::UpgradeApplet - channel > creation failure > [2008-12-23 12:44:27] ba5b14c8 RA_Processor::SetupSecureChannel - > Failed to create a secure channel - potentially due to an RA/TKS key > mismatch or differing RA/TKS key versions. > [2008-12-23 12:44:27] ba5b14c8 RA_Processor::UpgradeApplet - channel > creation failure > [2008-12-23 12:45:54] ba5f2590 RA_Processor::SetupSecureChannel - > Failed to create a secure channel - potentially due to an RA/TKS key > mismatch or differing RA/TKS key versions. > [2008-12-23 12:45:54] ba5f2590 RA_Processor::UpgradeApplet - channel > creation failure > > tps-debug.log > ... > [2008-12-23 12:45:54] ba5f2590 RA_Format_Processor::Process - > Authenticate returns: 0 > [2008-12-23 12:45:54] ba5f2590 AP_Session::WriteMsg - Sent > 's=67&msg_type=14&current_state=10&next_task_name=PROGRESS_APPLET_UPGRADE' > [2008-12-23 12:45:54] ba5f2590 RA_Processor::UpgradeApplet - path = > /usr/share/pki/tps/applets/1.3.44724DDE.ijc > [2008-12-23 12:45:54] ba5f2590 AP_Session::WriteMsg - pdu_len='12' > [2008-12-23 12:45:54] ba5f2590 AP_Session::WriteMsg - Sent > 's=68&msg_type=9&pdu_size=12&pdu_data=%00%A4%04%00%07%A0%00%00%00%03%00%00' > [2008-12-23 12:45:54] ba5f2590 AP_Session::ReadMsg - decoded pdu = > (length='20') > [2008-12-23 12:45:54] ba5f2590 AP_Session::ReadMsg - 6f 10 84 08 a0 00 > 00 00 03 00 > [2008-12-23 12:45:54] ba5f2590 AP_Session::ReadMsg - 00 00 a5 04 9f 65 > 01 ff 90 00 > [2008-12-23 12:45:54] ba5f2590 AP_Session::ReadMsg - > [2008-12-23 12:45:54] ba5f2590 AP_Session::WriteMsg - pdu_len='13' > [2008-12-23 12:45:54] ba5f2590 AP_Session::WriteMsg - Sent > 's=71&msg_type=9&pdu_size=13&pdu_data=%80%50%01%01%08%56%F5%29%9D%7B%8F%6F%A7' > [2008-12-23 12:45:54] ba5f2590 AP_Session::ReadMsg - decoded pdu = > (length='2') > [2008-12-23 12:45:54] ba5f2590 AP_Session::ReadMsg - 6a 86 > [2008-12-23 12:45:54] ba5f2590 RA_Format_Processor::Process - applet > upgrade failed > [2008-12-23 12:45:54] ba5f2590 AP_Session::WriteMsg - pdu_len='12' > [2008-12-23 12:45:54] ba5f2590 AP_Session::WriteMsg - Sent > 's=68&msg_type=9&pdu_size=12&pdu_data=%00%A4%04%00%07%62%76%01%FF%00%00%00' > [2008-12-23 12:45:54] ba5f2590 AP_Session::ReadMsg - decoded pdu = > (length='2') > [2008-12-23 12:45:54] ba5f2590 AP_Session::ReadMsg - 90 00 > [2008-12-23 12:45:54] ba5f2590 AP_Session::WriteMsg - Sent > 's=43&msg_type=13&operation=5&result=1&message=19' > > zach > > _____________________________________________ > *From:* Jack Magne [mailto:jmagne@redhat.com] > *Sent:* Tuesday, December 23, 2008 2:38 PM > *To:* Adewumi, Julius-p99373 > *Cc:* Zach Casper; pki-users(a)redhat.com > *Subject:* Re: [Pki-users] ESC Format / Enroll Error > > You are having a problem creating a secure channel. Perhaps posting a > > snippet of the log might help. > > > > Adewumi, Julius-p99373 wrote: > > > You might want to play with changing "false" to "true in the CS.cfg for > > > op.enroll.userKey.update.applet.emptyToken.enable=false or the > > > op.format... equivalent , etc. > > > > > > /From: Julius Adewumi/ > > > /(a)GDC4S.com/ > > > /Ph:480-441-6768/ > > > /Contract Corp:MTSI/ > > > > > > > > > ------------------------------------------------------------------------ > > > *From:* pki-users-bounces(a)redhat.com > > > [mailto:pki-users-bounces@redhat.com] *On Behalf Of *Zach Casper > > > *Sent:* Tuesday, December 23, 2008 12:00 PM > > > *To:* pki-users(a)redhat.com > > > *Subject:* RE: [Pki-users] ESC Format / Enroll Error > > > > > > Tps-debug log shows the following: > > > > > > RA_Format_Processor::Process – applet upgrade failed > > > > > > Tps-error log show the following: > > > > > > RA_Processor::SetupSecureChannel – Failed to create a secure channel > > > 0- potentially due to an RA/TKS key mismatch or differing RA/TKS key > > > versions. > > > > > > RA_Processor::UpgradeApplet -0 channel create failure > > > > > > And a series of Bad Response when trying to SelectApplet or GetStatus > > > > > > zach > > > > > > _____________________________________________ > > > *From:* Jack Magne [mailto:jmagne@redhat.com] > > > *Sent:* Tuesday, December 23, 2008 1:10 PM > > > *To:* Zach Casper > > > *Subject:* Re: [Pki-users] ESC Format / Enroll Error > > > > > > The first step would be to take a look at the tps log or smart card > > > server. > > > > > > These can be found at: > > > > > > /var/lib/pki-tps/logs/tps-debug.log > > > > > > Search the bottom of the log for error 19 and it should give you an idea > > > > > > of what TPS was trying to do at the time. > > > > > > Zach Casper wrote: > > > > > > > > > > > > > > We have an Infineon Smart Card and currently we are unable to > > > > > > > Format/Enroll due to the following ESC Error > > > > > > > > > > > > > > “Formatting of smart card failed. Error: The Smart Card Server cannot > > > > > > > upgrade the software on your smart card.” > > > > > > > > > > > > > > And Diagnostics show this error: > > > > > > > > > > > > > > “Attempting to Format Key, ID: ####### - Key Format failure, Error: > 19.” > > > > > > > > > > > > > > This card comes up as “Formatted” because we’ve manually installed a > > > > > > > version of the Dogtag applet prior to using ESC & Dogtag. > > > > > > > > > > > > > > Any advice on how we can troubleshoot? > > > > > > > > > > > > > > -- > > > > > > > > > > > > > > Zach Casper > > > > > > > > > > > > > > Envieta LLC > > > > > > > > > > > > > > ---------------------------------------- > > > > > > > > > > > > > > > ------------------------------------------------------------------------ > > > > > > > > > > > > > > _______________________________________________ > > > > > > > Pki-users mailing list > > > > > > > Pki-users(a)redhat.com > > > > > > > https://www.redhat.com/mailman/listinfo/pki-users > > > > > > > > > > > > > ------------------------------------------------------------------------ > > > > > > _______________________________________________ > > > Pki-users mailing list > > > Pki-users(a)redhat.com > > > https://www.redhat.com/mailman/listinfo/pki-users > > > > > ------------------------------------------------------------------------ > > _______________________________________________ > Pki-users mailing list > Pki-users(a)redhat.com > https://www.redhat.com/mailman/listinfo/pki-users >

Thanks Jack. It appears we are using the same keys so on to troubleshooting our error logs. Below are our current logs file contents. When we use the default values: channel.defKeyVersion=1 channel. defKeyIndex=1 Ther error we get is: [2009-01-07 11:05:07] ba6ec600 LDAP_Authentication::Authenticate - User bind required 'uid=testuser1,ou=People,dc=localdomain' 'envieta123' [2009-01-07 11:05:07] ba6ec600 LDAP_Authentication::Authenticate - Attributes mail,cn,uid [2009-01-07 11:05:07] ba6ec600 LDAP_Authentication::Authenticate - Exposed cn=Test User1 [2009-01-07 11:05:07] ba6ec600 LDAP_Authentication::Authenticate - Size 3 [2009-01-07 11:05:07] ba6ec600 LDAP_Authentication::Authenticate - Exposed uid=testuser1 [2009-01-07 11:05:07] ba6ec600 LDAP_Authentication::Authenticate - Size 4 [2009-01-07 11:05:07] ba6ec600 RA_Format_Processor::Process - Authenticate returns: 0 [2009-01-07 11:05:07] ba6ec600 AP_Session::WriteMsg - Sent 's=67&msg_type=14&current_state=10&next_task_name=PROGRESS_APPLET_UPGRADE' [2009-01-07 11:05:07] ba6ec600 RA_Processor::UpgradeApplet - path = /usr/share/pki/tps/applets/1.3.44724DDE.ijc [2009-01-07 11:05:07] ba6ec600 AP_Session::WriteMsg - pdu_len='12' [2009-01-07 11:05:07] ba6ec600 AP_Session::WriteMsg - Sent 's=68&msg_type=9&pdu_size=12&pdu_data=%00%A4%04%00%07%A0%00%00%00%03%00%00' [2009-01-07 11:05:07] ba6ec600 AP_Session::ReadMsg - decoded pdu = (length='20') [2009-01-07 11:05:07] ba6ec600 AP_Session::ReadMsg - 6f 10 84 08 a0 00 00 00 03 00 [2009-01-07 11:05:07] ba6ec600 AP_Session::ReadMsg - 00 00 a5 04 9f 65 01 ff 90 00 [2009-01-07 11:05:07] ba6ec600 AP_Session::ReadMsg - [2009-01-07 11:05:07] ba6ec600 AP_Session::WriteMsg - pdu_len='13' [2009-01-07 11:05:07] ba6ec600 AP_Session::WriteMsg - Sent 's=71&msg_type=9&pdu_size=13&pdu_data=%80%50%01%01%08%09%CD%60%A7%11%EC%23%A5' [2009-01-07 11:05:08] ba6ec600 AP_Session::ReadMsg - decoded pdu = (length='2') [2009-01-07 11:05:08] ba6ec600 AP_Session::ReadMsg - 6a 86 [2009-01-07 11:05:08] ba6ec600 RA_Format_Processor::Process - applet upgrade failed [2009-01-07 11:05:08] ba6ec600 AP_Session::WriteMsg - pdu_len='12' [2009-01-07 11:05:08] ba6ec600 AP_Session::WriteMsg - Sent 's=68&msg_type=9&pdu_size=12&pdu_data=%00%A4%04%00%07%62%76%01%FF%00%00%00' [2009-01-07 11:05:08] ba6ec600 AP_Session::ReadMsg - decoded pdu = (length='2') [2009-01-07 11:05:08] ba6ec600 AP_Session::ReadMsg - 90 00 [2009-01-07 11:05:08] ba6ec600 AP_Session::WriteMsg - Sent 's=43&msg_type=13&operation=5&result=1&message=19' When we switch the values to be: channel.defKeyVersion=0 channel. defKeyIndex=0 The error now looks like this: [2009-01-07 11:20:41] bacd2d28 LDAP_Authentication::Authenticate - User bind required 'uid=testuser1,ou=People,dc=localdomain' 'envieta123' [2009-01-07 11:20:41] bacd2d28 LDAP_Authentication::Authenticate - Attributes mail,cn,uid [2009-01-07 11:20:41] bacd2d28 LDAP_Authentication::Authenticate - Exposed cn=Test User1 [2009-01-07 11:20:41] bacd2d28 LDAP_Authentication::Authenticate - Size 3 [2009-01-07 11:20:41] bacd2d28 LDAP_Authentication::Authenticate - Exposed uid=testuser1 [2009-01-07 11:20:41] bacd2d28 LDAP_Authentication::Authenticate - Size 4 [2009-01-07 11:20:41] bacd2d28 RA_Format_Processor::Process - Authenticate returns: 0 [2009-01-07 11:20:41] bacd2d28 AP_Session::WriteMsg - Sent 's=67&msg_type=14&current_state=10&next_task_name=PROGRESS_APPLET_UPGRADE' [2009-01-07 11:20:41] bacd2d28 RA_Processor::UpgradeApplet - path = /usr/share/pki/tps/applets/1.3.44724DDE.ijc [2009-01-07 11:20:41] bacd2d28 AP_Session::WriteMsg - pdu_len='12' [2009-01-07 11:20:41] bacd2d28 AP_Session::WriteMsg - Sent 's=68&msg_type=9&pdu_size=12&pdu_data=%00%A4%04%00%07%A0%00%00%00%03%00%00' [2009-01-07 11:20:41] bacd2d28 AP_Session::ReadMsg - decoded pdu = (length='20') [2009-01-07 11:20:41] bacd2d28 AP_Session::ReadMsg - 6f 10 84 08 a0 00 00 00 03 00 [2009-01-07 11:20:41] bacd2d28 AP_Session::ReadMsg - 00 00 a5 04 9f 65 01 ff 90 00 [2009-01-07 11:20:41] bacd2d28 AP_Session::ReadMsg - [2009-01-07 11:20:41] bacd2d28 AP_Session::WriteMsg - pdu_len='13' [2009-01-07 11:20:41] bacd2d28 AP_Session::WriteMsg - Sent 's=71&msg_type=9&pdu_size=13&pdu_data=%80%50%00%00%08%95%74%0B%AC%37%C9%DE%80' [2009-01-07 11:20:41] bacd2d28 AP_Session::ReadMsg - decoded pdu = (length='30') [2009-01-07 11:20:41] bacd2d28 AP_Session::ReadMsg - 00 00 71 61 57 01 0e 0d 90 bd [2009-01-07 11:20:41] bacd2d28 AP_Session::ReadMsg - ff 02 00 21 2e 6b ec 9e 33 2b [2009-01-07 11:20:41] bacd2d28 AP_Session::ReadMsg - a5 26 d0 02 e6 64 c9 3c 90 00 [2009-01-07 11:20:41] bacd2d28 AP_Session::ReadMsg - [2009-01-07 11:20:41] bacd2d28 HttpConnection::getResponse - Send request to host localhost.localdomain:13443 servlet /tks/agent/tks/computeSessionKey [2009-01-07 11:20:42] bacd2d28 RA::Engine - Pre-processing content 'HTTP/1.1 200 OK Server: Apache-Coyote/1.1 Content-Type: text/html Content-Length: 8 Date: Wed, 07 Jan 2009 16:20:42 GMT status=3 [2009-01-07 11:20:42] bacd2d28 RA::Engine - Post-processing content 'status=3 [2009-01-07 11:20:42] bacd2d28 RA_Format_Processor::Process - applet upgrade failed [2009-01-07 11:20:42] bacd2d28 AP_Session::WriteMsg - pdu_len='12' [2009-01-07 11:20:42] bacd2d28 AP_Session::WriteMsg - Sent 's=68&msg_type=9&pdu_size=12&pdu_data=%00%A4%04%00%07%62%76%01%FF%00%00%00' [2009-01-07 11:20:42] bacd2d28 AP_Session::ReadMsg - decoded pdu = (length='2') [2009-01-07 11:20:42] bacd2d28 AP_Session::ReadMsg - 90 00 [2009-01-07 11:20:42] bacd2d28 AP_Session::WriteMsg - Sent 's=43&msg_type=13&operation=5&result=1&message=19' In addition – the following is the pki-tps…tps-error.log snippet [2008-12-23 12:09:39] ba5de4e0 RA_Processor::SetupSecureChannel - Failed to create a secure channel - potentially due to an RA/TKS key mismatch or differing RA/TKS key versions. [2008-12-23 12:09:39] ba5de4e0 RA_Processor::UpgradeApplet - channel creation failure [2008-12-23 12:10:20] ba5cb398 RA_Processor::SetupSecureChannel - Failed to create a secure channel - potentially due to an RA/TKS key mismatch or differing RA/TKS key versions. [2008-12-23 12:10:20] ba5cb398 RA_Processor::UpgradeApplet - channel creation failure [2008-12-23 12:11:14] b8e04520 RA_Processor::SetupSecureChannel - Failed to create a secure channel - potentially due to an RA/TKS key mismatch or differing RA/TKS key versions. [2008-12-23 12:11:14] b8e04520 RA_Processor::UpgradeApplet - channel creation failure [2008-12-23 12:39:38] ba5c00e0 RA_Processor::SetupSecureChannel - Failed to create a secure channel - potentially due to an RA/TKS key mismatch or differing RA/TKS key versions. [2008-12-23 12:39:38] ba5c00e0 RA_Processor::UpgradeApplet - channel creation failure [2008-12-23 12:44:27] ba5b14c8 RA_Processor::SetupSecureChannel - Failed to create a secure channel - potentially due to an RA/TKS key mismatch or differing RA/TKS key versions. [2008-12-23 12:44:27] ba5b14c8 RA_Processor::UpgradeApplet - channel creation failure [2008-12-23 12:45:54] ba5f2590 RA_Processor::SetupSecureChannel - Failed to create a secure channel - potentially due to an RA/TKS key mismatch or differing RA/TKS key versions. [2008-12-23 12:45:54] ba5f2590 RA_Processor::UpgradeApplet - channel creation failure I’m also bringing John Whitelock, another one of our engineers in on discussions. He just joined the pki-users list. Zach Casper _____________________________________________ *From:* Jack Magne [mailto:jmagne@redhat.com] *Sent:* Wednesday, January 07, 2009 1:09 PM *To:* Zach Casper *Cc:* pki-users(a)redhat.com *Subject:* Re: [Pki-users] ESC Format / Enroll Error Zach: Sorry for the delay.... The default developer keyset we use for our keys with TPS is the standard like follows: tks.defKeySet.auth_key=#40#41...#4f tks.defKeySet.kek_key=#40#41...#4f tks.defKeySet.mac_key=#40#41.. #4f If you look in the CS.cfg file under /var/lib/pki-tks/conf We have an entire procedure documented in the CS 7.3 documentation to perform a key changeover if required. Feel free to post any further logs you might obtain after further testing. thanks, jack Zach Casper wrote: > > Could there be an issue with the default key our card is loaded with > (VISA Key) not being able to create the secure connection? What are > the default key(s) used/needed by Dogtag? > > _____________________________________________ > *From:* Jack Magne [mailto:jmagne@redhat.com] > *Sent:* Tuesday, December 23, 2008 5:35 PM > *To:* Zach Casper > *Cc:* pki-users(a)redhat.com > *Subject:* Re: [Pki-users] ESC Format / Enroll Error > > I'll have to take a closer look later but there is a quick thing you can > > try. > > Also, remember depending upon your card, if you make too many failed > > attempts at a secure channel, the card can lock itself up. > > In /var/lib/pki-tps/conf/CS.cfg you will have a block like this: > > channel.defKeyVersion=1 > > channel. defKeyIndex=1 > > We have experimented with some other cards where the following works: > > channel.defKeyVersion=0 > > channel.defKeyIndex=0 > > Zach Casper wrote: > > > > > > tps-error.log > > > ... > > > [2008-12-23 12:09:39] ba5de4e0 RA_Processor::SetupSecureChannel - > > > Failed to create a secure channel - potentially due to an RA/TKS key > > > mismatch or differing RA/TKS key versions. > > > [2008-12-23 12:09:39] ba5de4e0 RA_Processor::UpgradeApplet - channel > > > creation failure > > > [2008-12-23 12:10:20] ba5cb398 RA_Processor::SetupSecureChannel - > > > Failed to create a secure channel - potentially due to an RA/TKS key > > > mismatch or differing RA/TKS key versions. > > > [2008-12-23 12:10:20] ba5cb398 RA_Processor::UpgradeApplet - channel > > > creation failure > > > [2008-12-23 12:11:14] b8e04520 RA_Processor::SetupSecureChannel - > > > Failed to create a secure channel - potentially due to an RA/TKS key > > > mismatch or differing RA/TKS key versions. > > > [2008-12-23 12:11:14] b8e04520 RA_Processor::UpgradeApplet - channel > > > creation failure > > > [2008-12-23 12:39:38] ba5c00e0 RA_Processor::SetupSecureChannel - > > > Failed to create a secure channel - potentially due to an RA/TKS key > > > mismatch or differing RA/TKS key versions. > > > [2008-12-23 12:39:38] ba5c00e0 RA_Processor::UpgradeApplet - channel > > > creation failure > > > [2008-12-23 12:44:27] ba5b14c8 RA_Processor::SetupSecureChannel - > > > Failed to create a secure channel - potentially due to an RA/TKS key > > > mismatch or differing RA/TKS key versions. > > > [2008-12-23 12:44:27] ba5b14c8 RA_Processor::UpgradeApplet - channel > > > creation failure > > > [2008-12-23 12:45:54] ba5f2590 RA_Processor::SetupSecureChannel - > > > Failed to create a secure channel - potentially due to an RA/TKS key > > > mismatch or differing RA/TKS key versions. > > > [2008-12-23 12:45:54] ba5f2590 RA_Processor::UpgradeApplet - channel > > > creation failure > > > > > > tps-debug.log > > > ... > > > [2008-12-23 12:45:54] ba5f2590 RA_Format_Processor::Process - > > > Authenticate returns: 0 > > > [2008-12-23 12:45:54] ba5f2590 AP_Session::WriteMsg - Sent > > > 's=67&msg_type=14&current_state=10&next_task_name=PROGRESS_APPLET_UPGRADE' > > > [2008-12-23 12:45:54] ba5f2590 RA_Processor::UpgradeApplet - path = > > > /usr/share/pki/tps/applets/1.3.44724DDE.ijc > > > [2008-12-23 12:45:54] ba5f2590 AP_Session::WriteMsg - pdu_len='12' > > > [2008-12-23 12:45:54] ba5f2590 AP_Session::WriteMsg - Sent > > > 's=68&msg_type=9&pdu_size=12&pdu_data=%00%A4%04%00%07%A0%00%00%00%03%00%00' > > > [2008-12-23 12:45:54] ba5f2590 AP_Session::ReadMsg - decoded pdu = > > > (length='20') > > > [2008-12-23 12:45:54] ba5f2590 AP_Session::ReadMsg - 6f 10 84 08 a0 00 > > > 00 00 03 00 > > > [2008-12-23 12:45:54] ba5f2590 AP_Session::ReadMsg - 00 00 a5 04 9f 65 > > > 01 ff 90 00 > > > [2008-12-23 12:45:54] ba5f2590 AP_Session::ReadMsg - > > > [2008-12-23 12:45:54] ba5f2590 AP_Session::WriteMsg - pdu_len='13' > > > [2008-12-23 12:45:54] ba5f2590 AP_Session::WriteMsg - Sent > > > 's=71&msg_type=9&pdu_size=13&pdu_data=%80%50%01%01%08%56%F5%29%9D%7B%8F%6F%A7' > > > [2008-12-23 12:45:54] ba5f2590 AP_Session::ReadMsg - decoded pdu = > > > (length='2') > > > [2008-12-23 12:45:54] ba5f2590 AP_Session::ReadMsg - 6a 86 > > > [2008-12-23 12:45:54] ba5f2590 RA_Format_Processor::Process - applet > > > upgrade failed > > > [2008-12-23 12:45:54] ba5f2590 AP_Session::WriteMsg - pdu_len='12' > > > [2008-12-23 12:45:54] ba5f2590 AP_Session::WriteMsg - Sent > > > 's=68&msg_type=9&pdu_size=12&pdu_data=%00%A4%04%00%07%62%76%01%FF%00%00%00' > > > [2008-12-23 12:45:54] ba5f2590 AP_Session::ReadMsg - decoded pdu = > > > (length='2') > > > [2008-12-23 12:45:54] ba5f2590 AP_Session::ReadMsg - 90 00 > > > [2008-12-23 12:45:54] ba5f2590 AP_Session::WriteMsg - Sent > > > 's=43&msg_type=13&operation=5&result=1&message=19' > > > > > > zach > > > > > > _____________________________________________ > > > *From:* Jack Magne [mailto:jmagne@redhat.com] > > > *Sent:* Tuesday, December 23, 2008 2:38 PM > > > *To:* Adewumi, Julius-p99373 > > > *Cc:* Zach Casper; pki-users(a)redhat.com > > > *Subject:* Re: [Pki-users] ESC Format / Enroll Error > > > > > > You are having a problem creating a secure channel. Perhaps posting a > > > > > > snippet of the log might help. > > > > > > > > > > > > Adewumi, Julius-p99373 wrote: > > > > > > > You might want to play with changing "false" to "true in the CS.cfg for > > > > > > > op.enroll.userKey.update.applet.emptyToken.enable=false or the > > > > > > > op.format... equivalent , etc. > > > > > > > > > > > > > > /From: Julius Adewumi/ > > > > > > > /(a)GDC4S.com/ > > > > > > > /Ph:480-441-6768/ > > > > > > > /Contract Corp:MTSI/ > > > > > > > > > > > > > > > > > > > > > > ------------------------------------------------------------------------ > > > > > > > *From:* pki-users-bounces(a)redhat.com > > > > > > > [mailto:pki-users-bounces@redhat.com] *On Behalf Of *Zach Casper > > > > > > > *Sent:* Tuesday, December 23, 2008 12:00 PM > > > > > > > *To:* pki-users(a)redhat.com > > > > > > > *Subject:* RE: [Pki-users] ESC Format / Enroll Error > > > > > > > > > > > > > > Tps-debug log shows the following: > > > > > > > > > > > > > > RA_Format_Processor::Process – applet upgrade failed > > > > > > > > > > > > > > Tps-error log show the following: > > > > > > > > > > > > > > RA_Processor::SetupSecureChannel – Failed to create a secure channel > > > > > > > 0- potentially due to an RA/TKS key mismatch or differing RA/TKS key > > > > > > > versions. > > > > > > > > > > > > > > RA_Processor::UpgradeApplet -0 channel create failure > > > > > > > > > > > > > > And a series of Bad Response when trying to SelectApplet or GetStatus > > > > > > > > > > > > > > zach > > > > > > > > > > > > > > _____________________________________________ > > > > > > > *From:* Jack Magne [mailto:jmagne@redhat.com] > > > > > > > *Sent:* Tuesday, December 23, 2008 1:10 PM > > > > > > > *To:* Zach Casper > > > > > > > *Subject:* Re: [Pki-users] ESC Format / Enroll Error > > > > > > > > > > > > > > The first step would be to take a look at the tps log or smart card > > > > > > > server. > > > > > > > > > > > > > > These can be found at: > > > > > > > > > > > > > > /var/lib/pki-tps/logs/tps-debug.log > > > > > > > > > > > > > > Search the bottom of the log for error 19 and it should give you an > idea > > > > > > > > > > > > > > of what TPS was trying to do at the time. > > > > > > > > > > > > > > Zach Casper wrote: > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > We have an Infineon Smart Card and currently we are unable to > > > > > > > > > > > > > > > Format/Enroll due to the following ESC Error > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > “Formatting of smart card failed. Error: The Smart Card Server cannot > > > > > > > > > > > > > > > upgrade the software on your smart card.” > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > And Diagnostics show this error: > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > “Attempting to Format Key, ID: ####### - Key Format failure, Error: > > > 19.” > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > This card comes up as “Formatted” because we’ve manually installed a > > > > > > > > > > > > > > > version of the Dogtag applet prior to using ESC & Dogtag. > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > Any advice on how we can troubleshoot? > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > -- > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > Zach Casper > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > Envieta LLC > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > ---------------------------------------- > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > ------------------------------------------------------------------------ > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > _______________________________________________ > > > > > > > > > > > > > > > Pki-users mailing list > > > > > > > > > > > > > > > Pki-users(a)redhat.com > > > > > > > > > > > > > > > https://www.redhat.com/mailman/listinfo/pki-users > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > ------------------------------------------------------------------------ > > > > > > > > > > > > > > _______________________________________________ > > > > > > > Pki-users mailing list > > > > > > > Pki-users(a)redhat.com > > > > > > > https://www.redhat.com/mailman/listinfo/pki-users > > > > > > > > > > > > > ------------------------------------------------------------------------ > > > > > > _______________________________________________ > > > Pki-users mailing list > > > Pki-users(a)redhat.com > > > https://www.redhat.com/mailman/listinfo/pki-users > > > >

Jack, Thanks again for the help. Below I have pasted the log you asked for from that same test. [07/Jan/2009:11:20:42][http-13443-Processor25]: Authentication: client certificate found [07/Jan/2009:11:20:42][http-13443-Processor25]: getConn: mNumConns now 2 [07/Jan/2009:11:20:42][http-13443-Processor25]: returnConn: mNumConns now 3 [07/Jan/2009:11:20:42][http-13443-Processor25]: Authentication: mapped certificate to user [07/Jan/2009:11:20:42][http-13443-Processor25]: authenticated uid=TPS-localhost.localdomain-7889,ou=People,dc=localhost.localdomain-pki-tk s [07/Jan/2009:11:20:42][http-13443-Processor25]: SignedAuditEventFactory: create() message=[AuditEvent=AUTH_SUCCESS][SubjectID=TPS-localhost.localdomain-7889][ Outcome=Success][AuthMgr=certUserDBAuthMgr] authentication success [07/Jan/2009:11:20:42][http-13443-Processor25]: checkACLS(): ACLEntry expressions= group="Token Key Service Manager Agents" [07/Jan/2009:11:20:42][http-13443-Processor25]: evaluating expressions: group="Token Key Service Manager Agents" [07/Jan/2009:11:20:42][http-13443-Processor25]: getConn: mNumConns now 2 [07/Jan/2009:11:20:42][http-13443-Processor25]: returnConn: mNumConns now 3 [07/Jan/2009:11:20:42][http-13443-Processor25]: UGSubsystem.isMemberOf() using new lookup code [07/Jan/2009:11:20:42][http-13443-Processor25]: getConn: mNumConns now 2 [07/Jan/2009:11:20:42][http-13443-Processor25]: authorization search base: cn=Token Key Service Manager Agents,ou=groups,dc=localhost.localdomain-pki-tks [07/Jan/2009:11:20:42][http-13443-Processor25]: authorization search filter: (uniquemember=uid=TPS-localhost.localdomain-7889,ou=People,dc=localhost.loca ldomain-pki-tks) [07/Jan/2009:11:20:42][http-13443-Processor25]: authorization result: true [07/Jan/2009:11:20:42][http-13443-Processor25]: returnConn: mNumConns now 3 [07/Jan/2009:11:20:42][http-13443-Processor25]: evaluated expression: group="Token Key Service Manager Agents" to be true [07/Jan/2009:11:20:42][http-13443-Processor25]: DirAclAuthz: authorization passed [07/Jan/2009:11:20:42][http-13443-Processor25]: SignedAuditEventFactory: create() message=[AuditEvent=AUTHZ_SUCCESS][SubjectID=TPS-localhost.localdomain-7889] [Outcome=Success][aclResource=certServer.tks.sessionkey][Op=read] authorization success [07/Jan/2009:11:20:42][http-13443-Processor25]: getConn: mNumConns now 2 [07/Jan/2009:11:20:42][http-13443-Processor25]: returnConn: mNumConns now 3 [07/Jan/2009:11:20:42][http-13443-Processor25]: SignedAuditEventFactory: create() message=[AuditEvent=ROLE_ASSUME][SubjectID=TPS-localhost.localdomain-7889][O utcome=Success][Role=Token Key Service Manager Agents] assume privileged role [07/Jan/2009:11:20:42][http-13443-Processor25]: keySet selected: defKeySet [07/Jan/2009:11:20:42][http-13443-Processor25]: keySet selected: defKeySet [07/Jan/2009:11:20:42][http-13443-Processor25]: processComputeSessionKey: [07/Jan/2009:11:20:42][http-13443-Processor25]: TokenServlet: serversideKeygen requested [07/Jan/2009:11:20:42][http-13443-Processor25]: TokenServlet about to try ComputeSessionKey selectedToken=Internal Key Storage Token keyNickName=#FF#02 [07/Jan/2009:11:20:42][http-13443-Processor25]: TokenServlet:Tried ComputeSessionKey, got NULL java.lang.Exception: Can't compute session key! at com.netscape.cms.servlet.tks.TokenServlet.processComputeSessionKey(TokenServ let.java:336) at com.netscape.cms.servlet.tks.TokenServlet.process(TokenServlet.java:945) at com.netscape.cms.servlet.base.CMSServlet.service(CMSServlet.java:482) at com.netscape.cms.servlet.tks.TokenServlet.service(TokenServlet.java:964) at javax.servlet.http.HttpServlet.service(HttpServlet.java:729) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(Application FilterChain.java:269) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterCh ain.java:188) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.ja va:213) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.ja va:172) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127 ) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:117 ) at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:548) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java :108) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:174) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:875) at org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHandler.processC onnection(Http11BaseProtocol.java:665) at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.jav a:528) at org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWo rkerThread.java:81) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.jav a:689) at java.lang.Thread.run(Thread.java:636) [07/Jan/2009:11:20:42][http-13443-Processor25]: TokenServlet Computing Session Key: java.lang.Exception: Can't compute session key! [07/Jan/2009:11:20:42][http-13443-Processor25]: TokenServlet:outputString.encode status=3 [07/Jan/2009:11:20:42][http-13443-Processor25]: TokenServlet:outputString.length 8 [07/Jan/2009:11:20:42][http-13443-Processor25]: CMSServlet: curDate=Wed Jan 07 11:20:42 GMT-05:00 2009 id=tksSessionKey time=430 -----Original Message----- From: Jack Magne [mailto:jmagne@redhat.com] Sent: Wednesday, January 07, 2009 4:24 PM To: Zach Casper Cc: pki-users(a)redhat.com; 'John Whitelock' Subject: Re: [Pki-users] ESC Format / Enroll Error Zach: It looks like with your second test, you have managed to get by the hurdle of the failed "InitializeUpdate" command. This is due to using 0 and 0 for the defKeyVersion and defKeyIndex. Now it looks like the TKS system is not acting as expected. It would be great to have a look at the TKS debug log found in /var/lib/pki-tks/logs I suspect we are having an issue with computing the session key in the TKS. thanks, jack Zach Casper wrote: > Thanks Jack. > > It appears we are using the same keys so on to troubleshooting our > error logs. Below are our current logs file contents. > > When we use the default values: > > channel.defKeyVersion=1 > > channel. defKeyIndex=1 > > Ther error we get is: > > [2009-01-07 11:05:07] ba6ec600 LDAP_Authentication::Authenticate - > User bind required 'uid=testuser1,ou=People,dc=localdomain' 'envieta123' > > [2009-01-07 11:05:07] ba6ec600 LDAP_Authentication::Authenticate - > Attributes mail,cn,uid > > [2009-01-07 11:05:07] ba6ec600 LDAP_Authentication::Authenticate - > Exposed cn=Test User1 > > [2009-01-07 11:05:07] ba6ec600 LDAP_Authentication::Authenticate - Size 3 > > [2009-01-07 11:05:07] ba6ec600 LDAP_Authentication::Authenticate - > Exposed uid=testuser1 > > [2009-01-07 11:05:07] ba6ec600 LDAP_Authentication::Authenticate - Size 4 > > [2009-01-07 11:05:07] ba6ec600 RA_Format_Processor::Process - > Authenticate returns: 0 > > [2009-01-07 11:05:07] ba6ec600 AP_Session::WriteMsg - Sent > 's=67&msg_type=14&current_state=10&next_task_name=PROGRESS_APPLET_UPGRADE' > > [2009-01-07 11:05:07] ba6ec600 RA_Processor::UpgradeApplet - path = > /usr/share/pki/tps/applets/1.3.44724DDE.ijc > > [2009-01-07 11:05:07] ba6ec600 AP_Session::WriteMsg - pdu_len='12' > > [2009-01-07 11:05:07] ba6ec600 AP_Session::WriteMsg - Sent > > 's=68&msg_type=9&pdu_size=12&pdu_data=%00%A4%04%00%07%A0%00%00%00%03%00%00' > [2009-01-07 11:05:07] ba6ec600 AP_Session::ReadMsg - decoded pdu = > (length='20') > > [2009-01-07 11:05:07] ba6ec600 AP_Session::ReadMsg - 6f 10 84 08 a0 00 > 00 00 03 00 > > [2009-01-07 11:05:07] ba6ec600 AP_Session::ReadMsg - 00 00 a5 04 9f 65 > 01 ff 90 00 > > [2009-01-07 11:05:07] ba6ec600 AP_Session::ReadMsg - > > [2009-01-07 11:05:07] ba6ec600 AP_Session::WriteMsg - pdu_len='13' > > [2009-01-07 11:05:07] ba6ec600 AP_Session::WriteMsg - Sent > > 's=71&msg_type=9&pdu_size=13&pdu_data=%80%50%01%01%08%09%CD%60%A7%11%EC%23%A 5' > [2009-01-07 11:05:08] ba6ec600 AP_Session::ReadMsg - decoded pdu = > (length='2') > > [2009-01-07 11:05:08] ba6ec600 AP_Session::ReadMsg - 6a 86 > > [2009-01-07 11:05:08] ba6ec600 RA_Format_Processor::Process - applet > upgrade failed > > [2009-01-07 11:05:08] ba6ec600 AP_Session::WriteMsg - pdu_len='12' > > [2009-01-07 11:05:08] ba6ec600 AP_Session::WriteMsg - Sent > > 's=68&msg_type=9&pdu_size=12&pdu_data=%00%A4%04%00%07%62%76%01%FF%00%00%00' > [2009-01-07 11:05:08] ba6ec600 AP_Session::ReadMsg - decoded pdu = > (length='2') > > [2009-01-07 11:05:08] ba6ec600 AP_Session::ReadMsg - 90 00 > > [2009-01-07 11:05:08] ba6ec600 AP_Session::WriteMsg - Sent > 's=43&msg_type=13&operation=5&result=1&message=19' > > When we switch the values to be: > > channel.defKeyVersion=0 > > channel. defKeyIndex=0 > > The error now looks like this: > > [2009-01-07 11:20:41] bacd2d28 LDAP_Authentication::Authenticate - > User bind required 'uid=testuser1,ou=People,dc=localdomain' 'envieta123' > > [2009-01-07 11:20:41] bacd2d28 LDAP_Authentication::Authenticate - > Attributes mail,cn,uid > > [2009-01-07 11:20:41] bacd2d28 LDAP_Authentication::Authenticate - > Exposed cn=Test User1 > > [2009-01-07 11:20:41] bacd2d28 LDAP_Authentication::Authenticate - Size 3 > > [2009-01-07 11:20:41] bacd2d28 LDAP_Authentication::Authenticate - > Exposed uid=testuser1 > > [2009-01-07 11:20:41] bacd2d28 LDAP_Authentication::Authenticate - Size 4 > > [2009-01-07 11:20:41] bacd2d28 RA_Format_Processor::Process - > Authenticate returns: 0 > > [2009-01-07 11:20:41] bacd2d28 AP_Session::WriteMsg - Sent > 's=67&msg_type=14&current_state=10&next_task_name=PROGRESS_APPLET_UPGRADE' > > [2009-01-07 11:20:41] bacd2d28 RA_Processor::UpgradeApplet - path = > /usr/share/pki/tps/applets/1.3.44724DDE.ijc > > [2009-01-07 11:20:41] bacd2d28 AP_Session::WriteMsg - pdu_len='12' > > [2009-01-07 11:20:41] bacd2d28 AP_Session::WriteMsg - Sent > > 's=68&msg_type=9&pdu_size=12&pdu_data=%00%A4%04%00%07%A0%00%00%00%03%00%00' > [2009-01-07 11:20:41] bacd2d28 AP_Session::ReadMsg - decoded pdu = > (length='20') > > [2009-01-07 11:20:41] bacd2d28 AP_Session::ReadMsg - 6f 10 84 08 a0 00 > 00 00 03 00 > > [2009-01-07 11:20:41] bacd2d28 AP_Session::ReadMsg - 00 00 a5 04 9f 65 > 01 ff 90 00 > > [2009-01-07 11:20:41] bacd2d28 AP_Session::ReadMsg - > > [2009-01-07 11:20:41] bacd2d28 AP_Session::WriteMsg - pdu_len='13' > > [2009-01-07 11:20:41] bacd2d28 AP_Session::WriteMsg - Sent > > 's=71&msg_type=9&pdu_size=13&pdu_data=%80%50%00%00%08%95%74%0B%AC%37%C9%DE%8 0' > [2009-01-07 11:20:41] bacd2d28 AP_Session::ReadMsg - decoded pdu = > (length='30') > > [2009-01-07 11:20:41] bacd2d28 AP_Session::ReadMsg - 00 00 71 61 57 01 > 0e 0d 90 bd > > [2009-01-07 11:20:41] bacd2d28 AP_Session::ReadMsg - ff 02 00 21 2e 6b > ec 9e 33 2b > > [2009-01-07 11:20:41] bacd2d28 AP_Session::ReadMsg - a5 26 d0 02 e6 64 > c9 3c 90 00 > > [2009-01-07 11:20:41] bacd2d28 AP_Session::ReadMsg - > > [2009-01-07 11:20:41] bacd2d28 HttpConnection::getResponse - Send > request to host localhost.localdomain:13443 servlet > /tks/agent/tks/computeSessionKey > > [2009-01-07 11:20:42] bacd2d28 RA::Engine - Pre-processing content > 'HTTP/1.1 200 OK > > Server: Apache-Coyote/1.1 > > Content-Type: text/html > > Content-Length: 8 > > Date: Wed, 07 Jan 2009 16:20:42 GMT > > status=3 > > [2009-01-07 11:20:42] bacd2d28 RA::Engine - Post-processing content > 'status=3 > > [2009-01-07 11:20:42] bacd2d28 RA_Format_Processor::Process - applet > upgrade failed > > [2009-01-07 11:20:42] bacd2d28 AP_Session::WriteMsg - pdu_len='12' > > [2009-01-07 11:20:42] bacd2d28 AP_Session::WriteMsg - Sent > > 's=68&msg_type=9&pdu_size=12&pdu_data=%00%A4%04%00%07%62%76%01%FF%00%00%00' > [2009-01-07 11:20:42] bacd2d28 AP_Session::ReadMsg - decoded pdu = > (length='2') > > [2009-01-07 11:20:42] bacd2d28 AP_Session::ReadMsg - 90 00 > > [2009-01-07 11:20:42] bacd2d28 AP_Session::WriteMsg - Sent > 's=43&msg_type=13&operation=5&result=1&message=19' > > In addition - the following is the pki-tps.tps-error.log snippet > > [2008-12-23 12:09:39] ba5de4e0 RA_Processor::SetupSecureChannel - > Failed to create a secure channel - potentially due to an RA/TKS key > mismatch or differing RA/TKS key versions. > [2008-12-23 12:09:39] ba5de4e0 RA_Processor::UpgradeApplet - channel > creation failure > [2008-12-23 12:10:20] ba5cb398 RA_Processor::SetupSecureChannel - > Failed to create a secure channel - potentially due to an RA/TKS key > mismatch or differing RA/TKS key versions. > [2008-12-23 12:10:20] ba5cb398 RA_Processor::UpgradeApplet - channel > creation failure > [2008-12-23 12:11:14] b8e04520 RA_Processor::SetupSecureChannel - > Failed to create a secure channel - potentially due to an RA/TKS key > mismatch or differing RA/TKS key versions. > [2008-12-23 12:11:14] b8e04520 RA_Processor::UpgradeApplet - channel > creation failure > [2008-12-23 12:39:38] ba5c00e0 RA_Processor::SetupSecureChannel - > Failed to create a secure channel - potentially due to an RA/TKS key > mismatch or differing RA/TKS key versions. > [2008-12-23 12:39:38] ba5c00e0 RA_Processor::UpgradeApplet - channel > creation failure > [2008-12-23 12:44:27] ba5b14c8 RA_Processor::SetupSecureChannel - > Failed to create a secure channel - potentially due to an RA/TKS key > mismatch or differing RA/TKS key versions. > [2008-12-23 12:44:27] ba5b14c8 RA_Processor::UpgradeApplet - channel > creation failure > [2008-12-23 12:45:54] ba5f2590 RA_Processor::SetupSecureChannel - > Failed to create a secure channel - potentially due to an RA/TKS key > mismatch or differing RA/TKS key versions. > [2008-12-23 12:45:54] ba5f2590 RA_Processor::UpgradeApplet - channel > creation failure > > I'm also bringing John Whitelock, another one of our engineers in on > discussions. He just joined the pki-users list. > > Zach Casper > > _____________________________________________ > *From:* Jack Magne [mailto:jmagne@redhat.com] > *Sent:* Wednesday, January 07, 2009 1:09 PM > *To:* Zach Casper > *Cc:* pki-users(a)redhat.com > *Subject:* Re: [Pki-users] ESC Format / Enroll Error > > Zach: > > Sorry for the delay.... > > The default developer keyset we use for our keys with TPS is the > > standard like follows: > > tks.defKeySet.auth_key=#40#41...#4f > > tks.defKeySet.kek_key=#40#41...#4f > > tks.defKeySet.mac_key=#40#41.. #4f > > If you look in the CS.cfg file under > > /var/lib/pki-tks/conf > > We have an entire procedure documented in the CS 7.3 documentation to > > perform a key changeover if required. > > Feel free to post any further logs you might obtain after further testing. > > thanks, > > jack > > Zach Casper wrote: > > >> Could there be an issue with the default key our card is loaded with >> >> (VISA Key) not being able to create the secure connection? What are >> >> the default key(s) used/needed by Dogtag? >> >> _____________________________________________ >> >> *From:* Jack Magne [mailto:jmagne@redhat.com] >> >> *Sent:* Tuesday, December 23, 2008 5:35 PM >> >> *To:* Zach Casper >> >> *Cc:* pki-users(a)redhat.com >> >> *Subject:* Re: [Pki-users] ESC Format / Enroll Error >> >> I'll have to take a closer look later but there is a quick thing you can >> >> try. >> >> Also, remember depending upon your card, if you make too many failed >> >> attempts at a secure channel, the card can lock itself up. >> >> In /var/lib/pki-tps/conf/CS.cfg you will have a block like this: >> >> channel.defKeyVersion=1 >> >> channel. defKeyIndex=1 >> >> We have experimented with some other cards where the following works: >> >> channel.defKeyVersion=0 >> >> channel.defKeyIndex=0 >> >> Zach Casper wrote: >> >>> tps-error.log >>> >>> ... >>> >>> [2008-12-23 12:09:39] ba5de4e0 RA_Processor::SetupSecureChannel - >>> >>> Failed to create a secure channel - potentially due to an RA/TKS key >>> >>> mismatch or differing RA/TKS key versions. >>> >>> [2008-12-23 12:09:39] ba5de4e0 RA_Processor::UpgradeApplet - channel >>> >>> creation failure >>> >>> [2008-12-23 12:10:20] ba5cb398 RA_Processor::SetupSecureChannel - >>> >>> Failed to create a secure channel - potentially due to an RA/TKS key >>> >>> mismatch or differing RA/TKS key versions. >>> >>> [2008-12-23 12:10:20] ba5cb398 RA_Processor::UpgradeApplet - channel >>> >>> creation failure >>> >>> [2008-12-23 12:11:14] b8e04520 RA_Processor::SetupSecureChannel - >>> >>> Failed to create a secure channel - potentially due to an RA/TKS key >>> >>> mismatch or differing RA/TKS key versions. >>> >>> [2008-12-23 12:11:14] b8e04520 RA_Processor::UpgradeApplet - channel >>> >>> creation failure >>> >>> [2008-12-23 12:39:38] ba5c00e0 RA_Processor::SetupSecureChannel - >>> >>> Failed to create a secure channel - potentially due to an RA/TKS key >>> >>> mismatch or differing RA/TKS key versions. >>> >>> [2008-12-23 12:39:38] ba5c00e0 RA_Processor::UpgradeApplet - channel >>> >>> creation failure >>> >>> [2008-12-23 12:44:27] ba5b14c8 RA_Processor::SetupSecureChannel - >>> >>> Failed to create a secure channel - potentially due to an RA/TKS key >>> >>> mismatch or differing RA/TKS key versions. >>> >>> [2008-12-23 12:44:27] ba5b14c8 RA_Processor::UpgradeApplet - channel >>> >>> creation failure >>> >>> [2008-12-23 12:45:54] ba5f2590 RA_Processor::SetupSecureChannel - >>> >>> Failed to create a secure channel - potentially due to an RA/TKS key >>> >>> mismatch or differing RA/TKS key versions. >>> >>> [2008-12-23 12:45:54] ba5f2590 RA_Processor::UpgradeApplet - channel >>> >>> creation failure >>> >>> tps-debug.log >>> >>> ... >>> >>> [2008-12-23 12:45:54] ba5f2590 RA_Format_Processor::Process - >>> >>> Authenticate returns: 0 >>> >>> [2008-12-23 12:45:54] ba5f2590 AP_Session::WriteMsg - Sent >>> > 's=67&msg_type=14&current_state=10&next_task_name=PROGRESS_APPLET_UPGRADE' > > >>> [2008-12-23 12:45:54] ba5f2590 RA_Processor::UpgradeApplet - path = >>> >>> /usr/share/pki/tps/applets/1.3.44724DDE.ijc >>> >>> [2008-12-23 12:45:54] ba5f2590 AP_Session::WriteMsg - pdu_len='12' >>> >>> [2008-12-23 12:45:54] ba5f2590 AP_Session::WriteMsg - Sent >>> 's=68&msg_type=9&pdu_size=12&pdu_data=%00%A4%04%00%07%A0%00%00%00%03%00%00' >>> [2008-12-23 12:45:54] ba5f2590 AP_Session::ReadMsg - decoded pdu = >>> >>> (length='20') >>> >>> [2008-12-23 12:45:54] ba5f2590 AP_Session::ReadMsg - 6f 10 84 08 a0 00 >>> >>> 00 00 03 00 >>> >>> [2008-12-23 12:45:54] ba5f2590 AP_Session::ReadMsg - 00 00 a5 04 9f 65 >>> >>> 01 ff 90 00 >>> >>> [2008-12-23 12:45:54] ba5f2590 AP_Session::ReadMsg - >>> >>> [2008-12-23 12:45:54] ba5f2590 AP_Session::WriteMsg - pdu_len='13' >>> >>> [2008-12-23 12:45:54] ba5f2590 AP_Session::WriteMsg - Sent >>> 's=71&msg_type=9&pdu_size=13&pdu_data=%80%50%01%01%08%56%F5%29%9D%7B%8F%6F%A 7' >>> [2008-12-23 12:45:54] ba5f2590 AP_Session::ReadMsg - decoded pdu = >>> >>> (length='2') >>> >>> [2008-12-23 12:45:54] ba5f2590 AP_Session::ReadMsg - 6a 86 >>> >>> [2008-12-23 12:45:54] ba5f2590 RA_Format_Processor::Process - applet >>> >>> upgrade failed >>> >>> [2008-12-23 12:45:54] ba5f2590 AP_Session::WriteMsg - pdu_len='12' >>> >>> [2008-12-23 12:45:54] ba5f2590 AP_Session::WriteMsg - Sent >>> 's=68&msg_type=9&pdu_size=12&pdu_data=%00%A4%04%00%07%62%76%01%FF%00%00%00' >>> [2008-12-23 12:45:54] ba5f2590 AP_Session::ReadMsg - decoded pdu = >>> >>> (length='2') >>> >>> [2008-12-23 12:45:54] ba5f2590 AP_Session::ReadMsg - 90 00 >>> >>> [2008-12-23 12:45:54] ba5f2590 AP_Session::WriteMsg - Sent >>> >>> 's=43&msg_type=13&operation=5&result=1&message=19' >>> >>> zach >>> >>> _____________________________________________ >>> >>> *From:* Jack Magne [mailto:jmagne@redhat.com] >>> >>> *Sent:* Tuesday, December 23, 2008 2:38 PM >>> >>> *To:* Adewumi, Julius-p99373 >>> >>> *Cc:* Zach Casper; pki-users(a)redhat.com >>> >>> *Subject:* Re: [Pki-users] ESC Format / Enroll Error >>> >>> You are having a problem creating a secure channel. Perhaps posting a >>> >>> snippet of the log might help. >>> >>> Adewumi, Julius-p99373 wrote: >>> >>>> You might want to play with changing "false" to "true in the >>>> > CS.cfg for > > >>>> op.enroll.userKey.update.applet.emptyToken.enable=false or the >>>> >>>> op.format... equivalent , etc. >>>> >>>> /From: Julius Adewumi/ >>>> >>>> /(a)GDC4S.com/ >>>> >>>> /Ph:480-441-6768/ >>>> >>>> /Contract Corp:MTSI/ >>>> >> ------------------------------------------------------------------------ >> >>>> *From:* pki-users-bounces(a)redhat.com >>>> >>>> [mailto:pki-users-bounces@redhat.com] *On Behalf Of *Zach Casper >>>> >>>> *Sent:* Tuesday, December 23, 2008 12:00 PM >>>> >>>> *To:* pki-users(a)redhat.com >>>> >>>> *Subject:* RE: [Pki-users] ESC Format / Enroll Error >>>> >>>> Tps-debug log shows the following: >>>> >>>> RA_Format_Processor::Process - applet upgrade failed >>>> >>>> Tps-error log show the following: >>>> >>>> RA_Processor::SetupSecureChannel - Failed to create a secure channel >>>> >>>> 0- potentially due to an RA/TKS key mismatch or differing RA/TKS key >>>> >>>> versions. >>>> >>>> RA_Processor::UpgradeApplet -0 channel create failure >>>> >>>> And a series of Bad Response when trying to SelectApplet or >>>> GetStatus >>>> zach >>>> >>>> _____________________________________________ >>>> >>>> *From:* Jack Magne [mailto:jmagne@redhat.com] >>>> >>>> *Sent:* Tuesday, December 23, 2008 1:10 PM >>>> >>>> *To:* Zach Casper >>>> >>>> *Subject:* Re: [Pki-users] ESC Format / Enroll Error >>>> >>>> The first step would be to take a look at the tps log or smart card >>>> >>>> server. >>>> >>>> These can be found at: >>>> >>>> /var/lib/pki-tps/logs/tps-debug.log >>>> >>>> Search the bottom of the log for error 19 and it should give you an >>>> >> idea >> >>>> of what TPS was trying to do at the time. >>>> >>>> Zach Casper wrote: >>>> >>>>> We have an Infineon Smart Card and currently we are unable to >>>>> >>>>> Format/Enroll due to the following ESC Error >>>>> >>>>> "Formatting of smart card failed. Error: The Smart Card Server >>>>> > cannot > > >>>>> upgrade the software on your smart card." >>>>> >>>>> And Diagnostics show this error: >>>>> >>>>> "Attempting to Format Key, ID: ####### - Key Format failure, >>>>> Error: >>> 19." >>> >>>>> This card comes up as "Formatted" because we've manually >>>>> > installed a > > >>>>> version of the Dogtag applet prior to using ESC & Dogtag. >>>>> >>>>> Any advice on how we can troubleshoot? >>>>> >>>>> -- >>>>> >>>>> Zach Casper >>>>> >>>>> Envieta LLC >>>>> >>>>> ---------------------------------------- >>>>> > ------------------------------------------------------------------------ > > >>>>> _______________________________________________ >>>>> >>>>> Pki-users mailing list >>>>> >>>>> Pki-users(a)redhat.com >>>>> >>>>> https://www.redhat.com/mailman/listinfo/pki-users >>>>> >> ------------------------------------------------------------------------ >> >>>> _______________________________________________ >>>> >>>> Pki-users mailing list >>>> >>>> Pki-users(a)redhat.com >>>> >>>> https://www.redhat.com/mailman/listinfo/pki-users >>>> > ------------------------------------------------------------------------ > > >>> _______________________________________________ >>> >>> Pki-users mailing list >>> >>> Pki-users(a)redhat.com >>> >>> https://www.redhat.com/mailman/listinfo/pki-users >>>

Jack, Thanks again for the help. Below I have pasted the log you asked for from that same test. [07/Jan/2009:11:20:42][http-13443-Processor25]: Authentication: client certificate found [07/Jan/2009:11:20:42][http-13443-Processor25]: getConn: mNumConns now 2 [07/Jan/2009:11:20:42][http-13443-Processor25]: returnConn: mNumConns now

[07/Jan/2009:11:20:42][http-13443-Processor25]: Authentication: mapped certificate to user [07/Jan/2009:11:20:42][http-13443-Processor25]: authenticated

s [07/Jan/2009:11:20:42][http-13443-Processor25]: SignedAuditEventFactory: create()

Outcome=Success][AuthMgr=certUserDBAuthMgr] authentication success [07/Jan/2009:11:20:42][http-13443-Processor25]: checkACLS(): ACLEntry expressions= group="Token Key Service Manager Agents" [07/Jan/2009:11:20:42][http-13443-Processor25]: evaluating expressions: group="Token Key Service Manager Agents" [07/Jan/2009:11:20:42][http-13443-Processor25]: getConn: mNumConns now 2 [07/Jan/2009:11:20:42][http-13443-Processor25]: returnConn: mNumConns now

[07/Jan/2009:11:20:42][http-13443-Processor25]: UGSubsystem.isMemberOf() using new lookup code [07/Jan/2009:11:20:42][http-13443-Processor25]: getConn: mNumConns now 2 [07/Jan/2009:11:20:42][http-13443-Processor25]: authorization search base: cn=Token Key Service Manager Agents,ou=groups,dc=localhost.localdomain-pki-tks [07/Jan/2009:11:20:42][http-13443-Processor25]: authorization search

ldomain-pki-tks) [07/Jan/2009:11:20:42][http-13443-Processor25]: authorization result: true [07/Jan/2009:11:20:42][http-13443-Processor25]: returnConn: mNumConns now

a:689) at java.lang.Thread.run(Thread.java:636) [07/Jan/2009:11:20:42][http-13443-Processor25]: TokenServlet Computing Session Key: java.lang.Exception: Can't compute session key! [07/Jan/2009:11:20:42][http-13443-Processor25]: TokenServlet:outputString.encode status=3 [07/Jan/2009:11:20:42][http-13443-Processor25]: TokenServlet:outputString.length 8 [07/Jan/2009:11:20:42][http-13443-Processor25]: CMSServlet: curDate=Wed