Loggers - Redundancy

This article covers loggers related to Redundancy that were introduced in Ignition version 7.9.X.

Loggers in this article:

• Redundancy.StateMonitoring

  • Redundancy.StateMonitoring.Channels.MasterTCPChannel

  • Redundancy.StateMonitoring.Channels.BackupTCPChannel

  • Redundancy.StateMonitoring.MasterStateManager

  • Redundancy.StateMonitoring.BackupStateManager

Redundancy.StateMonitoring

A series of loggers monitoring creation, communication, and disconnect for Redundancy on either the Master or Backup server. 7.8 contains a logger with the same name, however, the output of this logger provides different information for each level.

Redundancy.StateMonitoring.Channels.MasterTCPChannel

• Provides information about initialization and closing of the connection from the master node, as well as the synchronization of the two nodes.
  • INFO log that shows both the initialization and later, the closing of the connection for a redundant pair:

    Reporting master start time of Wed Dec 31 16:00:00 PST 1969 Peer node information has been updated: RedundancyNode(address=10.10.65.60, httpAddresses=[http://10.10.65.60:8088/main], sessionCount=0, activityLevel=Active, projectState=Good) ... Performing full sync. Runtime updates are paused until this completes. Full sync complete. Runtime updates can now be processed … Peer node information has been updated: RedundancyNode(address=10.10.65.60, httpAddresses=[http://10.10.65.60:8088/main], sessionCount=0, activityLevel=Cold, projectState=Good) … (id=1) Shutting down channel.

• • DEBUG log that shows additional detail for both the initialization and later, the closing of the connection for a redundant pair. In this example, the master node was set back to Independent to close the socket connection:

    (id=1) Initial contact with '/10.10.65.60', will attempt handshake Starting redundancy channel id 1 … Backup node's activity level is 'Active', and the master is currently active or the recovery mode is set to 'Automatic'. Sending a request for backup to become non-active. ... Comparing module manifests: [(com.inductiveautomation.alarm-notification/4.9.18 (b2021062913)), (com.inductiveautomation.eam/2.9.18 (b2021062913)), (com.inductiveautomation.phone-notification/3.8.5 (b2016120813)), (com.inductiveautomation.sfc/3.9.18 (b2021062920)), (com.inductiveautomation.sms-notification/4.9.18 (b2021062920)), (com.inductiveautomation.taghistorian/2.9.18 (b2021062920)), (dnp3-driver/2.9.18 (b2021062920)), (fpmi/9.9.18 (b2021062913)), (fsql/8.9.18 (b2021062920)), (help/4.9.18 (b2021062920)), (ia.voice.en_us_katherine/3.8.2 (b0)), (logix-v21/3.9.18 (b2021062913)), (mobile/4.9.18 (b2021062913)), (modbus-driver2/5.9.18 (b2021062920)), (omron-driver/2.9.18 (b2021062913)), (opccom/4.9.18 (b2021062920)), (rept/4.9.18 (b2021062913)), (siemens-drivers/4.9.18 (b2021062913)), (symfact/5.9.18 (b2021062920)), (udp-driver/4.9.18 (b2021062913)), (xopc/4.9.18 (b2021062920)), (xopc-drivers/4.9.18 (b2021062920))] [(com.inductiveautomation.alarm-notification/4.9.18 (b2021062913)), (com.inductiveautomation.eam/2.9.18 (b2021062913)), (com.inductiveautomation.phone-notification/3.8.5 (b2016120813)), (com.inductiveautomation.sfc/3.9.18 (b2021062920)), (com.inductiveautomation.sms-notification/4.9.18 (b2021062920)), (com.inductiveautomation.taghistorian/2.9.18 (b2021062920)), (dnp3-driver/2.9.18 (b2021062920)), (fpmi/9.9.18 (b2021062913)), (fsql/8.9.18 (b2021062920)), (help/4.9.18 (b2021062920)), (ia.voice.en_us_katherine/3.8.2 (b0)), (logix-v21/3.9.18 (b2021062913)), (mobile/4.9.18 (b2021062913)), (modbus-driver2/5.9.18 (b2021062920)), (omron-driver/2.9.18 (b2021062913)), (opccom/4.9.18 (b2021062920)), (rept/4.9.18 (b2021062913)), (siemens-drivers/4.9.18 (b2021062913)), (symfact/5.9.18 (b2021062920)), (udp-driver/4.9.18 (b2021062913)), (xopc/4.9.18 (b2021062920)), (xopc-drivers/4.9.18 (b2021062920))] … (id=1) Channel state set to 'CONNECTED' … Backup node's activity level is 'Active', and the master is currently active or the recovery mode is set to 'Automatic'. Sending a request for backup to become non-active. … (id=1) Channel state set to 'DISCONNECTED'

• • TRACE log showing comparison between the two redundant nodes to ensure synchronization. These logs will be reported every few seconds or so. This appears to be the only logger’s level that is the same as 7.8’s of the same name:

    Performing full backup node version check. Backup node version: [94124ae2-ebb6-4837-bf3e-07966a74ef54/0] Our version: [94124ae2-ebb6-4837-bf3e-07966a74ef54/0] Backup node version is OK.

Back to top

Redundancy.StateMonitoring.Channels.BackupTCPChannel

• Provide information about initialization and closing of the connection from the backup node, as well as the synchronization of the two nodes.
  • INFO log that shows both the initialization and later, the closing of the connection for a redundant pair:

    Server time sync complete. Server time is different by -849 ms. Master start time was reported to be 'Thu Oct 14 11:00:21 PDT 2021' (adjusted to backup clock) Peer node information has been updated: RedundancyNode(address=null, httpAddresses=null, sessionCount=0, activityLevel=Active, projectState=null) … Peer node information has been updated: RedundancyNode(address=169.254.56.163, httpAddresses=[http://169.254.56.163:8088/main], sessionCount=0, activityLevel=Active, projectState=Good) Project version synchronized, backup node is up-to-date. … Peer node information has been updated: RedundancyNode(address=169.254.56.163, httpAddresses=[http://169.254.56.163:8088/main], sessionCount=0, activityLevel=Active, projectState=null) … (id=1) Shutting down channel.

• • DEBUG log that shows additional detail for both the initialization and later, the closing of the connection for a redundant pair. In this example, a node was set back to Independent to close the socket connection:

    Starting redundancy channel id 1 Attempting to connect to '/10.10.60.75':8750  …  (id=1) Initial contact with '/10.10.60.75', will attempt handshake  …  Master has sent an updated project state. New projectState = 'Good'  …  (id=1) Channel state set to 'CONNECTED'  …  Channel thread was interrupted, system likely shutting down or redundancy stopped. java.lang.InterruptedException: null at java.lang.Object.wait(Native Method) at com.inductiveautomation.ignition.gateway.redundancy.channels.tcp.TcpBackupStateChannel .sleepThread(TcpBackupStateChannel.java:533) at com.inductiveautomation.ignition.gateway.redundancy.channels.tcp.TcpBackupStateChannel .runProtocol(TcpBackupStateChannel.java:235) at com.inductiveautomation.ignition.gateway.redundancy.channels.tcp.AbstractTcpChannel .run(AbstractTcpChannel.java:358)

• • TRACE log showing the process of calculating the time difference between the two gateways during the initialization process as well as declaring when the nodes are in sync:

    Time sync negotiation, sample 1: [1634234466606,1634234465773,32] … Time sync negotiation, sample 2: [1634234467111,1634234466276,31] Time sync negotiation, sample 3: [1634234467611,1634234466777,32] … Ping index 2, message: CurrentStateMessage[activity=Cold, sessions=0, projectstate=Unknown] … Last execution cycle took 1 seconds. Will sleep for 0 ms. … Ping index 3, message: [RTSYNC_MSG, id=300] … Runtime state is up-to-date. Last execution cycle took 32 ms. Will sleep for 968 ms. Ping index 2, message: CurrentStateMessage[activity=Cold, sessions=0, projectstate=Good]

• • TRACE log showing periodic checks to ensure synchronization. These logs will be reported every second:

    Last execution cycle took 56 ms. Will sleep for 944 ms. Ping index 3, message: [RTSYNC_MSG, id=300] Runtime state is up-to-date. Last execution cycle took 33 ms. Will sleep for 967 ms. Ping index 0, message: [PING_HELLO, id=1] Last execution cycle took 33 ms. Will sleep for 967 ms. Ping index 1, message: CurrentVersionMessage[uid=d81b1dd3-f28d-4c06-85ec-c84d93868d7c,revision=0,infoonly=false]

     

Back to top

Redundancy.StateMonitoring.MasterStateManager

• Also provides information about the initialization, active connection, and closing of the connection from the master node.
  • INFO logger stating a successful connection then later closed. This appears to be the only logger’s level that is different compared to 7.8’s logger of the same name:

    System UID has been updated to 'd81b1dd3-f28d-4c06-85ec-c84d93868d7c' ... Redundancy master state monitoring server started on port 8750 … Connection registered from '/10.10.65.60:61363' … Redundancy state changed: Role=Master, Activity level=Active, Project state=Good, History level=Full … Join-wait time has expired, will refresh system state. … Redundancy master state monitoring server stopped.

• • DEBUG log providing details about the connection’s channel id:

    Registered channel id '5' Monitoring channel detected. ... Unregistering closed channel '5'

• • TRACE log providing the current state of the Master node. These logs will be reported every few seconds or so:

    Refreshing redundant state (forced=false). Current state: [RedundancyState[role=Master, activity level=Active, project state=Good, history level=Full]

Back to top

Redundancy.StateMonitoring.BackupStateManager

• Provides information about the initialization and active connection of the connection from the backup node.
  • INFO logger stating a successful connection:

    Redundancy state changed: Role=Backup, Activity level=Cold, Project state=Unknown, History level=Full Backup redundancy node state manager started. Will attempt to connect to master at '/10.10.60.75' … Redundancy state changed: Role=Backup, Activity level=Cold, Project state=Good, History level=Full

• • DEBUG log providing additional details about the connection’s state:

    Calculating activity. Existing level: Cold, Channel state: UNSURE, negotiated level: Undecided, project state: Unknown, join-wait expired: false … Calculating activity. Existing level: Cold, Channel state: CONNECTED, negotiated level: Cold, project state: Good, join-wait expired: false

     

• • TRACE log providing the current state of the Backup node. These logs will be reported every few seconds or so:

    Refreshing redundant state (forced=false). Current state: [Role=Backup, Activity level=Cold, Project state=Good, History level=Full]

Back to top