Diagnostics
If you are going to dig in to find out why a particular failure occured, do so with the right information. Download and review these documents. SP 800-73-4, SP 800-78-4, SP 800-76-2, and SP 800-85B will be the most often used publications.
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.
Debug logs are found in the logs/debug subdirectory. Log file names start with the credential's identifier, start datestamp, end datestamp.
Open the file and search for the test case number of interest. The CCT will have either encountered an assertion error or an exception while executing that test case. Most of these 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 like a Null Pointer Exception or other system-level or I/O errors. Any of these conditions will cause a test failure.
The tool generally works as a database-driven JUunit test harness, gathering test metadata and test case parameters from a carefully constructed spreadsheet workbook. Using parameters, it is possible to re-use the same code for several similar objects in the PIV data model.
When a test case is developed, the programmer extracts a test case from the PIV Data Model Test Guidelines and breaks it into as many discrete assertions as are necessary to verify each part of the test case in question. NIST tends to add multiple requirements to a single sentence.
Each granular test requirement is assigned a test case number based on the SP 800-85B requirement for that container. We add additional decimal places when a requirement is split into multiple assertions.
The beginning of the log is marked as shown (timestamps and threads removed):
----------------------------------------
FIPS 201 CCT 1.0.4
----------------------------------------
Below is an example of a failed test case 8.10.2 in the debug log:
2021-02-11 13:53:20,989 INFO [Thread-1] [GuiTestListener.java:49] Test plan started for conformance test 8.10.2
2021-02-11 13:53:20,989 INFO [Thread-1] [GuiTestListener.java:100] Started 8.10.2:SP800_73_4SecurityObjectTests
2021-02-11 13:53:20,989 INFO [Thread-1] [GuiTestListener.java:100] Started 8.10.2:SP800-73-4.36 test
2021-02-11 13:53:20,989 INFO [Thread-1] [GuiTestListener.java:100] Started 8.10.2:1 => oid = 2.16.840.1.101.3.7.2.144.0
2021-02-11 13:53:20,989 DEBUG [Thread-1] [SP800_73_4SecurityObjectTests.java:138] Container ID list: index 3 is CARDHOLDER_FINGERPRINTS_OID
2021-02-11 13:53:20,989 DEBUG [Thread-1] [SP800_73_4SecurityObjectTests.java:138] Container ID list: index 7 is CARD_CAPABILITY_CONTAINER_OID
2021-02-11 13:53:21,005 DEBUG [Thread-1] [SP800_73_4SecurityObjectTests.java:138] Container ID list: index 8 is CARDHOLDER_FACIAL_IMAGE_OID
2021-02-11 13:53:21,005 DEBUG [Thread-1] [SP800_73_4SecurityObjectTests.java:138] Container ID list: index 9 is PRINTED_INFORMATION_OID
2021-02-11 13:53:21,005 DEBUG [Thread-1] [SP800_73_4SecurityObjectTests.java:138] Container ID list: index 12 is DISCOVERY_OBJECT_OID
2021-02-11 13:53:21,005 DEBUG [Thread-1] [PCSCWrapper.java:47] transmit() wrapper called
2021-02-11 13:53:21,005 DEBUG [Thread-1] [ChainingAPDUTransmitter.java:77] Sending Command APDU 00 cb 3f ff 03 5c 01 7e 00
2021-02-11 13:53:21,020 DEBUG [Thread-1] [ArtifactWriter.java:77] Wrote C:\cygwin64\home\bf7450\git\piv-conformance\fips201-card-conformance-tool-1.0.4-20210211124943\piv-artifacts\DiscoveryObject.dat
2021-02-11 13:53:21,020 DEBUG [Thread-1] [SP800_73_4SecurityObjectTests.java:138] Container ID list: index 13 is CARDHOLDER_IRIS_IMAGES_OID
2021-02-11 13:53:21,020 DEBUG [Thread-1] [PCSCWrapper.java:47] transmit() wrapper called
2021-02-11 13:53:21,020 DEBUG [Thread-1] [ChainingAPDUTransmitter.java:77] Sending Command APDU 00 cb 3f ff 05 5c 03 5f c1 21 00
2021-02-11 13:53:21,042 DEBUG [Thread-1] [AbstractPIVApplication.java:283] GET DATA returned status of 90 00 but a tag of 0x53 with a length of 0. Per SP800-73-4, PIV middleware should return PIV_DATA_OBJECT_NOT_FOUND.
2021-02-11 13:53:21,042 ERROR [Thread-1] [GuiTestListener.java:124] Test atom 8.10.2:1 => oid = 2.16.840.1.101.3.7.2.144.0 failed
2021-02-11 13:53:21,042 ERROR [Thread-1] [GuiTestListener.java:132] Caused by:
org.opentest4j.AssertionFailedError: expected: not <null>
at org.junit.jupiter.api.AssertionUtils.fail(AssertionUtils.java:39)
at org.junit.jupiter.api.Assertions.fail(Assertions.java:117)
at org.junit.jupiter.api.AssertNotNull.failNull(AssertNotNull.java:47)
at org.junit.jupiter.api.AssertNotNull.assertNotNull(AssertNotNull.java:36)
at org.junit.jupiter.api.AssertNotNull.assertNotNull(AssertNotNull.java:31)
at org.junit.jupiter.api.Assertions.assertNotNull(Assertions.java:283)
at gov.gsa.pivconformance.conformancelib.tests.SP800_73_4SecurityObjectTests.sp800_73_4_Test_36(SP800_73_4SecurityObjectTests.java:140)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at org.junit.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:688)
at org.junit.jupiter.engine.execution.MethodInvocation.proceed(MethodInvocation.java:60)
at org.junit.jupiter.engine.execution.InvocationInterceptorChain$ValidatingInvocation.proceed(InvocationInterceptorChain.java:131)
at org.junit.jupiter.engine.extension.TimeoutExtension.intercept(TimeoutExtension.java:149)
at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestableMethod(TimeoutExtension.java:140)
at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestTemplateMethod(TimeoutExtension.java:92)
at org.junit.jupiter.engine.execution.ExecutableInvoker$ReflectiveInterceptorCall.lambda$ofVoidMethod$0(ExecutableInvoker.java:115)
at org.junit.jupiter.engine.execution.ExecutableInvoker.lambda$invoke$0(ExecutableInvoker.java:105)
at org.junit.jupiter.engine.execution.InvocationInterceptorChain$InterceptedInvocation.proceed(InvocationInterceptorChain.java:106)
at org.junit.jupiter.engine.execution.InvocationInterceptorChain.proceed(InvocationInterceptorChain.java:64)
at org.junit.jupiter.engine.execution.InvocationInterceptorChain.chainAndInvoke(InvocationInterceptorChain.java:45)
at org.junit.jupiter.engine.execution.InvocationInterceptorChain.invoke(InvocationInterceptorChain.java:37)
at org.junit.jupiter.engine.execution.ExecutableInvoker.invoke(ExecutableInvoker.java:104)
at org.junit.jupiter.engine.execution.ExecutableInvoker.invoke(ExecutableInvoker.java:98)
at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.lambda$invokeTestMethod$6(TestMethodTestDescriptor.java:210)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.invokeTestMethod(TestMethodTestDescriptor.java:206)
at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:131)
at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:65)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:139)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:129)
at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:127)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:126)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:84)
at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.submit(SameThreadHierarchicalTestExecutorService.java:32)
at org.junit.platform.engine.support.hierarchical.NodeTestTask$DefaultDynamicTestExecutor.execute(NodeTestTask.java:212)
at org.junit.platform.engine.support.hierarchical.NodeTestTask$DefaultDynamicTestExecutor.execute(NodeTestTask.java:192)
at org.junit.jupiter.engine.descriptor.TestTemplateTestDescriptor.execute(TestTemplateTestDescriptor.java:139)
at org.junit.jupiter.engine.descriptor.TestTemplateTestDescriptor.lambda$execute$2(TestTemplateTestDescriptor.java:107)
at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:183)
at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:195)
at java.base/java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:177)
at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:195)
at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:183)
at java.base/java.util.stream.ReferencePipeline$11$1.accept(ReferencePipeline.java:442)
at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:195)
at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:195)
at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:195)
at java.base/java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1655)
at java.base/java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:658)
at java.base/java.util.stream.ReferencePipeline$7$1.accept(ReferencePipeline.java:274)
at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:195)
at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:195)
at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:195)
at java.base/java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1655)
at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:484)
at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:474)
at java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:150)
at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:173)
at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
at java.base/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:497)
at java.base/java.util.stream.ReferencePipeline$7$1.accept(ReferencePipeline.java:274)
at java.base/java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1655)
at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:484)
at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:474)
at java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:150)
at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:173)
at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
at java.base/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:497)
at org.junit.jupiter.engine.descriptor.TestTemplateTestDescriptor.execute(TestTemplateTestDescriptor.java:107)
at org.junit.jupiter.engine.descriptor.TestTemplateTestDescriptor.execute(TestTemplateTestDescriptor.java:42)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:139)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:129)
at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:127)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:126)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:84)
at java.base/java.util.ArrayList.forEach(ArrayList.java:1541)
at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:38)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:143)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:129)
at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:127)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:126)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:84)
at java.base/java.util.ArrayList.forEach(ArrayList.java:1541)
at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:38)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:143)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:129)
at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:127)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:126)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:84)
at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.submit(SameThreadHierarchicalTestExecutorService.java:32)
at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor.execute(HierarchicalTestExecutor.java:57)
at org.junit.platform.engine.support.hierarchical.HierarchicalTestEngine.execute(HierarchicalTestEngine.java:51)
at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:108)
at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:88)
at org.junit.platform.launcher.core.EngineExecutionOrchestrator.lambda$execute$0(EngineExecutionOrchestrator.java:54)
at org.junit.platform.launcher.core.EngineExecutionOrchestrator.withInterceptedStreams(EngineExecutionOrchestrator.java:67)
at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:52)
at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:96)
at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:75)
at gov.gsa.pivconformance.gui.GuiTestExecutionController.runAllTests(GuiTestExecutionController.java:258)
at gov.gsa.pivconformance.gui.SimpleTestExecutionPanel$2.lambda$actionPerformed$0(SimpleTestExecutionPanel.java:197)
at java.base/java.lang.Thread.run(Thread.java:834)
2021-02-11 13:53:21,042 INFO [Thread-1] [GuiTestListener.java:134] Finished 8.10.2:1 => oid = 2.16.840.1.101.3.7.2.144.0
2021-02-11 13:53:21,042 INFO [Thread-1] [GuiTestListener.java:134] Finished 8.10.2:SP800-73-4.36 test
2021-02-11 13:53:21,042 INFO [Thread-1] [GuiTestListener.java:134] Finished 8.10.2:SP800_73_4SecurityObjectTests
2021-02-11 13:53:21,042 INFO [Thread-1] [GuiTestListener.java:66] Test plan finished for conformance test 8.10.2
2021-02-11 13:53:21,042 INFO [Thread-1] [GuiTestListener.java:68] 8.10.2,"Parse data at tag 0xBA and for each data container found ensure that performing a select returns status words 0x90, 0x00",Pass,Fail
Reading the test case from SP 800-85B, we see that the object of this test so ensure that every hash specified in the security object's data group table matches the hash of the bytes in the container. We also see that the Cardholder Iris Images container can't be read. It's either missing or malformed.
Other errors may not be as simple to track down, but the debug log is the one log that contains the test case failures and some preliminary information to steer you to the right logs and artifacts.
The tags for each container are logged in the containers directory.
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. Container contents are stored in memory for quicker access and less stress on the card.
The binary form of each container is logged to the piv-artifacts directory. These are viewable certificates extracted from the card. The CHUID signing certificate is
X.509 certificates are extracted to the x509-artifacts directory from any containers that include X.509 certificates (including the CHUID).
The tool validates each certificate found on the card. A path build() to the appropriate trust anchor is attempted, supplying the end entity certificate, a trust anchor, 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 where identifier is a FASC-N or CHUID. All end-entity, intermediate, and root CA certs are saved to this directory. If a path cannot be built, the EE cert can be still found in the x509-artifacts directory but the intermediate certs for that path cannot be extracted.