Wiresharking IEC: Difference between revisions

From Phobos Wiki
Jump to navigation Jump to search
Line 79: Line 79:
</pre>
</pre>
Read more about COTP: https://wiki.wireshark.org/COTP
Read more about COTP: https://wiki.wireshark.org/COTP
Step 3. MMS CONNECT and ACCEPT
Step 3. MMS CONNECT and ACCEPT
  <pre>  
  <pre>  
Line 263: Line 264:
</pre>
</pre>
Step11. Send GI
Step11. Send GI
<pre>
2015-08-06 10:30:18.743 [INFO] Gateway.Port14 - Send GI, 255Relay/LLN0.brcbEV103
</pre>
In MMS, the RTU writes the LLN0$BR$brcbEV103$GI item to value 1, receives a response (success) and finally receives an "unconfirmed PDU" containing all the items that respond to GI in that dataset (in my case, 72 items)
<pre>
10:30:18.292709 10.0.0.104 172.16.1.3 MMS 126 confirmed-RequestPDU (MMS -> confirmedServiceRequest: write (5); itemId: LLN0$BR$brcbEV103$GI; boolean: True)
138 2015-08-06 10:30:18.742140 172.16.1.3 10.0.0.104 MMS 84 confirmed-ResponsePDU (MMS -> confirmedServiceResponse: write (5); Write-Response item: success (1); )
10:30:19.076348 172.16.1.3 10.0.0.104 MMS 444 unconfirmed-PDU (MMS -> unconfirmedService: informationReport (0); vmd-specific: RPT; listOfAccessResult: 72 items; AccessResult: success (1); visible-string: 255Relay/LLN0$BR$brcbEV103;
THIS IS GI RESPONSE WITH ALL VARIABLES AND PARAMETERS)
</pre>
The information gathered from GI response looks like this in the console.log:
<pre>
2015-08-06 10:30:19.749 [DEBUG] Gateway.Port14 - rptId=255Relay/LLN0$BR$brcbEV103,confRev=2053,datSet=255Relay/LLN0$DS1,entryId='000000000000000a',time=08/06/2015_07:30:18.471
2015-08-06 10:30:19.749 [DEBUG] Gateway.Port14 - 255Relay/I3pMMXU1$MX$A$phsA={{{f0.000000e+00}},[0000000000000],(u08/06/2015_07:21:14.532,[00110100])} [general-interrogation] => object not configured
2015-08-06 10:30:19.784 [DEBUG] Gateway.Port14 - 255Relay/I3pMMXU1$MX$A$phsB={{{f0.000000e+00}},[0000000000000],(u08/06/2015_07:21:14.532,[00110100])} [general-interrogation] => object not configured
2015-08-06 10:30:19.824 [DEBUG] Gateway.Port14 - 255Relay/I3pMMXU1$MX$A$phsC={{{f0.000000e+00}},[0000000000000],(u08/06/2015_07:21:14.533,[00110100])} [general-interrogation] => object not configured
2015-08-06 10:30:19.864 [DEBUG] Gateway.Port14 - rcv DI 255Relay/Obj1CSWI1$ST$Pos <> id - 1 <> val=01(1),time=u08/06/2015_07:21:14.663,[00110100],quality=0000000000000,reason=[general-interrogation],type=bitString
2015-08-06 10:30:19.865 [INFO] Gateway.Port14.db - obj1 st (255Relay/Obj1CSWI1$ST$Pos) event: 1 flags: GwTime GI  time: 2015-Aug-06 07:30:19.865107, received
2015-08-06 10:30:19.904 [DEBUG] Gateway.Port14 - rcv DI 255Relay/Obj1CSWI1$ST$BlkCls <> id - 2 <> val=F(1),time=u08/06/2015_07:21:14.534,[00110100],quality=0000000000000,reason=[general-interrogation],type=bool
2015-08-06 10:30:19.905 [INFO] Gateway.Port14.db -  (255Relay/Obj1CSWI1$ST$BlkCls) event: 1 flags: GwTime GI  time: 2015-Aug-06 07:30:19.905003, received
2015-08-06 10:30:19.944 [DEBUG] Gateway.Port14 - rcv DI 255Relay/Obj1CSWI1$ST$BlkOpn <> id - 3 <> val=F(1),time=u08/06/2015_07:21:14.534,[00110100],quality=0000000000000,reason=[general-interrogation],type=bool
2015-08-06 10:30:19.945 [INFO] Gateway.Port14.db -  (255Relay/Obj1CSWI1$ST$BlkOpn) event: 1 flags: GwTime GI  time: 2015-Aug-06 07:30:19.945055, received
2015-08-06 10:30:19.984 [DEBUG] Gateway.Port14 - rcv DI 255Relay/Obj2CSWI2$ST$Pos <> id - 4 <> val=01(1),time=u08/06/2015_07:26:54.499,[00010100],quality=0000000000000,reason=[general-interrogation],type=bitString
2015-08-06 10:30:19.985 [INFO] Gateway.Port14.db - obj2 st (255Relay/Obj2CSWI2$ST$Pos) event: 1 flags: GwTime GI  time: 2015-Aug-06 07:30:19.984973, received
2015-08-06 10:30:20.024 [DEBUG] Gateway.Port14 - rcv DI 255Relay/Obj2CSWI2$ST$BlkCls <> id - 5 <> val=F(1),time=u08/06/2015_07:21:14.534,[00110100],quality=0000000000000,reason=[general-interrogation],type=bool
2015-08-06 10:30:20.025 [INFO] Gateway.Port14.db -  (255Relay/Obj2CSWI2$ST$BlkCls) event: 1 flags: GwTime GI  time: 2015-Aug-06 07:30:20.025046, received
2015-08-06 10:30:20.064 [DEBUG] Gateway.Port14 - rcv DI 255Relay/Obj2CSWI2$ST$BlkOpn <> id - 6 <> val=F(1),time=u08/06/2015_07:21:14.534,[00110100],quality=0000000000000,reason=[general-interrogation],type=bool
2015-08-06 10:30:20.065 [INFO] Gateway.Port14.db -  (255Relay/Obj2CSWI2$ST$BlkOpn) event: 1 flags: GwTime GI  time: 2015-Aug-06 07:30:20.065085, received
2015-08-06 10:30:20.107 [DEBUG] Gateway.Port14 - rcv DI 255Relay/Obj3CSWI3$ST$Pos <> id - 7 <> val=00(0),time=u08/06/2015_07:21:14.535,[00110100],quality=0000000000000,reason=[general-interrogation],type=bitString
2015-08-06 10:30:20.107 [INFO] Gateway.Port14.db - obj3 st (255Relay/Obj3CSWI3$ST$Pos) event: 0 flags: GwTime GI  time: 2015-Aug-06 07:30:20.107382, received
2015-08-06 10:30:20.145 [DEBUG] Gateway.Port14 - rcv DI 255Relay/Obj3CSWI3$ST$BlkCls <> id - 8 <> val=F(1),time=u08/06/2015_07:21:14.535,[00110100],quality=0000000000000,reason=[general-interrogation],type=bool
2015-08-06 10:30:20.145 [INFO] Gateway.Port14.db -  (255Relay/Obj3CSWI3$ST$BlkCls) event: 1 flags: GwTime GI  time: 2015-Aug-06 07:30:20.145250, received
2015-08-06 10:30:20.185 [DEBUG] Gateway.Port14 - rcv DI 255Relay/Obj3CSWI3$ST$BlkOpn <> id - 9 <> val=F(1),time=u08/06/2015_07:21:14.535,[00110100],quality=0000000000000,reason=[general-interrogation],type=bool
2015-08-06 10:30:20.185 [INFO] Gateway.Port14.db -  (255Relay/Obj3CSWI3$ST$BlkOpn) event: 1 flags: GwTime GI  time: 2015-Aug-06 07:30:20.185352, received
2015-08-06 10:30:20.224 [DEBUG] Gateway.Port14 - 255Relay/U3pMMXU4$MX$PhV$phsA={{{f0.000000e+00}},[0000000000000],(u08/06/2015_07:21:14.536,[00110100])} [general-interrogation] => object not configured
2015-08-06 10:30:20.264 [DEBUG] Gateway.Port14 - 255Relay/U3pMMXU4$MX$PhV$phsB={{{f0.000000e+00}},[0000000000000],(u08/06/2015_07:21:14.536,[00110100])} [general-interrogation] => object not configured
2015-08-06 10:30:20.304 [DEBUG] Gateway.Port14 - 255Relay/U3pMMXU4$MX$PhV$phsC={{{f0.000000e+00}},[0000000000000],(u08/06/2015_07:21:14.536,[00110100])} [general-interrogation] => object not configured
2015-08-06 10:30:20.344 [DEBUG] Gateway.Port14 - 255Relay/U3ppMMXU5$MX$PPV$phsAB={{{f0.000000e+00}},[0000000000000],(u08/06/2015_07:21:14.537,[00110100])} [general-interrogation] => object not configured
2015-08-06 10:30:20.384 [DEBUG] Gateway.Port14 - 255Relay/U3ppMMXU5$MX$PPV$phsBC={{{f0.000000e+00}},[0000000000000],(u08/06/2015_07:21:14.537,[00110100])} [general-interrogation] => object not configured
2015-08-06 10:30:20.424 [DEBUG] Gateway.Port14 - 255Relay/U3ppMMXU5$MX$PPV$phsCA={{{f0.000000e+00}},[0000000000000],(u08/06/2015_07:21:14.538,[00110100])} [general-interrogation] => object not configured
2015-08-06 10:30:20.464 [DEBUG] Gateway.Port14 - 255Relay/UoMMXU10$MX$PhV$neut={{{f0.000000e+00}},[0000000000000],(u08/06/2015_07:21:14.538,[00110100])} [general-interrogation] => object not configured
2015-08-06 10:30:20.504 [DEBUG] Gateway.Port14 - rcv DI 255Relay/VI1GGIO137$ST$SPCSO <> id - 10 <> val=T(2),time=u08/06/2015_07:21:14.539,[00110100],quality=0000000000000,reason=[general-interrogation],type=bool
2015-08-06 10:30:20.505 [INFO] Gateway.Port14.db - vi1 st (255Relay/VI1GGIO137$ST$SPCSO) event: 2 flags: GwTime GI  time: 2015-Aug-06 07:30:20.504983, received
2015-08-06 10:30:20.544 [DEBUG] Gateway.Port14 - 255Relay/SIpMMXU23$MX$A={{{{f0.000000e+00}},[0000000000000],(u08/06/2015_07:21:14.539,[00110100])},{{{f0.000000e+00}},[0000000000000],(u08/06/2015_07:21:14.540,[00110100])},{{{f0.000000e+00}},[0000000000000],(u08/06/2015_07:21:14.540,[00110100])}} [general-interrogation] => object not configured
</pre>
Step12. Send control command
Before control command is sent, RTU reads the attributes of items Obj2CSWI2$CO$Pos$Oper$ctlVal and Obj2CSWI2$CO$Pos :
<pre>
146 2015-08-06 10:30:31.630020 10.0.0.104 172.16.1.3 MMS 125 confirmed-RequestPDU (MMS -> confirmedServiceRequest: getVariableAccessAttributes (6); domainId: 255Relay; itemId: Obj2CSWI2$CO$Pos$Oper$ctlVal)
148 2015-08-06 10:30:32.021978 172.16.1.3 10.0.0.104 MMS 88 confirmed-ResponsePDU (MMS -> confirmedServiceResponse: getVariableAccessAttributes (6); typeSpecification: boolean (3))
150 2015-08-06 10:30:32.064158 10.0.0.104 172.16.1.3 MMS 113 confirmed-RequestPDU (MMS -> confirmedServiceRequest: getVariableAccessAttributes (6); domainId: 255Relay; itemId: Obj2CSWI2$CO$Pos)
152 2015-08-06 10:30:32.536409 172.16.1.3 10.0.0.104 MMS 466 confirmed-ResponsePDU (MMS -> confirmedServiceResponse: getVariableAccessAttributes (6); components: 3 items;)
</pre>
RTU writes the current state of control object and sends the write (Select) command:
<pre>
2015-08-06 10:30:32.549 [INFO] Gateway.Port14 - DO selectWithValue() service Obj2CSWI2/255Relay$CO$Pos$Oper={T,(u08/06/2015_07:30:32.024,[00000000]),F,[01]} => interlock-check=Yes, synchrocheck=no
2015-08-06 10:30:33.015 [INFO] Gateway.Port14.db - obj2 co (255Relay/Obj2CSWI2$CO$Pos) response: 2 flags: Select Activation  time: 2015-Aug-06 07:30:35.155000, recv
2015-08-06 10:30:33.019 [INFO] Gateway.WebServer.db - obj2 co (112) event: 2 flags: Select Activation OK GwTime  time: 2015-Aug-06 10:30:33.015925, sent
</pre>
In MMS:
<pre>
154 2015-08-06 10:30:32.557450 10.0.0.104 172.16.1.3 MMS 158 confirmed-RequestPDU (MMS -> confirmedServiceRequest: write (5); domainId: 255Relay; itemId: Obj2CSWI2$CO$Pos$SBOw; listOfData: 1 item;)
156 2015-08-06 10:30:33.013975 172.16.1.3 10.0.0.104 MMS 84 confirmed-ResponsePDU (MMS -> confirmedServiceResponse: write (5); Write-Response item: success (1))
</pre>
Next, send the write command for execute:
<pre>
2015-08-06 10:30:34.942 [DEBUG] Gateway.WebServer - control id: DO_14_0_12 vType: DO v: 2 t: 2015-08-06 10:30:39.015 act: 1 sel: 0
2015-08-06 10:30:34.944 [INFO] Gateway.WebServer.db - obj2 co (112) control: 2 flags: Execute Activation  time: 2015-Aug-06 10:30:39.015000, recv
2015-08-06 10:30:35.024 [INFO] Gateway.Port14.db - obj2 co (255Relay/Obj2CSWI2$CO$Pos) control: 2 flags: Execute Activation  time: 2015-Aug-06 07:30:39.015000, sent
</pre>
<pre>
10:30:35.076529 10.0.0.104 172.16.1.3 MMS 158 confirmed-RequestPDU (MMS-> confirmedServiceRequest: write (5); itemId: Obj2CSWI2$CO$Pos$Oper; listOfData: 1 item;)
160 2015-08-06 10:30:35.510076 172.16.1.3 10.0.0.104 MMS 84 confirmed-ResponsePDU (MMS -> confirmedServiceResponse: write (5); Write-Response item: success (1);)
</pre>
Feedback for execute in console.log
<pre>
2015-08-06 10:30:35.026 [INFO] Gateway.Port14.db - obj2 co (255Relay/Obj2CSWI2$CO$Pos) response: 2 flags: Execute Activation  time: 2015-Aug-06 07:30:39.015000, recv
2015-08-06 10:30:35.029 [INFO] Gateway.WebServer.db - obj2 co (112) event: 2 flags: Execute Activation OK GwTime  time: 2015-Aug-06 10:30:35.026629, sent
2015-08-06 10:30:35.030 [DEBUG] Gateway.Port14 - DO operate() service Obj2CSWI2/255Relay$CO$Pos$Oper={T,(u08/06/2015_07:30:35.026,[00000000]),F,[01]} => interlock-check=Yes, synchrocheck=no
2015-08-06 10:30:35.511 [INFO] Gateway.Port14 - DO value ok, ctlVal=T
2015-08-06 10:30:35.512 [INFO] Gateway.Port14.db - obj2 co (255Relay/Obj2CSWI2$CO$Pos) response: 2 flags: Execute Activation  time: 2015-Aug-06 07:30:39.015000, recv
2015-08-06 10:30:35.517 [INFO] Gateway.WebServer.db - obj2 co (112) event: 2 flags: Execute Activation Finished GwTime  time: 2015-Aug-06 10:30:35.513460, sent
</pre>
Final step13. Receive spontaneous (unconfirmed PDU) event for state change:
<pre>
162 2015-08-06 10:30:35.894119 172.16.1.3 10.0.0.104 MMS 156 unconfirmed-PDU (MMS -> unconfirmedService: informationReport (0); listOfVariable: 1 item; domainId: 255Relay; itemId: Obj2CSWI2$CO$Pos$Oper;listOfAccessResult: 1 item; AccessResult: success (1);
164 2015-08-06 10:30:37.014259 172.16.1.3 10.0.0.104 MMS 232 unconfirmed-PDU (MMS -> unconfirmedService: informationReport (0); vmd-specific: RPT; listOfAccessResult: 12 items; AccessResult: success (1);
</pre>
These packets contain information about many items, most importantly state of OBJ2. Console.log:
<pre>
2015-08-06 10:30:37.522 [DEBUG] Gateway.Port14 - rptId=255Relay/LLN0$BR$brcbEV103,confRev=2053,datSet=255Relay/LLN0$DS1,entryId='000000000000000b',time=08/06/2015_07:30:35.703
2015-08-06 10:30:37.523 [DEBUG] Gateway.Port14 - rcv DI 255Relay/Obj2CSWI2$ST$Pos <> id - 4 <> val=10(2),time=u08/06/2015_07:30:35.268,[00010100],quality=0000000000000,reason=[data-change],type=bitString
2015-08-06 10:30:37.523 [INFO] Gateway.Port14.db - obj2 st (255Relay/Obj2CSWI2$ST$Pos) event: 2 time: 2015-Aug-06 07:30:35.268000, received
2015-08-06 10:30:37.527 [INFO] Gateway.WebServer.db - obj2 st (104) event: 2 time: 2015-Aug-06 10:30:35.268000, sent
</pre>

Revision as of 07:08, 7 August 2015

Some basic filters for analysing wireshark logs in case of IEC protocols.


IEC60870-5-104

If you use some port other than 2404, then Wireshark will not automatically detect the correct protocol. In this case,

  1. select a IEC104 packet from the captured packets list,
  2. go to Analyse -> Decode as
  3. In the transport tab, select TCP : both ports and protocol 104apci

Dispaly packages with TCP length>0 (no ack messages) 

tcp.len>0

IEC104 packages 

104apci

IEC104 packages (without testframes, S-packets etc) 

104asdu

Packets involving 192.168.0.111 

ip.addr==192.168.0.111

TCP port 2404 

tcp.port==2404

Information object address 401 

 104asdu.ioa == 401

Spontaneous events (COT==3) 

104asdu.causetx == 3

Command messages (COT 6, 7, 10) 

104asdu.causetx == 6  //Activation
104asdu.causetx == 7   //Confirmation
104asdu.causetx == 10   //Termination

Testframe messages 

104apci.utype == 0x10   //Activation
104apci.utype == 0x20   //Confirmation

S-Type messages 

104apci.type == 0x01

General Interrogation commands 

104asdu.typeid == 100   //Global, Group1...Group16
104asdu.qoi == 20       //Global
104asdu.qoi == 21       //Group1
104asdu.qoi == 35       //Group15
                        Do not use Group 16 GI with Martem devices. This is reserved.

Clock syncronisation commands 

104asdu.typeid == 103

Show IEC104 measurements with value "0" 

IEC104asdu.normval == 0

IEC61850 and Wireshark basics

MMS: Manufacturing Message Specification GOOSE: Generic Object Oriented Substation Events

Filter IEC61850 packets 

 mms

Display packets involving TCP port 102 

tcp.port==102

Display messages containing domain ID "VampRelay" 

mms.domainId == "VampRelay"

Display messages containing item ID "VI1GGIO137$CO$SPCSO$Oper" (VI1 control command) 

mms.itemId == "VI1GGIO137$CO$SPCSO$Oper"

Display messages containing control commands (Service request 5 = write) 

mms.confirmedServiceRequest == 5

Dispaly packets containing message "success" (response to command message) 

mms.Write_Response_item == 1

Wireshark capture side-by-side with console.log

Case study: GW6e connects with Vamp255 device over IEC61850. RTU initializes communication, sends GI, executes a SBO command and receives a report (spontaneous) about change of LN state.

Step1. RTU starts connecting to the IED with a TCP-handshake (3-way handshake): 

6	2015-08-06 10:29:59.943110	10.0.0.104	172.16.1.3	TCP	74	56642→102 [SYN] Seq=0 Win=5840 Len=0 MSS=1460 SACK_PERM=1 TSval=2023 TSecr=0 WS=64
7	2015-08-06 10:30:02.443727	172.16.1.3	10.0.0.104	TCP	60	102→56642 [SYN, ACK] Seq=0 Ack=1 Win=2047 Len=0
8	2015-08-06 10:30:02.443952	10.0.0.104	172.16.1.3	TCP	54	56642→102 [ACK] Seq=1 Ack=1 Win=5840 Len=0

Step2. COTP (Connection Oriented Transport Protocol) connect request (CR) and connect confirmation (CC): 

9	2015-08-06 10:30:02.444413	10.0.0.104	172.16.1.3	COTP	76	CR TPDU src-ref: 0x0001 dst-ref: 0x0000 (PDU Type: CR Connect Request (0x0e))
10	2015-08-06 10:30:02.539805	172.16.1.3	10.0.0.104	TCP	60	102→56642 [ACK] Seq=1 Ack=23 Win=2025 Len=0
11	2015-08-06 10:30:02.739731	172.16.1.3	10.0.0.104	COTP	76	CC TPDU src-ref: 0x0002 dst-ref: 0x0001 (PDU Type: CC Connect Confirm (0x0d))

Read more about COTP: https://wiki.wireshark.org/COTP

Step 3. MMS CONNECT and ACCEPT 

 
13	2015-08-06 10:30:02.740616	10.0.0.104	172.16.1.3	MMS	244	initiate-RequestPDU (ISO 8327-1 OSI Session Protocol -> SPDU Type: CONNECT (CN) SPDU (13))
15	2015-08-06 10:30:03.225870	172.16.1.3	10.0.0.104	MMS	212	initiate-ResponsePDU (ISO 8327-1 OSI Session Protocol -> SPDU Type: ACCEPT (AC) SPDU (14))

After successful MMS connection, RTU will write to console.log: 

 
2015-08-06 10:30:03.227 [INFO] Gateway.Port14 - ASSOCIATE ok for 172.16.1.3 0

Step 4. RTU sends a request for getNamedVariableListAttributes (domainId: 255Relay; itemId: LLN0$DS1) 

 
16	2015-08-06 10:30:03.231791	10.0.0.104	172.16.1.3	MMS	103	confirmed-RequestPDU ( MMS -> confirmedServiceRequest: getNamedVariableListAttributes (12)
19	2015-08-06 10:30:03.606017	172.16.1.3	10.0.0.104	MMS	316	confirmed-ResponsePDU ( MMS-> confirmedServiceResponse: getNamedVariableListAttributes (12) (itemId: I3pMMXU1$MX$A$phsA, I3pMMXU1$MX$A$phsB....up to SIpMMXU23$MX$A )

The response contains all the item ID-s from 255Relay that are in dataset LLN0$DS1. The RTU logs this information as follows: 

2015-08-06 10:30:03.607 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/I3pMMXU1$MX$A$phsA
2015-08-06 10:30:03.609 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/I3pMMXU1$MX$A$phsB
2015-08-06 10:30:03.644 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/I3pMMXU1$MX$A$phsC
2015-08-06 10:30:03.684 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/Obj1CSWI1$ST$Pos
2015-08-06 10:30:03.724 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/Obj1CSWI1$ST$BlkCls
2015-08-06 10:30:03.764 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/Obj1CSWI1$ST$BlkOpn
2015-08-06 10:30:03.804 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/Obj2CSWI2$ST$Pos
2015-08-06 10:30:03.844 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/Obj2CSWI2$ST$BlkCls
2015-08-06 10:30:03.884 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/Obj2CSWI2$ST$BlkOpn
2015-08-06 10:30:03.924 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/Obj3CSWI3$ST$Pos
2015-08-06 10:30:03.964 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/Obj3CSWI3$ST$BlkCls
2015-08-06 10:30:04.004 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/Obj3CSWI3$ST$BlkOpn
2015-08-06 10:30:04.044 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/U3pMMXU4$MX$PhV$phsA
2015-08-06 10:30:04.084 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/U3pMMXU4$MX$PhV$phsB
2015-08-06 10:30:04.124 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/U3pMMXU4$MX$PhV$phsC
2015-08-06 10:30:04.165 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/U3ppMMXU5$MX$PPV$phsAB
2015-08-06 10:30:04.205 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/U3ppMMXU5$MX$PPV$phsBC
2015-08-06 10:30:04.244 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/U3ppMMXU5$MX$PPV$phsCA
2015-08-06 10:30:04.284 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/UoMMXU10$MX$PhV$neut
2015-08-06 10:30:04.324 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/VI1GGIO137$ST$SPCSO
2015-08-06 10:30:04.364 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/SIpMMXU23$MX$A

Step 5. RTU sends a request for getNameList 

 
21	2015-08-06 10:30:04.404171	10.0.0.104	172.16.1.3	MMS	90	confirmed-RequestPDU ( MMS -> confirmedServiceRequest: getNameList (1))
23	2015-08-06 10:30:04.891920	172.16.1.3	10.0.0.104	MMS	96	confirmed-ResponsePDU ( MMS -> confirmedServiceResponse: getNameList (1))

The RTU log: 

 
2015-08-06 10:30:04.897 [INFO] Gateway.Port14 - Find DIs and AIs
2015-08-06 10:30:04.898 [INFO] Gateway.Port14 - found report=255Relay/LLN0.brcbEV103,DATA-SET="255Relay/LLN0$DS1"
2015-08-06 10:30:04.898 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/I3pMMXU1$MX$A$phsA
2015-08-06 10:30:04.899 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/I3pMMXU1$MX$A$phsB
2015-08-06 10:30:04.900 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/I3pMMXU1$MX$A$phsC
2015-08-06 10:30:04.900 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/Obj1CSWI1$ST$Pos
2015-08-06 10:30:04.900 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/Obj1CSWI1$ST$BlkCls
2015-08-06 10:30:04.901 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/Obj1CSWI1$ST$BlkOpn
2015-08-06 10:30:04.901 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/Obj2CSWI2$ST$Pos
2015-08-06 10:30:04.901 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/Obj2CSWI2$ST$BlkCls
2015-08-06 10:30:04.902 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/Obj2CSWI2$ST$BlkOpn
2015-08-06 10:30:04.902 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/Obj3CSWI3$ST$Pos
2015-08-06 10:30:04.902 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/Obj3CSWI3$ST$BlkCls
2015-08-06 10:30:04.903 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/Obj3CSWI3$ST$BlkOpn
2015-08-06 10:30:04.903 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/U3pMMXU4$MX$PhV$phsA
2015-08-06 10:30:04.904 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/U3pMMXU4$MX$PhV$phsB
2015-08-06 10:30:04.904 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/U3pMMXU4$MX$PhV$phsC
2015-08-06 10:30:04.904 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/U3ppMMXU5$MX$PPV$phsAB
2015-08-06 10:30:04.905 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/U3ppMMXU5$MX$PPV$phsBC
2015-08-06 10:30:04.905 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/U3ppMMXU5$MX$PPV$phsCA
2015-08-06 10:30:04.905 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/UoMMXU10$MX$PhV$neut
2015-08-06 10:30:04.906 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/VI1GGIO137$ST$SPCSO
2015-08-06 10:30:04.906 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/SIpMMXU23$MX$A

Step 6. RTU reads the LLN0$BR$brcbEV103$RptEna item: 

 
25	2015-08-06 10:30:05.956536	10.0.0.104	172.16.1.3	MMS	130	confirmed-RequestPDU  ( MMS -> confirmedServiceRequest: read (4) (domainId: 255Relay, itemId: LLN0$BR$brcbEV103$RptEna))
27	2015-08-06 10:30:06.315874	172.16.1.3	10.0.0.104	MMS	86	confirmed-ResponsePDU ( MMS -> confirmedServiceResponse: read (4); listOfAccessResult: 1 item; AccessResult: success (1), FALSE)

The response states that BRCB3 is not enabled. Next, RTU reads the LLN0$BR$brcbEV103$ResvTms parameter: 

29	2015-08-06 10:30:06.317941	10.0.0.104	172.16.1.3	MMS	131	confirmed-RequestPDU ( MMS -> confirmedServiceRequest: read (4) domainId: 255Relay; itemId: LLN0$BR$brcbEV103$ResvTms)
31	2015-08-06 10:30:06.747774	172.16.1.3	10.0.0.104	MMS	86	confirmed-ResponsePDU ( MMS -> confirmedServiceResponse: read (4) (AccessResult: success (1), integer: 0))

In the mean time, RTU has changed the "link" status of the device as "connected" 

 
2015-08-06 10:30:04.907 [INFO] Gateway.Port14 - Enable 1 RCB's
2015-08-06 10:30:04.912 [DEBUG] Gateway.Port14 - StatusDi: connected
2015-08-06 10:30:04.919 [INFO] Gateway.Port14 - Connected
2015-08-06 10:30:04.919 [INFO] Gateway.Port14 - Refresh all values

Step 7. RTU sends a write request (with new values) for BRCB3 items (see console.log for details): 

32	2015-08-06 10:30:06.754924	10.0.0.104	172.16.1.3	MMS	431	confirmed-RequestPDU  ( MMS -> confirmedServiceRequest: write (5) (domainId: 255Relay; Item ID-s and values...)
34	2015-08-06 10:30:07.195910	172.16.1.3	10.0.0.104	MMS	96	confirmed-ResponsePDU ( MMS -> confirmedServiceResponse: write (5) (write: 7 items; Write-Response item: success (1) for all 7 writes))

RTU console.log: 

2015-08-06 10:30:06.749 [INFO] Gateway.Port14 - RcbEnable: mms write 255Relay/LLN0$BR$brcbEV103$ResvTms=2
2015-08-06 10:30:06.750 [INFO] Gateway.Port14 - RcbEnable: mms write 255Relay/LLN0$BR$brcbEV103$DatSet="255Relay/LLN0$DS1"
2015-08-06 10:30:06.750 [INFO] Gateway.Port14 - RcbEnable: mms write 255Relay/LLN0$BR$brcbEV103$OptFlds=[0111111111]
2015-08-06 10:30:06.751 [INFO] Gateway.Port14 - RcbEnable: mms write 255Relay/LLN0$BR$brcbEV103$TrgOps=[011101]
2015-08-06 10:30:06.752 [INFO] Gateway.Port14 - RcbEnable: mms write 255Relay/LLN0$BR$brcbEV103$PurgeBuf=T
2015-08-06 10:30:06.752 [INFO] Gateway.Port14 - RcbEnable: mms write 255Relay/LLN0$BR$brcbEV103$RptEna=T
2015-08-06 10:30:06.753 [INFO] Gateway.Port14 - RcbEnable: mms write 255Relay/LLN0$BR$brcbEV103$GI=T

Step8. RTU reads the RptEna item again: 

 
35	2015-08-06 10:30:07.197131	10.0.0.104	172.16.1.3	MMS	130	confirmed-RequestPDU (MMS -> confirmedServiceRequest: read (4) (itemId: LLN0$BR$brcbEV103$RptEna)
42	2015-08-06 10:30:07.720025	172.16.1.3	10.0.0.104	MMS	86	confirmed-ResponsePDU (MMS -> confirmedServiceResponse: read (4) (AccessResult: success (1), TRUE)

This time RCB is enabled and RTU then writes to the console.log: 

 
2015-08-06 10:30:07.721 [INFO] Gateway.Port14 - RcbEnable: report enable ok 255Relay/LLN0$BR$brcbEV103

Step9. RTU reads parameters of BRCB3 (see console.log for details) 

 
44	2015-08-06 10:30:07.727357	10.0.0.104	172.16.1.3	MMS	398	confirmed-RequestPDU (MMS -> confirmedServiceRequest: read (4) (variableAccessSpecificatn: listOfVariable (0); listOfVariable: 7 items;)
46	2015-08-06 10:30:08.135870	172.16.1.3	10.0.0.104	MMS	132	confirmed-ResponsePDU (MMS -> confirmedServiceResponse: read (4) (listOfAccessResult: 7 items; AccessResult: success (1); values in console.log)

The following data is received: 

 
2015-08-06 10:30:07.722 [INFO] Gateway.Port14 - RcbEnable: mms read 255Relay/LLN0$BR$brcbEV103$RptID
2015-08-06 10:30:07.722 [INFO] Gateway.Port14 - RcbEnable: mms read 255Relay/LLN0$BR$brcbEV103$DatSet
2015-08-06 10:30:07.722 [INFO] Gateway.Port14 - RcbEnable: mms read 255Relay/LLN0$BR$brcbEV103$OptFlds
2015-08-06 10:30:07.723 [INFO] Gateway.Port14 - RcbEnable: mms read 255Relay/LLN0$BR$brcbEV103$TrgOps
2015-08-06 10:30:07.724 [INFO] Gateway.Port14 - RcbEnable: mms read 255Relay/LLN0$BR$brcbEV103$IntgPd
2015-08-06 10:30:07.724 [INFO] Gateway.Port14 - RcbEnable: mms read 255Relay/LLN0$BR$brcbEV103$ConfRev
2015-08-06 10:30:07.725 [INFO] Gateway.Port14 - RcbEnable: mms read 255Relay/LLN0$BR$brcbEV103$EntryID
2015-08-06 10:30:08.174 [INFO] Gateway.Port14 - RcbEnable: RCB attribute values: "","255Relay/LLN0$DS1",[0111111111],[011101],+60000,+2053,'0000000000000009'

Step10. For some reason, RTU reads ConfRev parameter again: 

 
48	2015-08-06 10:30:08.175876	10.0.0.104	172.16.1.3	MMS	131	confirmed-RequestPDU (MMS -> confirmedServiceRequest: read (4) (itemId: LLN0$BR$brcbEV103$ConfRev))
50	2015-08-06 10:30:08.593893	172.16.1.3	10.0.0.104	MMS	88	confirmed-ResponsePDU (MMS -> confirmedServiceResponse: read (4) (AccessResult: success (1); unsigned: 2053))

And outputs to console.log: 

 
2015-08-06 10:30:08.595 [INFO] Gateway.Port14 - RcbEnable: ConfRev=2053
2015-08-06 10:30:08.596 [DEBUG] Gateway.Port14 - rptId=255Relay/LLN0$BR$brcbEV103,confRev=2053,datSet=255Relay/LLN0$DS1,entryId='0000000000000009',time=08/06/2015_07:30:06.955

Step11. RTU requests getVariableAccessAttributes for all the configured objects, one by one and gets initial values: 

 
52	2015-08-06 10:30:08.634159	10.0.0.104	172.16.1.3	MMS	115	confirmed-RequestPDU (MMS -> confirmedServiceRequest: getVariableAccessAttributes (6); domainId: 255Relay; itemId: I3pMMXU1$MX$A$phsA)
54	2015-08-06 10:30:09.055958	172.16.1.3	10.0.0.104	MMS	152	confirmed-ResponsePDU (MMS -> confirmedServiceResponse: getVariableAccessAttributes (6); components: 3 items;)

The results are available in console.log: 

 
2015-08-06 10:30:09.057 [DEBUG] Gateway.Port14 - 255Relay/I3pMMXU1$MX$A$phsA={{{f0.000000e+00}},[0000000000000],(u08/06/2015_07:21:14.532,[00110100])} [general-interrogation] => object not configured
2015-08-06 10:30:09.519 [DEBUG] Gateway.Port14 - 255Relay/I3pMMXU1$MX$A$phsB={{{f0.000000e+00}},[0000000000000],(u08/06/2015_07:21:14.532,[00110100])} [general-interrogation] => object not configured
2015-08-06 10:30:09.977 [DEBUG] Gateway.Port14 - 255Relay/I3pMMXU1$MX$A$phsC={{{f0.000000e+00}},[0000000000000],(u08/06/2015_07:21:14.533,[00110100])} [general-interrogation] => object not configured
...
2015-08-06 10:30:10.505 [DEBUG] Gateway.Port14 - rcv DI 255Relay/Obj1CSWI1$ST$Pos <> id - 1 <> val=01(1),time=u08/06/2015_07:21:14.663,[00110100],quality=0000000000000,reason=[general-interrogation],type=bitString
2015-08-06 10:30:10.506 [INFO] Gateway.Port14.db - obj1 st (255Relay/Obj1CSWI1$ST$Pos) event: 1 flags: GwTime GI  time: 2015-Aug-06 07:30:10.505960, received
...
2015-08-06 10:30:10.925 [DEBUG] Gateway.Port14 - rcv DI 255Relay/Obj1CSWI1$ST$BlkCls <> id - 2 <> val=F(1),time=u08/06/2015_07:21:14.534,[00110100],quality=0000000000000,reason=[general-interrogation],type=bool
2015-08-06 10:30:10.926 [INFO] Gateway.Port14.db -  (255Relay/Obj1CSWI1$ST$BlkCls) event: 1 flags: GwTime GI  time: 2015-Aug-06 07:30:10.926003, received
...
2015-08-06 10:30:11.385 [DEBUG] Gateway.Port14 - rcv DI 255Relay/Obj1CSWI1$ST$BlkOpn <> id - 3 <> val=F(1),time=u08/06/2015_07:21:14.534,[00110100],quality=0000000000000,reason=[general-interrogation],type=bool
2015-08-06 10:30:11.386 [INFO] Gateway.Port14.db -  (255Relay/Obj1CSWI1$ST$BlkOpn) event: 1 flags: GwTime GI  time: 2015-Aug-06 07:30:11.385871, received
2015-08-06 10:30:11.845 [DEBUG] Gateway.Port14 - rcv DI 255Relay/Obj2CSWI2$ST$Pos <> id - 4 <> val=01(1),time=u08/06/2015_07:26:54.499,[00010100],quality=0000000000000,reason=[general-interrogation],type=bitString
2015-08-06 10:30:11.846 [INFO] Gateway.Port14.db - obj2 st (255Relay/Obj2CSWI2$ST$Pos) event: 1 flags: GwTime GI  time: 2015-Aug-06 07:30:11.845870, received
2015-08-06 10:30:12.305 [DEBUG] Gateway.Port14 - rcv DI 255Relay/Obj2CSWI2$ST$BlkCls <> id - 5 <> val=F(1),time=u08/06/2015_07:21:14.534,[00110100],quality=0000000000000,reason=[general-interrogation],type=bool
2015-08-06 10:30:12.306 [INFO] Gateway.Port14.db -  (255Relay/Obj2CSWI2$ST$BlkCls) event: 1 flags: GwTime GI  time: 2015-Aug-06 07:30:12.305839, received
2015-08-06 10:30:12.765 [DEBUG] Gateway.Port14 - rcv DI 255Relay/Obj2CSWI2$ST$BlkOpn <> id - 6 <> val=F(1),time=u08/06/2015_07:21:14.534,[00110100],quality=0000000000000,reason=[general-interrogation],type=bool
2015-08-06 10:30:12.766 [INFO] Gateway.Port14.db -  (255Relay/Obj2CSWI2$ST$BlkOpn) event: 1 flags: GwTime GI  time: 2015-Aug-06 07:30:12.765899, received
2015-08-06 10:30:13.234 [DEBUG] Gateway.Port14 - rcv DI 255Relay/Obj3CSWI3$ST$Pos <> id - 7 <> val=00(0),time=u08/06/2015_07:21:14.535,[00110100],quality=0000000000000,reason=[general-interrogation],type=bitString
2015-08-06 10:30:13.234 [INFO] Gateway.Port14.db - obj3 st (255Relay/Obj3CSWI3$ST$Pos) event: 0 flags: GwTime GI  time: 2015-Aug-06 07:30:13.234659, received
2015-08-06 10:30:13.685 [DEBUG] Gateway.Port14 - rcv DI 255Relay/Obj3CSWI3$ST$BlkCls <> id - 8 <> val=F(1),time=u08/06/2015_07:21:14.535,[00110100],quality=0000000000000,reason=[general-interrogation],type=bool
2015-08-06 10:30:13.686 [INFO] Gateway.Port14.db -  (255Relay/Obj3CSWI3$ST$BlkCls) event: 1 flags: GwTime GI  time: 2015-Aug-06 07:30:13.686278, received
2015-08-06 10:30:14.144 [DEBUG] Gateway.Port14 - rcv DI 255Relay/Obj3CSWI3$ST$BlkOpn <> id - 9 <> val=F(1),time=u08/06/2015_07:21:14.535,[00110100],quality=0000000000000,reason=[general-interrogation],type=bool
2015-08-06 10:30:14.144 [INFO] Gateway.Port14.db -  (255Relay/Obj3CSWI3$ST$BlkOpn) event: 1 flags: GwTime GI  time: 2015-Aug-06 07:30:14.144552, received
2015-08-06 10:30:14.603 [DEBUG] Gateway.Port14 - 255Relay/U3pMMXU4$MX$PhV$phsA={{{f0.000000e+00}},[0000000000000],(u08/06/2015_07:21:14.536,[00110100])} [general-interrogation] => object not configured
2015-08-06 10:30:15.078 [DEBUG] Gateway.Port14 - 255Relay/U3pMMXU4$MX$PhV$phsB={{{f0.000000e+00}},[0000000000000],(u08/06/2015_07:21:14.536,[00110100])} [general-interrogation] => object not configured
2015-08-06 10:30:15.541 [DEBUG] Gateway.Port14 - 255Relay/U3pMMXU4$MX$PhV$phsC={{{f0.000000e+00}},[0000000000000],(u08/06/2015_07:21:14.536,[00110100])} [general-interrogation] => object not configured
2015-08-06 10:30:15.983 [DEBUG] Gateway.Port14 - 255Relay/U3ppMMXU5$MX$PPV$phsAB={{{f0.000000e+00}},[0000000000000],(u08/06/2015_07:21:14.537,[00110100])} [general-interrogation] => object not configured
2015-08-06 10:30:16.443 [DEBUG] Gateway.Port14 - 255Relay/U3ppMMXU5$MX$PPV$phsBC={{{f0.000000e+00}},[0000000000000],(u08/06/2015_07:21:14.537,[00110100])} [general-interrogation] => object not configured
2015-08-06 10:30:16.905 [DEBUG] Gateway.Port14 - 255Relay/U3ppMMXU5$MX$PPV$phsCA={{{f0.000000e+00}},[0000000000000],(u08/06/2015_07:21:14.538,[00110100])} [general-interrogation] => object not configured
2015-08-06 10:30:17.368 [DEBUG] Gateway.Port14 - 255Relay/UoMMXU10$MX$PhV$neut={{{f0.000000e+00}},[0000000000000],(u08/06/2015_07:21:14.538,[00110100])} [general-interrogation] => object not configured
2015-08-06 10:30:17.833 [DEBUG] Gateway.Port14 - rcv DI 255Relay/VI1GGIO137$ST$SPCSO <> id - 10 <> val=T(2),time=u08/06/2015_07:21:14.539,[00110100],quality=0000000000000,reason=[general-interrogation],type=bool
2015-08-06 10:30:17.834 [INFO] Gateway.Port14.db - vi1 st (255Relay/VI1GGIO137$ST$SPCSO) event: 2 flags: GwTime GI  time: 2015-Aug-06 07:30:17.833953, received
2015-08-06 10:30:18.290 [DEBUG] Gateway.Port14 - 255Relay/SIpMMXU23$MX$A={{{{f0.000000e+00}},[0000000000000],(u08/06/2015_07:21:14.539,[00110100])},{{{f0.000000e+00}},[0000000000000],(u08/06/2015_07:21:14.540,[00110100])},{{{f0.000000e+00}},[0000000000000],(u08/06/2015_07:21:14.540,[00110100])}} [general-interrogation] => object not configured

Finally, the protocol is initialised: 

 
2015-08-06 10:30:17.843 [INFO] Gateway.Port14 - Protocol initialization took: 00:01:22.795722
2015-08-06 10:30:17.843 [INFO] Gateway.Port14 - protocol initialized

Step11. Send GI 

 
2015-08-06 10:30:18.743 [INFO] Gateway.Port14 - Send GI, 255Relay/LLN0.brcbEV103

In MMS, the RTU writes the LLN0$BR$brcbEV103$GI item to value 1, receives a response (success) and finally receives an "unconfirmed PDU" containing all the items that respond to GI in that dataset (in my case, 72 items) 

 
10:30:18.292709	10.0.0.104	172.16.1.3	MMS	126	confirmed-RequestPDU (MMS -> confirmedServiceRequest: write (5); itemId: LLN0$BR$brcbEV103$GI; boolean: True)
138	2015-08-06 10:30:18.742140	172.16.1.3	10.0.0.104	MMS	84	confirmed-ResponsePDU (MMS -> confirmedServiceResponse: write (5); Write-Response item: success (1); )
 10:30:19.076348	172.16.1.3	10.0.0.104	MMS	444	unconfirmed-PDU (MMS -> unconfirmedService: informationReport (0); vmd-specific: RPT; listOfAccessResult: 72 items; AccessResult: success (1); visible-string: 255Relay/LLN0$BR$brcbEV103;
THIS IS GI RESPONSE WITH ALL VARIABLES AND PARAMETERS)

The information gathered from GI response looks like this in the console.log: 

2015-08-06 10:30:19.749 [DEBUG] Gateway.Port14 - rptId=255Relay/LLN0$BR$brcbEV103,confRev=2053,datSet=255Relay/LLN0$DS1,entryId='000000000000000a',time=08/06/2015_07:30:18.471
2015-08-06 10:30:19.749 [DEBUG] Gateway.Port14 - 255Relay/I3pMMXU1$MX$A$phsA={{{f0.000000e+00}},[0000000000000],(u08/06/2015_07:21:14.532,[00110100])} [general-interrogation] => object not configured
2015-08-06 10:30:19.784 [DEBUG] Gateway.Port14 - 255Relay/I3pMMXU1$MX$A$phsB={{{f0.000000e+00}},[0000000000000],(u08/06/2015_07:21:14.532,[00110100])} [general-interrogation] => object not configured
2015-08-06 10:30:19.824 [DEBUG] Gateway.Port14 - 255Relay/I3pMMXU1$MX$A$phsC={{{f0.000000e+00}},[0000000000000],(u08/06/2015_07:21:14.533,[00110100])} [general-interrogation] => object not configured

2015-08-06 10:30:19.864 [DEBUG] Gateway.Port14 - rcv DI 255Relay/Obj1CSWI1$ST$Pos <> id - 1 <> val=01(1),time=u08/06/2015_07:21:14.663,[00110100],quality=0000000000000,reason=[general-interrogation],type=bitString
2015-08-06 10:30:19.865 [INFO] Gateway.Port14.db - obj1 st (255Relay/Obj1CSWI1$ST$Pos) event: 1 flags: GwTime GI  time: 2015-Aug-06 07:30:19.865107, received
2015-08-06 10:30:19.904 [DEBUG] Gateway.Port14 - rcv DI 255Relay/Obj1CSWI1$ST$BlkCls <> id - 2 <> val=F(1),time=u08/06/2015_07:21:14.534,[00110100],quality=0000000000000,reason=[general-interrogation],type=bool
2015-08-06 10:30:19.905 [INFO] Gateway.Port14.db -  (255Relay/Obj1CSWI1$ST$BlkCls) event: 1 flags: GwTime GI  time: 2015-Aug-06 07:30:19.905003, received
2015-08-06 10:30:19.944 [DEBUG] Gateway.Port14 - rcv DI 255Relay/Obj1CSWI1$ST$BlkOpn <> id - 3 <> val=F(1),time=u08/06/2015_07:21:14.534,[00110100],quality=0000000000000,reason=[general-interrogation],type=bool
2015-08-06 10:30:19.945 [INFO] Gateway.Port14.db -  (255Relay/Obj1CSWI1$ST$BlkOpn) event: 1 flags: GwTime GI  time: 2015-Aug-06 07:30:19.945055, received
2015-08-06 10:30:19.984 [DEBUG] Gateway.Port14 - rcv DI 255Relay/Obj2CSWI2$ST$Pos <> id - 4 <> val=01(1),time=u08/06/2015_07:26:54.499,[00010100],quality=0000000000000,reason=[general-interrogation],type=bitString
2015-08-06 10:30:19.985 [INFO] Gateway.Port14.db - obj2 st (255Relay/Obj2CSWI2$ST$Pos) event: 1 flags: GwTime GI  time: 2015-Aug-06 07:30:19.984973, received
2015-08-06 10:30:20.024 [DEBUG] Gateway.Port14 - rcv DI 255Relay/Obj2CSWI2$ST$BlkCls <> id - 5 <> val=F(1),time=u08/06/2015_07:21:14.534,[00110100],quality=0000000000000,reason=[general-interrogation],type=bool
2015-08-06 10:30:20.025 [INFO] Gateway.Port14.db -  (255Relay/Obj2CSWI2$ST$BlkCls) event: 1 flags: GwTime GI  time: 2015-Aug-06 07:30:20.025046, received
2015-08-06 10:30:20.064 [DEBUG] Gateway.Port14 - rcv DI 255Relay/Obj2CSWI2$ST$BlkOpn <> id - 6 <> val=F(1),time=u08/06/2015_07:21:14.534,[00110100],quality=0000000000000,reason=[general-interrogation],type=bool
2015-08-06 10:30:20.065 [INFO] Gateway.Port14.db -  (255Relay/Obj2CSWI2$ST$BlkOpn) event: 1 flags: GwTime GI  time: 2015-Aug-06 07:30:20.065085, received
2015-08-06 10:30:20.107 [DEBUG] Gateway.Port14 - rcv DI 255Relay/Obj3CSWI3$ST$Pos <> id - 7 <> val=00(0),time=u08/06/2015_07:21:14.535,[00110100],quality=0000000000000,reason=[general-interrogation],type=bitString
2015-08-06 10:30:20.107 [INFO] Gateway.Port14.db - obj3 st (255Relay/Obj3CSWI3$ST$Pos) event: 0 flags: GwTime GI  time: 2015-Aug-06 07:30:20.107382, received
2015-08-06 10:30:20.145 [DEBUG] Gateway.Port14 - rcv DI 255Relay/Obj3CSWI3$ST$BlkCls <> id - 8 <> val=F(1),time=u08/06/2015_07:21:14.535,[00110100],quality=0000000000000,reason=[general-interrogation],type=bool
2015-08-06 10:30:20.145 [INFO] Gateway.Port14.db -  (255Relay/Obj3CSWI3$ST$BlkCls) event: 1 flags: GwTime GI  time: 2015-Aug-06 07:30:20.145250, received
2015-08-06 10:30:20.185 [DEBUG] Gateway.Port14 - rcv DI 255Relay/Obj3CSWI3$ST$BlkOpn <> id - 9 <> val=F(1),time=u08/06/2015_07:21:14.535,[00110100],quality=0000000000000,reason=[general-interrogation],type=bool
2015-08-06 10:30:20.185 [INFO] Gateway.Port14.db -  (255Relay/Obj3CSWI3$ST$BlkOpn) event: 1 flags: GwTime GI  time: 2015-Aug-06 07:30:20.185352, received
2015-08-06 10:30:20.224 [DEBUG] Gateway.Port14 - 255Relay/U3pMMXU4$MX$PhV$phsA={{{f0.000000e+00}},[0000000000000],(u08/06/2015_07:21:14.536,[00110100])} [general-interrogation] => object not configured
2015-08-06 10:30:20.264 [DEBUG] Gateway.Port14 - 255Relay/U3pMMXU4$MX$PhV$phsB={{{f0.000000e+00}},[0000000000000],(u08/06/2015_07:21:14.536,[00110100])} [general-interrogation] => object not configured
2015-08-06 10:30:20.304 [DEBUG] Gateway.Port14 - 255Relay/U3pMMXU4$MX$PhV$phsC={{{f0.000000e+00}},[0000000000000],(u08/06/2015_07:21:14.536,[00110100])} [general-interrogation] => object not configured
2015-08-06 10:30:20.344 [DEBUG] Gateway.Port14 - 255Relay/U3ppMMXU5$MX$PPV$phsAB={{{f0.000000e+00}},[0000000000000],(u08/06/2015_07:21:14.537,[00110100])} [general-interrogation] => object not configured
2015-08-06 10:30:20.384 [DEBUG] Gateway.Port14 - 255Relay/U3ppMMXU5$MX$PPV$phsBC={{{f0.000000e+00}},[0000000000000],(u08/06/2015_07:21:14.537,[00110100])} [general-interrogation] => object not configured
2015-08-06 10:30:20.424 [DEBUG] Gateway.Port14 - 255Relay/U3ppMMXU5$MX$PPV$phsCA={{{f0.000000e+00}},[0000000000000],(u08/06/2015_07:21:14.538,[00110100])} [general-interrogation] => object not configured
2015-08-06 10:30:20.464 [DEBUG] Gateway.Port14 - 255Relay/UoMMXU10$MX$PhV$neut={{{f0.000000e+00}},[0000000000000],(u08/06/2015_07:21:14.538,[00110100])} [general-interrogation] => object not configured
2015-08-06 10:30:20.504 [DEBUG] Gateway.Port14 - rcv DI 255Relay/VI1GGIO137$ST$SPCSO <> id - 10 <> val=T(2),time=u08/06/2015_07:21:14.539,[00110100],quality=0000000000000,reason=[general-interrogation],type=bool
2015-08-06 10:30:20.505 [INFO] Gateway.Port14.db - vi1 st (255Relay/VI1GGIO137$ST$SPCSO) event: 2 flags: GwTime GI  time: 2015-Aug-06 07:30:20.504983, received
2015-08-06 10:30:20.544 [DEBUG] Gateway.Port14 - 255Relay/SIpMMXU23$MX$A={{{{f0.000000e+00}},[0000000000000],(u08/06/2015_07:21:14.539,[00110100])},{{{f0.000000e+00}},[0000000000000],(u08/06/2015_07:21:14.540,[00110100])},{{{f0.000000e+00}},[0000000000000],(u08/06/2015_07:21:14.540,[00110100])}} [general-interrogation] => object not configured

Step12. Send control command Before control command is sent, RTU reads the attributes of items Obj2CSWI2$CO$Pos$Oper$ctlVal and Obj2CSWI2$CO$Pos : 

146	2015-08-06 10:30:31.630020	10.0.0.104	172.16.1.3	MMS	125	confirmed-RequestPDU (MMS -> confirmedServiceRequest: getVariableAccessAttributes (6); domainId: 255Relay; itemId: Obj2CSWI2$CO$Pos$Oper$ctlVal)
148	2015-08-06 10:30:32.021978	172.16.1.3	10.0.0.104	MMS	88	confirmed-ResponsePDU (MMS -> confirmedServiceResponse: getVariableAccessAttributes (6); typeSpecification: boolean (3))

150	2015-08-06 10:30:32.064158	10.0.0.104	172.16.1.3	MMS	113	confirmed-RequestPDU (MMS -> confirmedServiceRequest: getVariableAccessAttributes (6); domainId: 255Relay; itemId: Obj2CSWI2$CO$Pos)
152	2015-08-06 10:30:32.536409	172.16.1.3	10.0.0.104	MMS	466	confirmed-ResponsePDU (MMS -> confirmedServiceResponse: getVariableAccessAttributes (6); components: 3 items;)

RTU writes the current state of control object and sends the write (Select) command: 

2015-08-06 10:30:32.549 [INFO] Gateway.Port14 - DO selectWithValue() service Obj2CSWI2/255Relay$CO$Pos$Oper={T,(u08/06/2015_07:30:32.024,[00000000]),F,[01]} => interlock-check=Yes, synchrocheck=no
2015-08-06 10:30:33.015 [INFO] Gateway.Port14.db - obj2 co (255Relay/Obj2CSWI2$CO$Pos) response: 2 flags: Select Activation  time: 2015-Aug-06 07:30:35.155000, recv
2015-08-06 10:30:33.019 [INFO] Gateway.WebServer.db - obj2 co (112) event: 2 flags: Select Activation OK GwTime  time: 2015-Aug-06 10:30:33.015925, sent

In MMS: 

154	2015-08-06 10:30:32.557450	10.0.0.104	172.16.1.3	MMS	158	confirmed-RequestPDU (MMS -> confirmedServiceRequest: write (5); domainId: 255Relay; itemId: Obj2CSWI2$CO$Pos$SBOw; listOfData: 1 item;)
156	2015-08-06 10:30:33.013975	172.16.1.3	10.0.0.104	MMS	84	confirmed-ResponsePDU (MMS -> confirmedServiceResponse: write (5); Write-Response item: success (1))

Next, send the write command for execute: 

2015-08-06 10:30:34.942 [DEBUG] Gateway.WebServer - control id: DO_14_0_12 vType: DO v: 2 t: 2015-08-06 10:30:39.015 act: 1 sel: 0
2015-08-06 10:30:34.944 [INFO] Gateway.WebServer.db - obj2 co (112) control: 2 flags: Execute Activation  time: 2015-Aug-06 10:30:39.015000, recv
2015-08-06 10:30:35.024 [INFO] Gateway.Port14.db - obj2 co (255Relay/Obj2CSWI2$CO$Pos) control: 2 flags: Execute Activation  time: 2015-Aug-06 07:30:39.015000, sent

10:30:35.076529	10.0.0.104	172.16.1.3	MMS	158	confirmed-RequestPDU (MMS-> confirmedServiceRequest: write (5); itemId: Obj2CSWI2$CO$Pos$Oper; listOfData: 1 item;)
160	2015-08-06 10:30:35.510076	172.16.1.3	10.0.0.104	MMS	84	confirmed-ResponsePDU (MMS -> confirmedServiceResponse: write (5); Write-Response item: success (1);)

Feedback for execute in console.log 

2015-08-06 10:30:35.026 [INFO] Gateway.Port14.db - obj2 co (255Relay/Obj2CSWI2$CO$Pos) response: 2 flags: Execute Activation  time: 2015-Aug-06 07:30:39.015000, recv
2015-08-06 10:30:35.029 [INFO] Gateway.WebServer.db - obj2 co (112) event: 2 flags: Execute Activation OK GwTime  time: 2015-Aug-06 10:30:35.026629, sent
2015-08-06 10:30:35.030 [DEBUG] Gateway.Port14 - DO operate() service Obj2CSWI2/255Relay$CO$Pos$Oper={T,(u08/06/2015_07:30:35.026,[00000000]),F,[01]} => interlock-check=Yes, synchrocheck=no
2015-08-06 10:30:35.511 [INFO] Gateway.Port14 - DO value ok, ctlVal=T
2015-08-06 10:30:35.512 [INFO] Gateway.Port14.db - obj2 co (255Relay/Obj2CSWI2$CO$Pos) response: 2 flags: Execute Activation  time: 2015-Aug-06 07:30:39.015000, recv
2015-08-06 10:30:35.517 [INFO] Gateway.WebServer.db - obj2 co (112) event: 2 flags: Execute Activation Finished GwTime  time: 2015-Aug-06 10:30:35.513460, sent

Final step13. Receive spontaneous (unconfirmed PDU) event for state change: 

162	2015-08-06 10:30:35.894119	172.16.1.3	10.0.0.104	MMS	156	unconfirmed-PDU (MMS -> unconfirmedService: informationReport (0); listOfVariable: 1 item; domainId: 255Relay; itemId: Obj2CSWI2$CO$Pos$Oper;listOfAccessResult: 1 item; AccessResult: success (1); 

164	2015-08-06 10:30:37.014259	172.16.1.3	10.0.0.104	MMS	232	unconfirmed-PDU (MMS -> unconfirmedService: informationReport (0); vmd-specific: RPT; listOfAccessResult: 12 items; AccessResult: success (1);

These packets contain information about many items, most importantly state of OBJ2. Console.log: 

2015-08-06 10:30:37.522 [DEBUG] Gateway.Port14 - rptId=255Relay/LLN0$BR$brcbEV103,confRev=2053,datSet=255Relay/LLN0$DS1,entryId='000000000000000b',time=08/06/2015_07:30:35.703
2015-08-06 10:30:37.523 [DEBUG] Gateway.Port14 - rcv DI 255Relay/Obj2CSWI2$ST$Pos <> id - 4 <> val=10(2),time=u08/06/2015_07:30:35.268,[00010100],quality=0000000000000,reason=[data-change],type=bitString
2015-08-06 10:30:37.523 [INFO] Gateway.Port14.db - obj2 st (255Relay/Obj2CSWI2$ST$Pos) event: 2 time: 2015-Aug-06 07:30:35.268000, received
2015-08-06 10:30:37.527 [INFO] Gateway.WebServer.db - obj2 st (104) event: 2 time: 2015-Aug-06 10:30:35.268000, sent
Retrieved from "https://phobos.martem.ee/w/index.php?title=Wiresharking_IEC&oldid=1967"