Diagnostics

How to understand the diagnostic logs

Logs

When the tool starts, if a logs folder doesn't exist, it is immediately created. Beneath logs, the apdu, conformancelog, file, and testlog folders are created. In each, you'll find timestamped log files corresponding to each test card run. The timestamps on each file denote the local start and finish times of the first and last test cases in that run.

When you need to understand why a particular test case failed, the first step is to locate the test case in the SP800-85B PIV Data Model Test Guidelines (DRAFT) referred to here as "SP85-B". Some CCT test cases are numbered using more granularity. You can use the CCT test case number to locate the test assertion in SP85-B Oftentimes in SP85-B, multiple assertions are made in a single test case number. The CCT attempts to isolate each assertion by adding a 4th or 5th test numbering level and a separate piece of code (atom) to handle that assertion test. Cross reference the CCT test case number with SP85-B and correlate the appropriate "sub" assertion to understand the nature of the failure.

Next, navigate to the files subdirectory. Use a text editor to open the log corresponding to the run you want to investigate. Search for the test case number you're interested in. The CCT likely threw an exception while executing that test case. Most exceptions are accompanied by a specific error that points to the cause of the failure. While the goal is to throw exceptions for all card and data issues, some card and data issues (as well as software issues) can result in system library exceptions such as a Null Pointer Exception when the CCT encounters an unexpected condition. Errors attributed to software should be reported to the FICAM Testing Lab.

Below is an example of a failed test case 8.2.2.12 in the 85b-swing-log:

2020-03-05 13:28:16,822 INFO [Thread-3] g.g.p.testProgress [GuiTestListener.java:88] Started 8.2.2.12:1 => oid = 2.16.840.1.101.3.7.2.48.0
2020-03-05 13:28:16,822 DEBUG [Thread-3] g.g.p.c.c.CardHolderUniqueIdentifier [CardHolderUniqueIdentifier.java:270] rawBytes: 538209b83019d4e739da739ced39ce739da1685899084210cdb9c84210c3e133093030303030303030303410508ab11fbd52403eaf0fe29c127bc363350832303139313130373d003e82096e3082096a06092a864886f70d010702a082095b30820957020103310f300d06096086480165030402010500300a06086086480165030601a08206a8308206a43082048ca003020102021211216d464d266a183951872206765b2e9455300d06092a864886f70d01010b0500308188310b300906035504061302555331273025060355040a131e436172696c6c6f6e204665646572616c20536572766963657320496e632e31223020060355040b131943657274696669636174696f6e20417574686f726974696573312c302a06035504031323436172696c6c6f6e204665646572616c205365727669636573205049562d4920434131301e170d3135303730393139313030375a170d3234303730393139313030375a305f310b300906035504061302555331273025060355040a131e436172696c6c6f6e204665646572616c20536572766963657320496e632e3110300e060355040b130744657669636573311530130603550403130c636f6e74656e745369676e3130820122300d06092a864886f70d01010105000382010f003082010a0282010100b0b4e77470552bf71c128a7e59e1c6d8b3980d0617a0876e3d82b347fa820d6251db5714ef2529d6067473f2f9027f0dc9b3c90c2479bfd82d074cd1efceb6806a71e5ddabf34eea3f579e93465bcd4c0efb485da13433660c856b18f8ec88aeff86bc0ff22eb9dc836c83657a3300fd0b34f4219286085bd7c6afcae63cf5bb1566cdcc141e762c4fb989bfac5c8ef3ab29fcc8c2fb3867a0f8fef13e8b50885164dee9ea778c27a1778dee751f9d927734fc7704847f50bdeef1bebd36e4a1ef8c3a84d3b743bfc6c703af644c709017a0b6ecee58f88307bf47e62ebf5974e674826413dd056c3ca876a086d1e7fb9714eb65c69f6eae0a8f517164251b390203010001a382022e3082022a300e0603551d0f0101ff0404030207803081ff0603551d200481f73081f43081f1060b2b0601040182e4260301163081e1304106082b06010505070201163568747470733a2f2f7075622e636172696c6c6f6e666564736572762e636f6d2f4365727469666963617465506f6c6963792e70646630819b06082b0601050507020230818e1a818b5468697320636572746966696361746520686173206265656e2069737375656420696e206163636f7264616e636520776974682074686520436172696c6c6f6e204665646572616c20536572766963657320496e632e20436572746966696361746520506f6c69637920617320666f756e6420696e2074686520435053706f696e746572206669656c642e30160603551d250101ff040c300a06086086480165030807303e0603551d1f043730353033a031a02f862d687474703a2f2f7075622e636172696c6c6f6e666564736572762e636f6d2f43524c2f4346534341312e63726c307e06082b0601050507010104723070303d06082b060105050730028631687474703a2f2f7075622e636172696c6c6f6e666564736572762e636f6d2f434163657274732f4346534341312e703763302f06082b060105050730018623687474703a2f2f7075622e636172696c6c6f6e666564736572762e636f6d2f6f637370301d0603551d0e0416041441df150b028f7eb393090b5e65b3c55e4216986b301f0603551d23041830168014e9ba674340ad41229afefa094388f362b86baf2a300d06092a864886f70d01010b050003820201004a7f2cca587da046632711d2c565ead26602833dda87bb2837864ef50362b42b01cec7d9daa81af52e391ce0a0686e1a48eb9f626087d82b109ec6a97273820d9f4b9d074d454990252ebc3e1ec5f7f9226158579830a77d2561a97560c2a971dfffb8435d3dbb70a956152657ae06fb588178aef08d3b0cdfd134ed15b1eafe599440423ffea2580a21774ed721a74dbcf18b55fc99df4992c59a594952c46a64b82be4b9bd0d31a87915fea4b23987869d3cc8519834c46f2064e870f3ed532617edbe1c8c4a744123d6fb87d30c55f03ade8f8e59d259f32826c729bc6fa830a8e56d9d7de1888515152e4deaf6be788687af462d6ba172b02f0628e58a0b5e05ba2e7c0c2b65d88c181b4d7bd630aed76c80ceeff1b546027485353531228422fe16c54063228fa66af05508fe332b1424298b6bea2a57fd59aa0a236e752c0c5d079bac565a923f88a3bd91c4366545f8d32a68be88f8de94bbe5b371d51c83d2c2c80d41cf03db107cf207a53c57d6046fd6cb0c539105e51d8e4320a1a55c86af4ddc4c2462f71da6e450adfb1c85f02399951825343ef9b3c185a69f3d68249a093fee39f3a31765e3df22b6feea6b38b3d3003356890177ab6c849b2afd5e858de18797d187676bf040c7fc3f79e59063bcdbd4cd62124685f2cdd431540fc1974b622d2a6edcd52f73d792165934ec5b3d472b89022ed4c232d406318202873082028302010130819f308188310b300906035504061302555331273025060355040a131e436172696c6c6f6e204665646572616c20536572766963657320496e632e31223020060355040b131943657274696669636174696f6e20417574686f726974696573312c302a06035504031323436172696c6c6f6e204665646572616c205365727669636573205049562d4920434131021211216d464d266a183951872206765b2e9455300d06096086480165030402010500a081b9301706092a864886f70d010903310a06086086480165030601302f06092a864886f70d010904312204208e4184136babf869a19ec42e837db3432d7bc969a51a6cfdff2a870040dd7e61306d060860864801650306053161305f310b300906035504061302555331273025060355040a131e436172696c6c6f6e204665646572616c20536572766963657320496e632e3110300e060355040b130744657669636573311530130603550403130c636f6e74656e745369676e31300d06092a864886f70d01010105000482010098a33e779db62353abaf681d0f30ca08d81093b2c9feed66fdd66a67b9aae097b4a05e13a09ed6615af81492d074039bb7da166d6f91156f684d7e6f0e245a57462801fd6c48e7b16d991039820252848898b11e33a95ca45c792ca5ca40a722c7a1cacf3f661372dcd1739ae834202374d4bd5ab0633160bed5baa0fa521054edcec3d182bf7999e55aa521d71122b1502bfd5a8c9ad412de0089b78f99a68bd63268cde8a43890eea3a82a2a66ff9cdab41602458e95a7f6b8876b4865b60c0032b950d842c226c77c93ea91f6bd3c0e365928f48a49fa118bf4e0cdb49baae653979470c1506189ebd753a6d191017c92b60b74631a744ae0362554eecb3efe00
2020-03-05 13:28:16,823 DEBUG [Thread-3] g.g.p.c.c.CardHolderUniqueIdentifier [CardHolderUniqueIdentifier.java:293] Tag 53: 3019d4e739da739ced39ce739da1685899084210cdb9c84210c3e133093030303030303030303410508ab11fbd52403eaf0fe29c127bc363350832303139313130373d003e82096e3082096a06092a864886f70d010702a082095b30820957020103310f300d06096086480165030402010500300a06086086480165030601a08206a8308206a43082048ca003020102021211216d464d266a183951872206765b2e9455300d06092a864886f70d01010b0500308188310b300906035504061302555331273025060355040a131e436172696c6c6f6e204665646572616c20536572766963657320496e632e31223020060355040b131943657274696669636174696f6e20417574686f726974696573312c302a06035504031323436172696c6c6f6e204665646572616c205365727669636573205049562d4920434131301e170d3135303730393139313030375a170d3234303730393139313030375a305f310b300906035504061302555331273025060355040a131e436172696c6c6f6e204665646572616c20536572766963657320496e632e3110300e060355040b130744657669636573311530130603550403130c636f6e74656e745369676e3130820122300d06092a864886f70d01010105000382010f003082010a0282010100b0b4e77470552bf71c128a7e59e1c6d8b3980d0617a0876e3d82b347fa820d6251db5714ef2529d6067473f2f9027f0dc9b3c90c2479bfd82d074cd1efceb6806a71e5ddabf34eea3f579e93465bcd4c0efb485da13433660c856b18f8ec88aeff86bc0ff22eb9dc836c83657a3300fd0b34f4219286085bd7c6afcae63cf5bb1566cdcc141e762c4fb989bfac5c8ef3ab29fcc8c2fb3867a0f8fef13e8b50885164dee9ea778c27a1778dee751f9d927734fc7704847f50bdeef1bebd36e4a1ef8c3a84d3b743bfc6c703af644c709017a0b6ecee58f88307bf47e62ebf5974e674826413dd056c3ca876a086d1e7fb9714eb65c69f6eae0a8f517164251b390203010001a382022e3082022a300e0603551d0f0101ff0404030207803081ff0603551d200481f73081f43081f1060b2b0601040182e4260301163081e1304106082b06010505070201163568747470733a2f2f7075622e636172696c6c6f6e666564736572762e636f6d2f4365727469666963617465506f6c6963792e70646630819b06082b0601050507020230818e1a818b5468697320636572746966696361746520686173206265656e2069737375656420696e206163636f7264616e636520776974682074686520436172696c6c6f6e204665646572616c20536572766963657320496e632e20436572746966696361746520506f6c69637920617320666f756e6420696e2074686520435053706f696e746572206669656c642e30160603551d250101ff040c300a06086086480165030807303e0603551d1f043730353033a031a02f862d687474703a2f2f7075622e636172696c6c6f6e666564736572762e636f6d2f43524c2f4346534341312e63726c307e06082b0601050507010104723070303d06082b060105050730028631687474703a2f2f7075622e636172696c6c6f6e666564736572762e636f6d2f434163657274732f4346534341312e703763302f06082b060105050730018623687474703a2f2f7075622e636172696c6c6f6e666564736572762e636f6d2f6f637370301d0603551d0e0416041441df150b028f7eb393090b5e65b3c55e4216986b301f0603551d23041830168014e9ba674340ad41229afefa094388f362b86baf2a300d06092a864886f70d01010b050003820201004a7f2cca587da046632711d2c565ead26602833dda87bb2837864ef50362b42b01cec7d9daa81af52e391ce0a0686e1a48eb9f626087d82b109ec6a97273820d9f4b9d074d454990252ebc3e1ec5f7f9226158579830a77d2561a97560c2a971dfffb8435d3dbb70a956152657ae06fb588178aef08d3b0cdfd134ed15b1eafe599440423ffea2580a21774ed721a74dbcf18b55fc99df4992c59a594952c46a64b82be4b9bd0d31a87915fea4b23987869d3cc8519834c46f2064e870f3ed532617edbe1c8c4a744123d6fb87d30c55f03ade8f8e59d259f32826c729bc6fa830a8e56d9d7de1888515152e4deaf6be788687af462d6ba172b02f0628e58a0b5e05ba2e7c0c2b65d88c181b4d7bd630aed76c80ceeff1b546027485353531228422fe16c54063228fa66af05508fe332b1424298b6bea2a57fd59aa0a236e752c0c5d079bac565a923f88a3bd91c4366545f8d32a68be88f8de94bbe5b371d51c83d2c2c80d41cf03db107cf207a53c57d6046fd6cb0c539105e51d8e4320a1a55c86af4ddc4c2462f71da6e450adfb1c85f02399951825343ef9b3c185a69f3d68249a093fee39f3a31765e3df22b6feea6b38b3d3003356890177ab6c849b2afd5e858de18797d187676bf040c7fc3f79e59063bcdbd4cd62124685f2cdd431540fc1974b622d2a6edcd52f73d792165934ec5b3d472b89022ed4c232d406318202873082028302010130819f308188310b300906035504061302555331273025060355040a131e436172696c6c6f6e204665646572616c20536572766963657320496e632e31223020060355040b131943657274696669636174696f6e20417574686f726974696573312c302a06035504031323436172696c6c6f6e204665646572616c205365727669636573205049562d4920434131021211216d464d266a183951872206765b2e9455300d06096086480165030402010500a081b9301706092a864886f70d010903310a06086086480165030601302f06092a864886f70d010904312204208e4184136babf869a19ec42e837db3432d7bc969a51a6cfdff2a870040dd7e61306d060860864801650306053161305f310b300906035504061302555331273025060355040a131e436172696c6c6f6e204665646572616c20536572766963657320496e632e3110300e060355040b130744657669636573311530130603550403130c636f6e74656e745369676e31300d06092a864886f70d01010105000482010098a33e779db62353abaf681d0f30ca08d81093b2c9feed66fdd66a67b9aae097b4a05e13a09ed6615af81492d074039bb7da166d6f91156f684d7e6f0e245a57462801fd6c48e7b16d991039820252848898b11e33a95ca45c792ca5ca40a722c7a1cacf3f661372dcd1739ae834202374d4bd5ab0633160bed5baa0fa521054edcec3d182bf7999e55aa521d71122b1502bfd5a8c9ad412de0089b78f99a68bd63268cde8a43890eea3a82a2a66ff9cdab41602458e95a7f6b8876b4865b60c0032b950d842c226c77c93ea91f6bd3c0e365928f48a49fa118bf4e0cdb49baae653979470c1506189ebd753a6d191017c92b60b74631a744ae0362554eecb3efe00
2020-03-05 13:28:16,823 WARN [Thread-3] g.g.p.c.c.CardHolderUniqueIdentifier [CardHolderUniqueIdentifier.java:316] Deprecated tag: 3d with value: 
2020-03-05 13:28:16,824 DEBUG [Thread-3] g.g.p.c.c.PIVDataObject [SignedPIVDataObject.java:347] Signed attribute digest: 8e4184136babf869a19ec42e837db3432d7bc969a51a6cfdff2a870040dd7e61
2020-03-05 13:28:16,824 DEBUG [Thread-3] g.g.p.c.c.PIVDataObject [SignedPIVDataObject.java:383] Content bytes: 3019d4e739da739ced39ce739da1685899084210cdb9c84210c3e133093030303030303030303410508ab11fbd52403eaf0fe29c127bc363350832303139313130373d00fe00
2020-03-05 13:28:16,824 DEBUG [Thread-3] g.g.p.c.c.PIVDataObject [SignedPIVDataObject.java:391] Computed digest: 8e4184136babf869a19ec42e837db3432d7bc969a51a6cfdff2a870040dd7e61 
2020-03-05 13:28:16,827 ERROR [Thread-3] g.g.p.testProgress [GuiTestListener.java:108] Test atom 8.2.2.12:1 => oid = 2.16.840.1.101.3.7.2.48.0 failed
2020-03-05 13:28:16,827 ERROR [Thread-3] g.g.p.GuiTestListener [GuiTestListener.java:118] Caused by:
org.opentest4j.AssertionFailedError: Tag 0x3E preceded by invalid tag ==> expected: <true> but was: <false>

The next step is to extract the contents of the appropriate container and decode the TLVs. It can be seen that a 0x3d tag with a length of zero exists in the CHUID container here:

3019d4e739da739ced39ce739da1685899084210cdb9c84210c3e133093030303030303030303410508ab11fbd52403eaf0fe29c127bc363350832303139313130373d003e820...

Other errors may not be as simple to track down, but the debug is the one file that contains the test cases and the container contents. If you need to check the APDUs sent to the card, change to the apdu directory and locate the corresponding log file for the run. Note that once a container has been read, it's generally never read again during a particular run. The contents are stored in memory for quicker access and less stress on the card.

PIV Artifacts

The binary form of each container is logged to the piv-artifacts directory.

X.509 Artifacts

X.509 certificates are extracted to the x509-artifacts directory from any containers that include X.509 certificates (including the CHUID).

X.509 Certificate Path Building

The tool validates each certificate found on the card. A path is build to the appropriate trust anchor, supplying the end entity certificate and a list of expected certificate policy OIDs. The validator extracts the certificates of each successfully built path and writes them to the x509-certs\identifier subdirectory. All end-entity, intermediate, and root CA certs are saved to this directory. If a path cannot be built, the EE cert can be found in the piv-artifacts directory but the intermediate certs for that path cannot be extracted.