Re: [Pki-users] "Format" button never enabled in Enterprise Security Client

Hi Jack, thanks for your suggestions. My responses are in-line, below. -- Steve Ross On 09/23/2013 07:20 PM, John Magne wrote: 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. 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. 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 --- --- 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 --- <snip>