wpa_supplicant with opensc smartcard

[David Mattes]

Hi,

I'm trying to get smartcard support working for wpa.  I know the 
credential is fine, because when it's on my hard drive, I can auth just 
fine.  I installed it on a smartcard (and can successfully use 
openssl->engine and openssl->req and openssl->s_client with the 
credential) and am having problems getting the supplicant to auth.  I'm 
using wpa_supplicant-0.4.9.  Notice it does take the engine ~7 seconds 
to initialize - is that too long?  It seems like something is timing out 
and causing a re-scan???  Any insights or suggestions for further debugging?

Here are the pertinent supplicant output snippets:
-------------------------------------------------------------
Dec 12 15:14:09.599719: EAP: EAP entering state RECEIVED
Dec 12 15:14:09.599726: EAP: Received EAP-Request method=13 id=5
Dec 12 15:14:09.599732: EAP: EAP entering state GET_METHOD
Dec 12 15:14:09.599738: EAP: Initialize selected EAP method (13, TLS)
Dec 12 15:14:09.600505: TLS: Trusted root certificate(s) loaded
Dec 12 15:14:09.600785: OpenSSL: tls_connection_client_cert - 
SSL_use_certificate_file (DER) failed error:0D0680A8:asn1 encoding 
routines:ASN1_CHECK_TLEN:wrong tag
Dec 12 15:14:09.600808: OpenSSL: pending error: error:0D07803A:asn1 
encoding routines:ASN1_ITEM_EX_D2I:nested asn1 error
Dec 12 15:14:09.600887: OpenSSL: pending error: error:140C800D:SSL 
routines:SSL_use_certificate_file:ASN1 lib
Dec 12 15:14:09.601198: OpenSSL: SSL_use_certificate_file (PEM) --> OK
Dec 12 15:14:09.601208: SSL: Initializing TLS engine
ctx.c:596:sc_establish_context: ===================================
pkcs11-object.c:123:C_GetAttributeValue: Object 3: CKA_KEY_TYPE = CKK_RSA
pkcs11-object.c:123:C_GetAttributeValue: Object 3: CKA_LABEL = Certificate
pkcs11-object.c:123:C_GetAttributeValue: Object 3: CKA_ID = 45
pkcs11-object.c:123:C_GetAttributeValue: Object 3: CKA_ID = 45
pkcs11-session.c:235:C_Login: Login for session 1
framework-pkcs15.c:741:pkcs15_login: PIN verification returned 0
pkcs11-object.c:207:C_FindObjectsInit: C_FindObjectsInit(slot = 0)
pkcs11-object.c:208:C_FindObjectsInit: C_FindObjectsInit(): CKA_CLASS = 
CKO_PRIVATE_KEY
pkcs11-object.c:266:C_FindObjectsInit: Object 0/1 matches
pkcs11-object.c:277:C_FindObjectsInit: 1 matching objects
pkcs11-object.c:123:C_GetAttributeValue: Object 1: CKA_KEY_TYPE = CKK_RSA
pkcs11-object.c:123:C_GetAttributeValue: Object 1: CKA_LABEL = Private Key
pkcs11-object.c:123:C_GetAttributeValue: Object 1: CKA_ID = 45
pkcs11-object.c:123:C_GetAttributeValue: Object 1: CKA_ID = 45
pkcs11-object.c:207:C_FindObjectsInit: C_FindObjectsInit(slot = 0)
pkcs11-object.c:208:C_FindObjectsInit: C_FindObjectsInit(): CKA_CLASS = 
CKO_PUBLIC_KEY
pkcs11-object.c:266:C_FindObjectsInit: Object 0/3 matches
pkcs11-object.c:277:C_FindObjectsInit: 1 matching objects
pkcs11-object.c:123:C_GetAttributeValue: Object 3: CKA_KEY_TYPE = CKK_RSA
pkcs11-object.c:123:C_GetAttributeValue: Object 3: CKA_LABEL = Certificate
pkcs11-object.c:123:C_GetAttributeValue: Object 3: CKA_ID = 45
pkcs11-object.c:123:C_GetAttributeValue: Object 3: CKA_ID = 45
pkcs11-object.c:123:C_GetAttributeValue: Object 1: CKA_SENSITIVE = TRUE
pkcs11-object.c:123:C_GetAttributeValue: Object 1: CKA_EXTRACTABLE = (null)
pkcs11-object.c:123:C_GetAttributeValue: Object 1: CKA_MODULUS = 
D124CEFEEA02A9523A03F72B05A37AB88D67062DE1FE8596E6E91AFDB2D3E1DB
pkcs11-object.c:123:C_GetAttributeValue: Object 1: CKA_PUBLIC_EXPONENT = 
010001
Dec 12 15:14:16.652950: CTRL-EVENT-EAP-METHOD EAP method 13 (TLS) selected
Dec 12 15:14:16.652967: CTRL_IFACE monitor send - hexdump(len=25): 2f 74 
6d 70 2f 77 70 61 5f 63 74 72 6c 5f 31 39 37 39 38 2d 35 30 31 30 00
Dec 12 15:14:16.653061: EAP: EAP entering state METHOD
Dec 12 15:14:16.653073: SSL: Received packet(len=6) - Flags 0x20
Dec 12 15:14:16.653080: EAP-TLS: Start
Dec 12 15:14:16.653144: SSL: (where=0x10 ret=0x1)
Dec 12 15:14:16.653224: SSL: (where=0x1001 ret=0x1)
Dec 12 15:14:16.653236: SSL: SSL_connect:before/connect initialization
Dec 12 15:14:16.653673: SSL: (where=0x1001 ret=0x1)
Dec 12 15:14:16.653683: SSL: SSL_connect:SSLv3 write client hello A
Dec 12 15:14:16.653698: SSL: (where=0x1002 ret=0xffffffff)
Dec 12 15:14:16.653706: SSL: SSL_connect:error in SSLv3 read server hello A
Dec 12 15:14:16.653719: SSL: SSL_connect - want more data
Dec 12 15:14:16.653727: SSL: 100 bytes pending from ssl_out
Dec 12 15:14:16.653736: SSL: 100 bytes left to be sent out (of total 100 
bytes)
Dec 12 15:14:16.653746: EAP: method process -> ignore=FALSE 
methodState=MAY_CONT decision=FAIL
Dec 12 15:14:16.653755: EAP: EAP entering state SEND_RESPONSE
Dec 12 15:14:16.653762: EAP: EAP entering state IDLE
Dec 12 15:14:16.653770: EAPOL: SUPP_BE entering state RESPONSE
Dec 12 15:14:16.653775: EAPOL: txSuppRsp
Dec 12 15:14:16.653782: TX EAPOL - hexdump(len=110): 01 00 00 6a 02 05 
00 6a 0d 00 16 03 01 00 5f 01 00 00 5b 03 01 45 7f 37 c8 20 c0 30 0f d2 
c9 22 59 c6 e5 ec 7b fe c7 2b ea d6 18 a4 74 a8 0a bd 87 2d c8 62 3a 00 
00 34 00 39 00 38 00 35 00 16 00 13 00 0a 00 33 00 32 00 2f 00 66 00 05 
00 04 00 63 00 62 00 61 00 15 00 12 00 09 00 65 00 64 00 60 00 14 00 11 
00 08 00 06 00 03 01 00
Dec 12 15:14:16.653879: EAPOL: SUPP_BE entering state RECEIVE
Dec 12 15:14:16.653951: Wireless event: cmd=0x8b15 len=20
Dec 12 15:14:16.653958: Wireless event: new AP: 00:00:00:00:00:00
Dec 12 15:14:16.653977: Setting scan request: 0 sec 100000 usec
Dec 12 15:14:16.653987: Added BSSID 00:14:1c:c8:9f:b0 into blacklist
Dec 12 15:14:16.653997: State: ASSOCIATED -> DISCONNECTED

---------------------------------------------------------------------------