Received unknown message from PMU

[hrvojej]

Hi,

I'm having problem receiving Data Frames from my PMU.

When I do test with example scripts using randomPMU.py as sample PMU and tinyPDC.py as PDC everything works perfectly.
But when I connect to my PMU I get ConfigFrame2 without any problems after that I got error receiving Data Frames.
PMU is on 192.168.100.214, port is 4712. PCAP capture taken with Wireshark is here.

C:\pypmu\venv\Scripts\python.exe C:/pypmu/iripdc.py
2021-12-09 18:57:08,984 INFO [2] - PDC successfully connected to PMU (192.168.100.214:4712)
CONFIG:  b'\xaaA\x00\x12\x00\x02a\xb2Ct\x00\x0f\x05\r\x00\x05\xd4x'
2021-12-09 18:57:08,999 DEBUG [2] - Received ConfigFrame2 from PMU (192.168.100.214:4712)
RECEIVED MESSAGE FROM PMU: b'\xaa1\x01\xda\x00\x02a\xb2Cv\x0f\x00\x00\x00\x00\xff\xff\xff\x00\x01STATION A       \x00\x02\x00\x00\x00\x08\x00\x00\x00\x01IAPM            IBPM            ICPM            VAPM            VBPM            VCPM            VSPM            V1PM            SV1             SV2             SV3             SV4             SV5             SV6             SV7             SV8             SV9             SV10            SV11            SV12            SV13            SV14            SV15            SV16            \x01\x00W\xe3\x01\x00W\xe3\x01\x00W\xe3\x00\x03\r@\x00\x03\r@\x00\x03\r@\x00\x02\xbf \x00\x03\r@\x00\x00\xff\xff\x00\x01\x00\x04\x002\xc3\x12'
START COMMAND:  b'\xaaA\x00\x12\x00\x02a\xb2Ct\x00\x0fA\xb2\x00\x02\xd2<'
2021-12-09 18:57:08,999 INFO [2] - Requesting to start sending from PMU (192.168.100.214:4712)
2021-12-09 18:57:09,031 WARNING [2] - Received unknown message from PMU (192.168.100.214:4712)
2021-12-09 18:57:09,031 INFO [2] - Connection to PMU closed (192.168.100.214:4712)

Any kind of help is highly appreciated,
Thanks!

[sstevan]

Hey @hrvojej

You might get better insight if you simply remove try / except on line 144 in pdc.py file.

            try:
                received_message = CommonFrame.convert2frame(received_data, self.pmu_cfg2)  # Try to decode received data
                self.logger.debug("[%d] - Received %s from PMU (%s:%d)", self.pdc_id, type(received_message).__name__,
                                  self.pmu_ip, self.pmu_port)
            except FrameError:
                self.logger.warning("[%d] - Received unknown message from PMU (%s:%d)",
                                    self.pdc_id, self.pmu_ip, self.pmu_port)

to this

            # try:
            received_message = CommonFrame.convert2frame(received_data, self.pmu_cfg2)  # Try to decode received data
            self.logger.debug("[%d] - Received %s from PMU (%s:%d)", self.pdc_id, type(received_message).__name__,
                              self.pmu_ip, self.pmu_port)
            # except FrameError:
            #     self.logger.warning("[%d] - Received unknown message from PMU (%s:%d)",
            #                         self.pdc_id, self.pmu_ip, self.pmu_port)

Even better, you can try with traceback and something like traceback.print_stack() and traceback.print_exc().
This will help you pinpoint the actual issue.

[hrvojej]

Hey @sstevan ,

thank you for that - it helped me find the error:

File "C:\pypmu\synchrophasor\frame.py", line 1973, in _int2stat
    unlocked = DataFrame.UNLOCKED_TIME_WORDS[stat & 0x30]
KeyError: 48

Program correctly identifies stat = 24624 (0x6030).
So stat & 0x30 = 48 .
Problem is that 48 is non-existing key. Fromframe.pyI can see that DataFrame.UNLOCKED_TIME_WORDS gives:
{0: '<10', 1: '<100', 2: '<1000', 3: '>1000'}
So 1, 2 or 3 are only possible values.

Any advice on what can I do now?

I assume that stat in binary is actually 110000000110000 which is 15 bits not 16. So I'm somehow missing one bit here.
This is stat from C37.118, and Unlock time in it:

So if I'm reading correctly bits 05-04 is Unlocked time and it suppose to be 11 as I read it from my stat value. From standard it says that this is unlocked time > 1000s which would than be option 3: '>1000' in UNLOCKED_TIME_WORDS.

Anyway I can change code so that value get calculated properly, or should I just hardcode UNLOCKED_TIME_WORDS on 3?

EDIT
I've edited file "C:\pypmu\synchrophasor\frame.py", line 1973
and just hardcoded UNLOCKED_TIME_WORDS on 3 :
unlocked = DataFrame.UNLOCKED_TIME_WORDS[3]

and I started to receive data!
:)

[hrvojej]

Since standard says that:

Bits 4–5―Unlocked time: indicates a range of seconds since loss of synch was detected. This counts
seconds from the loss of lock on time synch until it is reacquired. When sync is reacquired, the code goes to
00. The criteria for determining when lock on time synch is achieved or lost is not specified in this
standard. This will be normally implemented as follows:

Bit code -- Indication
00 -- Locked or unlocked less than 10 s
01 -- Unlocked 10 s or longer but less than 100 s
10 -- Unlocked 100 s or longer but less than 1000 s
11 -- Unlocked 1000 s or more

I guess I shouldn't keep this value hardcoded. Biggest problem is why is my STAT 15bit instead 16bit long and how to get around this?

[sstevan]

Hey @hrvojej,

Looks like shift operation is missing here:

unlocked = DataFrame.UNLOCKED_TIME_WORDS[(stat & 0x30) >> 4]

Shifting should be done for each flag in stat word.

[hrvojej]

According to your comment I've changed lines 1956 - 1969 in synchrophasor/frame.py

        measurement_status = DataFrame.MEASUREMENT_STATUS_WORDS[stat >> 15]
        sync = bool((stat & 0x2000) >> 13)

        if ((stat & 0x1000) >> 12):
            sorting = "arrival"
        else:
            sorting = "timestamp"

        trigger = bool((stat & 0x800) >> 11)
        cfg_change = bool((stat & 0x400) >> 10)
        modified = bool((stat & 0x200) >> 9)
        time_quality = DataFrame.TIME_QUALITY_WORDS[(stat & 0x1c0) >> 6]
        unlocked = DataFrame.UNLOCKED_TIME_WORDS[(stat & 0x30) >> 4]
        trigger_reason = DataFrame.TRIGGER_REASON_WORDS[stat & 0xf]

According to this:

After code updating everything seems to be running fine.
Please check if that looks ok with you.
Thanks!

[sstevan]

Thanks @hrvojej

I will keep this one open until we get this resolved.

[veljkoDjurkovic]

@hrvojej
Hello, I found some problems that are causing this error.

First, in line 1920 in frame.py:
stat = measurement_status << 2
This should be written this way:
stat = measurement_status << 1 because, according to the standard, PMU sync takes only 1 bit, so if we shift this two times, we have one zero more than we actually need to have.

Next, in line 1955 should be:
measurement_status = DataFrame.MEASUREMENT_STATUS_WORDS[stat >> 14]
If we shift this one 15 times, we will loose less significant bit in Data error bits.
So, this whole part of code should be written like this:

    measurement_status = DataFrame.MEASUREMENT_STATUS_WORDS[stat >> 14]
    sync = bool(stat & 0x2000)

    if stat & 0x1000:
        sorting = "arrival"
    else:
        sorting = "timestamp"

    trigger = bool(stat & 0x800)
    cfg_change = bool(stat & 0x400)
    modified = bool(stat & 0x200)

    time_quality = DataFrame.TIME_QUALITY_WORDS[(stat & 0x1c0)>>6]
    unlocked = DataFrame.UNLOCKED_TIME_WORDS[(stat & 0x30)>>4]
    trigger_reason = DataFrame.TRIGGER_REASON_WORDS[stat & 0xf]

    return measurement_status, sync, sorting, trigger, cfg_change, modified, time_quality, unlocked, trigger_reason

We don't really have to do any shifting with trigger and cfg_change, since they are casted into bool types, but shifting will not cause any error.
Tell me if you agree with those, and I will have frame.py updated as soon it is possible.

Thank you for helping us!
Best regards!

[hrvojej]

Hi Veljko, Your assumption seems correct. Unfortunately currently I don't have time to properly test this but if shifting is done according to number of bits each field occupies in standard than I guess it's correct. I'll implement this within 3 weeks time and report back to you. Hrvoje

…

On Tue, Jul 19, 2022, 17:12 Veljko Djurkovic ***@***.***> wrote: @hrvojej <https://github.com/hrvojej> Hello, I found some problems that are causing this error. First, in line 1920 in frame.py: stat = measurement_status << 2 This should be written this way: stat = measurement_status << 1 because, according to the standard, PMU sync takes only 1 bit, so if we shift this two times, we have one zero more than we actually need to have. Next, in line 1955 should be: measurement_status = DataFrame.MEASUREMENT_STATUS_WORDS[stat >> 14] If we shift this one 15 times, we will loose less significant byte in Data error bits. So, this whole part of code should be written like this: *measurement_status = DataFrame.MEASUREMENT_STATUS_WORDS[stat >> 14]* sync = bool(stat & 0x2000) if stat & 0x1000: sorting = "arrival" else: sorting = "timestamp" trigger = bool(stat & 0x800) cfg_change = bool(stat & 0x400) modified = bool(stat & 0x200) **_time_quality = DataFrame.TIME_QUALITY_WORDS[(stat & 0x1c0)>>6] unlocked = DataFrame.UNLOCKED_TIME_WORDS[(stat & 0x30)>>4]_** trigger_reason = DataFrame.TRIGGER_REASON_WORDS[stat & 0xf] return measurement_status, sync, sorting, trigger, cfg_change, modified, time_quality, unlocked, trigger_reason We don't really have to do any shifting with *trigger and cfg_change*, since they are casted into bool types, but shifting will not cause any error. Tell me if you agree with those, and I will have frame.py updated as soon it is possible. Thank you for helping us! Best regards! — Reply to this email directly, view it on GitHub <#35 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAIFMSLVW6NH2XRHPEZ7KVLVU3AUDANCNFSM5JXD3UTA> . You are receiving this because you were mentioned.Message ID: ***@***.***>

[veljkoDjurkovic]

Thank you @hrvojej for very fast response!

I'm glad that we might have this issue closed soon.
I'm looking forward to your report.

Veljko

[hrvojej]

Seems like everything is working correctly.
Can you just comment on line:
sync = bool((stat & 0x2000) >> 13)which is:
sync = bool(stat & 0x2000)
in your code.

Are you sure sync doesn't need any shifting?

[veljkoDjurkovic]

@hrvojej

The thing is that sync is casted to bool, so we don't need to shift it since bool casting returns True for every number which is not zero.

[hrvojej]

Ok, great, thanks.
I'm closing this bug than.