Introduction

An AEP engine outputs several kinds of trace for tracing and debugging purposes. This document describes the trace outputs emitted by an AEP engine during startup, steady state and shutdown with information on how to control and interpret the output.

The Engine Loggers

An AEP engine's trace is controlled via the nv.aep trace logger. This logger is used by an AEP engine to output flow of exection type of trace messages. The amount of information output by the engine is controlled by the logger's trace level. When using the native logger, the default trace level is INFO. DEBUG is the only additional supported trace level. When using SLF4J, the default trace level is as defined by the concrete SLF4J binding used. The trace levels with SLF4J that control trace output are INFO (corresponding to the native INFO trace level) and TRACE (corresponding to the native DEBUG trace level).
The nv.aep logger is used to output flow of execution trace messages during startup, steady state and shutdown. In steady state, the engine uses additional loggers to log other types of trace messages. They are:

• The nv.aep.sno logger that traces the sequence numbers of inbound and outbound messages
  • Enabled via
    • nv.aep.sno.trace=debug when using native trace logging
    • Settng the level of the nv.aep.sno logger to Trace when using SLF4J
• The nv.aep.event logger that traces events dispatched to an engine
  • Enable via
    • nv.aep.event.trace=debug when using native trace logging
    • Setting the level of the nv.aep.event logger to Trace when using SLF4J
• The nv.aep.alert logger that traces alert events emitted by the engine. 
  • Enable via
    • nv.aep.alert.trace=info when using native trace logging
    • Setting the level of the nv.aep.alert logger to WARN when using SLF4J
• The nv.aep.txn logger that traces the execution of transactions within an engine
  • Enable via
    • nv.aep.txn.trace=debug when using native trace logging
    • Setting the level of the nv.aep.txn logger to Trace when using SLF4J
• The nv.aep.msg logger that traces the flow of messages through an engine.
  • Enable via
    • nv.aep.msg.trace=debug when using native trace logging
    • Settingthe level of the nv.aep.msg logger to Trace when using SLF4J

Configuration Settings

Whether or not the engine emits trace is configured by setting the appropriate property in the app config in DDL. Note that when using SLF4J logging that the trace level must be set to Trace for the corresponding logger. 

...
<apps>
  <app name="processor-send-driver" mainClass="com.neeve.embedded_xvm_sample.driver.SendDriver">
    <enableEventTrace>true</enableEventTrace>
    <enableAlertTrace>true</enableAlertTrace> <!--Since 3.11.61-->
    <enableScheduleTrace>On</enableScheduleTrace>
    <enableSequenceNumberTrace>On</enableSequenceNumberTrace>
    <enableTransactionTrace>On</enableTransactionTrace>
    <enableMessageTrace>true</enableMessageTrace>
    <messageTraceFilterUnsetFields>true</messageTraceFilterUnsetFields>
    <messageTraceInJson>true</messageTraceInJson>
    <messageTraceJsonStyle>SingleLine</messageTraceJsonStyle>
    <messageTraceMetadataDisplayPolicy>On</messageTraceMetadataDisplayPolicy>
    ...
  </app>
</apps>
...

The table below summarize the engine trace level knobs. See DDL Reference for additional details on these knobs. The following sections will discuss the trace output and interpretation in more detail. 

Startup

Since the engine outputs maximal information when started up in debug mode (nv.aep.trace=debug or nv.aep SLF4J logger level set to Trace, we'll talk through a sample startup output of an engine operating in debug mode descibing what different parts of the trace means. Refer to the trace level in the trace output for information what trace messages are output at what levels.

Engine Creation

The following pertains is outbound during engine creation i.e. when the engine initializes itself prior to start.

All engine creation related output is bracketed between the "Creating engine…"and "Engine created successfully" trace messages. The first part of the output contains the engine configuration (which the engine outputs at the CONFIG trace level (INFO for SLF4J)). The remainder of the trace relates to the engine initializing its internal data structures from various descriptors (bus, store, persister, etc) that it loads from platform configuration repository.

Engine Startup

An AEP engine goes through the following steps during startup:

1. Open the engine's inbound message log if configured separate from the ODS recovery log.
   1. Note: Such a configuration is not permissible for a clustered EventSourcing engine.
2. Open the engine's outbound message log if configure separate from the ODS recovery log.
3. Open the application's ODS store. This performs the following initial actions
   1. Advertize presence the agent on the discovery network.
   2. Using the discovery protocol, determine presence of cluster peer members and
   3. Elect agent's role in the cluster
4. If agent elected as primary
   1. Initialize application state by replaying entries from the recovery log.
   2. Bind (connect) to the configured message buses
5. If elected as backup
   1. Initialize application state by replaying entries from the primary agent's recovery log.
   2. Enter standby mode.

Note: A standalone engine (engine not configured to run in clustered mode) does not open an ODS store. Therefore, steps 3, 4a and 5 do not apply to such engines.
All engine startup related output is bracketed between the "Starting engine…"and "Engine started successfully…" trace messages. Engine startup trace is composed of trace related to each of the steps outlined above. The following extracts pertain to each of the steps above:

Creating the Message Logs

The trace related to message log creation describes how the engine parses the configured inbound and outbound message logging policies and how it goes about processing them. In the engine that outputs the above trace, the store persister is configured for use as the inbound logger (default for clustered event-sourced engine) and is not configured for outbound message logging.

Joining the Discovery Network

The next step is to join the discovery network using the discovery descriptor configured for the engine. The discovery protocol is used by an engine to discover peer agents. The engine that output the trace above was configured to use UDP based discovery to advertize itself and discover other cluster agents.

Role Election

While the above trace statement represents steps 3a and 3b in the steps outlined above, role election is performed by the engine's ODS store subsequent to joining the discovery network using the information gleaned from the discovery process There is no trace information output by the AEP engine related to the role election process and, therefore, does not appear in the above output. All role election related trace is output by the engine's ODS store with nv.ods logger's trace level set at verbose or above i.e. nv.ods.trace=verbose/debug or the nv.ods SLF4J logger level at DEBUG or TRACE.

Application State Initialization

The next step after role election is to initialize application state from the application's recovery log. A primary agent initializes state from its recovery log while a backup agent initializes its state from the cluster primary's recovery log. The following is sample trace for the various initialization scenarios (the trace above was performed by a primary event-sourced engine that initialized its state by 100 messages in the recovery log):

Primary Engine Fresh Start

An engine's automatically creates its recovery log if not found on startup (if configured for persistence). The recovery log is accompanied by a factories file that is also created when the log is created. The factories file is created when the log is created and contains the set of factories registered in the X runtime at the time the factories. The above trace indicates that a new factories file and no entries were found in the recovery log to recover from. Together, they indicate that a new recovery log was created.

Primary Engine Restart

The above trace is output by a primary engine whose recovery log is already present at startup. The trace messages output how many messages were recovered from the recovery log to initialize the application state. The above engine recovered 100 messages from the log to reinitiaize its state.

Backup Engine Fresh Start

After being elected a backup, an engine first backs up its recovery log if it exists before it initializes its state from the cluster primary since the state initialization process will write the primary's state to the backup's log. The above output is emit by a backup that is being started fresh i.e. a backup agent that does not have a recovery log from a previous run.

Backup Engine Restart

The above output is emit by a backup that has been restarted.

State Initialization Completion

Primary Engine

For a primary engine, the completion of the log recovery is indicated by the "…Materialized xxx objects from recovery log." trace entry.

Backup Engine

For a backup engine, the completion of the log recovery is indicated by the dispatch of a StoreMemberInitCompleteEvent event. This event is dispatched by an engine when it's initialization from the primary has completed i.e. the backup has completed joining the cluster. The following extract from a backup's log reflects the dispatch of the init completion event.

Startup Completion

Once role election and application initialization is complete, the engine starts the messaging machinery only if elected as primary. If elected as a backup, the engine goes into standby mode operating per its function as a backup member of an event sourced or state replicated cluster as the case may be. Therefore, strictly speaking, the completion of application initialization marks the completion of engine startup. For a primary engine, the starting of messaging happens immediately after engine startup while, for backup engines, messaging is started only after the primary fails and the backup is elected the new primary in the cluster. For the purpose of understanding the contents of the logs, one application initialization is complete, the entries in the log relating to the completion of the startup and starting messaging should be considered to be executing concurrently.

Start Messaging Success (Primary)

The following trace extract from above describes the successful starting of messaging by an agent elected as primary:

Once a primary agent has completed the application initialization, it immediately kicks off the start of the messaging machinery. The trace related to the starting of the messaging starts with the statement of the engine's state and ends with the dispatch of the 'messaging started' event to the application. The trace essentially comprises of the following:

• Trace describing the opening of the various bus bindings configured in the engine
• Dispatch of the various events related to the bus binding establishment. These events are:
  • Messaging Prestart event
  • Channel Up events
  • Bus Binding Started evebts
  • Messaging Started event

See the AEP Events documents for more details on these events. 
The highligted portion above indicates the completion of initialization. If initialization fails, the highlighted message will not be output replaced by a corresponding message indicating start failure is output. The key point here is that a messaging start failure (as deemed by the MessagingStartFailPolicy) is not interpreted by the engine as a start failure. In the event that messaging fails to start, the above highlighted message will still be output. If the failures encountered during the starting of messaging - one or more messaging bindings (connections) failing to open – alongwith the start fail policy resolve in messaging deemed to have failed, then the engine will immediately trigger the engine's stop machinery. However, the above highlighted message will still be displayed. See the next section where this is illustrated.

Start Messaging Fail (Primary)

The following trace extract illustrates the failed starting of messaging by an agent elected as primary. Note the highlighted portion that illusrrates the point made in the previous section.

Waiting for Failover (Backup)

The following is the corresponding trace output by an agent elected as backup:

Once the agent takes over as primary, the output is similar to the above (see Failover section below).

Steady State

By default, when operating in steady state, an AEP engine only outputs warning/error messages and no informational messages. However, the engine can be configured to emit the following types of trace messages:

• Output used to trace the detailed flow of execution of an engine
  • Enabled via:
    • nv.aep.trace=debug when using the native logger
    • Configuring the level of the nv.aep logger to Trace when using SLF4J
• Output used to trace the sequence numbers of inbound and outbound messages
  • Enabled via
    • nv.aep.sno.trace=debug when using the native logger
    • Configuring the level of the nv.aep.sno logger to Trace when using SLF4J
• Output used to trace events dispatched to an engine
  • Enable via
    • nv.aep.event.trace=debug when using the native logger
    • Configuring the level of the nv.aep.event logger to Trace when using SLF4J
• Output used to trace the execution of transactions within an engine
  • Enable via
    • nv.aep.txn.trace=debug when using the native logger
    • Configuring the level of the nv.aep.txn logger to Trace when using SLF4J
• Output used to trace the flow of messages through an engine.
  • Enable via
    • nv.aep.msg.trace=debug when using the native logger
    • Configuring the level of the nv.aep.msg logger to Trace when using SLF4J

Flow of Execution Trace

Switching on debug flow of execution trace during steady state produces a lot of output.

Sequence Number Trace

The sequence number trace outputs sequence numbers of inbound and outbound messages. The following is an example of the sequence number trace output.

Sequence number trace records are output at different stages in the processing of messages. They are:

• When an OK message is received by a primary or backup engine for processing
• When a DUP message is received by a primary engine for processing
• When an outbound message is sent by a primary agent
• When an outbound message is enqueed in the backup's outbound queue (ES + ReplicateBeforeSend)
• When an outbound message is pruned from the backup's outbound queue (ES + ReplicateBeforeSend)
• When an outbound message is discarded by the backup (ES + SendBeforeReplicate)
• When an inbound message is acknowledged after its transaction is complete
• When a message is retransmitted from a backup's outbound queue on failover (ES/SR + ReplicateBeforeSend)

Inbound Messages

<11,62355,TestMachine> 20130304-23:59:15:429 (dbg)...<-- [-905962955, 42, 1, 36] OK 
The above trace message indicates that a message wth sequence number #42 was received from sender on flow #1, the message being #36 on that flow and it passed the duplicate checks (indicated by OK). This trace message essentially indicates a successful receipt of the message by the engine for processing.

Inbound Duplicate Messages

The above trace message indicates that a message wth sequence number #42 was received from sender -905962955 on flow #1, the message being #36 on that flow but it did not pass the duplicate checks (indicated by DUP). Not passing the duplicate check implies that a message with the same sequence number has already been processed from the sender. Such a situation should really never happen in steady state but is normal to happen initiallt after a failover when in-doubt messages retransmitted by the messaging subsystem are filtered by new primary. 
These trace messages can only be output if duplicate checking is enabled on an engine (default=true).

Outbound Message

The above trace message is output when a message is sent by a primary in response to an inbound message i.e. 'solicited' send. Unsolicited sends do not output the above trace.

Outbound Message Enque in Backup Outbound Queue

The above trace message can only be output by a backup agent running in an event-sourced cluster configured for ReplicateBeforeSend. In such a configuration, the backup processes inbound messages in parallel with the primary (driven by replication traffic governed by the primary). Messages sent outbound as part of the processing inbound messages are enqueued in an outbound queue on the backup. Sequence number trace messages are output when outbound messages are enqueued in the backup's outbound message queue. For example, the above trace message indicates that message #84 from sender 2097807922 was enqueued in the backup's outbound queue.

Outbound Message Prune from Backup Outbound Queue

The above trace message can only be output by a backup agent running in an event-sourced cluster configured for ReplicateBeforeSend. Messages enqueued in a backup's outbound queue are removed when the ACK for the message is successfully received by the backup. The primary replicates such information in the replication header at which point the messages are pruned from the backup's outbound queue. The above is an example output when message #84 from sender 2097807922 was pruned from the backup's outbound queue. 
Note: For outbound messages, the sender id is the sending id of the engine outputting the trace.

Outbound Message Discard on Backup

The above trace message can only be output by a backup agent running in an event-sourced cluster configured for SendBeforeReplicate. In such a configuration, the backup processes inbound messages in parallel with the primary (driven by replication traffic governed by the primary). However, messages sent by the backup are not enqueued in the backup but rather discarded.

Inbound Message Acknolwedge

The above trace message is outbound when an inbiund message is considered stable and is acknowledged upstream. In the above trace output, the message swith sequence numbr #42 was successfully acknowledged upstream.

Outbound Message Retransmit

The above trace message can only be output by a backup agent running in an event-sourced cluster configured for ReplicateBeforeSend. On failover, the primary re-transmits all outbound messages in its backup outbound queue. For example, the above trace indicates that message #84 was not acknolwedged by the primary and is retansmitted on a failover.

Event Dispatch Trace

The event trace outputs events received by the AEP engine for processing. The following is an example outout of event dispatch trace:

Where the line starting with "<—" indicates that the the event was picked up by the engine's multiplexer thread, and the line starting with "<D>" indicates that the event was dispatch to registered application EventHandlers (note that not all events processed by an engine are forwarded on to application handlers). 

Waiting for messaging to start...

Receiving and forwarding messages...

Each event trace message contains the name of the event dispatched to the engine. This trace is particularly useful when combined with the sequence number tracer.
The event trace is output by both the primary and backup.

Transaction Execution Trace

The transaction execution trace outputs events each indicating an execution step in the engine's transaction workflow. The following is an example of transaction execution trace:

Transaction execution trace is not output by a backup agent.

Alert Trace

Alert trace traces any event implement IAlertEvent to the nv.aep.alert logger. For example, an UnhandleMessageEvent emitted because no MessageView factory could be found, would yield trace like:

Unlike other AepEngine loggers, alert trace is enabled by default. This is because under normal usage patterns alerts are almost always indicative of a problem. Application's that want finer grain control over logging of alert logging can disable alert trace and provide their own EventHandler for IAlertEvent. 

Message Trace

See Tracing Messages

Failover

The following is the trace (with nv.aep.trace=debug) of a backup that was elected primary on failover

The trace above is divided into two parts. The first part from "Engine is Primary" to the completion of the dispatch of the messaging started event is very similar to the trace of the primary engine starting messaging during startup. The part after that i.e.between the bold text is where the backup agent restransmits messages in its backup outbound queue on failover. In the above case only a single message was retransmitted. However, more than one message could be retransmitted. The retransmitted messages are transmitted using sequence numbers at the point at which the primary left off. 

Shutdown

The trace output by an engine during shutdown is relatively standard and does not warrant special explanation.

Some documentation goes here. 

The nv.aep.event logger that traces events dispatched to an engine

• Enable via
  • nv.aep.event.trace=debug when using native trace logging
  • Setting the level of the nv.aep.event logger to Trace when using SLF4J