Wiresharking IEC

From Phobos Wiki
Jump to navigation Jump to search

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 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. Get initial values: 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 

 
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

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) 

 
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

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=1971"