hass-pfsense Issue: Everything goes unavailable

Home Assistant version: 2021.11.1 (Home Assistant Operating System) Component version: Latest

Several times a minute, all entities from the pfsense component go unavailable. It seems like this is only happening when I use one of the switches to turn on/off a firewall rule but I can't be certain Logbook shows this (note: it shows the same for all entities)

LAN: firewall_rule turned on
6:58:45 PM - 4 minutes ago
LAN: firewall_rule became unavailable
6:58:07 PM - 5 minutes ago
LAN: firewall_rule turned on
6:57:27 PM - 5 minutes ago
LAN: firewall_rule turned off
6:55:59 PM - 7 minutes ago
LAN: firewall_rule became unavailable
6:55:55 PM - 7 minutes ago
LAN: firewall_rule turned off
6:55:15 PM - 8 minutes ago
LAN: firewall_rule became unavailable
6:55:11 PM - 8 minutes ago
LAN: firewall_rule turned on
6:49:51 PM - 13 minutes ago
LAN: firewall_rule became unavailable
6:49:47 PM - 13 minutes ago
LAN: firewall_rule turned on
6:43:52 PM - 19 minutes ago
LAN: firewall_rule became unavailable
6:43:17 PM - 20 minutes ago
LAN: firewall_rule turned on
6:35:43 PM - 27 minutes ago
LAN: firewall_rule became unavailable
6:35:03 PM - 28 minutes ago

For troubleshooting this issue, I have:

Increased System -> Advanced -> Max Processes to as high as 30 but it didn't seem to have any effect.
Confirmed firewall rules allow this traffic
Restarted Home Assistant
Restarted the router
Ensured the user I created had the 'System - HA node sync' permission and then tried with full admin permissions
Increased scan interval to 60 seconds
Ran continual ping tests, see results below (left is my PC, right is from the HA host

Debug logs:

 18:38:14 DEBUG (MainThread) [custom_components.pfsense] Finished fetching pfSense state data in 5.329 seconds (success: True)
2021-11-07 18:38:50 DEBUG (MainThread) [custom_components.pfsense] Finished fetching pfSense state data in 5.925 seconds (success: True)
2021-11-07 18:39:26 DEBUG (MainThread) [custom_components.pfsense] Finished fetching pfSense state data in 6.019 seconds (success: True)
2021-11-07 18:40:02 DEBUG (MainThread) [custom_components.pfsense] Finished fetching pfSense state data in 6.439 seconds (success: True)
2021-11-07 18:40:37 DEBUG (MainThread) [custom_components.pfsense] Finished fetching pfSense state data in 5.122 seconds (success: True)
2021-11-07 18:41:12 DEBUG (MainThread) [custom_components.pfsense] Finished fetching pfSense state data in 5.169 seconds (success: True)
2021-11-07 18:41:47 DEBUG (MainThread) [custom_components.pfsense] Finished fetching pfSense state data in 5.410 seconds (success: True)
2021-11-07 18:42:24 DEBUG (MainThread) [custom_components.pfsense] Finished fetching pfSense state data in 7.120 seconds (success: True)
2021-11-07 18:43:00 DEBUG (MainThread) [custom_components.pfsense] Finished fetching pfSense state data in 6.950 seconds (success: True)
2021-11-07 18:43:09 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [139741298965040] The read operation timed out
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 185, in handle_call_service
    await hass.services.async_call(
  File "/usr/src/homeassistant/homeassistant/core.py", line 1495, in async_call
    task.result()
  File "/usr/src/homeassistant/homeassistant/core.py", line 1530, in _execute_service
    await handler.job.target(service_call)
  File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 213, in handle_service
    await self.hass.helpers.service.entity_service_call(
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 667, in entity_service_call
    future.result()  # pop exception if have
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 863, in async_request_call
    await coro
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 704, in _handle_entity_call
    await result
  File "/config/custom_components/pfsense/switch.py", line 250, in async_turn_off
    await self.hass.async_add_executor_job(client.disable_filter_rule_by_tracker, tracker)
  File "/usr/local/lib/python3.9/concurrent/futures/thread.py", line 52, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/config/custom_components/pfsense/pypfsense/__init__.py", line 163, in disable_filter_rule_by_tracker
    self._restore_config_section("filter", config["filter"])
  File "/config/custom_components/pfsense/pypfsense/__init__.py", line 53, in inner
    response = func(*args, **kwargs)
  File "/config/custom_components/pfsense/pypfsense/__init__.py", line 70, in _restore_config_section
    response = self._get_proxy().pfsense.restore_config_section(params, 60)
  File "/usr/local/lib/python3.9/xmlrpc/client.py", line 1116, in __call__
    return self.__send(self.__name, args)
  File "/usr/local/lib/python3.9/xmlrpc/client.py", line 1458, in __request
    response = self.__transport.request(
  File "/usr/local/lib/python3.9/xmlrpc/client.py", line 1160, in request
    return self.single_request(host, handler, request_body, verbose)
  File "/usr/local/lib/python3.9/xmlrpc/client.py", line 1173, in single_request
    resp = http_conn.getresponse()
  File "/usr/local/lib/python3.9/http/client.py", line 1371, in getresponse
    response.begin()
  File "/usr/local/lib/python3.9/http/client.py", line 319, in begin
    version, status, reason = self._read_status()
  File "/usr/local/lib/python3.9/http/client.py", line 280, in _read_status
    line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1")
  File "/usr/local/lib/python3.9/socket.py", line 704, in readinto
    return self._sock.recv_into(b)
  File "/usr/local/lib/python3.9/ssl.py", line 1241, in recv_into
    return self.read(nbytes, buffer)
  File "/usr/local/lib/python3.9/ssl.py", line 1099, in read
    return self._sslobj.read(len, buffer)
socket.timeout: The read operation timed out
2021-11-07 18:43:17 ERROR (MainThread) [custom_components.pfsense] Timeout fetching pfSense state data
2021-11-07 18:43:17 DEBUG (MainThread) [custom_components.pfsense] Finished fetching pfSense state data in 10.002 seconds (success: False)
2021-11-07 18:43:18 ERROR (MainThread) [homeassistant.core] Error executing service: <ServiceCall switch.turn_off (c:f479d0c743a0c126144d6fbd1237eb01): entity_id=['switch.router_filter_rule_1604272216_ha_lan_routevpn']>
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/core.py", line 1511, in catch_exceptions
    await coro_or_task
  File "/usr/src/homeassistant/homeassistant/core.py", line 1530, in _execute_service
    await handler.job.target(service_call)
  File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 213, in handle_service
    await self.hass.helpers.service.entity_service_call(
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 667, in entity_service_call
    future.result()  # pop exception if have
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 863, in async_request_call
    await coro
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 704, in _handle_entity_call
    await result
  File "/config/custom_components/pfsense/switch.py", line 251, in async_turn_off
    await self.coordinator.async_refresh()
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 165, in async_refresh
    await self._async_refresh(log_failures=True)
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 265, in _async_refresh
    update_callback()
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 325, in _handle_coordinator_update
    self.async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 486, in async_write_ha_state
    self._async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 538, in _async_write_ha_state
    if (icon := (entry and entry.icon) or self.icon) is not None:
  File "/config/custom_components/pfsense/sensor.py", line 427, in icon
    if property == "status" and self.native_value != "online":
  File "/config/custom_components/pfsense/sensor.py", line 437, in native_value
    value = gateway[property]
TypeError: 'NoneType' object is not subscriptable
2021-11-07 18:43:52 INFO (MainThread) [custom_components.pfsense] Fetching pfSense state data recovered
2021-11-07 18:43:52 DEBUG (MainThread) [custom_components.pfsense] Finished fetching pfSense state data in 5.462 seconds (success: True)
2021-11-07 18:43:52 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 134, in _handle_refresh_interval
    await self._async_refresh(log_failures=True, scheduled=True)
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 265, in _async_refresh
    update_callback()
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 325, in _handle_coordinator_update
    self.async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 486, in async_write_ha_state
    self._async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 519, in _async_write_ha_state
    state = self._stringify_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 492, in _stringify_state
    if (state := self.state) is None:
  File "/usr/src/homeassistant/homeassistant/components/sensor/__init__.py", line 273, in state
    value = self.native_value
  File "/config/custom_components/pfsense/sensor.py", line 437, in native_value
    value = gateway[property]
TypeError: 'NoneType' object is not subscriptable
2021-11-07 18:44:27 DEBUG (MainThread) [custom_components.pfsense] Finished fetching pfSense state data in 5.113 seconds (success: True)
2021-11-07 18:44:27 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 134, in _handle_refresh_interval
    await self._async_refresh(log_failures=True, scheduled=True)
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 265, in _async_refresh
    update_callback()
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 325, in _handle_coordinator_update
    self.async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 486, in async_write_ha_state
    self._async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 519, in _async_write_ha_state
    state = self._stringify_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 492, in _stringify_state
    if (state := self.state) is None:
  File "/usr/src/homeassistant/homeassistant/components/sensor/__init__.py", line 273, in state
    value = self.native_value
  File "/config/custom_components/pfsense/sensor.py", line 437, in native_value
    value = gateway[property]
TypeError: 'NoneType' object is not subscriptable
2021-11-07 18:45:02 DEBUG (MainThread) [custom_components.pfsense] Finished fetching pfSense state data in 5.220 seconds (success: True)
2021-11-07 18:45:02 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 134, in _handle_refresh_interval
    await self._async_refresh(log_failures=True, scheduled=True)
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 265, in _async_refresh
    update_callback()
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 325, in _handle_coordinator_update
    self.async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 486, in async_write_ha_state
    self._async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 519, in _async_write_ha_state
    state = self._stringify_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 492, in _stringify_state
    if (state := self.state) is None:
  File "/usr/src/homeassistant/homeassistant/components/sensor/__init__.py", line 273, in state
    value = self.native_value
  File "/config/custom_components/pfsense/sensor.py", line 437, in native_value
    value = gateway[property]
TypeError: 'NoneType' object is not subscriptable
2021-11-07 18:45:37 DEBUG (MainThread) [custom_components.pfsense] Finished fetching pfSense state data in 5.209 seconds (success: True)
2021-11-07 18:45:37 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 134, in _handle_refresh_interval
    await self._async_refresh(log_failures=True, scheduled=True)
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 265, in _async_refresh
    update_callback()
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 325, in _handle_coordinator_update
    self.async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 486, in async_write_ha_state
    self._async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 519, in _async_write_ha_state
    state = self._stringify_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 492, in _stringify_state
    if (state := self.state) is None:
  File "/usr/src/homeassistant/homeassistant/components/sensor/__init__.py", line 273, in state
    value = self.native_value
  File "/config/custom_components/pfsense/sensor.py", line 437, in native_value
    value = gateway[property]
TypeError: 'NoneType' object is not subscriptable
2021-11-07 18:46:12 DEBUG (MainThread) [custom_components.pfsense] Finished fetching pfSense state data in 5.075 seconds (success: True)
2021-11-07 18:46:12 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 134, in _handle_refresh_interval
    await self._async_refresh(log_failures=True, scheduled=True)
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 265, in _async_refresh
    update_callback()
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 325, in _handle_coordinator_update
    self.async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 486, in async_write_ha_state
    self._async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 519, in _async_write_ha_state
    state = self._stringify_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 492, in _stringify_state
    if (state := self.state) is None:
  File "/usr/src/homeassistant/homeassistant/components/sensor/__init__.py", line 273, in state
    value = self.native_value
  File "/config/custom_components/pfsense/sensor.py", line 437, in native_value
    value = gateway[property]
TypeError: 'NoneType' object is not subscriptable
2021-11-07 18:46:47 DEBUG (MainThread) [custom_components.pfsense] Finished fetching pfSense state data in 5.436 seconds (success: True)
2021-11-07 18:46:47 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 134, in _handle_refresh_interval
    await self._async_refresh(log_failures=True, scheduled=True)
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 265, in _async_refresh
    update_callback()
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 325, in _handle_coordinator_update
    self.async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 486, in async_write_ha_state
    self._async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 519, in _async_write_ha_state
    state = self._stringify_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 492, in _stringify_state
    if (state := self.state) is None:
  File "/usr/src/homeassistant/homeassistant/components/sensor/__init__.py", line 273, in state
    value = self.native_value
  File "/config/custom_components/pfsense/sensor.py", line 437, in native_value
    value = gateway[property]
TypeError: 'NoneType' object is not subscriptable
2021-11-07 18:47:22 DEBUG (MainThread) [custom_components.pfsense] Finished fetching pfSense state data in 5.095 seconds (success: True)
2021-11-07 18:47:22 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 134, in _handle_refresh_interval
    await self._async_refresh(log_failures=True, scheduled=True)
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 265, in _async_refresh
    update_callback()
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 325, in _handle_coordinator_update
    self.async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 486, in async_write_ha_state
    self._async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 519, in _async_write_ha_state
    state = self._stringify_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 492, in _stringify_state
    if (state := self.state) is None:
  File "/usr/src/homeassistant/homeassistant/components/sensor/__init__.py", line 273, in state
    value = self.native_value
  File "/config/custom_components/pfsense/sensor.py", line 437, in native_value
    value = gateway[property]
TypeError: 'NoneType' object is not subscriptable
2021-11-07 18:47:57 DEBUG (MainThread) [custom_components.pfsense] Finished fetching pfSense state data in 5.081 seconds (success: True)
2021-11-07 18:47:57 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 134, in _handle_refresh_interval
    await self._async_refresh(log_failures=True, scheduled=True)
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 265, in _async_refresh
    update_callback()
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 325, in _handle_coordinator_update
    self.async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 486, in async_write_ha_state
    self._async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 519, in _async_write_ha_state
    state = self._stringify_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 492, in _stringify_state
    if (state := self.state) is None:
  File "/usr/src/homeassistant/homeassistant/components/sensor/__init__.py", line 273, in state
    value = self.native_value
  File "/config/custom_components/pfsense/sensor.py", line 437, in native_value
    value = gateway[property]
TypeError: 'NoneType' object is not subscriptable
2021-11-07 18:48:32 DEBUG (MainThread) [custom_components.pfsense] Finished fetching pfSense state data in 5.276 seconds (success: True)
2021-11-07 18:48:32 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 134, in _handle_refresh_interval
    await self._async_refresh(log_failures=True, scheduled=True)
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 265, in _async_refresh
    update_callback()
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 325, in _handle_coordinator_update
    self.async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 486, in async_write_ha_state
    self._async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 519, in _async_write_ha_state
    state = self._stringify_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 492, in _stringify_state
    if (state := self.state) is None:
  File "/usr/src/homeassistant/homeassistant/components/sensor/__init__.py", line 273, in state
    value = self.native_value
  File "/config/custom_components/pfsense/sensor.py", line 437, in native_value
    value = gateway[property]
TypeError: 'NoneType' object is not subscriptable
2021-11-07 18:49:07 DEBUG (MainThread) [custom_components.pfsense] Finished fetching pfSense state data in 5.105 seconds (success: True)
2021-11-07 18:49:07 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 134, in _handle_refresh_interval
    await self._async_refresh(log_failures=True, scheduled=True)
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 265, in _async_refresh
    update_callback()
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 325, in _handle_coordinator_update
    self.async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 486, in async_write_ha_state
    self._async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 519, in _async_write_ha_state
    state = self._stringify_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 492, in _stringify_state
    if (state := self.state) is None:
  File "/usr/src/homeassistant/homeassistant/components/sensor/__init__.py", line 273, in state
    value = self.native_value
  File "/config/custom_components/pfsense/sensor.py", line 437, in native_value
    value = gateway[property]
TypeError: 'NoneType' object is not subscriptable

Nov 08 '21 00:11 JOHLC

Ok thanks for letting me know. When a rule is toggled I force an immediate refresh of the data instead of waiting for the poll interval (to make the ui reflect immediately the new state of the rule/etc). It looks like that is hitting a timeout for some reason and that makes everything go unavailable until the next poll of the data.

I’ll take a look and see if I can reproduce or anything. I don’t toggle the rules frequently so may be why I don’t see it regularly.

Nov 08 '21 01:11 travisghansen

Looking at the logs your average time to fetch data is double+ what mine takes locally. Do you have an unusually complex pfSense install? are you accessing it over a wan?

For comparison I have test instance running in a vm that averages just over 2 secs per fetch and my 'real' instance running on bare metal takes just over 1 sec. You're instance appears to be taking between 5-7 seconds on average.

Nov 08 '21 03:11 travisghansen

Hello, I would say I do have a complex pfSense install. Multiple networks, interfaces, vlans, service, packages, firewall rules, etc. Still only average 30% memory use (of 8GB) and current load averages show: 0.71, 0.55, 0.45 Bandwidth does not seem to be the issue as I am barely utilizing the available.

This is not being polled via WAN.

Let me know if you need any more info.

Nov 08 '21 22:11 JOHLC

Interesting. I wonder which data points are taking the most time.

For now if you’re comfortable hacking some code I’d be interested to know what you observe after bumping this value here: https://github.com/travisghansen/hass-pfsense/blob/main/custom_components/pfsense/pypfsense/init.py#L8

Nov 09 '21 03:11 travisghansen

I just bumped the value to 10 in the main branch. Let me know if that helps a bit..

Nov 10 '21 04:11 travisghansen

Similar here. I enabled 2 device trackers an all 800 sensors went unavailable

Nov 11 '21 03:11 nagyrobi

Interesting. The device tracker api calls are entirely distinct from all the other sensors, that leads me to believe that something is locking up the api generally.

If you disable the device tracker integration do you see the others go unavailable regularly?

Nov 11 '21 04:11 travisghansen

Had to restart HA, things went back to normal.

I use the 'main' version, it's OK.

Nov 11 '21 05:11 nagyrobi

Hello, I seem to have better stability with this:

DEFAULT_TIMEOUT = 30

in init.py

I have tried 10, 15, 20, and now 30.

Nov 24 '21 02:11 JOHLC

@JOHLC do you have device tracker enabled? Do the problem only appear when switches are toggled or happens generally?

Do you have other external apps using the pfsense api or generally making changes via the ui?

Nov 24 '21 03:11 travisghansen

@travisghansen I have had the issue with and without device tracker enabled. Even now at 30 seconds, I still get pretty frequent blips on all entities. Seems to happen generally, but is made worse when toggling a switch.

I don't have anything else polling the API

here's an example of this history

 
Start date
November 23, 2021, 8:00 PM
 
End date
November 23, 2021, 11:00 PM
 
Entity
switch.router_filter_rule_1604272216_ha_interface_routevpn
November 23, 2021
Interface: Route NordVPN turned on
10:48:04 PM - 9 minutes ago
Interface: Route NordVPN became unavailable
10:47:28 PM - 10 minutes ago
Interface: Route NordVPN turned on
10:45:36 PM - 11 minutes ago
Interface: Route NordVPN became unavailable
10:45:00 PM - 12 minutes ago
Interface: Route NordVPN turned on
10:43:08 PM - 14 minutes ago
Interface: Route NordVPN became unavailable
10:42:33 PM - 15 minutes ago
Interface: Route NordVPN turned on
10:25:30 PM - 32 minutes ago
Interface: Route NordVPN became unavailable
10:24:52 PM - 32 minutes ago
Interface: Route NordVPN turned on
10:22:58 PM - 34 minutes ago
Interface: Route NordVPN became unavailable
10:22:21 PM - 35 minutes ago
Interface: Route NordVPN turned on
10:20:29 PM - 37 minutes ago
Interface: Route NordVPN became unavailable
10:19:53 PM - 37 minutes ago
Interface: Route NordVPN turned on
10:18:00 PM - 39 minutes ago
Interface: Route NordVPN became unavailable
10:17:24 PM - 40 minutes ago
Interface: Route NordVPN turned on
10:14:56 PM - 42 minutes ago
Interface: Route NordVPN became unavailable
10:14:18 PM - 43 minutes ago
Interface: Route NordVPN turned on
10:13:01 PM - 44 minutes ago
Interface: Route NordVPN became unavailable
10:12:25 PM - 45 minutes ago

Nov 24 '21 03:11 JOHLC

Ok I think what we need to do is observe the average time the coordinator takes to make the api calls while simultaneously starting to eliminate data points from the api requests to see what the biggest contributors are to the delay.

It may make some other stuff blow up but we’ll see. Start with commenting this: https://github.com/travisghansen/hass-pfsense/blob/main/custom_components/pfsense/init.py#L249

You will have a bunch of entities go unavailable but we need to narrow down what’s holding everything up.

Nov 24 '21 04:11 travisghansen

Will get to that as soon as possible thanks for your time and effort.

Nov 24 '21 04:11 JOHLC

I get pretty often in the log:

2021-11-24 10:33:38 ERROR (MainThread) [custom_components.pfsense] Timeout fetching Router pfSense state data
2021-11-24 10:35:26 ERROR (MainThread) [custom_components.pfsense] Timeout fetching Router pfSense state data

Don't know why it it's timing out. It's in the same subnet.

Nov 24 '21 10:11 nagyrobi

Hello, commenting out:

        else:
            #self._state["telemetry"] = self._get_telemetry()
            self._state["config"] = self._get_config()

Resulting in this error and everything except for firewall rules being unavailable:

2021-11-27 11:42:57 DEBUG (MainThread) [custom_components.pfsense] Finished fetching Router pfSense state data in 10.780 seconds (success: False)
2021-11-27 11:43:33 DEBUG (MainThread) [custom_components.pfsense] Finished fetching Router pfSense state data in 6.746 seconds (success: True)
2021-11-27 11:44:09 ERROR (MainThread) [custom_components.pfsense] Unexpected error fetching Router pfSense state data: 'telemetry'
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 187, in _async_refresh
    self.data = await self._async_update_data()
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 147, in _async_update_data
    return await self.update_method()
  File "/config/custom_components/pfsense/__init__.py", line 95, in async_update_data
    await hass.async_add_executor_job(lambda: data.update())
  File "/usr/local/lib/python3.9/concurrent/futures/thread.py", line 52, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/config/custom_components/pfsense/__init__.py", line 95, in <lambda>
    await hass.async_add_executor_job(lambda: data.update())
  File "/config/custom_components/pfsense/__init__.py", line 312, in update
    for interface_name in self._state["telemetry"]["interfaces"].keys():
KeyError: 'telemetry'

Nov 27 '21 18:11 JOHLC

Yeah not surprising. I’ll make that more robust and we’ll have you try again after updating.

Nov 27 '21 18:11 travisghansen

OK, in the most recent commit I've added 2 things:

more robust behavior when the data is missing
timing stats for the api calls

enable logging for the component like this:

logger:
  logs:
    custom_components.pfsense: debug

for each scan interval you will see several lines like this:

2021-12-18 20:10:33 DEBUG (SyncWorker_11) [custom_components.pfsense] execution time: PfSenseData._get_system_info 0.056604623794555664
2021-12-18 20:10:33 DEBUG (SyncWorker_11) [custom_components.pfsense] execution time: PfSenseData._get_host_firmware_version 0.028592348098754883
2021-12-18 20:10:33 DEBUG (SyncWorker_9) [custom_components.pfsense] execution time: PfSenseData._get_system_info 0.15544772148132324
2021-12-18 20:10:33 DEBUG (SyncWorker_9) [custom_components.pfsense] execution time: PfSenseData._get_host_firmware_version 0.09694743156433105
2021-12-18 20:10:33 DEBUG (SyncWorker_11) [custom_components.pfsense] execution time: PfSenseData._get_telemetry 0.18806672096252441
2021-12-18 20:10:33 DEBUG (SyncWorker_11) [custom_components.pfsense] execution time: PfSenseData._get_config 0.03267192840576172
2021-12-18 20:10:33 DEBUG (SyncWorker_11) [custom_components.pfsense] execution time: PfSenseData._get_interfaces 0.01718735694885254
2021-12-18 20:10:33 DEBUG (SyncWorker_9) [custom_components.pfsense] execution time: PfSenseData._get_telemetry 0.2670109272003174
2021-12-18 20:10:33 DEBUG (SyncWorker_9) [custom_components.pfsense] execution time: PfSenseData._get_config 0.09575271606445312
2021-12-18 20:10:33 DEBUG (SyncWorker_9) [custom_components.pfsense] execution time: PfSenseData._get_interfaces 0.11377286911010742
2021-12-18 20:10:33 DEBUG (SyncWorker_11) [custom_components.pfsense] execution time: PfSenseData._get_services 0.373457670211792
2021-12-18 20:10:33 DEBUG (SyncWorker_11) [custom_components.pfsense] execution time: PfSenseData._get_carp_interfaces 0.013755559921264648
2021-12-18 20:10:33 DEBUG (SyncWorker_11) [custom_components.pfsense] execution time: PfSenseData._get_carp_status 0.01616644859313965

The purpose of this data is to watch it over time and get a general sense of which methods are taking the most time. After we have some sense of that, we'll dig deeper into the biggest culprits to see what specific data within each of those requests is taking the most amount of time.

Dec 19 '21 03:12 travisghansen

Anyone have a chance to gather some stats they can share?

Also interested in who is accessing the api over ssl vs not and if that has any impact on the behavior?

Dec 29 '21 15:12 travisghansen

For anyone running device tracker and adguard we have seen issues with dns throttling in adguard which causes the api to stall. You may increase the limit in adguard or remove it altogether by setting it to 0.

Jan 04 '22 16:01 travisghansen

Which adguard are you referring to?

Jan 04 '22 18:01 nagyrobi

I was incorrect. I was thinking adguard was in pfsense as well but apparently not. I suppose anything that could be throttling dns request could cause issues with device tracker though. Not sure if any other pfsense packages provide similar functionality.

Jan 04 '22 19:01 travisghansen

Not sure if any other pfsense packages provide similar functionality.

I run pfblocker which provides dns filtering.

Haven't gotten around to collecting any data yet

Jan 04 '22 19:01 JOHLC

Ok thanks. I don’t think it will impact stuff if you don’t have device tracker turned on but that may not be entirely true. There could be something else doing dns lookups that are causing issues even in the non device tracker code paths.

Does pfblocker have dns throttling by chance?

Jan 04 '22 19:01 travisghansen

Why is using the device tracker any dns? Isn't it just parsing the ARP table for the configured MAC addresses?

Jan 04 '22 20:01 nagyrobi

There is an option to 'resolve hostnames' (in the api) which I have flagged as true by default. It makes it so when setting up the integration the list of available devices to track has the hostname for easy discovery and hostname is one of the attributes expected/supported by the ScannerEntity interface as well.

Jan 04 '22 20:01 travisghansen

I suggest to expose this as a configurable checkbox option, so that people can disable it.

Jan 04 '22 21:01 nagyrobi

I've considered it but want to keep configuration options at a minimum.

Jan 05 '22 18:01 travisghansen

Then maybe set it to false... Useless to keep it always on, as data is not kept in logs etc. for later reviewing or security audit. It's just for making stuff fancier I agree.

But one has to know the MAC address anyway, as smartphones use random MAC addresses by default these days - so one has to go to the smartphone's settings and manually select the real MAC instead, which is clearly displayed. Thus the user can easily identify which one to choose in the component...

Jan 05 '22 18:01 nagyrobi

Yeah, understood. Seeing hostname (at least during the setup phase) has already been explicitly called out by others as being helpful when selecting devices however. I'm not sure where I'll land on it but the input is appreciated.

There are general misconceptions about the mac randomization on smart phones. Smart phones (at least Apple, and relatively confident android does the same) do not randomize the mac for the same network. The blurb about it on an iPhone states:

Using a private address helps reduce tracking of your iPhone across different WiFi networks.

The average user on their home network will never have the mac change, unless they change the ssid of the AP. It's not to make you random on your own network, but rather to ensure as you jump around public hotspots etc that your device/activity cannot be correlated as you roam around.

None of the above voids your comment btw (except selecting the real address as I understand your comment isn't really necessary), but rather is shared in the vein of increasing understanding and shedding light on things to consider when setting up the feature for others who may land here.

Jan 05 '22 22:01 travisghansen

All true, thanks for clarification!

Jan 05 '22 22:01 nagyrobi

Seeing hostname (at least during the setup phase) has already been explicitly called out by others as being helpful when selecting devices however.

...as long as it doesn't have a negative impact on performace and resources consumption - since this is more or less still a cosmetic thing here...

Jan 05 '22 22:01 nagyrobi

kép It goes unavailable on a regular basis exactly every 3 hours and also when PPPoE WAN disconnects and reconnects (this doesn't happen every 3 hours though). Visiting pfSense's web interface is also slower at login while WAN is down. Must me related to some reverse DNS lookup...

Jan 21 '22 15:01 nagyrobi

So could be unrelated to the integration entirely and just the api/firewall is going unavailable generally due to outside reasons?

Jan 25 '22 03:01 travisghansen

Not sure what outside reasons...

Jan 25 '22 07:01 nagyrobi

I also seems to experience this problem, all entities goes offline for 30sec if trying to enable/disable a rule. Also the command never seems to get changed in the pfSense (firewall rule)

Home Assistant 2021-12-04
pfSense 2.5.2,

5 VLAN

Arpwatch

Suricata

Pimd

Avahi

HTTPS

Source: custom_components/pfsense/pypfsense/__init__.py:73
Integration: pfSense (documentation, issues)
First occurred: 01:00:38 (2 occurrences)
Last logged: 01:01:59

Error executing service: <ServiceCall switch.turn_on (c:01c3c2693abff439d080fb6fc6037f0c): entity_id=['switch.pfsense_nat_port_forward_rule_1611410311_openvpn']>
Error executing service: <ServiceCall switch.turn_off (c:760ff5a4989583bef4ae61ee2e524553): entity_id=['switch.pfsense_nat_port_forward_rule_1611410311_openvpn']>
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/core.py", line 1511, in catch_exceptions
    await coro_or_task
  File "/usr/src/homeassistant/homeassistant/core.py", line 1530, in _execute_service
    await handler.job.target(service_call)
  File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 209, in handle_service
    await self.hass.helpers.service.entity_service_call(
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 663, in entity_service_call
    future.result()  # pop exception if have
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 896, in async_request_call
    await coro
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 700, in _handle_entity_call
    await result
  File "/config/custom_components/pfsense/switch.py", line 326, in async_turn_on
    await self.hass.async_add_executor_job(method, tracker)
  File "/usr/local/lib/python3.9/concurrent/futures/thread.py", line 52, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/config/custom_components/pfsense/pypfsense/__init__.py", line 212, in enable_nat_port_forward_rule_by_created_time
    self._restore_config_section("nat", config["nat"])
  File "/config/custom_components/pfsense/pypfsense/__init__.py", line 58, in inner
    response = func(*args, **kwargs)
  File "/config/custom_components/pfsense/pypfsense/__init__.py", line 73, in _restore_config_section
    response = self._get_proxy().pfsense.restore_config_section(params, 60)
  File "/usr/local/lib/python3.9/xmlrpc/client.py", line 1116, in __call__
    return self.__send(self.__name, args)
  File "/usr/local/lib/python3.9/xmlrpc/client.py", line 1458, in __request
    response = self.__transport.request(
  File "/usr/local/lib/python3.9/xmlrpc/client.py", line 1160, in request
    return self.single_request(host, handler, request_body, verbose)
  File "/usr/local/lib/python3.9/xmlrpc/client.py", line 1173, in single_request
    resp = http_conn.getresponse()
  File "/usr/local/lib/python3.9/http/client.py", line 1371, in getresponse
    response.begin()
  File "/usr/local/lib/python3.9/http/client.py", line 319, in begin
    version, status, reason = self._read_status()
  File "/usr/local/lib/python3.9/http/client.py", line 280, in _read_status
    line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1")
  File "/usr/local/lib/python3.9/socket.py", line 704, in readinto
    return self._sock.recv_into(b)
  File "/usr/local/lib/python3.9/ssl.py", line 1241, in recv_into
    return self.read(nbytes, buffer)
  File "/usr/local/lib/python3.9/ssl.py", line 1099, in read
    return self._sslobj.read(len, buffer)
socket.timeout: The read operation timed out```

Jan 29 '22 00:01 PerJarlemark

I'm curious what's causing this to happen. I'm curious if the integration is simply exposing some of these issues vs causing the issues. Perhaps someone can disable the integration altogether and setup a distinct process to monitor the availability of the login page or something (not just icmp, but actually invoking some sort of http request to the router).

Also of note, particularly in the case of failure when invoking a toggle switch or some sort of update action, is that the auto config backup (or similar) could be kicking in and causing issues.

As I don't experience these issues it's obviously hard to debug so I appreciate everyone's efforts to provide feedback!

Jan 29 '22 02:01 travisghansen

Not sure what is happening here, but the first 24h after installing hass-pfsense I had the issue constantly, I saw your comment about auto config backup, and since I use that I thought I would try disabling it but actually today everything is working flawless before I had the chance to try. Unless the integration was doing stuff during first hours after a new install I´m leaning towards your idea that I had some issue with pfSense but can´t say I have seen any problem before. So right now my installation is working, will let you know if it changes

Jan 29 '22 23:01 PerJarlemark

hi all - so - im still experience this issue - but i installed it a few hours ago - i still see disconnects but have increased the init.py timeout to 30 - im having a medium/pretty complex setup with vlans/etc etc - but the connection HA <> pfsense == without fw rules.

If i keep experiencing issues - which logging is helpfull ?

Mar 04 '22 14:03 poweredgenl

I'm not sure if what I'm seeing is the same issue, but it seems to be. If it isn't, I'll apologize right now ;)

Anyway, what I'm seeing is that with an interval of exactly 2 hours (give or take a few second) all the entities I've checked become unavailable for 33s and then they go back to their correct value. This seems to happen throughout the day, so also at night and thus is unrelated to me changing stuff in pfSense (which I don't do a lot anyway).

I'll try to answer some of the questions asked before:

Do you have an unusually complex pfSense install? -> About 10 VLANS with various firewall rules, a recursive DNS, acme and HAProxy, but that's about it. I have no IDS or stuff like that
Are you accessing it over a wan? -> No, but I do use an URL that passes through HAProxy so I have a valid SSL certificate
Perhaps someone can disable the integration altogether and setup a distinct process to monitor the availability of the login page or something (not just icmp, but actually invoking some sort of http request to the router). -> I didn't see anyone commenting on this, so I'll try to do this

I've just enabled the debug logging for that stat logging.

If there is any additional info you require, or want me to test something out, please let me know.

Jul 06 '22 10:07 bscheutjens

I already have an update on monitoring pfSense. It wasn't too much work, I created a small application that loads the login page (using the same URL as filled in at the integration) every 5 seconds and logs the time it needed and logs errors and any http status other than Ok.

I finished it just minutes before the next "2 hour mark" and decided to run the monitor alongside the integration to see if the monitoring would show any change when the entities would go to unavailable. However, when they all became unavailable the monitor just kept running without errors and the timing was within the same range as when the entities were ok.

So, unless you'd like me to keep running this test or test a specific page or something, I guess this test provided the info you were looking for.

I forgot one thing on my configuration, so I don't have that debug logging yet with the statistics. I'll check again when it happens again.

Edit: I saw the statistics are always logged, so hereby the first two loggings since the latest restart of HA:

2022-07-06 13:54:02 DEBUG (SyncWorker_1) [custom_components.pfsense] execution time: PfSenseData._get_system_info 0.181
2022-07-06 13:54:03 DEBUG (SyncWorker_1) [custom_components.pfsense] execution time: PfSenseData._get_host_firmware_version 0.223
2022-07-06 13:54:03 DEBUG (SyncWorker_1) [custom_components.pfsense] execution time: PfSenseData._get_firmware_update_info 0.313
2022-07-06 13:54:03 DEBUG (SyncWorker_1) [custom_components.pfsense] execution time: PfSenseData._get_telemetry 0.424
2022-07-06 13:54:04 DEBUG (SyncWorker_1) [custom_components.pfsense] execution time: PfSenseData._get_config 0.585
2022-07-06 13:54:04 DEBUG (SyncWorker_1) [custom_components.pfsense] execution time: PfSenseData._get_interfaces 0.196
2022-07-06 13:54:05 DEBUG (SyncWorker_1) [custom_components.pfsense] execution time: PfSenseData._get_services 1.28
2022-07-06 13:54:06 DEBUG (SyncWorker_1) [custom_components.pfsense] execution time: PfSenseData._get_carp_interfaces 0.176
2022-07-06 13:54:06 DEBUG (SyncWorker_1) [custom_components.pfsense] execution time: PfSenseData._get_carp_status 0.174
2022-07-06 13:54:06 DEBUG (SyncWorker_1) [custom_components.pfsense] execution time: PfSenseData._get_dhcp_leases 0.331
2022-07-06 13:54:06 DEBUG (SyncWorker_1) [custom_components.pfsense] execution time: PfSenseData._are_notices_pending 0.149
2022-07-06 13:54:07 DEBUG (SyncWorker_1) [custom_components.pfsense] execution time: PfSenseData._get_notices 0.657
2022-07-06 13:54:09 DEBUG (MainThread) [custom_components.pfsense] Finished fetching pfSense pfSense state data in 6.407 seconds (success: True)
2022-07-06 13:54:39 DEBUG (SyncWorker_3) [custom_components.pfsense] execution time: PfSenseData._get_system_info 0.176
2022-07-06 13:54:39 DEBUG (SyncWorker_3) [custom_components.pfsense] execution time: PfSenseData._get_host_firmware_version 0.14
2022-07-06 13:54:39 DEBUG (SyncWorker_3) [custom_components.pfsense] execution time: PfSenseData._get_firmware_update_info 0.308
2022-07-06 13:54:40 DEBUG (SyncWorker_3) [custom_components.pfsense] execution time: PfSenseData._get_telemetry 0.407
2022-07-06 13:54:40 DEBUG (SyncWorker_3) [custom_components.pfsense] execution time: PfSenseData._get_config 0.158
2022-07-06 13:54:40 DEBUG (SyncWorker_3) [custom_components.pfsense] execution time: PfSenseData._get_interfaces 0.14
2022-07-06 13:54:41 DEBUG (SyncWorker_3) [custom_components.pfsense] execution time: PfSenseData._get_services 1.017
2022-07-06 13:54:41 DEBUG (SyncWorker_3) [custom_components.pfsense] execution time: PfSenseData._get_carp_interfaces 0.141
2022-07-06 13:54:41 DEBUG (SyncWorker_3) [custom_components.pfsense] execution time: PfSenseData._get_carp_status 0.141
2022-07-06 13:54:41 DEBUG (SyncWorker_3) [custom_components.pfsense] execution time: PfSenseData._get_dhcp_leases 0.187
2022-07-06 13:54:41 DEBUG (SyncWorker_3) [custom_components.pfsense] execution time: PfSenseData._are_notices_pending 0.139
2022-07-06 13:54:42 DEBUG (SyncWorker_3) [custom_components.pfsense] execution time: PfSenseData._get_notices 0.139
2022-07-06 13:54:42 DEBUG (MainThread) [custom_components.pfsense] Finished fetching pfSense pfSense state data in 3.112 seconds (success: True)

The first one takes a bit of time, but that isn't very uncommon. After that, most of the pollings take about 3 seconds, although there is one that takes about 4 seconds:

2022-07-06 14:04:00 DEBUG (SyncWorker_2) [custom_components.pfsense] execution time: PfSenseData._get_system_info 0.181
2022-07-06 14:04:00 DEBUG (SyncWorker_2) [custom_components.pfsense] execution time: PfSenseData._get_host_firmware_version 0.142
2022-07-06 14:04:00 DEBUG (SyncWorker_2) [custom_components.pfsense] execution time: PfSenseData._get_firmware_update_info 0.305
2022-07-06 14:04:02 DEBUG (SyncWorker_2) [custom_components.pfsense] execution time: PfSenseData._get_telemetry 1.456
2022-07-06 14:04:02 DEBUG (SyncWorker_2) [custom_components.pfsense] execution time: PfSenseData._get_config 0.155
2022-07-06 14:04:02 DEBUG (SyncWorker_2) [custom_components.pfsense] execution time: PfSenseData._get_interfaces 0.14
2022-07-06 14:04:03 DEBUG (SyncWorker_2) [custom_components.pfsense] execution time: PfSenseData._get_services 1.017
2022-07-06 14:04:03 DEBUG (SyncWorker_2) [custom_components.pfsense] execution time: PfSenseData._get_carp_interfaces 0.138
2022-07-06 14:04:03 DEBUG (SyncWorker_2) [custom_components.pfsense] execution time: PfSenseData._get_carp_status 0.14
2022-07-06 14:04:03 DEBUG (SyncWorker_2) [custom_components.pfsense] execution time: PfSenseData._get_dhcp_leases 0.182
2022-07-06 14:04:04 DEBUG (SyncWorker_2) [custom_components.pfsense] execution time: PfSenseData._are_notices_pending 0.14
2022-07-06 14:04:04 DEBUG (SyncWorker_2) [custom_components.pfsense] execution time: PfSenseData._get_notices 0.139
2022-07-06 14:04:04 DEBUG (MainThread) [custom_components.pfsense] Finished fetching pfSense pfSense state data in 4.189 seconds (success: True)

Jul 06 '22 11:07 bscheutjens

What do the similar logs show during the outages? Do specific operations take longer? Do they just all fail? Etc

Jul 06 '22 13:07 travisghansen

What do the similar logs show during the outages? Do specific operations take longer? Do they just all fail? Etc

I wanted to make the joke "I'll let you know in 30 minutes". However, we are now about 15 minutes past the "2 hour mark" and everything is still ok. Strange, very strange.

Around the time it should have happened the only thing that stands out it that the time went up from about 3 second to about 5 seconds:

2022-07-06 15:39:58 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._get_system_info 0.176
2022-07-06 15:39:58 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._get_host_firmware_version 0.142
2022-07-06 15:39:58 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._get_firmware_update_info 0.31
2022-07-06 15:39:59 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._get_telemetry 0.41
2022-07-06 15:39:59 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._get_config 0.155
2022-07-06 15:39:59 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._get_interfaces 0.141
2022-07-06 15:40:00 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._get_services 1.142
2022-07-06 15:40:00 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._get_carp_interfaces 0.139
2022-07-06 15:40:02 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._get_carp_status 1.896
2022-07-06 15:40:02 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._get_dhcp_leases 0.244
2022-07-06 15:40:02 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._are_notices_pending 0.14
2022-07-06 15:40:03 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._get_notices 0.155
2022-07-06 15:40:03 DEBUG (MainThread) [custom_components.pfsense] Finished fetching pfSense pfSense state data in 5.098 seconds (success: True)

But it isn't that strange, I've looked through the logging and that has happened a few times. I'll keep an eye on it and if it happens again I'll post the logging.

Jul 06 '22 13:07 bscheutjens

My guess is this will continue to be elusive unfortunately. My assumption at this point is that something is going on outside the 'control' of the integration that's causing the delays. Something like:

bogon network refresh process
throttling kicking in (adguard dns, others)
some sort of cache being busted (ie: arp, etc)
firewall tarpit

Given that the login page remained available it probably eliminates some of the possibilities and likely points to something being 'triggered' by the commands invoked by the integration itself.

Probably the only way to figure out what exactly is triggering the issue is to find someone comfortable enough with coding that can start hacking the integration and selectively start removing the individual calls to determine which api request is the culprit. Once the problem api call is discovered (assuming it is associated with a specific call) then determining the real problem will likely be much easier.

If nobody has the means/interest for that I'm happy to point my own code to a server someone could expose and run some tests from own development environment. I get that's quite invasive but not sure how else I can help :(

Jul 06 '22 14:07 travisghansen

It just happened, not sure why that 2 hour changed, but ok. This is my full logging of when it happened. I'm not sure if that iaohttp is part of the integration or just a coincidence.

2022-07-06 16:30:05 DEBUG (SyncWorker_1) [custom_components.pfsense] execution time: PfSenseData._get_system_info 0.187
2022-07-06 16:30:05 DEBUG (SyncWorker_1) [custom_components.pfsense] execution time: PfSenseData._get_host_firmware_version 0.142
2022-07-06 16:30:15 ERROR (MainThread) [custom_components.pfsense] Timeout fetching pfSense pfSense state data
2022-07-06 16:30:15 DEBUG (MainThread) [custom_components.pfsense] Finished fetching pfSense pfSense state data in 10.009 seconds (success: False)
2022-07-06 16:30:15 DEBUG (SyncWorker_1) [custom_components.pfsense] execution time: PfSenseData._get_firmware_update_info 9.911
2022-07-06 16:30:15 DEBUG (SyncWorker_1) [custom_components.pfsense] execution time: PfSenseData._get_telemetry 0.405
2022-07-06 16:30:15 DEBUG (SyncWorker_1) [custom_components.pfsense] execution time: PfSenseData._get_config 0.154
2022-07-06 16:30:15 DEBUG (SyncWorker_1) [custom_components.pfsense] execution time: PfSenseData._get_interfaces 0.14
2022-07-06 16:30:16 DEBUG (SyncWorker_1) [custom_components.pfsense] execution time: PfSenseData._get_services 1.011
2022-07-06 16:30:17 DEBUG (SyncWorker_1) [custom_components.pfsense] execution time: PfSenseData._get_carp_interfaces 0.138
2022-07-06 16:30:17 DEBUG (SyncWorker_1) [custom_components.pfsense] execution time: PfSenseData._get_carp_status 0.141
2022-07-06 16:30:17 DEBUG (SyncWorker_1) [custom_components.pfsense] execution time: PfSenseData._get_dhcp_leases 0.182
2022-07-06 16:30:17 DEBUG (SyncWorker_1) [custom_components.pfsense] execution time: PfSenseData._are_notices_pending 0.139
2022-07-06 16:30:17 DEBUG (SyncWorker_1) [custom_components.pfsense] execution time: PfSenseData._get_notices 0.138
2022-07-06 16:30:45 DEBUG (SyncWorker_5) [custom_components.pfsense] execution time: PfSenseData._get_system_info 0.177
2022-07-06 16:30:45 DEBUG (SyncWorker_5) [custom_components.pfsense] execution time: PfSenseData._get_host_firmware_version 0.138
2022-07-06 16:30:45 DEBUG (SyncWorker_5) [custom_components.pfsense] execution time: PfSenseData._get_firmware_update_info 0.304
2022-07-06 16:30:46 DEBUG (SyncWorker_5) [custom_components.pfsense] execution time: PfSenseData._get_telemetry 0.407
2022-07-06 16:30:46 DEBUG (SyncWorker_5) [custom_components.pfsense] execution time: PfSenseData._get_config 0.154
2022-07-06 16:30:46 DEBUG (SyncWorker_5) [custom_components.pfsense] execution time: PfSenseData._get_interfaces 0.14
2022-07-06 16:30:47 DEBUG (SyncWorker_5) [custom_components.pfsense] execution time: PfSenseData._get_services 1.008
2022-07-06 16:30:47 DEBUG (SyncWorker_5) [custom_components.pfsense] execution time: PfSenseData._get_carp_interfaces 0.14
2022-07-06 16:30:47 DEBUG (SyncWorker_5) [custom_components.pfsense] execution time: PfSenseData._get_carp_status 0.141
2022-07-06 16:30:47 DEBUG (SyncWorker_5) [custom_components.pfsense] execution time: PfSenseData._get_dhcp_leases 0.184
2022-07-06 16:30:47 DEBUG (SyncWorker_5) [custom_components.pfsense] execution time: PfSenseData._are_notices_pending 0.139
2022-07-06 16:30:48 DEBUG (SyncWorker_5) [custom_components.pfsense] execution time: PfSenseData._get_notices 0.138
2022-07-06 16:30:48 INFO (MainThread) [custom_components.pfsense] Fetching pfSense pfSense state data recovered
2022-07-06 16:30:48 DEBUG (MainThread) [custom_components.pfsense] Finished fetching pfSense pfSense state data in 3.129 seconds (success: True)
2022-07-06 16:31:16 ERROR (MainThread) [aiohttp.server] Error handling request
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/aiohttp/web_protocol.py", line 334, in data_received
    messages, upgraded, tail = self._request_parser.feed_data(data)
  File "aiohttp/_http_parser.pyx", line 551, in aiohttp._http_parser.HttpParser.feed_data
aiohttp.http_exceptions.BadStatusLine: 400, message="Bad status line 'Invalid method encountered'"
2022-07-06 16:31:18 DEBUG (SyncWorker_7) [custom_components.pfsense] execution time: PfSenseData._get_system_info 0.175
2022-07-06 16:31:18 DEBUG (SyncWorker_7) [custom_components.pfsense] execution time: PfSenseData._get_host_firmware_version 0.139
2022-07-06 16:31:18 DEBUG (SyncWorker_7) [custom_components.pfsense] execution time: PfSenseData._get_firmware_update_info 0.306
2022-07-06 16:31:19 DEBUG (SyncWorker_7) [custom_components.pfsense] execution time: PfSenseData._get_telemetry 0.406
2022-07-06 16:31:19 DEBUG (SyncWorker_7) [custom_components.pfsense] execution time: PfSenseData._get_config 0.155
2022-07-06 16:31:19 DEBUG (SyncWorker_7) [custom_components.pfsense] execution time: PfSenseData._get_interfaces 0.141
2022-07-06 16:31:20 DEBUG (SyncWorker_7) [custom_components.pfsense] execution time: PfSenseData._get_services 1.017
2022-07-06 16:31:20 ERROR (MainThread) [aiohttp.server] Error handling request
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/aiohttp/web_protocol.py", line 334, in data_received
    messages, upgraded, tail = self._request_parser.feed_data(data)
  File "aiohttp/_http_parser.pyx", line 551, in aiohttp._http_parser.HttpParser.feed_data
aiohttp.http_exceptions.BadStatusLine: 400, message="Bad status line 'Invalid method encountered'"
2022-07-06 16:31:20 DEBUG (SyncWorker_7) [custom_components.pfsense] execution time: PfSenseData._get_carp_interfaces 0.138
2022-07-06 16:31:20 DEBUG (SyncWorker_7) [custom_components.pfsense] execution time: PfSenseData._get_carp_status 0.14
2022-07-06 16:31:20 DEBUG (SyncWorker_7) [custom_components.pfsense] execution time: PfSenseData._get_dhcp_leases 0.182
2022-07-06 16:31:20 DEBUG (SyncWorker_7) [custom_components.pfsense] execution time: PfSenseData._are_notices_pending 0.138
2022-07-06 16:31:21 DEBUG (SyncWorker_7) [custom_components.pfsense] execution time: PfSenseData._get_notices 0.138
2022-07-06 16:31:21 DEBUG (MainThread) [custom_components.pfsense] Finished fetching pfSense pfSense state data in 3.113 seconds (success: True)

Jul 06 '22 14:07 bscheutjens

Ha! Not sure if this is the same issue for everyone else, but your issue is likely connected to this:

    def get_firmware_update_info(self):
        """
        # the cache is 2 hours
        get_system_pkg_version($baseonly = false, $use_cache = true)

Basically when checking the latest firmware data pfSense itself caches the data for 2 hours, so that's likely the cause.

2022-07-06 16:30:15 DEBUG (SyncWorker_1) [custom_components.pfsense] execution time: PfSenseData._get_firmware_update_info 9.911

That took 9 seconds (way more than any of the others) ^ which means when trying to collect that data pfSense likely updated the repo metadata/etc behind the scenes (due to the cache expiring). It may be possible to background that refresh by reworking how the integration gathers and uses the info.

Jul 06 '22 14:07 travisghansen

Probably the only way to figure out what exactly is triggering the issue is to find someone comfortable enough with coding that can start hacking the integration and selectively start removing the individual calls to determine which api request is the culprit. Once the problem api call is discovered (assuming it is associated with a specific call) then determining the real problem will likely be much easier.

I'm a software developer myself, so reading code written in whatever language and understanding the global working isn't an issue for me. However, I don't have any experience with python (or any comparable language), so changing code is a different story. If you could explain me a bit about your code and what I should do to make those changes, I'm willing to give it a try.

Jul 06 '22 14:07 bscheutjens

Basically when checking the latest firmware data pfSense itself caches the data for 2 hours, so that's likely the cause.

And that might explain the shift of the two hours. I logged into pfSense and manually searched for updates.

Jul 06 '22 14:07 bscheutjens

OK, just implemented backgrounding logic in v0.5.1. Give it a try.

Jul 06 '22 16:07 travisghansen

After updating to 0.5.1 and restarting HA I get the following errors:

This error originated from a custom integration.

Logger: homeassistant.loader
Source: custom_components/pfsense/update.py:107
Integration: pfSense (documentation, issues)
First occurred: 18:42:26 (1 occurrences)
Last logged: 18:42:26

Unexpected exception importing platform custom_components.pfsense.update
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/loader.py", line 618, in get_platform
    cache[full_name] = self._import_platform(platform_name)
  File "/usr/src/homeassistant/homeassistant/loader.py", line 635, in _import_platform
    return importlib.import_module(f"{self.pkg_path}.{platform_name}")
  File "/usr/local/lib/python3.9/importlib/__init__.py", line 127, in import_module
    return _bootstrap._gcd_import(name[level:], package, level)
  File "<frozen importlib._bootstrap>", line 1030, in _gcd_import
  File "<frozen importlib._bootstrap>", line 1007, in _find_and_load
  File "<frozen importlib._bootstrap>", line 986, in _find_and_load_unlocked
  File "<frozen importlib._bootstrap>", line 680, in _load_unlocked
  File "<frozen importlib._bootstrap_external>", line 850, in exec_module
  File "<frozen importlib._bootstrap>", line 228, in _call_with_frames_removed
  File "/config/custom_components/pfsense/update.py", line 93, in <module>
    class PfSenseFirmwareUpdatesAvailableUpdate(PfSenseUpdate):
  File "/config/custom_components/pfsense/update.py", line 107, in PfSenseFirmwareUpdatesAvailableUpdate
    def installed_version(self) -> str | None:
TypeError: unsupported operand type(s) for |: 'type' and 'NoneType'

and:

Logger: homeassistant.setup
Source: setup.py:298
First occurred: 18:42:26 (1 occurrences)
Last logged: 18:42:26

Unable to prepare setup for platform pfsense.update: Platform not found (Exception importing custom_components.pfsense.update).

Jul 06 '22 16:07 bscheutjens

What version of hass are you running? The integration now requires 2022.04+ now..

Jul 06 '22 16:07 travisghansen

I'm running the latest versions:

Home Assistant Core 2022.6.7 Home Assistant Supervisor 2022.06.2 Home Assistant OS 8.2

Jul 06 '22 16:07 bscheutjens

Ow, by the way. I was using 0.4.1 before updating to 0.5.1, so this could be a 0.5.0 issue. And despite the errors, the integration does seem to work

Jul 06 '22 17:07 bscheutjens

Yeah, do you have a fancy new update entity? It replaces the binary sensor previously used and integrates with hass so you can trigger firmware updates right from the hass ui..

Jul 06 '22 17:07 travisghansen

The issue is partly solved. I can see in the logging what you tried to do, but it didn't solve the problem. The logging:

2022-07-06 19:16:02 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._get_system_info 0.177
2022-07-06 19:16:02 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._get_host_firmware_version 0.143
2022-07-06 19:16:02 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._get_firmware_update_info 0.0
2022-07-06 19:16:12 ERROR (MainThread) [custom_components.pfsense] Timeout fetching pfSense pfSense state data
2022-07-06 19:16:12 DEBUG (MainThread) [custom_components.pfsense] Finished fetching pfSense pfSense state data in 10.001 seconds (success: False)
2022-07-06 19:16:12 DEBUG (SyncWorker_2) [custom_components.pfsense] execution time: PfSenseData._refresh_firmware_update_info 10.016

2022-07-06 19:16:42 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._get_system_info 0.175
2022-07-06 19:16:42 DEBUG (SyncWorker_1) [custom_components.pfsense] execution time: PfSenseData._refresh_firmware_update_info 0.314
2022-07-06 19:16:42 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._get_host_firmware_version 0.441
2022-07-06 19:16:42 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._get_firmware_update_info 0.0
2022-07-06 19:16:43 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._get_telemetry 0.402
2022-07-06 19:16:43 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._get_config 0.154
2022-07-06 19:16:43 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._get_interfaces 0.14
2022-07-06 19:16:44 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._get_services 1.012
2022-07-06 19:16:44 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._get_carp_interfaces 0.14
2022-07-06 19:16:44 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._get_carp_status 0.141
2022-07-06 19:16:44 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._get_dhcp_leases 0.181
2022-07-06 19:16:44 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._are_notices_pending 0.139
2022-07-06 19:16:45 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._get_notices 0.14
2022-07-06 19:16:45 INFO (MainThread) [custom_components.pfsense] Fetching pfSense pfSense state data recovered
2022-07-06 19:16:45 DEBUG (MainThread) [custom_components.pfsense] Finished fetching pfSense pfSense state data in 3.105 seconds (success: True)

Jul 06 '22 17:07 bscheutjens

Yeah, do you have a fancy new update entity? It replaces the binary sensor previously used and integrates with hass so you can trigger firmware updates right from the hass ui..

It looks like I only have the old binary sensor (is now unavailable), but not a pfSense update entity.

Jul 06 '22 17:07 bscheutjens

Can you send more lines preceding the fetch that failed?

Jul 06 '22 17:07 travisghansen

Can you send more lines preceding the fetch that failed?

These are the four before the one that failed and the one that failed. I noticed that the line "refresh firmware update" sometimes is the second call and sometimes the fourth call.

2022-07-06 19:13:50 DEBUG (SyncWorker_2) [custom_components.pfsense] execution time: PfSenseData._get_system_info 0.175
2022-07-06 19:13:50 DEBUG (SyncWorker_4) [custom_components.pfsense] execution time: PfSenseData._refresh_firmware_update_info 0.309
2022-07-06 19:13:50 DEBUG (SyncWorker_2) [custom_components.pfsense] execution time: PfSenseData._get_host_firmware_version 0.436
2022-07-06 19:13:50 DEBUG (SyncWorker_2) [custom_components.pfsense] execution time: PfSenseData._get_firmware_update_info 0.0
2022-07-06 19:13:51 DEBUG (SyncWorker_2) [custom_components.pfsense] execution time: PfSenseData._get_telemetry 0.403
2022-07-06 19:13:51 DEBUG (SyncWorker_2) [custom_components.pfsense] execution time: PfSenseData._get_config 0.155
2022-07-06 19:13:51 DEBUG (SyncWorker_2) [custom_components.pfsense] execution time: PfSenseData._get_interfaces 0.141
2022-07-06 19:13:52 DEBUG (SyncWorker_2) [custom_components.pfsense] execution time: PfSenseData._get_services 1.018
2022-07-06 19:13:52 DEBUG (SyncWorker_2) [custom_components.pfsense] execution time: PfSenseData._get_carp_interfaces 0.143
2022-07-06 19:13:52 DEBUG (SyncWorker_2) [custom_components.pfsense] execution time: PfSenseData._get_carp_status 0.144
2022-07-06 19:13:52 DEBUG (SyncWorker_2) [custom_components.pfsense] execution time: PfSenseData._get_dhcp_leases 0.185
2022-07-06 19:13:52 DEBUG (SyncWorker_2) [custom_components.pfsense] execution time: PfSenseData._are_notices_pending 0.139
2022-07-06 19:13:53 DEBUG (SyncWorker_2) [custom_components.pfsense] execution time: PfSenseData._get_notices 0.14
2022-07-06 19:13:53 DEBUG (MainThread) [custom_components.pfsense] Finished fetching pfSense pfSense state data in 3.115 seconds (success: True)

2022-07-06 19:14:23 DEBUG (SyncWorker_2) [custom_components.pfsense] execution time: PfSenseData._get_system_info 0.175
2022-07-06 19:14:23 DEBUG (SyncWorker_2) [custom_components.pfsense] execution time: PfSenseData._get_host_firmware_version 0.142
2022-07-06 19:14:23 DEBUG (SyncWorker_2) [custom_components.pfsense] execution time: PfSenseData._get_firmware_update_info 0.0
2022-07-06 19:14:23 DEBUG (SyncWorker_3) [custom_components.pfsense] execution time: PfSenseData._refresh_firmware_update_info 0.441
2022-07-06 19:14:24 DEBUG (SyncWorker_2) [custom_components.pfsense] execution time: PfSenseData._get_telemetry 0.687
2022-07-06 19:14:24 DEBUG (SyncWorker_2) [custom_components.pfsense] execution time: PfSenseData._get_config 0.154
2022-07-06 19:14:24 DEBUG (SyncWorker_2) [custom_components.pfsense] execution time: PfSenseData._get_interfaces 0.141
2022-07-06 19:14:25 DEBUG (SyncWorker_2) [custom_components.pfsense] execution time: PfSenseData._get_services 1.017
2022-07-06 19:14:25 DEBUG (SyncWorker_2) [custom_components.pfsense] execution time: PfSenseData._get_carp_interfaces 0.142
2022-07-06 19:14:25 DEBUG (SyncWorker_2) [custom_components.pfsense] execution time: PfSenseData._get_carp_status 0.143
2022-07-06 19:14:25 DEBUG (SyncWorker_2) [custom_components.pfsense] execution time: PfSenseData._get_dhcp_leases 0.183
2022-07-06 19:14:25 DEBUG (SyncWorker_2) [custom_components.pfsense] execution time: PfSenseData._are_notices_pending 0.139
2022-07-06 19:14:26 DEBUG (SyncWorker_2) [custom_components.pfsense] execution time: PfSenseData._get_notices 0.14
2022-07-06 19:14:26 DEBUG (MainThread) [custom_components.pfsense] Finished fetching pfSense pfSense state data in 3.101 seconds (success: True)

2022-07-06 19:14:56 DEBUG (SyncWorker_1) [custom_components.pfsense] execution time: PfSenseData._get_system_info 0.175
2022-07-06 19:14:56 DEBUG (SyncWorker_1) [custom_components.pfsense] execution time: PfSenseData._get_host_firmware_version 0.142
2022-07-06 19:14:56 DEBUG (SyncWorker_1) [custom_components.pfsense] execution time: PfSenseData._get_firmware_update_info 0.0
2022-07-06 19:14:56 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._refresh_firmware_update_info 0.439
2022-07-06 19:14:57 DEBUG (SyncWorker_1) [custom_components.pfsense] execution time: PfSenseData._get_telemetry 0.69
2022-07-06 19:14:57 DEBUG (SyncWorker_1) [custom_components.pfsense] execution time: PfSenseData._get_config 0.155
2022-07-06 19:14:57 DEBUG (SyncWorker_1) [custom_components.pfsense] execution time: PfSenseData._get_interfaces 0.14
2022-07-06 19:14:58 DEBUG (SyncWorker_1) [custom_components.pfsense] execution time: PfSenseData._get_services 1.014
2022-07-06 19:14:58 DEBUG (SyncWorker_1) [custom_components.pfsense] execution time: PfSenseData._get_carp_interfaces 0.139
2022-07-06 19:14:58 DEBUG (SyncWorker_1) [custom_components.pfsense] execution time: PfSenseData._get_carp_status 0.141
2022-07-06 19:14:58 DEBUG (SyncWorker_1) [custom_components.pfsense] execution time: PfSenseData._get_dhcp_leases 0.184
2022-07-06 19:14:58 DEBUG (SyncWorker_1) [custom_components.pfsense] execution time: PfSenseData._are_notices_pending 0.139
2022-07-06 19:14:59 DEBUG (SyncWorker_1) [custom_components.pfsense] execution time: PfSenseData._get_notices 0.139
2022-07-06 19:14:59 DEBUG (MainThread) [custom_components.pfsense] Finished fetching pfSense pfSense state data in 3.095 seconds (success: True)

2022-07-06 19:15:29 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._get_system_info 0.176
2022-07-06 19:15:29 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._get_host_firmware_version 0.143
2022-07-06 19:15:29 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._get_firmware_update_info 0.0
2022-07-06 19:15:29 DEBUG (SyncWorker_5) [custom_components.pfsense] execution time: PfSenseData._refresh_firmware_update_info 0.443
2022-07-06 19:15:30 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._get_telemetry 0.692
2022-07-06 19:15:30 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._get_config 0.155
2022-07-06 19:15:30 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._get_interfaces 0.141
2022-07-06 19:15:31 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._get_services 1.016
2022-07-06 19:15:31 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._get_carp_interfaces 0.139
2022-07-06 19:15:31 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._get_carp_status 0.14
2022-07-06 19:15:31 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._get_dhcp_leases 0.183
2022-07-06 19:15:31 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._are_notices_pending 0.138
2022-07-06 19:15:32 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._get_notices 0.139
2022-07-06 19:15:32 DEBUG (MainThread) [custom_components.pfsense] Finished fetching pfSense pfSense state data in 3.104 seconds (success: True)

2022-07-06 19:16:02 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._get_system_info 0.177
2022-07-06 19:16:02 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._get_host_firmware_version 0.143
2022-07-06 19:16:02 DEBUG (SyncWorker_6) [custom_components.pfsense] execution time: PfSenseData._get_firmware_update_info 0.0
2022-07-06 19:16:12 ERROR (MainThread) [custom_components.pfsense] Timeout fetching pfSense pfSense state data
2022-07-06 19:16:12 DEBUG (MainThread) [custom_components.pfsense] Finished fetching pfSense pfSense state data in 10.001 seconds (success: False)
2022-07-06 19:16:12 DEBUG (SyncWorker_2) [custom_components.pfsense] execution time: PfSenseData._refresh_firmware_update_info 10.016

Jul 06 '22 17:07 bscheutjens

Can you try v0.5.2?

Jul 06 '22 20:07 travisghansen

Go to v0.5.3 and it should be backgrounding the firmware data calls.

As an aside, I noticed some code the made all the tests to bump the timeout for the xmlrpc calls useless (as it relates to the subject of this issue) so all the previous tests on this front are likely not helpful. Previously (to the very latest code) there was another hard-coded timeout at 10 seconds (that was being applied to all the api requests required per refresh interval). I have updated that code to make the value <interval> - 1 which should improve things generally on this front substantially.

I don't think it will fix all the problems floating around on this thread, but it's likely to help quite a bit, especially when combined with the new background logic for the firmware data.

Jul 06 '22 23:07 travisghansen

Thank you for your work on this! I tried the integration earlier but had to remove it because th device_tracker times out a lot and renders my presence sensor ineffective. I started this up again with v0.5.3 today to help you test. I am still seeing timeouts. Here's the latest

Unexpected error fetching pfsense pfSense device tracker state data: timed out
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 205, in _async_refresh
    self.data = await self._async_update_data()
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 164, in _async_update_data
    return await self.update_method()
  File "/config/custom_components/pfsense/__init__.py", line 124, in async_update_device_tracker_data
    await hass.async_add_executor_job(
  File "/usr/local/lib/python3.10/concurrent/futures/thread.py", line 58, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/config/custom_components/pfsense/__init__.py", line 125, in <lambda>
    lambda: device_tracker_data.update({"scope": "device_tracker"})
  File "/config/custom_components/pfsense/__init__.py", line 317, in update
    self._state["arp_table"] = self._get_arp_table()
  File "/config/custom_components/pfsense/__init__.py", line 229, in inner
    response = func(*args, **kwargs)
  File "/config/custom_components/pfsense/__init__.py", line 300, in _get_arp_table
    return self._client.get_arp_table(True)
  File "/config/custom_components/pfsense/pypfsense/__init__.py", line 393, in get_arp_table
    response = self._exec_php(script)
  File "/config/custom_components/pfsense/pypfsense/__init__.py", line 58, in inner
    response = func(*args, **kwargs)
  File "/config/custom_components/pfsense/pypfsense/__init__.py", line 91, in _exec_php
    response = self._get_proxy().pfsense.exec_php(script)
  File "/usr/local/lib/python3.10/xmlrpc/client.py", line 1122, in __call__
    return self.__send(self.__name, args)
  File "/usr/local/lib/python3.10/xmlrpc/client.py", line 1464, in __request
    response = self.__transport.request(
  File "/usr/local/lib/python3.10/xmlrpc/client.py", line 1166, in request
    return self.single_request(host, handler, request_body, verbose)
  File "/usr/local/lib/python3.10/xmlrpc/client.py", line 1179, in single_request
    resp = http_conn.getresponse()
  File "/usr/local/lib/python3.10/http/client.py", line 1374, in getresponse
    response.begin()
  File "/usr/local/lib/python3.10/http/client.py", line 318, in begin
    version, status, reason = self._read_status()
  File "/usr/local/lib/python3.10/http/client.py", line 279, in _read_status
    line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1")
  File "/usr/local/lib/python3.10/socket.py", line 705, in readinto
    return self._sock.recv_into(b)
TimeoutError: timed out

I see this as well

Logger: homeassistant.components.device_tracker
Source: helpers/entity_platform.py:298
Integration: Device tracker (documentation, issues)
First occurred: 8:48:27 PM (1 occurrences)
Last logged: 8:48:27 PM

Setup of platform pfsense is taking longer than 60 seconds. Startup will proceed without waiting any longer.

Jul 07 '22 02:07 nipuna-perera

Are you comfortable hacking code a little bit? If so I would like to have you try disabling the hostname resolution for the device tracker arp lookups.

Jul 07 '22 02:07 travisghansen

If you can guide me on how to do it I can definitely take a stab at it :) I am a SWE so I am comfortable navigating code.

Jul 07 '22 02:07 nipuna-perera

https://github.com/travisghansen/hass-pfsense/blob/v0.5.3/custom_components/pfsense/init.py#L300 change True to False and restart hass.

Jul 07 '22 02:07 travisghansen

if it matters, I was having the same problem. My TCP port in pfsense was changed to 10443 and I was unable to run my current, or setup a new integration, I changed it back to the default 443, and now it all works fine.

Jul 07 '22 02:07 bendiger

If the port configured for webConfigurator changes the integration configuration would definitely need to be updated (remove and re-add OR hack the .storage/core.config_entries file to update it).

Jul 07 '22 03:07 travisghansen

Right, I knew that, but trying to re add the config with 10443, it would give the %key:common::config_flow::error like in the SSL error Issue. I tried over and over. Multiple reboots of the router and home assistant. Changing back to 443 would stay stable and was able to add every time.

Jul 07 '22 03:07 bendiger

Indeed that is very strange then :(

Jul 07 '22 03:07 travisghansen

https://github.com/travisghansen/hass-pfsense/blob/v0.5.3/custom_components/pfsense/init.py#L300 change True to False and restart hass.

Done.

I haven't encountered the Unexpected error fetching pfsense pfSense device tracker state data: timed out Which I will have to monitor for a couple of hours to see if it occurs again.

But I still see this.

Logger: homeassistant.components.device_tracker
Source: helpers/entity_platform.py:298
Integration: Device tracker (documentation, issues)
First occurred: 10:24:30 PM (2 occurrences)
Last logged: 10:27:23 PM

Setup of platform pfsense is taking longer than 60 seconds. Startup will proceed without waiting any longer.