Wiresharking IEC: Difference between revisions

From Phobos Wiki
Jump to navigation Jump to search
 
(27 intermediate revisions by 2 users not shown)
Line 1: Line 1:
Some basic filters for analysing wireshark logs in case of IEC protocols.<br />
==Wireshark and IEC60870-5-104, IEC61850==
Some basic filters and examples for analysing wireshark logs in case of IEC protocols.<br />




Line 49: Line 50:
MMS: Manufacturing Message Specification
MMS: Manufacturing Message Specification
GOOSE: Generic Object Oriented Substation Events
GOOSE: Generic Object Oriented Substation Events
NOTE: when 61850 capture is recorded after the protocol has initialised (not from the beginning), then Wireshark will not automatically detect the protocol as MMS.
However, it is possible to change the "PRES" to "MMS" using the Wireshark menus:
<pre>Go to Edit->preferences->protocol->PRES and edit the users context tale
enter context = 3 and OID = 1.0.9506.2.3 and your trace will be dissected as MMS.</pre>


Filter IEC61850 packets
Filter IEC61850 packets
Line 63: Line 70:
<pre>mms.Write_Response_item == 1</pre>
<pre>mms.Write_Response_item == 1</pre>


===Wireshark capture side-by-side with console.log===
===61850 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.
Case study:  
 
GW6e connects with Vamp255 device over IEC61850.
 
RTU is configured to use BRCB3 and DS1.
 
RTU initializes communication, sends GI, executes a SBO command and receives a report (spontaneous) about change of LN state.
 
Pcap capture file is accessible from this link: http://phobos.martem.ee/shr/61850_example_log/tcplog61850.pcap
 
 
'''Summary:'''
--------------------------------------------------------------
Step1. TCP-handshake (3-way handshake)
 
Step2. COTP: connect request (CR) and connect confirmation (CC)
 
Step3. MMS CONNECT and ACCEPT
 
Step4. getNamedVariableListAttributes (domainId: 255Relay; itemId: LLN0$DS1)


Step1. RTU starts connecting to the IED with a TCP-handshake (3-way handshake):
Step5. getNameList
 
Step6. Check LLN0$BR$brcbEV103$RptEna item
 
Step7. Enable and configure BRCB3
 
Step8. Verify that BRCB3 is enabled
 
Step9. Verify that BRCB3 is configured correctly
 
Step10. Read ConfRev parameter
 
Step11. Read getVariableAccessAttributes for all the configured objects, one by one
 
Step12. Send GI
 
Step13. Send control command
 
Step14. Receive spontaneous (unconfirmed PDU) event for state change
 
 
--------------------------------------------------------------------- 
 
'''Step1. RTU starts connecting to the IED with a TCP-handshake (3-way handshake):'''
<pre>
<pre>
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
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
Line 72: Line 121:
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
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
</pre>
</pre>
Step2. COTP (Connection Oriented Transport Protocol) connect request (CR) and connect confirmation (CC):
'''Step2. COTP (Connection Oriented Transport Protocol) connect request (CR) and connect confirmation (CC):'''
  <pre>
  <pre>
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))
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))
Line 79: Line 128:
</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>  
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))
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))
Line 88: Line 138:
2015-08-06 10:30:03.227 [INFO] Gateway.Port14 - ASSOCIATE ok for 172.16.1.3 0
2015-08-06 10:30:03.227 [INFO] Gateway.Port14 - ASSOCIATE ok for 172.16.1.3 0
</pre>
</pre>
Step 4. RTU sends a request for getNamedVariableListAttributes (domainId: 255Relay; itemId: LLN0$DS1)
'''Step 4. RTU sends a request for getNamedVariableListAttributes (domainId: 255Relay; itemId: LLN0$DS1)'''
<pre>  
<pre>  
16 2015-08-06 10:30:03.231791 10.0.0.104 172.16.1.3 MMS 103 confirmed-RequestPDU ( MMS -> confirmedServiceRequest: getNamedVariableListAttributes (12)
16 2015-08-06 10:30:03.231791 10.0.0.104 172.16.1.3 MMS 103 confirmed-RequestPDU ( MMS -> confirmedServiceRequest: getNamedVariableListAttributes (12)
Line 117: Line 167:
2015-08-06 10:30:04.364 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/SIpMMXU23$MX$A  
2015-08-06 10:30:04.364 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/SIpMMXU23$MX$A  
</pre>
</pre>
Step 5. RTU sends a request for getNameList
'''Step 5. RTU sends a request for getNameList (IEC61850 GetDataSetDirectory)'''
<pre>  
<pre>  
21 2015-08-06 10:30:04.404171 10.0.0.104 172.16.1.3 MMS 90 confirmed-RequestPDU ( MMS -> confirmedServiceRequest: getNameList (1))
21 2015-08-06 10:30:04.404171 10.0.0.104 172.16.1.3 MMS 90 confirmed-RequestPDU ( MMS -> confirmedServiceRequest: getNameList (1))
Line 148: Line 198:
2015-08-06 10:30:04.906 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/SIpMMXU23$MX$A
2015-08-06 10:30:04.906 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/SIpMMXU23$MX$A
</pre>
</pre>
Step 6. RTU reads the LLN0$BR$brcbEV103$RptEna item:
'''Step 6. RTU reads the LLN0$BR$brcbEV103$RptEna and LLN0$BR$brcbEV103$ResvTms items:'''
<pre>  
<pre>  
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))
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))
Line 158: Line 208:
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))
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))
</pre>
</pre>
In the mean time, RTU has changed the "link" status of the device as "connected"
About ResvTms: Indicates the reservation of a control block by a peculiar client. Read http://tissue.iec61850.com/tissue/300
About configuring Vamp devices regarding ResvTms:
<pre>
https://m.vamp.fi/dmsdocument/204
ResvTms included in BRCBs = specifies whether “ResvTms”-attribute is included in
the BRCBs or not (this is actually an extension from Tissue 453 and Edition 2 and
should be set to “No” if the client system does not support this).
NOTE: Martem supports this extension
</pre>
BTW, in the mean time, RTU has changed the "link" status of the device as "connected"
<pre>  
<pre>  
2015-08-06 10:30:04.907 [INFO] Gateway.Port14 - Enable 1 RCB's
2015-08-06 10:30:04.907 [INFO] Gateway.Port14 - Enable 1 RCB's
Line 165: Line 224:
2015-08-06 10:30:04.919 [INFO] Gateway.Port14 - Refresh all values
2015-08-06 10:30:04.919 [INFO] Gateway.Port14 - Refresh all values
</pre>
</pre>
Step 7. RTU sends a write request (with new values) for BRCB3 items (see console.log for details):   
'''Step 7. RTU sends a write request (with new values) for BRCB3 items (see console.log for details):  '''
<pre>
<pre>
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...)
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...)
Line 180: Line 239:
2015-08-06 10:30:06.753 [INFO] Gateway.Port14 - RcbEnable: mms write 255Relay/LLN0$BR$brcbEV103$GI=T
2015-08-06 10:30:06.753 [INFO] Gateway.Port14 - RcbEnable: mms write 255Relay/LLN0$BR$brcbEV103$GI=T
</pre>
</pre>
Step8. RTU reads the RptEna item again:
'''Step8. RTU reads the RptEna item again:'''
<pre>  
<pre>  
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)
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)
Line 189: Line 248:
2015-08-06 10:30:07.721 [INFO] Gateway.Port14 - RcbEnable: report enable ok 255Relay/LLN0$BR$brcbEV103
2015-08-06 10:30:07.721 [INFO] Gateway.Port14 - RcbEnable: report enable ok 255Relay/LLN0$BR$brcbEV103
</pre>
</pre>
Step9. RTU reads parameters of BRCB3 (see console.log for details)
'''Step9. RTU reads parameters of BRCB3 (see console.log for details)'''
<pre>  
<pre>  
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;)
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;)
Line 205: Line 264:
2015-08-06 10:30:08.174 [INFO] Gateway.Port14 - RcbEnable: RCB attribute values: "","255Relay/LLN0$DS1",[0111111111],[011101],+60000,+2053,'0000000000000009'
2015-08-06 10:30:08.174 [INFO] Gateway.Port14 - RcbEnable: RCB attribute values: "","255Relay/LLN0$DS1",[0111111111],[011101],+60000,+2053,'0000000000000009'
</pre>
</pre>
Step10. For some reason, RTU reads ConfRev parameter again:
::::::::::::::::::::::::::::::::::<small>''0-NOT used''
::::::::::::::::::::::::::::::::::''1-data change=TRUE''
::::::::::::::::::::::::::::::::::''1-quality change =TRUE''
::::::::::::::::::::::::::::::::::''1-data update=TRUE''
::::::::::::::::::::::::::::::::::''0-integrity = FALSE''
::::::::::::::::::::::::::::::::::''1-GI enable =TRUE</small>''
'''Step10. RTU reads ConfRev parameter again (i.e to get it if RCB enabling fails):'''
<pre>  
<pre>  
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))
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))
Line 215: Line 280:
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
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
</pre>
</pre>
Step11. RTU requests getVariableAccessAttributes for all the configured objects, one by one and gets initial values:
'''Step11. RTU requests getVariableAccessAttributes for all the configured objects, one by one :'''
<pre>  
<pre>  
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)
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)
Line 228: Line 293:
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.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.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
</pre>
Finally, the protocol is initialised:
<pre>
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
</pre>
'''Step12. 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>
136 2015-08-06 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); )
144 2015-08-06 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>
'''Step13. 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>
158 2015-08-06 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 step14. 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>
</pre>
<pre>  
The response packet contains 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>
</pre>

Latest revision as of 08:31, 13 May 2016

Wireshark and IEC60870-5-104, IEC61850

Some basic filters and examples 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

NOTE: when 61850 capture is recorded after the protocol has initialised (not from the beginning), then Wireshark will not automatically detect the protocol as MMS. However, it is possible to change the "PRES" to "MMS" using the Wireshark menus: 

Go to Edit->preferences->protocol->PRES and edit the users context tale
enter context = 3 and OID = 1.0.9506.2.3 and your trace will be dissected as MMS.


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

61850 Wireshark capture side-by-side with console.log

Case study:

GW6e connects with Vamp255 device over IEC61850.

RTU is configured to use BRCB3 and DS1.

RTU initializes communication, sends GI, executes a SBO command and receives a report (spontaneous) about change of LN state.

Pcap capture file is accessible from this link: http://phobos.martem.ee/shr/61850_example_log/tcplog61850.pcap


Summary:

Step1. TCP-handshake (3-way handshake)

Step2. COTP: connect request (CR) and connect confirmation (CC)

Step3. MMS CONNECT and ACCEPT

Step4. getNamedVariableListAttributes (domainId: 255Relay; itemId: LLN0$DS1)

Step5. getNameList

Step6. Check LLN0$BR$brcbEV103$RptEna item

Step7. Enable and configure BRCB3

Step8. Verify that BRCB3 is enabled

Step9. Verify that BRCB3 is configured correctly

Step10. Read ConfRev parameter

Step11. Read getVariableAccessAttributes for all the configured objects, one by one

Step12. Send GI

Step13. Send control command

Step14. Receive spontaneous (unconfirmed PDU) event for state change


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 (IEC61850 GetDataSetDirectory) 

 
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 and LLN0$BR$brcbEV103$ResvTms items: 

 
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))

About ResvTms: Indicates the reservation of a control block by a peculiar client. Read http://tissue.iec61850.com/tissue/300 About configuring Vamp devices regarding ResvTms: 

https://m.vamp.fi/dmsdocument/204
ResvTms included in BRCBs = specifies whether “ResvTms”-attribute is included in
the BRCBs or not (this is actually an extension from Tissue 453 and Edition 2 and
should be set to “No” if the client system does not support this).
NOTE: Martem supports this extension

BTW, 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'
0-NOT used
1-data change=TRUE
1-quality change =TRUE
1-data update=TRUE
0-integrity = FALSE
1-GI enable =TRUE

Step10. RTU reads ConfRev parameter again (i.e to get it if RCB enabling fails): 

 
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 : 

 
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

Step12. 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) 

 
136	2015-08-06 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); )
144	2015-08-06 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

Step13. 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

158	2015-08-06 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 step14. 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);

The response packet contains 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=2015"