Wiresharking IEC: Difference between revisions
Line 188: | Line 188: | ||
<pre> | <pre> | ||
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> | |||
Step9. RTU reads parameters of BRCB3 (see console.log for details) | |||
<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;) | |||
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) | |||
</pre> | |||
The following data is received: | |||
<pre> | |||
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' | |||
</pre> | |||
Step10. For some reason, RTU reads ConfRev parameter again: | |||
<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)) | |||
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)) | |||
</pre> | |||
And outputs to console.log: | |||
<pre> | |||
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 | |||
</pre> | |||
Step11. RTU requests getVariableAccessAttributes for all the configured objects, one by one and gets initial values: | |||
<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) | |||
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;) | |||
</pre> | |||
The results are available in console.log: | |||
<pre> | |||
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 | |||
</pre> | |||
<pre> | |||
</pre> | </pre> |
Revision as of 14:12, 6 August 2015
Some basic filters for analysing wireshark logs in case of IEC protocols.
IEC60870-5-104
If you use some port other than 2404, then Wireshark will not automatically detect the correct protocol. In this case,
- select a IEC104 packet from the captured packets list,
- go to Analyse -> Decode as
- In the transport tab, select TCP : both ports and protocol 104apci
Dispaly packages with TCP length>0 (no ack messages)
tcp.len>0
IEC104 packages
104apci
IEC104 packages (without testframes, S-packets etc)
104asdu
Packets involving 192.168.0.111
ip.addr==192.168.0.111
TCP port 2404
tcp.port==2404
Information object address 401
104asdu.ioa == 401
Spontaneous events (COT==3)
104asdu.causetx == 3
Command messages (COT 6, 7, 10)
104asdu.causetx == 6 //Activation 104asdu.causetx == 7 //Confirmation 104asdu.causetx == 10 //Termination
Testframe messages
104apci.utype == 0x10 //Activation 104apci.utype == 0x20 //Confirmation
S-Type messages
104apci.type == 0x01
General Interrogation commands
104asdu.typeid == 100 //Global, Group1...Group16 104asdu.qoi == 20 //Global 104asdu.qoi == 21 //Group1 104asdu.qoi == 35 //Group15 Do not use Group 16 GI with Martem devices. This is reserved.
Clock syncronisation commands
104asdu.typeid == 103
Show IEC104 measurements with value "0"
IEC104asdu.normval == 0
IEC61850 and Wireshark basics
MMS: Manufacturing Message Specification GOOSE: Generic Object Oriented Substation Events
Filter IEC61850 packets
mms
Display packets involving TCP port 102
tcp.port==102
Display messages containing domain ID "VampRelay"
mms.domainId == "VampRelay"
Display messages containing item ID "VI1GGIO137$CO$SPCSO$Oper" (VI1 control command)
mms.itemId == "VI1GGIO137$CO$SPCSO$Oper"
Display messages containing control commands (Service request 5 = write)
mms.confirmedServiceRequest == 5
Dispaly packets containing message "success" (response to command message)
mms.Write_Response_item == 1
Wireshark capture side-by-side with console.log
Case study: GW6e connects with Vamp255 device over IEC61850. RTU initializes communication, sends GI, executes a SBO command and receives a report (spontaneous) about change of LN state.
Step1. RTU starts connecting to the IED with a TCP-handshake (3-way handshake):
6 2015-08-06 10:29:59.943110 10.0.0.104 172.16.1.3 TCP 74 56642→102 [SYN] Seq=0 Win=5840 Len=0 MSS=1460 SACK_PERM=1 TSval=2023 TSecr=0 WS=64 7 2015-08-06 10:30:02.443727 172.16.1.3 10.0.0.104 TCP 60 102→56642 [SYN, ACK] Seq=0 Ack=1 Win=2047 Len=0 8 2015-08-06 10:30:02.443952 10.0.0.104 172.16.1.3 TCP 54 56642→102 [ACK] Seq=1 Ack=1 Win=5840 Len=0
Step2. COTP (Connection Oriented Transport Protocol) connect request (CR) and connect confirmation (CC):
9 2015-08-06 10:30:02.444413 10.0.0.104 172.16.1.3 COTP 76 CR TPDU src-ref: 0x0001 dst-ref: 0x0000 (PDU Type: CR Connect Request (0x0e)) 10 2015-08-06 10:30:02.539805 172.16.1.3 10.0.0.104 TCP 60 102→56642 [ACK] Seq=1 Ack=23 Win=2025 Len=0 11 2015-08-06 10:30:02.739731 172.16.1.3 10.0.0.104 COTP 76 CC TPDU src-ref: 0x0002 dst-ref: 0x0001 (PDU Type: CC Connect Confirm (0x0d))
Read more about COTP: https://wiki.wireshark.org/COTP Step 3. MMS CONNECT and ACCEPT
13 2015-08-06 10:30:02.740616 10.0.0.104 172.16.1.3 MMS 244 initiate-RequestPDU (ISO 8327-1 OSI Session Protocol -> SPDU Type: CONNECT (CN) SPDU (13)) 15 2015-08-06 10:30:03.225870 172.16.1.3 10.0.0.104 MMS 212 initiate-ResponsePDU (ISO 8327-1 OSI Session Protocol -> SPDU Type: ACCEPT (AC) SPDU (14))
After successful MMS connection, RTU will write to console.log:
2015-08-06 10:30:03.227 [INFO] Gateway.Port14 - ASSOCIATE ok for 172.16.1.3 0
Step 4. RTU sends a request for getNamedVariableListAttributes (domainId: 255Relay; itemId: LLN0$DS1)
16 2015-08-06 10:30:03.231791 10.0.0.104 172.16.1.3 MMS 103 confirmed-RequestPDU ( MMS -> confirmedServiceRequest: getNamedVariableListAttributes (12) 19 2015-08-06 10:30:03.606017 172.16.1.3 10.0.0.104 MMS 316 confirmed-ResponsePDU ( MMS-> confirmedServiceResponse: getNamedVariableListAttributes (12) (itemId: I3pMMXU1$MX$A$phsA, I3pMMXU1$MX$A$phsB....up to SIpMMXU23$MX$A )
The response contains all the item ID-s from 255Relay that are in dataset LLN0$DS1. The RTU logs this information as follows:
2015-08-06 10:30:03.607 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/I3pMMXU1$MX$A$phsA 2015-08-06 10:30:03.609 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/I3pMMXU1$MX$A$phsB 2015-08-06 10:30:03.644 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/I3pMMXU1$MX$A$phsC 2015-08-06 10:30:03.684 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/Obj1CSWI1$ST$Pos 2015-08-06 10:30:03.724 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/Obj1CSWI1$ST$BlkCls 2015-08-06 10:30:03.764 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/Obj1CSWI1$ST$BlkOpn 2015-08-06 10:30:03.804 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/Obj2CSWI2$ST$Pos 2015-08-06 10:30:03.844 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/Obj2CSWI2$ST$BlkCls 2015-08-06 10:30:03.884 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/Obj2CSWI2$ST$BlkOpn 2015-08-06 10:30:03.924 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/Obj3CSWI3$ST$Pos 2015-08-06 10:30:03.964 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/Obj3CSWI3$ST$BlkCls 2015-08-06 10:30:04.004 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/Obj3CSWI3$ST$BlkOpn 2015-08-06 10:30:04.044 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/U3pMMXU4$MX$PhV$phsA 2015-08-06 10:30:04.084 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/U3pMMXU4$MX$PhV$phsB 2015-08-06 10:30:04.124 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/U3pMMXU4$MX$PhV$phsC 2015-08-06 10:30:04.165 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/U3ppMMXU5$MX$PPV$phsAB 2015-08-06 10:30:04.205 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/U3ppMMXU5$MX$PPV$phsBC 2015-08-06 10:30:04.244 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/U3ppMMXU5$MX$PPV$phsCA 2015-08-06 10:30:04.284 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/UoMMXU10$MX$PhV$neut 2015-08-06 10:30:04.324 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/VI1GGIO137$ST$SPCSO 2015-08-06 10:30:04.364 [INFO] Gateway.Port14 - LD=255Relay LN=LLN0 DataSet=DS1 member=255Relay/SIpMMXU23$MX$A
Step 5. RTU sends a request for getNameList
21 2015-08-06 10:30:04.404171 10.0.0.104 172.16.1.3 MMS 90 confirmed-RequestPDU ( MMS -> confirmedServiceRequest: getNameList (1)) 23 2015-08-06 10:30:04.891920 172.16.1.3 10.0.0.104 MMS 96 confirmed-ResponsePDU ( MMS -> confirmedServiceResponse: getNameList (1))
The RTU log:
2015-08-06 10:30:04.897 [INFO] Gateway.Port14 - Find DIs and AIs 2015-08-06 10:30:04.898 [INFO] Gateway.Port14 - found report=255Relay/LLN0.brcbEV103,DATA-SET="255Relay/LLN0$DS1" 2015-08-06 10:30:04.898 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/I3pMMXU1$MX$A$phsA 2015-08-06 10:30:04.899 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/I3pMMXU1$MX$A$phsB 2015-08-06 10:30:04.900 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/I3pMMXU1$MX$A$phsC 2015-08-06 10:30:04.900 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/Obj1CSWI1$ST$Pos 2015-08-06 10:30:04.900 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/Obj1CSWI1$ST$BlkCls 2015-08-06 10:30:04.901 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/Obj1CSWI1$ST$BlkOpn 2015-08-06 10:30:04.901 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/Obj2CSWI2$ST$Pos 2015-08-06 10:30:04.901 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/Obj2CSWI2$ST$BlkCls 2015-08-06 10:30:04.902 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/Obj2CSWI2$ST$BlkOpn 2015-08-06 10:30:04.902 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/Obj3CSWI3$ST$Pos 2015-08-06 10:30:04.902 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/Obj3CSWI3$ST$BlkCls 2015-08-06 10:30:04.903 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/Obj3CSWI3$ST$BlkOpn 2015-08-06 10:30:04.903 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/U3pMMXU4$MX$PhV$phsA 2015-08-06 10:30:04.904 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/U3pMMXU4$MX$PhV$phsB 2015-08-06 10:30:04.904 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/U3pMMXU4$MX$PhV$phsC 2015-08-06 10:30:04.904 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/U3ppMMXU5$MX$PPV$phsAB 2015-08-06 10:30:04.905 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/U3ppMMXU5$MX$PPV$phsBC 2015-08-06 10:30:04.905 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/U3ppMMXU5$MX$PPV$phsCA 2015-08-06 10:30:04.905 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/UoMMXU10$MX$PhV$neut 2015-08-06 10:30:04.906 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/VI1GGIO137$ST$SPCSO 2015-08-06 10:30:04.906 [INFO] Gateway.Port14 - "255Relay/LLN0$DS1" member=255Relay/SIpMMXU23$MX$A
Step 6. RTU reads the LLN0$BR$brcbEV103$RptEna item:
25 2015-08-06 10:30:05.956536 10.0.0.104 172.16.1.3 MMS 130 confirmed-RequestPDU ( MMS -> confirmedServiceRequest: read (4) (domainId: 255Relay, itemId: LLN0$BR$brcbEV103$RptEna)) 27 2015-08-06 10:30:06.315874 172.16.1.3 10.0.0.104 MMS 86 confirmed-ResponsePDU ( MMS -> confirmedServiceResponse: read (4); listOfAccessResult: 1 item; AccessResult: success (1), FALSE)
The response states that BRCB3 is not enabled. Next, RTU reads the LLN0$BR$brcbEV103$ResvTms parameter:
29 2015-08-06 10:30:06.317941 10.0.0.104 172.16.1.3 MMS 131 confirmed-RequestPDU ( MMS -> confirmedServiceRequest: read (4) domainId: 255Relay; itemId: LLN0$BR$brcbEV103$ResvTms) 31 2015-08-06 10:30:06.747774 172.16.1.3 10.0.0.104 MMS 86 confirmed-ResponsePDU ( MMS -> confirmedServiceResponse: read (4) (AccessResult: success (1), integer: 0))
In the mean time, RTU has changed the "link" status of the device as "connected"
2015-08-06 10:30:04.907 [INFO] Gateway.Port14 - Enable 1 RCB's 2015-08-06 10:30:04.912 [DEBUG] Gateway.Port14 - StatusDi: connected 2015-08-06 10:30:04.919 [INFO] Gateway.Port14 - Connected 2015-08-06 10:30:04.919 [INFO] Gateway.Port14 - Refresh all values
Step 7. RTU sends a write request (with new values) for BRCB3 items (see console.log for details):
32 2015-08-06 10:30:06.754924 10.0.0.104 172.16.1.3 MMS 431 confirmed-RequestPDU ( MMS -> confirmedServiceRequest: write (5) (domainId: 255Relay; Item ID-s and values...) 34 2015-08-06 10:30:07.195910 172.16.1.3 10.0.0.104 MMS 96 confirmed-ResponsePDU ( MMS -> confirmedServiceResponse: write (5) (write: 7 items; Write-Response item: success (1) for all 7 writes))
RTU console.log:
2015-08-06 10:30:06.749 [INFO] Gateway.Port14 - RcbEnable: mms write 255Relay/LLN0$BR$brcbEV103$ResvTms=2 2015-08-06 10:30:06.750 [INFO] Gateway.Port14 - RcbEnable: mms write 255Relay/LLN0$BR$brcbEV103$DatSet="255Relay/LLN0$DS1" 2015-08-06 10:30:06.750 [INFO] Gateway.Port14 - RcbEnable: mms write 255Relay/LLN0$BR$brcbEV103$OptFlds=[0111111111] 2015-08-06 10:30:06.751 [INFO] Gateway.Port14 - RcbEnable: mms write 255Relay/LLN0$BR$brcbEV103$TrgOps=[011101] 2015-08-06 10:30:06.752 [INFO] Gateway.Port14 - RcbEnable: mms write 255Relay/LLN0$BR$brcbEV103$PurgeBuf=T 2015-08-06 10:30:06.752 [INFO] Gateway.Port14 - RcbEnable: mms write 255Relay/LLN0$BR$brcbEV103$RptEna=T 2015-08-06 10:30:06.753 [INFO] Gateway.Port14 - RcbEnable: mms write 255Relay/LLN0$BR$brcbEV103$GI=T
Step8. RTU reads the RptEna item again:
35 2015-08-06 10:30:07.197131 10.0.0.104 172.16.1.3 MMS 130 confirmed-RequestPDU (MMS -> confirmedServiceRequest: read (4) (itemId: LLN0$BR$brcbEV103$RptEna) 42 2015-08-06 10:30:07.720025 172.16.1.3 10.0.0.104 MMS 86 confirmed-ResponsePDU (MMS -> confirmedServiceResponse: read (4) (AccessResult: success (1), TRUE)
This time RCB is enabled and RTU then writes to the console.log:
2015-08-06 10:30:07.721 [INFO] Gateway.Port14 - RcbEnable: report enable ok 255Relay/LLN0$BR$brcbEV103
Step9. RTU reads parameters of BRCB3 (see console.log for details)
44 2015-08-06 10:30:07.727357 10.0.0.104 172.16.1.3 MMS 398 confirmed-RequestPDU (MMS -> confirmedServiceRequest: read (4) (variableAccessSpecificatn: listOfVariable (0); listOfVariable: 7 items;) 46 2015-08-06 10:30:08.135870 172.16.1.3 10.0.0.104 MMS 132 confirmed-ResponsePDU (MMS -> confirmedServiceResponse: read (4) (listOfAccessResult: 7 items; AccessResult: success (1); values in console.log)
The following data is received:
2015-08-06 10:30:07.722 [INFO] Gateway.Port14 - RcbEnable: mms read 255Relay/LLN0$BR$brcbEV103$RptID 2015-08-06 10:30:07.722 [INFO] Gateway.Port14 - RcbEnable: mms read 255Relay/LLN0$BR$brcbEV103$DatSet 2015-08-06 10:30:07.722 [INFO] Gateway.Port14 - RcbEnable: mms read 255Relay/LLN0$BR$brcbEV103$OptFlds 2015-08-06 10:30:07.723 [INFO] Gateway.Port14 - RcbEnable: mms read 255Relay/LLN0$BR$brcbEV103$TrgOps 2015-08-06 10:30:07.724 [INFO] Gateway.Port14 - RcbEnable: mms read 255Relay/LLN0$BR$brcbEV103$IntgPd 2015-08-06 10:30:07.724 [INFO] Gateway.Port14 - RcbEnable: mms read 255Relay/LLN0$BR$brcbEV103$ConfRev 2015-08-06 10:30:07.725 [INFO] Gateway.Port14 - RcbEnable: mms read 255Relay/LLN0$BR$brcbEV103$EntryID 2015-08-06 10:30:08.174 [INFO] Gateway.Port14 - RcbEnable: RCB attribute values: "","255Relay/LLN0$DS1",[0111111111],[011101],+60000,+2053,'0000000000000009'
Step10. For some reason, RTU reads ConfRev parameter again:
48 2015-08-06 10:30:08.175876 10.0.0.104 172.16.1.3 MMS 131 confirmed-RequestPDU (MMS -> confirmedServiceRequest: read (4) (itemId: LLN0$BR$brcbEV103$ConfRev)) 50 2015-08-06 10:30:08.593893 172.16.1.3 10.0.0.104 MMS 88 confirmed-ResponsePDU (MMS -> confirmedServiceResponse: read (4) (AccessResult: success (1); unsigned: 2053))
And outputs to console.log:
2015-08-06 10:30:08.595 [INFO] Gateway.Port14 - RcbEnable: ConfRev=2053 2015-08-06 10:30:08.596 [DEBUG] Gateway.Port14 - rptId=255Relay/LLN0$BR$brcbEV103,confRev=2053,datSet=255Relay/LLN0$DS1,entryId='0000000000000009',time=08/06/2015_07:30:06.955
Step11. RTU requests getVariableAccessAttributes for all the configured objects, one by one and gets initial values:
52 2015-08-06 10:30:08.634159 10.0.0.104 172.16.1.3 MMS 115 confirmed-RequestPDU (MMS -> confirmedServiceRequest: getVariableAccessAttributes (6); domainId: 255Relay; itemId: I3pMMXU1$MX$A$phsA) 54 2015-08-06 10:30:09.055958 172.16.1.3 10.0.0.104 MMS 152 confirmed-ResponsePDU (MMS -> confirmedServiceResponse: getVariableAccessAttributes (6); components: 3 items;)
The results are available in console.log:
2015-08-06 10:30:09.057 [DEBUG] Gateway.Port14 - 255Relay/I3pMMXU1$MX$A$phsA={{{f0.000000e+00}},[0000000000000],(u08/06/2015_07:21:14.532,[00110100])} [general-interrogation] => object not configured 2015-08-06 10:30:09.519 [DEBUG] Gateway.Port14 - 255Relay/I3pMMXU1$MX$A$phsB={{{f0.000000e+00}},[0000000000000],(u08/06/2015_07:21:14.532,[00110100])} [general-interrogation] => object not configured 2015-08-06 10:30:09.977 [DEBUG] Gateway.Port14 - 255Relay/I3pMMXU1$MX$A$phsC={{{f0.000000e+00}},[0000000000000],(u08/06/2015_07:21:14.533,[00110100])} [general-interrogation] => object not configured ... 2015-08-06 10:30:10.505 [DEBUG] Gateway.Port14 - rcv DI 255Relay/Obj1CSWI1$ST$Pos <> id - 1 <> val=01(1),time=u08/06/2015_07:21:14.663,[00110100],quality=0000000000000,reason=[general-interrogation],type=bitString 2015-08-06 10:30:10.506 [INFO] Gateway.Port14.db - obj1 st (255Relay/Obj1CSWI1$ST$Pos) event: 1 flags: GwTime GI time: 2015-Aug-06 07:30:10.505960, received