Core: Ads-Integration has ADSTimouts since update to 0.113.0

Created on 24 Jul 2020 · 81Comments · Source: home-assistant/core

The problem

This morning I updated the HomeAssistant from version 0.112 to 0.113.0, and since then the connection to my ads device does not work anymore. As you can see in the logs (Log 1), ADSTimeouts always occur when registering the notifications of the individual variables. Only with the 1st variable the registration works. While looking through the commits of the ads component (https://github.com/home-assistant/core/tree/dev/homeassistant/components/ads) I found a commit of @balloob (0bf772b68b632e1cc6a26de803cac349a5cd244e) where the version of pyads was increased from 3.0.7 to 3.1.3. After undoing this commit on my system everything works as expected again (see log 2). It seems that the behaviour of the new version of pyads has some kind of negative effect on the component.

BR Peter

Environment

Home Assistant Core release with the issue: 0.113.0
Last working Home Assistant Core release (if known): 0.112.x (I can't remember exactly)
Operating environment (OS/Container/Supervised/Core): see table above
Integration causing this issue: ads
Link to integration documentation on our website: https://www.home-assistant.io/integrations/ads/

Problem-relevant `configuration.yaml`

ads:
  device: '192.168.5.10.1.1'
  port: 801
  ip_address: '192.168.5.10'

switch:
  - platform: ads
    adsvar: '.g_heating_with_wood'
    name: 'Heizen mit Holz'
  - platform: ads
    adsvar: '.g_override_boiler_enable'
    name: 'Boiler override'

Traceback/Error logs

Log 1

2020-07-24 09:51:46 INFO (MainThread) [homeassistant.setup] Setting up ads
2020-07-24 09:51:47 INFO (MainThread) [homeassistant.setup] Setup of domain ads took 0.6 seconds
2020-07-24 09:51:47 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.ads
2020-07-24 09:51:47 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.ads
2020-07-24 09:51:47 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.ads
2020-07-24 09:51:47 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.ads
2020-07-24 09:51:47 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.ads
2020-07-24 09:51:47 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.ads
2020-07-24 09:51:47 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.ads
2020-07-24 09:51:47 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.ads
2020-07-24 09:51:47 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.ads
2020-07-24 09:51:47 INFO (MainThread) [homeassistant.components.switch] Setting up switch.ads
2020-07-24 09:51:47 INFO (MainThread) [homeassistant.components.switch] Setting up switch.ads
2020-07-24 09:51:48 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.ads
2020-07-24 09:51:48 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.ads
2020-07-24 09:51:48 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.ads
2020-07-24 09:51:48 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.ads
2020-07-24 09:51:48 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.ads
2020-07-24 09:51:48 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.ads
2020-07-24 09:51:48 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.ads
2020-07-24 09:51:48 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.ads
2020-07-24 09:51:48 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.ads
2020-07-24 09:51:48 DEBUG (SyncWorker_3) [homeassistant.components.ads] Added device notification 11 for variable .g_heating_circle_needs_warm_water
2020-07-24 09:51:48 DEBUG (SyncWorker_3) [homeassistant.components.ads] Added device notification 12 for variable .g_output_pump_heating_circle_enable
2020-07-24 09:51:48 DEBUG (Dummy-7) [homeassistant.components.ads] Received notification 12
2020-07-24 09:51:53 ERROR (SyncWorker_3) [homeassistant.components.ads] Error subscribing to .g_input_boiler_signal: ADSError: timeout elapsed (1861).
  File "/usr/local/lib/python3.8/site-packages/pyads/pyads_ex.py", line 849, in wrapper
  File "/usr/src/homeassistant/homeassistant/components/ads/__init__.py", line 244, in _device_notification_callback
2020-07-24 09:51:53 DEBUG (SyncWorker_4) [homeassistant.components.ads] Added device notification 13 for variable .g_boiler_needs_warm_water
2020-07-24 09:51:53 DEBUG (Dummy-7) [homeassistant.components.ads] Received notification 13
2020-07-24 09:51:57 WARNING (MainThread) [homeassistant.components.binary_sensor] Setup of binary_sensor platform ads is taking over 10 seconds.
2020-07-24 09:51:57 WARNING (MainThread) [homeassistant.components.binary_sensor] Setup of binary_sensor platform ads is taking over 10 seconds.
2020-07-24 09:51:57 WARNING (MainThread) [homeassistant.components.binary_sensor] Setup of binary_sensor platform ads is taking over 10 seconds.
2020-07-24 09:51:57 WARNING (MainThread) [homeassistant.components.switch] Setup of switch platform ads is taking over 10 seconds.
2020-07-24 09:51:58 WARNING (MainThread) [homeassistant.components.sensor] Setup of sensor platform ads is taking over 10 seconds.
2020-07-24 09:51:58 WARNING (MainThread) [homeassistant.components.sensor] Setup of sensor platform ads is taking over 10 seconds.
2020-07-24 09:51:58 WARNING (MainThread) [homeassistant.components.sensor] Setup of sensor platform ads is taking over 10 seconds.
2020-07-24 09:51:58 WARNING (MainThread) [homeassistant.components.sensor] Setup of sensor platform ads is taking over 10 seconds.
2020-07-24 09:51:58 WARNING (MainThread) [homeassistant.components.sensor] Setup of sensor platform ads is taking over 10 seconds.
2020-07-24 09:51:58 WARNING (MainThread) [homeassistant.components.sensor] Setup of sensor platform ads is taking over 10 seconds.
2020-07-24 09:51:58 WARNING (MainThread) [homeassistant.components.sensor] Setup of sensor platform ads is taking over 10 seconds.
2020-07-24 09:51:58 WARNING (MainThread) [homeassistant.components.sensor] Setup of sensor platform ads is taking over 10 seconds.
2020-07-24 09:51:58 WARNING (MainThread) [homeassistant.components.sensor] Setup of sensor platform ads is taking over 10 seconds.
2020-07-24 09:51:58 DEBUG (MainThread) [homeassistant.components.ads] Variable .g_heating_circle_needs_warm_water: Timeout during first update
2020-07-24 09:51:58 DEBUG (MainThread) [homeassistant.components.ads] Variable .g_output_pump_heating_circle_enable: Timeout during first update
2020-07-24 09:51:58 ERROR (SyncWorker_1) [homeassistant.components.ads] Error subscribing to .g_output_pump_boiler_enable: ADSError: timeout elapsed (1861).
2020-07-24 09:52:03 DEBUG (MainThread) [homeassistant.components.ads] Variable .g_input_boiler_signal: Timeout during first update
2020-07-24 09:52:03 DEBUG (MainThread) [homeassistant.components.ads] Variable .g_boiler_needs_warm_water: Timeout during first update
2020-07-24 09:52:03 ERROR (SyncWorker_0) [homeassistant.components.ads] Error subscribing to .g_output_oil_burner_enable: ADSError: timeout elapsed (1861).
2020-07-24 09:52:08 DEBUG (MainThread) [homeassistant.components.ads] Variable .g_output_pump_boiler_enable: Timeout during first update
2020-07-24 09:52:08 ERROR (SyncWorker_7) [homeassistant.components.ads] Error subscribing to .g_input_wood_burner_steam_signal: ADSError: timeout elapsed (1861).
2020-07-24 09:52:13 ERROR (SyncWorker_2) [homeassistant.components.ads] Error subscribing to .g_input_wood_burner_preflow_signal: ADSError: timeout elapsed (1861).

Logs 2

`2020-07-24 10:03:24 INFO (SyncWorker_0) [homeassistant.util.package] Attempting install of pyads==3.0.7 2020-07-24 10:03:30 INFO (MainThread) [homeassistant.setup] Setting up ads 2020-07-24 10:03:31 INFO (MainThread) [homeassistant.setup] Setup of domain ads took 0.5 seconds 2020-07-24 10:03:31 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.ads 2020-07-24 10:03:31 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.ads 2020-07-24 10:03:31 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.ads 2020-07-24 10:03:31 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.ads 2020-07-24 10:03:31 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.ads 2020-07-24 10:03:31 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.ads 2020-07-24 10:03:31 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.ads 2020-07-24 10:03:31 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.ads 2020-07-24 10:03:31 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.ads 2020-07-24 10:03:31 INFO (MainThread) [homeassistant.components.switch] Setting up switch.ads 2020-07-24 10:03:31 INFO (MainThread) [homeassistant.components.switch] Setting up switch.ads 2020-07-24 10:03:31 DEBUG (SyncWorker_5) [homeassistant.components.ads] Added device notification 21 for variable .g_heating_circle_needs_warm_water 2020-07-24 10:03:31 DEBUG (Dummy-32) [homeassistant.components.ads] Received notification 21 2020-07-24 10:03:31 DEBUG (SyncWorker_7) [homeassistant.components.ads] Added device notification 22 for variable .g_output_pump_heating_circle_enable 2020-07-24 10:03:32 DEBUG (SyncWorker_5) [homeassistant.components.ads] Added device notification 23 for variable .g_input_boiler_signal 2020-07-24 10:03:32 DEBUG (Dummy-32) [homeassistant.components.ads] Variable .g_heating_circle_needs_warm_water changed its value to 0 2020-07-24 10:03:32 DEBUG (Dummy-32) [homeassistant.components.ads] Received notification 22 2020-07-24 10:03:32 DEBUG (SyncWorker_7) [homeassistant.components.ads] Added device notification 24 for variable .g_boiler_needs_warm_water 2020-07-24 10:03:32 DEBUG (SyncWorker_2) [homeassistant.components.ads] Added device notification 25 for variable .g_output_pump_boiler_enable 2020-07-24 10:03:33 DEBUG (SyncWorker_5) [homeassistant.components.ads] Added device notification 26 for variable .g_output_oil_burner_enable 2020-07-24 10:03:33 DEBUG (Dummy-32) [homeassistant.components.ads] Variable .g_output_pump_heating_circle_enable changed its value to 0 2020-07-24 10:03:33 DEBUG (Dummy-32) [homeassistant.components.ads] Received notification 23 2020-07-24 10:03:33 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.ads 2020-07-24 10:03:33 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.ads 2020-07-24 10:03:33 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.ads 2020-07-24 10:03:33 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.ads 2020-07-24 10:03:33 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.ads 2020-07-24 10:03:33 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.ads 2020-07-24 10:03:33 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.ads 2020-07-24 10:03:33 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.ads 2020-07-24 10:03:33 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.ads 2020-07-24 10:03:34 DEBUG (SyncWorker_7) [homeassistant.components.ads] Added device notification 27 for variable .g_input_wood_burner_steam_signal 2020-07-24 10:03:34 DEBUG (SyncWorker_2) [homeassistant.components.ads] Added device notification 28 for variable .g_input_wood_burner_preflow_signal 2020-07-24 10:03:34 DEBUG (SyncWorker_5) [homeassistant.components.ads] Added device notification 29 for variable .g_input_wood_burner_preflow_70Degrees_signal 2020-07-24 10:03:34 DEBUG (Dummy-32) [homeassistant.components.ads] Variable .g_input_boiler_signal changed its value to 0 2020-07-24 10:03:34 DEBUG (Dummy-32) [homeassistant.components.ads] Received notification 24 2020-07-24 10:03:34 DEBUG (SyncWorker_3) [homeassistant.components.ads] Added device notification 30 for variable .g_heating_with_wood 2020-07-24 10:03:34 DEBUG (SyncWorker_7) [homeassistant.components.ads] Added device notification 31 for variable .g_heating_valve_actual_value_in_percent 2020-07-24 10:03:34 DEBUG (SyncWorker_6) [homeassistant.components.ads] Added device notification 32 for variable .g_override_boiler_enable 2020-07-24 10:03:34 DEBUG (Dummy-32) [homeassistant.components.ads] Variable .g_boiler_needs_warm_water changed its value to 0 2020-07-24 10:03:34 DEBUG (Dummy-32) [homeassistant.components.ads] Received notification 25 2020-07-24 10:03:34 DEBUG (SyncWorker_5) [homeassistant.components.ads] Added device notification 33 for variable .g_woodburner_command_value_in_percent 2020-07-24 10:03:34 DEBUG (SyncWorker_2) [homeassistant.components.ads] Added device notification 34 for variable .g_real_value_window_childs_room_1_percent 2020-07-24 10:03:34 DEBUG (SyncWorker_3) [homeassistant.components.ads] Added device notification 35 for variable .g_real_value_window_childs_room_2_1_percent 2020-07-24 10:03:35 DEBUG (SyncWorker_7) [homeassistant.components.ads] Added device notification 36 for variable .g_real_value_window_childs_room_2_2_percent 2020-07-24 10:03:35 DEBUG (SyncWorker_6) [homeassistant.components.ads] Added device notification 37 for variable .g_real_value_window_living_room_door_percent 2020-07-24 10:03:35 DEBUG (Dummy-32) [homeassistant.components.ads] Variable .g_output_pump_boiler_enable changed its value to 0 2020-07-24 10:03:35 DEBUG (Dummy-32) [homeassistant.components.ads] Received notification 26´

Additional information

ads

Source

punzenbergerpeter

Most helpful comment

I finally was able to setup a test environment an reproduce the error. It seems that somewhere between 3.0.7 and 3.1.3 the return type of DeviceNotifications changed. Instead of returning bytes as contents.data we now have an integer. Because of that struct.unpack results in an error:

2020-07-28 16:07:54 ERROR (Dummy-4) [root] Uncaught exception
Traceback (most recent call last):
  File "_ctypes/callbacks.c", line 237, in 'calling callback function'
  File "/home/stefan/.homeassistant/deps/lib/python3.8/site-packages/pyads/pyads_ex.py", line 849, in wrapper
    return callback(notification, data)
  File "/home/stefan/Dokumente/python/forks/home-assistant/homeassistant/components/ads/__init__.py", line 244, in _device_notification_callback
    value = bool(struct.unpack("<?", bytearray(data)[:1])[0])
struct.error: unpack requires a buffer of 1 bytes

The effected area in the code is the following (__init__.py):

def _device_notification_callback(self, notification, name):
    """Handle device notifications."""
    contents = notification.contents

    hnotify = int(contents.hNotification)
    _LOGGER.debug("Received notification %d", hnotify)
    data = contents.data

    try:
        with self._lock:
            notification_item = self._notification_items[hnotify]
    except KeyError:
        _LOGGER.error("Unknown device notification handle: %d", hnotify)
        return

    # Parse data to desired datatype
    if notification_item.plc_datatype == self.PLCTYPE_BOOL:
        value = bool(struct.unpack("<?", bytearray(data)[:1])[0])
    elif notification_item.plc_datatype == self.PLCTYPE_INT:
        value = struct.unpack("<h", bytearray(data)[:2])[0]
    elif notification_item.plc_datatype == self.PLCTYPE_BYTE:
        value = struct.unpack("<B", bytearray(data)[:1])[0]
    elif notification_item.plc_datatype == self.PLCTYPE_UINT:
        value = struct.unpack("<H", bytearray(data)[:2])[0]
    elif notification_item.plc_datatype == self.PLCTYPE_DINT:
        value = struct.unpack("<i", bytearray(data)[:4])[0]
    elif notification_item.plc_datatype == self.PLCTYPE_UDINT:
        value = struct.unpack("<I", bytearray(data)[:4])[0]
    else:
        value = bytearray(data)
        _LOGGER.warning("No callback available for this datatype")

    notification_item.callback(notification_item.name, value)

I still need to find out why contents.data changed and will come back to you.

stlehmann on 28 Jul 2020

👍6

All 81 comments

Possibly this issue is related: #35945

punzenbergerpeter on 24 Jul 2020

@stlehmann do you know what version of pyads we can upgrade to that requires the least amount of changes to the integration, while fixing the issues?

MartinHjelmare on 24 Jul 2020

@MartinHjelmare I need to do some investigations on this one. It might have to do with the change from sync to async connection to ADS. I'll come back to you here.

stlehmann on 24 Jul 2020

👍4

ads documentation
ads source
_{^{(message by IssueLinks)}}

probot-home-assistant[bot] on 24 Jul 2020

Same problem here, issues started since upgrade to 0.103(.1)

gijbelsy on 26 Jul 2020

Same here. Since update from version 0.112 to 0.113.0. Ads integration no longer works.

VDHeerJu on 26 Jul 2020

Since I've started with HA, ADS integration has always been a sore to make and keep it running properly.
There are some absolutely necessary features missing, and every time HA gets an update, I hold my breath to whether or not it's still working after the update.

gijbelsy on 26 Jul 2020

👎2

Hm, I'm still struggling to setup a test environment. It has been a long while since I have used home-assistant. I'm on it but I have only limited time at the moment. A temporary solution would be to revert the commit https://github.com/home-assistant/core/commit/0bf772b68b632e1cc6a26de803cac349a5cd244e and downgrade the pyads-dependency back to 3.0.7.
I hope to get a working test environment ready soon.

stlehmann on 27 Jul 2020

Version 3.0.7 depends on typing which conflicts with the built in typing module on Python versions 3.6+. See https://github.com/home-assistant/core/pull/37707.

MartinHjelmare on 27 Jul 2020

Hm, I'm still struggling to setup a test environment. It has been a long while since I have used home-assistant. I'm on it but I have only limited time at the moment. A temporary solution would be to revert the commit 0bf772b and downgrade the pyads-dependency back to 3.0.7.
I hope to get a working test environment ready soon.

I can set-up a new VM for testing.
If the updated version becomes available, I can test this and report back.

gijbelsy on 27 Jul 2020

2020-07-28 16:07:54 ERROR (Dummy-4) [root] Uncaught exception
Traceback (most recent call last):
  File "_ctypes/callbacks.c", line 237, in 'calling callback function'
  File "/home/stefan/.homeassistant/deps/lib/python3.8/site-packages/pyads/pyads_ex.py", line 849, in wrapper
    return callback(notification, data)
  File "/home/stefan/Dokumente/python/forks/home-assistant/homeassistant/components/ads/__init__.py", line 244, in _device_notification_callback
    value = bool(struct.unpack("<?", bytearray(data)[:1])[0])
struct.error: unpack requires a buffer of 1 bytes

The effected area in the code is the following (__init__.py):

def _device_notification_callback(self, notification, name):
    """Handle device notifications."""
    contents = notification.contents

    hnotify = int(contents.hNotification)
    _LOGGER.debug("Received notification %d", hnotify)
    data = contents.data

    try:
        with self._lock:
            notification_item = self._notification_items[hnotify]
    except KeyError:
        _LOGGER.error("Unknown device notification handle: %d", hnotify)
        return

    # Parse data to desired datatype
    if notification_item.plc_datatype == self.PLCTYPE_BOOL:
        value = bool(struct.unpack("<?", bytearray(data)[:1])[0])
    elif notification_item.plc_datatype == self.PLCTYPE_INT:
        value = struct.unpack("<h", bytearray(data)[:2])[0]
    elif notification_item.plc_datatype == self.PLCTYPE_BYTE:
        value = struct.unpack("<B", bytearray(data)[:1])[0]
    elif notification_item.plc_datatype == self.PLCTYPE_UINT:
        value = struct.unpack("<H", bytearray(data)[:2])[0]
    elif notification_item.plc_datatype == self.PLCTYPE_DINT:
        value = struct.unpack("<i", bytearray(data)[:4])[0]
    elif notification_item.plc_datatype == self.PLCTYPE_UDINT:
        value = struct.unpack("<I", bytearray(data)[:4])[0]
    else:
        value = bytearray(data)
        _LOGGER.warning("No callback available for this datatype")

    notification_item.callback(notification_item.name, value)

I still need to find out why contents.data changed and will come back to you.

stlehmann on 28 Jul 2020

👍6

I created a PR fixing this issue: #38402.

stlehmann on 31 Jul 2020

👍2

@stlehmann : Is it possible to implement extra features while you're at it?

gijbelsy on 31 Jul 2020

@gijbelsy Depends on what you are asking for 😏 What do you have in mind?

stlehmann on 31 Jul 2020

'just' two things 😄 :

The implementation of datatype REAL (example) and WORD
elif notification_item.plc_datatype == self.PLCTYPE_REAL: value = struct.unpack("<f", bytearray(data)[:4])[0]

The ability to have an 'update time'.
This last one has the use to check if the entity has been updated within a defined timeframe (say 10s. settable via parameter).
This I use for example: if a sensor reads 5°, and it jumps constantly around 5 and 5.1°. This floods Home Assistant with updates, and database grows exponentially with meaningless data.
I've tried to implement this with a custom component, code snipplet below, but I'm not sure this is the right approach:
' def update(name, value):

    _LOGGER.debug("Variable %s changed its value to %d", name, value)

    # Modification
    needsupdate = False

    if self._state_dict[state_key] == None:
        needsupdate = True
    else:
        states = self.hass.states.get('sensor.' + self._name)
        _LOGGER.debug("Sensor %s has state: %s", self._name, states)
        update_after = dt_util.utcnow() - timedelta(seconds=update_interval)
        if states != None and update_after > states.last_updated:
            needsupdate = True

    if needsupdate == True:
        if factor is None:
            tempvalue = value
        else:
            tempvalue = value / factor

        if round_perform:
            x = Decimal(tempvalue)
            if round_decimal == 0:
                value = round(x, None)
            else:
                value = round(x, round_decimal)
        else:
            value = tempvalue

        self._state_dict[state_key] = value
        asyncio.run_coroutine_threadsafe(async_event_set(), self.hass.loop)
        self.schedule_update_ha_state()

One of the problems with the code above is that this only works with sensor. domain.

gijbelsy on 31 Jul 2020

I have 0.113.3 now.
With ADS I have several switches declared in automation.yaml.
Since update today only 1 or 2 out of 10 are working now. rest of entities are unavailable.
When I reboot I get 1 or 2 other switches to work. The ones that worked before are unavailable again.
Random, no pattern. ??

VDHeerJu on 2 Aug 2020

Same issues here, had to roll back to previous version of HA.
Still getting 'ADS timeout' errors in the logs. Had no time to further investigate.

gijbelsy on 2 Aug 2020

@gijbelsy, @VDHeerJu that is odd. I just checked: 0.113.3 should contain the patch. Can you please provide a minimal configuration and the corresponding logs for it so I can do further investigations.

stlehmann on 2 Aug 2020

Will do, but I'm afraid that's not for today neither tomorrow, possible for Tuesday.

gijbelsy on 2 Aug 2020

2020-08-02 00:31:46 WARNING (SyncWorker_0) [homeassistant.util.yaml.loader] YAML file /config/configuration.yaml contains duplicate key "automation". Check lines 5 and 232
2020-08-02 00:31:48 WARNING (MainThread) [homeassistant.components.http] The 'base_url' option is deprecated, please remove it from your configuration
2020-08-02 00:31:59 ERROR (SyncWorker_2) [homeassistant.components.ads] Error subscribing to .HA_VW_ACTIEF_Keuken: ADSError: timeout elapsed (1861). 
2020-08-02 00:32:02 WARNING (MainThread) [homeassistant.setup] Setup of timer is taking over 10 seconds.
2020-08-02 00:32:02 WARNING (MainThread) [homeassistant.setup] Setup of input_boolean is taking over 10 seconds.
2020-08-02 00:32:03 WARNING (MainThread) [homeassistant.setup] Setup of zeroconf is taking over 10 seconds.
2020-08-02 00:32:03 WARNING (MainThread) [homeassistant.components.binary_sensor] Setup of binary_sensor platform ads is taking over 10 seconds.
2020-08-02 00:32:03 WARNING (MainThread) [homeassistant.components.switch] Setup of switch platform ads is taking over 10 seconds.
2020-08-02 00:32:03 WARNING (MainThread) [homeassistant.components.switch] Setup of switch platform ads is taking over 10 seconds.
2020-08-02 00:32:03 WARNING (MainThread) [homeassistant.components.light] Setup of light platform ads is taking over 10 seconds.
2020-08-02 00:32:04 ERROR (SyncWorker_3) [homeassistant.components.ads] Error subscribing to .HA_VW_ACTIEF_Slaapkamer1: ADSError: timeout elapsed (1861). 
2020-08-02 00:32:04 WARNING (MainThread) [homeassistant.components.weather] Setup of weather platform met is taking over 10 seconds.
2020-08-02 00:32:04 ERROR (MainThread) [metno] https://aa015h6buqvih86i1.api.met.no/weatherapi/locationforecast/1.9/ returned 
2020-08-02 00:32:04 ERROR (MainThread) [homeassistant.components.met.weather] Retrying in 20 minutes
2020-08-02 00:32:04 WARNING (MainThread) [homeassistant.setup] Setup of mobile_app is taking over 10 seconds.
2020-08-02 00:32:09 ERROR (SyncWorker_4) [homeassistant.components.ads] Error subscribing to .HA_VW_ACTIEF_Slaapkamer2: ADSError: timeout elapsed (1861). 
2020-08-02 00:32:14 ERROR (SyncWorker_6) [homeassistant.components.ads] Error subscribing to .HA_VW_ACTIEF_Slaapkamer3: ADSError: timeout elapsed (1861). 
2020-08-02 00:32:19 ERROR (SyncWorker_5) [homeassistant.components.ads] Error subscribing to .HA_VW_ACTIEF_Slaapkamer4: ADSError: timeout elapsed (1861). 
2020-08-02 00:32:24 ERROR (SyncWorker_0) [homeassistant.components.ads] Error subscribing to .HA_SL_KEU_Tafel: ADSError: timeout elapsed (1861). 
2020-08-02 00:32:29 ERROR (SyncWorker_2) [homeassistant.components.ads] Error subscribing to .HA_SL_KEU_Raam: ADSError: timeout elapsed (1861). 
2020-08-02 00:32:34 ERROR (SyncWorker_1) [homeassistant.components.ads] Error subscribing to .HA_SL_KEU_Eiland: ADSError: timeout elapsed (1861). 
2020-08-02 00:32:39 ERROR (SyncWorker_4) [homeassistant.components.ads] Error subscribing to .HA_SL_ZH_Centraal: ADSError: timeout elapsed (1861). 
2020-08-02 00:32:44 ERROR (SyncWorker_6) [homeassistant.components.ads] Error subscribing to .HA_SL_EH_Centraal: ADSError: timeout elapsed (1861). 
2020-08-02 00:32:49 ERROR (SyncWorker_5) [homeassistant.components.ads] Error subscribing to .HA_SL_Inkom_achter: ADSError: timeout elapsed (1861). 
2020-08-02 00:32:52 WARNING (MainThread) [homeassistant.bootstrap] Waiting on integrations to complete setup: timer, input_boolean, mobile_app
2020-08-02 00:32:54 ERROR (SyncWorker_0) [homeassistant.components.ads] Error subscribing to .HA_SL_WC_beneden: ADSError: timeout elapsed (1861). 
2020-08-02 00:32:59 ERROR (SyncWorker_0) [homeassistant.components.ads] Error subscribing to .HA_SL_Overloop2: ADSError: timeout elapsed (1861). 
2020-08-02 00:33:04 ERROR (SyncWorker_2) [homeassistant.components.ads] Error subscribing to .HA_SL_Berging: ADSError: timeout elapsed (1861). 
2020-08-02 00:33:09 ERROR (SyncWorker_2) [homeassistant.components.ads] Error subscribing to .HA_SL_SLPK1: ADSError: timeout elapsed (1861). 
2020-08-02 00:33:14 ERROR (SyncWorker_2) [homeassistant.components.ads] Error subscribing to .HA_SL_SLPK2: ADSError: timeout elapsed (1861). 
2020-08-02 00:33:19 ERROR (SyncWorker_6) [homeassistant.components.ads] Error subscribing to .HA_SL_Dressing: ADSError: timeout elapsed (1861). 
2020-08-02 00:33:24 ERROR (SyncWorker_5) [homeassistant.components.ads] Error subscribing to .HA_SL_Overloop1: ADSError: timeout elapsed (1861). 
2020-08-02 00:33:29 ERROR (SyncWorker_7) [homeassistant.components.ads] Error subscribing to .HA_SL_Badkamer: ADSError: timeout elapsed (1861). 
2020-08-02 00:33:34 ERROR (SyncWorker_0) [homeassistant.components.ads] Error subscribing to .HA_SL_Overloop3: ADSError: timeout elapsed (1861). 
2020-08-02 00:33:39 ERROR (SyncWorker_1) [homeassistant.components.ads] Error subscribing to .HA_SL_Kelder: ADSError: timeout elapsed (1861). 
2020-08-02 00:33:44 ERROR (SyncWorker_3) [homeassistant.components.ads] Error subscribing to .HA_SL_Buitenberging: ADSError: timeout elapsed (1861). 
2020-08-02 00:33:49 ERROR (SyncWorker_2) [homeassistant.components.ads] Error subscribing to .HA_SL_SLPK3: ADSError: timeout elapsed (1861). 
2020-08-02 00:33:52 WARNING (MainThread) [homeassistant.bootstrap] Waiting on integrations to complete setup: mobile_app
2020-08-02 00:33:54 ERROR (SyncWorker_4) [homeassistant.components.ads] Error subscribing to .HA_SL_SLPK4: ADSError: timeout elapsed (1861). 
2020-08-02 00:33:59 ERROR (SyncWorker_5) [homeassistant.components.ads] Error subscribing to .HA_SVW_Badkamer: ADSError: timeout elapsed (1861). 
2020-08-02 00:34:04 ERROR (SyncWorker_7) [homeassistant.components.ads] Error subscribing to .HA_SVW_Keuken: ADSError: timeout elapsed (1861). 
2020-08-02 00:34:09 ERROR (SyncWorker_0) [homeassistant.components.ads] Error subscribing to .HA_SVW_Living: ADSError: timeout elapsed (1861). 
2020-08-02 00:34:14 ERROR (SyncWorker_1) [homeassistant.components.ads] Error subscribing to .HA_SVW_Slaapkamer1: ADSError: timeout elapsed (1861). 
2020-08-02 00:34:19 ERROR (SyncWorker_3) [homeassistant.components.ads] Error subscribing to .HA_SVW_Slaapkamer2: ADSError: timeout elapsed (1861). 
2020-08-02 00:34:24 ERROR (SyncWorker_2) [homeassistant.components.ads] Error subscribing to .HA_SVW_Slaapkamer3: ADSError: timeout elapsed (1861). 
2020-08-02 00:34:29 ERROR (SyncWorker_4) [`homeassistant.components.ads`] Error subscribing to .HA_SVW_Slaapkamer4: ADSError: timeout elapsed (1861). 
2020-08-02 00:34:34 ERROR (SyncWorker_6) [homeassistant.components.ads] Error subscribing to .living_licht1_aan: ADSError: timeout elapsed (1861).

VDHeerJu on 2 Aug 2020

# ADS Beckhoff
ads:
  device: '5.8.143.247.1.1'
  port: 801
  ip_address: '192.168.0.114'

binary_sensor:
  - platform: ads
    adsvar: .HA_VW_ACTIEF_Badkamer
    name: Verwarming Badkamer actief
  - platform: ads
    adsvar: .HA_VW_ACTIEF_Keuken
    name: Verwarming Keuken actief
  - platform: ads
    adsvar: .HA_VW_ACTIEF_Living
    name: Verwarming Living actief
  - platform: ads
    adsvar: .HA_VW_ACTIEF_Slaapkamer1
    name: Verwarming Slaapkamer 1 actief
  - platform: ads
    adsvar: .HA_VW_ACTIEF_Slaapkamer2
    name: Verwarming Slaapkamer 2 actief
  - platform: ads
    adsvar: .HA_VW_ACTIEF_Slaapkamer3
    name: Verwarming Slaapkamer 3 actief
  - platform: ads
    adsvar: .HA_VW_ACTIEF_Slaapkamer4
    name: Verwarming Slaapkamer 4 actief   

sensor:
  - platform: ads
    adsvar: .I_Temperatuur_Keuken
    unit_of_measurement: '°C'
    adstype: int    


light:
  - platform: ads
    adsvar: .living_licht1_aan
    adsvar_brightness: .living_lichtsterkte_licht1
    name: Living 1
  - platform: ads
    adsvar: .living_licht2_aan
    adsvar_brightness: .living_lichtsterkte_licht2
    name: Living 2

switch:
  - platform: ads
    adsvar: .HA_SL_KEU_Tafel
    name: tafel
  - platform: ads
    adsvar: .HA_SL_KEU_Raam
    name: raam
  - platform: ads
    adsvar: .HA_SL_KEU_Eiland
    name: eiland
  - platform: ads
    adsvar: .HA_SL_KEU_Werkblad
    name: werkblad
  - platform: ads
    adsvar: .HA_SL_ZH_Centraal
    name: Zithoek
  - platform: ads
    adsvar: .HA_SL_EH_Centraal
    name: Eethoek
  - platform: ads
    adsvar: .HA_SL_Inkom_achter
    name: Inkom achter
  - platform: ads
    adsvar: .HA_SL_WC_beneden
    name: WC Beneden
  - platform: ads
    adsvar: .HA_SL_Badkamer
    name: Badkamer
  - platform: ads
    adsvar: .HA_SL_Berging
    name: Berging
  - platform: ads
    adsvar: .HA_SL_Kelder
    name: Kelder
  - platform: ads
    adsvar: .HA_SL_Buitenberging
    name: Buitenberging
  - platform: ads
    adsvar: .HA_SL_Gang
    name: Gang
  - platform: ads
    adsvar: .HA_SL_Dressing
    name: Dressing
  - platform: ads
    adsvar: .HA_SL_Overloop1
    name: Overloop1
  - platform: ads
    adsvar: .HA_SL_Overloop2
    name: Overloop2
  - platform: ads
    adsvar: .HA_SL_Overloop3
    name: Overloop3
  - platform: ads
    adsvar: .HA_SL_SLPK1
    name: Slaapkamer 1
  - platform: ads
    adsvar: .HA_SL_SLPK2
    name: Slaapkamer 2
  - platform: ads
    adsvar: .HA_SL_SLPK3
    name: Slaapkamer 3
  - platform: ads
    adsvar: .HA_SL_SLPK4
    name: Slaapkamer 4
  - platform: ads
    adsvar: .HA_SL_Zolder
    name: Zolder

  - platform: ads
    adsvar: .HA_SVW_Badkamer
    name: Verwarming Badkamer
  - platform: ads
    adsvar: .HA_SVW_Keuken
    name: Verwarming Keuken
  - platform: ads
    adsvar: .HA_SVW_Living
    name: Verwarming Living
  - platform: ads
    adsvar: .HA_SVW_Slaapkamer1
    name: Verwarming Slaapkamer 1
  - platform: ads
    adsvar: .HA_SVW_Slaapkamer2
    name: Verwarming Slaapkamer 2
  - platform: ads
    adsvar: .HA_SVW_Slaapkamer3
    name: Verwarming Slaapkamer 3
  - platform: ads
    adsvar: .HA_SVW_Slaapkamer4
    name: Verwarming Slaapkamer 4

VDHeerJu on 2 Aug 2020

The output of my logs are similar.

gijbelsy on 2 Aug 2020

Same problem here, even after update to 0113.3.

Flupke1979 on 4 Aug 2020

I can confirm this. The issue occurs if I add more then two variables. I don't know the reason for this, though. Need to take a closer look at it.

stlehmann on 4 Aug 2020

Any updates? My home assistant is not functional at the moment. Cannot go back to a previous version

pconfig on 6 Aug 2020

Sorry to keep you waiting. This issue seems to be a tricky one. I couldn' t locate it, yet.

stlehmann on 6 Aug 2020

@MartinHjelmare As the fix didn't completely resolve the issue apparently I want to ask you to repopen the issue.

stlehmann on 7 Aug 2020

As my time is very limited at the moment I can not estimate when a fix for the issue with the current version of pyads will be ready. However, I think a workaround to make the ads component work again would be to take the latest working version of pyads (should be 3.0.7) and make a small modification to remove the typing requirement. I could release the patched version as 3.0.7.1 and we could change the requirement in homeassistant. @MartinHjelmare would this be a way to go?

stlehmann on 7 Aug 2020

That could work. Your release history might look a bit weird after that with non incremental version ordering when sorting chronologically. Should be fine.

MartinHjelmare on 7 Aug 2020

Same problem here, i try a new HA installation and a new Twincat2 Programm.
Only 5 Bool declared in HA(light) and in Twincat --> the 2 first declared Bool Working and the other generate TimeOut Error
I try multiple inversion in the declaration HA & Twincat --> Always the same error.

DidierLengele on 8 Aug 2020

Same happens with TwinCAT 3

gijbelsy on 8 Aug 2020

any ideas what we should do ? wait for some new release or reinstall and use 0.112 ?

murcin on 11 Aug 2020

I'm on vacation this week. I'll create a PR for solving the issue beginning/mid next week.

stlehmann on 12 Aug 2020

👍3

It seems downgrading the pyads version does not fix the issue either. So for now I think it is best for all affected to downgrade home-assistant to 0.112 until the issue is fixed. 😞

stlehmann on 21 Aug 2020

It seems like the response from the ADS device gets lost once in a while. @MartinHjelmare is there a switch to start homeassistant only with one worker for testing purposes? This would help me a great deal debugging.

stlehmann on 21 Aug 2020

It seems downgrading the pyads version does not fix the issue either.

You mean pyads 3.0.7 w/o the typing requirement does not fix the issue? That's odd, as 3.0.7 worked with no issues.

If I can be of any help for testing etc., just let me know.

carstenschroeder on 21 Aug 2020

@MartinHjelmare: Wouldn't it be wise to revert #37748 and #38402 as long, as we have no fix for this? #37748 doesn't seem like a must have. Currently two other integrations also require typing.

carstenschroeder on 21 Aug 2020

We won't allow reverting the PRs. The typing package breaks virtual environments. Users that are prepared to handle this can always copy an older version of the integration as a custom integration until the library and bugs have been fixed.

MartinHjelmare on 21 Aug 2020

👍1

OK I seem to get a grip on it. It seems to be an issue with the underlying aslib.so If I use the old version from 3.0.7 everything seems to work fine with both version of pyads (3.0.7 and 3.2.1).

With the current version of adslib.so there seems to be a timeout issue.

stlehmann on 21 Aug 2020

@carstenschroeder Could you try checking out adslib #b56d01, build the adslib.so with make and put it in your .homeassistant/deps/lib/python3.8/site-packages/pyads/pyads directory. Hopefully this does the job.

stlehmann on 21 Aug 2020

@stlehmann I can confirm that it works with adslib #b56d01.

carstenschroeder on 21 Aug 2020

Great. @pbruenn do you have an idea what could lead adslib to ignore incoming responses? Is this already a known issue?

stlehmann on 21 Aug 2020

We won't allow reverting the PRs. The typing package breaks virtual environments. Users that are prepared to handle this can always copy an older version of the integration as a custom integration until the library and bugs have been fixed.

A maintenance PR is allowed to break functionality for multiple releases. That's how it works at home assistant these days...no surprise on my side

carstenschroeder on 21 Aug 2020

@carstenschroeder I think it is very hard for the maintainers to keep track of alle the components and their dependencies. It is almost inevitable that some components break during the update process. But it is not the right way to revert sensible changes due to some broken components. It is important that the components get fixed to meet the requirements.

stlehmann on 21 Aug 2020

@stlehmann Sorry, I have no idea. I think your adslib #b56d01 matches upstream https://github.com/Beckhoff/ADS/commit/286a06297d5bbd045e354cefa24621baf88d0c6b thats more than two years old, so I have no idea which change breaks your usecase. Maybe you could give me a hint on how to reproduce this in AdsLib or you might be able to bisect the bad commit yourself.

pbruenn on 21 Aug 2020

@stlehmann I agree in all you say, except one topic: the PR that broke things is not sensible as it is only a preparation for the removal of the workaround for the typing issue. Currently the workaround is still needed because two other integrations also require typing. So the whole change could have been done w/o breaking ADS for so long. It has been left broken to generate pressure to fix the library at the expense of the user experience. Just my 2 cents

@MartinHjelmare @stlehmann This is by no means a criticism on you both. It is always a pleasure to work with you and I really appreciate your contributions to home assistant.

carstenschroeder on 21 Aug 2020

@pbruenn thanks for the feedback I will do some further investigations on this issue and try to bisect the commit that causes the issue.

stlehmann on 21 Aug 2020

In the meantime this workaround can be used to keep current installations working:

Could you try checking out adslib #b56d01, build the adslib.so with make and put it in your .homeassistant/deps/lib/python3.8/site-packages/pyads/pyads directory. Hopefully this does the job.

stlehmann on 24 Aug 2020

Would it be an idea to put this workaround in the next point release?

pconfig on 24 Aug 2020

In the meantime this workaround can be used to keep current installations working:

Could you try checking out adslib #b56d01, build the adslib.so with make and put it in your .homeassistant/deps/lib/python3.8/site-packages/pyads/pyads directory. Hopefully this does the job.

I can confirm this workaround works for me. I'm using a Raspberry Pi 3 with a virtual environment

tomation7 on 26 Aug 2020

In the meantime I think I identified the "evil" commit by cherry-picking every single commit since the last working version 🤯. It seems that commit https://github.com/Beckhoff/ADS/commit/8e4e8bb9d656097e7bbe3d19d18cffeb9e0ab37e breaks the notification handling. It replaces threads by async. But honestly I don' t know why this would break the homeassistant component. AFAIK the notification handling works just fine with plain pyads. Maybe @pbruenn or @MartinHjelmare have an idea on this matter?

stlehmann on 26 Aug 2020

I have no idea either. As I understand the issue that commit breaks notifications entirely for homeassistant. Is this correct?

Could you point me to the callback function, which is registered by homeassistant and executed in the context of std::async()?

Notification::Notify() is called here in the context of std::async().

Which platforms are effected? Is it only Raspberry Pi 3 ARM or x64, too?

pbruenn on 26 Aug 2020

@pbruenn Funny enough it does not break notifications entirely. One notification works. With multiple notifications it seems a bit of a gamble if a notification can be registered or not. Two notifications sometimes work while three or more notifications most certainly won't work.

The notification are added here:
https://github.com/home-assistant/core/blob/51a63c1fc413670fb776560380c1ad24c3998297/homeassistant/components/ads/__init__.py#L205

And the callback here:
https://github.com/home-assistant/core/blob/51a63c1fc413670fb776560380c1ad24c3998297/homeassistant/components/ads/__init__.py#L227

The affected platforms are Raspberry ARM and x64.

I observed that sometimes the response to the addDeviceNotification request is not processed within pyads. I will dive into this tomorrow and provide some more detailled information.

stlehmann on 26 Aug 2020

@stlehmann thanks for the links unfortunately I am not to familiar with python. At some point you have a C function which you pass to the C AdsLib don't you? Or do you pass direct pointers to your python functions? How do these python functions work? do they copy the notification object into some kind of queue, where they are processed in context of another thread, or are they completely process within this std::async() context (in most c++ runtimes a thread from a thread pool).
If you have time two (good&bad) Wireshark captures would be interesting, to see which messages receive the wire.

EDIT: Well, indeed if my python is correct I would read the callback as the processing continues within the std::asyncs context. Is there something similar in python to continue the processing in another thread? But to be honest I am still puzzled how the python handling is related to changing one static thread to std::async in AdsLib :-(

pbruenn on 26 Aug 2020

Maybe my C++ isn't better. Reading the reference of std:async() creates a bad feeling, that maybe we always call the callback synchronously. I have to check that tomorrow, to be sure.

pbruenn on 26 Aug 2020

Which platforms are effected? Is it only Raspberry Pi 3 ARM or x64, too?

I'm running hass.os in Hyper-V environment, and the issue occurs.
As I understand from @tomation7 the same issue occurs on RPI3 Virtual Env.
Haven't tested it on RPI4 with Hassbian and Docker.

gijbelsy on 26 Aug 2020

Reading the reference of std:async() creates a bad feeling, that maybe we always call the callback synchronously.

My feeling is that this would fit in the described behaviour. Would be great if you could check this 👍. In the meantime I will provide some Wireshark snippets and gather more detailed information on the actual behaviour.

stlehmann on 27 Aug 2020

I set up a minimal configuration with the following configuration.yml:

# Configure a default setup of Home Assistant (frontend, api, etc)
default_config:

# Text to speech
tts:
  - platform: google_translate
ads:
  device: '172.18.3.25.1.1'
  port: 851

switch:
  - platform: ads
    adsvar: GVL.b1

binary_sensor:
  - platform: ads
    adsvar: GVL.b2

logger:
  default: warning
  logs:
    homeassistant.components.ads: info


group: !include groups.yaml
automation: !include automations.yaml
script: !include scripts.yaml
scene: !include scenes.yaml

So basically this is a switch and a binary sensor. The plc runs a very simple program that set GVL.b2 = GVL.b1. So if GVL.b1 is changed by toggling the switch GVL.b2 gets toggled as well and the binary sensor should reflect that. I captured the communication for both versions of adslib. They are basically identical. Find it in this file: wireshark_ads.zip. I modified pyads to print out import steps in the debug log.

If I run homeassistant with the working version of adslib everything works fine. The Wireshark dump resembles that:

wireshark_ads_working

debug-log:

2020-08-27T10:58:52+0200 Info: Connected to 172.18.3.25
Request handle for GVL.b1
Got handle 218103823 for GVL.b1
Request: Add device notification
Response: 0
Request handle for GVL.b2
Got handle 218103824 for GVL.b2
Request: Add device notification
Response: 0

If I use the non-working version of adslib the dump looks like this:
grafik

debug-log:

2020-08-27T10:53:22+0200 Info: Connected to 172.18.3.25
Request handle for GVL.b1
Got handle 218103823 for GVL.b1
Request: Add device notification
Response: 0
Request handle for GVL.b2
2020-08-27 10:53:27 ERROR (SyncWorker_0) [homeassistant.components.ads] Error subscribing to GVL.b2: ADSError: timeout elapsed (1861). 
2020-08-27T10:53:27+0200 Warning: InvokeId mismatch: waiting for 0x0 received 0x3
2020-08-27T10:53:27+0200 Warning: No response pending
2020-08-27 10:53:32 WARNING (MainThread) [homeassistant.components.binary_sensor] Setup of binary_sensor platform ads is taking over 10 seconds.

This shows that pyads is waining for the response on packet 10 and finally times out even though the packet has been sent by the plc.

stlehmann on 27 Aug 2020

My guess that it has something to do with the order of the packets. Randomly I get the following dump:

grafik

Log:

2020-08-27T11:06:08+0200 Info: Connected to 172.18.3.25
Request handle for GVL.b1
Got handle 218103823 for GVL.b1
Request: Add device notification
Response: 0
Request handle for GVL.b2
Got handle 218103824 for GVL.b2
Request: Add device notification
Response: 1861
2020-08-27 11:06:13 ERROR (SyncWorker_7) [homeassistant.components.ads] Error subscribing to GVL.b2: ADSError: timeout elapsed (1861). 
2020-08-27T11:06:13+0200 Warning: InvokeId mismatch: waiting for 0x0 received 0x4
2020-08-27T11:06:13+0200 Warning: No response pending
2020-08-27 11:06:18 WARNING (MainThread) [homeassistant.components.binary_sensor] Setup of binary_sensor platform ads is taking over 10 seconds.

Here the request for the handle works fine (response packet comes directly after request packet) but the notification request times out. Note that there is a "ADS Device Notification Request" coming from the plc between packet 13 and 15.

stlehmann on 27 Aug 2020

So in conclusion: It seems works if all packets (request and response) come in order but breaks if there are other packets in between request and response (like device notification requests from the plc).

stlehmann on 27 Aug 2020

@stlehmann Yes That std:async() is just stupid and effectively the same as a simple call to run() (with the overhead of thread switching...)
In general this should be a problem if the callback function is fast enough, but I expect the homeassistant callback runs for too long. I will look for a solution to decouple the receive and callback handling like it was intended (async)

pbruenn on 27 Aug 2020

@pbruenn Thanks for looking into this. I'm tempted to just revert the commit that replaces threads by async. Do you think this could work or are there further dependencies I didn't take into account?

stlehmann on 27 Aug 2020

@stlehmann A revert will have merge conflicts. I am currently working on a fix (doing the revert). Another idea was to store the futures in std::vector. That would be easier, should work, but is pretty unefficient

pbruenn on 27 Aug 2020

A revert will have merge conflicts.

Thanks, I just found out the hard way ;). So I'm looking forward for your fix. Sadly I'm not familiar with async programming in C++ so I can not provide any significant help. But if you need some testing or other help please let me know.

stlehmann on 27 Aug 2020

@stlehmann Could you try to git apply this patch and see if it helps:
0001-AdsLib-repair-async-notifications.txt

Effectively it is just a revert of that bad commit, but I change some semaphore function names (to match C++20). I will try to make the patch a little nicer before release. But first lets see if it actually fixes the problem.

pbruenn on 27 Aug 2020

👍1

@pbruenn Looks great. I tried it with multiple configurations and it seems to work just fine.

stlehmann on 27 Aug 2020

@stlehmann good to hear. Attached you find my final version. I will run it through our CI tests and merge it tomorrow. Would be cool if you have the time to take a look on it to:
0001-AdsLib-repair-async-notifications-v2.txt
This time I tried to keep the semaphore more aligned with what we might get with C++20. It _should_ work just like the previous patch.

pbruenn on 27 Aug 2020

👍1

@pbruenn Patch 2 looks fine as well. I just tried it and all works as expected.

I'm looking forward to your merge tomorrow and will merge it in my fork right away. Happy you could fix this issue and many thanks for your fast responses 🎉 🙇

stlehmann on 27 Aug 2020

👍3

Well, introducing such a bug is embarrassing, but fixing it with you guys was fun ;-). The fast feedback to my questions was great, and your help in tracking down the issue was outstanding. So I am pretty happy to give the compliment back.

The patch is now merged and available as https://github.com/Beckhoff/ADS/commit/6684d9308dc79993924b91c62fac4941d2d68f69.

If you merge master, you will get 3 more commits. The first merges AdsLibOOI into AdsLib, so the resulting library is slightly larger. The second commit simplifies the Makefile. And the last commit just indents our bugfix. I split the bugfix and code formatting to make the fix more readable.

pbruenn on 28 Aug 2020

👍2

@pbruenn Thanks for fixing this bug so quickly. Unfortunately I won't be able to test and implement the new commit today because my Virtual machine has broken due to installing WSL2 :boom: 😞. I will get to it by the start of next week.

stlehmann on 28 Aug 2020

I got my Virtual machine working again and drafted a new release 3.2.2 for pyads. @carstenschroeder, @gijbelsy, @tomation7 could you please give it a try and send feedback if everything is working fine now. 🙏

stlehmann on 28 Aug 2020

👍1

@stlehmann Under Ubuntu in a virtualenv install of HA I can confirm that it works.

But in the docker image of Hassos the installation of pyads fails. Releases 3.0.7 and 3.2.1 of pyads install fine. I see the following errors in homeassistant.log:

2020-08-28 16:48:30 ERROR (SyncWorker_2) [homeassistant.util.package] Unable to install package pyads==3.2.2: ERROR: Command errored out with exit status 1:
   command: /usr/local/bin/python3 -u -c 'import sys, setuptools, tokenize; sys.argv[0] = '"'"'/tmp/pip-install-ix1sahan/pyads/setup.py'"'"'; __file__='"'"'/tmp/pip-install-ix1sahan/pyads/setup.py'"'"';f=getattr(tokenize, '"'"'open'"'"', open)(__file__);code=f.read().replace('"'"'\r\n'"'"', '"'"'\n'"'"');f.close();exec(compile(code, __file__, '"'"'exec'"'"'))' bdist_wheel -d /tmp/pip-wheel-n_hog2i3
       cwd: /tmp/pip-install-ix1sahan/pyads/
  Complete output (3 lines):
  running bdist_wheel
  running build
  error: [Errno 2] No such file or directory: 'make'
  ----------------------------------------
  ERROR: Failed building wheel for pyads
    ERROR: Command errored out with exit status 1:
     command: /usr/local/bin/python3 -u -c 'import sys, setuptools, tokenize; sys.argv[0] = '"'"'/tmp/pip-install-ix1sahan/pyads/setup.py'"'"'; __file__='"'"'/tmp/pip-install-ix1sahan/pyads/setup.py'"'"';f=getattr(tokenize, '"'"'open'"'"', open)(__file__);code=f.read().replace('"'"'\r\n'"'"', '"'"'\n'"'"');f.close();exec(compile(code, __file__, '"'"'exec'"'"'))' install --record /tmp/pip-record-nhx3sujk/install-record.txt --single-version-externally-managed --compile --install-headers /usr/local/include/python3.8/pyads
         cwd: /tmp/pip-install-ix1sahan/pyads/
    Complete output (2 lines):
    running install
    error: [Errno 2] No such file or directory: 'make'
    ----------------------------------------
ERROR: Command errored out with exit status 1: /usr/local/bin/python3 -u -c 'import sys, setuptools, tokenize; sys.argv[0] = '"'"'/tmp/pip-install-ix1sahan/pyads/setup.py'"'"'; __file__='"'"'/tmp/pip-install-ix1sahan/pyads/setup.py'"'"';f=getattr(tokenize, '"'"'open'"'"', open)(__file__);code=f.read().replace('"'"'\r\n'"'"', '"'"'\n'"'"');f.close();exec(compile(code, __file__, '"'"'exec'"'"'))' install --record /tmp/pip-record-nhx3sujk/install-record.txt --single-version-externally-managed --compile --install-headers /usr/local/include/python3.8/pyads Check the logs for full command output.

carstenschroeder on 28 Aug 2020

But in the docker image of Hassos the installation of pyads fails.

I tested this by using a modified version of ads as a custom component which requires pyads 3.2.2

So, it might work if the docker image is built natively with this new release. Unfortunately, I don't know how I could test this.

carstenschroeder on 28 Aug 2020

But in the docker image of Hassos the installation of pyads fails. Releases 3.0.7 and 3.2.1 of pyads install fine. I see the following errors in homeassistant.log:

To build adslib in a docker image you need to install build-essentials first. Use the package manager to install them in the container:

$ apt update
$ apt install build-essentials

stlehmann on 28 Aug 2020

Thanks for the hint!

As Alpine Linux is used in the docker image I had to install build-base package. Then it worked. Release 3.0.7 and 3.2.1 worked because there are already corresponding wheel builds in the HA wheel index.

So, I can confirm pyads 3.2.2 works in my installation.

carstenschroeder on 28 Aug 2020

👍1

The fixed version of the ADS-component has been merged to the dev branch and awaits testing 😄

stlehmann on 31 Aug 2020

👍3

Any idea when the fix will be available in the next update ?

VDHeerJu on 9 Sep 2020

The fix will go out in 0.115.0 on Thursday 17 September.

MartinHjelmare on 9 Sep 2020

🎉5

I have updated to 0.115 today. Ads works fine again. Thank you all for your great work.

benblai on 18 Sep 2020

Installed the update just a few minutes ago, doing some testing, but it all looks good for the moment!
Tnx y'all.

gijbelsy on 18 Sep 2020

I installed the latest 0.115 today and everything works fine. Thanks a lot for the work.

punzenbergerpeter on 21 Sep 2020

Was this page helpful?

0 / 5 - 0 ratings

Related issues

Wink component not able to use full OAuth for authorization

missedtheapex · 3Comments

Rewrite facebook unittest tests to pytest style test functions

MartinHjelmare · 3Comments

Z-wave issues after upgrade 0.84.6 to 0.85.1

moskovskiy82 · 3Comments

Deconz Integration uncapable of https / wss

sh0rez · 3Comments

Websocket Error

sogeniusio · 3Comments

Core: Ads-Integration has ADSTimouts since update to 0.113.0

The problem

Environment

Problem-relevant configuration.yaml

Traceback/Error logs

Log 1

Logs 2

Additional information

Most helpful comment

All 81 comments

Related issues

Problem-relevant `configuration.yaml`