Yokogawa FAST/TOOLS

Yokogawa FAST/TOOLS is a scalable and hardware-independent real-time information management and visualization software environment. It implements a web-based supervisory control human-machine interface, OPC server/client functions, data acquisition from various controllers and devices, alarm management, and historical data management. FAST/TOOLS supports redundant and nonstop systems and provides online configuration capabilities.

Types of Logs

NXLog can collect FAST/TOOLS log data from the following sources:

Collecting diagnostic data from log files

FAST/TOOLS and its components create diagnostic data in various log files and in most cases, the logs do not follow a unified formatting schema. Most log files are saved in the dedicated directory C:\Users\Public\Yokogawa\tls\log\.

To handle the inconsistent formatting of these logs, NXLog can make use of regular expressions to parse log records into structured data. Regular expressions can also contain named capturing groups so that the resulting fields will be automatically added to the output.

This section discusses the different types of file-based logs and provides information on how to collect and process log entries with NXLog. Each example contains an original input sample, an NXLog configuration, and an output log sample.

Table 1. List of log files
Log type File name

System error log

umhlog.log

Start log

fast_start.log
fast_start_*.log

System monitor logs

smdmon.log
smd_<node name>_<logging level>_<process name>.log

Alarm kernel debugger log

smd_<node_name>_<log_level>_almdbg_all.log

Data Set Services debugger log

smd_<node_name>_<log_level>_dssxdb_all.log

DUR debugger log

smd_<node_name>_<log_level>_durdbg_all.log

DUR simulator log

smd_<node_name>_<log_level>_dursim_logging.log

EQUIPMENT/FAST debugger log

smd_<node_name>_<log_level>_eqpdbg_all.log

History manager (HIS) debugger log

smd_<node_name>_<log_level>_hisdbg_all.log

ISM debugger log

smd_<node_name>_<log_level>_ismdbg_all.log

ITH debugger log

smd_<node_name>_<log_level>_ithdbg_all.log

ITM debugger log

smd_<node_name>_<log_level>_itmdbg_all.log

OPC debugger log

smd_<node_name>_<log_level>_opcdbg_all.log

SMDSNP general log

smd_<node_name>_<log_level>_smdsnp_general.log

SMDSNP lock log

smd_<node_name>_<log_level>_smdsnp_lock.log

SMDSNP process log

smd_<node_name>_<log_level>_smdsnp_process.log

EQPMDC log

EQPMDC.xml

System error log and start log

Any error messages produced by FAST/TOOLS components are processed by the Unsolicited Message Handler (UMH). The primary function of the UMH is to build and display messages in response to requests from FAST/TOOLS components. These requests may be a result of detected errors or other informational events. The logging process UMHLOG receives the messages from UMH in its receive buffer. Processed messages are written to the log file umhlog.log in the FAST/TOOLS log directory.

The start log contains information about the startup process of the FAST/TOOLS components. A new file is created after each start, and the old file is renamed to fast_start_*.log.

Example 1. Processing system error log and start log files

The following two input samples are taken from umhlog.log and fast_start.log respectively.

umhlog.log input sample
--> From: EQPMDC       (UNLICENCED) on Thu May 27 06:51:35 2021
EQP-E-TCPNOCON, Connection on TCP level not (yet) established
EQP-W-LIN_COM_BAD, Communication with station DUMMYSTATION_1 via line 0 bad
EQP-E-SLV_COM_BAD, Communication with station DUMMYSTATION_1 bad
fast_start.log input sample
--> From: OPCEXE       (Node 1/Task -1) on Thu May 27 06:51:36 2021
GIN-I-DII_INI_FLW, Flow control started for node 1
Pri Type   Time raised        Inst   Unit   Item             Text
 0  ALARM  27-MAY-21 06:51:36 DUMMYI MAIN   P0               overranged
 0  ALARM  27-MAY-21 06:51:36 DUMMYI MAIN   P9               overranged
REPORT/FAST started
ACCESS/FAST started
USER Web servers started
FAST/Start started
INTEGRATION started
FAST/TOOLS started
2021-05-27 06:51:43.08::INFO:  Logging to STDERR via org.mortbay.log.StdErrLog
2021-05-27 06:51:43.037::INFO:  jetty-6.1.x
2021-05-27 06:51:44.599::INFO:  Started SocketConnector@0.0.0.0:8080

The example below is based on fast_start.log due to the higher complexity of this log file. Event formats found in umhlog.log are similar to those found in fast_start.log and can be processed using the same configuration. To process umhlog.log, simply replace the log file name in the File directive of the from_file input instance.

The start log is designed to be a human-readable log file consisting of a header and four different types of events. The following is an example of each event type and the regular expression used to parse each type.

Header part
--> From: OPCEXE       (Node 1/Task -1) on Thu May 27 06:51:36 2021

Based on this header, the following fields can be parsed:

  • Process

  • Node

  • Task

  • Timestamp (ANSI C asctime() format)

Defining the UMHLOGTOO_HEAD_REGEX regular expression
define UMHLOGTOO_HEAD_REGEX     /(?x)^-->\s*From\:\s*(?<Process>.*?)\s+\
                                \((?:Node\s*)?(?<Node>.*?)[\/\)]+\
                                (?:Task\s*(?<Task>.*?)[\/\)]+)?\s*on\s*\
                                (\w+\s*\w+\s*\d+\s*\d+.\d+.\d+\s*\d+)/
Event type 1
GIN-I-DII_INI_FLW, Flow control started for node 1

Based on this type of event, the following fields can be parsed:

  • Component

  • Message

Defining the UMHLOGTOO_TYPE1_REGEX regular expression
define UMHLOGTOO_TYPE1_REGEX    /(?x)^(?:(?<Component>[A-Z]+[\w\-]+)\s*\,\s*\
                                (?<Message>.*))/
Event type 2
Pri Type   Time raised        Inst   Unit   Item             Text
 0  ALARM  27-MAY-21 06:51:36 DUMMYI MAIN   P0               overranged
 0  ALARM  27-MAY-21 06:51:36 DUMMYI MAIN   P9               overranged

Based on the second type of event, the following fields can be parsed:

  • Priority

  • Type

  • Time raised

  • Instance

  • Unit

  • Item

  • Text

Defining the UMHLOGTOO_TYPE2_REGEX regular expression
define UMHLOGTOO_TYPE2_REGEX    /(?x)^\s*(?<Priority>\d+)\s+\
                                (?<Type>[A-Z]*)\s+\
                                (\d+.\w+.\d+.\d+.\d+.\d+)\s+\
                                (?<Instance>.*?)\s+\
                                (?<Unit>.*?)\s+\
                                (?<Item>.*?)\s+\
                                (?<Text>.*)/
Event type 3
REPORT/FAST started
ACCESS/FAST started
USER Web servers started
FAST/Start started
INTEGRATION started
FAST/TOOLS started

The third type of event contains information about FAST/TOOLS started bricks and can be parsed as a single field called Message.

Defining the UMHLOGTOO_TYPE3_REGEX regular expression
define UMHLOGTOO_TYPE3_REGEX    /(?x)^(?<Message>[A-Z]{2,}[^\,]*started)$/
Event type 4
2021-05-27 06:51:43.08::INFO:  Logging to STDERR via org.mortbay.log.StdErrLog
2021-05-27 06:51:43.037::INFO:  jetty-6.1.x
2021-05-27 06:51:44.599::INFO:  Started SocketConnector@0.0.0.0:8080

Based on the fourth type of event, the following fields can be parsed:

  • Timestamp (yyyy-mm-dd hh:mm:ss.xxx)

  • Severity

  • Message

Defining the UMHLOGTOO_TYPE4_REGEX regular expression
define UMHLOGTOO_TYPE4_REGEX    /(?x)^(\d+.\d+.\d+.\s+\d+.\d+.\d+.\d+)\:+\
                                (?<Severity>.*?)\:\s*\
                                (?<Message>.*)/

The regular expressions above are defined in the configuration as constants.

To read and parse log messages this NXLog configuration uses the im_file input module. An Exec block is used to match the log line ($raw_event) against the appropriate regular expression. Once a match occurs, the respective fields are created according to the named capturing groups.

The timestamp fields are converted to datetime using the parsedate()function or the strptime() function if a custom date/time format is used.

Finally, the fields are converted to JSON using the to_json() procedure of the xm_json module. If the log line does not match any of the defined regular expressions, it is discarded using the drop() procedure.

The following NXLog configuration combines all the steps described above.

nxlog.conf
# Regular expressions defined as a constants to read the content of the logs
define UMHLOGTOO_HEAD_REGEX     /(?x)^-->\s*From\:\s*(?<Process>.*?)\s+\
                                \((?:Node\s*)?(?<Node>.*?)[\/\)]+\
                                (?:Task\s*(?<Task>.*?)[\/\)]+)?\s*on\s*\
                                (\w+\s*\w+\s*\d+\s*\d+.\d+.\d+\s*\d+)/

define UMHLOGTOO_TYPE1_REGEX    /(?x)^(?:(?<Component>[A-Z]+[\w\-]+)\s*\,\s*\
                                (?<Message>.*))/

define UMHLOGTOO_TYPE2_REGEX    /(?x)^\s*(?<Priority>\d+)\s+\
                                (?<Type>[A-Z]*)\s+\
                                (\d+.\w+.\d+.\d+.\d+.\d+)\s+\
                                (?<Instance>.*?)\s+\
                                (?<Unit>.*?)\s+\
                                (?<Item>.*?)\s+\
                                (?<Text>.*)/

define UMHLOGTOO_TYPE3_REGEX    /(?x)^(?<Message>[A-Z]{2,}[^\,]*started)$/

define UMHLOGTOO_TYPE4_REGEX    /(?x)^(\d+.\d+.\d+.\s+\d+.\d+.\d+.\d+)\:+\
                                (?<Severity>.*?)\:\s*\
                                (?<Message>.*)/

# Part of the log path defined as a constant
define LOG_PATH                 C:\Users\Public\Yokogawa\tls\log

<Extension json>
    Module      xm_json
</Extension>

<Input from_file>
    Module      im_file
    File        '%LOG_PATH%\fast_start.log'

    <Exec>
        # Matches the events with a regular expression
        if $raw_event =~ %UMHLOGTOO_HEAD_REGEX%
        {
            # Creates the timestamp
            $EventTime = parsedate($4);
        }
        else if $raw_event =~ %UMHLOGTOO_TYPE1_REGEX% or
                $raw_event =~ %UMHLOGTOO_TYPE3_REGEX%
        {
            # No further parsing required
        }
        else if $raw_event =~ %UMHLOGTOO_TYPE2_REGEX%
        {
            # Creates the timestamp
            $TimeRaised = strptime($3, '%d-%b-%y %H:%M:%S');
        }
        else if $raw_event =~ %UMHLOGTOO_TYPE4_REGEX%
        {
            # Creates the timestamp
            $EventTime = parsedate($1);
        }
        # Discarding message if it does not match any expression
        else drop();

        # Formats the result as JSON
        to_json();

        # Replaces unwanted whitespace characters
        $raw_event =~ s/\s{2,}/ /g;
    </Exec>
</Input>

The following output samples depict the processed events in JSON format.

Output sample of the header
{
  "EventReceivedTime": "2021-05-27T06:51:37.121883-07:00",
  "SourceModuleName": "from_file",
  "SourceModuleType": "im_file",
  "Node": "1",
  "Process": "OPCEXE",
  "Task": "-1",
  "EventTime": "2021-05-27T06:51:36.000000-07:00"
}
Output sample of event type 1
{
  "EventReceivedTime": "2021-05-27T06:51:37.121883-07:00",
  "SourceModuleName": "from_file",
  "SourceModuleType": "im_file",
  "Component": "GIN-I-DII_INI_FLW",
  "Message": "Flow control started for node 1"
}
Output sample of event type 2
{
  "EventReceivedTime": "2021-05-27T06:51:37.121883-07:00",
  "SourceModuleName": "from_file",
  "SourceModuleType": "im_file",
  "Instance": "DUMMYI",
  "Item": "P0",
  "Priority": "0",
  "Text": "overranged ",
  "Type": "ALARM",
  "Unit": "MAIN",
  "TimeRaised": "2021-05-27T06:51:36.000000-07:00"
}
Output sample of event type 3
{
  "EventReceivedTime": "2021-05-27T06:51:37.121883-07:00",
  "SourceModuleName": "from_file",
  "SourceModuleType": "im_file",
  "Message": "REPORT/FAST started"
}
Output sample of event type 4
{
  "EventReceivedTime": "2021-05-27T06:51:44.153165-07:00",
  "SourceModuleName": "from_file",
  "SourceModuleType": "im_file",
  "Message": "Logging to STDERR via org.mortbay.log.StdErrLog",
  "Severity": "INFO",
  "EventTime": "2021-05-27T06:51:43.080000-07:00"
}

System monitor and diagnostics logs

The FAST/TOOLS system monitor provides information about tools, processes, queues, nodes, and locks in the FAST/TOOLS system. Additionally, it also displays critical indicators about the FAST/TOOLS performance.

FAST/TOOLS provides a set of debugger processes designed to give visibility into the internal data of each system module. The system monitor continuously gathers and logs information about the system and the system modules.

System monitor provides various logging levels which affect the frequency and type of events that are logged:

  • Off - No information is gathered

  • Low - Information is gathered at a low frequency

  • Medium - Information is gathered at a higher frequency

  • High - Information is gathered at a high frequency

The logging level can be specified in the configuration file located at C:\Program Files (x86)\Yokogawa\FAST TOOLS\tls\sup\smdmon_config.csv.

This guide covers processing system monitor logs gathered at the default low level. If a higher logging level is used, additional regular expressions need to be defined in the configuration to cater to more event types.

Example 2. Processing system monitor log

The following input samples are taken from smdmon.log. This log can contain two types of events. Below is an example of each event type and the regular expressions used to parse them.

Event type 1
10/05/2021 08:18:25:398 >> (smdm_run_prg.c:214)  Running program: dursim  -c 0 umhlog -1 20 l1 l4
10/05/2021 08:18:25:398 >> (smdm_upd_srv.c:165)  Server running on address 192.168.10.127

The first type of event is a single-line event that contains information about the processes performed by the system monitor and includes the following fields:

  • EventTime

  • Process

  • Message

Defining the SMDMON_TYPE1_REGEX regular expression
define SMDMON_TYPE1_REGEX   /(?x)^(\d+.\d+.\d+.\d+.\d+.\d+).\d+\s*>>\s*\(\
                            (?<Process>.*?)\)\s*(?<Message>.*)/
Event type 2
id = 5
    level      = LOW
    tool       = BUS
    program    = smdsnp
    options    = -g
    params     =
    comment    = General
    file_label = general
    timeout    = 10 seconds
    start_time = #
    stop_time  = #
    next_time  = Mon May 10 03:36:27 2021
    interval   = 600 minutes
    log_size   = 2 Mbytes
    cur_log_nm = C:\Users\Public\Yokogawa\tls\log/smd_UNLICENCED_LOW_smdsnp_general.log
    old_log_nm = C:\Users\Public\Yokogawa\tls\log/smd_UNLICENCED_LOW_smdsnp_general.old

The second type of event displays information about each command defined in the configuration file smdmon_config.csv. The event contains the following fields:

  • ID

  • Level

  • Tool

  • Program

  • Options

  • Parameters

  • Comment

  • FileLabel

  • Timeout

  • StartTime

  • StopTime

  • NextTime

  • Interval

  • LogSize

  • CurrentLogName

  • OldLogName

Defining the SMDMON_TYPE2_REGEX regular expression
define SMDMON_TYPE2_REGEX   /(?x)^(?:id\s*\=\s(?<ID>\d+))\s+\
                            (?:level\s*\=\s(?<Level>.*))\s+\
                            (?:tool\s*\=\s(?<Tool>.*))\s+\
                            (?:program\s*\=\s(?<Program>.*))\s+\
                            (?:options\s*\=\s(?<Options>.*))\s+\
                            (?:params\s*\=\s(?<Parameters>.*))\s+\
                            (?:comment\s*\=\s(?<Comment>.*))\s+\
                            (?:file_label\s*\=\s(?<FileLabel>.*))\s+\
                            (?:timeout\s*\=\s(?<Timeout>.*))\s+\
                            (?:start_time\s*\=\s(?<StartTime>.*))\s+\
                            (?:stop_time\s*\=\s(?<StopTime>.*))\s+\
                            (?:next_time\s*\=\s(?<NextTime>.*))\s+\
                            (?:interval\s*\=\s(?<Interval>.*))\s+\
                            (?:log_size\s*\=\s(?<LogSize>.*))\s+\
                            (?:cur_log_nm\s*\=\s(?<CurrentLogName>.*))\s+\
                            (?:old_log_nm\s*\=\s(?<OldLogName>.*))/

The regular expressions above are defined in the configuration as constants.

Since the log file contains both single-line and multi-line events with an entirely different event structure, separate instances of the im_file input module are defined.

The xm_multiline extension module is used to process multi-line events as a single record. The HeaderLine directive of this module specifies a regular expression that determines the beginning of the multi-line event.

The Exec block of each input module instance is used to match the log line ($raw_event) against the appropriate regular expression. Once a match occurs, the respective fields are created according to the named capturing groups.

Since captured group $1 of event type 1 contains a timestamp in a custom date/time format, it is converted to datetime using the strptime() function and then assigned to the $EventTime field.

Finally, the fields are converted to JSON using the to_json() procedure of the xm_json module. If the log line does not match the regular expression, it is discarded using the drop() procedure.

The following NXLog configuration combines all the steps described above.

nxlog.conf
# Regular expressions defined as a constants to read the content of the logs
define SMDMON_TYPE1_REGEX   /(?x)^(\d+.\d+.\d+.\d+.\d+.\d+).\d+\s*>>\s*\(\
                            (?<Process>.*?)\)\s*(?<Message>.*)/

define SMDMON_TYPE2_REGEX   /(?x)^(?:id\s*\=\s(?<ID>\d+))\s+\
                            (?:level\s*\=\s(?<Level>.*))\s+\
                            (?:tool\s*\=\s(?<Tool>.*))\s+\
                            (?:program\s*\=\s(?<Program>.*))\s+\
                            (?:options\s*\=\s(?<Options>.*))\s+\
                            (?:params\s*\=\s(?<Parameters>.*))\s+\
                            (?:comment\s*\=\s(?<Comment>.*))\s+\
                            (?:file_label\s*\=\s(?<FileLabel>.*))\s+\
                            (?:timeout\s*\=\s(?<Timeout>.*))\s+\
                            (?:start_time\s*\=\s(?<StartTime>.*))\s+\
                            (?:stop_time\s*\=\s(?<StopTime>.*))\s+\
                            (?:next_time\s*\=\s(?<NextTime>.*))\s+\
                            (?:interval\s*\=\s(?<Interval>.*))\s+\
                            (?:log_size\s*\=\s(?<LogSize>.*))\s+\
                            (?:cur_log_nm\s*\=\s(?<CurrentLogName>.*))\s+\
                            (?:old_log_nm\s*\=\s(?<OldLogName>.*))/

# Part of the log path defined as a constant
define LOG_PATH             C:\Users\Public\Yokogawa\tls\log

<Extension json>
    Module       xm_json
</Extension>

<Extension multiline_smdmon>
    Module       xm_multiline
    # Regular expression to look for the header of the message
    HeaderLine   /id\s*\=\s*\d+/
</Extension>

<Input from_file_type1>
    Module       im_file
    File         '%LOG_PATH%\smdmon.log'
    <Exec>
        # Matches the events with a regular expression
        if $raw_event =~ %SMDMON_TYPE1_REGEX%
        {
            # Creates the timestamp
            $EventTime = strptime($1, '%d/%m/%Y %T');
            # Formats the result as JSON
            to_json();
        }
        # Discarding message if it does not match the expression
        else drop();

        # Replaces unwanted whitespace characters
        $raw_event =~ s/\s{2,}/ /g;
    </Exec>
</Input>

<Input from_file_type2>
    Module       im_file
    File         '%LOG_PATH%\smdmon.log'
    InputType    multiline_smdmon
    <Exec>
        # Matches the events with a regular expression
        if $raw_event =~ %SMDMON_TYPE2_REGEX%
        {
            # Formats the result as JSON
            to_json();
        }
        # Discarding message if it does not match the expression
        else drop();

        # Replaces unwanted whitespace characters
        $raw_event =~ s/\s{2,}/ /g;
    </Exec>
</Input>

The following output samples depict the processed events in JSON format.

Output sample of event type 1
{
  "EventReceivedTime": "2021-05-10T08:18:26.351847-07:00",
  "SourceModuleName": "from_file_type1",
  "SourceModuleType": "im_file",
  "Message": "Running program: dursim -c 0 umhlog -1 20 l1 l4 ",
  "Process": "smdm_run_prg.c:214",
  "EventTime": "2021-05-10T08:18:25.000000-07:00"
}
Output sample of event type 2
{
  "EventReceivedTime": "2021-05-10T08:18:26.336248-07:00",
  "SourceModuleName": "from_file_type2",
  "SourceModuleType": "im_file",
  "Comment": "General",
  "CurrentLogName": "C:\\Users\\Public\\Yokogawa\\tls\\log/smd_UNLICENCED_LOW_smdsnp_general.log",
  "FileLabel": "general",
  "ID": "5",
  "Level": "LOW",
  "LogSize": "2 Mbytes",
  "NextTime": "Mon May 10 08:28:25 2021",
  "OldLogName": "C:\\Users\\Public\\Yokogawa\\tls\\log/smd_UNLICENCED_LOW_smdsnp_general.old",
  "Options": "-g",
  "Parameters": "",
  "Program": "smdsnp",
  "StartTime": "#",
  "StopTime": "#",
  "Timeout": "10 seconds",
  "Tool": "BUS",
  "Interval": "600 minutes"
}

Alarm kernel debugger log

The alarm kernel debugger can help resolve problems that appear at runtime. It is also suitable to gather alarm kernel statistics. The alarm kernel debugger is called almdbg.

Example 3. Processing alarm kernel debugger log

According to the default configuration in smdmon_config.csv, the alarm kernel debugger receives the following commands:

  • Get destination (option "1") - gives an overview of the destination(s) which are currently connected to the alarm kernel.

  • Get statistics (option "12") - can be used to get alarm kernel statistics.

Alarm kernel debugger events have a complex structure and can’t be processed by NXLog as a single event. However, the event can be split into three parts: the request, alarm kernel statistics, and destination information. The following is an example of each section and the regular expressions used to parse them.

Request part
##[33][almdbg  < 12, 1, -1, ][All][12/05/2021 05:08:33:965]

The request part of the event contains the following fields:

  • ID

  • Process

  • Commands

  • Comment

  • EventTime

Defining the SMD_ALMDBG_REQ_REGEX regular expression
define SMD_ALMDBG_REQ_REGEX     /(?x)^\#\#\[(?<ID>\d+)\]\
                                \[(?<Process>\w+)[\s\<\>]*(?<Commands>.*?)\]\
                                \[(?<Comment>.*?)\]\[(\d+.\d+.\d+.\d+.\d+.\d+)\
                                .\d+\]/
Alarm kernel statistics part
---- Get statistics ----



Alarmkernel statistics
----------------------

Startup time (Local civil time)                : Wed May 12 04:57:38 2021
Total number of item-based events received     :         17
Total number of non-item-based events received :          0
Total number of events send to destinations    :         74
Number of eac timeout list entry's             :          0
Number of free lst_itm list entry's            :          0
Number of free repeat delay list entry's       :          0
Number of free change prio list entry's        :          0
Number of free alarm event list entry's        :          0
Number of act type list entry's                :          3
Number of  destination list entry's            :          3

Give action to do [-1 - 26] [12]

The alarm kernel statistics part of the event contains the following fields:

  • Request

  • Response

  • StartupTime

  • TotNumOfItemBasedEventsRcvd

  • TotNumOfNonItemBasedEventsRcvd

  • TotNumOfEventsSendToDestinations

  • NumOfEacTimeoutListEntries

  • NumOfFreeLstItmListEntries

  • NumOfFreeRepeatDelayEntries

  • NumOfFreeChangePrioListEntries

  • NumOfFreeAlarmEventListEntries

  • NumOfActTypeListEntries

  • NumOfDestinationListEntries

Defining the SMD_ALMDBG_TYPE1_REGEX regular expression
define SMD_ALMDBG_TYPE1_REGEX   /(?x)^\-+\s*(?<Request>.*?)\s*\-+\s*\
                                (?<Response>.*)\s*\-*\s*\
                                (?:Startup\s*time\s*\(Local\s*civil\s*time\)\
                                [\s\:]*\
                                (?<StartupTime>.*))\s*\
                                (?:Total\s*number\s*of\s*item\-based\s*events\
                                \s*received[\s\:]*\
                                (?<TotNumOfItemBasedEventsRcvd>.*))\s*\
                                (?:Total\s*number\s*of\s*non\-item\-based\s*\
                                events\s*received[\s\:]*\
                                (?<TotNumOfNonItemBasedEventsRcvd>.*))\s*\
                                (?:Total\s*number\s*of\s*events\s*send\s*to\s*\
                                destinations[\s\:]*\
                                (?<TotNumOfEventsSendToDestinations>.*))\s*\
                                (?:Number\s*of\s*eac\s*timeout\s*list\s*\
                                entry.s[\s\:]*\
                                (?<NumOfEacTimeoutListEntries>.*))\s*\
                                (?:Number\s*of\s*free\s*lst_itm\s*list\s*\
                                entry.s[\s\:]*\
                                (?<NumOfFreeLstItmListEntries>.*))\s*\
                                (?:Number\s*of\s*free\s*repeat\s*delay\s*\
                                list\s*entry.s[\s\:]*\
                                (?<NumOfFreeRepeatDelayEntries>.*))\s*\
                                (?:Number\s*of\s*free\s*change\s*prio\s*\
                                list\s*entry.s[\s\:]*\
                                (?<NumOfFreeChangePrioListEntries>.*))\s*\
                                (?:Number\s*of\s*free\s*alarm\s*event\s*\
                                list\s*entry.s[\s\:]*\
                                (?<NumOfFreeAlarmEventListEntries>.*))\s*\
                                (?:Number\s*of\s*act\s*type\s*list\s*\
                                entry.s[\s:]*\
                                (?<NumOfActTypeListEntries>.*))\s*\
                                (?:Number\s*of\s*destination\s*list\s*\
                                entry.s[\s\:]*\
                                (?<NumOfDestinationListEntries>.*))/
Destinations part
---- Get destinations ----



Node  Name          Base-msg-id  Events-send-to  Cur. ovf.  Tot. ovf.
---------------------------------------------------------------------
1     ALH           3            20              0          0
1     ALNMGR        100          17              0          0
1     ALDPRT        1            20              0          0

Give action to do [-1 - 26] [1]

This part displays the list of destinations connected to the alarm kernel. Since the event is a table with a variable number of rows, the best way to process it is to read each row as a single-line event.

The following fields can be parsed:

  • Node

  • DestinationName

  • BaseMsgID

  • EventsSendTo

  • CurNumOfOverflows

  • TotNumOfOverflows

Defining the SMD_ALMDBG_TYPE2_REGEX regular expression
define SMD_ALMDBG_TYPE2_REGEX   /(?x)^(?<Node>\d+)\s*\
                                (?<DestinationName>[A-Z]+)\s*\
                                (?<BaseMsgID>\d+)\s*\
                                (?<EventsSendTo>\d+)\s*\
                                (?<CurNumOfOverflows>\d+)\s*\
                                (?<TotNumOfOverflows>\d+)\s*/

The regular expressions above are defined in the configuration as constants.

Since the log file contains both single-line and multi-line events, separate instances of the im_file input module are defined.

The xm_multiline extension module is used to process multi-line events as a single record. The HeaderLine directive of this module specifies a regular expression that determines the beginning of the multi-line event.

The Exec block of each input module instance matches the log line ($raw_event) against the appropriate regular expression. Once a match occurs, the respective fields are created according to the named capturing groups.

Since captured group $5 of the request event contains a timestamp in a custom date/time format, it is converted to datetime using the strptime() function and then assigned to the $EventTime field.

Finally, the fields are converted to JSON using the to_json() procedure of the xm_json module. If the log line does not match any of the defined regular expressions, it is discarded using the drop() procedure.

The following NXLog configuration combines all the steps described above.

nxlog.conf
# A regular expression defined as a constant to read the content of the logs
define SMD_ALMDBG_REQ_REGEX     /(?x)^\#\#\[(?<ID>\d+)\]\
                                \[(?<Process>\w+)[\s\<\>]*(?<Commands>.*?)\]\
                                \[(?<Comment>.*?)\]\[(\d+.\d+.\d+.\d+.\d+.\d+)\
                                .\d+\]/

define SMD_ALMDBG_TYPE1_REGEX   /(?x)^\-+\s*(?<Request>.*?)\s*\-+\s*\
                                (?<Response>.*)\s*\-*\s*\
                                (?:Startup\s*time\s*\(Local\s*civil\s*time\)\
                                [\s\:]*\
                                (?<StartupTime>.*))\s*\
                                (?:Total\s*number\s*of\s*item\-based\s*events\
                                \s*received[\s\:]*\
                                (?<TotNumOfItemBasedEventsRcvd>.*))\s*\
                                (?:Total\s*number\s*of\s*non\-item\-based\s*\
                                events\s*received[\s\:]*\
                                (?<TotNumOfNonItemBasedEventsRcvd>.*))\s*\
                                (?:Total\s*number\s*of\s*events\s*send\s*to\s*\
                                destinations[\s\:]*\
                                (?<TotNumOfEventsSendToDestinations>.*))\s*\
                                (?:Number\s*of\s*eac\s*timeout\s*list\s*\
                                entry.s[\s\:]*\
                                (?<NumOfEacTimeoutListEntries>.*))\s*\
                                (?:Number\s*of\s*free\s*lst_itm\s*list\s*\
                                entry.s[\s\:]*\
                                (?<NumOfFreeLstItmListEntries>.*))\s*\
                                (?:Number\s*of\s*free\s*repeat\s*delay\s*\
                                list\s*entry.s[\s\:]*\
                                (?<NumOfFreeRepeatDelayEntries>.*))\s*\
                                (?:Number\s*of\s*free\s*change\s*prio\s*\
                                list\s*entry.s[\s\:]*\
                                (?<NumOfFreeChangePrioListEntries>.*))\s*\
                                (?:Number\s*of\s*free\s*alarm\s*event\s*\
                                list\s*entry.s[\s\:]*\
                                (?<NumOfFreeAlarmEventListEntries>.*))\s*\
                                (?:Number\s*of\s*act\s*type\s*list\s*\
                                entry.s[\s:]*\
                                (?<NumOfActTypeListEntries>.*))\s*\
                                (?:Number\s*of\s*destination\s*list\s*\
                                entry.s[\s\:]*\
                                (?<NumOfDestinationListEntries>.*))/

define SMD_ALMDBG_TYPE2_REGEX   /(?x)^(?<Node>\d+)\s*\
                                (?<DestinationName>[A-Z]+)\s*\
                                (?<BaseMsgID>\d+)\s*\
                                (?<EventsSendTo>\d+)\s*\
                                (?<CurNumOfOverflows>\d+)\s*\
                                (?<TotNumOfOverflows>\d+)\s*/

# Part of the log path defined as a constant
define LOG_PATH                 C:\Users\Public\Yokogawa\tls\log

<Extension json>
    Module        xm_json
</Extension>

<Extension multiline_smd_almdbg>
    Module        xm_multiline
    # Regular expression to look for the header of the message
    HeaderLine    /\-*\s*Get\s*statistics\s*\-*/
</Extension>

<Input from_file_multi>
    Module        im_file
    File          '%LOG_PATH%\smd_*_almdbg_all.log'
    InputType     multiline_smd_almdbg
    <Exec>
        # Matches the events with a regular expression
        if $raw_event =~ %SMD_ALMDBG_TYPE1_REGEX%
        {
            # Formats the result as JSON
            to_json();
        }
        # Discard event if it doesn't match a/the regular expression
        else drop();
    </Exec>
</Input>

<Input from_file_single>
    Module        im_file
    File          '%LOG_PATH%\smd_*_almdbg_all.log'
    <Exec>
        # Matches the events with a regular expression
        if $raw_event =~ %SMD_ALMDBG_REQ_REGEX%
        {
            # Creates the timestamp
            $EventTime = strptime($5, '%d/%m/%Y %T');
        }
        else if $raw_event =~ %SMD_ALMDBG_TYPE2_REGEX%
        {
            # No further parsing required
        }
        # Discard event if it doesn't match a/the regular expression
        else drop();

        # Formats the result as JSON
        to_json();
    </Exec>
</Input>

The following output samples depict the processed events in JSON format.

Output sample of the request part
{
  "EventReceivedTime": "2021-05-12T05:08:34.121775-07:00",
  "SourceModuleName": "from_file_single",
  "SourceModuleType": "im_file",
  "Commands": "12, 1, -1, ",
  "Comment": "All",
  "ID": "33",
  "Process": "almdbg",
  "EventTime": "2021-05-12T05:08:33.000000-07:00"
}
Output sample of the alarm kernel statistics part
{
  "EventReceivedTime": "2021-05-12T05:08:35.106279-07:00",
  "SourceModuleName": "from_file_multi",
  "SourceModuleType": "im_file",
  "NumOfActTypeListEntries": "3",
  "NumOfDestinationListEntries": "3",
  "NumOfEacTimeoutListEntries": "0",
  "NumOfFreeAlarmEventListEntries": "0",
  "NumOfFreeChangePrioListEntries": "0",
  "NumOfFreeLstItmListEntries": "0",
  "NumOfFreeRepeatDelayEntries": "0",
  "Request": "Get statistics",
  "Response": "Alarmkernel statistics",
  "StartupTime": "Wed May 12 04:57:38 2021",
  "TotNumOfEventsSendToDestinations": "74",
  "TotNumOfItemBasedEventsRcvd": "17",
  "TotNumOfNonItemBasedEventsRcvd": "0"
}
Output sample of the destinations part
{
  "EventReceivedTime": "2021-05-12T05:08:34.121775-07:00",
  "SourceModuleName": "from_file_single",
  "SourceModuleType": "im_file",
  "BaseMsgID": "3",
  "CurNumOfOverflows": "0",
  "DestinationName": "ALH",
  "EventsSendTo": "20",
  "Node": "1",
  "TotNumOfOverflows": "0"
}

Data Set Services debugger log

Data Set Services (DSS) is a DATABASE/FAST tool module whose primary function is to provide a general and universal interface to FAST/TOOLS data. The interface offered by DSS to the FAST/TOOLS data is always the same, no matter how the data is stored.

The DSS debugger is DSSXBD and it allows reading some data present in the DSS shared memory and reading the content of the FAST/TOOLS data dictionary on the node where the debugger is started.

The information provided by the DSSXDB utility functions requires an understanding of DSS implementation. However, two main functions can be interesting for observation:

  • Data dictionary-related actions - provide various sub-functions to inspect the contents of the data dictionary.

  • Beautify DSS dictionary source - provides the possibility to output the contents of a DSS file in a human-readable format.

Example 4. Processing Data Set Services debugger log

Like most system monitor and diagnostic log events, DSS debugger events consist of the request part and one or more response sections. The following is an example of the two sections and the regular expressions used to parse them.

Request part
##[59][dssxdb  < 1, 3, -1, -1, ][All][13/05/2021 03:42:48:193]

This part of the event contains the following fields:

  • ID

  • Process

  • Commands

  • Comment

  • EventTime

As shown in the request part of the event, the default configuration of the DSS debugger utility in smdmon_config.csv contains the following list of commands:

  • 1 - DSS-API related actions

    • 3 - List connected DSS clients

    • -1 - Exit

  • -1 - Exit

Defining the SMD_DSSXDB_REQ_REGEX regular expression
define SMD_DSSXDB_REQ_REGEX     /(?x)^\#\#\[(?<ID>\d+)\]\
                                \[(?<Process>\w+)[\s\<\>]*(?<Commands>.*?)\]\
                                \[(?<Comment>.*?)\]\[(\d+.\d+.\d+.\d+.\d+.\d+).\
                                \d+\]/
Response part
---- List connected DSS clients ----

Conn. hnd. : 0x1000008
DUR address: 1    WFLGDI       -1
Flags      :
NONE

...

Give action to do [-1 - 9] [3]

The response part of the event consists of the following fields:

  • ConnHnd

  • DURAddress

  • Flags

Defining the SMD_DSSXDB_TYPE1_REGEX regular expression
define SMD_DSSXDB_TYPE1_REGEX   /(?x)^(?:Conn\.\s*hnd\.[\s\:]*(?<ConnHnd>.*))\
                                \s*\
                                (?:DUR\s*address[\s\:]*(?<DURAddress>.*))\s*\
                                (?:Flags[\s\:]*(?<Flags>.*?))\s*\w*/

The regular expressions above are defined in the configuration as constants.

Since the log file contains both single-line and multi-line events, separate instances of the im_file input module are defined.

The xm_multiline extension module is used to processmulti-line events as a single record. The HeaderLine directive of this module specifies a regular expression that determines the beginning of the multi-line event.

The Exec block of each input module instance matches the log line ($raw_event) against the appropriate regular expression. Once a match occurs, the respective fields are created according to the named capturing groups.

Since captured group $5 of the request part contains a timestamp in a custom date/time format, it is converted to datetime using the strptime() function and then assigned to the $EventTime field.

Finally, the fields are converted to JSON using the to_json() procedure of the xm_json module. If the log line does not match any of the defined regular expressions, it is discarded using the drop() procedure.

The following NXLog configuration combines all the steps described above.

nxlog.conf
# A regular expression defined as a constant to read the content of the logs
define SMD_DSSXDB_REQ_REGEX     /(?x)^\#\#\[(?<ID>\d+)\]\
                                \[(?<Process>\w+)[\s\<\>]*(?<Commands>.*?)\]\
                                \[(?<Comment>.*?)\]\[(\d+.\d+.\d+.\d+.\d+.\d+).\
                                \d+\]/

define SMD_DSSXDB_TYPE1_REGEX   /(?x)^(?:Conn\.\s*hnd\.[\s\:]*(?<ConnHnd>.*))\
                                \s*\
                                (?:DUR\s*address[\s\:]*(?<DURAddress>.*))\s*\
                                (?:Flags[\s\:]*(?<Flags>.*?))\s*\w*/

# Part of the log path defined as a constant
define LOG_PATH                 C:\Users\Public\Yokogawa\tls\log

<Extension json>
    Module        xm_json
</Extension>

<Extension multiline_smd_dssxdb>
    Module        xm_multiline
    # Regular expression to look for the header of the message
    HeaderLine    /Conn\.\s*hnd\.[\s\:]*/
</Extension>

<Input from_file_multi>
    Module        im_file
    File          '%LOG_PATH%\smd_*_dssxdb_all.log'
    InputType     multiline_smd_dssxdb
    <Exec>
        # Matches the events with a regular expression
        if $raw_event =~ %SMD_DSSXDB_TYPE1_REGEX%
        {
            # Formats the result as JSON
            to_json();
        }
        # Discard event if it doesn't match a/the regular expression
        else drop();

        # Replaces unwanted spaces
        $raw_event =~ s/\s{2,}/ /g;
    </Exec>
</Input>

<Input from_file_single>
    Module        im_file
    File          '%LOG_PATH%\smd_*_dssxdb_all.log'
    <Exec>
        # Matches the events with a regular expression
        if $raw_event =~ %SMD_DSSXDB_REQ_REGEX%
        {
            # Creates the timestamp
            $EventTime = strptime($5, '%d/%m/%Y %T');
            # Formats the result as JSON
            to_json();
        }
        # Discard event if it doesn't match a/the regular expression
        else drop();
    </Exec>
</Input>

The following output samples depict the processed events in JSON format.

Output sample of the request part
{
  "EventReceivedTime": "2021-05-13T03:42:50.007061-07:00",
  "SourceModuleName": "from_file_single",
  "SourceModuleType": "im_file",
  "Commands": "1, 3, -1, -1, ",
  "Comment": "All",
  "ID": "59",
  "Process": "dssxdb",
  "EventTime": "2021-05-13T03:42:48.000000-07:00"
}
Output sample of the response part
{
  "EventReceivedTime": "2021-05-13T03:42:50.007061-07:00",
  "SourceModuleName": "from_file_multi",
  "SourceModuleType": "im_file",
  "ConnHnd": "0x1000008",
  "DURAddress": "1 WFLGDI -1 ",
  "Flags": ""
}

DUR debugger log

The DUR debugger is only used for low-level debugging of DUR and requires a lot of inside information.

Example 5. Processing DUR debugger log

DUR debugger events can be split into two parts, the request, and general info. The following is an example of each section and the regular expressions used to parse them.

Request part
##[30][durdbg  < 1, -1, ][All][19/05/2021 01:37:47:757]

The following fields can be parsed from the request:

  • ID

  • Process

  • Commands

  • Comment

  • EventTime

Defining the SMD_DURDBG_REQ_REGEX regular expression
define SMD_DURDBG_REQ_REGEX /(?x)^\#\#\[(?<ID>\d+)\]\[\
                            (?<Process>.*?)\s*\<\s*\
                            (?<Commands>.*?)\s*\]\[\
                            (?<Comment>.*?)\]\[\
                            (\d+.\d+.\d+.\d+.\d+.\d+).\d+\]/
General info part
Give type of structure (0 = help) :
node_name     = UNLICENCED
emt_page_head = 5001d000
free_pages    =     1219      minimum_pages =     1206
rhb_head      = 50015d6c      emt_head      = 50000770
icb_head      = 00000000      ncb_head      = 00000000
lcb_head      = 00000000      clq_head      = 500006c4
ncr_head      = 500135a4      total_msg     =    14970
node          =        1      overflow_msg  =        0
system_type   =        5      prt_overflow  =        0
emp_wmb       = 50015f2c      act_time_stamp= 1621413467
lnb_tab       = 00000000      locking info:
  lock_id pid      lock_flag collisions lock_sem_id
  DUR     0        0         525        5769340
  ISM     0        0         5          5769340
  ITM     0        0         4          5769340
wake_sem_id   =  5767340
dur_common    = 50000000      attach_count  = 1621413471
wake_sem_used = 1111-1101-1111-1111-1111-1111-1111-1111
                1111-1111-1111-1111-1111-1111-1000-0000
                0000-0000-0000-0000-0000-0000-0000-0000
                0000-0000-0000-0000-0000-0000-0000-0000
                0000-0000-0000-0000-0000-0000-0000-0000
                0000-0000-0000-0000-0000-0000-0000-0000
                0000-0000-0000-0000-0000-0000-0000-0000
                0000-0000-0000-0000-0000-0000-00

The following fields can be parsed from the general info:

  • NodeName

  • EmtPageHead

  • FreePages

  • MinimumPages

  • RhbHead

  • EmtHead

  • IcbHead

  • NcbHead

  • LcbHead

  • ClqHead

  • NcrHead

  • TotalMsg

  • Node

  • OverflowMsg

  • SystemType

  • PrtOverflow

  • EmpWmb

  • ActTimeStamp

  • LnbTab

  • LockingInfo

  • WakeSemId

  • DurCommon

  • AttachCount

  • WakeSemUsed

Defining the SMD_DURDBG_RSP_REGEX regular expression
define SMD_DURDBG_RSP_REGEX /(?x)^Give\s*type\s*of\s*structure.*\:\s*\
                            (?:node_name[\s\=]*(?<NodeName>.*?))\s*\
                            (?:emt_page_head[\s\=]*(?<EmtPageHead>.*?))\s*\
                            (?:free_pages[\s\=]*(?<FreePages>.*?))\s*\
                            (?:minimum_pages[\s\=]*(?<MinimumPages>.*?))\s*\
                            (?:rhb_head[\s\=]*(?<RhbHead>.*?))\s*\
                            (?:emt_head[\s\=]*(?<EmtHead>.*?))\s*\
                            (?:icb_head[\s\=]*(?<IcbHead>.*?))\s*\
                            (?:ncb_head[\s\=]*(?<NcbHead>.*?))\s*\
                            (?:lcb_head[\s\=]*(?<LcbHead>.*?))\s*\
                            (?:clq_head[\s\=]*(?<ClqHead>.*?))\s*\
                            (?:ncr_head[\s\=]*(?<NcrHead>.*?))\s*\
                            (?:total_msg[\s\=]*(?<TotalMsg>.*?))\s*\
                            (?:node[\s\=]*(?<Node>.*?))\s*\
                            (?:overflow_msg[\s\=]*(?<OverflowMsg>.*?))\s*\
                            (?:system_type[\s\=]*(?<SystemType>.*?))\s*\
                            (?:prt_overflow[\s\=]*(?<PrtOverflow>.*?))\s*\
                            (?:emp_wmb[\s\=]*(?<EmpWmb>.*?))\s*\
                            (?:act_time_stamp[\s\=]*(?<ActTimeStamp>.*?))\s*\
                            (?:lnb_tab[\s\=]*(?<LnbTab>.*?))\s*\
                            (?:locking\s*info\:.*)\s*\
                            (?:wake_sem_id[\s\=]*(?<WakeSemId>.*?))\s*\
                            (?:dur_common[\s\=]*(?<DurCommon>.*?))\s*\
                            (?:attach_count[\s\=]*(?<AttachCount>.*?))\s*\
                            (?:wake_sem_used[\s\=]*(?<WakeSemUsed>[\d\s\-]*))\
                            \s+Give\s*type\s*of\s*structure.*\:/

The general info part includes the locking info field containing information in a table form. It is difficult to parse the complete part. Therefore, the locking info field is parsed separately.

Locking info part
  DUR     0        0         525        5769340
  ISM     0        0         5          5769340
  ITM     0        0         4          5769340

The following fields can be parsed from the locking info:

  • LockID

  • PID

  • LockFlag

  • Collisions

  • LockSemID

Defining the SMD_DURDBG_LOC_REGEX regular expression
define SMD_DURDBG_LOC_REGEX /(?x)^\s*(?<LockID>[A-Z]+.*?)\s+\
                            (?<PID>\d+)\s+\
                            (?<LockFlag>\d+)\s+\
                            (?<Collisions>\d+)\s+\
                            (?<LockSemID>\d+)/

The regular expressions above are defined in the configuration as constants.

Since the log file contains both single-line and multi-line events, separate instances of the im_file input module are defined.

The xm_multiline extension module is used to process multi-line events as a single record. The HeaderLine and EndLine directives of this module specify a regular expression to detect the beginning and end of each multi-line event respectively.

The Exec block of each input module instance matches the log line ($raw_event) against the appropriate regular expression. Once a match occurs, the respective fields are created according to the named capturing groups.

Captured group $5 of the request part contains a timestamp in a custom date/time format, therefore it is converted to datetime using the strptime() function and then assigned to the $EventTime field.

Finally, the fields are converted to JSON using the to_json() procedure of the xm_json module. If the log line does not match any of the defined regular expressions, it is discarded using the drop() procedure.

The following NXLog configuration combines all the steps described above.

nxlog.conf
# A regular expression defined as a constant to read the content of the logs
define SMD_DURDBG_REQ_REGEX /(?x)^\#\#\[(?<ID>\d+)\]\[\
                            (?<Process>.*?)\s*\<\s*\
                            (?<Commands>.*?)\s*\]\[\
                            (?<Comment>.*?)\]\[\
                            (\d+.\d+.\d+.\d+.\d+.\d+).\d+\]/

define SMD_DURDBG_RSP_REGEX /(?x)^Give\s*type\s*of\s*structure.*\:\s*\
                            (?:node_name[\s\=]*(?<NodeName>.*?))\s*\
                            (?:emt_page_head[\s\=]*(?<EmtPageHead>.*?))\s*\
                            (?:free_pages[\s\=]*(?<FreePages>.*?))\s*\
                            (?:minimum_pages[\s\=]*(?<MinimumPages>.*?))\s*\
                            (?:rhb_head[\s\=]*(?<RhbHead>.*?))\s*\
                            (?:emt_head[\s\=]*(?<EmtHead>.*?))\s*\
                            (?:icb_head[\s\=]*(?<IcbHead>.*?))\s*\
                            (?:ncb_head[\s\=]*(?<NcbHead>.*?))\s*\
                            (?:lcb_head[\s\=]*(?<LcbHead>.*?))\s*\
                            (?:clq_head[\s\=]*(?<ClqHead>.*?))\s*\
                            (?:ncr_head[\s\=]*(?<NcrHead>.*?))\s*\
                            (?:total_msg[\s\=]*(?<TotalMsg>.*?))\s*\
                            (?:node[\s\=]*(?<Node>.*?))\s*\
                            (?:overflow_msg[\s\=]*(?<OverflowMsg>.*?))\s*\
                            (?:system_type[\s\=]*(?<SystemType>.*?))\s*\
                            (?:prt_overflow[\s\=]*(?<PrtOverflow>.*?))\s*\
                            (?:emp_wmb[\s\=]*(?<EmpWmb>.*?))\s*\
                            (?:act_time_stamp[\s\=]*(?<ActTimeStamp>.*?))\s*\
                            (?:lnb_tab[\s\=]*(?<LnbTab>.*?))\s*\
                            (?:locking\s*info\:.*)\s*\
                            (?:wake_sem_id[\s\=]*(?<WakeSemId>.*?))\s*\
                            (?:dur_common[\s\=]*(?<DurCommon>.*?))\s*\
                            (?:attach_count[\s\=]*(?<AttachCount>.*?))\s*\
                            (?:wake_sem_used[\s\=]*(?<WakeSemUsed>[\d\s\-]*))\
                            \s+Give\s*type\s*of\s*structure.*\:/

define SMD_DURDBG_LOC_REGEX /(?x)^\s*(?<LockID>[A-Z]+.*?)\s+\
                            (?<PID>\d+)\s+\
                            (?<LockFlag>\d+)\s+\
                            (?<Collisions>\d+)\s+\
                            (?<LockSemID>\d+)/

# Part of the log path defined as a constant
define LOG_PATH             C:\Users\Public\Yokogawa\tls\log

<Extension json>
    Module        xm_json
</Extension>

<Extension multiline_smd_durdbg>
    Module      xm_multiline
    # Regular expression to look for the header of the message
    HeaderLine    /^Give\s*type\s*of\s*structure/
    EndLine       /^Give\s*type\s*of\s*structure.*\:\s/
</Extension>

<Input from_file_single>
    Module        im_file
    File          '%LOG_PATH%\smd_*_durdbg_all.log'

    <Exec>
        # Matches the events with a regular expression
        if $raw_event =~ %SMD_DURDBG_REQ_REGEX%
        {
            # Creates the timestamp
            $EventTime = strptime($5, '%d/%m/%Y %T');
        }
        else if $raw_event =~ %SMD_DURDBG_LOC_REGEX%
        {
            # No further parsing required
        }
        # Discard event if it doesn't match a/the regular expression
        else drop();

        # Formats the result as JSON
        to_json();
    </Exec>
</Input>

<Input from_file_multi>
    Module        im_file
    File          '%LOG_PATH%\smd_*_durdbg_all.log'
    InputType     multiline_smd_durdbg

    <Exec>
        # Replaces unwanted characters
        $raw_event =~ s/\\n/ /g;
        $raw_event =~ s/\\r/ /g;
        $raw_event =~ s/\s{2,}/ /g;
    </Exec>

    <Exec>
        # Matches the events with a regular expression
        if $raw_event =~ %SMD_DURDBG_RSP_REGEX%
        {
            # Formats the result as JSON
            to_json();
        }
        # Discard event if it doesn't match a/the regular expression
        else drop();
    </Exec>
</Input>

The following output samples depict the processed events in JSON format.

Output sample of the request part
{
  "EventReceivedTime": "2021-05-19T01:37:48.477750-07:00",
  "SourceModuleName": "from_file_single",
  "SourceModuleType": "im_file",
  "Commands": "1, -1,",
  "Comment": "All",
  "ID": "30",
  "Process": "durdbg",
  "EventTime": "2021-05-19T01:37:47.000000-07:00"
}
Output sample of the general section
{
  "EventReceivedTime": "2021-05-19T01:37:48.477750-07:00",
  "SourceModuleName": "from_file_multi",
  "SourceModuleType": "im_file",
  "ActTimeStamp": "1621413467",
  "AttachCount": "1621413471",
  "ClqHead": "500006c4",
  "DurCommon": "50000000",
  "EmpWmb": "50015f2c",
  "EmtHead": "50000770",
  "EmtPageHead": "5001d000",
  "FreePages": "1219",
  "IcbHead": "00000000",
  "LcbHead": "00000000",
  "LnbTab": "00000000",
  "MinimumPages": "1206",
  "NcbHead": "00000000",
  "NcrHead": "500135a4",
  "Node": "1",
  "NodeName": "UNLICENCED",
  "OverflowMsg": "0",
  "PrtOverflow": "0",
  "RhbHead": "50015d6c",
  "SystemType": "5",
  "TotalMsg": "14970",
  "WakeSemId": "5767340",
  "WakeSemUsed": "1111-1101-1111-1111-1111-1111-1111-1111 1111-1111-1111-1111-1111-1111-1000-0000 0000-0000-0000-0000-0000-0000-0000-0000 0000-0000-0000-0000-0000-0000-0000-0000 0000-0000-0000-0000-0000-0000-0000-0000 0000-0000-0000-0000-0000-0000-0000-0000 0000-0000-0000-0000-0000-0000-0000-0000 0000-0000-0000-0000-0000-0000-00"
}
Output sample of the locking info section
{
  "EventReceivedTime": "2021-05-19T01:37:48.477750-07:00",
  "SourceModuleName": "from_file_single",
  "SourceModuleType": "im_file",
  "Collisions": "525",
  "LockFlag": "0",
  "LockID": "DUR",
  "LockSemID": "5769340",
  "PID": "0"
}

DUR simulator log

DURSIM is a utility that can be used for application debugging. It simulates a requester or server process by sending and/or receiving messages. Therefore DURSIM can act both as a dummy server and a client (in the client/server model).

Example 6. Processing DUR simulator log

This example covers the default DURSIM configuration specified in the smdmon_config.csv system monitor configuration file.

The input sample below is taken from smd_<node_name>_LOW_dursim_logging.log and contains the request information to the umhlog process.

Input sample
##[1][dursim -c 0 umhlog -1 20 l1 l4][Switching umhlogging on][19/05/2021 04:46:02:226]

The following fields can be parsed from this event:

  • ID

  • Process

  • Node Number

  • Destination Process

  • Options

  • Message

  • Timestamp

Defining the SMD_DURSIM_LOG_REGEX regular expression
define SMD_DURSIM_LOG_REGEX /(?x)^\#\#\[(?<ID>\d+)\]\[\
                            (?<Process>\w+\s*\-*c*)\s+\
                            (?<NodeNum>\d+)\s+\
                            (?<DestProcess>\w+)\s+\
                            (?<Options>.*?)\]\[\
                            (?<Message>.*?)\]\[\
                            (\d+.\d+.\d+.\d+.\d+.\d+).\d+\]/

This regular expression is defined in the configuration as a constant.

To read and parse events, the configuration uses the im_file input module. An Exec block is used to match the log line ($raw_event) against the regular expression. The respective fields are created according to the named capturing groups if matched.

Captured group $7 contains a timestamp in a custom date/time format, therefore it is converted to datetime using the strptime() function and then assigned to the $EventTime field.

Finally, the fields are converted to JSON format using the to_json() procedure of the xm_json module. If the log line does not match any of the defined regular expressions, it is discarded using the drop() procedure.

The following NXLog configuration combines all the steps described above.

nxlog.conf
# A regular expression defined as a constant to read the content of the logs
define SMD_DURSIM_LOG_REGEX /(?x)^\#\#\[(?<ID>\d+)\]\[\
                            (?<Process>\w+\s*\-*c*)\s+\
                            (?<NodeNum>\d+)\s+\
                            (?<DestProcess>\w+)\s+\
                            (?<Options>.*?)\]\[\
                            (?<Message>.*?)\]\[\
                            (\d+.\d+.\d+.\d+.\d+.\d+).\d+\]/

# Part of the log path defined as a constant
define LOG_PATH             C:\Users\Public\Yokogawa\tls\log

<Extension json>
    Module      xm_json
</Extension>

<Input from_file>
    Module      im_file
    File        '%LOG_PATH%\smd_*_dursim_logging.log'

    <Exec>
        # Matches the events with a regular expression
        if $raw_event =~ %SMD_DURSIM_LOG_REGEX%
        {
            # Creates the timestamp
            $EventTime = strptime($7, '%d/%m/%Y %T');
            # Formats the result as JSON
            to_json();
        }
        # Discard messages that do not match the expression
        else drop();
    </Exec>
</Input>

The following output sample depicts a processed event in JSON format.

Output sample
{
  "EventReceivedTime": "2021-05-19T04:46:02.679816-07:00",
  "SourceModuleName": "from_file",
  "SourceModuleType": "im_file",
  "DestProcess": "umhlog",
  "ID": "1",
  "Message": "Switching umhlogging on",
  "NodeNum": "0",
  "Options": "-1 20 l1 l4",
  "Process": "dursim -c",
  "EventTime": "2021-05-19T04:46:02.000000-07:00"
}

EQUIPMENT/FAST debugger log

The equipment manager module (EQP) is a framework handling communication to field devices. In other words, this is the link between the equipment (e.g., PLCs, DCS systems, or RTU equipment) and the item handler.

The EQUIPMENT/FAST debugger process EQPDBG is designed to provide insight into the internal data of the equipment manager. It allows to inspect the equipment manager process and perform some configuration actions.

Example 7. Processing EQP debugger log

The default EQPDBG related configuration in smdmon_config.csv specifies getting several blocks of information from the EQUIPMENT/FAST debugger process, such as:

  • 1 - Get main info

  • 3 - Get slave info

  • 11 - Get statistics

EQP debugger events have a complex structure and can’t be processed by NXLog as a single event. However, the event can be split into six parts: the request, main info, slave info, statistics, statistics table, and statistics table total sections. The following is an example of each section and the regular expressions used to parse them.

Request part
##[10][eqpdbg  < 0, EQPMDC, 1, 3, 1, 11, 1, -1, ][All][21/05/2021 02:27:22:885]

The request part consists of the following fields:

  • ID

  • Process

  • Commands

  • Comment

  • EventTime

Defining the SMD_EQPDBG_REQ_REGEX regular expression
define SMD_EQPDBG_REQ_REGEX         /(?x)^\#\#\[(?<ID>\d+)\]\[\
                                    (?<Process>\w+)[\s\<\>]*\
                                    (?<Commands>.*?)\]\[\
                                    (?<Comment>.*?)\]\[\
                                    (\d+.\d+.\d+.\d+.\d+.\d+).\d+\]/
Main info part
---- Get main info ----

line type 107
Line 0: attached
Line 1: attached
Scan interval    = 100 msec
Scan status      = ON_SCAN
Ext scan status  = ON_SCAN
Period. process. = 0 scan intervals
Slave count      = 1
Scans done       = 3104
Reset_time       = Fri May 21 09:21:31 2021
Stat. i/o timing = FALSE
Input  items offline: No   on-line: No
Output items offline: No   on-line: No
Criterion mask   = 0x000D
Logging file size= 0 Mega bytes
Log file name    =
Slave conn. log. = Yes
Line conn. log.  = No
MIB start address= 0x0019FA78

Give action to do [-2 - 23] [1]

The Get main info command returns global data about the equipment manager. It can also be used to see if communication devices are attached successfully.

The main info part contains the following fields:

  • LineType

  • Line0

  • Line1

  • ScanInterval

  • ScanStatus

  • ExtScanStatus

  • PeriodProcess

  • SlaveCount

  • ScansDone

  • ResetTime

  • Stat_IO_Timing

  • InputItemsOffline

  • OutputItemsOffline

  • CriterionMask

  • LoggingFileSize

  • LogFileName

  • SlaveConnLog

  • LineConnLog

  • MIB_StartAddress

Defining the SMD_EQPDBG_MAIN_INFO_REGEX regular expression
define SMD_EQPDBG_MAIN_INFO_REGEX   /(?x)^\-*\s*Get\s*main\s*info\s*\-*\s*\
                                    (?:line\s*type\s*(?<LineType>\d+))\s*\
                                    (?:Line\s*0[\s\:]*(?<Line0>.*?))\s*\
                                    (?:Line\s*1[\s\:]*(?<Line1>.*?))\s*\
                                    (?:Scan\s*interval[\s\=]*\
                                    (?<ScanInterval>.*?))\s*\
                                    (?:Scan\s*status[\s\=]*\
                                    (?<ScanStatus>.*?))\s*\
                                    (?:Ext\s*scan\s*status[\s\=]*\
                                    (?<ExtScanStatus>.*?))?\s*\
                                    (?:Period\.\s*process\.[\s\=]*\
                                    (?<PeriodProcess>.*?))\s*\
                                    (?:Slave\s*count[\s\=]*\
                                    (?<SlaveCount>.*?))\s*\
                                    (?:Scans\s*done[\s\=]*\
                                    (?<ScansDone>.*?))\s*\
                                    (?:Reset_time[\s\=]*(?<ResetTime>.*?))\s*\
                                    (?:Stat\.\s*i\/o\s*timing[\s\=]*\
                                    (?<Stat_IO_Timing>.*?))\s*\
                                    (?:Input\s*items\s*offline[\s\:]*\
                                    (?<InputItemsOffline>.*?))\s*\
                                    (?:Output\s*items\s*offline[\s\:]*\
                                    (?<OutputItemsOffline>.*?))\s*\
                                    (?:Criterion\s*mask[\s\=]*\
                                    (?<CriterionMask>.*?))\s*\
                                    (?:Logging\s*file\s*size[\s\=]*\
                                    (?<LoggingFileSize>.*?))\s*\
                                    (?:Log\s*file\s*name[\s\=]*\
                                    (?<LogFileName>.*?))\s*\
                                    (?:Slave\s*conn\.\s*log\.[\s\=]*\
                                    (?<SlaveConnLog>.*?))\s*\
                                    (?:Line\s*conn\.\s*log\.[\s\=]*\
                                    (?<LineConnLog>.*?))\s*\
                                    (?:MIB\s*start\s*address[\s\=]*\
                                    (?<MIB_StartAddress>.*?))\s*\
                                    Give\s*action\s*to\s*do\s*\.*/
Slave info part
---- Get slave info ----

Give slave number [0 - 65535] [0] Slave            =      1    Name             = DUMMYSTATION
Slave_type       =    100    Wanted path      =      0
One path         = TRUE      Scan status      = ON_SCAN
General request  = TRUE      Re-init          = FALSE
Recover line 0   =      0    Recover line 1   =      0 Sec
Output method    =      0    Slave info size  =    132
Address gap      =     20    Max. addresses   =    240
Output tib count =      1    Scan preset      =      0
LST/LCT diff     =      0
Sync interval    =      0    Next sync        =      0
Request events   =      0    User info pnt    = 00E66C30
Allowed tries    =      2    Retries on reads =      0

------------------ item (g,n) -- actual -- #bad/#swt -- last error --
Line 0           =   0,    0      GOOD        0         0x00000000
Line 1           =   0,    0      BAD         0         0x00000000
Both lines       =   0,    0      GOOD        0
Selection        =   0,    0      line 0           0

Statistics:                              line 0      line 1
Total requests sent                         237           0
  Valid responses                           237           0
    Return code indicates success           236           0
    Return code indicates error               1           0
  Invalid responses                           0           0
    No response, no data received             0           0
    No start of message detected              0           0
    Start of message detected                 0           0
    Frame too long                            0           0
    Invalid data inside message               0           0
    Frame too short                           0           0
    Bad checksum                              0           0
    Intermediate response received            0           0
    Incorrect RTU echo                        0           0
Retries initiated                             0           0
Retries succeeded                             0           0

Give action to do [-2 - 23] [3]

The Get slave info option returns information about a defined slave station.

The slave info part contains the following fields:

  • Slave number

  • Slave name

  • Slave type - slave type number

  • Wanted path - preferred communication device

  • One path - use of a second communication device

  • Scan status - whether the station is currently being scanned

  • General request

  • Re-init

  • Recover line 0 / Recover line 1 - the amount of time left until the next communication check is performed

  • Output method - defines whether or not output signals are reset to zero inside the connected slave station whenever the equipment manager is started.

  • Slave info size

  • Address gap - specifies the maximum address gap allowed within a single I/O

  • Max. addresses - the maximum size of the data returned by the slave station

  • Output tib count

  • Scan preset - slave station’s offset within a scan interval

  • LST/LCT diff

  • Sync interval

  • Next sync

  • Request events

  • User info pnt

  • Allowed tries

  • Retries on reads

  • A counter which administrates the number of times a line has gone BAD and the number of times a line switch over was made

  • An overview of item id’s that reflects the status of communications lines

  • Statistic information about the messages transferred

Defining the SMD_EQPDBG_SLAVE_INFO_REGEX regular expression
define SMD_EQPDBG_SLAVE_INFO_REGEX  /(?x)^\-*\s*Get\s*slave\s*info\s*\-*\s*.*?\
                                    (?:Slave[\s\=]*(?<Slave>\d+))\s*\
                                    (?:Name[\s\=]*(?<Name>.*?))\s*\
                                    (?:Slave_type[\s\=]*(?<SlaveType>.*?))\s*\
                                    (?:Wanted\s*path[\s\=]*\
                                    (?<WantedPath>.*?))\s*\
                                    (?:One\s*path[\s\=]*(?<OnePath>.*?))\s*\
                                    (?:Scan\s*status[\s\=]*\
                                    (?<ScanStatus>.*?))\s*\
                                    (?:General\s*request[\s\=]*\
                                    (?<GeneralRequest>.*?))\s*\
                                    (?:Re\-init[\s\=]*(?<Reinit>.*?))\s*\
                                    (?:Recover\s*line\s*0[\s\=]*\
                                    (?<RecoverLine0>.*?))\s*\
                                    (?:Recover\s*line\s*1[\s\=]*\
                                    (?<RecoverLine1>.*?))\s*\
                                    (?:Output\s*method[\s\=]*\
                                    (?<OutputMethod>.*?))\s*\
                                    (?:Slave\s*info\s*size[\s\=]*\
                                    (?<SlaveInfoSize>.*?))\s*\
                                    (?:Address\s*gap[\s\=]*\
                                    (?<AddressGap>.*?))\s*\
                                    (?:Max\.\s*addresses[\s\=]*\
                                    (?<MaxAddresses>.*?))\s*\
                                    (?:Output\s*tib\s*count[\s\=]*\
                                    (?<OutputTibCount>.*?))\s*\
                                    (?:Scan\s*preset[\s\=]*\
                                    (?<ScanPreset>.*?))\s*\
                                    (?:LST\/LCT\s*diff[\s\=]*\
                                    (?<LST_LCT_diff>.*?))\s*\
                                    (?:Sync\s*interval[\s\=]*\
                                    (?<SyncInterval>.*?))\s*\
                                    (?:Next\s*sync[\s\=]*(?<NextSync>.*?))\s*\
                                    (?:Request\s*events[\s\=]*\
                                    (?<RequestEvents>.*?))\s*\
                                    (?:User\s*info\s*pnt[\s\=]*\
                                    (?<UserInfoPnt>.*?))\s*\
                                    (?:Allowed\s*tries[\s\=]*\
                                    (?<AllowedTries>.*?))\s*\
                                    (?:Retries\s*on\s*reads[\s\=]*\
                                    (?<RetriesOnReads>.*?))\s*\-+.*\s*\
                                    (?:Line\s*0[\s\=]*\
                                    (?<Line0_Item>\d+\,\s*\d+))\s+\
                                    (?<Line0_Actual>.*?)\s+\
                                    (?<Line0_BadSwt>.*?)\s+\
                                    (?<Line0_LastError>.*?)\s*\
                                    (?:Line\s*1[\s\=]*\
                                    (?<Line1_Item>\d+\,\s*\d+))\s+\
                                    (?<Line1_Actual>.*?)\s+\
                                    (?<Line1_BadSwt>.*?)\s+\
                                    (?<Line1_LastError>.*?)\s*\
                                    (?:Both\s*lines[\s\=]*\
                                    (?<BothLines_Item>\d+\,\s*\d+))\s+\
                                    (?<BothLines_Actual>.*?)\s+\
                                    (?<BothLines_BadSwt>.*?)\s+\
                                    (?<BothLines_LastError>.*?)\s*\
                                    (?:Selection[\s\=]*\
                                    (?<Selection_Item>\d+\,\s*\d+))\s+\
                                    (?<Selection_Actual>.*?)\s+\
                                    (?<Selection_BadSwt>\d+)\s*\
                                    (?:Statistics\:\s*line\s*0\s*line\s*1)\s*\
                                    (?:Total\s*requests\s*sent\s*\
                                    (?<TotalRequestsSent_Line0_Line1>.*?))\s*\
                                    (?:Valid\s*responses\s*\
                                    (?<ValidResponses_Line0_Line1>.*?))\s*\
                                    (?:Return\s*code\s*indicates\s*success\s*\
                                    (?<ReturnCodeIndSuccess_Line0_Line1>.*?))\s*\
                                    (?:Return\s*code\s*indicates\s*error\s*\
                                    (?<ReturnCodeIndError_Line0_Line1>.*?))\s*\
                                    (?:Invalid\s*responses\s*\
                                    (?<InvalidResponses_Line0_Line1>.*?))\s*\
                                    (?:No\s*response\,\s*no\s*data\s*\
                                    received\s*\
                                    (?<NoResponseNoDataRec_Line0_Line1>.*?))\s*\
                                    (?:No\s*start\s*of\s*message\s*detected\s*\
                                    (?<NoStartOfMsgDetected_Line0_Line1>.*?))\s*\
                                    (?:Start\s*of\s*message\s*detected\s*\
                                    (?<StartOfMsgDetected_Line0_Line1>.*?))\s*\
                                    (?:Frame\s*too\s*long\s*\
                                    (?<FrameTooLong_Line0_Line1>.*?))\s*\
                                    (?:Invalid\s*data\s*inside\s*message\s*\
                                    (?<InvalidDataInsideMsg_Line0_Line1>.*?))\s*\
                                    (?:Frame\s*too\s*short\s*\
                                    (?<FrameTooShort_Line0_Line1>.*?))\s*\
                                    (?:Bad\s*checksum\s*\
                                    (?<BadChecksum_Line0_Line1>.*?))\s*\
                                    (?:Intermediate\s*response\s*received\s*\
                                    (?<IntermedResponceRec_Line0_Line1>.*?))\s*\
                                    (?:Incorrect\s*RTU\s*echo\s*\
                                    (?<IncorrectRTUEcho_line0_Line1>.*?))\s*\
                                    (?:Retries\s*initiated\s*\
                                    (?<RetriesInitiated_Line0_Line1>.*?))\s*\
                                    (?:Retries\s*succeeded\s*\
                                    (?<RetriesSucceeded>.*))\s*Give\s*\
                                    action\s*to\s*do\s*.*/
Statistics part
---- Get statistics ----

Give slave number [0 - 65535] [1] Slave            = 1
Statistics over    352 seconds
I/O_type / scans = 2
Bad count line 0 = 0
Bad count line 1 = 0
Bad count lines  = 0
Switch line count= 0

 io   scan   <-- static info -->   <------- dynamic info ------->  <-i/o time->
type  rate   item's  io's  adr's      io's     actions    updates    seconds
-------------------------------------------------------------------------------
 105   1000     1      1      2          0           0          0         0.000
 104   1000    10      1     20        236        2360       2350         0.000
-------------------------------------------------------------------------------
Total :        11      2     22        236        2360       2350         0.000

Give action to do [-2 - 23] [11]

The Get statistics option produces I/O timing statistics.

This part contains the following fields:

  • Slave

  • StatisticsOver

  • IO_type_scans

  • BadCountLine0

  • BadCountLine1

  • BadCountLines

  • SwitchLineCount

Defining the SMD_EQPDBG_STATISTICS_REGEX regular expression
define SMD_EQPDBG_STATISTICS_REGEX  /(?x)^\-*\s*Get\s*statistics\s*\-*\
                                    \s*Give\s*slave\s*number\s*.*?\
                                    (?:Slave[\s\=]*(?<Slave>.*?))\s*\
                                    (?:Statistics\s*over\s*\
                                    (?<StatisticsOver>.*?))\s*\
                                    (?:I\/O_type\s*\/\s*scans[\s\=]*\
                                    (?<IO_type_scans>.*?))\s*\
                                    (?:Bad\s*count\s*line\s*0[\s\=]*\
                                    (?<BadCountLine0>.*?))\s*\
                                    (?:Bad\s*count\s*line\s*1[\s\=]*\
                                    (?<BadCountLine1>.*?))\s*\
                                    (?:Bad\s*count\s*lines[\s\=]*\
                                    (?<BadCountLines>.*?))\s*\
                                    (?:Switch\s*line\s*count[\s\=]*\
                                    (?<SwitchLineCount>\d*))/
Statistics table
 105   1000     1      1      2          0           0          0         0.000
 104   1000    10      1     20        236        2360       2350         0.000

The statistics section also contains a table with a variable number of rows. The best approach is to parse each row as a separate event.

The following fields can be parsed from each table row:

  • IO_type

  • ScanRate

  • StaticInfo_Items

  • StaticInfo_IOs

  • StaticInfo_Adrs

  • DynamicInfo_IOs

  • DynamicInfo_Actions

  • DynamicInfo_Updates

  • IO_Time_Seconds

Defining the SMD_EQPDBG_STAT_ADD_REGEX regular expression
define SMD_EQPDBG_STAT_ADD_REGEX    /(?x)^\s*(?<IO_type>[\d\-\.]+)\s+\
                                    (?<ScanRate>[\d\-\.]+)\s+\
                                    (?<StaticInfo_Items>[\d\-\.]+)\s+\
                                    (?<StaticInfo_IOs>[\d\-\.]+)\s+\
                                    (?<StaticInfo_Adrs>[\d\-\.]+)\s+\
                                    (?<DynamicInfo_IOs>[\d\-\.]+)\s+\
                                    (?<DynamicInfo_Actions>[\d\-\.]+)\s+\
                                    (?<DynamicInfo_Updates>[\d\-\.]+)\s+\
                                    (?<IO_Time_Seconds>[\d\-\.]+)/
Statistics table total
Total :        11      2     22        236        2360       2350         0.000

The Total row of the table in the Get statistics section follows a different pattern and requires a different regular expression.

The following fields can be parsed from the table total row:

  • StaticInfo_TotalItems

  • StaticInfo_TotalIOs

  • StaticInfo_TotalAdrs

  • DynamicInfo_TotalIOs

  • DynamicInfo_TotalActions

  • DynamicInfo_TotalUpdates

  • IOTime_TotalSeconds

Defining the SMD_EQPDBG_STAT_TOTAL_REGEX regular expression
define SMD_EQPDBG_STAT_TOTAL_REGEX  /(?x)^Total\s*\:\s+\
                                    (?<StaticInfo_TotalItems>[\d\-\.]+)\s+\
                                    (?<StaticInfo_TotalIOs>[\d\-\.]+)\s+\
                                    (?<StaticInfo_TotalAdrs>[\d\-\.]+)\s+\
                                    (?<DynamicInfo_TotalIOs>[\d\-\.]+)\s+\
                                    (?<DynamicInfo_TotalActions>[\d\-\.]+)\s+\
                                    (?<DynamicInfo_TotalUpdates>[\d\-\.]+)\s+\
                                    (?<IOTime_TotalSeconds>[\d\-\.]+)/

The regular expressions above are defined in the configuration as constants.

Since the log file contains multi-line events in different formats, separate instances of the im_file input module are defined. The name of the corresponding input reader function is specified by the InputType directive.

Different xm_multiline module instances are used to process multi-line events as a single record. The HeaderLine and EndLine directives of this module specify a regular expression to detect the beginning and end of each multi-line event respectively.

The Exec block of each input module instance matches the log line ($raw_event) against the appropriate regular expression. Once a match occurs, the respective fields are created according to the named capturing groups.

Captured fields containing a timestamp are converted to datetime using the strptime() function and then assigned to the $EventTime field.

Finally, the fields are converted to JSON format using the to_json() procedure of the xm_json module. If the log line doesn’t match any of the defined regular expressions, it is discarded using the drop() procedure.

The following NXLog configuration combines all the steps described above.

nxlog.conf
# A regular expression defined as a constant to read the content of the logs
define SMD_EQPDBG_REQ_REGEX         /(?x)^\#\#\[(?<ID>\d+)\]\[\
                                    (?<Process>\w+)[\s\<\>]*\
                                    (?<Commands>.*?)\]\[\
                                    (?<Comment>.*?)\]\[\
                                    (\d+.\d+.\d+.\d+.\d+.\d+).\d+\]/

define SMD_EQPDBG_MAIN_INFO_REGEX   /(?x)^\-*\s*Get\s*main\s*info\s*\-*\s*\
                                    (?:line\s*type\s*(?<LineType>\d+))\s*\
                                    (?:Line\s*0[\s\:]*(?<Line0>.*?))\s*\
                                    (?:Line\s*1[\s\:]*(?<Line1>.*?))\s*\
                                    (?:Scan\s*interval[\s\=]*\
                                    (?<ScanInterval>.*?))\s*\
                                    (?:Scan\s*status[\s\=]*\
                                    (?<ScanStatus>.*?))\s*\
                                    (?:Ext\s*scan\s*status[\s\=]*\
                                    (?<ExtScanStatus>.*?))?\s*\
                                    (?:Period\.\s*process\.[\s\=]*\
                                    (?<PeriodProcess>.*?))\s*\
                                    (?:Slave\s*count[\s\=]*\
                                    (?<SlaveCount>.*?))\s*\
                                    (?:Scans\s*done[\s\=]*\
                                    (?<ScansDone>.*?))\s*\
                                    (?:Reset_time[\s\=]*(?<ResetTime>.*?))\s*\
                                    (?:Stat\.\s*i\/o\s*timing[\s\=]*\
                                    (?<Stat_IO_Timing>.*?))\s*\
                                    (?:Input\s*items\s*offline[\s\:]*\
                                    (?<InputItemsOffline>.*?))\s*\
                                    (?:Output\s*items\s*offline[\s\:]*\
                                    (?<OutputItemsOffline>.*?))\s*\
                                    (?:Criterion\s*mask[\s\=]*\
                                    (?<CriterionMask>.*?))\s*\
                                    (?:Logging\s*file\s*size[\s\=]*\
                                    (?<LoggingFileSize>.*?))\s*\
                                    (?:Log\s*file\s*name[\s\=]*\
                                    (?<LogFileName>.*?))\s*\
                                    (?:Slave\s*conn\.\s*log\.[\s\=]*\
                                    (?<SlaveConnLog>.*?))\s*\
                                    (?:Line\s*conn\.\s*log\.[\s\=]*\
                                    (?<LineConnLog>.*?))\s*\
                                    (?:MIB\s*start\s*address[\s\=]*\
                                    (?<MIB_StartAddress>.*?))\s*\
                                    Give\s*action\s*to\s*do\s*\.*/

define SMD_EQPDBG_SLAVE_INFO_REGEX  /(?x)^\-*\s*Get\s*slave\s*info\s*\-*\s*.*?\
                                    (?:Slave[\s\=]*(?<Slave>\d+))\s*\
                                    (?:Name[\s\=]*(?<Name>.*?))\s*\
                                    (?:Slave_type[\s\=]*(?<SlaveType>.*?))\s*\
                                    (?:Wanted\s*path[\s\=]*\
                                    (?<WantedPath>.*?))\s*\
                                    (?:One\s*path[\s\=]*(?<OnePath>.*?))\s*\
                                    (?:Scan\s*status[\s\=]*\
                                    (?<ScanStatus>.*?))\s*\
                                    (?:General\s*request[\s\=]*\
                                    (?<GeneralRequest>.*?))\s*\
                                    (?:Re\-init[\s\=]*(?<Reinit>.*?))\s*\
                                    (?:Recover\s*line\s*0[\s\=]*\
                                    (?<RecoverLine0>.*?))\s*\
                                    (?:Recover\s*line\s*1[\s\=]*\
                                    (?<RecoverLine1>.*?))\s*\
                                    (?:Output\s*method[\s\=]*\
                                    (?<OutputMethod>.*?))\s*\
                                    (?:Slave\s*info\s*size[\s\=]*\
                                    (?<SlaveInfoSize>.*?))\s*\
                                    (?:Address\s*gap[\s\=]*\
                                    (?<AddressGap>.*?))\s*\
                                    (?:Max\.\s*addresses[\s\=]*\
                                    (?<MaxAddresses>.*?))\s*\
                                    (?:Output\s*tib\s*count[\s\=]*\
                                    (?<OutputTibCount>.*?))\s*\
                                    (?:Scan\s*preset[\s\=]*\
                                    (?<ScanPreset>.*?))\s*\
                                    (?:LST\/LCT\s*diff[\s\=]*\
                                    (?<LST_LCT_diff>.*?))\s*\
                                    (?:Sync\s*interval[\s\=]*\
                                    (?<SyncInterval>.*?))\s*\
                                    (?:Next\s*sync[\s\=]*(?<NextSync>.*?))\s*\
                                    (?:Request\s*events[\s\=]*\
                                    (?<RequestEvents>.*?))\s*\
                                    (?:User\s*info\s*pnt[\s\=]*\
                                    (?<UserInfoPnt>.*?))\s*\
                                    (?:Allowed\s*tries[\s\=]*\
                                    (?<AllowedTries>.*?))\s*\
                                    (?:Retries\s*on\s*reads[\s\=]*\
                                    (?<RetriesOnReads>.*?))\s*\-+.*\s*\
                                    (?:Line\s*0[\s\=]*\
                                    (?<Line0_Item>\d+\,\s*\d+))\s+\
                                    (?<Line0_Actual>.*?)\s+\
                                    (?<Line0_BadSwt>.*?)\s+\
                                    (?<Line0_LastError>.*?)\s*\
                                    (?:Line\s*1[\s\=]*\
                                    (?<Line1_Item>\d+\,\s*\d+))\s+\
                                    (?<Line1_Actual>.*?)\s+\
                                    (?<Line1_BadSwt>.*?)\s+\
                                    (?<Line1_LastError>.*?)\s*\
                                    (?:Both\s*lines[\s\=]*\
                                    (?<BothLines_Item>\d+\,\s*\d+))\s+\
                                    (?<BothLines_Actual>.*?)\s+\
                                    (?<BothLines_BadSwt>.*?)\s+\
                                    (?<BothLines_LastError>.*?)\s*\
                                    (?:Selection[\s\=]*\
                                    (?<Selection_Item>\d+\,\s*\d+))\s+\
                                    (?<Selection_Actual>.*?)\s+\
                                    (?<Selection_BadSwt>\d+)\s*\
                                    (?:Statistics\:\s*line\s*0\s*line\s*1)\s*\
                                    (?:Total\s*requests\s*sent\s*\
                                    (?<TotalRequestsSent_Line0_Line1>.*?))\s*\
                                    (?:Valid\s*responses\s*\
                                    (?<ValidResponses_Line0_Line1>.*?))\s*\
                                    (?:Return\s*code\s*indicates\s*success\s*\
                                    (?<ReturnCodeIndSuccess_Line0_Line1>.*?))\s*\
                                    (?:Return\s*code\s*indicates\s*error\s*\
                                    (?<ReturnCodeIndError_Line0_Line1>.*?))\s*\
                                    (?:Invalid\s*responses\s*\
                                    (?<InvalidResponses_Line0_Line1>.*?))\s*\
                                    (?:No\s*response\,\s*no\s*data\s*\
                                    received\s*\
                                    (?<NoResponseNoDataRec_Line0_Line1>.*?))\s*\
                                    (?:No\s*start\s*of\s*message\s*detected\s*\
                                    (?<NoStartOfMsgDetected_Line0_Line1>.*?))\s*\
                                    (?:Start\s*of\s*message\s*detected\s*\
                                    (?<StartOfMsgDetected_Line0_Line1>.*?))\s*\
                                    (?:Frame\s*too\s*long\s*\
                                    (?<FrameTooLong_Line0_Line1>.*?))\s*\
                                    (?:Invalid\s*data\s*inside\s*message\s*\
                                    (?<InvalidDataInsideMsg_Line0_Line1>.*?))\s*\
                                    (?:Frame\s*too\s*short\s*\
                                    (?<FrameTooShort_Line0_Line1>.*?))\s*\
                                    (?:Bad\s*checksum\s*\
                                    (?<BadChecksum_Line0_Line1>.*?))\s*\
                                    (?:Intermediate\s*response\s*received\s*\
                                    (?<IntermedResponceRec_Line0_Line1>.*?))\s*\
                                    (?:Incorrect\s*RTU\s*echo\s*\
                                    (?<IncorrectRTUEcho_line0_Line1>.*?))\s*\
                                    (?:Retries\s*initiated\s*\
                                    (?<RetriesInitiated_Line0_Line1>.*?))\s*\
                                    (?:Retries\s*succeeded\s*\
                                    (?<RetriesSucceeded>.*))\s*Give\s*\
                                    action\s*to\s*do\s*.*/

define SMD_EQPDBG_STATISTICS_REGEX  /(?x)^\-*\s*Get\s*statistics\s*\-*\
                                    \s*Give\s*slave\s*number\s*.*?\
                                    (?:Slave[\s\=]*(?<Slave>.*?))\s*\
                                    (?:Statistics\s*over\s*\
                                    (?<StatisticsOver>.*?))\s*\
                                    (?:I\/O_type\s*\/\s*scans[\s\=]*\
                                    (?<IO_type_scans>.*?))\s*\
                                    (?:Bad\s*count\s*line\s*0[\s\=]*\
                                    (?<BadCountLine0>.*?))\s*\
                                    (?:Bad\s*count\s*line\s*1[\s\=]*\
                                    (?<BadCountLine1>.*?))\s*\
                                    (?:Bad\s*count\s*lines[\s\=]*\
                                    (?<BadCountLines>.*?))\s*\
                                    (?:Switch\s*line\s*count[\s\=]*\
                                    (?<SwitchLineCount>\d*))/

define SMD_EQPDBG_STAT_ADD_REGEX    /(?x)^\s*(?<IO_type>[\d\-\.]+)\s+\
                                    (?<ScanRate>[\d\-\.]+)\s+\
                                    (?<StaticInfo_Items>[\d\-\.]+)\s+\
                                    (?<StaticInfo_IOs>[\d\-\.]+)\s+\
                                    (?<StaticInfo_Adrs>[\d\-\.]+)\s+\
                                    (?<DynamicInfo_IOs>[\d\-\.]+)\s+\
                                    (?<DynamicInfo_Actions>[\d\-\.]+)\s+\
                                    (?<DynamicInfo_Updates>[\d\-\.]+)\s+\
                                    (?<IO_Time_Seconds>[\d\-\.]+)/

define SMD_EQPDBG_STAT_TOTAL_REGEX  /(?x)^Total\s*\:\s+\
                                    (?<StaticInfo_TotalItems>[\d\-\.]+)\s+\
                                    (?<StaticInfo_TotalIOs>[\d\-\.]+)\s+\
                                    (?<StaticInfo_TotalAdrs>[\d\-\.]+)\s+\
                                    (?<DynamicInfo_TotalIOs>[\d\-\.]+)\s+\
                                    (?<DynamicInfo_TotalActions>[\d\-\.]+)\s+\
                                    (?<DynamicInfo_TotalUpdates>[\d\-\.]+)\s+\
                                    (?<IOTime_TotalSeconds>[\d\-\.]+)/

# Part of the log path defined as a constant
define LOG_PATH                     C:\Users\Public\Yokogawa\tls\log

<Extension json>
    Module        xm_json
</Extension>

<Extension multiline_main_info>
    Module        xm_multiline
    # Regular expression to look for the header of the message
    HeaderLine    /^\-+\s*Get\s*main\s*info\s*\-+/
    EndLine       /^Give\s*action\s*to\s*do\s*\[.*?\]\s\[1\]\s*/
</Extension>

<Extension multiline_slave_info>
    Module        xm_multiline
    # Regular expression to look for the header of the message
    HeaderLine    /^\-+\s*Get\s*slave\s*info\s*\-+/
    EndLine       /^Give\s*action\s*to\s*do\s*\[.*?\]\s\[3\]\s*/
</Extension>

<Extension multiline_statistics>
    Module        xm_multiline
    # Regular expression to look for the header of the message
    HeaderLine    /^\-+\s*Get\s*statistics\s*\-+/
    EndLine       /^Switch\s*line\s*count[\s\=\d]*/
</Extension>

<Input from_file_main_info>
    Module        im_file
    File          '%LOG_PATH%\smd_*_eqpdbg_all.log'
    InputType     multiline_main_info

    <Exec>
        # Replaces unwanted characters
        $raw_event =~ s/\\n/ /g;
        $raw_event =~ s/\\r/ /g;
        $raw_event =~ s/\s{2,}/ /g;
    </Exec>

    <Exec>
        # Matches the events with a regular expression
        if $raw_event =~ %SMD_EQPDBG_MAIN_INFO_REGEX%
        {
            # Formats the result as JSON
            to_json();
        }
        # Discard event if it doesn't match a/the regular expression
        #else drop();
    </Exec>
</Input>

<Input from_file_slave_info>
    Module        im_file
    File          '%LOG_PATH%\smd_*_eqpdbg_all.log'
    InputType     multiline_slave_info

    <Exec>
        # Replaces unwanted characters
        $raw_event =~ s/\\n/ /g;
        $raw_event =~ s/\\r/ /g;
        $raw_event =~ s/\s{2,}/ /g;
    </Exec>

    <Exec>
        # Matches the events with a regular expression
        if $raw_event =~ %SMD_EQPDBG_SLAVE_INFO_REGEX%
        {
            # Formats the result as JSON
            to_json();
        }
        # Discard event if it doesn't match a/the regular expression
        else drop();
    </Exec>
</Input>

<Input from_file_statistics>
    Module        im_file
    File          '%LOG_PATH%\smd_*_eqpdbg_all.log'
    InputType     multiline_statistics

    <Exec>
        # Replaces unwanted characters
        $raw_event =~ s/\\n/ /g;
        $raw_event =~ s/\\r/ /g;
        $raw_event =~ s/\s{2,}/ /g;
    </Exec>

    <Exec>
        # Matches the events with a regular expression
        if $raw_event =~ %SMD_EQPDBG_STATISTICS_REGEX%
        {
            # Formats the result as JSON
            to_json();
        }
        # Discard event if it doesn't match a/the regular expression
        else drop();
    </Exec>
</Input>

<Input from_file>
    Module        im_file
    File          '%LOG_PATH%\smd_*_eqpdbg_all.log'

    <Exec>
        # Matches the events with a regular expression
        if $raw_event =~ %SMD_EQPDBG_REQ_REGEX%
        {
            # Creates the timestamp
            $EventTime = strptime($5, '%d/%m/%Y %T');
            # Formats the result as JSON
            to_json();
        }
        else if $raw_event =~ %SMD_EQPDBG_STAT_ADD_REGEX% or
                $raw_event =~ %SMD_EQPDBG_STAT_TOTAL_REGEX%
        {
            # Formats the result as JSON
            to_json();
        }
        # Discard event if it doesn't match a/the regular expression
        else drop();
    </Exec>
</Input>

The following output samples depict the processed events in JSON format.

Output sample of the request part
{
  "EventReceivedTime": "2021-05-21T02:27:22.979649-07:00",
  "SourceModuleName": "from_file",
  "SourceModuleType": "im_file",
  "Commands": "0, EQPMDC, 1, 3, 1, 11, 1, -1, ",
  "Comment": "All",
  "ID": "10",
  "Process": "eqpdbg",
  "EventTime": "2021-05-21T02:27:22.000000-07:00"
}
Output sample of the main info part
{
  "EventReceivedTime": "2021-05-21T02:27:23.526464-07:00",
  "SourceModuleName": "from_file_main_info",
  "SourceModuleType": "im_file",
  "CriterionMask": "0x000D",
  "ExtScanStatus": "ON_SCAN",
  "InputItemsOffline": "No on-line: No",
  "Line0": "attached",
  "Line1": "attached",
  "LineConnLog": "No",
  "LineType": "107",
  "LogFileName": "",
  "LoggingFileSize": "0 Mega bytes",
  "MIB_StartAddress": "0x0019FA78",
  "OutputItemsOffline": "No on-line: No",
  "PeriodProcess": "0 scan intervals",
  "ResetTime": "Fri May 21 09:21:31 2021",
  "ScanInterval": "100 msec",
  "ScanStatus": "ON_SCAN",
  "ScansDone": "3104",
  "SlaveConnLog": "Yes",
  "SlaveCount": "1",
  "Stat_IO_Timing": "FALSE"
}
Output sample of the slave info part
{
  "EventReceivedTime": "2021-05-21T02:27:23.526464-07:00",
  "SourceModuleName": "from_file_slave_info",
  "SourceModuleType": "im_file",
  "AddressGap": "20",
  "AllowedTries": "2",
  "BadChecksum_Line0_Line1": "0 0",
  "BothLines_Actual": "GOOD",
  "BothLines_BadSwt": "0",
  "BothLines_Item": "0, 0",
  "BothLines_LastError": "",
  "FrameTooLong_Line0_Line1": "0 0",
  "FrameTooShort_Line0_Line1": "0 0",
  "GeneralRequest": "TRUE",
  "IncorrectRTUEcho_line0_Line1": "0 0",
  "IntermedResponceRec_Line0_Line1": "0 0",
  "InvalidDataInsideMsg_Line0_Line1": "0 0",
  "InvalidResponses_Line0_Line1": "0 0",
  "LST_LCT_diff": "0",
  "Line0_Actual": "GOOD",
  "Line0_BadSwt": "0",
  "Line0_Item": "0, 0",
  "Line0_LastError": "0x00000000",
  "Line1_Actual": "BAD",
  "Line1_BadSwt": "0",
  "Line1_Item": "0, 0",
  "Line1_LastError": "0x00000000",
  "MaxAddresses": "240",
  "Name": "DUMMYSTATION",
  "NextSync": "0",
  "NoResponseNoDataRec_Line0_Line1": "0 0",
  "NoStartOfMsgDetected_Line0_Line1": "0 0",
  "OnePath": "TRUE",
  "OutputMethod": "0",
  "OutputTibCount": "1",
  "RecoverLine0": "0",
  "RecoverLine1": "0 Sec",
  "Reinit": "FALSE",
  "RequestEvents": "0",
  "RetriesInitiated_Line0_Line1": "0 0",
  "RetriesOnReads": "0",
  "RetriesSucceeded": "0 0 ",
  "ReturnCodeIndError_Line0_Line1": "1 0",
  "ReturnCodeIndSuccess_Line0_Line1": "236 0",
  "ScanPreset": "0",
  "ScanStatus": "ON_SCAN",
  "Selection_Actual": "line 0",
  "Selection_BadSwt": "0",
  "Selection_Item": "0, 0",
  "Slave": "1",
  "SlaveInfoSize": "132",
  "SlaveType": "100",
  "StartOfMsgDetected_Line0_Line1": "0 0",
  "SyncInterval": "0",
  "TotalRequestsSent_Line0_Line1": "237 0",
  "UserInfoPnt": "00E66C30",
  "ValidResponses_Line0_Line1": "237 0",
  "WantedPath": "0"
}
Output sample of the statistics part
{
  "EventReceivedTime": "2021-05-21T02:27:23.542148-07:00",
  "SourceModuleName": "from_file_statistics",
  "SourceModuleType": "im_file",
  "BadCountLines": "0",
  "BadCountLine0": "0",
  "BadCountLine1": "0",
  "IO_type_scans": "2",
  "Slave": "1",
  "StatisticsOver": "352 seconds",
  "SwitchLineCount": "0"
}
Output sample of the statistics table
{
  "EventReceivedTime": "2021-05-21T02:27:23.620195-07:00",
  "SourceModuleName": "from_file",
  "SourceModuleType": "im_file",
  "DynamicInfo_Actions": "0",
  "DynamicInfo_IOs": "0",
  "DynamicInfo_Updates": "0",
  "IO_Time_Seconds": "0.000",
  "IO_type": "105",
  "ScanRate": "1000",
  "StaticInfo_Adrs": "2",
  "StaticInfo_IOs": "1",
  "StaticInfo_Items": "1"
}
Output sample of the statistics table total
{
  "EventReceivedTime": "2021-05-21T02:27:23.620195-07:00",
  "SourceModuleName": "from_file",
  "SourceModuleType": "im_file",
  "DynamicInfo_TotalActions": "2360",
  "DynamicInfo_TotalIOs": "236",
  "DynamicInfo_TotalUpdates": "2350",
  "IOTime_TotalSeconds": "0.000",
  "StaticInfo_TotalAdrs": "22",
  "StaticInfo_TotalIOs": "2",
  "StaticInfo_TotalItems": "11"
}

History manager (HIS) debugger log

The history manager (HIS) handles all history actions, and its functions are to:

  • Control the start, rollover, and stop times of history storage

  • Control the naming of the data files

  • Control all history information stored on the disks

  • Control the deletion of old history information

  • Supply information about the available history information

  • Supply information about processes working for a specific history part

It contains utilities and command procedures for the backup and restoration of history files.

The debugger utility HISDBG of the history manager provides analysis and functionality to control the behavior of the history manager process.

Example 8. Processing HIS debugger log

The system monitor and diagnostics service can run the HISDBG utility with the configuration defined in the smdmon_config.csv file.

The default configuration for HISDBG specifies only one action to perform:

  • 1 - Get statistics

HIS debugger events can be split into two parts: the request and the statistics. The following is an example of each section and the regular expressions used to parse them.

Request part
##[15][hisdbg  < 0, 1, -1, ][All][21/05/2021 04:51:07:667]

The following fields can be parsed from the request:

  • ID

  • Process

  • Commands

  • Comment

  • EventTime

Defining the SMD_HISDBG_REQ_REGEX regular expression
define SMD_HISDBG_REQ_REGEX     /(?x)^\#\#\[(?<ID>\d+)\]\[\
                                (?<Process>\w+)[\s\<\>]*\
                                (?<Commands>.*?)\]\[\
                                (?<Comment>.*?)\]\[\
                                (\d+.\d+.\d+.\d+.\d+.\d+).\d+\]/
Statistics part
---- Get statistics ----

group count :            32
login process count :    15
login interest count :   49
buffered message count : 0
command sequence no :    127

group creations :        0
group deletions :        0
group modifications :    0
schedule modifications : 0
unit starts :            26
unit stops :             19
unit rollovers :         0
unit deletions :         6
messages sent :          57

Give action to do [-1 - 22] [1]

The following fields can be parsed from the statistics part:

  • group count - total count of history groups

  • login process count - total count of clients logged in the history manager

  • login interest count - total number of command interest of all clients

  • buffered message count - number of messages the manager still has to distribute to clients

  • command sequence no - total number of commands generated by the manager

  • group creations - number of history groups created since the manager was started

  • group deletions - number of history groups deleted since the manager was started

  • group modifications - number of history groups modified since the manager was started

  • schedule modifications - number of history groups of which schedule information has been modified since the manager was started

  • unit starts - number of started units since the manager was started

  • unit stops - number of stopped units since the manager was started

  • unit rollovers - number of unit rollovers since the manager was started

  • unit deletions - number of deleted units since the manager was started

  • messages sent - number of messages sent to clients

Defining the SMD_HISDBG_STAT_REGEX regular expression
define SMD_HISDBG_STAT_REGEX    /(?x)^\-*\s*Get\s*statistics\s*\-*\s*\
                                (?:group\s*count[\s\:]*\
                                (?<GroupCount>\d+))\s*\
                                (?:login\s*process\s*count[\s\:]*\
                                (?<LoginProcessCount>\d+))\s*\
                                (?:login\s*interest\s*count[\s\:]*\
                                (?<LoginInterestCount>\d+))\s*\
                                (?:buffered\s*message\s*count[\s\:]*\
                                (?<BufferedMessageCount>\d+))\s*\
                                (?:command\s*sequence\s*no[\s\:]*\
                                (?<CommandSequenceNo>\d+))\s*\
                                (?:group\s*creations[\s\:]*\
                                (?<GroupCreation>\d+))\s*\
                                (?:group\s*deletions[\s\:]*\
                                (?<GroupDeletions>\d+))\s*\
                                (?:group\s*modifications[\s\:]*\
                                (?<GroupModifications>\d+))\s*\
                                (?:schedule\s*modifications[\s\:]*\
                                (?<ScheduleModifications>\d+))\s*\
                                (?:unit\s*starts[\s\:]*(?<UnitStarts>\d+))\s*\
                                (?:unit\s*stops[\s\:]*(?<UnitStops>\d+))\s*\
                                (?:unit\s*rollovers[\s\:]*\
                                (?<UnitRollovers>\d+))\s*\
                                (?:unit\s*deletions[\s\:]*\
                                (?<UnitDeletions>\d+))\s*\
                                (?:messages\s*sent[\s\:]*\
                                (?<MessagesSent>\d+))\s*\
                                Give\s*action\s*to\s*do.*/

The regular expressions above are defined in the configuration as constants.

The xm_multiline extension module is used to process multi-line events as a single record. The HeaderLine and EndLine directives of this module specify a regular expression to detect the beginning and end of each multi-line event respectively.

The Exec block of each input module instance matches the log line ($raw_event) against the appropriate regular expression. Once a match occurs, the respective fields are created according to the named capturing groups.

Captured group $5 of the request part contains a timestamp in a custom date/time format, therefore it is converted to datetime using the strptime() function and then assigned to the $EventTime field.

Finally, the fields are converted to JSON format using the to_json() procedure of the xm_json module. If the log line does not match any of the defined regular expressions, it is discarded using the drop() procedure.

The following NXLog configuration combines all the steps described above.

nxlog.conf
# A regular expression defined as a constant to read the content of the logs
define SMD_HISDBG_REQ_REGEX     /(?x)^\#\#\[(?<ID>\d+)\]\[\
                                (?<Process>\w+)[\s\<\>]*\
                                (?<Commands>.*?)\]\[\
                                (?<Comment>.*?)\]\[\
                                (\d+.\d+.\d+.\d+.\d+.\d+).\d+\]/

define SMD_HISDBG_STAT_REGEX    /(?x)^\-*\s*Get\s*statistics\s*\-*\s*\
                                (?:group\s*count[\s\:]*\
                                (?<GroupCount>\d+))\s*\
                                (?:login\s*process\s*count[\s\:]*\
                                (?<LoginProcessCount>\d+))\s*\
                                (?:login\s*interest\s*count[\s\:]*\
                                (?<LoginInterestCount>\d+))\s*\
                                (?:buffered\s*message\s*count[\s\:]*\
                                (?<BufferedMessageCount>\d+))\s*\
                                (?:command\s*sequence\s*no[\s\:]*\
                                (?<CommandSequenceNo>\d+))\s*\
                                (?:group\s*creations[\s\:]*\
                                (?<GroupCreation>\d+))\s*\
                                (?:group\s*deletions[\s\:]*\
                                (?<GroupDeletions>\d+))\s*\
                                (?:group\s*modifications[\s\:]*\
                                (?<GroupModifications>\d+))\s*\
                                (?:schedule\s*modifications[\s\:]*\
                                (?<ScheduleModifications>\d+))\s*\
                                (?:unit\s*starts[\s\:]*(?<UnitStarts>\d+))\s*\
                                (?:unit\s*stops[\s\:]*(?<UnitStops>\d+))\s*\
                                (?:unit\s*rollovers[\s\:]*\
                                (?<UnitRollovers>\d+))\s*\
                                (?:unit\s*deletions[\s\:]*\
                                (?<UnitDeletions>\d+))\s*\
                                (?:messages\s*sent[\s\:]*\
                                (?<MessagesSent>\d+))\s*\
                                Give\s*action\s*to\s*do.*/

# Part of the log path defined as a constant
define LOG_PATH                 C:\Users\Public\Yokogawa\tls\log

<Extension json>
    Module        xm_json
</Extension>

<Extension multiline_statistics>
    Module        xm_multiline
    # Regular expression to look for the header of the message
    HeaderLine    /^\-+\s*Get\s*statistics\s*\-+/
    EndLine       /^Give\s*action\s*to\s*do\s*\[.*?\]\s\[1\]\s*/
</Extension>

<Input from_file>
    Module        im_file
    File          '%LOG_PATH%\smd_*_hisdbg_all.log'

    <Exec>
        # Matches the events with a regular expression
        if $raw_event =~ %SMD_HISDBG_REQ_REGEX%
        {
            # Creates the timestamp
            $EventTime = strptime($5, '%d/%m/%Y %T');
            # Formats the result as JSON
            to_json();
        }
        # Discard event if it doesn't match a/the regular expression
        else drop();
    </Exec>
</Input>

<Input from_file_statistics>
    Module        im_file
    File          '%LOG_PATH%\smd_*_hisdbg_all.log'
    InputType     multiline_statistics

    <Exec>
        # Replaces unwanted characters
        $raw_event =~ s/\\n/ /g;
        $raw_event =~ s/\\r/ /g;
        $raw_event =~ s/\s{2,}/ /g;
    </Exec>

    <Exec>
        # Matches the events with a regular expression
        if $raw_event =~ %SMD_HISDBG_STAT_REGEX%
        {
            # Formats the result as JSON
            to_json();
        }
        # Discard event if it doesn't match a/the regular expression
        else drop();
    </Exec>
</Input>

The following output samples depict the processed events in JSON format.

Output sample of the request part
{
  "EventReceivedTime": "2021-05-21T04:51:08.182691-07:00",
  "SourceModuleName": "from_file",
  "SourceModuleType": "im_file",
  "Commands": "0, 1, -1, ",
  "Comment": "All",
  "ID": "15",
  "Process": "hisdbg",
  "EventTime": "2021-05-21T04:51:07.000000-07:00"
}
Output sample of the statistics part
{
  "EventReceivedTime": "2021-05-21T04:51:08.182691-07:00",
  "SourceModuleName": "from_file_statistics",
  "SourceModuleType": "im_file",
  "BufferedMessageCount": "0",
  "CommandSequenceNo": "127",
  "GroupCount": "32",
  "GroupCreation": "0",
  "GroupDeletions": "0",
  "GroupModifications": "0",
  "LoginInterestCount": "49",
  "LoginProcessCount": "15",
  "MessagesSent": "57",
  "ScheduleModifications": "0",
  "UnitDeletions": "6",
  "UnitRollovers": "0",
  "UnitStarts": "26",
  "UnitStops": "19"
}

ISM debugger log

DATABASE/FAST is a FAST/TOOLS collection member that promotes Indexed Sequential Access Method (ISAM) to files.

The ISM is one of the DATABASE/FAST components, providing a routine set for accessing ISAM files located on the BUS/FAST node where the application is running.

The ISMDBG utility observes the ISAM file activity. It can display all processes that have ISAM files open and a list of opened ISAM files.

Example 9. Processing ISM debugger log

According to the default system monitor configuration in smdmon_config.csv, ISMDBG executes the following commands:

  • 1 - Show users

  • 2 - Show files

  • 3 - Show subscriptions

  • 4 - Show pending locks

ISM debugger events have a complex structure and can’t be processed as a single event. However, the event can be split into five parts: the request, users list, files list, subscriptions header, and subscriptions item. The following is an example of each section and the regular expressions used to parse them.

Request part
##[55][ismdbg  < 1, 2, 3, 4, -1, ][All][24/05/2021 02:06:49:061]

The following fields can be parsed from the request:

  • ID

  • Process

  • Commands

  • Comment

  • EventTime

Defining the SMD_ISMDBG_REQ_REGEX regular expression
define SMD_ISMDBG_REQ_REGEX     /(?x)^\#\#\[(?<ID>\d+)\]\[\
                                (?<Process>\w+)[\s\<\>]*\
                                (?<Commands>.*?)\]\[\
                                (?<Comment>.*?)\]\[\
                                (\d+.\d+.\d+.\d+.\d+.\d+).\d+\]/
Users list part
 no ----user---- --db id- --attach-- ------------------files------------------
                             count
==============================================================================
  0   INT_SERVER 005460b8 1621845976           1:item.d01
  1   INT_SERVER 00ca01e8 1621845976     1:item_name1.d01
  2   INT_SERVER 00ca9270 1621845976     1:item_name2.d01

  ...

146    EQPIOSTAT 00a0c3c0 1621846023    1:epa_station.d01
147    EQPIOSTAT 00a0ed10 1621846023       1:epa_line.d01

148 entries used out of 1024


Used directories:

Nr. Directory name
=============================================================================
 1: C:\Users\Public\Yokogawa\tls\dat\
 2: C:\Users\Public\Yokogawa\tls\sav\
 3: C:\Users\Public\Yokogawa\tls\his\

Enter action to do : [-1 - 4] [1]

This section shows all the user processes which have ISAM files open and contains the following fields:

  • no - sequence number of each entry

  • user - BUS/FAST queue name of the process which has the ISAM files open

  • db id - sequence number of each ISAM file open by a certain process

  • attach count - attach count of the process within BUS/FAST at the time the ISAM file was opened

  • files - flat files opened

Since this section consists of a table with an undefined number of rows, it is best to process each row as a separate event.

Defining the SMD_ISMDBG_TYPE1_REGEX regular expression
define SMD_ISMDBG_TYPE1_REGEX   /(?x)^\s*(?<No>\d+)\s*\
                                (?<User>[A-Z0-9\_]+)\s*\
                                (?<DB_ID>[a-z0-9]+)\s*\
                                (?<AttachCount>\d+)\s*\
                                (?<Files>.*)/
Files list part
 no -------file------- lck ---------------------users------------------------

=============================================================================
  0         1:item.d01  f  INT_SERVER  DSSSDAOPC  DSSSDAOPC  DSSEVT00  DSSEVT00  DSSSDA00  DSSSDA00  DSSSDA01  DSSSDA01
  1   1:item_name1.d01  f  INT_SERVER  DSSSDA01  DSSEVT00  DSSSDA01  DSSSDA01  DSSSDA01  DSSEVT00  DSSSDA00
  2   1:item_name2.d01  f  INT_SERVER  DSSSDA01  DSSEVT00

  ...

 51      1:adt_ecl.d01  f  JWUIISG  JWUIPOI02672  ALM
 52     1:epa_line.d01  f  EQPIOSTAT

53 entries used out of 800


Used directories:

Nr. Directory name
=============================================================================
 1: C:\Users\Public\Yokogawa\tls\dat\
 2: C:\Users\Public\Yokogawa\tls\sav\
 3: C:\Users\Public\Yokogawa\tls\his\

 Enter action to do : [-1 - 4] [2]

This section shows a list of the open ISAM files and contains the following fields:

  • no - sequence number of each entry

  • file - file name is displayed when the file is located in the FAST/TOOLS data directory

  • lck - the type of locking

  • users - all the processes which have the file open

Each row should be processed as a separate event like the users' list section.

Defining the SMD_ISMDBG_TYPE2_REGEX regular expression
define SMD_ISMDBG_TYPE2_REGEX   /(?x)^\s*(?<No>\d+)\s*\
                                (?<File>\d+\:.*?\.d\d+)\s*\
                                (?<Lck>\w+)\s*\
                                (?<Users>.*)/
Subscriptions header
User:  60     DSSEVT00
  Next event sequence: 1, Time of last event: 1621847151
  Flow: YES, Msg id: 4306, Timeout: 60, Next flow sequence: 21

The following fields can be parsed from the subscriptions header:

  • User

  • NextEventSequence

  • TimeOfLastEvent

  • Flow

  • MsgID

  • Timeout

  • NextFlowSequence

Defining the SMD_ISMDBG_TYPE3_REGEX regular expression
define SMD_ISMDBG_TYPE3_REGEX   /(?x)^Enter\s*action\s*to\s*do.*?\
                                (?:User[\s\:]*(?<User>.*?))\s*\
                                (?:Next\s*event\s*sequence[\s\:]*\
                                (?<NextEventSequence>\d+))[\s\,]+\
                                (?:Time\s*of\s*last\s*event[\s\:]*\
                                (?<TimeOfLastEvent>\d+))[\s\,]+\
                                (?:Flow[\s\:]*(?<Flow>.*?))[\s\,]+\
                                (?:Msg\s*id[\s\:]*(?<MsgID>\d+))[\s\,]+\
                                (?:Timeout[\s\:]*(?<Timeout>\d+))[\s\,]+\
                                (?:Next\s*flow\s*sequence[\s\:]*\
                                (?<NextFlowSequence>\d+))/
Subscriptions item
  File: item_name2.d01
    evt id: 010c1da8, Msg id: 6236, Ref id: 16222304
    Criteria: CRI_WRITE CRI_REWRITE CRI_DELETE INF_OLD_RECORD INF_NEW_RECORD

The following fields can be parsed from the subscription item:

  • File

  • EvtID

  • MsgID

  • RefID

  • Criteria

Defining the SMD_ISMDBG_TYPE31_REGEX regular expression
define SMD_ISMDBG_TYPE31_REGEX  /(?x)^\s*(?:File[\s\:]*(?<File>.*?))\s*\
                                (?:evt\s*id[\s\:]*(?<EvtID>[a-z\d]+))[\s\,]+\
                                (?:Msg\s*id[\s\:]*(?<MsgID>\d+))[\s\,]+\
                                (?:Ref\s*id[\s\:]*(?<RefID>\d+))[\s\,]+\
                                (?:Criteria[\s\:]*(?<Criteria>.*))/

The regular expressions above are defined in the configuration as constants.

Since the log file contains multi-line events in different formats, separate instances of the im_file input module are defined. The name of the corresponding input reader function is specified by the InputType directive.

Different xm_multiline module instances are used to process multi-line events as a single record. The HeaderLine and EndLine directives of this module specify a regular expression to detect the beginning and end of each multi-line event respectively.

The Exec block of each input module instance matches the log line ($raw_event) against the appropriate regular expression. Once a match occurs, the respective fields are created according to the named capturing groups.

Captured group $5 of the request part contains a timestamp in a custom date/time format, therefore it is converted to datetime using the strptime() function and then assigned to the $EventTime field.

Finally, the fields are converted to JSON format using the to_json() procedure of the xm_json module. If the log line doesn’t match any of the defined regular expressions, it is discarded using the drop() procedure.

The following NXLog configuration combines all the steps described above.

nxlog.conf
# A regular expression defined as a constant to read the content of the logs
define SMD_ISMDBG_REQ_REGEX     /(?x)^\#\#\[(?<ID>\d+)\]\[\
                                (?<Process>\w+)[\s\<\>]*\
                                (?<Commands>.*?)\]\[\
                                (?<Comment>.*?)\]\[\
                                (\d+.\d+.\d+.\d+.\d+.\d+).\d+\]/

define SMD_ISMDBG_TYPE1_REGEX   /(?x)^\s*(?<No>\d+)\s*\
                                (?<User>[A-Z0-9\_]+)\s*\
                                (?<DB_ID>[a-z0-9]+)\s*\
                                (?<AttachCount>\d+)\s*\
                                (?<Files>.*)/

define SMD_ISMDBG_TYPE2_REGEX   /(?x)^\s*(?<No>\d+)\s*\
                                (?<File>\d+\:.*?\.d\d+)\s*\
                                (?<Lck>\w+)\s*\
                                (?<Users>.*)/

define SMD_ISMDBG_TYPE3_REGEX   /(?x)^Enter\s*action\s*to\s*do.*?\
                                (?:User[\s\:]*(?<User>.*?))\s*\
                                (?:Next\s*event\s*sequence[\s\:]*\
                                (?<NextEventSequence>\d+))[\s\,]+\
                                (?:Time\s*of\s*last\s*event[\s\:]*\
                                (?<TimeOfLastEvent>\d+))[\s\,]+\
                                (?:Flow[\s\:]*(?<Flow>.*?))[\s\,]+\
                                (?:Msg\s*id[\s\:]*(?<MsgID>\d+))[\s\,]+\
                                (?:Timeout[\s\:]*(?<Timeout>\d+))[\s\,]+\
                                (?:Next\s*flow\s*sequence[\s\:]*\
                                (?<NextFlowSequence>\d+))/

define SMD_ISMDBG_TYPE31_REGEX  /(?x)^\s*(?:File[\s\:]*(?<File>.*?))\s*\
                                (?:evt\s*id[\s\:]*(?<EvtID>[a-z\d]+))[\s\,]+\
                                (?:Msg\s*id[\s\:]*(?<MsgID>\d+))[\s\,]+\
                                (?:Ref\s*id[\s\:]*(?<RefID>\d+))[\s\,]+\
                                (?:Criteria[\s\:]*(?<Criteria>.*))/

# Part of the log path defined as a constant
define LOG_PATH                 C:\Users\Public\Yokogawa\tls\log

<Extension json>
    Module      xm_json
</Extension>

<Extension multiline_type3>
    Module        xm_multiline
    # Regular expression to look for the header of the message
    HeaderLine    /(?x)^Enter\s*action\s*to\s*do[\s\:]+\[.*?\]\s*\[\d+\]\s*\
                  User[\s\:]+\d+\s*[A-Z\d]+/
    EndLine       /^\s*Flow\:\s*.+?\,/
</Extension>

<Extension multiline_type31>
    Module        xm_multiline
    # Regular expression to look for the header of the message
    HeaderLine    /^\s*File\:\s*.+?\.d\d+/
    EndLine       /^\s*Criteria\:[\sA-Z\_]+/
</Extension>

<Input from_file>
    Module        im_file
    File          '%LOG_PATH%\smd_*_ismdbg_all.log'

    <Exec>
        # Matches the events with a regular expression
        if $raw_event =~ %SMD_ISMDBG_REQ_REGEX%
        {
            # Creates the timestamp
            $EventTime = strptime($5, '%d/%m/%Y %T');
            # Formats the result as JSON
            to_json();
        }
        else if $raw_event =~ %SMD_ISMDBG_TYPE1_REGEX% or
                $raw_event =~ %SMD_ISMDBG_TYPE2_REGEX%
        {
            # Formats the result as JSON
            to_json();
        }
        # Discard event if it doesn't match a/the regular expression
        else drop();
        # Replaces unwanted characters
        $raw_event =~ s/\s{2,}/ /g;
    </Exec>
</Input>

<Input from_file_type3>
    Module        im_file
    File          '%LOG_PATH%\smd_*_ismdbg_all.log'
    InputType     multiline_type3

    <Exec>
        # Replaces unwanted characters
        $raw_event =~ s/\\n/ /g;
        $raw_event =~ s/\\r/ /g;
        $raw_event =~ s/\s{2,}/ /g;
    </Exec>

    <Exec>
        # Matches the events with a regular expression
        if $raw_event =~ %SMD_ISMDBG_TYPE3_REGEX%
        {
            # Formats the result as JSON
            to_json();
        }
        # Discard event if it doesn't match a/the regular expression
        else drop();
    </Exec>
</Input>

<Input from_file_type31>
    Module        im_file
    File          '%LOG_PATH%\smd_*_ismdbg_all.log'
    InputType     multiline_type31

    <Exec>
        # Replaces unwanted characters
        $raw_event =~ s/\\n/ /g;
        $raw_event =~ s/\\r/ /g;
        $raw_event =~ s/\s{2,}/ /g;
    </Exec>

    <Exec>
        # Matches the events with a regular expression
        if $raw_event =~ %SMD_ISMDBG_TYPE31_REGEX%
        {
            # Formats the result as JSON
            to_json();
        }
        # Discard event if it doesn't match a/the regular expression
        else drop();
    </Exec>
</Input>

The following output samples depict the processed events in JSON format.

Output sample of the request part
{
  "EventReceivedTime": "2021-05-24T02:06:49.624428-07:00",
  "SourceModuleName": "from_file",
  "SourceModuleType": "im_file",
  "Commands": "1, 2, 3, 4, -1, ",
  "Comment": "All",
  "ID": "55",
  "Process": "ismdbg",
  "EventTime": "2021-05-24T02:06:49.000000-07:00"
}
Output sample of the users' list
{
  "EventReceivedTime": "2021-05-24T02:06:49.624428-07:00",
  "SourceModuleName": "from_file",
  "SourceModuleType": "im_file",
  "AttachCount": "1621845976",
  "DB_ID": "005460b8",
  "Files": "1:item.d01 ",
  "No": "0",
  "User": "INT_SERVER"
}
Output sample of the files list
{
  "EventReceivedTime": "2021-05-24T02:06:49.624428-07:00",
  "SourceModuleName": "from_file",
  "SourceModuleType": "im_file",
  "File": "1:item.d01",
  "Lck": "f",
  "No": "0",
  "Users": "INT_SERVER DSSSDAOPC DSSSDAOPC DSSEVT00 DSSEVT00 DSSSDA00 DSSSDA00 DSSSDA01 DSSSDA01 "
}
Output sample of the subscriptions header
{
  "EventReceivedTime": "2021-05-24T02:06:49.624428-07:00",
  "SourceModuleName": "from_file_type3",
  "SourceModuleType": "im_file",
  "Flow": "YES",
  "MsgID": "4306",
  "NextEventSequence": "1",
  "NextFlowSequence": "16",
  "TimeOfLastEvent": "1621846851",
  "Timeout": "60",
  "User": "60 DSSEVT00"
}
Output sample of a subscriptions item
{
  "EventReceivedTime": "2021-05-24T02:06:49.624428-07:00",
  "SourceModuleName": "from_file_type31",
  "SourceModuleType": "im_file",
  "Criteria": "CRI_WRITE CRI_REWRITE CRI_DELETE INF_OLD_RECORD INF_NEW_RECORD ",
  "EvtID": "010c1da8",
  "File": "item_name2.d01",
  "MsgID": "6236",
  "RefID": "16222304"
}

ITH debugger log

ITH is an ITEM/FAST tool component that maintains a historical database with process signal data. The data is gathered periodically or on an event basis from the ITEM/FAST component ITM and stored in the history databases. On request, history from the databases is returned to the interrogating client.

The debug utility ITHDBG is used to examine the content of the databases or display information about an active ITH process.

Example 10. Processing ITH debugger log

According to the system monitor configuration in smdmon_config.csv, ITHDBG executes the following commands:

  • 4 - Display global info of ITHSER

ITH debugger events can be split into two parts: the request and the global info. The following is an example of each section and the regular expressions used to parse them.

Request part
##[33][ithdbg  < 0, 4, 0, ITHSER, -1, ][All][24/05/2021 05:28:30:046]

The request in this sample displays a general utility configuration and consists of the following fields:

  • ID

  • Process

  • Commands

  • Comment

  • EventTime

Defining the SMD_ITHDBG_REQ_REGEX regular expression
define SMD_ITHDBG_REQ_REGEX     /(?x)^\#\#\[(?<ID>\d+)\]\[\
                                (?<Process>\w+)[\s\<\>]*\
                                (?<Commands>.*?)\]\[\
                                (?<Comment>.*?)\]\[\
                                (\d+.\d+.\d+.\d+.\d+.\d+).\d+\]/

The request is followed by a list of commands that the ITHDBG utility can execute. This information isn’t interesting from a log collection perspective and will be excluded.

Global info part
Initialised at Mon May 24 12:17:30 2021

Statistics                  :
---------------------------------------
Total requests              : 38
Total retrieve requests     : 4
Total IIB hits              : 0
Total HIS unit-info requests: 0

Administration              :
---------------------------------------
Total IIB's                 : 0
Total IUP's                 : 0
Total IUB's                 : 0
Total UCB's                 : 0

Action (0 = help)           :  [4]
ITHDBG exit

This section displays global information about the ITHSER process and contains the following fields:

  • Initialised_at

  • TotalRequests

  • TotalRetrieveRequests

  • TotalIIBHits

  • TotalHISUnitInfoRequests

  • TotalIIBs

  • TotalIUPs

  • TotalIUBs

  • TotalUCBs

Defining the SMD_ITHDBG_ITHSER_REGEX regular expression
define SMD_ITHDBG_ITHSER_REGEX  /(?x)^Initialised\s*at\s*\
                                (\w+\s*\w+\s*\d+\s*\d+.\d+.\d+\s*\d+)\s*\
                                Statistics[\s\:\-]*\
                                (?:Total\s*requests[\s\:]*\
                                (?<TotalRequests>\d+))\s*\
                                (?:Total\s*retrieve\s*requests[\s\:]*\
                                (?<TotalRetrieveRequests>\d+))\s*\
                                (?:Total\s*IIB\s*hits[\s\:]*\
                                (?<TotalIIBHits>\d+))\s*\
                                (?:Total\s*HIS\s*unit\-info\s*requests[\s\:]*\
                                (?<TotalHISUnitInfoRequests>\d+))\s*\
                                Administration[\s\:\-]*\
                                (?:Total\s*IIB\'s[\s\:]*(?<TotalIIBs>\d+))\s*\
                                (?:Total\s*IUP\'s[\s\:]*(?<TotalIUPs>\d+))\s*\
                                (?:Total\s*IUB\'s[\s\:]*(?<TotalIUBs>\d+))\s*\
                                (?:Total\s*UCB\'s[\s\:]*(?<TotalUCBs>\d+))\s*\
                                Action.*\s*ITHDBG\s*exit/

The regular expressions above are defined in the configuration as constants.

Since the log file contains both single-line and multi-line events, separate instances of the im_file input module are defined.

The xm_multiline extension module is used to process multi-line events as a single record. The HeaderLine and the EndLine directives of this module specify a regular expression to detect the beginning and end of each multi-line event respectively.

The Exec block of each input module instance matches the log line ($raw_event) against the appropriate regular expression. Once a match occurs, the respective fields are created according to the named capturing groups.

Since captured group $5 of the request part contains a timestamp in a custom date/time format, it is converted to datetime using the strptime() function and then assigned to the $EventTime field.

Finally, the fields are converted to JSON format using the to_json() procedure of the xm_json extension module. If the log line does not match any of the defined regular expressions, it is discarded using the drop() procedure.

The following NXLog configuration combines all the steps described above.

nxlog.conf
# A regular expression defined as a constant to read the content of the logs
define SMD_ITHDBG_REQ_REGEX     /(?x)^\#\#\[(?<ID>\d+)\]\[\
                                (?<Process>\w+)[\s\<\>]*\
                                (?<Commands>.*?)\]\[\
                                (?<Comment>.*?)\]\[\
                                (\d+.\d+.\d+.\d+.\d+.\d+).\d+\]/

define SMD_ITHDBG_ITHSER_REGEX  /(?x)^Initialised\s*at\s*\
                                (\w+\s*\w+\s*\d+\s*\d+.\d+.\d+\s*\d+)\s*\
                                Statistics[\s\:\-]*\
                                (?:Total\s*requests[\s\:]*\
                                (?<TotalRequests>\d+))\s*\
                                (?:Total\s*retrieve\s*requests[\s\:]*\
                                (?<TotalRetrieveRequests>\d+))\s*\
                                (?:Total\s*IIB\s*hits[\s\:]*\
                                (?<TotalIIBHits>\d+))\s*\
                                (?:Total\s*HIS\s*unit\-info\s*requests[\s\:]*\
                                (?<TotalHISUnitInfoRequests>\d+))\s*\
                                Administration[\s\:\-]*\
                                (?:Total\s*IIB\'s[\s\:]*(?<TotalIIBs>\d+))\s*\
                                (?:Total\s*IUP\'s[\s\:]*(?<TotalIUPs>\d+))\s*\
                                (?:Total\s*IUB\'s[\s\:]*(?<TotalIUBs>\d+))\s*\
                                (?:Total\s*UCB\'s[\s\:]*(?<TotalUCBs>\d+))\s*\
                                Action.*\s*ITHDBG\s*exit/

# Part of the log path defined as a constant
define LOG_PATH                 C:\Users\Public\Yokogawa\tls\log

<Extension json>
    Module      xm_json
</Extension>

<Extension multiline_ithser>
    Module      xm_multiline
    # Regular expression to look for the header of the message
    HeaderLine  /^Initialised\s*at\s*(\w+\s*\w+\s*\d+\s*\d+.\d+.\d+\s*\d+)/
    EndLine     /^ITHDBG\s*exit/
</Extension>

<Input from_file>
    Module      im_file
    File        '%LOG_PATH%\smd_*_ithdbg_all.log'

    <Exec>
        # Matches the events with a regular expression
        if $raw_event =~ %SMD_ITHDBG_REQ_REGEX%
        {
            # Creates the timestamp
            $EventTime = strptime($5, '%d/%m/%Y %T');
            # Formats the result as JSON
            to_json();
        }
        # Discard event if it doesn't match a/the regular expression
        else drop();
        # Replaces unwanted characters
        $raw_event =~ s/\s{2,}/ /g;
    </Exec>
</Input>

<Input from_file_ithser>
    Module      im_file
    File        '%LOG_PATH%\smd_*_ithdbg_all.log'
    InputType   multiline_ithser

    <Exec>
        # Replaces unwanted characters
        $raw_event =~ s/\\n/ /g;
        $raw_event =~ s/\\r/ /g;
        $raw_event =~ s/\s{2,}/ /g;
    </Exec>

    <Exec>
        # Matches the events with a regular expression
        if $raw_event =~ %SMD_ITHDBG_ITHSER_REGEX%
        {
            # Creates the timestamp
            $Initialised_at = parsedate($1);
            # Formats the result as JSON
            to_json();
        }
        # Discard event if it doesn't match a/the regular expression
        else drop();
    </Exec>
</Input>

The following output samples depict the processed events in JSON format.

Output sample of the request part
{
  "EventReceivedTime": "2021-05-24T05:28:30.468275-07:00",
  "SourceModuleName": "from_file",
  "SourceModuleType": "im_file",
  "Commands": "0, 4, 0, ITHSER, -1, ",
  "Comment": "All",
  "ID": "33",
  "Process": "ithdbg",
  "EventTime": "2021-05-24T05:28:30.000000-07:00"
}
Output sample of the global info part
{
  "EventReceivedTime": "2021-05-24T05:28:30.468275-07:00",
  "SourceModuleName": "from_file_ithser",
  "SourceModuleType": "im_file",
  "TotalHISUnitInfoRequests": "0",
  "TotalIIBHits": "0",
  "TotalIIBs": "0",
  "TotalIUBs": "0",
  "TotalIUPs": "0",
  "TotalRequests": "38",
  "TotalRetrieveRequests": "4",
  "TotalUCBs": "0",
  "Initialised_at": "2021-05-24T12:17:30.000000-07:00"
}

ITM debugger log

ITM is a component of the ITEM/FAST tool, which maintains a real-time database with process signal data. The data that fills the database can be distributed over the system.

The ITM debugger ITMDBG is a utility that can be used to look in the ITM common data area. The utility can analyze information blocks and request statistical information. It can save all common data info to disk for an up-to-date warm restart.

Example 11. Processing ITM debugger log

The following commands are specified for the ITMDBG utility in the system monitor configuration file smdmon_config.csv:

  • 2 - Statistics

  • 6 - Main actions info

  • 7 - Task table

  • 8 - Event buffers

  • 14 - Flow control

  • 17 - Locked items

ITM debugger events can be split into several parts. The following is an example of each section and the regular expressions used to parse them.

Request part
##[121][itmdbg  < 2, 6, 7, 8, 14, 17, -1, ][All][25/05/2021 03:18:22:282]

The first part is a header of the event, which contains the request information. It consists of the following fields:

  • ID

  • Process

  • Commands

  • Comment

  • EventTime

Defining the SMD_ITMDBG_REQ_REGEX regular expression
define SMD_ITMDBG_REQ_REGEX     /(?x)^\#\#\[(?<ID>\d+)\]\[\
                                (?<Process>\w+)[\s\<\>]*\
                                (?<Commands>.*?)\]\[\
                                (?<Comment>.*?)\]\[\
                                (\d+.\d+.\d+.\d+.\d+.\d+).\d+\]/
Statistics part
-- Show statistics --

common size   =    10240000 bytes       free size     =     9991848 bytes
fragments     =           1             biggest       =     9991848 bytes
max_groups    =          20             max_number    =       60000
max_appl_info =           0             max_upd_info  =         512
nr of items   =          10             integr. secs  =           1

save mode     = item base
                               total   last 0 seconds     per second
-----------------------------------------------------------------------
        item updates           22390              0              0
    sub item updates               0              0              0
   attribute updates               0              0              0
         single gets              27              0              0
  multiple get calls               0              0              0
  multiple get items               0              0              0
   direct dur events               2              0              0
     buffered events            4511              0              0
 buffered dur events            2157              0              0
   autom. item saves           22390              0              0
  flow control msg's              82              0              0
   audit fast events               0              0              0
 audit fast messages               0              0              0

Give code (0 = help) :  [2]

Command 2 (statistics) returns the statistics overview. The overview contains values of parameters, and a list of actions since system and program start-up. The parameters are:

  • common size - Size of data of the common area in bytes

  • free size - Size of the common area not yet used

  • fragments - Number of free fragments

  • biggest - Biggest free fragment

  • max_groups - Configured number of item groups

  • max_number - Configured number of items per group

  • max_appl_info - Configured application info size

  • max_upd_info - Configured update information size

  • nr of items - Actual number of items defined

  • integr. secs - Configured integration period

The actions are:

  • item updates - Number of times an item is updated

  • sub-item updates - Number of times a sub-item is updated

  • attribute updates - Number of times a limit/deadband is updated

  • single gets - Number of itm_val_sta requests

  • multiple get calls - Number of itm_mval_sta requests

  • multiple get items - Number of items in these previous calls

  • direct dur events - Number of event messages sent directly

  • buffered events - Number of events stored in the allocated buffer

  • buffered dur events - Number of filled buffers sent

  • autom. item saves - Number of automatic items saves to disk

  • flow control msg’s - Number of flow control messages sent

  • audit fast events - Number of audit fast events created

  • audit fast messages - Number of audit fast event buffers sent

Defining the SMD_ITMDBG_STAT_REGEX regular expression.
define SMD_ITMDBG_STAT_REGEX    /(?x)^[\s\-]*Show\s*statistics[\s\-]*\
                                (?:common\s*size[\s\=]*(?<CommonSize>.*?))\s*\
                                (?:free\s*size[\s\=]*(?<FreeSize>.*?))\s*\
                                (?:fragments[\s\=]*(?<Fragments>\d+))\s*\
                                (?:biggest[\s\=]*(?<Biggest>.*?))\s*\
                                (?:max_groups[\s\=]*(?<MaxGroups>\d+))\s*\
                                (?:max_number[\s\=]*(?<MaxNumber>\d+))\s*\
                                (?:max_appl_info[\s\=]*(?<MaxapplInfo>\d+))\s*\
                                (?:max_upd_info[\s\=]*(?<MaxUpdInfo>\d+))\s*\
                                (?:nr\s*of\s*items[\s\=]*(?<NrOfItems>\d+))\s*\
                                (?:integr\.\s*secs[\s\=]*(?<IntegrSecs>\d+))\s*\
                                (?:save\s*mode[\s\=]*(?<SaveMode>.*?))\s*\
                                total.*[\s\-]*(?:item\s*updates\s*\
                                (?<ItemUpdates_Total>\d+)\s*\
                                (?<ItemUpdates_Last0Seconds>\d+)\s*\
                                (?<ItemUpdates_PerSecond>\d*))\s*\
                                (?:sub\s*item\s*updates\s*\
                                (?<SubItemUpdates_Total>\d+)\s*\
                                (?<SubItemUpdates_Last0Seconds>\d+)\s*\
                                (?<SubItemUpdates_Persecond>\d*))\s*\
                                (?:attribute\s*updates\s*\
                                (?<AttributeUpdates_Total>\d+)\s*\
                                (?<AttributeUpdates_Last0Seconds>\d+)\s*\
                                (?<AttributeUpdates_PerSecond>\d+))\s*\
                                (?:single\s*gets\s*(?<SingleGets_Total>\d+)\s*\
                                (?<SingleGets_Last0Seconds>\d+)\s*\
                                (?<SingleGets_PerSeconds>\d+))\s*\
                                (?:multiple\s*get\s*calls\s*\
                                (?<MultipleGetCalls_Total>\d+)\s+\
                                (?<MultipleGetCalls_LastoSeconds>\d+)\s*\
                                (?<MultipleGetCalls_PerSecond>\d+))\s*\
                                (?:multiple\s*get\s*items\s*\
                                (?<MultipleGetItems_Total>\d+)\s*\
                                (?<MultipleGetItems_Last0Seconds>\d+)\s*\
                                (?<MultipleGetItems_PerSecond>\d+))\s*\
                                (?:direct\s*dur\s*events\s*\
                                (?<DirectDurEvents_Total>\d+)\s*\
                                (?<DirectDurEvents_Last0Seconds>\d+)\s*\
                                (?<DirectDurEvents_PerSecond>\d+))\s*\
                                (?:buffered\s*events\s*\
                                (?<BufferedEvents_Total>\d+)\s*\
                                (?<BufferedEvents_Last0Seconds>\d+)\s*\
                                (?<BufferedEvents_PerSecond>\d+))\s*\
                                (?:buffered\s*dur\s*events\s*\
                                (?<BufferedDurEvents_Total>\d+)\s*\
                                (?<BufferedDurEvents_Last0Seconds>\d+)\s*\
                                (?<BufferedDurEvents_PerSecond>\d+))\s*\
                                (?:autom\.\s*item\s*saves\s*\
                                (?<AutomItemSaves_Total>\d+)\s*\
                                (?<AutomItemSaves_Last0Seconds>\d+)\s*\
                                (?<AutomItemSaves_PerSecond>\d+))\s*\
                                (?:flow\s*control\s*msg\'s\s*\
                                (?<FlowControlMsgs>\d+)\s*\
                                (?<FlowControlMsgs_Last0Seconds>\d+)\s*\
                                (?<FlowControlMsgs_PerSecond>\d+))\s*\
                                (?:audit\s*fast\s*events\s*\
                                (?<AuditFastEvents_Total>\d+)\s*\
                                (?<AuditFastEvents_Last0seconds>\d+)\s*\
                                (?<AuditFastEvents_Persecond>\d+))\s*\
                                (?:audit\s*fast\s*messages\s*\
                                (?<AuditFastMessages_Total>\d+)\s*\
                                (?<AuditFastMessages_Last0Seconds>\d+)\s*\
                                (?<AuditFastMessages_PerSeconds>\d+))\s*\
                                Give\s*code.*/
Main action info part
-- Display main actions --

evt_b  crit_m   process         evt_l      flags  msg_id  evt_buf  flow
-----------------------------------------------------------------------
 0001   0309    1,ALM            0000a98f   0001      1    No      No

Give code (0 = help) :  [6]

Command 6 shows a list of all main actions. For each main action block, the following information is shown:

  • evt_b - Event bit mask (= key)

  • crit_m - Criterion mask specified by the caller

  • process - Node number and process name of the caller

  • evt_l - Event layout specified by caller

  • flags - Flags field of the action block

  • msg_id - Message ID specified by the caller

  • evt_buf - Yes, if events should be buffered

  • flow - Yes, if flow control selected

Defining the SMD_ITMDBG_MAINACT_REGEX
define SMD_ITMDBG_MAINACT_REGEX /(?x)^\s*(?<Evt_b>\d+)\s+\
                                (?<Crit_m>\d+)\s+\
                                (?<Process>\d+\,\w+)\s+\
                                (?<Evt_l>\w+)\s+\
                                (?<Flags>\d+)\s+\
                                (?<MsgID>\d+)\s+\
                                (?<EvtBuff>[a-zA-Z]+)\s+\
                                (?<Flow>[a-zA-Z]+)$/
Task table
-- Display task table --

 adress     adr.name        evt_l      u_cnt  evtbuf  flow  flags
-----------------------------------------------------------------
5203c930    1,WFLIDI         0000ba2d      2   Yes     Yes    0002
5203c904    1,WFLIDI         0000b22d      0   Yes     Yes    0002
520004b4    1,EQPMDC         000020ab      1   No      No     0002

Give code (0 = help) :  [7]

The task table contains a list of all processes waiting for item modification events. The fields in this section are:

  • address - Address in the common area of this process info

  • adr.name - Node number and name of the process

  • evt_l - Event layout as specified by the process

  • u_cnt - Number of events for this process

  • evtbuf - Yes, if events should be stored in the event buffer

  • flow - Yes, if flow control selected

  • flags - Internal flags

Defining the SMD_ITMDBG_TASKTAB_REGEX regular expression
define SMD_ITMDBG_TASKTAB_REGEX /(?x)^(?<Address>\w+)\s+\
                                (?<AdrName>\d+\,\w+)\s+\
                                (?<Evt_l>\w+)\s+\
                                (?<U_cnt>\d+)\s+\
                                (?<EvtBuf>[a-zA-Z]+)\s+\
                                (?<Flow>[a-zA-Z]+)\s+\
                                (?<Flags>\d+)$/
Event buffers part
-- Display event buffers --

 address    adr.name       m_len  u_len  u_cnt  evt_f  t_cnt  tics  flags
-------------------------------------------------------------------------
5203c4e0    1,WFLIDI        1000      0      2      0    100   100  0000
5203c090    1,OPCEXE        1000      0      0      0    100   100  0004
52000754    1,ITHEIX         960      0      0      0   1000   235  0004
52000538    1,ITHEEX         480      0      0      0   1000   235  0004

Give code (0 = help) :  [8]

With the event buffers request, a list of all allocated event buffers can be generated. The following fields are shown in this section:

  • adr.name - Process which allocated this buffer

  • m_len - Buffer size allocated

  • u_len - Actual size used

  • u_cnt - Number of event requests related to this buffer

  • evt_f - Event flag to be set if first entry in buffer

  • t_cnt - Maximum storage time (m_sec)

  • tics - Time left till next send

  • flags - Internal flags

Defining the SMD_ITMDBG_EVBUF_REGEX regular expression
define SMD_ITMDBG_EVBUF_REGEX   /(?x)^(?<Address>[\d\w]+)\s+\
                                (?<AdrName>\d+\,[A-Z\d\_]+)\s+\
                                (?<M_len>\d+)\s+\
                                (?<U_len>\d+)\s+\
                                (?<U_cnt>\d+)\s+\
                                (?<Evt_f>\d+)\s+\
                                (?<T_cnt>\d+)\s+\
                                (?<Tics>\d+)\s+\
                                (?<Flags>\d+)$/
Flow control blocks part
-- Display flow control blocks --

actual time = 1621937902

 address   adr.name          evt_seq  flw_seq  last_time  max_time  msgid
-------------------------------------------------------------------------
5203c4b4   1,WFLIDI             4511        3 1621937901        30   2000
5203c064   1,OPCEXE                0       79 1621937895        30   1000

Give code (0 = help) :  [14]

With command code 14, ITMDBG can display the flow control list. The following fields are shown in this section:

  • address - Address of the flow control block

  • adr.name - Process requesting flow control

  • evt_seq - Number of events sent since connect

  • flw_seq - Number of flow control messages since connect

  • last_time - Time of last event or flow message sent

  • max_time - Maximum time allowed between messages

  • msgid - Message ID specified by the caller

Defining the SMD_ITMDBG_FLOW_REGEX regular expression
define SMD_ITMDBG_FLOW_REGEX    /(?x)^(?<Address>\w+)\s+\
                                (?<AdrName>\d+\,\w+)\s+\
                                (?<EvtSeq>\d+)\s+\
                                (?<FlwSeq>\d+)\s+\
                                (?<LastTime>\d+)\s+\
                                (?<MaxTime>\d+)\s+\
                                (?<Msgid>\d+)$/

The regular expressions above are defined in the configuration as constants.

Since the log file requires processing of both single-line and multi-line events, separate instances of the im_file input module are defined.

The xm_multiline extension module is used to process multi-line events as a single record. The HeaderLine and the EndLine directives of this module specify a regular expression to detect the beginning and end of each multi-line event respectively.

The Exec block of each input module instance matches the log line ($raw_event) against the appropriate regular expression. Once a match occurs, the respective fields are created according to the named capturing groups.

Since captured group $5 of the request event contains a timestamp in a custom date/time format, it is converted to datetime using the strptime() function and then assigned to the $EventTime field.

Finally, the fields are converted to JSON format using the to_json() procedure of the xm_json module. If the log line does not match any of the defined regular expressions, it is discarded using the drop() procedure.

The following NXLog configuration combines all the steps described above.

nxlog.conf
# A regular expression defined as a constant to read the content of the logs
define SMD_ITMDBG_REQ_REGEX     /(?x)^\#\#\[(?<ID>\d+)\]\[\
                                (?<Process>\w+)[\s\<\>]*\
                                (?<Commands>.*?)\]\[\
                                (?<Comment>.*?)\]\[\
                                (\d+.\d+.\d+.\d+.\d+.\d+).\d+\]/

define SMD_ITMDBG_STAT_REGEX    /(?x)^[\s\-]*Show\s*statistics[\s\-]*\
                                (?:common\s*size[\s\=]*(?<CommonSize>.*?))\s*\
                                (?:free\s*size[\s\=]*(?<FreeSize>.*?))\s*\
                                (?:fragments[\s\=]*(?<Fragments>\d+))\s*\
                                (?:biggest[\s\=]*(?<Biggest>.*?))\s*\
                                (?:max_groups[\s\=]*(?<MaxGroups>\d+))\s*\
                                (?:max_number[\s\=]*(?<MaxNumber>\d+))\s*\
                                (?:max_appl_info[\s\=]*(?<MaxapplInfo>\d+))\s*\
                                (?:max_upd_info[\s\=]*(?<MaxUpdInfo>\d+))\s*\
                                (?:nr\s*of\s*items[\s\=]*(?<NrOfItems>\d+))\s*\
                                (?:integr\.\s*secs[\s\=]*(?<IntegrSecs>\d+))\s*\
                                (?:save\s*mode[\s\=]*(?<SaveMode>.*?))\s*\
                                total.*[\s\-]*(?:item\s*updates\s*\
                                (?<ItemUpdates_Total>\d+)\s*\
                                (?<ItemUpdates_Last0Seconds>\d+)\s*\
                                (?<ItemUpdates_PerSecond>\d*))\s*\
                                (?:sub\s*item\s*updates\s*\
                                (?<SubItemUpdates_Total>\d+)\s*\
                                (?<SubItemUpdates_Last0Seconds>\d+)\s*\
                                (?<SubItemUpdates_Persecond>\d*))\s*\
                                (?:attribute\s*updates\s*\
                                (?<AttributeUpdates_Total>\d+)\s*\
                                (?<AttributeUpdates_Last0Seconds>\d+)\s*\
                                (?<AttributeUpdates_PerSecond>\d+))\s*\
                                (?:single\s*gets\s*(?<SingleGets_Total>\d+)\s*\
                                (?<SingleGets_Last0Seconds>\d+)\s*\
                                (?<SingleGets_PerSeconds>\d+))\s*\
                                (?:multiple\s*get\s*calls\s*\
                                (?<MultipleGetCalls_Total>\d+)\s+\
                                (?<MultipleGetCalls_LastoSeconds>\d+)\s*\
                                (?<MultipleGetCalls_PerSecond>\d+))\s*\
                                (?:multiple\s*get\s*items\s*\
                                (?<MultipleGetItems_Total>\d+)\s*\
                                (?<MultipleGetItems_Last0Seconds>\d+)\s*\
                                (?<MultipleGetItems_PerSecond>\d+))\s*\
                                (?:direct\s*dur\s*events\s*\
                                (?<DirectDurEvents_Total>\d+)\s*\
                                (?<DirectDurEvents_Last0Seconds>\d+)\s*\
                                (?<DirectDurEvents_PerSecond>\d+))\s*\
                                (?:buffered\s*events\s*\
                                (?<BufferedEvents_Total>\d+)\s*\
                                (?<BufferedEvents_Last0Seconds>\d+)\s*\
                                (?<BufferedEvents_PerSecond>\d+))\s*\
                                (?:buffered\s*dur\s*events\s*\
                                (?<BufferedDurEvents_Total>\d+)\s*\
                                (?<BufferedDurEvents_Last0Seconds>\d+)\s*\
                                (?<BufferedDurEvents_PerSecond>\d+))\s*\
                                (?:autom\.\s*item\s*saves\s*\
                                (?<AutomItemSaves_Total>\d+)\s*\
                                (?<AutomItemSaves_Last0Seconds>\d+)\s*\
                                (?<AutomItemSaves_PerSecond>\d+))\s*\
                                (?:flow\s*control\s*msg\'s\s*\
                                (?<FlowControlMsgs>\d+)\s*\
                                (?<FlowControlMsgs_Last0Seconds>\d+)\s*\
                                (?<FlowControlMsgs_PerSecond>\d+))\s*\
                                (?:audit\s*fast\s*events\s*\
                                (?<AuditFastEvents_Total>\d+)\s*\
                                (?<AuditFastEvents_Last0seconds>\d+)\s*\
                                (?<AuditFastEvents_Persecond>\d+))\s*\
                                (?:audit\s*fast\s*messages\s*\
                                (?<AuditFastMessages_Total>\d+)\s*\
                                (?<AuditFastMessages_Last0Seconds>\d+)\s*\
                                (?<AuditFastMessages_PerSeconds>\d+))\s*\
                                Give\s*code.*/

define SMD_ITMDBG_MAINACT_REGEX /(?x)^\s*(?<Evt_b>\d+)\s+\
                                (?<Crit_m>\d+)\s+\
                                (?<Process>\d+\,\w+)\s+\
                                (?<Evt_l>\w+)\s+\
                                (?<Flags>\d+)\s+\
                                (?<MsgID>\d+)\s+\
                                (?<EvtBuff>[a-zA-Z]+)\s+\
                                (?<Flow>[a-zA-Z]+)$/

define SMD_ITMDBG_TASKTAB_REGEX /(?x)^(?<Address>\w+)\s+\
                                (?<AdrName>\d+\,\w+)\s+\
                                (?<Evt_l>\w+)\s+\
                                (?<U_cnt>\d+)\s+\
                                (?<EvtBuf>[a-zA-Z]+)\s+\
                                (?<Flow>[a-zA-Z]+)\s+\
                                (?<Flags>\d+)$/

define SMD_ITMDBG_EVBUF_REGEX   /(?x)^(?<Address>[\d\w]+)\s+\
                                (?<AdrName>\d+\,[A-Z\d\_]+)\s+\
                                (?<M_len>\d+)\s+\
                                (?<U_len>\d+)\s+\
                                (?<U_cnt>\d+)\s+\
                                (?<Evt_f>\d+)\s+\
                                (?<T_cnt>\d+)\s+\
                                (?<Tics>\d+)\s+\
                                (?<Flags>\d+)$/

define SMD_ITMDBG_FLOW_REGEX    /(?x)^(?<Address>\w+)\s+\
                                (?<AdrName>\d+\,\w+)\s+\
                                (?<EvtSeq>\d+)\s+\
                                (?<FlwSeq>\d+)\s+\
                                (?<LastTime>\d+)\s+\
                                (?<MaxTime>\d+)\s+\
                                (?<Msgid>\d+)$/

# Part of the log path defined as a constant
define LOG_PATH                 C:\Users\Public\Yokogawa\tls\log

<Extension json>
    Module        xm_json
</Extension>

<Extension multiline_stat>
    Module        xm_multiline
    # Regular expression to look for the header of the message
    HeaderLine    /^\-*\s*Show\s*statistics\s*\-*/
    EndLine       /^Give\s*code.*\[2\]\s*/
</Extension>

<Input from_file>
    Module        im_file
    File          '%LOG_PATH%\smd_*_itmdbg_all.log'

    <Exec>
        # Matches the events with a regular expression
        if $raw_event =~ %SMD_ITMDBG_REQ_REGEX%
        {
            # Creates the timestamp
            $EventTime = strptime($5, '%d/%m/%Y %T');
            # Formats the result as JSON
            to_json();
        }
        else if $raw_event =~ %SMD_ITMDBG_MAINACT_REGEX% or
                $raw_event =~ %SMD_ITMDBG_TASKTAB_REGEX% or
                $raw_event =~ %SMD_ITMDBG_EVBUF_REGEX% or
                $raw_event =~ %SMD_ITMDBG_FLOW_REGEX%
        {
            # Formats the result as JSON
            to_json();
        }
        # Discard event if it doesn't match a/the regular expression
        else drop();
        # Replaces unwanted characters
        $raw_event =~ s/\s{2,}/ /g;
    </Exec>
</Input>

<Input from_file_stat>
    Module        im_file
    File          '%LOG_PATH%\smd_*_itmdbg_all.log'
    InputType     multiline_stat

    <Exec>
        # Replaces unwanted characters
        $raw_event =~ s/\\n/ /g;
        $raw_event =~ s/\\r/ /g;
        $raw_event =~ s/\s{2,}/ /g;
    </Exec>

    <Exec>
        # Matches the events with a regular expression
        if $raw_event =~ %SMD_ITMDBG_STAT_REGEX%
        {
            # Formats the result as JSON
            to_json();
        }
        # Discard event if it doesn't match a/the regular expression
        else drop();
    </Exec>
</Input>

The following output samples depict the processed events in JSON format.

Output sample of the request part
{
  "EventReceivedTime": "2021-05-25T03:18:22.970592-07:00",
  "SourceModuleName": "from_file",
  "SourceModuleType": "im_file",
  "Commands": "2, 6, 7, 8, 14, 17, -1, ",
  "Comment": "All",
  "ID": "121",
  "Process": "itmdbg",
  "EventTime": "2021-05-25T03:18:22.000000-07:00"
}
Output sample of the statistics part
{
  "EventReceivedTime": "2021-05-25T03:18:22.970592-07:00",
  "SourceModuleName": "from_file_stat",
  "SourceModuleType": "im_file",
  "AttributeUpdates_Last0Seconds": "0",
  "AttributeUpdates_PerSecond": "0",
  "AttributeUpdates_Total": "0",
  "AuditFastEvents_Last0seconds": "0",
  "AuditFastEvents_Persecond": "0",
  "AuditFastEvents_Total": "0",
  "AuditFastMessages_Last0Seconds": "0",
  "AuditFastMessages_PerSeconds": "0",
  "AuditFastMessages_Total": "0",
  "AutomItemSaves_Last0Seconds": "0",
  "AutomItemSaves_PerSecond": "0",
  "AutomItemSaves_Total": "22390",
  "Biggest": "9991848 bytes",
  "BufferedDurEvents_Last0Seconds": "0",
  "BufferedDurEvents_PerSecond": "0",
  "BufferedDurEvents_Total": "2157",
  "BufferedEvents_Last0Seconds": "0",
  "BufferedEvents_PerSecond": "0",
  "BufferedEvents_Total": "4511",
  "CommonSize": "10240000 bytes",
  "DirectDurEvents_Last0Seconds": "0",
  "DirectDurEvents_PerSecond": "0",
  "DirectDurEvents_Total": "2",
  "FlowControlMsgs": "82",
  "FlowControlMsgs_Last0Seconds": "0",
  "FlowControlMsgs_PerSecond": "0",
  "Fragments": "1",
  "FreeSize": "9991848 bytes",
  "IntegrSecs": "1",
  "ItemUpdates_Last0Seconds": "0",
  "ItemUpdates_PerSecond": "0",
  "ItemUpdates_Total": "22390",
  "MaxGroups": "20",
  "MaxNumber": "60000",
  "MaxUpdInfo": "512",
  "MaxapplInfo": "0",
  "MultipleGetCalls_LastoSeconds": "0",
  "MultipleGetCalls_PerSecond": "0",
  "MultipleGetCalls_Total": "0",
  "MultipleGetItems_Last0Seconds": "0",
  "MultipleGetItems_PerSecond": "0",
  "MultipleGetItems_Total": "0",
  "NrOfItems": "10",
  "SaveMode": "item base",
  "SingleGets_Last0Seconds": "0",
  "SingleGets_PerSeconds": "0",
  "SingleGets_Total": "27",
  "SubItemUpdates_Last0Seconds": "0",
  "SubItemUpdates_Persecond": "0",
  "SubItemUpdates_Total": "0"
}
Output sample of the main actions part
{
  "EventReceivedTime": "2021-05-25T03:18:22.970592-07:00",
  "SourceModuleName": "from_file",
  "SourceModuleType": "im_file",
  "Crit_m": "0309",
  "EvtBuff": "No",
  "Evt_b": "0001",
  "Evt_l": "0000a98f",
  "Flags": "0001",
  "Flow": "No",
  "MsgID": "1",
  "Process": "1,ALM"
}
Output sample of the task table
{
  "EventReceivedTime": "2021-05-25T03:18:22.986157-07:00",
  "SourceModuleName": "from_file",
  "SourceModuleType": "im_file",
  "Address": "5203c930",
  "AdrName": "1,WFLIDI",
  "EvtBuf": "Yes",
  "Evt_l": "0000ba2d",
  "Flags": "0002",
  "Flow": "Yes",
  "U_cnt": "2"
}
Output sample of the event buffers part
{
  "EventReceivedTime": "2021-05-25T03:18:22.986157-07:00",
  "SourceModuleName": "from_file",
  "SourceModuleType": "im_file",
  "Address": "5203c4e0",
  "AdrName": "1,WFLIDI",
  "Evt_f": "0",
  "Flags": "0000",
  "M_len": "1000",
  "T_cnt": "100",
  "Tics": "100",
  "U_cnt": "2",
  "U_len": "0"
}
Output sample of the flow control blocks part
{
  "EventReceivedTime": "2021-05-25T03:18:22.986157-07:00",
  "SourceModuleName": "from_file",
  "SourceModuleType": "im_file",
  "Address": "5203c4b4",
  "AdrName": "1,WFLIDI",
  "EvtSeq": "4511",
  "FlwSeq": "3",
  "LastTime": "1621937901",
  "MaxTime": "30",
  "Msgid": "2000"
}

OPC debugger log

The OPC debugger is used to resolve possible problems found at run-time or during configuration of PROCESS/FAST, which is a member of the FAST/TOOLS collection.

The OPCDBG utility gathers performance characteristics of objects, checking and repairing inconsistencies in the OPC data store. It can also be used to maintain trigger groups, classes, and objects for this purpose.

Example 12. Processing OPC debugger log

The following actions are listed for the OPCDBG utility in the system monitor configuration file smdmon_config.csv:

  • 0 - Help

  • 4 - Performance

    • 1 - Obtain main info

    • 10 - Class execution top 10

    • 11 - Object execution top 10

OPC debugger events can be split into two parts: the request and the main info. The following is an example of each section and the regular expressions used to parse them.

Request part
##[13][opcdbg  < 0, 4, 0, OPCEXE, 1, 10, 10, 11, 10, -1, -1, ][All][25/05/2021 13:09:59:469]

The following fields can be parsed from the request:

  • ID

  • Process

  • Commands

  • Comment

  • EventTime

Defining the SMD_OPCDBG_REQ_REGEX regular expression
define SMD_OPCDBG_REQ_REGEX     /(?x)^\#\#\[(?<ID>\d+)\]\[\
                                (?<Process>\w+)[\s\<\>]*\
                                (?<Commands>.*?)\]\[\
                                (?<Comment>.*?)\]\[\
                                (\d+.\d+.\d+.\d+.\d+.\d+).\d+\]/
Main info part
OPC excutor process (node,name) : 0, OPCEXE
Activation time : 1621973037 (= 25-05-2021 20:03:57)
Number of active classes : 0
Number of active objects : 0
Number of active trigger groups : 0
Number of active items : 0
Number of ready to execute objects : 0
Number of free ready to execute locations : 0
Statistics :
  Number of object executions : 0
  Total excution time (msec) : 0
  Average execution time (msec) : 0
  Fastest execution time (msec) : -1
  for object id (sec.seq) : 0.0
  Slowest execution time (msec) : 0
  for object id (sec.seq) : 0.0

PERFORMANCE: Enter action to do : [-1 - 11] [1]

The "Obtain main info" action retrieves general statistics from the specified OPCEXE process. Information includes the location, name, and start time of the process, class, object, trigger info, and execution statistics.

Defining the SMD_OPCDBG_MAIN_REGEX regular expression
define SMD_OPCDBG_MAIN_REGEX    /(?x)^(?:OPC\s*excutor\s*process\s*\
                                \(node\,name\)[\s\:]+\
                                (?<OPC_ExcutorProcess>.*?))\s*\
                                (?:Activation\s*time[\s\:]+\
                                (?<ActivationTime>.*?))\s*\
                                (?:Number\s*of\s*active\s*classes[\s\:]+\
                                (?<NumOfActiveClasses>\d+))\s*\
                                (?:Number\s*of\s*active\s*objects[\s\:]+\
                                (?<NumOfActiveObjects>\d+))\s*\
                                (?:Number\s*of\s*active\s*trigger\s*groups[\s\:]+\
                                (?<NumOfActiveTriggerGroups>\d+))\s*\
                                (?:Number\s*of\s*active\s*items[\s\:]+\
                                (?<NumOfActiveItems>\d+))\s*\
                                (?:Number\s*of\s*ready\s*to\s*\
                                execute\s*objects[\s\:]+\
                                (?<NumOfReadyToExecObjects>\d+))\s*\
                                (?:Number\s*of\s*free\s*ready\s*to\s*\
                                execute\s*locations[\s\:]+\
                                (?<NumOfFreeReadyToExecLocations>\d+))\s*\
                                Statistics[\s\:]+\
                                (?:Number\s*of\s*object\s*executions[\s\:]+\
                                (?<NumOfObjectExecutions>\d+))\s*\
                                (?:Total\s*excution\s*time\s*\(msec\)[\s\:]+\
                                (?<TotalExcutionTime_msec>\d+))\s*\
                                (?:Average\s*execution\s*time\s*\(msec\)[\s\:]+\
                                (?<AverageExecutionTime_msec>\d+))\s*\
                                (?:Fastest\s*execution\s*time\s*\(msec\)[\s\:]+\
                                (?<FastestExecutionTime_msec>.*?))\s*\
                                (?:for\s*object\sid\s\(sec\.seq\)[\s\:]+\
                                (?<FastestExecTimeForObjectId>.*?))\s*\
                                (?:Slowest\s*execution\s*time\s*\(msec\)[\s\:]+\
                                (?<SlowestExecutionTime_msec>.*?))\s*\
                                (?:for\s*object\sid\s\(sec\.seq\)[\s\:]+\
                                (?<SlowestExecTimeForObjectId>.*?))\s*\
                                PERFORMANCE\:\sEnter\s*action\s*to\sdo.*/

The regular expressions above are defined in the configuration as constants.

Since the log file contains both single-line and multi-line event, separate instances of the im_file input module are defined.

The xm_multiline extension module is used to process multi-line events as a single record. The HeaderLine and the EndLine directives of this module specify a regular expression to detect the beginning and end of each multi-line event respectively.

The Exec block of each input module instance matches the log line ($raw_event) against the appropriate regular expression. Once a match occurs, the respective fields are created according to the named capturing groups.

Captured group $5 of the request part contains a timestamp in a custom date/time format, therefore it is converted to datetime using the strptime() function and then assigned to the $EventTime field.

Finally, the fields are converted to JSON using the to_json() procedure of the xm_json module. If the log line does not match any of the defined regular expressions, it is discarded using the drop() procedure.

The following NXLog configuration combines all the steps described above.

nxlog.conf
# A regular expression defined as a constant to read the content of the logs
define SMD_OPCDBG_REQ_REGEX     /(?x)^\#\#\[(?<ID>\d+)\]\[\
                                (?<Process>\w+)[\s\<\>]*\
                                (?<Commands>.*?)\]\[\
                                (?<Comment>.*?)\]\[\
                                (\d+.\d+.\d+.\d+.\d+.\d+).\d+\]/

define SMD_OPCDBG_MAIN_REGEX    /(?x)^(?:OPC\s*excutor\s*process\s*\
                                \(node\,name\)[\s\:]+\
                                (?<OPC_ExcutorProcess>.*?))\s*\
                                (?:Activation\s*time[\s\:]+\
                                (?<ActivationTime>.*?))\s*\
                                (?:Number\s*of\s*active\s*classes[\s\:]+\
                                (?<NumOfActiveClasses>\d+))\s*\
                                (?:Number\s*of\s*active\s*objects[\s\:]+\
                                (?<NumOfActiveObjects>\d+))\s*\
                                (?:Number\s*of\s*active\s*trigger\s*groups[\s\:]+\
                                (?<NumOfActiveTriggerGroups>\d+))\s*\
                                (?:Number\s*of\s*active\s*items[\s\:]+\
                                (?<NumOfActiveItems>\d+))\s*\
                                (?:Number\s*of\s*ready\s*to\s*\
                                execute\s*objects[\s\:]+\
                                (?<NumOfReadyToExecObjects>\d+))\s*\
                                (?:Number\s*of\s*free\s*ready\s*to\s*\
                                execute\s*locations[\s\:]+\
                                (?<NumOfFreeReadyToExecLocations>\d+))\s*\
                                Statistics[\s\:]+\
                                (?:Number\s*of\s*object\s*executions[\s\:]+\
                                (?<NumOfObjectExecutions>\d+))\s*\
                                (?:Total\s*excution\s*time\s*\(msec\)[\s\:]+\
                                (?<TotalExcutionTime_msec>\d+))\s*\
                                (?:Average\s*execution\s*time\s*\(msec\)[\s\:]+\
                                (?<AverageExecutionTime_msec>\d+))\s*\
                                (?:Fastest\s*execution\s*time\s*\(msec\)[\s\:]+\
                                (?<FastestExecutionTime_msec>.*?))\s*\
                                (?:for\s*object\sid\s\(sec\.seq\)[\s\:]+\
                                (?<FastestExecTimeForObjectId>.*?))\s*\
                                (?:Slowest\s*execution\s*time\s*\(msec\)[\s\:]+\
                                (?<SlowestExecutionTime_msec>.*?))\s*\
                                (?:for\s*object\sid\s\(sec\.seq\)[\s\:]+\
                                (?<SlowestExecTimeForObjectId>.*?))\s*\
                                PERFORMANCE\:\sEnter\s*action\s*to\sdo.*/

# Part of the log path defined as a constant
define LOG_PATH     C:\Users\Public\Yokogawa\tls\log

<Extension json>
    Module      xm_json
</Extension>

<Extension multiline_stat>
    Module      xm_multiline
    # Regular expression to look for the header of the message
    HeaderLine  /^OPC\s*excutor\s*process\s*\(node\,name\)[\s\:]+\d\,\s*\w+/
    EndLine     /^PERFORMANCE[\s\:]+Enter\s*action\s*to\s*do.*?\[1\]/
</Extension>

<Input from_file>
    Module      im_file
    File        '%LOG_PATH%\smd_*_opcdbg_all.log'

    <Exec>
        # Matches the events with a regular expression
        if $raw_event =~ %SMD_OPCDBG_REQ_REGEX%
        {
            # Creates the timestamp
            $EventTime = strptime($5, '%d/%m/%Y %T');
            # Formats the result as JSON
            to_json();
        }
        # Discard event if it doesn't match a/the regular expression
        else drop();
        # Replaces unwanted characters
        $raw_event =~ s/\s{2,}/ /g;
    </Exec>
</Input>

<Input from_file_main_info>
    Module      im_file
    File        '%LOG_PATH%\smd_*_opcdbg_all.log'
    InputType   multiline_stat

    <Exec>
        # Replaces unwanted characters
        $raw_event =~ s/\\n/ /g;
        $raw_event =~ s/\\r/ /g;
        $raw_event =~ s/\s{2,}/ /g;
    </Exec>

    <Exec>
        # Matches the events with a regular expression
        if $raw_event =~ %SMD_OPCDBG_MAIN_REGEX%
        {
            # Formats the result as JSON
            to_json();
        }
        # Discard event if it doesn't match a/the regular expression
        else drop();
    </Exec>
</Input>

The following output samples depict the processed events in JSON format.

Output sample of the request part
{
  "EventReceivedTime": "2021-05-25T13:09:59.485278-07:00",
  "SourceModuleName": "from_file",
  "SourceModuleType": "im_file",
  "Commands": "0, 4, 0, OPCEXE, 1, 10, 10, 11, 10, -1, -1, ",
  "Comment": "All",
  "ID": "13",
  "Process": "opcdbg",
  "EventTime": "2021-05-25T13:09:59.000000-07:00"
}
Output sample of the main info part
{
  "EventReceivedTime": "2021-05-25T13:09:59.954078-07:00",
  "SourceModuleName": "from_file_main_info",
  "SourceModuleType": "im_file",
  "ActivationTime": "1621973037 (= 25-05-2021 20:03:57)",
  "AverageExecutionTime_msec": "0",
  "FastestExecTimeForObjectId": "0.0",
  "FastestExecutionTime_msec": "-1",
  "NumOfActiveClasses": "0",
  "NumOfActiveItems": "0",
  "NumOfActiveObjects": "0",
  "NumOfActiveTriggerGroups": "0",
  "NumOfFreeReadyToExecLocations": "0",
  "NumOfObjectExecutions": "0",
  "NumOfReadyToExecObjects": "0",
  "OPC_ExcutorProcess": "0, OPCEXE",
  "SlowestExecTimeForObjectId": "0.0",
  "SlowestExecutionTime_msec": "0",
  "TotalExcutionTime_msec": "0"
}

SMDSNP general log

The SMDSNP general log contains general information about the FAST/TOOLS system.

Example 13. Processing SMDSNP general log

The following input sample is taken from smd_*_smdsnp_general.log.

Input sample
##[2][smdsnp -g][General][26/05/2021 01:08:07:285]


Version             : 9.04
Service pack        :
Customer            : YOKOGAWA ELECTRIC CORPORATION
Node name           : UNLICENCED
Node nr             : 1
Processes           : 58
Nodes               : 0
Common size (bytes) : 5120000
Common used (bytes) : 122880
Common high (bytes) : 176128
Event_size          : 500
Event_used          : 2
Queue_transf        : 7409
Queue_failed        : 0
Items_licence       : 1024
Items_used          : 13
Local time          : Wed May 26 01:08:07 2021

General SMDSNP events can be split into two parts, the request and the general info. The following is an example of each section and the regular expressions used to parse them.

Request part
##[2][smdsnp -g][General][26/05/2021 01:08:07:285]

The following fields can be parsed from the request part:

  • ID

  • Process

  • Commands

  • Comment

  • EventTime

Defining the SMD_SMDSNP_GEN_REQ_REGEX regular expression
define SMD_SMDSNP_GEN_REQ_REGEX /(?x)^\#\#\[(?<ID>\d+)\]\[\
                                (?<Process>\w+)[\s\<\>]*\
                                (?<Commands>.*?)\]\[\
                                (?<Comment>.*?)\]\[\
                                (\d+.\d+.\d+.\d+.\d+.\d+).\d+\]/
General info part
Version             : 9.04
Service pack        :
Customer            : YOKOGAWA ELECTRIC CORPORATION
Node name           : UNLICENCED
Node nr             : 1
Processes           : 58
Nodes               : 0
Common size (bytes) : 5120000
Common used (bytes) : 122880
Common high (bytes) : 176128
Event_size          : 500
Event_used          : 2
Queue_transf        : 7409
Queue_failed        : 0
Items_licence       : 1024
Items_used          : 13
Local time          : Wed May 26 01:08:07 2021

The following fields can be parsed from the general info section:

  • Version

  • ServicePack

  • Customer

  • NodeName

  • NodeNr

  • Processes

  • Nodes

  • CommonSize_bytes

  • CommonUsed_bytes

  • CommonHigh_bytes

  • EventSize

  • EventUsed

  • QueueTrensf

  • QueueFailed

  • ItemsLicence

  • ItemUsed

  • LocalTime

Defining the SMD_SMDSNP_GEN_REGEX regular expression
define SMD_SMDSNP_GEN_REGEX     /(?x)^(?:Version[\s\:]+(?<Version>.*?))\s*\
                                (?:Service\s*pack[\s\:]+(?<ServicePack>.*?))\s*\
                                (?:Customer[\s\:]+(?<Customer>.*?))\s*\
                                (?:Node\s*name[\s\:]+(?<NodeName>.*?))\s*\
                                (?:Node\s*nr[\s\:]+(?<NodeNr>\d+))\s*\
                                (?:Processes[\s\:]+(?<Processes>\d+))\s*\
                                (?:Nodes[\s\:]+(?<Nodes>\d+))\s*\
                                (?:Common\s*size\s*\(bytes\)[\s\:]+\
                                (?<CommonSize_bytes>\d+))\s*\
                                (?:Common\s*used\s*\(bytes\)[\s\:]+\
                                (?<CommonUsed_bytes>\d+))\s*\
                                (?:Common\s*high\s*\(bytes\)[\s\:]+\
                                (?<CommonHigh_bytes>\d+))\s*\
                                (?:Event_size[\s\:]+(?<EventSize>\d+))\s*\
                                (?:Event_used[\s\:]+(?<EventUsed>\d+))\s*\
                                (?:Queue_transf[\s\:]+(?<QueueTrensf>\d+))\s*\
                                (?:Queue_failed[\s\:]+(?<QueueFailed>\d+))\s*\
                                (?:Items_licence[\s\:]+(?<ItemsLicence>\d+))\s*\
                                (?:Items_used[\s\:]+(?<ItemUsed>\d+))\s*\
                                (?:Local\s*time[\s\:]+\
                                (\w+\s*\w+\s*\d+\s*\d+.\d+.\d+\s*\d+))/

The regular expressions above are defined in the configuration as constants.

Since the log file contains both single-line and multi-line events, separate instances of the im_file input module are defined.

The xm_multiline extension module is used to process multi-line events as a single record. The HeaderLine and the EndLine directives of this module specify a regular expression to detect the beginning and end of each multi-line event respectively.

The Exec blocks of each input module instance matches the log line ($raw-event) against the appropriate regular expression. Once a match occurs, the respective fields are created according to the named capturing groups.

Captured group $5 of the request part contains a timestamp in a custom date/time format, therefore it is converted to datetime using the strptime() function and assigned to the $EventTime field.

Captured group $17 of the general info section also contains a timestamp. Since the timestamp is in a format supported by parsedate(), this function is used to parse the date, and the value is assigned to the $LocalTime field.

Finally, the fields are converted to JSON using the to_json() procedure of the xm_json module. If the log line does not match any of the defined regular expressions, it is discarded using the drop() procedure.

The following NXLog configuration combines all the steps described above.

nxlog.conf
# A regular expression defined as a constant to read the content of the logs
define SMD_SMDSNP_GEN_REQ_REGEX /(?x)^\#\#\[(?<ID>\d+)\]\[\
                                (?<Process>\w+)[\s\<\>]*\
                                (?<Commands>.*?)\]\[\
                                (?<Comment>.*?)\]\[\
                                (\d+.\d+.\d+.\d+.\d+.\d+).\d+\]/

define SMD_SMDSNP_GEN_REGEX     /(?x)^(?:Version[\s\:]+(?<Version>.*?))\s*\
                                (?:Service\s*pack[\s\:]+(?<ServicePack>.*?))\s*\
                                (?:Customer[\s\:]+(?<Customer>.*?))\s*\
                                (?:Node\s*name[\s\:]+(?<NodeName>.*?))\s*\
                                (?:Node\s*nr[\s\:]+(?<NodeNr>\d+))\s*\
                                (?:Processes[\s\:]+(?<Processes>\d+))\s*\
                                (?:Nodes[\s\:]+(?<Nodes>\d+))\s*\
                                (?:Common\s*size\s*\(bytes\)[\s\:]+\
                                (?<CommonSize_bytes>\d+))\s*\
                                (?:Common\s*used\s*\(bytes\)[\s\:]+\
                                (?<CommonUsed_bytes>\d+))\s*\
                                (?:Common\s*high\s*\(bytes\)[\s\:]+\
                                (?<CommonHigh_bytes>\d+))\s*\
                                (?:Event_size[\s\:]+(?<EventSize>\d+))\s*\
                                (?:Event_used[\s\:]+(?<EventUsed>\d+))\s*\
                                (?:Queue_transf[\s\:]+(?<QueueTrensf>\d+))\s*\
                                (?:Queue_failed[\s\:]+(?<QueueFailed>\d+))\s*\
                                (?:Items_licence[\s\:]+(?<ItemsLicence>\d+))\s*\
                                (?:Items_used[\s\:]+(?<ItemUsed>\d+))\s*\
                                (?:Local\s*time[\s\:]+\
                                (\w+\s*\w+\s*\d+\s*\d+.\d+.\d+\s*\d+))/

# Part of the log path defined as a constant
define LOG_PATH                 C:\Users\Public\Yokogawa\tls\log

<Extension json>
    Module      xm_json
</Extension>

<Extension multiline_general>
    Module      xm_multiline
    # Regular expression to look for the header of the message
    HeaderLine  /^Version\s*\:\s*\d+\.\d+/
    EndLine     /^Local\s*time\s*\:\s*\w+\s*\w+\s*\d+\s*\d+.\d+.\d+\s*\d+/
</Extension>

<Input from_file>
    Module      im_file
    File        '%LOG_PATH%\smd_*_smdsnp_general.log'

    <Exec>
        # Matches the events with a regular expression
        if $raw_event =~ %SMD_SMDSNP_GEN_REQ_REGEX%
        {
            # Creates the timestamp
            $EventTime = strptime($5, '%d/%m/%Y %T');
            # Formats the result as JSON
            to_json();
        }
        # Discard event if it doesn't match a/the regular expression
        else drop();
        # Replaces unwanted characters
        $raw_event =~ s/\s{2,}/ /g;
    </Exec>
</Input>

<Input from_file_general>
    Module      im_file
    File        '%LOG_PATH%\smd_*_smdsnp_general.log'
    InputType   multiline_general

    <Exec>
        # Replaces unwanted characters
        $raw_event =~ s/\\n/ /g;
        $raw_event =~ s/\\r/ /g;
        $raw_event =~ s/\s{2,}/ /g;
    </Exec>

    <Exec>
        # Matches the events with a regular expression
        if $raw_event =~ %SMD_SMDSNP_GEN_REGEX%
        {
            $LocalTime = parsedate($17);
            # Formats the result as JSON
            to_json();
        }
        # Discard event if it doesn't match a/the regular expression
        else drop();
    </Exec>
</Input>

The following output samples depict the processed events in JSON format.

Output sample of the request part
{
  "EventReceivedTime": "2021-05-26T01:08:07.975622-07:00",
  "SourceModuleName": "from_file",
  "SourceModuleType": "im_file",
  "Commands": "-g",
  "Comment": "General",
  "ID": "2",
  "Process": "smdsnp",
  "EventTime": "2021-05-26T01:08:07.000000-07:00"
}
Output sample of the general info part
{
  "EventReceivedTime": "2021-05-26T01:08:07.975622-07:00",
  "SourceModuleName": "from_file_general",
  "SourceModuleType": "im_file",
  "CommonHigh_bytes": "176128",
  "CommonSize_bytes": "5120000",
  "CommonUsed_bytes": "122880",
  "Customer": "YOKOGAWA ELECTRIC CORPORATION",
  "EventSize": "500",
  "EventUsed": "2",
  "ItemUsed": "13",
  "ItemsLicence": "1024",
  "NodeName": "UNLICENCED",
  "NodeNr": "1",
  "Nodes": "0",
  "Processes": "58",
  "QueueFailed": "0",
  "QueueTrensf": "7409",
  "ServicePack": "",
  "Version": "9.04",
  "LocalTime": "2021-05-26T01:08:07.000000-07:00"
}

SMDSNP lock log

The SMDSNP lock log shows lock information for the FAST/TOOLS common areas.

Shared memory sections exchange information between the FAST/TOOLS processes. Before a process accesses a common area, it needs to obtain privileged access to the common area. When the process finishes working in the common area, it releases the privileged access by releasing the lock on the area. When, for some reason, the process exits in an uncontrolled way before releasing the lock, the common area cannot be accessed by other processes anymore.

Example 14. Processing SMDSNP lock log

The following input sample is taken from smd_*_smdsnp_lock.log.

Input sample
##[5][smdsnp -l][Lock][26/05/2021 01:56:57:301]


lock_name    | Locked by    | collisions
-------------+--------------+-----------
DUR          |              | 166
ISM          |              | 3
ITM          |              | 5
CWS          |              | 0
DSS-API      |              | 0
DSS-LCK      |              | 0
EQP_VNET     |              | 0

SMDSNP lock events can be split into two parts: the request and the lock info. The following is an example of each section and the regular expressions used to parse them.

Request section
##[5][smdsnp -l][Lock][26/05/2021 01:56:57:301]

The following fields can be parsed from the request part:

  • ID

  • Process

  • Commands

  • Comment

  • EventTime

Defining the SMD_SMDSNP_LOCK_REQ_REGEX regular expression
define SMD_SMDSNP_LOCK_REQ_REGEX    /(?x)^\#\#\[(?<ID>\d+)\]\[\
                                    (?<Process>\w+)[\s\<\>]*\
                                    (?<Commands>.*?)\]\[\
                                    (?<Comment>.*?)\]\[\
                                    (\d+.\d+.\d+.\d+.\d+.\d+).\d+\]/
Lock info part
lock_name    | Locked by    | collisions
-------------+--------------+-----------
DUR          |              | 166
ISM          |              | 3
ITM          |              | 5
CWS          |              | 0
DSS-API      |              | 0
DSS-LCK      |              | 0
EQP_VNET     |              | 0

The following fields can be parsed from the lock info part:

  • LockName

  • LockedBy

  • Collisions

Since this section comprises a table with a variable number of rows, the best approach to process it is to read each row as a separate single-line event.

Defining the SMD_SMDSNP_LOCK_REGEX regular expression
define SMD_SMDSNP_LOCK_REGEX        /(?x)^(?<LockName>[\w\-]+)\s*\|\s*\
                                    (?<LockedBy>.*?)\s*\|\s*\
                                    (?<Collisions>\d+)\s*/

The regular expressions above are defined in the configuration as constants.

To read and parse log messages this NXLog configuration uses the im_file input module. An Exec block is used to match the log line ($raw_event) against the appropriate regular expression. Once a match occurs, the respective fields are created according to the named capturing groups.

Captured group $5 of the request part contains a timestamp in a custom date/time format, therefore it is converted to datetime using the strptime() function and assigned to the $EventTime field.

Finally, the fields are converted to JSON using the to_json() procedure of the xm_json module. If the log line does not match any of the defined regular expressions, it is discarded using the drop() procedure.

The following NXLog configuration combines all the steps described above.

nxlog.conf
# A regular expression defined as a constant to read the content of the logs
define SMD_SMDSNP_LOCK_REQ_REGEX    /(?x)^\#\#\[(?<ID>\d+)\]\[\
                                    (?<Process>\w+)[\s\<\>]*\
                                    (?<Commands>.*?)\]\[\
                                    (?<Comment>.*?)\]\[\
                                    (\d+.\d+.\d+.\d+.\d+.\d+).\d+\]/

define SMD_SMDSNP_LOCK_REGEX        /(?x)^(?<LockName>[\w\-]+)\s*\|\s*\
                                    (?<LockedBy>.*?)\s*\|\s*\
                                    (?<Collisions>\d+)\s*/

# Part of the log path defined as a constant
define LOG_PATH                     C:\Users\Public\Yokogawa\tls\log

<Extension json>
    Module      xm_json
</Extension>

<Input from_file>
    Module      im_file
    File        '%LOG_PATH%\smd_*_smdsnp_lock.log'

    <Exec>
        # Matches the events with a regular expression
        if $raw_event =~ %SMD_SMDSNP_LOCK_REQ_REGEX%
        {
            # Creates the timestamp
            $EventTime = strptime($5, '%d/%m/%Y %T');
            # Formats the result as JSON
            to_json();
        }
        else if $raw_event =~ %SMD_SMDSNP_LOCK_REGEX%
        {
            # Formats the result as JSON
            to_json();
        }
        # Discard event if it doesn't match a/the regular expression
        else drop();
        # Replaces unwanted characters
        $raw_event =~ s/\s{2,}/ /g;
    </Exec>
</Input>

The following output samples depict the processed events in JSON format.

Output sample of the request part
{
  "EventReceivedTime": "2021-05-26T01:56:58.223057-07:00",
  "SourceModuleName": "from_file",
  "SourceModuleType": "im_file",
  "Commands": "-l",
  "Comment": "Lock",
  "ID": "5",
  "Process": "smdsnp",
  "EventTime": "2021-05-26T01:56:57.000000-07:00"
}
Output sample of the lock info part
{
  "EventReceivedTime": "2021-05-26T01:56:58.223057-07:00",
  "SourceModuleName": "from_file",
  "SourceModuleType": "im_file",
  "Collisions": "166",
  "LockName": "DUR",
  "LockedBy": ""
}

SMDSNP process log

The SMDSNP process log contains information about the FAST/TOOLS processes running on the FAST/TOOLS system.

Example 15. Processing SMDSNP process log

The following input sample is taken from smd_*_smdsnp_process.log.

Input sample
##[3][smdsnp -p][Process][26/05/2021 02:40:16:176]


Name         | proc_id    | cpu_kernel | cpu_user   | cpu_total  | queue_size | queue_used | queue_high | msg_in     | msg_transf | msg_failed | waiting
-------------+------------+------------+------------+------------+------------+------------+------------+------------+------------+------------+--------
FMFPRT       | 4980       | 31         | 0          | 31         | 102000     | 0          | 544        | 0          | 301        | 0          | 1
JWUIISG      | 5856       | 1531       | 8781       | 10312      | 510000     | 0          | 2720       | 0          | 267        | 0          | 0
WFLIDI       | 5296       | 15         | 15         | 31         | 510000     | 0          | 816        | 0          | 554        | 0          | 1
JHMISET05476 | 5476       | 1296       | 4437       | 5734       | 510000     | 0          | 816        | 0          | 64         | 0          | 0

SMDSNP process events can be split into two parts: the request and the process info. The following is an example of each section and the regular expressions used to parse them.

Request part
##[3][smdsnp -p][Process][26/05/2021 02:40:16:176]

The following fields can be parsed from the request part:

  • ID

  • Process

  • Commands

  • Comment

  • EventTime

Defining the SMD_SMDSNP_PROC_REQ_REGEX regular expression
define SMD_SMDSNP_PROC_REQ_REGEX    /(?x)^\#\#\[(?<ID>\d+)\]\[\
                                    (?<Process>\w+)[\s\<\>]*\
                                    (?<Commands>.*?)\]\[\
                                    (?<Comment>.*?)\]\[\
                                    (\d+.\d+.\d+.\d+.\d+.\d+).\d+\]/
Process info part
Name         | proc_id    | cpu_kernel | cpu_user   | cpu_total  | queue_size | queue_used | queue_high | msg_in     | msg_transf | msg_failed | waiting
-------------+------------+------------+------------+------------+------------+------------+------------+------------+------------+------------+--------
FMFPRT       | 4980       | 31         | 0          | 31         | 102000     | 0          | 544        | 0          | 301        | 0          | 1
JWUIISG      | 5856       | 1531       | 8781       | 10312      | 510000     | 0          | 2720       | 0          | 267        | 0          | 0
WFLIDI       | 5296       | 15         | 15         | 31         | 510000     | 0          | 816        | 0          | 554        | 0          | 1
JHMISET05476 | 5476       | 1296       | 4437       | 5734       | 510000     | 0          | 816        | 0          | 64         | 0          | 0

The following fields can be parsed from the process info part:

  • Name

  • ProcID

  • CPU_Kernel

  • CPU_User

  • CPU_Total

  • QueueSize

  • QueueUsed

  • QueueHigh

  • MsgIn

  • MsgTransf

  • MsgFailed

  • Waiting

Since this part is made up of a table with a variable number of rows, the best approach to process it is to read each row as a separate single-line event.

Defining the SMD_SMDSNP_PROC_REGEX regular expression
define SMD_SMDSNP_PROC_REGEX        /(?x)^(?<Name>[\w\-]+)\s*\|\s*\
                                    (?<ProcID>\d+)\s*\|\s*\
                                    (?<CPU_Kernel>\d+)\s*\|\s*\
                                    (?<CPU_User>\d+)\s*\|\s*\
                                    (?<CPU_Total>\d+)\s*\|\s*\
                                    (?<QueueSize>\d+)\s*\|\s*\
                                    (?<QueueUsed>\d+)\s*\|\s*\
                                    (?<QueueHigh>\d+)\s*\|\s*\
                                    (?<MsgIn>\d+)\s*\|\s*\
                                    (?<MsgTransf>\d+)\s*\|\s*\
                                    (?<MsgFailed>\d+)\s*\|\s*\
                                    (?<Waiting>\d+)\s*/

The regular expressions above are defined in the configuration as constants.

To read and parse log messages this NXLog configuration uses the im_file input module. An Exec block is used to match the log line ($raw_event) against the appropriate regular expression. Once a match occurs, the respective fields are created according to the named capturing groups.

Captured group $5 of the request part contains a timestamp in a custom date/time format, therefore it is converted to datetime using the strptime() function and assigned to the $EventTime field.

Finally, the fields are converted to JSON using the to_json() procedure of the xm_json module. If the log line does not match any of the defined regular expressions, it is discarded using the drop() procedure.

The following NXLog configuration combines all the steps described above.

nxlog.conf
# A regular expression defined as a constant to read the content of the logs
define SMD_SMDSNP_PROC_REQ_REGEX    /(?x)^\#\#\[(?<ID>\d+)\]\[\
                                    (?<Process>\w+)[\s\<\>]*\
                                    (?<Commands>.*?)\]\[\
                                    (?<Comment>.*?)\]\[\
                                    (\d+.\d+.\d+.\d+.\d+.\d+).\d+\]/

define SMD_SMDSNP_PROC_REGEX        /(?x)^(?<Name>[\w\-]+)\s*\|\s*\
                                    (?<ProcID>\d+)\s*\|\s*\
                                    (?<CPU_Kernel>\d+)\s*\|\s*\
                                    (?<CPU_User>\d+)\s*\|\s*\
                                    (?<CPU_Total>\d+)\s*\|\s*\
                                    (?<QueueSize>\d+)\s*\|\s*\
                                    (?<QueueUsed>\d+)\s*\|\s*\
                                    (?<QueueHigh>\d+)\s*\|\s*\
                                    (?<MsgIn>\d+)\s*\|\s*\
                                    (?<MsgTransf>\d+)\s*\|\s*\
                                    (?<MsgFailed>\d+)\s*\|\s*\
                                    (?<Waiting>\d+)\s*/

# Part of the log path defined as a constant
define LOG_PATH                     C:\Users\Public\Yokogawa\tls\log

<Extension json>
    Module      xm_json
</Extension>

<Input from_file>
    Module      im_file
    File        '%LOG_PATH%\smd_*_smdsnp_process.log'

    <Exec>
        # Matches the events with a regular expression
        if $raw_event =~ %SMD_SMDSNP_PROC_REQ_REGEX%
        {
            # Creates the timestamp
            $EventTime = strptime($5, '%d/%m/%Y %T');
            # Formats the result as JSON
            to_json();
        }
        else if $raw_event =~ %SMD_SMDSNP_PROC_REGEX%
        {
            # Formats the result as JSON
            to_json();
        }
        # Discard event if it doesn't match a/the regular expression
        else drop();
        # Replaces unwanted characters
        $raw_event =~ s/\s{2,}/ /g;
    </Exec>
</Input>

The following output samples depict the processed events in JSON format.

Output sample of the request part
{
  "EventReceivedTime": "2021-05-26T02:40:16.254210-07:00",
  "SourceModuleName": "from_file",
  "SourceModuleType": "im_file",
  "Commands": "-p",
  "Comment": "Process",
  "ID": "3",
  "Process": "smdsnp",
  "EventTime": "2021-05-26T02:40:16.000000-07:00"
}
Output sample of the process info part
{
  "EventReceivedTime": "2021-05-26T02:40:16.254210-07:00",
  "SourceModuleName": "from_file",
  "SourceModuleType": "im_file",
  "CPU_Kernel": "1296",
  "CPU_Total": "5734",
  "CPU_User": "4437",
  "MsgFailed": "0",
  "MsgIn": "0",
  "MsgTransf": "64",
  "Name": "JHMISET05476",
  "ProcID": "5476",
  "QueueHigh": "816",
  "QueueSize": "510000",
  "QueueUsed": "0",
  "Waiting": "0"
}

EQPMDC log

The Equipment Manager for Modbus log file contains trace information of the Modbus communication.

Example 16. Processing EQPMDC log

The following sample is taken from EQPMDC.xml.

Input sample
<BLK>
<SLAVE>DUMMYSTATION</SLAVE>
<TIME>2021-05-14 14:22:28.563</TIME>
<INFO>Read holding registers 1-10</INFO>
<OUT><LINE>0,0</LINE><PROT>OPEN MODBUS</PROT>
<HEAD>87 00 00 00 00 06</HEAD>
<MSG>01 03 00 00 00 0A</MSG>
<RAW>87 00 00 00 00 06 01 03  00 00 00 0A</RAW>
</OUT>
<IN><LINE>0,0</LINE>
<TIME>2021-05-14 14:22:28.579</TIME>
<RAW>
87 00 00 00 00 17 01 03  14 0D F9 0D FA 0D FB 0D
FD 0D FE 0D FF 0E 00 0E  01 0D FC 0E 02
</RAW>
<HEAD>87 00 00 00 00 17</HEAD>
<MSG>
01 03 14 0D F9 0D FA 0D  FB 0D FD 0D FE 0D FF 0E
00 0E 01 0D FC 0E 02
</MSG>
</IN>
<ITM ID="1,1"><RAW>0xDF9</RAW><TM>2021-05-14 14:22:28.563</TM><VAL>3577</VAL><ST>12</ST></ITM>
<ITM ID="1,2"><RAW>0xDFA</RAW><TM>2021-05-14 14:22:28.563</TM><VAL>3578</VAL><ST>12</ST></ITM>
<ITM ID="1,3"><RAW>0xDFB</RAW><TM>2021-05-14 14:22:28.563</TM><VAL>3579</VAL><ST>12</ST></ITM>
<ITM ID="1,4"><RAW>0xDFD</RAW><TM>2021-05-14 14:22:28.563</TM><VAL>3581</VAL><ST>12</ST></ITM>
<ITM ID="1,5"><RAW>0xDFE</RAW><TM>2021-05-14 14:22:28.563</TM><VAL>3582</VAL><ST>12</ST></ITM>
<ITM ID="1,6"><RAW>0xDFF</RAW><TM>2021-05-14 14:22:28.563</TM><VAL>3583</VAL><ST>12</ST></ITM>
<ITM ID="1,7"><RAW>0xE00</RAW><TM>2021-05-14 14:22:28.563</TM><VAL>3584</VAL><ST>12</ST></ITM>
<ITM ID="1,8"><RAW>0xE01</RAW><TM>2021-05-14 14:22:28.563</TM><VAL>3585</VAL><ST>12</ST></ITM>
<ITM ID="1,9"><RAW>0xDFC</RAW><TM>2021-05-14 14:22:28.563</TM><VAL>3580</VAL><ST>12</ST></ITM>
<ITM ID="1,10"><RAW>0xE02</RAW><TM>2021-05-14 14:22:28.563</TM><VAL>3586</VAL><ST>12</ST></ITM>
</BLK>

EQPMDC events can be split into four parts: the block info, output data, input data, and item data. The following is an example of each section and the regular expressions used to parse them.

Block info part
<SLAVE>DUMMYSTATION</SLAVE>
<TIME>2021-05-14 14:22:28.563</TIME>
<INFO>Read holding registers 1-10</INFO>

The block info part consists of the following fields:

  • Slave

  • LocalTime

  • INFO

Defining the EQPMDC_BLK_INFO_REGEX regular expression
define EQPMDC_BLK_INFO_REGEX    /(?x)^(?:\<SLAVE\>(?<Slave>.*?)\<\/SLAVE\>)\s*\
                                (?:\<TIME\>(\d+.\d+.\d+\s*\d+.\d+.\d+.\d+)\
                                \<\/TIME\>)\s*\
                                (?:\<INFO\>(?<INFO>.*?)\<\/INFO\>)/
Output data part
<OUT><LINE>0,0</LINE><PROT>OPEN MODBUS</PROT>
<HEAD>87 00 00 00 00 06</HEAD>
<MSG>01 03 00 00 00 0A</MSG>
<RAW>87 00 00 00 00 06 01 03  00 00 00 0A</RAW>
</OUT>

The output data part consists of the following fields:

  • Line

  • Prot

  • Head

  • Msg

  • Raw

Defining the define EQPMDC_BLK_OUT_REGEX
define EQPMDC_BLK_OUT_REGEX     /(?x)^\<OUT\>(?:\<LINE\>(?<Line>.*?)\<\/LINE\>)\s*\
                                (?:\<PROT\>(?<Prot>.*?)\<\/PROT\>)\s*\
                                (?:\<HEAD\>\s*(?<Head>[\w\s]+)\s*\<\/HEAD\>)\s*\
                                (?:\<MSG\>\s*(?<Msg>[\w\s]+)\s*\<\/MSG\>)\s*\
                                (?:\<RAW\>\s*(?<Raw>[\w\s]+)\s*\<\/RAW\>)\
                                \s*\<\/OUT\>/
Input data part
<IN><LINE>0,0</LINE>
<TIME>2021-05-14 14:22:28.579</TIME>
<RAW>
87 00 00 00 00 17 01 03  14 0D F9 0D FA 0D FB 0D
FD 0D FE 0D FF 0E 00 0E  01 0D FC 0E 02
</RAW>
<HEAD>87 00 00 00 00 17</HEAD>
<MSG>
01 03 14 0D F9 0D FA 0D  FB 0D FD 0D FE 0D FF 0E
00 0E 01 0D FC 0E 02
</MSG>
</IN>

The input data part consist of the following fields:

  • Line

  • LocalTime

  • Raw

  • Head

  • Msg

Defining the define EQPMDC_BLK_IN_REGEX
define EQPMDC_BLK_IN_REGEX      /(?x)^\<IN\>(?:\<LINE\>(?<Line>.*?)\<\/LINE\>)\s*\
                                (?:\<TIME\>(\d+.\d+.\d+\s*\d+.\d+.\d+.\d+)\
                                \<\/TIME\>)\s*\
                                (?:\<RAW\>\s*(?<Raw>[\w\s]+)\s*\<\/RAW\>)\s*\
                                (?:\<HEAD\>\s*(?<Head>[\w\s]+)\s*\<\/HEAD\>)\s*\
                                (?:\<MSG\>\s*(?<Msg>[\w\s]+)\s*\<\/MSG\>)\
                                \s*\<\/IN\>/
Item data
<ITM ID="1,1"><RAW>0xDF9</RAW><TM>2021-05-14 14:22:28.563</TM><VAL>3577</VAL><ST>12</ST></ITM>

The item data part consists of the following fields:

  • ID

  • Raw

  • EventTime

  • Val

  • St

Defining the EQPMDC_BLK_ITM_REGEX regular expression
define EQPMDC_BLK_ITM_REGEX     /(?x)^\<ITM\s*(?:ID\=\"(?<ID>.*?)\")\>\s*\
                                (?:\<RAW\>(?<Raw>.*?)\<\/RAW\>)\s*\
                                (?:\<TM\>(\d+.\d+.\d+\s*\d+.\d+.\d+.\d+.)\
                                \<\/TM\>)\s*\
                                (?:\<VAL\>(?<Val>\d+)\<\/VAL\>)\s*\
                                (?:\<ST\>(?<St>\d+)\<\/ST\>)\s*\<\/ITM\>/

The regular expressions above are defined in the configuration as constants.

Since the log file contains multi-line events in different formats, separate instances of the im_file input module are defined. The name of the corresponding input reader function is specified by the InputType directive.

Different xm_multiline module instances are used to process multi-line events as a single record. The HeaderLine and EndLine directives of this module specify a regular expression to detect the beginning and end of each multi-line event respectively.

The Exec block of each input module instance matches the log line ($raw_event) against the appropriate regular expression. Once a match occurs, the respective fields are created according to the named capturing groups.

Captured groups containing a timestamp are converted to datetime using the parsedate() function.

Finally, the fieds are converted to JSON using the to_json() procedure of the xm_json module. If the log line doesn’t match any of the defined regular expressions, it is discarded using the drop() procedure.

The following NXLog configuration combines all the steps described above.

nxlog.conf
# A regular expression defined as a constant to read the content of the logs
define EQPMDC_BLK_INFO_REGEX    /(?x)^(?:\<SLAVE\>(?<Slave>.*?)\<\/SLAVE\>)\s*\
                                (?:\<TIME\>(\d+.\d+.\d+\s*\d+.\d+.\d+.\d+)\
                                \<\/TIME\>)\s*\
                                (?:\<INFO\>(?<INFO>.*?)\<\/INFO\>)/

define EQPMDC_BLK_OUT_REGEX     /(?x)^\<OUT\>(?:\<LINE\>(?<Line>.*?)\<\/LINE\>)\s*\
                                (?:\<PROT\>(?<Prot>.*?)\<\/PROT\>)\s*\
                                (?:\<HEAD\>\s*(?<Head>[\w\s]+)\s*\<\/HEAD\>)\s*\
                                (?:\<MSG\>\s*(?<Msg>[\w\s]+)\s*\<\/MSG\>)\s*\
                                (?:\<RAW\>\s*(?<Raw>[\w\s]+)\s*\<\/RAW\>)\
                                \s*\<\/OUT\>/

define EQPMDC_BLK_IN_REGEX      /(?x)^\<IN\>(?:\<LINE\>(?<Line>.*?)\<\/LINE\>)\s*\
                                (?:\<TIME\>(\d+.\d+.\d+\s*\d+.\d+.\d+.\d+)\
                                \<\/TIME\>)\s*\
                                (?:\<RAW\>\s*(?<Raw>[\w\s]+)\s*\<\/RAW\>)\s*\
                                (?:\<HEAD\>\s*(?<Head>[\w\s]+)\s*\<\/HEAD\>)\s*\
                                (?:\<MSG\>\s*(?<Msg>[\w\s]+)\s*\<\/MSG\>)\
                                \s*\<\/IN\>/

define EQPMDC_BLK_ITM_REGEX     /(?x)^\<ITM\s*(?:ID\=\"(?<ID>.*?)\")\>\s*\
                                (?:\<RAW\>(?<Raw>.*?)\<\/RAW\>)\s*\
                                (?:\<TM\>(\d+.\d+.\d+\s*\d+.\d+.\d+.\d+.)\
                                \<\/TM\>)\s*\
                                (?:\<VAL\>(?<Val>\d+)\<\/VAL\>)\s*\
                                (?:\<ST\>(?<St>\d+)\<\/ST\>)\s*\<\/ITM\>/

# Part of the log path defined as a constant
define LOG_PATH                 C:\Users\Public\Yokogawa\tls\log

<Extension json>
    Module        xm_json
</Extension>

<Extension multiline_blk_info>
    Module        xm_multiline
    # Regular expression to look for the header of the message
    HeaderLine    /^\<SLAVE\>.*\<\/SLAVE\>/
    EndLine       /^\<INFO\>.*\<\/INFO\>/
</Extension>

<Extension multiline_blk_out>
    Module        xm_multiline
    # Regular expression to look for the header of the message
    HeaderLine    /^\<OUT\>/
    EndLine       /^\<\/OUT\>/
</Extension>

<Extension multiline_blk_in>
    Module        xm_multiline
    # Regular expression to look for the header of the message
    HeaderLine    /^\<IN\>/
    EndLine       /^\<\/IN\>/
</Extension>

<Input from_file>
    Module        im_file
    File          '%LOG_PATH%\EQPMDC.xml'

    <Exec>
        # Matches the events with a regular expression
        if $raw_event =~ %EQPMDC_BLK_ITM_REGEX%
        {
            # Creates the timestamp
            $EventTime = parsedate($3);
            # Formats the result as JSON
            to_json();
        }
        # Discard event if it doesn't match a/the regular expression
        else drop();
        # Replaces unwanted characters
        $raw_event =~ s/\s{2,}/ /g;
    </Exec>
</Input>

<Input from_file_blk_info>
    Module        im_file
    File          '%LOG_PATH%\EQPMDC.xml'
    InputType     multiline_blk_info

    <Exec>
        # Replaces unwanted characters
        $raw_event =~ s/\\n/ /g;
        $raw_event =~ s/\\r/ /g;
        $raw_event =~ s/\s{2,}/ /g;
    </Exec>

    <Exec>
        # Matches the events with a regular expression
        if $raw_event =~ %EQPMDC_BLK_INFO_REGEX%
        {
            $LocalTime = parsedate($2);
            # Formats the result as JSON
            to_json();
        }
        # Discard event if it doesn't match a/the regular expression
        else drop();
    </Exec>
</Input>

<Input from_file_blk_out>
    Module        im_file
    File          '%LOG_PATH%\EQPMDC.xml'
    InputType     multiline_blk_out

    <Exec>
        # Replaces unwanted characters
        $raw_event =~ s/\\n/ /g;
        $raw_event =~ s/\\r/ /g;
        $raw_event =~ s/\s{2,}/ /g;
    </Exec>

    <Exec>
        # Matches the events with a regular expression
        if $raw_event =~ %EQPMDC_BLK_OUT_REGEX%
        {
            # Formats the result as JSON
            to_json();
        }
        # Discard event if it doesn't match a/the regular expression
        else drop();
    </Exec>
</Input>

<Input from_file_blk_in>
    Module        im_file
    File          '%LOG_PATH%\EQPMDC.xml'
    InputType     multiline_blk_in
    <Exec>
        # Replaces unwanted characters
        $raw_event =~ s/\\n/ /g;
        $raw_event =~ s/\\r/ /g;
        $raw_event =~ s/\s{2,}/ /g;
    </Exec>

    <Exec>
        # Matches the events with a regular expression
        if $raw_event =~ %EQPMDC_BLK_IN_REGEX%
        {
            $LocalTime = parsedate($2);
            # Formats the result as JSON
            to_json();
        }
        # Discard event if it doesn't match a/the regular expression
        else drop();
    </Exec>
</Input>

The following output samples depict the processed events in JSON format.

Output sample of the block info part
{
  "EventReceivedTime": "2021-05-26T13:04:53.332375-07:00",
  "SourceModuleName": "from_file_blk_info",
  "SourceModuleType": "im_file",
  "INFO": "Read holding registers 1-10",
  "Slave": "DUMMYSTATION",
  "LocalTime": "2021-05-14T14:22:28.563000-07:00"
}
Output sample of the output data part
{
  "EventReceivedTime": "2021-05-26T13:04:53.332375-07:00",
  "SourceModuleName": "from_file_blk_out",
  "SourceModuleType": "im_file",
  "Head": "87 00 00 00 00 06",
  "Line": "0,0",
  "Msg": "01 03 00 00 00 0A",
  "Prot": "OPEN MODBUS",
  "Raw": "87 00 00 00 00 06 01 03 00 00 00 0A"
}
Output sample of the input data part
{
  "EventReceivedTime": "2021-05-26T13:04:53.332375-07:00",
  "SourceModuleName": "from_file_blk_in",
  "SourceModuleType": "im_file",
  "Head": "87 00 00 00 00 17",
  "Line": "0,0",
  "Msg": "01 03 14 0D F9 0D FA 0D FB 0D FD 0D FE 0D FF 0E 00 0E 01 0D FC 0E 02 ",
  "Raw": "87 00 00 00 00 17 01 03 14 0D F9 0D FA 0D FB 0D FD 0D FE 0D FF 0E 00 0E 01 0D FC 0E 02 ",
  "LocalTime": "2021-05-14T14:22:28.579000-07:00"
}
Output sample of the item data part
{
  "EventReceivedTime": "2021-05-26T13:04:53.332375-07:00",
  "SourceModuleName": "from_file",
  "SourceModuleType": "im_file",
  "ID": "1,1",
  "Raw": "0xDF9",
  "St": "12",
  "Val": "3577",
  "EventTime": "2021-05-14T14:22:28.563000-07:00"
}

Network Monitoring

Yokogawa FAST/TOOLS supports communication with various DCS/PLC/RTU systems and controllers, providing many drivers for proprietary and general-purpose communication protocols.

At the same time, FAST/TOOLS supports OPC functionality, including embedded OPC Unified Architecture (UA) environment and classic OPC for distributed communication (DCOM) links over the network.

NXLog’s im_pcap module provides support to passively monitor network traffic by generating logs for various protocols. The following protocols are considered in the examples below:

Modbus TCP

Modbus is an open, general-purpose industrial protocol based on a master/slave architecture for intersystem communication. The Modbus TCP protocol adapts the widely used Modbus protocol to TCP/IP with Ethernet as the common medium.

Example 17. Collecting Modbus network packets

In this example, the im_pcap module is configured to listen on the \Device\NPF_{159289BE-CE80-47DB-A659-2F8BF277C9C6} network interface for network traffic that uses the Modbus protocol. The result is formatted as JSON then saved to file.

nxlog.conf
<Extension _json>
    Module      xm_json
</Extension>

<Input pcap>
    Module      im_pcap

    # Specifies the name of a network device/interface
    Dev         \Device\NPF_{159289BE-CE80-47DB-A659-2F8BF277C9C6}

    # Specifies the protocol type
    <Protocol>
        Type    modbus
    </Protocol>
</Input>

<Output file>
    Module      om_file
    File        "C:\output.txt"
    
    # Formats the result as JSON
    Exec        to_json();
</Output>
Modbus TCP query sample
{
  "modbus.function_code": "Read Holding Registers (03)",
  "modbus.length": "6",
  "modbus.prot_id": "0",
  "modbus.query.read_holding_regs.qty_of_regs": "10",
  "modbus.query.read_holding_regs.starting_address": "0",
  "modbus.trans_id": "64512",
  "modbus.unit_id": "1",
  "EventTime": "2021-07-14T13:51:49.525579-07:00",
  "EventReceivedTime": "2021-07-14T13:51:49.886997-07:00",
  "SourceModuleName": "pcap",
  "SourceModuleType": "im_pcap"
}
Modbus TCP response sample
{
  "modbus.function_code": "Read Holding Registers (03)",
  "modbus.length": "23",
  "modbus.prot_id": "0",
  "modbus.response.read_holding_regs.byte_count": "20",
  "modbus.response.read_holding_regs.registers": "1942, 1939, 1936, 1934, 1930, 1927, 1924, 1921, 1919, 1916",
  "modbus.trans_id": "64512",
  "modbus.unit_id": "1",
  "EventTime": "2021-07-14T13:51:49.548326-07:00",
  "EventReceivedTime": "2021-07-14T13:51:49.886997-07:00",
  "SourceModuleName": "pcap",
  "SourceModuleType": "im_pcap"
}

BACnet

BACnet (Building Automation Control Network) is a standard data transfer protocol for the interoperability of systems, devices, and control applications, mainly used in building automation.

BACnet defines seven network types as the transport for BACnet messages:

  • BACnet/IP

  • BACnet MS/TP

  • BACnet ISO 8802-3

  • BACnet over ARCNET

  • BACnet Point-to-Point

  • BACnet over LonTalk Foreign Frames

  • BACnet over ZigBee

BACnet/IP uses UDP/IP for compatibility with an existing IP infrastructure.

Example 18. Collecting BACnet network packets

In this example, the im_pcap input module is configured to listen on the \Device\NPF_{159289BE-CE80-47DB-A659-2F8BF277C9C6} network interface for network traffic that uses the BACnet protocol. The result is formatted as JSON then saved to a file.

nxlog.conf
<Extension _json>
    Module      xm_json
</Extension>

<Input pcap>
    Module      im_pcap

    # Specifies the name of a network device/interface
    Dev         \Device\NPF_{159289BE-CE80-47DB-A659-2F8BF277C9C6}

    # Specifies the protocol type
    <Protocol>
        Type    bacnet
    </Protocol>
</Input>

<Output file>
    Module      om_file
    File        "C:\output.txt"
    
    # Formats the result as JSON
    Exec        to_json();
</Output>
BACnet "Confirmed-REQ" sample
{
  "bacnet.apdu.bacnet_confirmed_request.invoke_id": "69",
  "bacnet.apdu.bacnet_confirmed_request.max_resp": "1476",
  "bacnet.apdu.bacnet_confirmed_request.max_segs": "Unspecified",
  "bacnet.apdu.bacnet_confirmed_request.more_segments_follow": "false",
  "bacnet.apdu.bacnet_confirmed_request.segmented": "false",
  "bacnet.apdu.bacnet_confirmed_request.segmented_accepted": "true",
  "bacnet.apdu.bacnet_confirmed_request.service_choice": "Read Property Multiple (14)",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.0.object_identifier.instance_number": "0",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.0.object_identifier.type": "analog-input (0)",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.1": "Opening Tag (1)",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.10.0.property_identifier": "units (117)",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.11": "Closing Tag (1)",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.12.object_identifier.instance_number": "0",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.12.object_identifier.type": "analog-input (0)",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.13": "Opening Tag (1)",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.14.0.property_identifier": "time-delay (113)",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.15": "Closing Tag (1)",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.16.object_identifier.instance_number": "0",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.16.object_identifier.type": "analog-input (0)",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.17": "Opening Tag (1)",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.18.0.property_identifier": "resolution (106)",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.19": "Closing Tag (1)",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.2.0.property_identifier": "update-interval (118)",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.20.object_identifier.instance_number": "0",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.20.object_identifier.type": "analog-input (0)",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.21": "Opening Tag (1)",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.22.0.property_identifier": "reliability (103)",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.23": "Closing Tag (1)",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.24.object_identifier.instance_number": "0",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.24.object_identifier.type": "analog-input (0)",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.25": "Opening Tag (1)",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.26.0.property_identifier": "profile-name (168)",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.27": "Closing Tag (1)",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.28.object_identifier.instance_number": "0",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.28.object_identifier.type": "analog-input (0)",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.29": "Opening Tag (1)",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.3": "Closing Tag (1)",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.30.0.property_identifier": "out-of-service (81)",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.31": "Closing Tag (1)",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.32.object_identifier.instance_number": "0",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.32.object_identifier.type": "analog-input (0)",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.33": "Opening Tag (1)",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.34.0.property_identifier": "object-type (79)",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.35": "Closing Tag (1)",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.4.object_identifier.instance_number": "0",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.4.object_identifier.type": "analog-input (0)",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.5": "Opening Tag (1)",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.6.0.property_identifier": "event-time-stamps (130)",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.7": "Closing Tag (1)",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.8.object_identifier.instance_number": "0",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.8.object_identifier.type": "analog-input (0)",
  "bacnet.apdu.bacnet_confirmed_request.service_request.records.9": "Opening Tag (1)",
  "bacnet.apdu.pdu_type": "BACnet-Confirmed-Request-PDU (0x00)",
  "bacnet.bvlc.function": "Original-Unicast-NPDU (0x0A)",
  "bacnet.bvlc.length": "101",
  "bacnet.bvlc.type": "BACnet/IP (Annex J) (0x81)",
  "bacnet.npdu.control": "0x0024",
  "bacnet.npdu.control.contains": "BACnet APDU message (0)",
  "bacnet.npdu.control.dst_spec": "DNET, DLEN, Hop Count present (1)",
  "bacnet.npdu.control.prio": "Normal message",
  "bacnet.npdu.control.reply_expected": "Yes (1)",
  "bacnet.npdu.control.src_spec": "SNET, SLEN, SADR absent (0)",
  "bacnet.npdu.version": "0x0001",
  "EventTime": "2021-07-24T13:23:49.300690-07:00",
  "EventReceivedTime": "2021-07-24T13:23:50.005135-07:00",
  "SourceModuleName": "pcap",
  "SourceModuleType": "im_pcap"
}
BACnet "Complex-ACK" sample
{
  "bacnet.apdu.bacnet_complexack.more_segments_follow": "false",
  "bacnet.apdu.bacnet_complexack.original_invoke_id": "69",
  "bacnet.apdu.bacnet_complexack.segmented": "false",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.0.0.object_identifier.instance_number": "0",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.0.0.object_identifier.type": "analog-input (0)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.0.1": "Opening Tag (1)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.0.2.property_identifier": "update-interval (118)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.0.3.records.0": "Opening Tag (4)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.0.3.records.1": "100",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.0.3.records.2": "Closing Tag (4)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.0.4": "Closing Tag (1)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.1.0.object_identifier.instance_number": "0",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.1.0.object_identifier.type": "analog-input (0)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.1.1": "Opening Tag (1)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.1.2.property_identifier": "event-time-stamps (130)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.1.3.records.0": "Opening Tag (4)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.1.3.records.1.0.records.0": "Opening Tag",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.1.3.records.1.0.records.1.date": "Any",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.1.3.records.1.0.records.1.time": "Any",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.1.3.records.1.0.records.2": "Closing Tag",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.1.3.records.1.1.records.0": "Opening Tag",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.1.3.records.1.1.records.1.date": "Any",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.1.3.records.1.1.records.1.time": "Any",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.1.3.records.1.1.records.2": "Closing Tag",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.1.3.records.1.2.records.0": "Opening Tag",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.1.3.records.1.2.records.1.date": "Any",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.1.3.records.1.2.records.1.time": "Any",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.1.3.records.1.2.records.2": "Closing Tag",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.1.3.records.2": "Closing Tag (4)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.1.4": "Closing Tag (1)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.2.0.object_identifier.instance_number": "0",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.2.0.object_identifier.type": "analog-input (0)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.2.1": "Opening Tag (1)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.2.2.property_identifier": "units (117)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.2.3.records.0": "Opening Tag (4)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.2.3.records.1.engineering_units": "no-units (95)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.2.3.records.2": "Closing Tag (4)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.2.4": "Closing Tag (1)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.3.0.object_identifier.instance_number": "0",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.3.0.object_identifier.type": "analog-input (0)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.3.1": "Opening Tag (1)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.3.2.property_identifier": "time-delay (113)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.3.3.records.0": "Opening Tag (4)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.3.3.records.1": "10",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.3.3.records.2": "Closing Tag (4)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.3.4": "Closing Tag (1)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.4.0.object_identifier.instance_number": "0",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.4.0.object_identifier.type": "analog-input (0)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.4.1": "Opening Tag (1)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.4.2.property_identifier": "resolution (106)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.4.3.records.0": "Opening Tag (4)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.4.3.records.1": "0.100000",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.4.3.records.2": "Closing Tag (4)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.4.4": "Closing Tag (1)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.5.0.object_identifier.instance_number": "0",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.5.0.object_identifier.type": "analog-input (0)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.5.1": "Opening Tag (1)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.5.2.property_identifier": "reliability (103)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.5.3.records.0": "Opening Tag (4)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.5.3.records.1.reliability": "no-fault-detected (0)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.5.3.records.2": "Closing Tag (4)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.5.4": "Closing Tag (1)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.6.0.object_identifier.instance_number": "0",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.6.0.object_identifier.type": "analog-input (0)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.6.1": "Opening Tag (1)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.6.2.property_identifier": "profile-name (168)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.6.3.records.0": "Opening Tag (4)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.6.3.records.1": "123-0-cbms.simulator.plugin.AiAllProperties (ANSI X3.4/UTF-8 (0))",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.6.3.records.2": "Closing Tag (4)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.6.4": "Closing Tag (1)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.7.0.object_identifier.instance_number": "0",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.7.0.object_identifier.type": "analog-input (0)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.7.1": "Opening Tag (1)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.7.2.property_identifier": "out-of-service (81)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.7.3.records.0": "Opening Tag (4)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.7.3.records.1": "false",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.7.3.records.2": "Closing Tag (4)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.7.4": "Closing Tag (1)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.8.0.object_identifier.instance_number": "0",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.8.0.object_identifier.type": "analog-input (0)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.8.1": "Opening Tag (1)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.8.2.property_identifier": "object-type (79)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.8.3.records.0": "Opening Tag (4)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.8.3.records.1.object_type": "analog-input (0)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.8.3.records.2": "Closing Tag (4)",
  "bacnet.apdu.bacnet_complexack.service_ack.records.0.8.4": "Closing Tag (1)",
  "bacnet.apdu.bacnet_complexack.service_choice": "Read Property Multiple (14)",
  "bacnet.apdu.pdu_type": "BACnet-Complex-ACK-PDU (0x03)",
  "bacnet.bvlc.function": "Original-Unicast-NPDU (0x0A)",
  "bacnet.bvlc.length": "215",
  "bacnet.bvlc.type": "BACnet/IP (Annex J) (0x81)",
  "bacnet.npdu.control": "0x0008",
  "bacnet.npdu.control.contains": "BACnet APDU message (0)",
  "bacnet.npdu.control.dst_spec": "DNET, DLEN, DADR, Hop Count absent (0)",
  "bacnet.npdu.control.prio": "Normal message",
  "bacnet.npdu.control.reply_expected": "No (0)",
  "bacnet.npdu.control.src_spec": "SNET, SLEN, SADR present (1)",
  "bacnet.npdu.version": "0x0001",
  "EventTime": "2021-07-24T13:23:49.405642-07:00",
  "EventReceivedTime": "2021-07-24T13:23:50.005135-07:00",
  "SourceModuleName": "pcap",
  "SourceModuleType": "im_pcap"
}
BACnet "Unconfirmed-REQ" sample
{
  "bacnet.apdu.bacnet_unconfirmed_request.service_choice": "Unconfirmed COV Notification (2)",
  "bacnet.apdu.bacnet_unconfirmed_request.service_choice.records.0.subscriber_process_id": "51895320",
  "bacnet.apdu.bacnet_unconfirmed_request.service_choice.records.1.initiating_device_identifier.instance_number": "1",
  "bacnet.apdu.bacnet_unconfirmed_request.service_choice.records.1.initiating_device_identifier.object_id": "device (8)",
  "bacnet.apdu.bacnet_unconfirmed_request.service_choice.records.2.monitored_device_identifier.instance_number": "0",
  "bacnet.apdu.bacnet_unconfirmed_request.service_choice.records.2.monitored_device_identifier.object_id": "analog-input (0)",
  "bacnet.apdu.bacnet_unconfirmed_request.service_choice.records.3.time_remaining": "3310",
  "bacnet.apdu.bacnet_unconfirmed_request.service_choice.records.4": "Opening Tag (4)",
  "bacnet.apdu.bacnet_unconfirmed_request.service_choice.records.5.0.property_identifier": "present-value (85)",
  "bacnet.apdu.bacnet_unconfirmed_request.service_choice.records.5.0.property_value.records.0": "Opening Tag (2)",
  "bacnet.apdu.bacnet_unconfirmed_request.service_choice.records.5.0.property_value.records.1": "731000.125000",
  "bacnet.apdu.bacnet_unconfirmed_request.service_choice.records.5.0.property_value.records.2": "Closing Tag (2)",
  "bacnet.apdu.bacnet_unconfirmed_request.service_choice.records.5.1.property_identifier": "status-flags (111)",
  "bacnet.apdu.bacnet_unconfirmed_request.service_choice.records.5.1.property_value.records.0": "Opening Tag (2)",
  "bacnet.apdu.bacnet_unconfirmed_request.service_choice.records.5.1.property_value.records.1": "in-alarm (0): false, fault (1): false, overriden (2): false, out-of-service (3): false",
  "bacnet.apdu.bacnet_unconfirmed_request.service_choice.records.5.1.property_value.records.2": "Closing Tag (2)",
  "bacnet.apdu.bacnet_unconfirmed_request.service_choice.records.6": "Closing Tag (4)",
  "bacnet.apdu.pdu_type": "BACnet-Unconfirmed-Request-PDU (0x01)",
  "bacnet.bvlc.function": "Original-Unicast-NPDU (0x0A)",
  "bacnet.bvlc.length": "44",
  "bacnet.bvlc.type": "BACnet/IP (Annex J) (0x81)",
  "bacnet.npdu.control": "0x0000",
  "bacnet.npdu.control.contains": "BACnet APDU message (0)",
  "bacnet.npdu.control.dst_spec": "DNET, DLEN, DADR, Hop Count absent (0)",
  "bacnet.npdu.control.prio": "Normal message",
  "bacnet.npdu.control.reply_expected": "No (0)",
  "bacnet.npdu.control.src_spec": "SNET, SLEN, SADR absent (0)",
  "bacnet.npdu.version": "0x0001",
  "EventTime": "2021-07-24T13:23:49.385044-07:00",
  "EventReceivedTime": "2021-07-24T13:23:50.005135-07:00",
  "SourceModuleName": "pcap",
  "SourceModuleType": "im_pcap"
}

DNP3

DNP3 (Distributed Network Protocol Version 3.0) is an open SCADA protocol used for communication between substation computers, RTUs (Remote Terminal Units), IEDs (Intelligent Electronic Devices), and Master Stations.

DNP3 is mainly used for substation automation to monitor and control equipment, for example, monitoring current and voltage transducers to close circuit breakers, open or close valves, or regulate pressure.

DNP3 is a layered protocol that follows EPA (Enhanced Performance Architecture), a simplified three-layer standard including the physical, data link, and application layers. However, DNP3 adds a fourth layer to EPA, a pseudo-transport layer that allows for message segmentation.

Example 19. Collecting DNP3 network packets

In this example, the im_pcap input module is configured to listen on the \Device\NPF_{159289BE-CE80-47DB-A659-2F8BF277C9C6} network interface for network traffic that uses the DNP3 protocol subsets Level 1 and Level 2. The result is formatted as JSON, then saved to file.

nxlog.conf
<Extension _json>
    Module      xm_json
</Extension>

<Input pcap>
    Module      im_pcap

    # Specifies the name of a network device/interface
    Dev         \Device\NPF_{159289BE-CE80-47DB-A659-2F8BF277C9C6}

    # Specifies the protocol type
    <Protocol>
        Type    dnp3
    </Protocol>
</Input>

<Output file>
    Module      om_file
    File        "C:\output.txt"

    # Formats the result as JSON
    Exec        to_json();
</Output>
DNP3 unsolicited response sample
{
  "dnp3.application_layer.control.con": "1",
  "dnp3.application_layer.control.fin": "1",
  "dnp3.application_layer.control.fir": "1",
  "dnp3.application_layer.control.sequence": "5",
  "dnp3.application_layer.control.uns": "1",
  "dnp3.application_layer.function_code": "Unsolicited Response",
  "dnp3.application_layer.internal_indications.already_executing": "0",
  "dnp3.application_layer.internal_indications.broadcast": "0",
  "dnp3.application_layer.internal_indications.class1_events": "0",
  "dnp3.application_layer.internal_indications.class2_events": "0",
  "dnp3.application_layer.internal_indications.class3_events": "0",
  "dnp3.application_layer.internal_indications.config_corrupt": "0",
  "dnp3.application_layer.internal_indications.device_restart": "0",
  "dnp3.application_layer.internal_indications.device_trouble": "0",
  "dnp3.application_layer.internal_indications.events_buffer_overflow": "0",
  "dnp3.application_layer.internal_indications.local_control": "0",
  "dnp3.application_layer.internal_indications.need_time": "0",
  "dnp3.application_layer.internal_indications.no_func_code_support": "0",
  "dnp3.application_layer.internal_indications.object_unknown": "0",
  "dnp3.application_layer.internal_indications.parameter_error": "0",
  "dnp3.application_layer.internal_indications.reserved": "0 (expected 0)",
  "dnp3.application_layer.object0.count": "3",
  "dnp3.application_layer.object0.group": "32",
  "dnp3.application_layer.object0.name": "Analog input event - single-precision, floating-point with time",
  "dnp3.application_layer.object0.point0.flags": "[ONLINE]",
  "dnp3.application_layer.object0.point0.index": "0",
  "dnp3.application_layer.object0.point0.time_of_occurance": "1626937226148",
  "dnp3.application_layer.object0.point0.value": "14932.826172",
  "dnp3.application_layer.object0.point1.flags": "[ONLINE]",
  "dnp3.application_layer.object0.point1.index": "1",
  "dnp3.application_layer.object0.point1.time_of_occurance": "1626937226148",
  "dnp3.application_layer.object0.point1.value": "1090.492310",
  "dnp3.application_layer.object0.point2.flags": "[ONLINE]",
  "dnp3.application_layer.object0.point2.index": "2",
  "dnp3.application_layer.object0.point2.time_of_occurance": "1626937226148",
  "dnp3.application_layer.object0.point2.value": "29280.162109",
  "dnp3.application_layer.object0.range": "2-octet count of objects",
  "dnp3.application_layer.object0.variation": "7",
  "dnp3.data_layer.control": "0x44",
  "dnp3.data_layer.control.dir": "0",
  "dnp3.data_layer.control.fcb": "0",
  "dnp3.data_layer.control.fcv": "0",
  "dnp3.data_layer.control.function_code": "Unconfirmed User Data",
  "dnp3.data_layer.control.prm": "1",
  "dnp3.data_layer.destination": "2",
  "dnp3.data_layer.length": "54",
  "dnp3.data_layer.source": "1",
  "dnp3.data_layer.start_bytes": "0x0564",
  "dnp3.transport.fin": "1",
  "dnp3.transport.fir": "1",
  "dnp3.transport.sequence": "47",
  "EventTime": "2021-07-22T07:00:26.174124-07:00",
  "EventReceivedTime": "2021-07-22T07:00:26.774308-07:00",
  "SourceModuleName": "pcap",
  "SourceModuleType": "im_pcap"
}
DNP3 confirm sample
{
  "dnp3.application_layer.control.con": "0",
  "dnp3.application_layer.control.fin": "1",
  "dnp3.application_layer.control.fir": "1",
  "dnp3.application_layer.control.sequence": "5",
  "dnp3.application_layer.control.uns": "1",
  "dnp3.application_layer.function_code": "Confirm",
  "dnp3.data_layer.control": "0xC4",
  "dnp3.data_layer.control.dir": "1",
  "dnp3.data_layer.control.fcb": "0",
  "dnp3.data_layer.control.fcv": "0",
  "dnp3.data_layer.control.function_code": "Unconfirmed User Data",
  "dnp3.data_layer.control.prm": "1",
  "dnp3.data_layer.destination": "1",
  "dnp3.data_layer.length": "8",
  "dnp3.data_layer.source": "2",
  "dnp3.data_layer.start_bytes": "0x0564",
  "dnp3.transport.fin": "1",
  "dnp3.transport.fir": "1",
  "dnp3.transport.sequence": "29",
  "EventTime": "2021-07-22T07:00:26.200221-07:00",
  "EventReceivedTime": "2021-07-22T07:00:26.774308-07:00",
  "SourceModuleName": "pcap",
  "SourceModuleType": "im_pcap"
}

IEC 60870-5-104

IEC 60870-5-104 and IEC 60870-5-101 are derived from the IEC 60870-5 protocol standard definition based on the reduced reference model called EPA (Enhanced Performance Architecture).

EPA includes three layers of the ISO-OSI model:

  • Application layer

  • Link layer

  • Physical layer

IEC 61870-5-101 and IEC 60870-5-104 are the companion standards based on the same application and transport layer profiles. However, IEC 60870-5-104 includes a network link layer specification for ETHERNET/TCP communication.

Example 20. Collecting IEC 60870-5-104 network packets

In this example, the im_pcap input module is configured to listen on the \Device\NPF_{159289BE-CE80-47DB-A659-2F8BF277C9C6} network interface for network traffic that uses the IEC 60870-5-104 protocol. The result is formatted as JSON then saved to a file.

nxlog.conf
<Extension _json>
    Module      xm_json
</Extension>

<Input pcap>
    Module      im_pcap

    # Specifies the name of a network device/interface
    Dev         \Device\NPF_{159289BE-CE80-47DB-A659-2F8BF277C9C6}

    # Specifies the protocol type
    <Protocol>
        Type    iec104apci
    </Protocol>
    <Protocol>
        Type    iec104asdu
    </Protocol>
</Input>

<Output file>
    Module      om_file
    File        "C:\output.txt"

    # Formats the result as JSON
    Exec        to_json();
</Output>
IEC 60870-5-104 sample
{
  "iec104.apci.receive_sequence_number": "65",
  "iec104.apci.send_sequence_number": "2682",
  "iec104.apci.type": "Information (I)",
  "iec104.asdu.data": {
    "io": [
      {
        "ioa": 1,
        "ie": [
          {
            "type": "R32",
            "value": 3.299999952316284
          },
          {
            "type": "QDS",
            "invalid": false,
            "not-topical": false,
            "substituted": false,
            "blocked": false,
            "overflow": false
          },
          {
            "type": "CP56Time2A",
            "milliseconds": 12744,
            "minutes": 18,
            "hours": 1,
            "day-of-week": 0,
            "day-of-month": 26,
            "month": 7,
            "year": 21
          }
        ],
        "ies": 3
      },
      {
        "ioa": 2,
        "ie": [
          {
            "type": "R32",
            "value": 115
          },
          {
            "type": "QDS",
            "invalid": false,
            "not-topical": false,
            "substituted": false,
            "blocked": false,
            "overflow": false
          },
          {
            "type": "CP56Time2A",
            "milliseconds": 12744,
            "minutes": 18,
            "hours": 1,
            "day-of-week": 0,
            "day-of-month": 26,
            "month": 7,
            "year": 21
          }
        ],
        "ies": 3
      }
    ],
    "ios": 2
  },
  "iec104.asdu.dui.cause_of_transmission": "Spontaneous (3)",
  "iec104.asdu.dui.coa": "1",
  "iec104.asdu.dui.num_records": "2",
  "iec104.asdu.dui.org": "0",
  "iec104.asdu.dui.pn": "0",
  "iec104.asdu.dui.sq": "FALSE",
  "iec104.asdu.dui.test_bit": "0",
  "iec104.asdu.dui.type": "M_ME_TF_1",
  "EventTime": "2021-07-26T01:18:12.705559-07:00",
  "EventReceivedTime": "2021-07-26T01:18:13.403974-07:00",
  "SourceModuleName": "pcap",
  "SourceModuleType": "im_pcap"
}
Disclaimer

While we endeavor to keep the information in this topic up to date and correct, NXLog makes no representations or warranties of any kind, express or implied about the completeness, accuracy, reliability, suitability, or availability of the content represented here.

The accurateness of the content was tested and proved to be working in our lab environment at the time of the last revision with the following software versions:

Yokogawa FAST/TOOLS R9.04
NXLog version 5.3.7166

Last revision: 09 February 2022