Received unknown message from PMU
Closed this issue · 12 comments
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!
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.
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!
:)
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?
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.
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!
@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!
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
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?
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.
Ok, great, thanks.
I'm closing this bug than.