Async message parsing #57

yozik04 · 2019-03-15T12:35:28Z

Currently we have situation that sometimes a message response comes out of an order and we fail to map it to a request as that request already failed. I periodically see this when loading labels and some events kick in.

I propose having a different model of request parsing.

When we issue a request that waits for a response we register it's handler in a queue. Then when a response comes we iterate through all handlers in a queue to find matching request handler. Request handler can tell if passed response was intended for it.

This handler queue can have permanent Event handler in it so all events are processed separately.

All this will allow us to start using async await in our code.

jpbarraca · 2019-03-15T13:27:24Z

The way we handle messages and events has always bugged me.

I fully support this approach, but it will take a reasonable effort

…ht handlers regardless of order they come in.

…ate_labels in MGSP

yozik04 · 2019-04-01T21:12:27Z

asyncio branch testing required!

Benefits: Status messages are not get lost if an event comes in. Great performance improvements.

No idea if Serial is working in this branch. Testing required.
IP Interface is probably broken. Will check in upcoming days.

yozik04 · 2019-04-01T21:18:30Z

@jpbarraca We probably want to switch to aioserial in this branch.

jpbarraca · 2019-04-01T21:20:56Z

yes. But lets test, we introduced many changes since the last merge to master

yellowonblack · 2019-04-02T17:53:19Z

Panel: EVO192
Serial connection: Cable 307USB Direct Connect Interface
OS: Raspbian Stretch up-to-date

At first run I got: ImportError: No module named 'serial_asyncio'
I did: pip3 install pyserial-asyncio (pyserial-asyncio==0.4)
After that is not passing from "Initiating communication" section:
2019-04-02 18:46:51,927 - INFO - PAI - Starting...
2019-04-02 18:46:51,929 - INFO - PAI.paradox.paradox - Connecting to interface
2019-04-02 18:46:51,930 - INFO - PAI.paradox.connections.serial_connection - Connecting to serial port /dev/ttyUSB0
2019-04-02 18:46:51,935 - INFO - PAI.paradox.connections.serial_connection - Serial port Open
2019-04-02 18:46:51,936 - INFO - PAI.paradox.connections.serial_connection - Serial port open
2019-04-02 18:46:51,938 - INFO - PAI.paradox.paradox - Connecting to panel
2019-04-02 18:46:51,939 - INFO - PAI.paradox.paradox - Initiating communication

yozik04 · 2019-04-03T13:14:14Z

@yellowonblack I am not sure if @jpbarraca has fixed Serial connection already.

yellowonblack · 2019-04-03T21:30:56Z

Just tried now and it seems that not:

message = Special events: WinLoad in (connected)
label_provider = <bound method Paradox.get_label of <paradox.paradox.Paradox object at 0x7615d7b0>>
label =
2019-04-03 22:26:45,512 - WARNING - PAI.paradox.paradox - Missing element ID in system/?, m/m: 45/4, message: Special events: WinLoad in (connected)
^C2019-04-03 22:26:52,235 - INFO - PAI.paradox.paradox - Cleaning previous session. Closing connection

yellowonblack · 2019-04-03T21:46:41Z

The panel is correctly identified but when trying to get most probably label data it fails. I can provide full debug log file if needed.

2019-04-03 22:42:36,990 - INFO - PAI - Starting Paradox Alarm Interface
2019-04-03 22:42:36,991 - INFO - PAI - Console Log level set to 20
2019-04-03 22:42:36,991 - INFO - PAI.paradox.interfaces.interface_manager - Using MQTT Interface
2019-04-03 22:42:37,115 - INFO - PAI.paradox.interfaces.mqtt_interface - MQTT Broker Connected
2019-04-03 22:42:38,091 - INFO - PAI - Using Serial Connection
2019-04-03 22:42:38,124 - INFO - PAI - Starting...
2019-04-03 22:42:38,126 - INFO - PAI.paradox.paradox - Connecting to interface
2019-04-03 22:42:38,127 - INFO - PAI.paradox.connections.serial_connection - Connecting to serial port /dev/ttyUSB0
2019-04-03 22:42:38,132 - INFO - PAI.paradox.connections.serial_connection - Serial port Open
2019-04-03 22:42:38,133 - INFO - PAI.paradox.connections.serial_connection - Serial port open
2019-04-03 22:42:38,134 - INFO - PAI.paradox.paradox - Connecting to panel
2019-04-03 22:42:38,135 - INFO - PAI.paradox.paradox - Initiating communication
2019-04-03 22:42:38,181 - INFO - PAI.paradox.paradox - Found Panel EVO192 version 7.1 build 4
2019-04-03 22:42:38,182 - INFO - PAI.paradox.paradox - Starting communication
2019-04-03 22:42:38,286 - INFO - PAI.paradox.hardware.evo.panel - Initializing communication
2019-04-03 22:42:38,337 - WARNING - PAI.paradox.paradox - Missing element ID in system/?, m/m: 45/4, message: Special events: WinLoad in (connected)

yellowonblack · 2019-04-03T23:16:28Z

Panel: EVO192
IP connection: IP150 v4.30 with siteID

Very Good:

the zone status change message on MQTT is almost instant. Before this, the delays were up to 5-6 seconds and sometime even lost messages. Great job @yozik04.

Not so good:

only 2 partition from 4 are detected at the initialisation
the unidentified partitions DO NOT generate messages on paradox/states/partitions but the zones in the unidentified partitions DO generate messages on paradox/states/zones and paradox/events

That might be related to some error which appears in the logs:
2019-04-03 23:52:27,140 - INFO - PAI.paradox.paradox - Connecting to panel
2019-04-03 23:52:27,140 - INFO - PAI.paradox.paradox - Initiating communication
2019-04-03 23:52:27,274 - INFO - PAI.paradox.paradox - Found Panel EVO192 version 7.1 build 4
2019-04-03 23:52:27,275 - INFO - PAI.paradox.paradox - Starting communication
2019-04-03 23:52:27,440 - INFO - PAI.paradox.hardware.evo.panel - Initializing communication
2019-04-03 23:52:27,532 - INFO - PAI.paradox.hardware.evo.panel - Authentication Success
2019-04-03 23:52:27,533 - INFO - PAI.paradox.hardware.panel - Updating Labels from Panel
2019-04-03 23:52:27,533 - INFO - PAI.paradox.hardware.panel - Door:
2019-04-03 23:52:27,587 - WARNING - PAI.paradox.paradox - Missing element ID in system/?, m/m: 45/4, message: Special events: WinLoad in (connected)
2019-04-03 23:52:28,169 - INFO - PAI.paradox.hardware.panel - Pgm: PGM 01, PGM 02, PGM 03, PGM 04, PGM 05, PGM 06, PGM 07
2019-04-03 23:52:28,337 - INFO - PAI.paradox.hardware.panel - Partition: Partition1, Partition4

2019-04-03 23:38:01,671 - WARNING - PAI.paradox.paradox - Missing element with ID 12 in zone/1_LivingW

yozik04 · 2019-04-04T05:33:33Z

@yellowonblack Do you have in configuration for EVO?

STATUS_REQUESTS = list(range(1, 6))

PARTITIONS_CHANGE_NOTIFICATION_IGNORE = [
  'arm_full',
  'exit_delay',
  'all_zone_closed', 
  'ready',
  'stay_instant_ready',
  'force_ready',
  'entry_delay',
  'auto_arming_engaged'
]

LIMITS = {
    'zone': range(1, 51),     # Zones to monitor and control 1-50
    'user': range(1, 11),     # Users to consider 1-10
    'door': [],               # Doors to consider
    'pgm': range(1, 6),    # Outputs to monitor and control 1-5
    'partition': range(1, 9), # Partitions to monitor and control 1-8
    'bus-module': [],         # Buses to monitor
}

yozik04 · 2019-04-04T05:39:56Z

IP150 v4.30 with siteID connects? That is a surprise. I thought I broke it while rewriting to async 😄

jpbarraca · 2019-04-04T06:52:36Z

The issue with missing labels could be related to the messages rate, which is much higher. An MG panel takes 70ms to 100ms to issue a reply and we easily send messages with less interval.
@yozik04 try to throttle the messages to 100ms.

yozik04 · 2019-04-04T08:13:18Z

I have not seen this issue with IP150 module. I run at full speed without any problems.

yozik04 · 2019-04-04T08:15:16Z

Throttling may be applicable for Serial only.

yellowonblack · 2019-04-04T08:49:30Z

I updated my pai.conf as @yozik04 mentioned and now all partitions are identified correctly, although if I use 'partition': range(1, 9) and I only have 4 partition, this will cause creation of a bad topic on MQTT paradox/states/partitions// (with double / at the end) probably because of the missing partition labels names.
If I use 'partition': range(1, 4) the bad topic, with double /, is not created.

Now the only warning remaining is:

2019-04-04 09:46:28,294 - INFO - PAI.paradox.paradox - Connecting to panel
2019-04-04 09:46:28,295 - INFO - PAI.paradox.paradox - Initiating communication
2019-04-04 09:46:28,405 - INFO - PAI.paradox.paradox - Found Panel EVO192 version 7.1 build 4
2019-04-04 09:46:28,405 - INFO - PAI.paradox.paradox - Starting communication
2019-04-04 09:46:28,570 - INFO - PAI.paradox.hardware.evo.panel - Initializing communication
2019-04-04 09:46:28,657 - INFO - PAI.paradox.hardware.evo.panel - Authentication Success
2019-04-04 09:46:28,657 - INFO - PAI.paradox.hardware.panel - Updating Labels from Panel
2019-04-04 09:46:28,721 - WARNING - PAI.paradox.paradox - Missing element ID in system/?, m/m: 45/4, message: Special events: WinLoad in (connected)

yellowonblack · 2019-04-04T08:51:37Z

IP150 v4.30 with siteID connects? That is a surprise. I thought I broke it while rewriting to async 😄

It connects as you see, but something strange appears in the first log lines after I connect: Panel version 20, firmware: 4.48,. Do you have any idea why?

2019-04-04 09:46:26,707 - INFO - PAI - Using IP Connection
2019-04-04 09:46:27,108 - INFO - PAI - Starting...
2019-04-04 09:46:27,109 - INFO - PAI.paradox.paradox - Connecting to interface
2019-04-04 09:46:27,109 - INFO - PAI.paradox.connections.ip_connection - Connecting to Site: mysite
2019-04-04 09:46:27,693 - INFO - PAI.paradox.connections.ip_connection - Connected to Site: mysite
2019-04-04 09:46:28,044 - INFO - PAI.paradox.connections.ip_connection - Authentication Success. Panel version 20, firmware: 4.48, serial: 12345678
2019-04-04 09:46:28,293 - INFO - PAI.paradox.connections.ip_connection - Session Established with IP Module

jpbarraca · 2019-04-04T10:23:07Z

@yellowonblack You can safely ignore those warnings, they are used to pinpoint sub optimal processing.
Regarding the Panel version and firmware: we didn't spend much time validating that and it has no impact whatsoever. You can also ignore.
Those values are the ones reported by the panel, and different values are reported in different messages. We do not know if they are correct or reflect different parts of the firmware.

yellowonblack · 2019-04-04T14:09:30Z

Thanks for clarifications @jpbarraca.

I will keep the IP siteID connection running and let you know if I find problems. Also, if you fix things on the serial connection, I will test it and sent you feedback.

Another problem quite important (also referenced in #55 (comment)):

When closing the run.py, I get INFO log messages that the session disconnected from MQTT, but I get no paradox/interface/MQTTInterface offline message.

2019-04-04 15:01:44,782 - INFO - PAI.paradox.paradox - Disconnected from the Alarm Panel
2019-04-04 15:01:44,784 - INFO - PAI.paradox.interfaces.mqtt_interface - MQTT Broker Disconnected
2019-04-04 15:01:46,796 - INFO - PAI - Good bye!
2019-04-04 15:01:47,799 - INFO - PAI - Good bye!

The same happens when there are automatic reconnection to the panel because of lost connection

That would be very useful to get the offline messages on the topic.

jpbarraca · 2019-04-04T18:35:27Z

@yellowonblack I tested with a serial connection and it works. Which problems are you facing?

yellowonblack · 2019-04-05T00:05:45Z

Here I mentioned what is happening: #57 (comment) + #57 (comment)

I tried again now and the same error.

yozik04 · 2019-04-05T04:29:53Z

Send me full log from latest asyncio. With Debugs on.

yellowonblack · 2019-04-05T22:11:16Z

Send me full log from latest asyncio. With Debugs on.

Full log has been sent.

yozik04 added the enhancement New feature or request label Mar 17, 2019

yozik04 added a commit that referenced this issue Mar 22, 2019

#57 Initial Async/await. No retries anymore. Messages land in the rig…

0631663

…ht handlers regardless of order they come in.

yozik04 added a commit that referenced this issue Mar 23, 2019

#57 Resume async needs to call connect async

e71769e

yozik04 added a commit that referenced this issue Mar 23, 2019

#57 Initial Async/await. No retries anymore. Messages land in the rig…

936ff74

…ht handlers regardless of order they come in.

yozik04 added a commit that referenced this issue Mar 23, 2019

#57 Resume async needs to call connect async

92bcb4a

jpbarraca added a commit that referenced this issue Mar 26, 2019

#57 Add missing reply_expected to MGSP. Remove superfluous method upd…

c7ffd6c

…ate_labels in MGSP

yozik04 added a commit that referenced this issue Mar 27, 2019

#57 Connection data receive async worker.

9df1631

yozik04 added a commit that referenced this issue Mar 29, 2019

#57 Probable async socket

5992923

yozik04 added the testing required Should be fixed, needs validation label Mar 29, 2019

yozik04 added a commit that referenced this issue Apr 1, 2019

#57 Full async socket reading.

4ca8ef0

jpbarraca added a commit that referenced this issue Apr 2, 2019

#57 Async support for Serial

e6f5941

yozik04 added a commit that referenced this issue Apr 3, 2019

#57 Reconnection fix

77a5ba3

yellowonblack mentioned this issue Apr 9, 2019

EVO192 256K v7.01.004 serial connection problem #62

Closed

yozik04 closed this as completed Apr 9, 2019

yellowonblack mentioned this issue Apr 9, 2019

MQTT Interface topic not updating to "Offline' state #55

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Async message parsing #57

Async message parsing #57

yozik04 commented Mar 15, 2019

jpbarraca commented Mar 15, 2019

yozik04 commented Apr 1, 2019

yozik04 commented Apr 1, 2019

jpbarraca commented Apr 1, 2019

yellowonblack commented Apr 2, 2019

yozik04 commented Apr 3, 2019

yellowonblack commented Apr 3, 2019

yellowonblack commented Apr 3, 2019

yellowonblack commented Apr 3, 2019

yozik04 commented Apr 4, 2019

yozik04 commented Apr 4, 2019

jpbarraca commented Apr 4, 2019

yozik04 commented Apr 4, 2019

yozik04 commented Apr 4, 2019

yellowonblack commented Apr 4, 2019

yellowonblack commented Apr 4, 2019

jpbarraca commented Apr 4, 2019

yellowonblack commented Apr 4, 2019 •

edited

Loading

jpbarraca commented Apr 4, 2019

yellowonblack commented Apr 5, 2019

yozik04 commented Apr 5, 2019 •

edited

Loading

yellowonblack commented Apr 5, 2019

Async message parsing #57

Async message parsing #57

Comments

yozik04 commented Mar 15, 2019

jpbarraca commented Mar 15, 2019

yozik04 commented Apr 1, 2019

yozik04 commented Apr 1, 2019

jpbarraca commented Apr 1, 2019

yellowonblack commented Apr 2, 2019

yozik04 commented Apr 3, 2019

yellowonblack commented Apr 3, 2019

yellowonblack commented Apr 3, 2019

yellowonblack commented Apr 3, 2019

yozik04 commented Apr 4, 2019

yozik04 commented Apr 4, 2019

jpbarraca commented Apr 4, 2019

yozik04 commented Apr 4, 2019

yozik04 commented Apr 4, 2019

yellowonblack commented Apr 4, 2019

yellowonblack commented Apr 4, 2019

jpbarraca commented Apr 4, 2019

yellowonblack commented Apr 4, 2019 • edited Loading

jpbarraca commented Apr 4, 2019

yellowonblack commented Apr 5, 2019

yozik04 commented Apr 5, 2019 • edited Loading

yellowonblack commented Apr 5, 2019

yellowonblack commented Apr 4, 2019 •

edited

Loading

yozik04 commented Apr 5, 2019 •

edited

Loading