Error: The Smart Card Manager has lost the connection to the Smart Card Server.
I set up a Dogtag Certificate System in a fresh CentOS 5.5 server and AFAIK everything went fine. When I insert the card (Samsung S3CC9P9 - Java Card 2.2.1, Open Platform v2.0.1) in a Fedora 13 desktop, the Smart Card Manager successfully tests the TPS Config URI and reports: Smart Card Server config information successfully obtained! Then it identifies the card as "Unformated", but when I try to format I get the error: Formatting of smart card failed. Error: The Smart Card Manager has lost the connection to the Smart Card Server. In the client, "Diagnostics" reports: SMART CARD DIAGNOSTICS REPORT ***Software Version Information*** Smart Card Manager Version: 1.1.0-12.fc13 System Versions: mozilla/5.0 (x11; u; linux x86_64; en-us; rv:1.9.2.4) gecko/20100622 fedora/1.9.2.4-1.fc13 ***Active Smart Card Details*** Number of Smart Cards Detected: 1 Smart Card CoolKey 02052223: Smart Card Applet Version: 0.0 Key ID: 4250503933f602052223 Status: Unformatted Issuer: Fedora Project Atr: 3B690000806331460183FF9000 Phone Home URL: http://ca.abcd.edu.br:7888/cgi-bin/home/index.cgi?cuid=4250503933f602052223 Smart Card Server URL: http://ca.abcd.edu.br:7888/nk_service Enrollment UI URL: http://ca.abcd.edu.br:7888/cgi-bin/home/enroll.cgi ***Smart Card Activity*** [Mon 28 Jun 2010 07:29:06 PM BRT] NSS system intialized successfully! [Mon 28 Jun 2010 07:29:09 PM BRT] Attempting to phone home for Key 4250503933f602052223 [Mon 28 Jun 2010 07:29:09 PM BRT] Attempting to get key issuer info. Can't select CoolKey manager! [Mon 28 Jun 2010 07:29:09 PM BRT] Attempting to get the key's Issuer: Key: 4250503933f602052223, Issuer . [Mon 28 Jun 2010 07:29:09 PM BRT] IsPhoneHomeCached keyID: 4250503933f602052223 IsCached: false [Mon 28 Jun 2010 07:30:55 PM BRT] Actually phoning Home for Key: 4250503933f602052223 URI: http://ca.abcd.edu.br:7888/cgi-bin/home/index.cgi [Mon 28 Jun 2010 07:30:56 PM BRT] Phone Home config value for Key: 4250503933f602052223 ConfigKey: Operation-4250503933f602052223 ConfigValue: http://ca.abcd.edu.br:7888/nk_service [Mon 28 Jun 2010 07:30:56 PM BRT] Phone Home config value for Key: 4250503933f602052223 ConfigKey: UI-4250503933f602052223 ConfigValue: http://ca.abcd.edu.br:7888/cgi-bin/home/enroll.cgi [Mon 28 Jun 2010 07:30:56 PM BRT] Phone Home config value for Key: 4250503933f602052223 ConfigKey: EnrolledTokenBrowserURL-4250503933f602052223 ConfigValue: http://www.fedora.redhat.com [Mon 28 Jun 2010 07:30:56 PM BRT] Phone Home config value for Key: 4250503933f602052223 ConfigKey: TokenType-4250503933f602052223 ConfigValue: userKey [Mon 28 Jun 2010 07:30:57 PM BRT] Phone Home config value for Key: 4250503933f602052223 ConfigKey: keyIssuerUrl-4250503933f602052223 ConfigValue: http://ca.abcd.edu.br:7888/cgi-bin/home/index.cgi?cuid=4250503933f602052223 [Mon 28 Jun 2010 07:31:35 PM BRT] Attempting to Format Key, ID: 4250503933f602052223. [Mon 28 Jun 2010 07:31:38 PM BRT] Processing HTTP message. Write back to TPS failed , disconnecting. [Mon 28 Jun 2010 07:31:38 PM BRT] Key Format failure. Error: 28. In the server I got the logs: /var/log/pki-tps/access_log 189.104.62.234 - - [28/Jun/2010:18:30:56 -0400] "GET /cgi-bin/home/index.cgi?cuid=4250503933f602052223 HTTP/1.1" 200 409 /var/log/pki-tps/tps-debug.log [2010-06-28 18:31:35] 8208eb98 mod_tps::mod_tps_handler - mod_tps::mod_tps_handler [2010-06-28 18:31:35] 8208eb98 mod_tps::mod_tps_handler - uri '/nk_service' [2010-06-28 18:31:35] 8208eb98 mod_tps::mod_tps_handler - uri '/nk_service' DONE [2010-06-28 18:31:35] 8208eb98 AP_Session::ReadMsg - ========== ReadMsg Begins ======= [2010-06-28 18:31:35] 8208eb98 AP_Session::ReadMsg - msg_len=180 [2010-06-28 18:31:35] 8208eb98 AP_Session::ReadMsg - Received len='180' msg='msg_type=2&operation=5&extensions=tokenType%3DuserKey%26clientVersion%3DESC+1%2E0%2E1%26tokenATR%3D3B690000806331460183FF9000%26statusUpdate%3Dtrue%26extendedLoginRequest%3Dtrue%26' [2010-06-28 18:31:35] 8208eb98 AP_Session::create_pblock - Data 'msg_type=2&operation=5&extensions=tokenType%3DuserKey%26clientVersion%3DESC+1%2E0%2E1%26tokenATR%3D3B690000806331460183FF9000%26statusUpdate%3Dtrue%26extendedLoginRequest%3Dtrue%26' [2010-06-28 18:31:35] 8208eb98 AP_Session::create_pblock - Found Arguments=3, nalloc=50 [2010-06-28 18:31:35] 8208eb98 AP_Session::create_pblock - entry name=msg_type, value=2 [2010-06-28 18:31:35] 8208eb98 AP_Session::create_pblock - entry name=operation, value=5 [2010-06-28 18:31:35] 8208eb98 AP_Session::create_pblock - entry name=extensions, value=tokenType%3DuserKey%26clientVersion%3DESC+1%2E0%2E1%26tokenATR%3D3B690000806331460183FF9000%26statusUpdate%3Dtrue%26extendedLoginRequest%3Dtrue%26 [2010-06-28 18:31:35] 8208eb98 AP_Session::ReadMsg - Found msg_type=BEGIN_OP (2) [2010-06-28 18:31:35] 8208eb98 AP_Session::ReadMsg - content= (length='1') [2010-06-28 18:31:35] 8208eb98 AP_Session::ReadMsg - 35 [2010-06-28 18:31:35] 8208eb98 AP_Session::ReadMsg - Extensions tokenType=userKey&clientVersion=ESC 1.0.1&tokenATR=3B690000806331460183FF9000&statusUpdate=true&extendedLoginRequest=true& [2010-06-28 18:31:35] 8208eb98 AP_Session::ReadMsg - begin_op_msg msg_type=FORMAT [2010-06-28 18:31:35] 8208eb98 RA_pblock::free_pblock - in free_pblock [2010-06-28 18:31:35] 8208eb98 RA_pblock::free_pblock - in free_pblock done [2010-06-28 18:31:35] 8208eb98 AP_Session::ReadMsg - ========= ReadMsg Ends ========= [2010-06-28 18:31:35] 8208eb98 RA_Format_Processor::Process - Begin upgrade process [2010-06-28 18:31:35] 8208eb98 RA_Format_Processor::Process - Client 189.104.62.234 [2010-06-28 18:31:35] 8208eb98 RA_Processor::SelectApplet - RA_Processor::SelectApplet with aid= (length='7') [2010-06-28 18:31:35] 8208eb98 RA_Processor::SelectApplet - a0 00 00 00 03 00 00 [2010-06-28 18:31:35] 8208eb98 AP_Session::WriteMsg - pdu_len='12' [2010-06-28 18:31:35] 8208eb98 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' [2010-06-28 18:31:35] 8208eb98 RA_Processor::SelectApplet - Sent select_request_msg [2010-06-28 18:31:35] 8208eb98 AP_Session::ReadMsg - ========== ReadMsg Begins ======= [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - msg_len=112 [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - Received len='112' msg='msg_type=10&pdu_size=29&pdu_data=o%19%84%08%A0%00%00%00%03%00%00%00%A5%0D%9Fn%06%10%01v%DE%00%05%9Fe%01%7F%90%00' [2010-06-28 18:31:36] 8208eb98 AP_Session::create_pblock - Data 'msg_type=10&pdu_size=29&pdu_data=o%19%84%08%A0%00%00%00%03%00%00%00%A5%0D%9Fn%06%10%01v%DE%00%05%9Fe%01%7F%90%00' [2010-06-28 18:31:36] 8208eb98 AP_Session::create_pblock - Found Arguments=3, nalloc=50 [2010-06-28 18:31:36] 8208eb98 AP_Session::create_pblock - entry name=msg_type, value=10 [2010-06-28 18:31:36] 8208eb98 AP_Session::create_pblock - entry name=pdu_size, value=29 [2010-06-28 18:31:36] 8208eb98 AP_Session::create_pblock - entry name=pdu_data, value=o%19%84%08%A0%00%00%00%03%00%00%00%A5%0D%9Fn%06%10%01v%DE%00%05%9Fe%01%7F%90%00 [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - Found msg_type=TOKEN_PDU_RESPONSE (10) [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - Found pdu_size=29 [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - decoded_pdu size= 29 [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - decoded pdu = (length='29') [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - 6f 19 84 08 a0 00 00 00 03 00 [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - 00 00 a5 0d 9f 6e 06 10 01 76 [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - de 00 05 9f 65 01 7f 90 00 [2010-06-28 18:31:36] 8208eb98 RA_pblock::free_pblock - in free_pblock [2010-06-28 18:31:36] 8208eb98 RA_pblock::free_pblock - in free_pblock done [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - ========= ReadMsg Ends ========= [2010-06-28 18:31:36] 8208eb98 AP_Session::WriteMsg - pdu_len='5' [2010-06-28 18:31:36] 8208eb98 AP_Session::WriteMsg - Sent 's=46&msg_type=9&pdu_size=5&pdu_data=%80%CA%9F%7F%2D' [2010-06-28 18:31:36] 8208eb98 RA_Processor::GetData - Sent get_data_request_msg [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - ========== ReadMsg Begins ======= [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - msg_len=144 [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - Received len='144' msg='msg_type=10&pdu_size=47&pdu_data=%9F%7F%2ABPP9%10%01v%DE%00%05q%18%02%05%22%233%F6BRq%27SSv%DE%00%00v%DE%AA%BB%CC%DD%00%00v%DE%AA%BB%CC%DD%90%00' [2010-06-28 18:31:36] 8208eb98 AP_Session::create_pblock - Data 'msg_type=10&pdu_size=47&pdu_data=%9F%7F%2ABPP9%10%01v%DE%00%05q%18%02%05%22%233%F6BRq%27SSv%DE%00%00v%DE%AA%BB%CC%DD%00%00v%DE%AA%BB%CC%DD%90%00' [2010-06-28 18:31:36] 8208eb98 AP_Session::create_pblock - Found Arguments=3, nalloc=50 [2010-06-28 18:31:36] 8208eb98 AP_Session::create_pblock - entry name=msg_type, value=10 [2010-06-28 18:31:36] 8208eb98 AP_Session::create_pblock - entry name=pdu_size, value=47 [2010-06-28 18:31:36] 8208eb98 AP_Session::create_pblock - entry name=pdu_data, value=%9F%7F%2ABPP9%10%01v%DE%00%05q%18%02%05%22%233%F6BRq%27SSv%DE%00%00v%DE%AA%BB%CC%DD%00%00v%DE%AA%BB%CC%DD%90%00 [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - Found msg_type=TOKEN_PDU_RESPONSE (10) [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - Found pdu_size=47 [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - decoded_pdu size= 47 [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - decoded pdu = (length='47') [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - 9f 7f 2a 42 50 50 39 10 01 76 [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - de 00 05 71 18 02 05 22 23 33 [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - f6 42 52 71 27 53 53 76 de 00 [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - 00 76 de aa bb cc dd 00 00 76 [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - de aa bb cc dd 90 00 [2010-06-28 18:31:36] 8208eb98 RA_pblock::free_pblock - in free_pblock [2010-06-28 18:31:36] 8208eb98 RA_pblock::free_pblock - in free_pblock done [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - ========= ReadMsg Ends ========= [2010-06-28 18:31:36] 8208eb98 RA_Format_Processor::process - CPLC Data = (length='47') [2010-06-28 18:31:36] 8208eb98 RA_Format_Processor::process - 9f 7f 2a 42 50 50 39 10 01 76 [2010-06-28 18:31:36] 8208eb98 RA_Format_Processor::process - de 00 05 71 18 02 05 22 23 33 [2010-06-28 18:31:36] 8208eb98 RA_Format_Processor::process - f6 42 52 71 27 53 53 76 de 00 [2010-06-28 18:31:36] 8208eb98 RA_Format_Processor::process - 00 76 de aa bb cc dd 00 00 76 [2010-06-28 18:31:36] 8208eb98 RA_Format_Processor::process - de aa bb cc dd 90 00 [2010-06-28 18:31:36] 8208eb98 RA_Format_Processor::process - Token CUID= (length='10') [2010-06-28 18:31:36] 8208eb98 RA_Format_Processor::process - 42 50 50 39 33 f6 02 05 22 23 [2010-06-28 18:31:36] 8208eb98 RA_Format_Processor::process - [2010-06-28 18:31:36] 8208eb98 RA_Format_Processor::process - Token MSN= (length='4') [2010-06-28 18:31:36] 8208eb98 RA_Format_Processor::process - aa bb cc dd [2010-06-28 18:31:36] 8208eb98 RA_Processor::SelectApplet - RA_Processor::SelectApplet with aid= (length='7') [2010-06-28 18:31:36] 8208eb98 RA_Processor::SelectApplet - 62 76 01 ff 00 00 00 [2010-06-28 18:31:36] 8208eb98 AP_Session::WriteMsg - pdu_len='12' [2010-06-28 18:31:36] 8208eb98 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' [2010-06-28 18:31:36] 8208eb98 RA_Processor::SelectApplet - Sent select_request_msg [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - ========== ReadMsg Begins ======= [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - msg_len=36 [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - Received len='36' msg='msg_type=10&pdu_size=2&pdu_data=j%82' [2010-06-28 18:31:36] 8208eb98 AP_Session::create_pblock - Data 'msg_type=10&pdu_size=2&pdu_data=j%82' [2010-06-28 18:31:36] 8208eb98 AP_Session::create_pblock - Found Arguments=3, nalloc=50 [2010-06-28 18:31:36] 8208eb98 AP_Session::create_pblock - entry name=msg_type, value=10 [2010-06-28 18:31:36] 8208eb98 AP_Session::create_pblock - entry name=pdu_size, value=2 [2010-06-28 18:31:36] 8208eb98 AP_Session::create_pblock - entry name=pdu_data, value=j%82 [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - Found msg_type=TOKEN_PDU_RESPONSE (10) [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - Found pdu_size=2 [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - decoded_pdu size= 2 [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - decoded pdu = (length='2') [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - 6a 82 [2010-06-28 18:31:36] 8208eb98 RA_pblock::free_pblock - in free_pblock [2010-06-28 18:31:36] 8208eb98 RA_pblock::free_pblock - in free_pblock done [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - ========= ReadMsg Ends ========= [2010-06-28 18:31:36] 8208eb98 RA_Processor::SelectApplet - Bad Response [2010-06-28 18:31:36] 8208eb98 AP_Session::WriteMsg - pdu_len='5' [2010-06-28 18:31:36] 8208eb98 AP_Session::WriteMsg - Sent 's=46&msg_type=9&pdu_size=5&pdu_data=%B0%3C%00%00%10' [2010-06-28 18:31:36] 8208eb98 RA_Processor::GetStatus - Sent get_status_request_msg [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - ========== ReadMsg Begins ======= [2010-06-28 18:31:37] 8208eb98 AP_Session::ReadMsg - msg_len=36 [2010-06-28 18:31:37] 8208eb98 AP_Session::ReadMsg - Received len='36' msg='msg_type=10&pdu_size=2&pdu_data=n%00' [2010-06-28 18:31:37] 8208eb98 AP_Session::create_pblock - Data 'msg_type=10&pdu_size=2&pdu_data=n%00' [2010-06-28 18:31:37] 8208eb98 AP_Session::create_pblock - Found Arguments=3, nalloc=50 [2010-06-28 18:31:37] 8208eb98 AP_Session::create_pblock - entry name=msg_type, value=10 [2010-06-28 18:31:37] 8208eb98 AP_Session::create_pblock - entry name=pdu_size, value=2 [2010-06-28 18:31:37] 8208eb98 AP_Session::create_pblock - entry name=pdu_data, value=n%00 [2010-06-28 18:31:37] 8208eb98 AP_Session::ReadMsg - Found msg_type=TOKEN_PDU_RESPONSE (10) [2010-06-28 18:31:37] 8208eb98 AP_Session::ReadMsg - Found pdu_size=2 [2010-06-28 18:31:37] 8208eb98 AP_Session::ReadMsg - decoded_pdu size= 2 [2010-06-28 18:31:37] 8208eb98 AP_Session::ReadMsg - decoded pdu = (length='2') [2010-06-28 18:31:37] 8208eb98 AP_Session::ReadMsg - 6e 00 [2010-06-28 18:31:37] 8208eb98 RA_pblock::free_pblock - in free_pblock [2010-06-28 18:31:37] 8208eb98 RA_pblock::free_pblock - in free_pblock done [2010-06-28 18:31:37] 8208eb98 AP_Session::ReadMsg - ========= ReadMsg Ends ========= [2010-06-28 18:31:37] 8208eb98 RA_Processor::GetStatus - Bad Response [2010-06-28 18:31:37] 8208eb98 RA_Format_Processor::Process - Major=0 Minor=0 [2010-06-28 18:31:37] 8208eb98 RA_Format_Processor::Process - Applet Major=0 Applet Minor=0 [2010-06-28 18:31:37] 8208eb98 RA_Processor::GetTokenType - Starting: [2010-06-28 18:31:37] 8208eb98 RA_Processor::GetTokenType - mappingId='0' [2010-06-28 18:31:37] 8208eb98 RA_Processor::GetTokenType - tokenType: soCleanUserToken [2010-06-28 18:31:37] 8208eb98 RA_Processor::GetTokenType - mappingId='1' [2010-06-28 18:31:37] 8208eb98 RA_Processor::GetTokenType - tokenType: soUserKey [2010-06-28 18:31:37] 8208eb98 RA_Processor::GetTokenType - mappingId='2' [2010-06-28 18:31:37] 8208eb98 RA_Processor::GetTokenType - tokenType: soKey [2010-06-28 18:31:37] 8208eb98 RA_Processor::GetTokenType - mappingId='3' [2010-06-28 18:31:37] 8208eb98 RA_Processor::GetTokenType - tokenType: userKey [2010-06-28 18:31:37] 8208eb98 RA_Processor::GetTokenType - Selected Token type is 'userKey' [2010-06-28 18:31:37] 8208eb98 RA_Format_Processor::Process - Not Found token 4250503933F602052223 [2010-06-28 18:31:37] 8208eb98 AP_Session::WriteMsg - pdu_len='5' [2010-06-28 18:31:37] 8208eb98 AP_Session::WriteMsg - Sent 's=46&msg_type=9&pdu_size=5&pdu_data=%B0%70%00%00%04' [2010-06-28 18:31:37] 8208eb98 RA_Processor::GetAppletVersion - Sent get_version_request_msg [2010-06-28 18:31:37] 8208eb98 AP_Session::ReadMsg - ========== ReadMsg Begins ======= [2010-06-28 18:31:37] 8208eb98 AP_Session::ReadMsg - msg_len=36 [2010-06-28 18:31:37] 8208eb98 AP_Session::ReadMsg - Received len='36' msg='msg_type=10&pdu_size=2&pdu_data=n%00' [2010-06-28 18:31:37] 8208eb98 AP_Session::create_pblock - Data 'msg_type=10&pdu_size=2&pdu_data=n%00' [2010-06-28 18:31:37] 8208eb98 AP_Session::create_pblock - Found Arguments=3, nalloc=50 [2010-06-28 18:31:37] 8208eb98 AP_Session::create_pblock - entry name=msg_type, value=10 [2010-06-28 18:31:37] 8208eb98 AP_Session::create_pblock - entry name=pdu_size, value=2 [2010-06-28 18:31:37] 8208eb98 AP_Session::create_pblock - entry name=pdu_data, value=n%00 [2010-06-28 18:31:37] 8208eb98 AP_Session::ReadMsg - Found msg_type=TOKEN_PDU_RESPONSE (10) [2010-06-28 18:31:37] 8208eb98 AP_Session::ReadMsg - Found pdu_size=2 [2010-06-28 18:31:37] 8208eb98 AP_Session::ReadMsg - decoded_pdu size= 2 [2010-06-28 18:31:37] 8208eb98 AP_Session::ReadMsg - decoded pdu = (length='2') [2010-06-28 18:31:37] 8208eb98 AP_Session::ReadMsg - 6e 00 [2010-06-28 18:31:37] 8208eb98 RA_pblock::free_pblock - in free_pblock [2010-06-28 18:31:37] 8208eb98 RA_pblock::free_pblock - in free_pblock done [2010-06-28 18:31:37] 8208eb98 AP_Session::ReadMsg - ========= ReadMsg Ends ========= [2010-06-28 18:31:37] 8208eb98 RA_Processor::GetAppletVersion - Bad Response [2010-06-28 18:31:37] 8208eb98 RA_Format_Processor - final_applet_version = [2010-06-28 18:31:37] 8208eb98 RA_Enroll_Processor::RequestUserId - Extended Login Request detected [2010-06-28 18:31:37] 8208eb98 RA_Enroll_Processor::AuthenticateUser - Authentication enabled [2010-06-28 18:31:39] 800b1c60 RA::InitializeInChild - begins: 2 [2010-06-28 18:31:39] 800b1c60 RA::InitializeInChild - NSS already initialized [2010-06-28 18:31:39] 800b1c60 RA::InitializeHttpConnections - A ca certificate nicknamed "subsystemCert cert-pki-tps" was found in the certificate database for connection 1. [2010-06-28 18:31:39] 800b1c60 RA::InitializeHttpConnections - A tks certificate nicknamed "subsystemCert cert-pki-tps" was found in the certificate database for connection 1. [2010-06-28 18:31:39] 800b1c60 RA::InitializeHttpConnections - A drm certificate nicknamed "subsystemCert cert-pki-tps" was found in the certificate database for connection 1. [2010-06-28 18:31:39] 800b1c60 RA::InitializeInChild - nSignedAuditInitCount=2 [2010-06-28 18:31:39] 800b1c60 RA:: InitializeSignedAudit - begins /var/log/pki-tps/tps-error.log [2010-06-28 18:31:36] 8208eb98 RA_Processor::SelectApplet - Bad Response [2010-06-28 18:31:37] 8208eb98 RA_Processor::GetStatus - Bad Response [2010-06-28 18:31:37] 8208eb98 RA_Processor::GetAppletVersion - Bad Response /var/log/pki-tps/error_log [Mon Jun 28 18:31:38 2010] [notice] child pid 6700 exit signal Segmentation fault (11) [Mon Jun 28 18:31:39 2010] [info] Configuring server for SSL protocol [Mon Jun 28 18:31:39 2010] [debug] nss_engine_init.c(638): Enabling SSL3 [Mon Jun 28 18:31:39 2010] [debug] nss_engine_init.c(643): Enabling TLS [Mon Jun 28 18:31:39 2010] [debug] nss_engine_init.c(814): Configuring permitted SSL ciphers [-des,-desede3,-rc2,-rc2export,-rc4,-rc4export,+rsa_3des_sha,-rsa_des_56_sha,+rsa_des_sha,-rsa_null_md5,-rsa_null_sha,-rsa_rc2_40_md5,+rsa_rc4_128_md5,-rsa_rc4_128_sha,-rsa_rc4_40_md5,-rsa_rc4_56_sha,-fortezza,-fortezza_rc4_128_sha,-fortezza_null,-fips_des_sha,+fips_3des_sha,-rsa_aes_128_sha,-rsa_aes_256_sha,+ecdhe_ecdsa_aes_256_sha] [Mon Jun 28 18:31:39 2010] [info] Using nickname Server-Cert cert-pki-tps. [Mon Jun 28 18:31:39 2010] [info] Configuring server for SSL protocol [Mon Jun 28 18:31:39 2010] [debug] nss_engine_init.c(638): Enabling SSL3 [Mon Jun 28 18:31:39 2010] [debug] nss_engine_init.c(643): Enabling TLS [Mon Jun 28 18:31:39 2010] [debug] nss_engine_init.c(814): Configuring permitted SSL ciphers [-des,-desede3,-rc2,-rc2export,-rc4,-rc4export,+rsa_3des_sha,-rsa_des_56_sha,+rsa_des_sha,-rsa_null_md5,-rsa_null_sha,-rsa_rc2_40_md5,+rsa_rc4_128_md5,-rsa_rc4_128_sha,-rsa_rc4_40_md5,-rsa_rc4_56_sha,-fortezza,-fortezza_rc4_128_sha,-fortezza_null,-fips_des_sha,+fips_3des_sha,-rsa_aes_128_sha,-rsa_aes_256_sha,+ecdhe_ecdsa_aes_256_sha] [Mon Jun 28 18:31:39 2010] [info] Using nickname Server-Cert cert-pki-tps. /var/log/pki-tps/tps-audit.log [2010-06-28 18:31:39] 800b1c60 [AuditEvent=AUDIT_LOG_STARTUP][SubjectID=System][Outcome=Success] audit function startup Best regards -- -- Danilo Câmara
I'll have to take a closer look in a bit, but it appears that the host may have gone down and restarted near the beginning of the process. It may be possible that we need a different AID configuration for this card's card manager application. ----- Original Message ----- From: "Danilo Câmara" <fcdanilo@gmail.com> To: pki-users@redhat.com Sent: Monday, June 28, 2010 7:34:38 PM GMT -08:00 US/Canada Pacific Subject: [Pki-users] Error: The Smart Card Manager has lost the connection to the Smart Card Server. I set up a Dogtag Certificate System in a fresh CentOS 5.5 server and AFAIK everything went fine. When I insert the card (Samsung S3CC9P9 - Java Card 2.2.1, Open Platform v2.0.1) in a Fedora 13 desktop, the Smart Card Manager successfully tests the TPS Config URI and reports: Smart Card Server config information successfully obtained! Then it identifies the card as "Unformated", but when I try to format I get the error: Formatting of smart card failed. Error: The Smart Card Manager has lost the connection to the Smart Card Server. In the client, "Diagnostics" reports: SMART CARD DIAGNOSTICS REPORT ***Software Version Information*** Smart Card Manager Version: 1.1.0-12.fc13 System Versions: mozilla/5.0 (x11; u; linux x86_64; en-us; rv:1.9.2.4) gecko/20100622 fedora/1.9.2.4-1.fc13 ***Active Smart Card Details*** Number of Smart Cards Detected: 1 Smart Card CoolKey 02052223: Smart Card Applet Version: 0.0 Key ID: 4250503933f602052223 Status: Unformatted Issuer: Fedora Project Atr: 3B690000806331460183FF9000 Phone Home URL: http://ca.abcd.edu.br:7888/cgi-bin/home/index.cgi?cuid=4250503933f602052223 Smart Card Server URL: http://ca.abcd.edu.br:7888/nk_service Enrollment UI URL: http://ca.abcd.edu.br:7888/cgi-bin/home/enroll.cgi ***Smart Card Activity*** [Mon 28 Jun 2010 07:29:06 PM BRT] NSS system intialized successfully! [Mon 28 Jun 2010 07:29:09 PM BRT] Attempting to phone home for Key 4250503933f602052223 [Mon 28 Jun 2010 07:29:09 PM BRT] Attempting to get key issuer info. Can't select CoolKey manager! [Mon 28 Jun 2010 07:29:09 PM BRT] Attempting to get the key's Issuer: Key: 4250503933f602052223, Issuer . [Mon 28 Jun 2010 07:29:09 PM BRT] IsPhoneHomeCached keyID: 4250503933f602052223 IsCached: false [Mon 28 Jun 2010 07:30:55 PM BRT] Actually phoning Home for Key: 4250503933f602052223 URI: http://ca.abcd.edu.br:7888/cgi-bin/home/index.cgi [Mon 28 Jun 2010 07:30:56 PM BRT] Phone Home config value for Key: 4250503933f602052223 ConfigKey: Operation-4250503933f602052223 ConfigValue: http://ca.abcd.edu.br:7888/nk_service [Mon 28 Jun 2010 07:30:56 PM BRT] Phone Home config value for Key: 4250503933f602052223 ConfigKey: UI-4250503933f602052223 ConfigValue: http://ca.abcd.edu.br:7888/cgi-bin/home/enroll.cgi [Mon 28 Jun 2010 07:30:56 PM BRT] Phone Home config value for Key: 4250503933f602052223 ConfigKey: EnrolledTokenBrowserURL-4250503933f602052223 ConfigValue: http://www.fedora.redhat.com [Mon 28 Jun 2010 07:30:56 PM BRT] Phone Home config value for Key: 4250503933f602052223 ConfigKey: TokenType-4250503933f602052223 ConfigValue: userKey [Mon 28 Jun 2010 07:30:57 PM BRT] Phone Home config value for Key: 4250503933f602052223 ConfigKey: keyIssuerUrl-4250503933f602052223 ConfigValue: http://ca.abcd.edu.br:7888/cgi-bin/home/index.cgi?cuid=4250503933f602052223 [Mon 28 Jun 2010 07:31:35 PM BRT] Attempting to Format Key, ID: 4250503933f602052223. [Mon 28 Jun 2010 07:31:38 PM BRT] Processing HTTP message. Write back to TPS failed , disconnecting. [Mon 28 Jun 2010 07:31:38 PM BRT] Key Format failure. Error: 28. In the server I got the logs: /var/log/pki-tps/access_log 189.104.62.234 - - [28/Jun/2010:18:30:56 -0400] "GET /cgi-bin/home/index.cgi?cuid=4250503933f602052223 HTTP/1.1" 200 409 /var/log/pki-tps/tps-debug.log [2010-06-28 18:31:35] 8208eb98 mod_tps::mod_tps_handler - mod_tps::mod_tps_handler [2010-06-28 18:31:35] 8208eb98 mod_tps::mod_tps_handler - uri '/nk_service' [2010-06-28 18:31:35] 8208eb98 mod_tps::mod_tps_handler - uri '/nk_service' DONE [2010-06-28 18:31:35] 8208eb98 AP_Session::ReadMsg - ========== ReadMsg Begins ======= [2010-06-28 18:31:35] 8208eb98 AP_Session::ReadMsg - msg_len=180 [2010-06-28 18:31:35] 8208eb98 AP_Session::ReadMsg - Received len='180' msg='msg_type=2&operation=5&extensions=tokenType%3DuserKey%26clientVersion%3DESC+1%2E0%2E1%26tokenATR%3D3B690000806331460183FF9000%26statusUpdate%3Dtrue%26extendedLoginRequest%3Dtrue%26' [2010-06-28 18:31:35] 8208eb98 AP_Session::create_pblock - Data 'msg_type=2&operation=5&extensions=tokenType%3DuserKey%26clientVersion%3DESC+1%2E0%2E1%26tokenATR%3D3B690000806331460183FF9000%26statusUpdate%3Dtrue%26extendedLoginRequest%3Dtrue%26' [2010-06-28 18:31:35] 8208eb98 AP_Session::create_pblock - Found Arguments=3, nalloc=50 [2010-06-28 18:31:35] 8208eb98 AP_Session::create_pblock - entry name=msg_type, value=2 [2010-06-28 18:31:35] 8208eb98 AP_Session::create_pblock - entry name=operation, value=5 [2010-06-28 18:31:35] 8208eb98 AP_Session::create_pblock - entry name=extensions, value=tokenType%3DuserKey%26clientVersion%3DESC+1%2E0%2E1%26tokenATR%3D3B690000806331460183FF9000%26statusUpdate%3Dtrue%26extendedLoginRequest%3Dtrue%26 [2010-06-28 18:31:35] 8208eb98 AP_Session::ReadMsg - Found msg_type=BEGIN_OP (2) [2010-06-28 18:31:35] 8208eb98 AP_Session::ReadMsg - content= (length='1') [2010-06-28 18:31:35] 8208eb98 AP_Session::ReadMsg - 35 [2010-06-28 18:31:35] 8208eb98 AP_Session::ReadMsg - Extensions tokenType=userKey&clientVersion=ESC 1.0.1&tokenATR=3B690000806331460183FF9000&statusUpdate=true&extendedLoginRequest=true& [2010-06-28 18:31:35] 8208eb98 AP_Session::ReadMsg - begin_op_msg msg_type=FORMAT [2010-06-28 18:31:35] 8208eb98 RA_pblock::free_pblock - in free_pblock [2010-06-28 18:31:35] 8208eb98 RA_pblock::free_pblock - in free_pblock done [2010-06-28 18:31:35] 8208eb98 AP_Session::ReadMsg - ========= ReadMsg Ends ========= [2010-06-28 18:31:35] 8208eb98 RA_Format_Processor::Process - Begin upgrade process [2010-06-28 18:31:35] 8208eb98 RA_Format_Processor::Process - Client 189.104.62.234 [2010-06-28 18:31:35] 8208eb98 RA_Processor::SelectApplet - RA_Processor::SelectApplet with aid= (length='7') [2010-06-28 18:31:35] 8208eb98 RA_Processor::SelectApplet - a0 00 00 00 03 00 00 [2010-06-28 18:31:35] 8208eb98 AP_Session::WriteMsg - pdu_len='12' [2010-06-28 18:31:35] 8208eb98 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' [2010-06-28 18:31:35] 8208eb98 RA_Processor::SelectApplet - Sent select_request_msg [2010-06-28 18:31:35] 8208eb98 AP_Session::ReadMsg - ========== ReadMsg Begins ======= [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - msg_len=112 [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - Received len='112' msg='msg_type=10&pdu_size=29&pdu_data=o%19%84%08%A0%00%00%00%03%00%00%00%A5%0D%9Fn%06%10%01v%DE%00%05%9Fe%01%7F%90%00' [2010-06-28 18:31:36] 8208eb98 AP_Session::create_pblock - Data 'msg_type=10&pdu_size=29&pdu_data=o%19%84%08%A0%00%00%00%03%00%00%00%A5%0D%9Fn%06%10%01v%DE%00%05%9Fe%01%7F%90%00' [2010-06-28 18:31:36] 8208eb98 AP_Session::create_pblock - Found Arguments=3, nalloc=50 [2010-06-28 18:31:36] 8208eb98 AP_Session::create_pblock - entry name=msg_type, value=10 [2010-06-28 18:31:36] 8208eb98 AP_Session::create_pblock - entry name=pdu_size, value=29 [2010-06-28 18:31:36] 8208eb98 AP_Session::create_pblock - entry name=pdu_data, value=o%19%84%08%A0%00%00%00%03%00%00%00%A5%0D%9Fn%06%10%01v%DE%00%05%9Fe%01%7F%90%00 [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - Found msg_type=TOKEN_PDU_RESPONSE (10) [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - Found pdu_size=29 [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - decoded_pdu size= 29 [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - decoded pdu = (length='29') [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - 6f 19 84 08 a0 00 00 00 03 00 [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - 00 00 a5 0d 9f 6e 06 10 01 76 [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - de 00 05 9f 65 01 7f 90 00 [2010-06-28 18:31:36] 8208eb98 RA_pblock::free_pblock - in free_pblock [2010-06-28 18:31:36] 8208eb98 RA_pblock::free_pblock - in free_pblock done [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - ========= ReadMsg Ends ========= [2010-06-28 18:31:36] 8208eb98 AP_Session::WriteMsg - pdu_len='5' [2010-06-28 18:31:36] 8208eb98 AP_Session::WriteMsg - Sent 's=46&msg_type=9&pdu_size=5&pdu_data=%80%CA%9F%7F%2D' [2010-06-28 18:31:36] 8208eb98 RA_Processor::GetData - Sent get_data_request_msg [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - ========== ReadMsg Begins ======= [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - msg_len=144 [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - Received len='144' msg='msg_type=10&pdu_size=47&pdu_data=%9F%7F%2ABPP9%10%01v%DE%00%05q%18%02%05%22%233%F6BRq%27SSv%DE%00%00v%DE%AA%BB%CC%DD%00%00v%DE%AA%BB%CC%DD%90%00' [2010-06-28 18:31:36] 8208eb98 AP_Session::create_pblock - Data 'msg_type=10&pdu_size=47&pdu_data=%9F%7F%2ABPP9%10%01v%DE%00%05q%18%02%05%22%233%F6BRq%27SSv%DE%00%00v%DE%AA%BB%CC%DD%00%00v%DE%AA%BB%CC%DD%90%00' [2010-06-28 18:31:36] 8208eb98 AP_Session::create_pblock - Found Arguments=3, nalloc=50 [2010-06-28 18:31:36] 8208eb98 AP_Session::create_pblock - entry name=msg_type, value=10 [2010-06-28 18:31:36] 8208eb98 AP_Session::create_pblock - entry name=pdu_size, value=47 [2010-06-28 18:31:36] 8208eb98 AP_Session::create_pblock - entry name=pdu_data, value=%9F%7F%2ABPP9%10%01v%DE%00%05q%18%02%05%22%233%F6BRq%27SSv%DE%00%00v%DE%AA%BB%CC%DD%00%00v%DE%AA%BB%CC%DD%90%00 [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - Found msg_type=TOKEN_PDU_RESPONSE (10) [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - Found pdu_size=47 [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - decoded_pdu size= 47 [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - decoded pdu = (length='47') [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - 9f 7f 2a 42 50 50 39 10 01 76 [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - de 00 05 71 18 02 05 22 23 33 [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - f6 42 52 71 27 53 53 76 de 00 [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - 00 76 de aa bb cc dd 00 00 76 [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - de aa bb cc dd 90 00 [2010-06-28 18:31:36] 8208eb98 RA_pblock::free_pblock - in free_pblock [2010-06-28 18:31:36] 8208eb98 RA_pblock::free_pblock - in free_pblock done [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - ========= ReadMsg Ends ========= [2010-06-28 18:31:36] 8208eb98 RA_Format_Processor::process - CPLC Data = (length='47') [2010-06-28 18:31:36] 8208eb98 RA_Format_Processor::process - 9f 7f 2a 42 50 50 39 10 01 76 [2010-06-28 18:31:36] 8208eb98 RA_Format_Processor::process - de 00 05 71 18 02 05 22 23 33 [2010-06-28 18:31:36] 8208eb98 RA_Format_Processor::process - f6 42 52 71 27 53 53 76 de 00 [2010-06-28 18:31:36] 8208eb98 RA_Format_Processor::process - 00 76 de aa bb cc dd 00 00 76 [2010-06-28 18:31:36] 8208eb98 RA_Format_Processor::process - de aa bb cc dd 90 00 [2010-06-28 18:31:36] 8208eb98 RA_Format_Processor::process - Token CUID= (length='10') [2010-06-28 18:31:36] 8208eb98 RA_Format_Processor::process - 42 50 50 39 33 f6 02 05 22 23 [2010-06-28 18:31:36] 8208eb98 RA_Format_Processor::process - [2010-06-28 18:31:36] 8208eb98 RA_Format_Processor::process - Token MSN= (length='4') [2010-06-28 18:31:36] 8208eb98 RA_Format_Processor::process - aa bb cc dd [2010-06-28 18:31:36] 8208eb98 RA_Processor::SelectApplet - RA_Processor::SelectApplet with aid= (length='7') [2010-06-28 18:31:36] 8208eb98 RA_Processor::SelectApplet - 62 76 01 ff 00 00 00 [2010-06-28 18:31:36] 8208eb98 AP_Session::WriteMsg - pdu_len='12' [2010-06-28 18:31:36] 8208eb98 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' [2010-06-28 18:31:36] 8208eb98 RA_Processor::SelectApplet - Sent select_request_msg [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - ========== ReadMsg Begins ======= [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - msg_len=36 [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - Received len='36' msg='msg_type=10&pdu_size=2&pdu_data=j%82' [2010-06-28 18:31:36] 8208eb98 AP_Session::create_pblock - Data 'msg_type=10&pdu_size=2&pdu_data=j%82' [2010-06-28 18:31:36] 8208eb98 AP_Session::create_pblock - Found Arguments=3, nalloc=50 [2010-06-28 18:31:36] 8208eb98 AP_Session::create_pblock - entry name=msg_type, value=10 [2010-06-28 18:31:36] 8208eb98 AP_Session::create_pblock - entry name=pdu_size, value=2 [2010-06-28 18:31:36] 8208eb98 AP_Session::create_pblock - entry name=pdu_data, value=j%82 [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - Found msg_type=TOKEN_PDU_RESPONSE (10) [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - Found pdu_size=2 [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - decoded_pdu size= 2 [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - decoded pdu = (length='2') [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - 6a 82 [2010-06-28 18:31:36] 8208eb98 RA_pblock::free_pblock - in free_pblock [2010-06-28 18:31:36] 8208eb98 RA_pblock::free_pblock - in free_pblock done [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - ========= ReadMsg Ends ========= [2010-06-28 18:31:36] 8208eb98 RA_Processor::SelectApplet - Bad Response [2010-06-28 18:31:36] 8208eb98 AP_Session::WriteMsg - pdu_len='5' [2010-06-28 18:31:36] 8208eb98 AP_Session::WriteMsg - Sent 's=46&msg_type=9&pdu_size=5&pdu_data=%B0%3C%00%00%10' [2010-06-28 18:31:36] 8208eb98 RA_Processor::GetStatus - Sent get_status_request_msg [2010-06-28 18:31:36] 8208eb98 AP_Session::ReadMsg - ========== ReadMsg Begins ======= [2010-06-28 18:31:37] 8208eb98 AP_Session::ReadMsg - msg_len=36 [2010-06-28 18:31:37] 8208eb98 AP_Session::ReadMsg - Received len='36' msg='msg_type=10&pdu_size=2&pdu_data=n%00' [2010-06-28 18:31:37] 8208eb98 AP_Session::create_pblock - Data 'msg_type=10&pdu_size=2&pdu_data=n%00' [2010-06-28 18:31:37] 8208eb98 AP_Session::create_pblock - Found Arguments=3, nalloc=50 [2010-06-28 18:31:37] 8208eb98 AP_Session::create_pblock - entry name=msg_type, value=10 [2010-06-28 18:31:37] 8208eb98 AP_Session::create_pblock - entry name=pdu_size, value=2 [2010-06-28 18:31:37] 8208eb98 AP_Session::create_pblock - entry name=pdu_data, value=n%00 [2010-06-28 18:31:37] 8208eb98 AP_Session::ReadMsg - Found msg_type=TOKEN_PDU_RESPONSE (10) [2010-06-28 18:31:37] 8208eb98 AP_Session::ReadMsg - Found pdu_size=2 [2010-06-28 18:31:37] 8208eb98 AP_Session::ReadMsg - decoded_pdu size= 2 [2010-06-28 18:31:37] 8208eb98 AP_Session::ReadMsg - decoded pdu = (length='2') [2010-06-28 18:31:37] 8208eb98 AP_Session::ReadMsg - 6e 00 [2010-06-28 18:31:37] 8208eb98 RA_pblock::free_pblock - in free_pblock [2010-06-28 18:31:37] 8208eb98 RA_pblock::free_pblock - in free_pblock done [2010-06-28 18:31:37] 8208eb98 AP_Session::ReadMsg - ========= ReadMsg Ends ========= [2010-06-28 18:31:37] 8208eb98 RA_Processor::GetStatus - Bad Response [2010-06-28 18:31:37] 8208eb98 RA_Format_Processor::Process - Major=0 Minor=0 [2010-06-28 18:31:37] 8208eb98 RA_Format_Processor::Process - Applet Major=0 Applet Minor=0 [2010-06-28 18:31:37] 8208eb98 RA_Processor::GetTokenType - Starting: [2010-06-28 18:31:37] 8208eb98 RA_Processor::GetTokenType - mappingId='0' [2010-06-28 18:31:37] 8208eb98 RA_Processor::GetTokenType - tokenType: soCleanUserToken [2010-06-28 18:31:37] 8208eb98 RA_Processor::GetTokenType - mappingId='1' [2010-06-28 18:31:37] 8208eb98 RA_Processor::GetTokenType - tokenType: soUserKey [2010-06-28 18:31:37] 8208eb98 RA_Processor::GetTokenType - mappingId='2' [2010-06-28 18:31:37] 8208eb98 RA_Processor::GetTokenType - tokenType: soKey [2010-06-28 18:31:37] 8208eb98 RA_Processor::GetTokenType - mappingId='3' [2010-06-28 18:31:37] 8208eb98 RA_Processor::GetTokenType - tokenType: userKey [2010-06-28 18:31:37] 8208eb98 RA_Processor::GetTokenType - Selected Token type is 'userKey' [2010-06-28 18:31:37] 8208eb98 RA_Format_Processor::Process - Not Found token 4250503933F602052223 [2010-06-28 18:31:37] 8208eb98 AP_Session::WriteMsg - pdu_len='5' [2010-06-28 18:31:37] 8208eb98 AP_Session::WriteMsg - Sent 's=46&msg_type=9&pdu_size=5&pdu_data=%B0%70%00%00%04' [2010-06-28 18:31:37] 8208eb98 RA_Processor::GetAppletVersion - Sent get_version_request_msg [2010-06-28 18:31:37] 8208eb98 AP_Session::ReadMsg - ========== ReadMsg Begins ======= [2010-06-28 18:31:37] 8208eb98 AP_Session::ReadMsg - msg_len=36 [2010-06-28 18:31:37] 8208eb98 AP_Session::ReadMsg - Received len='36' msg='msg_type=10&pdu_size=2&pdu_data=n%00' [2010-06-28 18:31:37] 8208eb98 AP_Session::create_pblock - Data 'msg_type=10&pdu_size=2&pdu_data=n%00' [2010-06-28 18:31:37] 8208eb98 AP_Session::create_pblock - Found Arguments=3, nalloc=50 [2010-06-28 18:31:37] 8208eb98 AP_Session::create_pblock - entry name=msg_type, value=10 [2010-06-28 18:31:37] 8208eb98 AP_Session::create_pblock - entry name=pdu_size, value=2 [2010-06-28 18:31:37] 8208eb98 AP_Session::create_pblock - entry name=pdu_data, value=n%00 [2010-06-28 18:31:37] 8208eb98 AP_Session::ReadMsg - Found msg_type=TOKEN_PDU_RESPONSE (10) [2010-06-28 18:31:37] 8208eb98 AP_Session::ReadMsg - Found pdu_size=2 [2010-06-28 18:31:37] 8208eb98 AP_Session::ReadMsg - decoded_pdu size= 2 [2010-06-28 18:31:37] 8208eb98 AP_Session::ReadMsg - decoded pdu = (length='2') [2010-06-28 18:31:37] 8208eb98 AP_Session::ReadMsg - 6e 00 [2010-06-28 18:31:37] 8208eb98 RA_pblock::free_pblock - in free_pblock [2010-06-28 18:31:37] 8208eb98 RA_pblock::free_pblock - in free_pblock done [2010-06-28 18:31:37] 8208eb98 AP_Session::ReadMsg - ========= ReadMsg Ends ========= [2010-06-28 18:31:37] 8208eb98 RA_Processor::GetAppletVersion - Bad Response [2010-06-28 18:31:37] 8208eb98 RA_Format_Processor - final_applet_version = [2010-06-28 18:31:37] 8208eb98 RA_Enroll_Processor::RequestUserId - Extended Login Request detected [2010-06-28 18:31:37] 8208eb98 RA_Enroll_Processor::AuthenticateUser - Authentication enabled [2010-06-28 18:31:39] 800b1c60 RA::InitializeInChild - begins: 2 [2010-06-28 18:31:39] 800b1c60 RA::InitializeInChild - NSS already initialized [2010-06-28 18:31:39] 800b1c60 RA::InitializeHttpConnections - A ca certificate nicknamed "subsystemCert cert-pki-tps" was found in the certificate database for connection 1. [2010-06-28 18:31:39] 800b1c60 RA::InitializeHttpConnections - A tks certificate nicknamed "subsystemCert cert-pki-tps" was found in the certificate database for connection 1. [2010-06-28 18:31:39] 800b1c60 RA::InitializeHttpConnections - A drm certificate nicknamed "subsystemCert cert-pki-tps" was found in the certificate database for connection 1. [2010-06-28 18:31:39] 800b1c60 RA::InitializeInChild - nSignedAuditInitCount=2 [2010-06-28 18:31:39] 800b1c60 RA:: InitializeSignedAudit - begins /var/log/pki-tps/tps-error.log [2010-06-28 18:31:36] 8208eb98 RA_Processor::SelectApplet - Bad Response [2010-06-28 18:31:37] 8208eb98 RA_Processor::GetStatus - Bad Response [2010-06-28 18:31:37] 8208eb98 RA_Processor::GetAppletVersion - Bad Response /var/log/pki-tps/error_log [Mon Jun 28 18:31:38 2010] [notice] child pid 6700 exit signal Segmentation fault (11) [Mon Jun 28 18:31:39 2010] [info] Configuring server for SSL protocol [Mon Jun 28 18:31:39 2010] [debug] nss_engine_init.c(638): Enabling SSL3 [Mon Jun 28 18:31:39 2010] [debug] nss_engine_init.c(643): Enabling TLS [Mon Jun 28 18:31:39 2010] [debug] nss_engine_init.c(814): Configuring permitted SSL ciphers [-des,-desede3,-rc2,-rc2export,-rc4,-rc4export,+rsa_3des_sha,-rsa_des_56_sha,+rsa_des_sha,-rsa_null_md5,-rsa_null_sha,-rsa_rc2_40_md5,+rsa_rc4_128_md5,-rsa_rc4_128_sha,-rsa_rc4_40_md5,-rsa_rc4_56_sha,-fortezza,-fortezza_rc4_128_sha,-fortezza_null,-fips_des_sha,+fips_3des_sha,-rsa_aes_128_sha,-rsa_aes_256_sha,+ecdhe_ecdsa_aes_256_sha] [Mon Jun 28 18:31:39 2010] [info] Using nickname Server-Cert cert-pki-tps. [Mon Jun 28 18:31:39 2010] [info] Configuring server for SSL protocol [Mon Jun 28 18:31:39 2010] [debug] nss_engine_init.c(638): Enabling SSL3 [Mon Jun 28 18:31:39 2010] [debug] nss_engine_init.c(643): Enabling TLS [Mon Jun 28 18:31:39 2010] [debug] nss_engine_init.c(814): Configuring permitted SSL ciphers [-des,-desede3,-rc2,-rc2export,-rc4,-rc4export,+rsa_3des_sha,-rsa_des_56_sha,+rsa_des_sha,-rsa_null_md5,-rsa_null_sha,-rsa_rc2_40_md5,+rsa_rc4_128_md5,-rsa_rc4_128_sha,-rsa_rc4_40_md5,-rsa_rc4_56_sha,-fortezza,-fortezza_rc4_128_sha,-fortezza_null,-fips_des_sha,+fips_3des_sha,-rsa_aes_128_sha,-rsa_aes_256_sha,+ecdhe_ecdsa_aes_256_sha] [Mon Jun 28 18:31:39 2010] [info] Using nickname Server-Cert cert-pki-tps. /var/log/pki-tps/tps-audit.log [2010-06-28 18:31:39] 800b1c60 [AuditEvent=AUDIT_LOG_STARTUP][SubjectID=System][Outcome=Success] audit function startup Best regards -- -- Danilo Câmara _______________________________________________ Pki-users mailing list Pki-users@redhat.com https://www.redhat.com/mailman/listinfo/pki-users
participants (2)
-
Danilo Câmara -
John Magne