PGM activation and spurious zone status

Benoit3 commented 2 years ago

Alarm system

EVO192 (V6.86) + IP100 (V5.1) + Hassio baudrate 57600+ "System Options -> Communication -> “Transmit zone status on serial port” " activated

Environment

RPI + Python version 3.8

Git branch

V2.7.1

Describe the bug

A PGM is used to open the motor driven gate. PGM is activated through MQTT message "on" and deactivated with a 2s timer (defined in EVO panel) to generate a pulse (duration 1 to 2s) on the gate controler. A magnetic sensor switch is used to detect the gate close status and connected to one EVO zone. I observe (In PAI log and through send MQTT messages) spurious status on zone associated to the gate: when an open request is done through PAI (and the PGM) the gate open (normal), the zone status first change to open (correct), 1s later change back (error) to close then back to open (correct finally) 10 s after.

This spurious behaviour is seen on other zones which are opened simultaneously with the gate (just after PGM activation).

This spurious behaviour of the zone status is not seen if the PGM is activated through another method (EVO remote control->utility key->PGM) or via direct activation of the gate controler.

=> it seems that zone status reported just after a PGM activation are valid during 1 s, corrupted during 10s and correct after.

To Reproduce

When the MQTT message is end to open the gate:

the PGM is well activated.
the zone open status open is well changed to True (in the log) and corresponding MQTT message send
But one second later the open status open is erroneously send back to False (with erroneous MQTT message send)
Around 10 s later the zone open status is corrected (with associated MQTT message)

Logs

It seems it is not possible to send you logs through keybase.io (Error: no valid primary key self-signature or key(s) have expired)

So I send you commented extract without sensitive info:

an MQTT message is sent (from Hassio) to open the gate through PAI and the PGM "Portail"

2022-03-19 11:02:53,644 - INFO - PAI.paradox.interfaces.mqtt.basic - message topic=paradox/control/outputs/Portail, payload=on 2022-03-19 11:02:53,646 - DEBUG - PAI.paradox.interfaces.mqtt.basic - Output command: Portail=on user: None 2022-03-19 11:02:53,646 - DEBUG - PAI.paradox.paradox - Control Output: Portail - on 2022-03-19 11:02:53,784 - INFO - PAI.paradox.hardware.evo.panel - PGM command: "on" succeeded 2022-03-19 11:02:53,970 - DEBUG - PAI.paradox.hardware.evo.panel - Received status response: 1 ..... 2022-03-19 11:02:55,127 - DEBUG - PAI.paradox.hardware.evo.panel - Received status response: 7

Here (2s later) we can see the zone "Portail" status changed from False to True, it is correct

2022-03-19 11:02:55,307 - DEBUG - PAI.paradox.data.memory_storage - Change zone/Portail/open from False to True

corresponding MQTT message is send : :-) !

2022-03-19 11:02:55,312 - DEBUG - PAI.paradox.interfaces.mqtt.core - MQTT: paradox/states/zones/Portail/open=True ....

But here (1.5s later) the zone "Portail" status is change back to False, it is an ERROR, electrical status of the input didn't change, this event is not seen with PRT3

2022-03-19 11:02:56,611 - DEBUG - PAI.paradox.hardware.evo.panel - Received status response: 58 2022-03-19 11:02:56,843 - DEBUG - PAI.paradox.paradox - pgm/line_ring:False ignored 2022-03-19 11:02:56,845 - DEBUG - PAI.paradox.data.memory_storage - Change system/date/time from 2022-03-19 12:02:41 to 2022-03-19 12:02:47 2022-03-19 11:02:56,845 - DEBUG - PAI.paradox.data.memory_storage - Change system/power/vdc from 16.6 to 16.5 2022-03-19 11:02:56,845 - DEBUG - PAI.paradox.data.memory_storage - Change system/power/dc from 11.5 to 11.6 2022-03-19 11:02:56,847 - DEBUG - PAI.paradox.data.memory_storage - Change zone/Portail/open from True to False 2022-03-19 11:02:56,863 - DEBUG - PAI.paradox.lib.ps - Future already done 2022-03-19 11:02:56,865 - DEBUG - PAI.paradox.paradox - Could not create event from change 2022-03-19 11:02:56,865 - DEBUG - PAI.paradox.interfaces.mqtt.core - MQTT: paradox/states/system/date/time=2022-03-19 12:02:47 2022-03-19 11:02:56,865 - DEBUG - PAI.paradox.paradox - Could not create event from change 2022-03-19 11:02:56,869 - DEBUG - PAI.paradox.interfaces.mqtt.core - MQTT: paradox/states/system/power/vdc=16.5 2022-03-19 11:02:56,869 - DEBUG - PAI.paradox.interfaces.mqtt.core - MQTT: paradox/states/system/power/dc=11.6

And the corresponding MQTT erroneous message is send

2022-03-19 11:02:56,870 - DEBUG - PAI.paradox.interfaces.mqtt.core - MQTT: paradox/states/zones/Portail/open=False .....

10 second later the zone "Portail" status is definitely corrected to True

022-03-19 11:03:06,544 - DEBUG - PAI.paradox.hardware.evo.panel - Received status response: 58 2022-03-19 11:03:06,726 - DEBUG - PAI.paradox.paradox - pgm/line_ring:False ignored 2022-03-19 11:03:06,728 - DEBUG - PAI.paradox.data.memory_storage - Change system/date/time from 2022-03-19 12:02:47 to 2022-03-19 12:02:57 2022-03-19 11:03:06,728 - DEBUG - PAI.paradox.data.memory_storage - Change system/power/dc from 11.6 to 11.7 2022-03-19 11:03:06,730 - DEBUG - PAI.paradox.data.memory_storage - Change zone/Portail/open from False to True

yozik04 commented 2 years ago

After PAI triggers PGM it queues refresh of PGM statuses. It should happen just after sending PGM command to the panel. You can try to enable dumping messages that may shed some more light on it. I currently have no idea what is wrong.

Benoit3 commented 2 years ago

Hello,

I thank you for your answer. In the below file with dumping messages: paradox.log

line 11 at 2022-03-21 21:02:36,438 you can see PGM on activation. line 3620 at 2022-03-21 21:02:38,068 you can see zone opening (correct) line 6136 at 2022-03-21 21:02:39,440 pgm status is received line 6254 at 2022-03-21 21:02:39,672 you can see zone closing (spurious / wrong, the zone zone loop is open) => it is the pgm status reception which cause the spurious zone status message line 12457 at 2022-03-21 21:02:49,596 you can see zone opening message (correct the previous one) Regards, Benoit

Benoit3 commented 2 years ago

Hello,

I have an hypothesis, maybe it is completely wrong, I don't know enough the design of PAI and have difficulties to catch the code:

after PGM activation
an EVO event signal a zone status change which just happened
the PGM status memory block only is dumped from the panel memory
all zone, PGM status , etc are refreshed in PAI from saved panel memory dump. As the only memory bloc dumped recently is the PGM one, recent zone change are cleared back to its previous state

Is it an idea to dig?

Regards, Benoit

yozik04 commented 2 years ago

I do not understand how a zone is related to a PGM in your case.

yozik04 commented 2 years ago

When you activate PGM with PAI. PGM gets activated and status refresh request is scheduled to the event loop. So it should refresh within a fraction of a second. If PGM is triggered outside of PAI. PAI does not know about it and will get info regarding state only in periodic status refresh (10 seconds) When PGM status is received it is propagated to MQTT.

Benoit3 commented 2 years ago

I think you should be able to reproduce it if you belong an evo 192 panel or similar:

trigger a PGM with PAI
close or open a zone 1 s later , and have a look to the status

In my case the PGM is triggered with an MQTT message received from hassio, and I look zone status in Hassio.

Here you have the log with dumping messages paradox.log line 11, activation of PGM by PAI: _2022-03-21 21:02:36,438 - DEBUG - MainThread - PAI.paradox.paradox - Control Output: Portail - on 2022-03-21 21:02:36,576 - DEBUG - MainThread - PAI.paradox.paradox - Message received: Container: fields = Container: data = b'B\x07\x00\x00\x00\x00' (total 6) value = Container: po = Container: command = 4 status = Container: reserved = False alarm_reporting_pending = False Winload_connected = True NeWare_connected = False packetlength = 7 offset1 = 0 offset2 = 6 length = 6 checksum = b'I' (total 1) 2022-03-21 21:02:36,580 - INFO - MainThread - PAI.paradox.hardware.evo.panel - PGM command: "on" succeeded

line 3593, 1.6s later you can see that on reception of an event, zone 20 becomes open which is correct:

_2022-03-21 21:02:38,065 - DEBUG - MainThread - PAI.paradox.paradox - Message received: Container: fields = Container: data = b'\xe2\xff\xe9\t\x14\x16\x03\x15\x16\x02\x01\x03\x14\x00\x00\x00'... (truncated, total 36) value = Container: po = Container: command = 14 status = Container: reserved = False alarm_reporting_pending = False Winload_connected = True NeWare_connected = False event_source = 255 event_nr = 59657 time = 2022-03-21 22:02:00 event = Container: major = 1 minor = 20 minor2 = 0 partition = 3 partition = 3 module_serial = b'\x00\x00\x00\x00' (total 4) label_type = b'\x02' (total 1) label = b'Portail ' (total 16) offset1 = 0 offset2 = 36 length = 36 checksum = b'B' (total 1) 2022-03-21 21:02:38,068 - DEBUG - MainThread - PAI.paradox.data.memorystorage - Change zone/Portail/open from False to True 2022-03-21 21:02:38,070 - DEBUG - BasicMQTTInterface - PAI.paradox.interfaces.mqtt.core - MQTT: paradox/states/zones/Portail/open=True

line 6136, 1.4s later the PGM status reception (received 3s after PGM control output has been send ) trigger also a open to close change for the zone 20 (it is wrong, it is the pgm status reception which cause the spurious zone status message): _2022-03-21 21:02:39,427 - DEBUG - MainThread - PAI.paradox.hardware.evo.panel - Received status response: 58 2022-03-21 21:02:39,440 - DEBUG - MainThread - PAI.paradox.hardware.panel - Status parsed(58): Container: pgm_status = Container: 17 = Container: fire_2_wires = False normally_closed = False disabled = True timer_active = False on = False time_left = 0 18 = Container: fire_2_wires = False normally_closed = False disabled = True timer_active = False on = False time_left = 0 19 = Container: fire_2_wires = False normally_closed = False disabled = True timer_active = False on = False time_left = 0 20 = Container: fire_2_wires = False normally_closed = False disabled = True timer_active = False on = False time_left = 0 21 = Container: fire_2_wires = False normally_closed = False disabled = True timer_active = False on = False time_left = 0 22 = Container: fire_2_wires = False normally_closed = False disabled = True timer_active = False on = False time_left = 0 23 = Container: fire_2_wires = False normally_closed = False disabled = True timer_active = False on = False time_left = 0 24 = Container: fire_2_wires = False normally_closed = False disabled = True timer_active = False on = False time_left = 0 25 = Container: fire_2_wires = False normally_closed = False disabled = True timer_active = False on = False time_left = 0 26 = Container: fire_2_wires = False normally_closed = False disabled = True timer_active = False on = False time_left = 0 27 = Container: fire_2_wires = False normally_closed = False disabled = True timer_active = False on = False time_left = 0 28 = Container: fire_2_wires = False normally_closed = False disabled = True timer_active = False on = False time_left = 0 29 = Container: fire_2_wires = False normally_closed = False disabled = True timer_active = False on = False time_left = 0 30 = Container: fire_2_wires = False normally_closed = False disabled = True timer_active = False on = False time_left = 0 31 = Container: fire_2_wires = False normally_closed = False disabled = True timer_active = False on = False time_left = 0 32 = Container: fire_2_wires = False normally_closed = False disabled = True timer_active = False on = False time_left = 0 2022-03-21 21:02:39,668 - DEBUG - MainThread - PAI.paradox.paradox - pgm/line_ring:False ignored 2022-03-21 21:02:39,670 - DEBUG - MainThread - PAI.paradox.data.memory_storage - Change system/date/time from 2022-03-21 22:02:24 to 2022-03-21 22:02:31 2022-03-21 21:02:39,670 - DEBUG - MainThread - PAI.paradox.data.memory_storage - Change system/power/vdc from 16.5 to 16.4 2022-03-21 21:02:39,672 - DEBUG - MainThread - PAI.paradox.data.memorystorage - Change zone/Portail/open from True to False

We can see that PGM status reception (triggered by PGM control output) by PAI send wrong zone status when this zone stus has changed between PGM control output and PGM status refresh

yozik04 commented 2 years ago

But PAI can not control zone status. It only reads it. Is that zone wired to that PGM? PAI does not have any logic to change value during read flow. It spits out what it receives. PGM and Zone Statuses are in different memory blocks. I currently have no idea how to help you.

yozik04 commented 2 years ago

when PGM state changes panel does not send any event to the bus for PAI to read. At least it is how I remember. So it is not possible to detect PGM status right away.

Benoit3 commented 2 years ago

Hello, I think now I have a clear view of what happen:

a PGM is activated on Hassio, transmitted to PAI
PAI send the PGM activation to evo panel and request status refresh ( control_output method in paradox.py). The PGM trigger gate opening.
PAI start to download evo panel status and then process this status to update its internal memory and send MQTT message. The time duration of these operations is around 4s.
If the gate zone is open in the middle of above operations, the gate zone status can be downloaded as closed, then the open event received and processed (=> open MQTT message send), and then the initial closed gate zone status processed which trigger close MQTT message send, which is now wrong.
To avoid that , I have tested the following solution ( see here https://github.com/Benoit3/pai) which is to keep only one stream for zone change information :
1. remove pai internal zone status update on event reception (paradox.py)
2. trigger the general status refresh on zone event reception (evo/event.py)
3. remove status refresh after PGM activation by PAI (paradox.py) . It is unnecessary for me and PAI loose 4s general status refresh just before a zone change)
the initial issue disappear, the side effect is now the latency at each zone change is around 4 s, the time needed to download the whole evo status and process it
to decreasy latency, a solution could be to process status data bloc by bloc and not after having download all blocs
an additionnal improvement could be to implement status request for one bloc only, use it for blocs containing zone info

But I do not understand enough the general design of PAI, and my python knowledge is to low.

Thank you for your work, PAI is nice solution even with small defects. Regards, Benoit

yozik04 commented 2 years ago

It is exactly as you described. Now I understood why this happens. I did not thought that status fetching takes 4 seconds. I actually need to log that on debug level.

a solution could be to process status data bloc by bloc and not after having download all blocs

This is what I wanted to make but did not had time to implement.

yozik04 commented 2 years ago

@Benoit3 Do not forget to switch to current dev branch if you are planning to edit something.

Python is simple language to learn.

ParadoxAlarmInterface / pai