openiec61850 reporting: BdaEntryTime offset

ThE-MaRaC commented 3 years ago

IEC61850_ENTRY_TIME_OFFSET (441763200000L) which represents 14 years (1970 - 1984) in milliseconds is added twice. Once it is added within OpenIec61850 library (com.beanit.openiec61850.BdaEntryTime.getTimestampValue()) and one more time within osgp-protocol-adapter-iec61850 reporting package, so resulting timestamp is invalid.

kevinsmeets commented 3 years ago

Yes, this is a known issue. We are not using the 'time of entry' value (BdaEntryTIme) of a buffered report. We are using a dedicated timestamp (BdaTimestamp) in the buffered report as input for saving records to the database for example. I think the buffered report implementation has been developed using an older version of the OpenIEC61850 library. At that time, the conversion from 1984 to 1970 based timestamps was not part of the library, if I remember correctly.

Little logging which shows the 2 timestamps. One of them is off by 14 years: timeOfEntry: 2034-11-10T13:00:02.280+01:00, the other one is OK: trgTime: 2020-11-10T13:00:02.000+01:00.


2020-11-10 12:42:29.939] [dev-box] [Thread-107] INFO o.o.a.p.i.i.n.r.Iec61850ClientSSLDEventListener@newReport:105 - newReport for device: TST-1, reportId: evn_rpn, timeOfEntry: 2034-11-10T13:00:02.280+01:00, sqNum: 56
2020-11-10 12:42:29.939] [dev-box] [Thread-107] INFO o.o.a.p.i.i.n.r.Iec61850ClientSSLDEventListener@logReportDetails:309 - Report details for device TST-1
                 RptId: evn_rpn
            DataSetRef: SWDeviceGenericIO/LLN0.evn_rpn
               ConfRev: null
               BufOvfl: false
               EntryId: none: [0, 0, 1, 117, -78, 6, -10, -24]
                        (   
    InclusionBitString: [true]
    MoreSegmentsFollow: false
                 SqNum: 56
              SubSqNum: null
           TimeOfEntry: none: 1605009602280
                        (2034-11-10T13:00:02.280+01:00)
           ReasonCodes:
                        0x40    (DataChange)
               DataSet: SWDeviceGenericIO/LLN0.evn_rpn
       DataSet members: 1
                member: SWDeviceGenericIO/CSLC.EvnRpn [ST]
SWDeviceGenericIO/CSLC.EvnRpn.evnType: 3
SWDeviceGenericIO/CSLC.EvnRpn.swNum: 4
SWDeviceGenericIO/CSLC.EvnRpn.trgType: 3
SWDeviceGenericIO/CSLC.EvnRpn.swVal: false
SWDeviceGenericIO/CSLC.EvnRpn.trgTime: Tue Nov 10 12:00:02 UTC 2020
SWDeviceGenericIO/CSLC.EvnRpn.remark: remark
                            evnType: 3 = LIGHT_EVENTS_LIGHT_OFF
                            swNum: 4 = get external index for switch 4
                            trgType: 3 = fixed time trigger
                            swVal: false = OFF
                            trgTime: 2020-11-10T13:00:02.000+01:00
                            remark: remark

2020-11-10 12:42:33.819] [dev-box] [DefaultMessageListenerContainer-2] INFO o.o.c.a.s.EventNotificationMessageService@handleEvents:117 - Saving event for device: TST-1 with eventType: LIGHT_EVENTS_LIGHT_OFF eventTime: 2020-11-10T13:00:02.000+01:00 description: fixed time trigger index: 4

ThE-MaRaC commented 3 years ago

That's correct for SSLD, but LMD events (Iec61850ClientLMDEventListener) are still using TimeOfEntry from the report. Regarding the offset, this was fixed/introduced within openIec61850 library v1.50.

kevinsmeets commented 3 years ago

I did a little test, and don't see a wrong timestamp for the buffered reports for an LMD: timeOfEntry: 2020-11-11T12:08:51.215Z

2020-11-11 12:08:51.215] [dev-box] [Thread-46] INFO o.o.a.p.i.i.n.r.Iec61850ClientLMDEventListener@newReport:45 - newReport for reportId: A, timeOfEntry: 2020-11-11T12:08:51.215Z, sqNum: null
2020-11-11 12:08:51.216] [dev-box] [Thread-46] INFO o.o.a.p.i.i.n.r.Iec61850ClientLMDEventListener@logReportDetails:160 - Report details for device LichtmeterLeeuwarden
                 RptId: A
            DataSetRef: AA1TH01LD0/LLN0.StatNrmlA
               ConfRev: null
               BufOvfl: null
               EntryId: null
    InclusionBitString: [false, true, false, false, true, true, false, false, false, false, false, false, false, false, true, false, false]
    MoreSegmentsFollow: false
                 SqNum: null
              SubSqNum: null
           TimeOfEntry: null
               DataSet: AA1TH01LD0/LLN0.StatNrmlA
       DataSet members: 4
                member: AA1TH01LD0/SPGGIO1.Ind [ST]
AA1TH01LD0/SPGGIO1.Ind.stVal: true
AA1TH01LD0/SPGGIO1.Ind.q: 0x00 0x00
AA1TH01LD0/SPGGIO1.Ind.t: Thu Jan 01 00:00:00 UTC 1970
                member: AA1TH01LD0/SPGGIO2.Ind [ST]
AA1TH01LD0/SPGGIO2.Ind.stVal: true
AA1TH01LD0/SPGGIO2.Ind.q: 0x00 0x00
AA1TH01LD0/SPGGIO2.Ind.t: Thu Jan 01 00:00:00 UTC 1970
                member: AA1TH01LD0/SPGGIO3.Ind [ST]
AA1TH01LD0/SPGGIO3.Ind.stVal: true
AA1TH01LD0/SPGGIO3.Ind.q: 0x00 0x00
AA1TH01LD0/SPGGIO3.Ind.t: Thu Jan 01 00:00:00 UTC 1970
                member: AA1TH01LD0/SPGGIO4.Ind [ST]
AA1TH01LD0/SPGGIO4.Ind.stVal: true
AA1TH01LD0/SPGGIO4.Ind.q: 0x00 0x00
AA1TH01LD0/SPGGIO4.Ind.t: Thu Jan 01 00:00:00 UTC 1970

I will look into this some more at a later time.

ThE-MaRaC commented 3 years ago

I assume that 2020-11-11T12:08:51.215Z is actually current time in UTC, because TimeOfEntry is missing in your report. This is already patched in my version of the service, but I can remove it and provide a trace.

kevinsmeets commented 3 years ago

You are correct, TimeOfEntry is null in the buffered report. I guess a current time is used for this particular implementation. I'm going to look into this in more detail at a later time. Possibly create a JIRA ticket and discuss this with the team. Thank you for your attention regarding this item, I appreciate it 👍

You mention you have made a change or patch. Would you be willing to commit your changes to a bug fix branch? I would love to have a look at the code. For now, I don't think I'm that interested in a trace, obviously, I could be wrong there...

ThE-MaRaC commented 3 years ago

Sure, I can provide a pull request with the correction. I will use this bug report as a reference.

OSGP / Documentation

openiec61850 reporting: BdaEntryTime offset #235