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.
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.
| Log type | File name |
|---|---|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
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.
The following two input samples are taken from umhlog.log and
fast_start.log respectively.
--> 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--> 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:8080The 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.
--> From: OPCEXE (Node 1/Task -1) on Thu May 27 06:51:36 2021Based on this header, the following fields can be parsed:
-
Process
-
Node
-
Task
-
Timestamp (ANSI C asctime() format)
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+)/GIN-I-DII_INI_FLW, Flow control started for node 1Based on this type of event, the following fields can be parsed:
-
Component
-
Message
define UMHLOGTOO_TYPE1_REGEX /(?x)^(?:(?<Component>[A-Z]+[\w\-]+)\s*\,\s*\
(?<Message>.*))/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 overrangedBased on the second type of event, the following fields can be parsed:
-
Priority
-
Type
-
Time raised
-
Instance
-
Unit
-
Item
-
Text
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>.*)/REPORT/FAST started
ACCESS/FAST started
USER Web servers started
FAST/Start started
INTEGRATION started
FAST/TOOLS startedThe third type of event contains information about FAST/TOOLS
started bricks and can be parsed as a single field called Message.
define UMHLOGTOO_TYPE3_REGEX /(?x)^(?<Message>[A-Z]{2,}[^\,]*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:8080Based on the fourth type of event, the following fields can be parsed:
-
Timestamp (yyyy-mm-dd hh:mm:ss.xxx)
-
Severity
-
Message
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.
# 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.
{
"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"
}{
"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"
}{
"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"
}{
"EventReceivedTime": "2021-05-27T06:51:37.121883-07:00",
"SourceModuleName": "from_file",
"SourceModuleType": "im_file",
"Message": "REPORT/FAST started"
}{
"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.
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.
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.127The 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
define SMDMON_TYPE1_REGEX /(?x)^(\d+.\d+.\d+.\d+.\d+.\d+).\d+\s*>>\s*\(\
(?<Process>.*?)\)\s*(?<Message>.*)/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.oldThe 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
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.
# 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.
{
"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"
}{
"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.
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.
##[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
define SMD_ALMDBG_REQ_REGEX /(?x)^\#\#\[(?<ID>\d+)\]\
\[(?<Process>\w+)[\s\<\>]*(?<Commands>.*?)\]\
\[(?<Comment>.*?)\]\[(\d+.\d+.\d+.\d+.\d+.\d+)\
.\d+\]/---- 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
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>.*))/---- 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
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.
# 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.
{
"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"
}{
"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"
}{
"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.
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.
##[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
define SMD_DSSXDB_REQ_REGEX /(?x)^\#\#\[(?<ID>\d+)\]\
\[(?<Process>\w+)[\s\<\>]*(?<Commands>.*?)\]\
\[(?<Comment>.*?)\]\[(\d+.\d+.\d+.\d+.\d+.\d+).\
\d+\]/---- 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
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.
# 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.
{
"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"
}{
"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.
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.
##[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
define SMD_DURDBG_REQ_REGEX /(?x)^\#\#\[(?<ID>\d+)\]\[\
(?<Process>.*?)\s*\<\s*\
(?<Commands>.*?)\s*\]\[\
(?<Comment>.*?)\]\[\
(\d+.\d+.\d+.\d+.\d+.\d+).\d+\]/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-00The 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
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.
DUR 0 0 525 5769340
ISM 0 0 5 5769340
ITM 0 0 4 5769340The following fields can be parsed from the locking info:
-
LockID
-
PID
-
LockFlag
-
Collisions
-
LockSemID
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.
# 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.
{
"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"
}{
"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"
}{
"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).
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.
##[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
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.
# 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.
{
"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.
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.
##[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
define SMD_EQPDBG_REQ_REGEX /(?x)^\#\#\[(?<ID>\d+)\]\[\
(?<Process>\w+)[\s\<\>]*\
(?<Commands>.*?)\]\[\
(?<Comment>.*?)\]\[\
(\d+.\d+.\d+.\d+.\d+.\d+).\d+\]/---- 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
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*\.*/---- 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
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*.*/---- 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
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*))/ 105 1000 1 1 2 0 0 0 0.000
104 1000 10 1 20 236 2360 2350 0.000The 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
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\-\.]+)/Total : 11 2 22 236 2360 2350 0.000The 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
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.
# 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.
{
"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"
}{
"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"
}{
"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"
}{
"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"
}{
"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"
}{
"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.
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.
##[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
define SMD_HISDBG_REQ_REGEX /(?x)^\#\#\[(?<ID>\d+)\]\[\
(?<Process>\w+)[\s\<\>]*\
(?<Commands>.*?)\]\[\
(?<Comment>.*?)\]\[\
(\d+.\d+.\d+.\d+.\d+.\d+).\d+\]/---- 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
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.
# 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.
{
"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"
}{
"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.
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.
##[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
define SMD_ISMDBG_REQ_REGEX /(?x)^\#\#\[(?<ID>\d+)\]\[\
(?<Process>\w+)[\s\<\>]*\
(?<Commands>.*?)\]\[\
(?<Comment>.*?)\]\[\
(\d+.\d+.\d+.\d+.\d+.\d+).\d+\]/ 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.
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>.*)/ 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.
define SMD_ISMDBG_TYPE2_REGEX /(?x)^\s*(?<No>\d+)\s*\
(?<File>\d+\:.*?\.d\d+)\s*\
(?<Lck>\w+)\s*\
(?<Users>.*)/User: 60 DSSEVT00
Next event sequence: 1, Time of last event: 1621847151
Flow: YES, Msg id: 4306, Timeout: 60, Next flow sequence: 21The following fields can be parsed from the subscriptions header:
-
User
-
NextEventSequence
-
TimeOfLastEvent
-
Flow
-
MsgID
-
Timeout
-
NextFlowSequence
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+))/ 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_RECORDThe following fields can be parsed from the subscription item:
-
File
-
EvtID
-
MsgID
-
RefID
-
Criteria
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.
# 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.
{
"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"
}{
"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"
}{
"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 "
}{
"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"
}{
"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.
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.
##[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
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.
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 exitThis section displays global information about the ITHSER process and contains the following fields:
-
Initialised_at
-
TotalRequests
-
TotalRetrieveRequests
-
TotalIIBHits
-
TotalHISUnitInfoRequests
-
TotalIIBs
-
TotalIUPs
-
TotalIUBs
-
TotalUCBs
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.
# 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.
{
"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"
}{
"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.
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.
##[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
define SMD_ITMDBG_REQ_REGEX /(?x)^\#\#\[(?<ID>\d+)\]\[\
(?<Process>\w+)[\s\<\>]*\
(?<Commands>.*?)\]\[\
(?<Comment>.*?)\]\[\
(\d+.\d+.\d+.\d+.\d+.\d+).\d+\]/-- 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
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.*/-- 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
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]+)$/-- 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
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+)$/-- 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
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+)$/-- 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
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.
# 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.
{
"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"
}{
"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"
}{
"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"
}{
"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"
}{
"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"
}{
"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.
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.
##[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
define SMD_OPCDBG_REQ_REGEX /(?x)^\#\#\[(?<ID>\d+)\]\[\
(?<Process>\w+)[\s\<\>]*\
(?<Commands>.*?)\]\[\
(?<Comment>.*?)\]\[\
(\d+.\d+.\d+.\d+.\d+.\d+).\d+\]/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.
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.
# 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.
{
"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"
}{
"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.
The following input sample is taken from smd_*_smdsnp_general.log.
##[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 2021General 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.
##[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
define SMD_SMDSNP_GEN_REQ_REGEX /(?x)^\#\#\[(?<ID>\d+)\]\[\
(?<Process>\w+)[\s\<\>]*\
(?<Commands>.*?)\]\[\
(?<Comment>.*?)\]\[\
(\d+.\d+.\d+.\d+.\d+.\d+).\d+\]/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 2021The 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
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.
# 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.
{
"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"
}{
"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.
The following input sample is taken from smd_*_smdsnp_lock.log.
##[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 | | 0SMDSNP 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.
##[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
define SMD_SMDSNP_LOCK_REQ_REGEX /(?x)^\#\#\[(?<ID>\d+)\]\[\
(?<Process>\w+)[\s\<\>]*\
(?<Commands>.*?)\]\[\
(?<Comment>.*?)\]\[\
(\d+.\d+.\d+.\d+.\d+.\d+).\d+\]/lock_name | Locked by | collisions
-------------+--------------+-----------
DUR | | 166
ISM | | 3
ITM | | 5
CWS | | 0
DSS-API | | 0
DSS-LCK | | 0
EQP_VNET | | 0The 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.
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.
# 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.
{
"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"
}{
"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.
The following input sample is taken from smd_*_smdsnp_process.log.
##[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 | 0SMDSNP 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.
##[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
define SMD_SMDSNP_PROC_REQ_REGEX /(?x)^\#\#\[(?<ID>\d+)\]\[\
(?<Process>\w+)[\s\<\>]*\
(?<Commands>.*?)\]\[\
(?<Comment>.*?)\]\[\
(\d+.\d+.\d+.\d+.\d+.\d+).\d+\]/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 | 0The 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.
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.
# 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.
{
"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"
}{
"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.
The following sample is taken from EQPMDC.xml.
<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.
<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
define EQPMDC_BLK_INFO_REGEX /(?x)^(?:\<SLAVE\>(?<Slave>.*?)\<\/SLAVE\>)\s*\
(?:\<TIME\>(\d+.\d+.\d+\s*\d+.\d+.\d+.\d+)\
\<\/TIME\>)\s*\
(?:\<INFO\>(?<INFO>.*?)\<\/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>The output data part consists of the following fields:
-
Line
-
Prot
-
Head
-
Msg
-
Raw
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\>/<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
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\>/<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
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.
# 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.
{
"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"
}{
"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"
}{
"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"
}{
"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.
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.
<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.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.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.
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.
<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.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.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.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.
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.
<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.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.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.
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.
<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>{
"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"
}