Opened 8 years ago

Closed 7 years ago

#52623 closed defect (worksforme)

p11-kit @0.23.2_1: fails to properly complete operation and disconnect on Sierra

Reported by: mouse07410 (Mouse) Owned by: lbschenkel (Leonardo Brondani Schenkel)
Priority: Normal Milestone:
Component: ports Version: 2.3.4
Keywords: upstream Cc: dbevans (David B. Evans)
Port: p11-kit

Description

The symptoms are described here: https://github.com/OpenSC/libp11/issues/123

The following command hangs up when PKCS11_MODULE_PATH=/opt/local/lib/p11-kit-proxy.dylib:

$ openssl dgst -engine pkcs11 -keyform engine -sign "pkcs11:manufacturer=piv_II;object=SIGN%20key;type=private" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:-1 -out t256.dat.sig t256.dat
engine "pkcs11" set.
PKCS#11 token PIN: 
^C      [have to kill this hanging process]
$ openssl dgst -engine pkcs11 -keyform engine -verify "pkcs11:manufacturer=piv_II;object=SIGN%20pubkey;type=public" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:-1 -signature t256.dat.sig t256.dat
engine "pkcs11" set.
Verified OK
$

The signature file t256.dat.sig is created, and can be verified (as shown above). But signing command does not exit, and has to be killed manually.

If PKCS11_MODULE_PATH is set to, e.g., /Library/OpenSC/lib/opensc-pkcs11.dylib, it completes and exits correctly.

Running with PKCS11_MODULE_PATH=/Library/OpenSC/lib/pkcs11-spy.dylib and PKCS11SPY=/opt/local/lib/p11-kit-proxy.dylib shows that everything seems to run fine, up until the very last step C_Finalize where it does not return:

. . . . .
98: C_Sign
2016-10-15 22:20:29.843
[in] hSession = 0x11
[in] pData[ulDataLen] 00007f99c7703cd0 / 256
    00000000  0B 10 33 11 4B 5D 72 30 6C A5 6C 94 4E B6 6C 4A  ..3.K]r0l.l.N.lJ
    00000010  B3 FE A4 47 6A B4 01 64 01 9F C5 B7 7A 8F 62 10  ...Gj..d....z.b.
    . . . . .
    000000F0  CA 30 0A D2 70 CC 25 36 AB DE C9 B4 CF 35 46 BC  .0..p.%6.....5F.
[out] pSignature[*pulSignatureLen] 00007f99c8002400 / 256
    00000000  6C D9 35 4C AC 1F 91 55 CB 89 5A FC 26 AB 83 0F  l.5L...U..Z.&...
    00000010  F6 21 37 74 FE 4E 72 55 B7 00 B0 BF D7 84 F3 81  .!7t.NrU........
    . . . . .
    000000F0  76 E0 1D AF CC EF 32 80 AD E0 5C 38 B2 3E 67 33  v.....2...\8.>g3
Returned:  0 CKR_OK

99: C_CloseAllSessions
2016-10-15 22:20:30.517
[in] slotID = 0x10
Returned:  0 CKR_OK

100: C_CloseAllSessions
2016-10-15 22:20:30.517
[in] slotID = 0x11
Returned:  0 CKR_OK

101: C_CloseAllSessions
2016-10-15 22:20:30.517
[in] slotID = 0x12
Returned:  0 CKR_OK

102: C_CloseAllSessions
2016-10-15 22:20:30.517
[in] slotID = 0x13
Returned:  0 CKR_OK

103: C_CloseAllSessions
2016-10-15 22:20:30.517
[in] slotID = 0x14
Returned:  0 CKR_OK

104: C_CloseAllSessions
2016-10-15 22:20:30.517
[in] slotID = 0x15
Returned:  0 CKR_OK

105: C_CloseAllSessions
2016-10-15 22:20:30.517
[in] slotID = 0x16
Returned:  0 CKR_OK

106: C_Finalize
2016-10-15 22:20:30.517
^C
$

It appears to be seeing and trying to work with many more token slots than I seem to have/use.

Here's what C_Finalize looks like if the above is invoked with PKCS11SPY=/Library/OpenSC/lib/opensc-pkcs11.dylib:

. . . . .
87: C_Sign
2016-10-13 10:30:37.731
[in] hSession = 0x7fdbb3004e00
[in] pData[ulDataLen] 00007fdbb160be30 / 256
    00000000  19 C7 12 37 09 18 52 8A 8B B1 53 ED B7 B3 7D A6  ...7..R...S...}.
    00000010  AC 2D CA 07 AF 57 26 14 6F 1C 45 93 B5 76 6F 7C  .-...W&.o.E..vo|
    . . . . .
    000000F0  0B 4A 57 A9 32 86 BD 35 C9 76 EB C5 AD 81 80 BC  .JW.2..5.v......
[out] pSignature[*pulSignatureLen] 00007fdbb2801000 / 256
    00000000  74 08 82 C2 1A A6 46 ED BF 50 80 EB DB C9 49 8C  t.....F..P....I.
    00000010  53 42 3A 01 ED A1 E4 E3 8C 7A F4 E7 C2 4D 08 13  SB:......z...M..
    . . . . .
    000000F0  FF BD 28 CD E3 37 C8 8D 2C 78 FC C6 88 F3 71 9E  ..(..7..,x....q.
Returned:  0 CKR_OK

88: C_CloseAllSessions
2016-10-13 10:30:38.402
[in] slotID = 0x0
Returned:  224 CKR_TOKEN_NOT_PRESENT

89: C_CloseAllSessions
2016-10-13 10:30:38.403
[in] slotID = 0x4
Returned:  0 CKR_OK

90: C_Finalize
2016-10-13 10:30:38.403
Returned:  0 CKR_OK
$

If any logs would be of help, I'd be happy to provide.

Change History (15)

comment:1 Changed 8 years ago by mouse07410 (Mouse)

Don't know if this helps:

$ p11-kit list-modules
p11-kit-trust: p11-kit-trust.so
    library-description: PKCS#11 Kit Trust Module
    library-manufacturer: PKCS#11 Kit
    library-version: 0.23
    token: Default Trust
        manufacturer: PKCS#11 Kit
        model: p11-kit-trust
        serial-number: 1
        hardware-version: 0.23
        flags:
               write-protected
               token-initialized
    token: System Trust
        manufacturer: PKCS#11 Kit
        model: p11-kit-trust
        serial-number: 1
        hardware-version: 0.23
        flags:
               write-protected
               token-initialized
pkcs11: /Library/OpenSC/lib/opensc-pkcs11.dylib
    library-description: OpenSC smartcard framework
    library-manufacturer: OpenSC Project
    library-version: 0.16
    token: PIV Card Holder pin (PIV_II)
        manufacturer: piv_II
        model: PKCS#15 emulated
        serial-number: a0fxxxxxxxxxxxxx
        flags:
               rng
               login-required
               user-pin-initialized
               token-initialized
softhsm2: /opt/local/lib/softhsm/libsofthsm2.so
    library-description: Implementation of PKCS11
    library-manufacturer: SoftHSM
    library-version: 2.1
    token: Botan PKCS#11 tests
        manufacturer: SoftHSM project
        model: SoftHSM v2
        serial-number: b15xxxxxxxxxxxxx
        hardware-version: 2.1
        firmware-version: 2.1
        flags:
               rng
               login-required
               user-pin-initialized
               restore-key-not-needed
               token-initialized
    token: test
        manufacturer: SoftHSM project
        model: SoftHSM v2
        serial-number: 02bxxxxxxxxxxxxx
        hardware-version: 2.1
        firmware-version: 2.1
        flags:
               rng
               login-required
               user-pin-initialized
               restore-key-not-needed
               token-initialized
    token: 
        manufacturer: SoftHSM project
        model: SoftHSM v2
        serial-number: 
        hardware-version: 2.1
        firmware-version: 2.1
        flags:
               rng
               login-required
               restore-key-not-needed
               so-pin-locked
               so-pin-to-be-changed
ykcs11: /usr/local/lib/libykcs11.dylib
    library-description: PKCS#11 PIV Library (SP-800-73)
    library-manufacturer: Yubico (www.yubico.com)
    library-version: 1.42
    token: YubiKey PIV
        manufacturer: Yubico
        model: YubiKey NEO
        serial-number: 1234
        hardware-version: 6.0
        firmware-version: 1.4
        flags:
               rng
               login-required
               user-pin-initialized
               token-initialized
$ 

comment:2 Changed 8 years ago by ryandesign (Ryan Carsten Schmidt)

Cc: devans@… removed
Owner: changed from macports-tickets@… to devans@…
Summary: Fails to properly complete operation and disconnect on Sierrap11-kit @0.23.2_1: fails to properly complete operation and disconnect on Sierra

comment:3 Changed 8 years ago by larryv (Lawrence Velázquez)

Cc: leonardo.schenkel@… added

comment:4 Changed 8 years ago by lbschenkel (Leonardo Brondani Schenkel)

I noticed something similar when I had SoftHSM2 enabled. Could you please disable all your p11-kit modules and enable just the want you want to use, and enable only one additional module at a time until the issue re-appears? Which module is that?

comment:5 Changed 8 years ago by mouse07410 (Mouse)

The only two modules I (explicitly) enabled are OpenSC PKCS#11 and Yubico YKCS11 (subset of PKCS#11 with extensions for YubiKey devices):

$ ll ~/.config/pkcs11/modules/
total 16
drwxr-xr-x  4 uri  staff  136 Oct  3 10:19 ./
drwxr-xr-x  3 uri  staff  102 Oct  2 12:42 ../
-rw-r--r--  1 uri  staff   48 Oct  2 12:44 pkcs11.module
-rw-r--r--  1 uri  staff   39 Oct  2 12:44 ykcs11.module
$

Here's what happens if I remove ykcs11.module:

$ export PKCS11_MODULE_PATH=/opt/local/lib/p11-kit-proxy.dylib 
$ mv ~/.config/pkcs11/modules/ykcs11.module /tmp/
$ openssl dgst -engine pkcs11 -keyform engine -sign "pkcs11:manufacturer=piv_II;object=SIGN%20key;type=private" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:-1 -out t256.dat.sig t256.dat
engine "pkcs11" set.
PKCS#11 token PIN: 
^C
$ 

With PKCS11SPY:

PKCS11_MODULE_PATH=/Library/OpenSC/lib/pkcs11-spy.dylib openssl dgst -engine pkcs11 -keyform engine -sign "pkcs11:manufacturer=piv_II;object=SIGN%20key;type=private" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:-1 -out t256.dat.sig t256.dat


*************** OpenSC PKCS#11 spy *****************
Loaded: "/opt/local/lib/p11-kit-proxy.dylib"

0: C_GetFunctionList
2016-10-16 11:43:40.125
Returned:  0 CKR_OK

1: C_Initialize
2016-10-16 11:43:40.126
[in] pInitArgs = 0x7fff5a42b5f0
     flags: 2
       CKF_OS_LOCKING_OK
Returned:  0 CKR_OK

2: C_GetInfo
2016-10-16 11:43:40.866
[out] pInfo: 
      cryptokiVersion:         2.20
      manufacturerID:         'PKCS#11 Kit                     '
      flags:                   0
      libraryDescription:     'PKCS#11 Kit Proxy Module        '
      libraryVersion:          1.1
Returned:  0 CKR_OK

3: C_GetSlotList
2016-10-16 11:43:40.866
[in] tokenPresent = 0x0
[out] pSlotList: 
Count is 6
[out] *pulCount = 0x6
Returned:  0 CKR_OK

4: C_GetSlotList
2016-10-16 11:43:40.866
[in] tokenPresent = 0x0
[out] pSlotList: 
Slot 16
Slot 17
Slot 18
Slot 19
Slot 20
Slot 21
[out] *pulCount = 0x6
Returned:  0 CKR_OK

5: C_GetSlotInfo
2016-10-16 11:43:40.866
[in] slotID = 0x10
[out] pInfo: 
      slotDescription:        '/opt/local/share/curl/curl-ca-bu'
                              'ndle.crt                        '
      manufacturerID:         'PKCS#11 Kit                     '
      hardwareVersion:         0.23
      firmwareVersion:         0.0
      flags:                   1
        CKF_TOKEN_PRESENT                
Returned:  0 CKR_OK

6: C_GetTokenInfo
2016-10-16 11:43:40.866
[in] slotID = 0x10
[out] pInfo: 
      label:                  'Default Trust                   '
      manufacturerID:         'PKCS#11 Kit                     '
      model:                  'p11-kit-trust   '
      serialNumber:           '1               '
      ulMaxSessionCount:       0
      ulSessionCount:          -1
      ulMaxRwSessionCount:     0
      ulRwSessionCount:        -1
      ulMaxPinLen:             0
      ulMinPinLen:             0
      ulTotalPublicMemory:     -1
      ulFreePublicMemory:      -1
      ulTotalPrivateMemory:    -1
      ulFreePrivateMemory:     -1
      hardwareVersion:         0.23
      firmwareVersion:         0.0
      time:                   '                '
      flags:                   402
        CKF_WRITE_PROTECTED              
        CKF_TOKEN_INITIALIZED            
Returned:  0 CKR_OK

7: C_GetSlotInfo
2016-10-16 11:43:40.866
[in] slotID = 0x11
[out] pInfo: 
      slotDescription:        '/opt/local/etc/openssl          '
                              '                                '
      manufacturerID:         'PKCS#11 Kit                     '
      hardwareVersion:         0.23
      firmwareVersion:         0.0
      flags:                   1
        CKF_TOKEN_PRESENT                
Returned:  0 CKR_OK

8: C_GetTokenInfo
2016-10-16 11:43:40.866
[in] slotID = 0x11
[out] pInfo: 
      label:                  'System Trust                    '
      manufacturerID:         'PKCS#11 Kit                     '
      model:                  'p11-kit-trust   '
      serialNumber:           '1               '
      ulMaxSessionCount:       0
      ulSessionCount:          -1
      ulMaxRwSessionCount:     0
      ulRwSessionCount:        -1
      ulMaxPinLen:             0
      ulMinPinLen:             0
      ulTotalPublicMemory:     -1
      ulFreePublicMemory:      -1
      ulTotalPrivateMemory:    -1
      ulFreePrivateMemory:     -1
      hardwareVersion:         0.23
      firmwareVersion:         0.0
      time:                   '                '
      flags:                   402
        CKF_WRITE_PROTECTED              
        CKF_TOKEN_INITIALIZED            
Returned:  0 CKR_OK

9: C_GetSlotInfo
2016-10-16 11:43:40.867
[in] slotID = 0x12
[out] pInfo: 
      slotDescription:        'Yubico Yubikey NEO OTP+U2F+CCID '
                              '                                '
      manufacturerID:         'Yubico                          '
      hardwareVersion:         3.70
      firmwareVersion:         0.0
      flags:                   7
        CKF_TOKEN_PRESENT                
        CKF_REMOVABLE_DEVICE             
        CKF_HW_SLOT                      
Returned:  0 CKR_OK

10: C_GetTokenInfo
2016-10-16 11:43:40.868
[in] slotID = 0x12
[out] pInfo: 
      label:                  'PIV Card Holder pin (PIV_II)    '
      manufacturerID:         'piv_II                          '
      model:                  'PKCS#15 emulated'
      serialNumber:           'a0fxxxxxxxxxxxxx'
      ulMaxSessionCount:       0
      ulSessionCount:          0
      ulMaxRwSessionCount:     0
      ulRwSessionCount:        0
      ulMaxPinLen:             8
      ulMinPinLen:             4
      ulTotalPublicMemory:     -1
      ulFreePublicMemory:      -1
      ulTotalPrivateMemory:    -1
      ulFreePrivateMemory:     -1
      hardwareVersion:         0.0
      firmwareVersion:         0.0
      time:                   '                '
      flags:                   40d
        CKF_RNG                          
        CKF_LOGIN_REQUIRED               
        CKF_USER_PIN_INITIALIZED         
        CKF_TOKEN_INITIALIZED            
Returned:  0 CKR_OK

11: C_GetSlotInfo
2016-10-16 11:43:40.891
[in] slotID = 0x13
[out] pInfo: 
      slotDescription:        'SoftHSM slot ID 0x21bc4979      '
                              '                                '
      manufacturerID:         'SoftHSM project                 '
      hardwareVersion:         2.1
      firmwareVersion:         2.1
      flags:                   1
        CKF_TOKEN_PRESENT                
Returned:  0 CKR_OK

12: C_GetTokenInfo
2016-10-16 11:43:40.891
[in] slotID = 0x13
[out] pInfo: 
      label:                  'Botan PKCS#11 tests             '
      manufacturerID:         'SoftHSM project                 '
      model:                  'SoftHSM v2      '
      serialNumber:           'b15xxxxxxxxxxxxx'
      ulMaxSessionCount:       0
      ulSessionCount:          -1
      ulMaxRwSessionCount:     0
      ulRwSessionCount:        -1
      ulMaxPinLen:             255
      ulMinPinLen:             4
      ulTotalPublicMemory:     -1
      ulFreePublicMemory:      -1
      ulTotalPrivateMemory:    -1
      ulFreePrivateMemory:     -1
      hardwareVersion:         2.1
      firmwareVersion:         2.1
      time:                   '2016101615434000'
      flags:                   42d
        CKF_RNG                          
        CKF_LOGIN_REQUIRED               
        CKF_USER_PIN_INITIALIZED         
        CKF_RESTORE_KEY_NOT_NEEDED       
        CKF_TOKEN_INITIALIZED            
Returned:  0 CKR_OK

13: C_GetSlotInfo
2016-10-16 11:43:40.891
[in] slotID = 0x14
[out] pInfo: 
      slotDescription:        'SoftHSM slot ID 0x2879828e      '
                              '                                '
      manufacturerID:         'SoftHSM project                 '
      hardwareVersion:         2.1
      firmwareVersion:         2.1
      flags:                   1
        CKF_TOKEN_PRESENT                
Returned:  0 CKR_OK

14: C_GetTokenInfo
2016-10-16 11:43:40.891
[in] slotID = 0x14
[out] pInfo: 
      label:                  'test                            '
      manufacturerID:         'SoftHSM project                 '
      model:                  'SoftHSM v2      '
      serialNumber:           '02bxxxxxxxxxxxxx'
      ulMaxSessionCount:       0
      ulSessionCount:          -1
      ulMaxRwSessionCount:     0
      ulRwSessionCount:        -1
      ulMaxPinLen:             255
      ulMinPinLen:             4
      ulTotalPublicMemory:     -1
      ulFreePublicMemory:      -1
      ulTotalPrivateMemory:    -1
      ulFreePrivateMemory:     -1
      hardwareVersion:         2.1
      firmwareVersion:         2.1
      time:                   '2016101615434000'
      flags:                   42d
        CKF_RNG                          
        CKF_LOGIN_REQUIRED               
        CKF_USER_PIN_INITIALIZED         
        CKF_RESTORE_KEY_NOT_NEEDED       
        CKF_TOKEN_INITIALIZED            
Returned:  0 CKR_OK

15: C_GetSlotInfo
2016-10-16 11:43:40.892
[in] slotID = 0x15
[out] pInfo: 
      slotDescription:        'SoftHSM slot ID 0x2             '
                              '                                '
      manufacturerID:         'SoftHSM project                 '
      hardwareVersion:         2.1
      firmwareVersion:         2.1
      flags:                   1
        CKF_TOKEN_PRESENT                
Returned:  0 CKR_OK

16: C_GetTokenInfo
2016-10-16 11:43:40.892
[in] slotID = 0x15
[out] pInfo: 
      label:                  '                                '
      manufacturerID:         'SoftHSM project                 '
      model:                  'SoftHSM v2      '
      serialNumber:           '                '
      ulMaxSessionCount:       0
      ulSessionCount:          -1
      ulMaxRwSessionCount:     0
      ulRwSessionCount:        -1
      ulMaxPinLen:             255
      ulMinPinLen:             4
      ulTotalPublicMemory:     -1
      ulFreePublicMemory:      -1
      ulTotalPrivateMemory:    -1
      ulFreePrivateMemory:     -1
      hardwareVersion:         2.1
      firmwareVersion:         2.1
      time:                   '2016101615434000'
      flags:                   c00025
        CKF_RNG                          
        CKF_LOGIN_REQUIRED               
        CKF_RESTORE_KEY_NOT_NEEDED       
        CKF_SO_PIN_LOCKED                
        CKF_SO_PIN_TO_BE_CHANGED         
Returned:  0 CKR_OK
engine "pkcs11" set.

17: C_OpenSession
2016-10-16 11:43:40.892
[in] slotID = 0x12
[in] flags = 0x4
pApplication=0x0
Notify=0x0
[out] *phSession = 0x11
Returned:  0 CKR_OK

18: C_FindObjectsInit
2016-10-16 11:43:40.892
[in] hSession = 0x11
[in] pTemplate[1]: 
    CKA_CLASS             CKO_CERTIFICATE      
Returned:  0 CKR_OK

19: C_FindObjects
2016-10-16 11:43:40.892
[in] hSession = 0x11
[in] ulMaxObjectCount = 0x1
[out] ulObjectCount = 0x1
Object 0x7fd27ad28c80 matches
Returned:  0 CKR_OK

20: C_GetAttributeValue
2016-10-16 11:43:40.892
[in] hSession = 0x11
[in] hObject = 0x7fd27ad28c80
[in] pTemplate[1]: 
    CKA_CERTIFICATE_TYPE  00007fff5a42b498 / 8
[out] pTemplate[1]: 
    CKA_CERTIFICATE_TYPE  CKC_X_509
Returned:  0 CKR_OK

21: C_GetAttributeValue
2016-10-16 11:43:40.892
[in] hSession = 0x11
[in] hObject = 0x7fd27ad28c80
[in] pTemplate[1]: 
    CKA_LABEL             0000000000000000 / 0
[out] pTemplate[1]: 
    CKA_LABEL             0000000000000000 / 34
Returned:  0 CKR_OK

22: C_GetAttributeValue
2016-10-16 11:43:40.892
[in] hSession = 0x11
[in] hObject = 0x7fd27ad28c80
[in] pTemplate[1]: 
    CKA_LABEL             00007fd27af144f0 / 34
[out] pTemplate[1]: 
    CKA_LABEL             00007fd27af144f0 / 34
    43657274 69666963 61746520 666F7220 50495620 41757468 656E7469 63617469
     C e r t  i f i c  a t e .  f o r .  P I V .  A u t h  e n t i  c a t i6F6E
     o n
Returned:  0 CKR_OK

23: C_GetAttributeValue
2016-10-16 11:43:40.892
[in] hSession = 0x11
[in] hObject = 0x7fd27ad28c80
[in] pTemplate[1]: 
. . . . .
95: C_SignInit
2016-10-16 11:43:43.504
[in] hSession = 0x11
pMechanism->type=CKM_RSA_X_509                
[in] hKey = 0x7fd27af138f0
Returned:  0 CKR_OK

96: C_Sign
2016-10-16 11:43:43.504
[in] hSession = 0x11
[in] pData[ulDataLen] 00007fd27af14c10 / 256
    00000000  5A 6B BB 1E 19 2F 6F D9 52 B7 40 E9 9D DA 21 EA  Zk.../o.R.@...!.
    00000010  2C 6C 59 CD B6 69 B6 4A 5C 85 4F DE CD C1 72 0E  ,lY..i.J\.O...r.
    . . . . .
    000000F0  AC DB FE 80 DE 31 13 F1 9F 85 D1 BD 1E B8 9E BC  .....1..........
[out] pSignature[*pulSignatureLen] 00007fd27b801000 / 256
    00000000  0E FA 39 F3 DD 9C B9 EB D1 F9 2F E6 28 4E E3 56  ..9......./.(N.V
    00000010  53 DC 7F 90 3E 72 23 48 91 D2 E8 E8 E4 1C 59 D0  S..>r#H......Y.
    . . . . .
    000000F0  59 1A 90 C8 D1 E0 B0 87 3C 5F 73 99 A2 73 F3 CB  Y.......<_s..s..
Returned:  0 CKR_OK

97: C_CloseAllSessions
2016-10-16 11:43:44.174
[in] slotID = 0x10
Returned:  0 CKR_OK

98: C_CloseAllSessions
2016-10-16 11:43:44.174
[in] slotID = 0x11
Returned:  0 CKR_OK

99: C_CloseAllSessions
2016-10-16 11:43:44.174
[in] slotID = 0x12
Returned:  0 CKR_OK

100: C_CloseAllSessions
2016-10-16 11:43:44.175
[in] slotID = 0x13
Returned:  0 CKR_OK

101: C_CloseAllSessions
2016-10-16 11:43:44.175
[in] slotID = 0x14
Returned:  0 CKR_OK

102: C_CloseAllSessions
2016-10-16 11:43:44.175
[in] slotID = 0x15
Returned:  0 CKR_OK

103: C_Finalize
2016-10-16 11:43:44.175
^C
$ 

I see SoftHSMv2 module(s), which I did NOT enable, at least explicitly. Nor do I have any idea what that "/opt/local/etc/openssl" is doing there. I'd appreciate some guidance how to perform the test you need.

comment:6 Changed 8 years ago by lbschenkel (Leonardo Brondani Schenkel)

Check /opt/local/share/p11-kit/modules or /opt/local/etc/pkcs11/modules. To disable modules that are present in one of these locations you may open the file and comment out the module: line or you may create an override file with the same name in ~/.config/pkcs11/modules and that file should have a module: line with an empty value (check the manual at https://p11-glue.freedesktop.org/doc/p11-kit/pkcs11-conf.html for more info).

Disable all modules besides OpenSC and re-enable one by one until you find the offending module.

comment:7 Changed 8 years ago by mouse07410 (Mouse)

Check /opt/local/share/p11-kit/modules

Bingo. That's where I found softhsm2.module file. When I replaced the "module: whatever" line with "module: " line, openssl started hanging immediately, without even prompting for a PIN. After I removed that file out from the /opt/local/share/p11-kit/modules directory, openssl stopped hanging, and was completing operation properly:

$ openssl dgst -engine pkcs11 -keyform engine -sign "pkcs11:manufacturer=piv_II;object=SIGN%20key;type=private" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:-1 -out ~/src/t256.dat.sig ~/src/t256.dat
engine "pkcs11" set.
PKCS#11 token PIN: 
$ openssl dgst -engine pkcs11 -keyform engine -verify "pkcs11:manufacturer=piv_II;object=SIGN%20pubkey;type=public" -sha384 -sigopt rsa_padding_mode:pss -sigopt rsa_pss_saltlen:-1 -signature ~/src/t256.dat.sig ~/src/t256.dat
engine "pkcs11" set.
Verified OK
$

So the offending module turned out to be softhsm2.module. It contains "module: /opt/local/lib/softhsm/libsofthsm2.so".

What now?

Version 0, edited 8 years ago by mouse07410 (Mouse) (next)

comment:8 Changed 8 years ago by lbschenkel (Leonardo Brondani Schenkel)

I noticed that when I use p11-kit-proxy.so via OpenSC's pkcs11-tool and libsofthsm2.so is enabled then pkcs11-tool does not exit when it's done and I have to press Ctrl+C. But that happens only on pkcs11-tool and not on GnuTLS' p11-tool, nor when I use the libsofthsm2.so module directly via pkcs11-tool, bypassing p11-kit.

Honestly I don't know which one is at fault here. It could be SoftHSM2, p11-kit, or even OpenSC (the engine for OpenSSL is from the OpenSC project). Personally I'm betting on some weird interaction between SoftHSM2 and p11-kit. I think your best choice is to report this upstream to both projects; should I do that or do you want to do yourself?

comment:9 Changed 8 years ago by mouse07410 (Mouse)

I'd really appreciate if you could report this upstream. Thank you!

comment:10 Changed 8 years ago by dbevans (David B. Evans)

Cc: devans@… added; leonardo.schenkel@… removed
Keywords: upstream added
Owner: changed from devans@… to leonardo.schenkel@…

Leonardo, thanks for your help in diagnosing this issue. Don't forget to add links to any upstream tickets you may open so they can be tracked from here.

Leaving this ticket open pending upstream resolution of the issues involved.

comment:11 Changed 8 years ago by dbevans (David B. Evans)

With his kind permission, leonardo@... added as principal co-maintainer for p11-kit and gpgme in r153990. Thanks again, Leonardo.

comment:12 Changed 8 years ago by mouse07410 (Mouse)

It looks like the cause of the problem is deadlocking in OpenSSL engine, as SoftHSMv2 and OpenSSL engine both use OpenSSL locking mechanism...

Not sure what the role of p11-kit is here, besides just enabling the problem by making SoftHSMv2 available and able to cause this deadlock.

comment:13 Changed 7 years ago by lbschenkel (Leonardo Brondani Schenkel)

mouse07410: can you still reproduce this with the latest version of p11-kit from the ports tree? This fell out of my radar and I would like to determine if it is still an issue.

comment:14 Changed 7 years ago by mouse07410 (Mouse)

It fell off my radar as well. I think we've fixed in in libp11.

comment:15 Changed 7 years ago by lbschenkel (Leonardo Brondani Schenkel)

Resolution: worksforme
Status: newclosed

I will then go ahead and close this.

Note: See TracTickets for help on using tickets.