[Pki-users] "Format" button never enabled in Enterprise Security Client
Steve Ross
sross at trustedcs.com
Tue Sep 24 19:39:51 UTC 2013
Hi Jack, thanks for your suggestions. My responses are in-line, below.
-- Steve Ross
On 09/23/2013 07:20 PM, John Magne wrote:
> Steve greetings:
>
> Comments below:
>
>
>
> ----- Original Message -----
>> From: "Steve Ross" <sross at trustedcs.com>
>> To: "John Magne" <jmagne at redhat.com>
>> Cc: pki-users at redhat.com
>> Sent: Monday, September 23, 2013 4:45:22 PM
>> Subject: Re: [Pki-users] "Format" button never enabled in Enterprise Security Client
>>
>> Jack,
>>
>> Thanks for your quick reply.
>>
>> Regarding "Phone Home", I believe that both TPS and ESC are set up
>> correctly by default. For example, the TPS "CS.cfg" file contains the
>> lines:
>> ...
>> op.enroll.userKey.issuerinfo.enable=true
>> op.enroll.userKey.issuerinfo.value=http://dhcp-12-90.il.tcs-sec.com:7888/cgi-bin/home/index.cgi
>> ...
>> op.format.userKey.issuerinfo.enable=true
>> op.format.userKey.issuerinfo.value=http://dhcp-12-90.il.tcs-sec.com:7888/cgi-bin/home/index.cgi
>>
>> By using the "netstat" command, I can see that my TPS process is
>> listening on ports 7888, 7889, and 7890.
>>
>> The file "/var/lib/pki-tps/cgi-bin/home/index.cgi", which I haven't
>> edited, produces:
>>
>> <ServiceInfo>
>> <IssuerName>Fedora Project</IssuerName>
>> <Services>
>> <Operation>http://dhcp-12-90.il.tcs-sec.com:7888/nk_service</Operation>
>> <UI>http://dhcp-12-90.il.tcs-sec.com:7888/cgi-bin/home/enroll.cgi</UI>
>> <EnrolledTokenBrowserURL>http://www.fedora.redhat.com</EnrolledTokenBrowserURL>
>> <EnrolledTokenURL></EnrolledTokenURL>
>> <TokenType>userKey</TokenType>
>> </Services>
>> </ServiceInfo>
>>
>> which again references port 7888.
>>
>>
>> I have edited the file
>> "user/lib/esc-1.1.0/defaults/preferences/esc-prefs.js", where I've set:
>>
>> pref("esc.global.phone.home.url","http://dhcp-12-90.il.tcs-sec.com:7888/cgi-bin/home/index.cgi");
> OK, here is why you aren't getting the phone home dialog. This optional config param was put in for those that didn't
> want to be able to use a different phone home url for every token they use. This should prevent the dialog from coming up
> and the system should use that particular phone home url to contact the TPS server.
Regarding the above "pref" statement, I killed the "escd" and
"xulrunner" processes, commented out the statement, and restarted
"esc". However, I still do *not* see any "Phone Home" dialog after I
insert my unformatted smart card.
>
> One thing you could do is to hit that URL in a browser to make sure it is available. You should a printout of that tiny
> XML file you referenced above.
I verified that, as seen in a browser, I do indeed see the same 10-line
XML file that I referenced above from port 7888.
>
> Based on this, it sounds like that maybe your token was not properly recognized by the client.
>
>
> You could do the following:
>
> 1. Stop the pcscd daemon, I think it's service pcscd stop.
>
> 2. Run it in interactive mode. /usr/sbin/pcscd -d -f -a
>
> This will print out what is going on.
>
> 3. Bring up ESC again and insert the token.
>
> Have a look at the output and something might be useful for us to debug. Let us know.
My apologies for flooding this e-mail with a couple of long logs, but
here goes...
Following is the "pcscd" debug log with APDU's enabled. I don't really
know the APDU commands and responses, but it looks like the "pcscd" client:
1. Requested three different Applet IDs, and none were found.
2. Requested any Applet ID and received a response.
3. Requested data and was told that the request contained the wrong length.
and then the client repeated the same three steps, and then stopped.
Following is the log. I've added some comments following the pound/hash
symbol.
--- begin "pcscd" log ---
# Before executing "esc".
winscard_msg_srv.c:217:SHMProcessEventsServer() Common channel packet
arrival
winscard_msg_srv.c:226:SHMProcessEventsServer()
SHMProcessCommonChannelRequest detects: 7
pcscdaemon.c:174:SVCServiceRunLoop() A new context thread creation is
requested: 7
winscard_svc.c:131:ContextThread() Thread is started: 7
winscard_msg_srv.c:288:SHMProcessEventsContext() correctly processed
client: 7
winscard_svc.c:179:ContextThread() Client is protocol version 2:2
winscard_msg_srv.c:288:SHMProcessEventsContext() correctly processed
client: 7
winscard.c:242:SCardEstablishContext() Establishing Context: 17015714
winscard_msg_srv.c:288:SHMProcessEventsContext() correctly processed
client: 7
winscard.c:298:SCardConnect() Attempting Connect to OmniKey CardMan 3121
00 00 using protocol: 3
winscard.c:360:SCardConnect() Card Not Inserted
winscard_msg_srv.c:288:SHMProcessEventsContext() correctly processed
client: 7
winscard.c:298:SCardConnect() Attempting Connect to OmniKey CardMan 3121
00 00 using protocol: 3
winscard.c:360:SCardConnect() Card Not Inserted
winscard_msg_srv.c:288:SHMProcessEventsContext() correctly processed
client: 7
winscard.c:298:SCardConnect() Attempting Connect to OmniKey CardMan 3121
00 00 using protocol: 3
winscard.c:360:SCardConnect() Card Not Inserted
winscard_msg_srv.c:288:SHMProcessEventsContext() correctly processed
client: 7
winscard.c:298:SCardConnect() Attempting Connect to OmniKey CardMan 3121
00 00 using protocol: 3
winscard.c:360:SCardConnect() Card Not Inserted
# After executing "esc".
# Before inserting card
ifdhandler.c:924:IFDHPowerICC() lun: 0, action: PowerUp
winscard_msg_srv.c:288:SHMProcessEventsContext() correctly processed
client: 7
winscard.c:298:SCardConnect() Attempting Connect to OmniKey CardMan 3121
00 00 using protocol: 3
prothandler.c:130:PHSetProtocol() Attempting PTS to T=1
ifdhandler.c:488:IFDHSetProtocolParameters() lun: 0, protocol T=1
ifdhandler.c:1451:extra_egt() Extra EGT patch applied
winscard.c:433:SCardConnect() Active Protocol: T=1
winscard.c:443:SCardConnect() hCard Identity: 15e47
eventhandler.c:431:EHStatusHandlerThread() Card inserted into OmniKey
CardMan 3121 00 00
Card ATR: 3B F6 18 00 FF 81 31 FE 45 4A 32 41 30 38 30 1B
winscard_msg_srv.c:288:SHMProcessEventsContext() correctly processed
client: 7
winscard_msg_srv.c:288:SHMProcessEventsContext() correctly processed
client: 7
winscard_msg_srv.c:288:SHMProcessEventsContext() correctly processed
client: 7
winscard.c:1023:SCardBeginTransaction() Status: 0x00000000
winscard_msg_srv.c:288:SHMProcessEventsContext() correctly processed
client: 7
winscard.c:1601:SCardTransmit() Send Protocol: T=1
APDU: 00 A4 04 00 07 62 76 01 FF 00 00 00
ifdhandler.c:1035:IFDHTransmitToICC() lun: 0
SW: 6A 82
winscard_msg_srv.c:288:SHMProcessEventsContext() correctly processed
client: 7
winscard.c:1601:SCardTransmit() Send Protocol: T=1
APDU: 00 A4 04 00 07 A0 00 00 01 16 DB 00
ifdhandler.c:1035:IFDHTransmitToICC() lun: 0
SW: 6A 82
winscard_msg_srv.c:288:SHMProcessEventsContext() correctly processed
client: 7
winscard.c:1601:SCardTransmit() Send Protocol: T=1
APDU: 00 A4 04 00 07 A0 00 00 00 79 01 00
ifdhandler.c:1035:IFDHTransmitToICC() lun: 0
SW: 6A 82
winscard_msg_srv.c:288:SHMProcessEventsContext() correctly processed
client: 7
winscard.c:1171:SCardEndTransaction() Status: 0x00000000
winscard_msg_srv.c:288:SHMProcessEventsContext() correctly processed
client: 7
winscard.c:1023:SCardBeginTransaction() Status: 0x00000000
winscard_msg_srv.c:288:SHMProcessEventsContext() correctly processed
client: 7
winscard.c:1601:SCardTransmit() Send Protocol: T=1
APDU: 00 A4 04 00 00
ifdhandler.c:1035:IFDHTransmitToICC() lun: 0
SW: 6F 65 84 08 A0 00 00 00 03 00 00 00 A5 59 9F 65 01 FF 9F 6E 06 47 91
00 78 33 00 73 4A 06 07 2A 86 48 86 FC 6B 01 60 0C 06 0A 2A 86 48 86 FC
6B 02 02 01 01 63 09 06 07 2A 86 48 86 FC 6B 03 64 0B 06 09 2A 86 48 86
FC 6B 04 02 15 65 0B 06 09 2B 85 10 86 48 64 02 01 03 66 0C 06 0A 2B 06
01 04 01 2A 02 6E 01 02 90 00
winscard_msg_srv.c:288:SHMProcessEventsContext() correctly processed
client: 7
winscard.c:1601:SCardTransmit() Send Protocol: T=1
APDU: 80 CA 9F 7F 2D
ifdhandler.c:1035:IFDHTransmitToICC() lun: 0
SW: 67 00
winscard_msg_srv.c:288:SHMProcessEventsContext() correctly processed
client: 7
winscard.c:1171:SCardEndTransaction() Status: 0x00000000
winscard_msg_srv.c:288:SHMProcessEventsContext() correctly processed
client: 7
... There are a total of 26 repetitions of this logging statement....
winscard_msg_srv.c:288:SHMProcessEventsContext() correctly processed
client: 7
winscard_msg_srv.c:217:SHMProcessEventsServer() Common channel packet
arrival
winscard_msg_srv.c:226:SHMProcessEventsServer()
SHMProcessCommonChannelRequest detects: 8
pcscdaemon.c:174:SVCServiceRunLoop() A new context thread creation is
requested: 8
winscard_svc.c:131:ContextThread() Thread is started: 8
winscard_msg_srv.c:288:SHMProcessEventsContext() correctly processed
client: 8
winscard_svc.c:179:ContextThread() Client is protocol version 2:2
winscard_msg_srv.c:288:SHMProcessEventsContext() correctly processed
client: 8
winscard.c:242:SCardEstablishContext() Establishing Context: 17006901
winscard_msg_srv.c:288:SHMProcessEventsContext() correctly processed
client: 8
winscard.c:298:SCardConnect() Attempting Connect to OmniKey CardMan 3121
00 00 using protocol: 3
winscard.c:433:SCardConnect() Active Protocol: T=1
winscard.c:443:SCardConnect() hCard Identity: 116b5
winscard_msg_srv.c:288:SHMProcessEventsContext() correctly processed
client: 8
winscard_msg_srv.c:288:SHMProcessEventsContext() correctly processed
client: 8
winscard_msg_srv.c:288:SHMProcessEventsContext() correctly processed
client: 8
winscard.c:1023:SCardBeginTransaction() Status: 0x00000000
winscard_msg_srv.c:288:SHMProcessEventsContext() correctly processed
client: 8
winscard.c:1601:SCardTransmit() Send Protocol: T=1
APDU: 00 A4 04 00 07 62 76 01 FF 00 00 00
ifdhandler.c:1035:IFDHTransmitToICC() lun: 0
SW: 6A 82
winscard_msg_srv.c:288:SHMProcessEventsContext() correctly processed
client: 8
winscard.c:1601:SCardTransmit() Send Protocol: T=1
APDU: 00 A4 04 00 07 A0 00 00 01 16 DB 00
ifdhandler.c:1035:IFDHTransmitToICC() lun: 0
SW: 6A 82
winscard_msg_srv.c:288:SHMProcessEventsContext() correctly processed
client: 8
winscard.c:1601:SCardTransmit() Send Protocol: T=1
APDU: 00 A4 04 00 07 A0 00 00 00 79 01 00
ifdhandler.c:1035:IFDHTransmitToICC() lun: 0
SW: 6A 82
winscard_msg_srv.c:288:SHMProcessEventsContext() correctly processed
client: 8
winscard.c:1171:SCardEndTransaction() Status: 0x00000000
winscard_msg_srv.c:288:SHMProcessEventsContext() correctly processed
client: 8
winscard.c:1023:SCardBeginTransaction() Status: 0x00000000
winscard_msg_srv.c:288:SHMProcessEventsContext() correctly processed
client: 8
winscard.c:1601:SCardTransmit() Send Protocol: T=1
APDU: 00 A4 04 00 00
ifdhandler.c:1035:IFDHTransmitToICC() lun: 0
SW: 6F 65 84 08 A0 00 00 00 03 00 00 00 A5 59 9F 65 01 FF 9F 6E 06 47 91
00 78 33 00 73 4A 06 07 2A 86 48 86 FC 6B 01 60 0C 06 0A 2A 86 48 86 FC
6B 02 02 01 01 63 09 06 07 2A 86 48 86 FC 6B 03 64 0B 06 09 2A 86 48 86
FC 6B 04 02 15 65 0B 06 09 2B 85 10 86 48 64 02 01 03 66 0C 06 0A 2B 06
01 04 01 2A 02 6E 01 02 90 00
winscard_msg_srv.c:288:SHMProcessEventsContext() correctly processed
client: 8
winscard.c:1601:SCardTransmit() Send Protocol: T=1
APDU: 80 CA 9F 7F 2D
ifdhandler.c:1035:IFDHTransmitToICC() lun: 0
SW: 67 00
winscard_msg_srv.c:288:SHMProcessEventsContext() correctly processed
client: 8
winscard.c:1171:SCardEndTransaction() Status: 0x00000000
winscard_msg_srv.c:288:SHMProcessEventsContext() correctly processed
client: 8
... There are a total of 52 repetitions of this logging statement....
winscard_msg_srv.c:288:SHMProcessEventsContext() correctly processed
client: 8
# After card inserted.
--- end "pcscd" log ---
>
> If this doesn't give us any useful info, we can get some debug output from our PKCS#11 module coolkey.
>
> 1. In a terminal, with esc dead, set this env var:
>
> COOL_KEY_LOG_FILE=/tmp/cool.log
>
> 2. Start ESC in the terminal : esc.
>
> 3. Take a look at the cool.log file and show us. There may be some obvious log statement that could be helpful.
>
--- begin "coolkey" log ---
card changed
cleared all sessions
isTokenPresent, card state is 0x1
C_WaitForSlotEvent called
Called C_GetSlotInfo
calling IsConnected
card changed
cleared all sessions
isTokenPresent, card state is 0x1
C_WaitForSlotEvent called
# After starting "esc".
# Before inserting card.
Called C_GetSlotInfo
calling IsConnected
card changed
cleared all sessions
time connect: Connect Time 414 ms
time connect: Read Slot 414 ms
time connect: connection status 415 ms
time connnect: Begin transaction 415 ms
CoolKey Select failed 0x6
CAC Select failed 0x6
isTokenPresent, card state is 0xe
C_GetTokenInfo called
calling IsConnected
IsConnected returned false
isTokenPresent, card state is 0xe
C_GetMechanismList called
calling IsConnected
IsConnected returned false
isTokenPresent, card state is 0xe
C_GetMechanismList returning 0
C_GetMechanismList called
calling IsConnected
IsConnected returned false
isTokenPresent, card state is 0xe
C_GetMechanismList returning 0
C_OpenSession called
calling IsConnected
IsConnected returned false
isTokenPresent, card state is 0xe
C_FindObjectsInit called, 1 templates
template [00] type: 0000, pValue: b7f82174, ulValueLen: 00000004, value:
3461563221
calling IsConnected
IsConnected returned false
C_FindObjectsInit found matching object 0x00000002
C_FindObjects called, max objects = 10
calling IsConnected
IsConnected returned false
returned 1 objects: 0x00000002
C_GetAttributeValue called, 1 templates for object 0x00000002
template [00] type: 0003, pValue: 00000000, ulValueLen: 00000000
calling IsConnected
IsConnected returned false
template [00] type: 0003, pValue: 00000000, ulValueLen: 0000001a
C_GetAttributeValue called, 1 templates for object 0x00000002
template [00] type: 0003, pValue: 08877338, ulValueLen: 0000001a
calling IsConnected
IsConnected returned false
template [00] type: 0003, pValue: 08877338, ulValueLen: 0000001a
C_GetAttributeValue called, 1 templates for object 0x00000002
template [00] type: ce534369, pValue: 00000000, ulValueLen: 00000000
calling IsConnected
IsConnected returned false
template [00] type: ce534369, pValue: 00000000, ulValueLen: 00000010
C_GetAttributeValue called, 1 templates for object 0x00000002
template [00] type: ce534369, pValue: 08877390, ulValueLen: 00000010
calling IsConnected
IsConnected returned false
template [00] type: ce534369, pValue: 08877390, ulValueLen: 00000010
C_GetTokenInfo called
calling IsConnected
IsConnected returned false
isTokenPresent, card state is 0xe
C_GetAttributeValue called, 1 templates for object 0x00000002
template [00] type: ce534368, pValue: 00000000, ulValueLen: 00000000
calling IsConnected
IsConnected returned false
template [00] type: ce534368, pValue: 00000000, ulValueLen: 00000001
C_GetAttributeValue called, 1 templates for object 0x00000002
template [00] type: ce534368, pValue: 088773a8, ulValueLen: 00000001
calling IsConnected
IsConnected returned false
template [00] type: ce534368, pValue: 088773a8, ulValueLen: 00000001
C_WaitForSlotEvent called
Initialize called, hello 5
C_GetInfo called
C_GetSlotList called
calling IsConnected
card changed
cleared all sessions
time connect: Connect Time 412 ms
time connect: Read Slot 412 ms
time connect: connection status 412 ms
time connnect: Begin transaction 413 ms
CoolKey Select failed 0x6
CAC Select failed 0x6
isTokenPresent, card state is 0xe
C_GetSlotList called
calling IsConnected
IsConnected returned false
isTokenPresent, card state is 0xe
Called C_GetSlotInfo
calling IsConnected
IsConnected returned false
isTokenPresent, card state is 0xe
C_GetTokenInfo called
calling IsConnected
IsConnected returned false
isTokenPresent, card state is 0xe
C_GetMechanismList called
calling IsConnected
IsConnected returned false
isTokenPresent, card state is 0xe
C_GetMechanismList returning 0
C_GetMechanismList called
calling IsConnected
IsConnected returned false
isTokenPresent, card state is 0xe
C_GetMechanismList returning 0
C_OpenSession called
calling IsConnected
IsConnected returned false
isTokenPresent, card state is 0xe
C_FindObjectsInit called, 1 templates
template [00] type: 0000, pValue: bffda99c, ulValueLen: 00000004, value:
3461563220
calling IsConnected
IsConnected returned false
C_FindObjects called, max objects = 1
calling IsConnected
IsConnected returned false
returned 0 objects:
C_WaitForSlotEvent called
Called C_GetSlotInfo
calling IsConnected
IsConnected returned false
isTokenPresent, card state is 0xe
C_GetSessionInfo called
calling IsConnected
IsConnected returned false
C_FindObjectsInit called, 1 templates
template [00] type: 0000, pValue: ad5fe174, ulValueLen: 00000004, value:
3461563221
calling IsConnected
IsConnected returned false
C_FindObjectsInit found matching object 0x00000002
C_FindObjects called, max objects = 10calling IsConnected
IsConnected returned false
returned 1 objects: 0x00000002
C_GetAttributeValue called, 1 templates for object 0x00000002
template [00] type: 0003, pValue: 00000000, ulValueLen: 00000000
calling IsConnected
IsConnected returned false
template [00] type: 0003, pValue: 00000000, ulValueLen: 0000001a
C_GetAttributeValue called, 1 templates for object 0x00000002
template [00] type: 0003, pValue: b1f39520, ulValueLen: 0000001a
calling IsConnected
IsConnected returned false
template [00] type: 0003, pValue: b1f39520, ulValueLen: 0000001a
C_GetAttributeValue called, 1 templates for object 0x00000002
template [00] type: ce534369, pValue: 00000000, ulValueLen: 00000000
calling IsConnected
IsConnected returned false
template [00] type: ce534369, pValue: 00000000, ulValueLen: 00000010
C_GetAttributeValue called, 1 templates for object 0x00000002
template [00] type: ce534369, pValue: b1f3b6f0, ulValueLen: 00000010
calling IsConnected
IsConnected returned false
template [00] type: ce534369, pValue: b1f3b6f0, ulValueLen: 00000010
C_GetTokenInfo called
calling IsConnected
IsConnected returned false
isTokenPresent, card state is 0xe
C_GetAttributeValue called, 1 templates for object 0x00000002
template [00] type: ce534368, pValue: 00000000, ulValueLen: 00000000
calling IsConnected
IsConnected returned false
template [00] type: ce534368, pValue: 00000000, ulValueLen: 00000001
C_GetAttributeValue called, 1 templates for object 0x00000002
template [00] type: ce534368, pValue: b7d41c14, ulValueLen: 00000001
calling IsConnected
IsConnected returned false
template [00] type: ce534368, pValue: b7d41c14, ulValueLen: 00000001
C_WaitForSlotEvent called
C_FindObjectsInit called, 2 templates
template [00] type: 0001, pValue: 05be5874, ulValueLen: 00000001
template [01] type: 0000, pValue: bffda4b8, ulValueLen: 00000004, value:
3461563219
calling IsConnected
IsConnected returned false
C_FindObjects called, max objects = 10
calling IsConnected
IsConnected returned false
returned 0 objects:
C_FindObjectsInit called, 2 templates
template [00] type: 0001, pValue: 05be5874, ulValueLen: 00000001
template [01] type: 0000, pValue: 05be5878, ulValueLen: 00000004, value: 1
calling IsConnected
IsConnected returned false
C_FindObjects called, max objects = 16
calling IsConnected
IsConnected returned false
returned 0 objects:
C_GetSessionInfo called
calling IsConnected
IsConnected returned false
C_FindObjectsInit called, 2 templates
template [00] type: 0001, pValue: 05be5874, ulValueLen: 00000001
template [01] type: 0000, pValue: 05be5878, ulValueLen: 00000004, value: 1
calling IsConnected
IsConnected returned false
C_FindObjects called, max objects = 16
calling IsConnected
IsConnected returned false
returned 0 objects:
# "esc" GUI appears.
--- end "coolkey" log ---
>
>
>>
>> So, I'm confused as to why I don't see the "Phone Home Configuration
>> Information" dialog that you mention.
>>
>> By default, does ESC communicate with TPS over HTTP port 7888? It is
>> necessary to switch ESC to use HTTPS port 7890?
>>
>> Is there part of installation or configuration of ESC and TPS that
>> people (like me) regularly get wrong?
>>
>> Thanks,
>> -- Steve Ross
>>
>>
>>
<snip>
More information about the Pki-users
mailing list