MacOS: Parallel codesigning (a la Xcode) results in "errSecInternalComponent"

[herm-cb]

Problem Description

Goal:
I am trying to sign an iOS app with a certificate on my Yubikey.

Problem:
After successfully building my iOS app through Xcode, Xcode tries to sign the app using codesign. This results in indeterminate failures with code errSecInternalComponent. After some inspection, it seems that the cause of this is codesign being called in parallel processes (recreated below).

Proposed Resolution

Lock access to codesigning from a single process.

Steps to reproduce

I have the following two scripts that simply codesign all arbitrary text files in a directory. One signs serially while the other one opens a new process for each code signature.

#!/bin/bash
# serial_codesign_test.sh

# Get the codesigning identity
if [ -z "$1" ]
    then
        echo "Please specify the codesigning identity with the first parameter."
        exit 1;
fi
IDENTITY="$1"

for f in *.txt
do
    # Codesign Serially
    codesign -fs "$IDENTITY" "$f"
done

exit 0;

#!/bin/bash
# parallel_codesign_test.sh

# Get the codesigning identity
if [ -z "$1" ]
    then
        echo "Please specify the codesigning identity with the first parameter."
        exit 1;
fi
IDENTITY="$1"

for f in *.txt
do
    # Codesign in Parallel
    codesign -fs "$IDENTITY" "$f" &
done

exit 0;

The error is easily reproducible with the following:

./parallel_codesign_test.sh $IDENTITY_ON_YUBIKEY

Logs

➜  codesign_files ./serial_codesign_test.sh $IDENTITY_IN_LOCAL_KEYCHAIN
test_0.txt: replacing existing signature
test_1.txt: replacing existing signature
test_2.txt: replacing existing signature
test_3.txt: replacing existing signature
test_4.txt: replacing existing signature
test_5.txt: replacing existing signature
test_6.txt: replacing existing signature
test_7.txt: replacing existing signature
test_8.txt: replacing existing signature
test_9.txt: replacing existing signature

➜  codesign_files ./serial_codesign_test.sh $IDENTITY_ON_YUBIKEY
test_0.txt: replacing existing signature
test_1.txt: replacing existing signature
test_2.txt: replacing existing signature
test_3.txt: replacing existing signature
test_4.txt: replacing existing signature
test_5.txt: replacing existing signature
test_6.txt: replacing existing signature
test_7.txt: replacing existing signature
test_8.txt: replacing existing signature
test_9.txt: replacing existing signature

➜  codesign_files ./parallel_codesign_test.sh $IDENTITY_IN_LOCAL_KEYCHAIN
➜  codesign_files test_4.txt: replacing existing signature
test_8.txt: replacing existing signature
test_5.txt: replacing existing signature
test_1.txt: replacing existing signature
test_9.txt: replacing existing signature
test_0.txt: replacing existing signature
test_6.txt: replacing existing signature
test_3.txt: replacing existing signature
test_7.txt: replacing existing signature
test_2.txt: replacing existing signature

➜  codesign_files ./parallel_codesign_test.sh $IDENTITY_ON_YUBIKEY
➜  codesign_files test_0.txt: replacing existing signature
test_1.txt: replacing existing signature
test_7.txt: replacing existing signature
test_1.txt: errSecInternalComponent
test_5.txt: replacing existing signature
test_7.txt: errSecInternalComponent
test_2.txt: replacing existing signature
test_5.txt: errSecInternalComponent
test_8.txt: replacing existing signature
test_2.txt: errSecInternalComponent
test_6.txt: replacing existing signature
test_8.txt: errSecInternalComponent
test_6.txt: errSecInternalComponent
test_9.txt: replacing existing signature
test_9.txt: errSecInternalComponent
test_4.txt: replacing existing signature
test_3.txt: replacing existing signature
test_3.txt: errSecInternalComponent

[herm-cb]

OpenSC debug=3 logs here

[dengert]

Quick look at the log show the card has lost the login state and pin caching is off. Try turning on pin caching in opensc.conf. Login state can be lost by commands set to the device during card matching by other OpenSC drivers. Try running with env OPENSC_DRIVER=PIV-II or modify opensc.conf to ser drivers = to the only cards you expect to use.

I do not have any MacOS systems and never looked at reader-cryptotokenkit.m to see if pcsc does better locking then cryptotokenkit.

https://smartcard-atr.apdu.fr/parse?ATR=3B+FD+13+00+00+81+31+FE+15+80+73+C0+21+C0+57+59+75+62+69+4B+65+79+40
says you have a "Yubico YubiKey 5 NFC (PKI)" The card-piv.c does not recognize this as a Yubikey so calls it a generic PIV card, type = 14001. Yubikey devices can lose the login state because they do not strictly follow the NIST PIV standards. card-piv.c tries to address many of these issues if it can identify the card. I do not have any Yubico 5 devices.

If you are willing to run some tests using your device, I will send you a script later in the week.

[dengert]

Correction should be OPENSC_DRIVER=PIV-II

[herm-cb]

@dengert Thanks for the feedback!

I only had pin caching turned off to see if that would help, but it does not. I re-enabled it, and it doesn't have any change.

Setting OPENSC_DRIVER=PIV-II didn't have any effect. How would I explicitly set this in opensc.conf?

I would gladly run some test scripts! I did notice that my yubikey model doesn't seem explicitly supported.

For what it's worth, this does't look like a new issue. I found this from 2018:

https://forums.developer.apple.com/thread/106938

[dengert]

To only use selected drivers via opensc.conf see: https://github.com/OpenSC/OpenSC/blob/master/etc/opensc.conf.example.in#L136

To simulate a Yubkey4 you can also add to opensc.conf:

# make Yubico 5 look like Yubico 4 for testing
   card_atr  3B:FD:13:00:00:81:31:FE:15:80:73:C0:21:C0:57:59:75:62:69:4B:65:79:40 {
                driver = "PIV-II";
                type = 14004;
   }

[herm-cb]

@dengert Got it, thanks! This still didn't have any net effect, but cool to know I can do this. What exactly is type = 14004 doing here?

[dengert]

Its the card number for a Yubikey 4 with PIV applet
https://github.com/OpenSC/OpenSC/blob/master/src/libopensc/cards.h#L137

[herm-cb]

@dengert Thanks that's helpful! The bug is still there though.

[dengert]

In the previous log, it was for just one process and the process had multiple threads.

Your serial_codesign_test.sh all work, and the parallel_codesign_test.sh has many failures.
pcsc does the process locking on other systems, and locking within threads and processes work well. This implies that the process locking done by reader-cryptotokenkit.m (between processes ) has a problem. Other possible problems are detection of the lost of login state and its recovery or the pin caching code is not using the locking correctly.

in the parallel run, 8 of the 10 process failed. So it looks like you can get a failure with just 3. OpenSC should write to the log from multiple processes, without losing any lines, as last resort your script could used env OPENSC_CONF= to point to a copy of opensc.conf with a different debug_file = opensc-debug.log; for each process without losing any lines. But then the logs have to be compared by time stamps.

Can you send a log of the failing test using the type=14004 I want to see what is different. This should show better test of lost login state and might show interference between processes.

I do not have a MacOS device so never looked at reader-cryptotokenkit.m. It might be releasing an exclusive lock to early, or is only doing a shared lock of some type.

@frankmorgner you wrote reader-cryptotokenkit.m in 2017, any ideas?

@mouse07410 any ideas? Can you reproduce?

[dengert]

https://github.com/frankmorgner/OpenSCToken/blob/master/OpenSCToken/Token.m#L83
looks like thread locking is not enabled. @frankmorgner

This problem is very similar to #1966 in that the debug log does not show enough info to tell if thread locking is working or not. sc_mutex_lock and friends return SC_SUCCESS if no thread locking is being done.

[herm-cb]

@dengert it looks like you narrowed the problem down -- would those logs still help?

[dengert]

You can hold off until Frank has a look.

[frankmorgner]

Sigh, It looks like CTK is not clever enough to manage concurrent access within a single process. Yes, we're locking the reader with the designated method beginSessionWithReply, but in your log we can see that, for example, thread 0x123145548386304 is holding a lock for the card when thread 0x123145548922880 is requesting (and getting) a lock as well:

P:3075; T:0x123145548386304 21:31:54.143 [cryptotokenkit] reader-cryptotokenkit.m:211:cryptotokenkit_lock: called
P:3075; T:0x123145548386304 21:31:54.143 [cryptotokenkit] reader-cryptotokenkit.m:233:cryptotokenkit_lock: returning with: 0 (Success)
...
P:3075; T:0x123145548386304 21:31:54.360 [cryptotokenkit] reader-cryptotokenkit.m:240:cryptotokenkit_unlock: called
P:3075; T:0x123145548386304 21:31:54.360 [cryptotokenkit] reader-cryptotokenkit.m:247:cryptotokenkit_unlock: returning with: 0 (Success)

P:3075; T:0x123145548922880 21:31:54.166 [cryptotokenkit] reader-cryptotokenkit.m:211:cryptotokenkit_lock: called
P:3075; T:0x123145548922880 21:31:54.166 [cryptotokenkit] reader-cryptotokenkit.m:233:cryptotokenkit_lock: returning with: 0 (Success)
...
P:3075; T:0x123145548922880 21:31:54.172 [cryptotokenkit] reader-cryptotokenkit.m:240:cryptotokenkit_unlock: called
P:3075; T:0x123145548922880 21:31:54.172 [cryptotokenkit] reader-cryptotokenkit.m:247:cryptotokenkit_unlock: returning with: 0 (Success)

I think that should be solved by using a global lock in cryptotokenkit_lock...