corda/docs/source/tools-checkpoint-agent.rst

Checkpoint Agent

Firstly, please ensure you understand the mechanics and principles of Corda Flows by reading key-concepts-flows and flow-state-machines. We also recommend you understand the purpose and behaviour of the node-flow-hospital in relation to checkpoints and flow recovery. An advanced explanation of *checkpoints* <flow_internals_checkpoints_ref> within the flow state machine can be found here: contributing-flow-internals.

As a recap,

"A flow checkpoint is a serialised snapshot of the flow's stack frames and any objects reachable from the stack. Checkpoints are saved to the database automatically when a flow suspends or resumes, which typically happens when sending or receiving messages. A flow may be replayed from the last checkpoint if the node restarts. Automatic checkpointing is an unusual feature of Corda and significantly helps developers write reliable code that can survive node restarts and crashes. It also assists with scaling up, as flows that are waiting for a response can be flushed from memory."

The Checkpoint Agent is a very low level diagnostics tool that can be used to output the type, size and content of flow checkpoints at node runtime. It is primarily targeted at users developing and testing code that may exhibit flow mis-behaviour (preferably before going into production).

For a given flow checkpoint, the agent outputs:

1. Information about the checkpoint such as its id (also called a flow id) that can be used to correlate with that flows lifecycle details in the main Corda logs.
2. A nested hierarchical view of its reachable objects (indented and tagged with depth and size) and their associated sizes, including the state of any flows held within the checkpoint.

Diagnostics information is written to standard log files (eg. log4j2 configured logger).

This tool is particularly useful when used in conjunction with the dumpCheckpoints CRaSH shell command to troubleshoot and identify potential problems associated with checkpoints for flows that appear to not be completing.

The checkpoint agent can be downloaded from here.

To run simply pass in the following jar to the JVM used to start a Corda node: -javaagent:<PATH>/checkpoint-agent.jar[=arg=value,...]

Warning

This tool requires additional memory footprint and we recommended a minimal heap size of at least 1Gb.

The agent can be customised with a number of optional parameters described below.

Note

When using the gradle plugin utilities for deploying and running nodes, ensure the checkpoint agent jar is correctly passed to capsule as follows: -Dcapsule.jvm.args=-javaagent:checkpoint-agent.jar[=arg=value,...]

Configuration

The checkpoint agent can be started with the following optional parameters:

checkpoint-agent.jar=[instrumentType=<read|write>],[instrumentClassname=<CLASSNAME>],[minimumSize=<MIN_SIZE>],[maximumSize=<MAX_SIZE>, [graphDepth=<DEPTH>], [printOnce=<true|false>]

• instrumentType: whether to output checkpoints on read or write. Possible values: [read, write]. Default: read.
• instrumentClassname: specify the base type of objects to log. The default setting is to process all Flow object types. Default: net.corda.node.services.statemachine.FlowStateMachineImpl.
• minimumSize: specifies the minimum size (in bytes) of objects to log. Default: 8192 bytes (8K)
• maximumSize: specifies the maximum size (in bytes) of objects to log. Default: 20000000 bytes (20Mb)
• graphDepth: specifies how many levels deep to display the graph output. Default: unlimited
• printOnce: if true, will display a full object reference (and its sub-graph) only once. Otherwise an object will be displayed repeatedly as referenced. Default: true

These arguments are passed to the JVM along with the agent specification. For example:

-javaagent:<PATH>/checkpoint-agent.jar=instrumentClassname=net.corda.vega.flows.SimmFlow,instrumentType=read,minimumSize=10240,maximumSize=512000,graphDepth=6,printOnce=false

Note

Arguments may be passed into the agent in any order and should not contain spaces between them.

Checkpoint Dump support

When used in combination with the dumpCheckpoints shell command (see Upgrading CorDapps <upgrading-cordapps-flow-drains>.), the checkpoint agent will automatically output additional diagnostic information for all checkpoints dumped by the aforementioned tool.

You should therefore see two different output files upon invoking the checkpoint dumper command:

• <NODE_BASE>\logs\checkpoints_dump-<date>.zip contains zipped JSON representation of checkpoints (from dumpCheckpoints shell command)
• <NODE_BASE>\logs\checkpoints_agent-<date>.log contains output from this agent tool (types and sizes of a checkpoint stack)

Note

You will only see a separate checkpoints_agent-<date>.log file if you configure a separate log4j logger as described below. Otherwise all diagnostics logging will be routed to the standard Corda node log file: node-<hostname>.log.

If you only wish to log checkpoint data for failing flows, start the checkpoint agent with the following arguments:

checkpoint-agent.jar=instrumentType=read,instrumentClassname=NONE

and use the dumpCheckpoints shell command to trigger diagnostics collection.

Warning

The checkpoint agent JAR file must be called "checkpoint-agent.jar" as the checkpoint dump support code uses Java reflection to determine whether the VM has been instrumented or not at runtime.

Logging configuration

The agent will log output to a log4j2 configured logger.

It is recommended to configure a separate log file to capture this information by configuring an appender as follows:

<Logger name="CheckpointAgent" level="info" additivity="false">
    <AppenderRef ref="Checkpoint-Agent-RollingFile-Appender"/>
</Logger>

Warning

You must specify "CheckpointAgent" as the logger name.

In this instance we are specifying a Rolling File appender with archival rotation as follows:

<RollingFile name="Checkpoint-Agent-RollingFile-Appender"
             fileName="${log-path}/checkpoints_agent-${date:yyyyMMdd-HHmmss}.log"
             filePattern="${archive}/checkpoints_agent.%date{yyyy-MM-dd}-%i.log.gz">

    <PatternLayout pattern="[%-5level] %date{ISO8601}{UTC}Z [%t] %c{2}.%method - %msg%n"/>

    <Policies>
        <TimeBasedTriggeringPolicy/>
        <SizeBasedTriggeringPolicy size="100MB"/>
    </Policies>

    <DefaultRolloverStrategy min="1" max="100">
        <Delete basePath="${archive}" maxDepth="1">
            <IfFileName glob="${log-name}*.log.gz"/>
            <IfLastModified age="60d">
                <IfAny>
                    <IfAccumulatedFileSize exceeds="10 GB"/>
                </IfAny>
            </IfLastModified>
        </Delete>
    </DefaultRolloverStrategy>

</RollingFile>

The log4j2.xml containing the above configuration must now be be passed to the Corda node JVM along with the agent specification:

-Dlog4j.configurationFile=<PATH>/log4j2.xml

Sample output

Using the log4j2 configuration described above, the following output is generated to a file called checkpoints_agent-<DATE>.log under the Corda node logs directory for a single flow execution (in this case):

[INFO ] 2019-07-11T18:25:15,723Z [Node thread-1] CheckpointAgent. - [WRITE] Fiber@10000004:[43c7d5c8-aa66-4a98-beed-dc91354d0353][task: co.paralleluniverse.fibers.RunnableFiberTask@4dc8eaf(Fiber@10000004), target: null, scheduler: co.paralleluniverse.fibers.FiberExecutorScheduler@4e468018]
000:net.corda.node.services.statemachine.FlowStateMachineImpl 21,149

[INFO ] 2019-07-11T18:19:51,115Z [FiberDeserializationChecker] CheckpointAgent. - [READ] class net.corda.node.services.statemachine.FlowStateMachineImpl
000:net.corda.node.services.statemachine.FlowStateMachineImpl 21,151
001:  net.corda.node.services.statemachine.FlowStateMachineImpl 21,149
002:    java.lang.String 107
003:      [C 77
002:    co.paralleluniverse.fibers.Stack 20,932
003:      [J 278
003:      [Ljava.lang.Object; 20,054
004:        net.corda.finance.flows.CashIssueAndPaymentFlow 7,229
005:          net.corda.core.utilities.ProgressTracker 5,664
etc ...

[INFO ] 2019-07-11T18:35:03,198Z [rpc-server-handler-pool-2] CheckpointAgent. - [READ] class net.corda.node.services.statemachine.ErrorState$Clean
Checkpoint id: 15f16740-4ea2-4e48-bcb3-fd9051d5ba59
000:net.corda.node.services.statemachine.FlowStateMachineImpl 21,151
001:  [C 77
001:  [J 278
001:  [Ljava.lang.Object; 20,054
002:    java.util.ArrayList 1,658
003:      net.corda.core.utilities.ProgressTracker$STARTING 0
etc ...

Note,

• on WRITE (eg. a checkpoint is being serialized to disk), we have complete information of the checkpoint object including the Fiber it is running on and its checkpoint id (43c7d5c8-aa66-4a98-beed-dc91354d0353)
• on READ (eg. a checkpoint is being deserialized from disk), we only have information about the stack class hierarchy. Additionally, if we are using the CRaSH shell dumpCheckpoints command, we also see a flows checkpoint id.

Flow diagnostic process

Lets assume a scenario where we have triggered a flow in a node (eg. node acting as a flow initiator) but the flow does not appear to complete.

For example, you may see the following using the CRaSH shell flow watch command:

Id                                Flow name                                                           Initiator                        Status
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
15f16740-4ea2-4e48-bcb3-fd9051d5b Cash Issue And Payment                                              bankUser                         In progress
1c6c3e59-26aa-4b93-8435-4e34e265e Cash Issue And Payment                                              bankUser                         In progress
90613d6f-be78-41bd-98e1-33a756c28 Cash Issue And Payment                                              bankUser                         In progress
43c7d5c8-aa66-4a98-beed-dc91354d0 Cash Issue And Payment                                              bankUser                         In progress
Waiting for completion or Ctrl-C ...

Note that "In progress" indicates the flows above have not completed (and will have been checkpointed).

1. Check the main corda node log file for hospitalisation and/or flow retry messages: <NODE_BASE>\logs\node-<hostname>.log

[INFO ] 2019-07-11T17:56:43,227Z [pool-12-thread-1] statemachine.FlowMonitor. - Flow with id 90613d6f-be78-41bd-98e1-33a756c28808 has been waiting for 97904 seconds to receive messages from parties [O=BigCorporation, L=New York, C=US].

Note

Always search for the flow id, in this case 90613d6f-be78-41bd-98e1-33a756c28808

2. From the CRaSH shell run the dumpCheckpoints command to trigger diagnostics information.

Welcome to the Corda interactive shell.
Useful commands include 'help' to see what is available, and 'bye' to shut down the node.

Thu Jul 11 18:56:48 BST 2019>>> run dumpCheckpoints

You will now see an addition line in the main corda node log file as follows:

[INFO ] 2019-07-11T18:02:47,610Z [rpc-server-handler-pool-0] rpc.CheckpointDumper. - Checkpoint agent processing checkpointId: [90613d6f-be78-41bd-98e1-33a756c28808]

And two additional files will appear in the nodes logs directory:

• <NODE_BASE>\logs\checkpoints_dump-20190711-180247.zip
• <NODE_BASE>\logs\checkpoints_agent-20190711-185424.log

3. Unzip the <NODE_BASE>\logs\checkpoints_dump-<date>.zip file, and you should see a file with a matching flow id as above: CashIssueAndPaymentFlow-90613d6f-be78-41bd-98e1-33a756c28808.jsos

   It contents will contain the following diagnostics information:

{
  "id" : "90613d6f-be78-41bd-98e1-33a756c28808",
  "flowLogicClass" : "net.corda.finance.flows.CashIssueAndPaymentFlow",
  "flowLogic" : {
    "amount" : "200.00 USD",
    "issueRef" : "AQ==",
    "recipient" : "O=BigCorporation, L=New York, C=US",
    "anonymous" : true,
    "notary" : "O=Notary Service, L=Zurich, C=CH"
  },
  "flowCallStack" : [
    {
      "flowClass" : "net.corda.confidential.SwapIdentitiesFlow",
      "progressStep" : "Awaiting counterparty's anonymous identity"
    },
    {
      "flowClass" : "net.corda.finance.flows.CashPaymentFlow",
      "progressStep" : "Generating anonymous identities"
    },
    {
      "flowClass" : "net.corda.finance.flows.CashIssueAndPaymentFlow",
      "progressStep" : "Paying recipient"
    }
  ],
  "suspendedOn" : {
    "sendAndReceive" : [
      {
        "session" : {
          "peer" : "O=BigCorporation, L=New York, C=US",
          "ourSessionId" : 1443438003030966253
        },
        "sentPayloadType" : "net.corda.confidential.SwapIdentitiesFlow$IdentityWithSignature",
        "sentPayload" : {
          "identity" : {
            "class" : "net.corda.core.identity.PartyAndCertificate",
            "deserialized" : "O=BankOfCorda, L=London, C=GB"
          },
          "signature" : "t+7hyUnQE08n3ST4krA/7fi1R8ItdrGvpeEbMFgTBDCHibMWiKo/NaTSVUdfwPmsEtl1PFx0MHz5rtRQ+XuEBg=="
        }
      }
    ],
    "suspendedTimestamp" : "2019-07-10T14:44:58",
    "secondsSpentWaiting" : 98268
  },
  "origin" : {
    "rpc" : "bankUser"
  },
  "ourIdentity" : "O=BankOfCorda, L=London, C=GB",
  "activeSessions" : [ ],
  "errored" : null
}

4. View the contents of the node agent diagnostics file:

[INFO ] 2019-07-11T18:02:47,615Z [rpc-server-handler-pool-0] CheckpointAgent. - [READ] class net.corda.node.services.statemachine.Checkpoint
Checkpoint id: 90613d6f-be78-41bd-98e1-33a756c28808
000:net.corda.node.services.statemachine.Checkpoint 29,200
001:  net.corda.node.services.statemachine.ErrorState$Clean 0
001:  net.corda.node.services.statemachine.FlowState$Started 26,061
002:    net.corda.core.internal.FlowIORequest$SendAndReceive 4,666
003:      java.util.Collections$SingletonMap 4,536
004:        net.corda.node.services.statemachine.FlowSessionImpl 500
005:          net.corda.core.identity.Party 360
005:          net.corda.node.services.statemachine.SessionId 28
004:        net.corda.core.serialization.SerializedBytes 3,979
002:    net.corda.core.serialization.SerializedBytes 21,222
001:  net.corda.core.context.InvocationContext 905
002:    net.corda.core.context.Actor 259
002:    net.corda.core.context.InvocationOrigin$RPC 13
002:    net.corda.core.context.Trace 398
001:  net.corda.core.identity.Party 156
002:    net.i2p.crypto.eddsa.EdDSAPublicKey 45
002:    net.corda.core.identity.CordaX500Name 92
001:  java.util.LinkedHashMap 327
002:    net.corda.node.services.statemachine.SessionState$Initiating 214
001:  java.util.ArrayList 1,214
002:    net.corda.node.services.statemachine.SubFlow$Inlined 525
003:      java.lang.Class 47
003:      net.corda.node.services.statemachine.SubFlowVersion$CorDappFlow 328
004:        net.corda.core.crypto.SecureHash$SHA256 118
005:          [B 33
002:    net.corda.node.services.statemachine.SubFlow$Initiating 322
003:      java.lang.Class 39
003:      net.corda.core.flows.FlowInfo 124
003:      net.corda.node.services.statemachine.SubFlowVersion$CorDappFlow 11
002:    net.corda.node.services.statemachine.SubFlow$Initiating 250
003:      java.lang.Class 41
003:      net.corda.core.flows.FlowInfo 99
004:        java.lang.String 91
005:          [C 85
003:      net.corda.node.services.statemachine.SubFlowVersion$CoreFlow 28

5. Take relevant recovery action, which may include:

• killing and retrying the flow:

Welcome to the Corda interactive shell.
Useful commands include 'help' to see what is available, and 'bye' to shut down the node.

Thu Jul 11 20:24:11 BST 2019>>> flow kill 90613d6f-be78-41bd-98e1-33a756c28808
[ERROR] 20:24:18+0100 [Node thread-1] corda.flow. - Flow interrupted while waiting for events, aborting immediately {actor_id=bankUser, actor_owning_identity=O=BankOfCorda, L=London, C=GB, actor_store_id=NODE_CONFIG, fiber-id=10000003, flow-id=15f16740-4ea2-4e48-bcb3-fd9051d5ba59, invocation_id=45622dc7-c4cf-4d11-85ad-1c45e0943455, invocation_timestamp=2019-07-11T18:19:40.519Z, origin=bankUser, session_id=02010e15-8e7a-46f7-976b-5e0626451c54, session_timestamp=2019-07-11T18:19:32.285Z, thread-id=176}
Killed flow [90613d6f-be78-41bd-98e1-33a756c28808]

Thu Jul 11 20:26:45 BST 2019>>> flow start CashIssueAndPaymentFlow amount: $1000, issueRef: 0x01, recipient: "Bank B", anonymous: false, notary: "Notary Service"

• attempting to perform a graceful shutdown (draining all outstanding flows and preventing others from starting) and re-start of the node:

Welcome to the Corda interactive shell.
Useful commands include 'help' to see what is available, and 'bye' to shut down the node.

Thu Jul 11 19:52:56 BST 2019>>> gracefulShutdown

Upon re-start ensure you disable flow draining mode to allow the node to continue to receive requests:

Welcome to the Corda interactive shell.
Useful commands include 'help' to see what is available, and 'bye' to shut down the node.

Thu Jul 11 19:52:56 BST 2019>>> run setFlowsDrainingModeEnabled enabled: false

See also Flow draining mode <draining-mode>.

• contacting other participants in the network where their nodes are not responding to an initiated flow. The checkpoint dump gives good diagnostics on the reason a flow may be suspended (including the destination peer participant node that is not responding):

"suspendedOn" : {
  "sendAndReceive" : [
    {
      "session" : {
        "peer" : "O=BigCorporation, L=New York, C=US",
        "ourSessionId" : 1443438003030966253
      },
      "sentPayloadType" : "net.corda.confidential.SwapIdentitiesFlow$IdentityWithSignature",
      "sentPayload" : {
        "identity" : {
          "class" : "net.corda.core.identity.PartyAndCertificate",
          "deserialized" : "O=BankOfCorda, L=London, C=GB"
        },
        "signature" : "t+7hyUnQE08n3ST4krA/7fi1R8ItdrGvpeEbMFgTBDCHibMWiKo/NaTSVUdfwPmsEtl1PFx0MHz5rtRQ+XuEBg=="
      }
    }