Debug a smart card application on Sierra

This article is an update of the previous article "Debug a smart card application on Yosemite".

New logging scheme

Apple made some changes in the way system, and application, logs are managed.
Now to get the log messages from a process use the command:

$ log stream

You will get a lot of messages. It is possible to restrict the messages from a particular process using predicates.

Logs from com.apple.ifdreader

To get only the log messages from the process com.apple.ifdreader use:

$ log stream --predicate 'process == "com.apple.ifdreader"'

For example I get something like:

$ log stream --predicate 'process == "com.apple.ifdreader"'
Filtering the log data using "process == "com.apple.ifdreader""
Timestamp                       Thread     Type        Activity             PID    
2017-11-06 16:11:21.092392+0100 0x751b1    Error       0x0                  260    com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.token] <private>: failed to transmit APDU
2017-11-06 16:11:22.173066+0100 0x74b9d    Error       0x800000000000af43   260    com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.token] <private>: failed to transmit APDU
2017-11-06 16:11:23.253418+0100 0x734eb    Error       0x0                  260    com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.token] <private>: failed to transmit APDU

APDU logging

It is still possible to log the APDU sent to the card and the response received. Use the same command as before:

$ sudo defaults write /Library/Preferences/com.apple.security.smartcard Logging -bool yes

You need to connect the reader after executing the above command to get the results.

For example I now get something like:

$ log stream --predicate 'process == "com.apple.ifdreader"'
Filtering the log data using "process == "com.apple.ifdreader""
Timestamp                       Thread     Type        Activity             PID    
2017-11-06 16:13:58.514542+0100 0x7868a    Activity    0x8000000000000511   260    com.apple.ifdreader: (CoreFoundation) Loading Preferences From System CFPrefsD
2017-11-06 16:13:58.514929+0100 0x7868a    Activity    0x8000000000000512   260    com.apple.ifdreader: (CoreFoundation) Sending Updated Preferences to System CFPrefsD
2017-11-06 16:13:58.516120+0100 0x7868a    Default     0x0                  260    com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.APDULog] logging slot Gemalto PC Twin Reader
2017-11-06 16:14:06.444894+0100 0x734eb    Default     0x0                  260    com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.APDULog] card in
2017-11-06 16:14:06.508793+0100 0x734eb    Default     0x0                  260    com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.APDULog] ATR: 3b 7f 96 00 00 80 31 80 65 b0 85 03 00 ef 12 0f fe 82 90 00
2017-11-06 16:14:06.541594+0100 0x76ff0    Default     0x800000000000afe6   260    com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.APDULog] T=0
2017-11-06 16:14:06.542311+0100 0x76752    Default     0x800000000000afe6   260    com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.APDULog] APDU -> 00 a4 04 00 0b a0 00 00 03 08 00 00 10 00 01 00
2017-11-06 16:14:06.560122+0100 0x76ff0    Default     0x800000000000afe6   260    com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.APDULog] APDU <- 61 13
2017-11-06 16:14:06.568852+0100 0x76752    Default     0x0                  260    com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.APDULog] APDU -> 00 a6 00 00 15
2017-11-06 16:14:07.649227+0100 0x734eb    Default     0x0                  260    com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.APDULog] APDU FAILED
2017-11-06 16:14:07.649267+0100 0x734eb    Error       0x0                  260    com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.token] <private>: failed to transmit APDU
2017-11-06 16:14:07.650895+0100 0x76ff0    Default     0x800000000000b133   260    com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.APDULog] APDU -> 00 a4 04 00 0b a0 00 00 03 08 00 00 10 00 01 00
2017-11-06 16:14:08.729874+0100 0x734eb    Default     0x800000000000b133   260    com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.APDULog] APDU FAILED
2017-11-06 16:14:08.729915+0100 0x734eb    Error       0x800000000000b133   260    com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.token] <private>: failed to transmit APDU
2017-11-06 16:14:08.731128+0100 0x74b9d    Default     0x0                  260    com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.APDULog] APDU -> 00 a6 00 00 15
2017-11-06 16:14:09.809998+0100 0x734eb    Default     0x0                  260    com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.APDULog] APDU FAILED
2017-11-06 16:14:09.810069+0100 0x734eb    Error       0x0                  260    com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.token] <private>: failed to transmit APDU
2017-11-06 16:14:11.670245+0100 0x7868a    Default     0x0                  260    com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.APDULog] unpower

Private fields

Some fields are shown as <private> in the log. To see the real value you must use:

$ sudo log config --mode "private_data:on"

For example I now get something like:

$ log stream --predicate 'process == "com.apple.ifdreader"'
Filtering the log data using "process == "com.apple.ifdreader""
Timestamp                       Thread     Type        Activity             PID    
2017-11-06 16:28:06.270662+0100 0x8689a    Activity    0x8000000000000514   260    com.apple.ifdreader: (CoreFoundation) Loading Preferences From System CFPrefsD
2017-11-06 16:28:06.271009+0100 0x8689a    Activity    0x8000000000000515   260    com.apple.ifdreader: (CoreFoundation) Sending Updated Preferences to System CFPrefsD
2017-11-06 16:28:06.280244+0100 0x8689a    Default     0x0                  260    com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.APDULog] logging slot Gemalto PC Twin Reader
2017-11-06 16:28:08.106965+0100 0x85613    Default     0x0                  260    com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.APDULog] card in
2017-11-06 16:28:08.171131+0100 0x85613    Default     0x0                  260    com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.APDULog] ATR: 3b 7f 96 00 00 80 31 80 65 b0 85 03 00 ef 12 0f fe 82 90 00
2017-11-06 16:28:08.197556+0100 0x86c91    Default     0x800000000000afef   260    com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.APDULog] T=0
2017-11-06 16:28:08.198083+0100 0x86c91    Default     0x800000000000afef   260    com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.APDULog] APDU -> 00 a4 04 00 0b a0 00 00 03 08 00 00 10 00 01 00
2017-11-06 16:28:08.214878+0100 0x86c92    Default     0x800000000000afef   260    com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.APDULog] APDU <- 61 13
2017-11-06 16:28:08.220709+0100 0x86c92    Default     0x0                  260    com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.APDULog] APDU -> 00 a6 00 00 15
2017-11-06 16:28:09.301451+0100 0x7c9d3    Default     0x0                  260    com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.APDULog] APDU FAILED
2017-11-06 16:28:09.301494+0100 0x7c9d3    Error       0x0                  260    com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.token] Gemalto PC Twin Reader: failed to transmit APDU
2017-11-06 16:28:09.302846+0100 0x86c91    Default     0x800000000000b693   260    com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.APDULog] APDU -> 00 a4 04 00 0b a0 00 00 03 08 00 00 10 00 01 00
2017-11-06 16:28:10.381888+0100 0x82669    Default     0x800000000000b693   260    com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.APDULog] APDU FAILED
2017-11-06 16:28:10.381933+0100 0x82669    Error       0x800000000000b693   260    com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.token] Gemalto PC Twin Reader: failed to transmit APDU
2017-11-06 16:28:10.383481+0100 0x7c9d3    Default     0x0                  260    com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.APDULog] APDU -> 00 a6 00 00 15
2017-11-06 16:28:11.462582+0100 0x82669    Default     0x0                  260    com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.APDULog] APDU FAILED
2017-11-06 16:28:11.462616+0100 0x82669    Error       0x0                  260    com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.token] Gemalto PC Twin Reader: failed to transmit APDU
2017-11-06 16:28:13.333227+0100 0x85613    Default     0x0                  260    com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.APDULog] unpower

More debug

You can get even more details by adding the --debug argument.

For example, just by connecting the smart card reader, I now get something like:

$ log stream --predicate 'process == "com.apple.ifdreader"' --debug
Filtering the log data using "process == "com.apple.ifdreader""
Timestamp                       Thread     Type        Activity             PID    
2017-11-06 16:39:11.456379+0100 0x91fc6    Debug       0x0                  11944  com.apple.ifdreader: [com.apple.CryptoTokenKit.smartcard] deviceRemovalHandler invoked (entryId=4294970878)
2017-11-06 16:39:11.456411+0100 0x91fc6    Debug       0x0                  11944  com.apple.ifdreader: [com.apple.CryptoTokenKit.smartcard] installed device removal notification
2017-11-06 16:39:11.456533+0100 0x91fc6    Debug       0x0                  11944  com.apple.ifdreader: [com.apple.CryptoTokenKit.smartcard] new device arrival: 08e6:3437 14400000 (entryId=4294970878)
2017-11-06 16:39:11.470462+0100 0x91fc6    Debug       0x0                  11944  com.apple.ifdreader: [com.apple.CryptoTokenKit.smartcard] bundle loaded: /usr/libexec/SmartCardServices/drivers/ifd-ccid.bundle
2017-11-06 16:39:11.470519+0100 0x91fc6    Debug       0x0                  11944  com.apple.ifdreader: [com.apple.CryptoTokenKit.smartcard] found bundle for device, resolved entryId=4294970878 to deviceName='Gemalto PC Twin Reader'
2017-11-06 16:39:11.470708+0100 0x92267    Debug       0x0                  11944  com.apple.ifdreader: [com.apple.CryptoTokenKit.smartcard] -> IFDHCreateChannelByName(00000000, 'Gemalto PC Twin Reader')
2017-11-06 16:39:11.778142+0100 0x92267    Debug       0x0                  11944  com.apple.ifdreader: [com.apple.CryptoTokenKit.smartcard] <- IFDHCreateChannelByName() = 0
2017-11-06 16:39:11.778188+0100 0x92267    Debug       0x0                  11944  com.apple.ifdreader: [com.apple.CryptoTokenKit.smartcard] -> IFDHGetCapabilities(00000000, TAG_IFD_THREAD_SAFE)
2017-11-06 16:39:11.778203+0100 0x92267    Debug       0x0                  11944  com.apple.ifdreader: [com.apple.CryptoTokenKit.smartcard] <- IFDHGetCapabilities() = 0 (0)
2017-11-06 16:39:11.778297+0100 0x92267    Debug       0x0                  11944  com.apple.ifdreader: [com.apple.CryptoTokenKit.smartcard] -> IFDHGetCapabilities(00000000, SCARD_ATTR_MAXINPUT)
2017-11-06 16:39:11.778323+0100 0x92267    Debug       0x0                  11944  com.apple.ifdreader: [com.apple.CryptoTokenKit.smartcard] <- IFDHGetCapabilities() = 0 (261)
2017-11-06 16:39:11.778495+0100 0x92267    Debug       0x0                  11944  com.apple.ifdreader: [com.apple.CryptoTokenKit.smartcard] -> IFDHControl_v3(00000000, code=1107299656, in=(null))
2017-11-06 16:39:11.778570+0100 0x92267    Debug       0x0                  11944  com.apple.ifdreader: [com.apple.CryptoTokenKit.smartcard] <- IFDHControl(out=<12044233 0012>) = 0
2017-11-06 16:39:11.778590+0100 0x92267    Debug       0x0                  11944  com.apple.ifdreader: [com.apple.CryptoTokenKit.smartcard] -> IFDHGetCapabilities(00000000, TAG_IFD_SLOTS_NUMBER)
2017-11-06 16:39:11.778605+0100 0x92267    Debug       0x0                  11944  com.apple.ifdreader: [com.apple.CryptoTokenKit.smartcard] <- IFDHGetCapabilities() = 0, (1)
2017-11-06 16:39:11.778657+0100 0x92267    Debug       0x0                  11944  com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.token] setupWithName:'Gemalto PC Twin Reader'
2017-11-06 16:39:11.779628+0100 0x92267    Debug       0x0                  11944  com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.token] port for pm notifications registered
2017-11-06 16:39:11.781182+0100 0x92267    Debug       0x0                  11944  com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.token] initWithName:'Gemalto PC Twin Reader' successfully registered
2017-11-06 16:39:11.781648+0100 0x92267    Activity    0x800000000000bb00   11944  com.apple.ifdreader: (CoreFoundation) Loading Preferences From System CFPrefsD
2017-11-06 16:39:11.781704+0100 0x92284    Debug       0x0                  11944  com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.token] Gemalto PC Twin Reader: new client connection established
2017-11-06 16:39:11.781847+0100 0x9228d    Debug       0x0                  11944  com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.token] Gemalto PC Twin Reader: slot was set up
2017-11-06 16:39:11.781997+0100 0x92267    Debug       0x800000000000bb00   11944  com.apple.ifdreader: (CoreFoundation) [com.apple.defaults.User Defaults] CFPrefsPlistSource<0x7fd450c0d910> (Domain: com.apple.security.smartcard, User: kCFPreferencesAnyUser, ByHost: Yes, Container: (null)) loaded: a new base plist and no additional changes from the base plist
2017-11-06 16:39:11.782060+0100 0x92267    Activity    0x800000000000bb01   11944  com.apple.ifdreader: (CoreFoundation) Sending Updated Preferences to System CFPrefsD
2017-11-06 16:39:11.782193+0100 0x92267    Debug       0x0                  11944  com.apple.ifdreader: (CoreFoundation) [com.apple.defaults.User Defaults] CFPrefsPlistSource<0x7fd450c0d910> (Domain: com.apple.security.smartcard, User: kCFPreferencesAnyUser, ByHost: Yes, Container: (null)) is waiting for writes to complete
2017-11-06 16:39:11.782204+0100 0x9228d    Debug       0x0                  11944  com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.token] Gemalto PC Twin Reader: new client connection established
2017-11-06 16:39:11.782291+0100 0x9228d    Debug       0x0                  11944  com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.token] Gemalto PC Twin Reader: slot was set up
2017-11-06 16:39:11.783202+0100 0x91fce    Debug       0x0                  11944  com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.token] Gemalto PC Twin Reader: new client connection established
2017-11-06 16:39:11.783284+0100 0x9228d    Debug       0x0                  11944  com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.token] Gemalto PC Twin Reader: slot was set up
2017-11-06 16:39:11.790768+0100 0x92267    Default     0x0                  11944  com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.APDULog] logging slot Gemalto PC Twin Reader
2017-11-06 16:39:12.306587+0100 0x9228d    Debug       0x0                  11944  com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.token] Gemalto PC Twin Reader: new client connection established
2017-11-06 16:39:12.306724+0100 0x92284    Debug       0x0                  11944  com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.token] Gemalto PC Twin Reader: slot was set up
2017-11-06 16:39:12.307550+0100 0x91fce    Debug       0x0                  11944  com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.token] Gemalto PC Twin Reader: new client connection established
2017-11-06 16:39:12.307663+0100 0x92267    Debug       0x0                  11944  com.apple.ifdreader: (CryptoTokenKit) [com.apple.CryptoTokenKit.token] Gemalto PC Twin Reader: slot was set up
[...]

Resize your terminal

The logs lines are very long. I suggest you to resize your Terminal window to be very large, at least as large as the log lines.

Console application

You can also use the Console application (/Applications/Utilities/Console.app). It may be easier to use if you prefer a graphical application instead of the Terminal and the command line.

I have not yet found a way to have the equivalent of --debug with the Console application.

Conclusion

Apple provides nice tools to get useful debug messages. Since some applications can be very verbose logs messages are not all stored in a file like /var/log/system.log. You need to use the log stream command.

The log command has many other options that you can explore.