9:34 p.m.
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
11:44 a.m.
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(a)gmail.com>
To: pki-users(a)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(a)redhat.com
https://www.redhat.com/mailman/listinfo/pki-users
5050
days inactive
5050
days old
1 comments
2 participants
participants (2)
-
Danilo Câmara -
John Magne