Closed UrsusS closed 1 year ago
It seems that during startup the loading of rule files is not canceled. Can you try the Develop Branch and see if everything works as expected?
Hi, while testing with dev version under the same conditions (but OH 4.0.0) the error didn't occur again. Thanks for fixing.
But I got several times ServerDisconnectedErrors. The test condition was a ###programmed restart of the habapp.service (erroneously every 10 secs, but the root cause is now fixed in OH 4.0.1).
2023-07-29 12:27:43.812 [INFO ] [HABApp ] - HABApp Version 1.1.3.DEV-4
2023-07-29 12:27:44.009 [INFO ] [HABApp.mqtt.connection ] - MQTT disabled
2023-07-29 12:27:44.438 [INFO ] [HABApp.openhab.connection ] - Connected to OpenHAB version 4.0.0 (Release Build)
2023-07-29 12:27:44.530 [INFO ] [HABApp.openhab.transform ] - Transformations:
2023-07-29 12:27:44.530 [INFO ] [HABApp.openhab.transform ] - Map: de.map, en.map, ups.map
2023-07-29 12:27:45.342 [WARN ] [HABApp.Rule ] - /opt/habapp/lib/python3.9/site-packages/HABApp/openhab/connection_logic/plugin_things/plugin_things.py:73: PydanticDeprecatedSince20:The `dict` method is deprecated; use `model_dump` instead. Deprecated in Pydantic V2.0 to be removed in V3.0. See Pydantic V2 Migration Guide at https://errors.pydantic.dev/2.1.1/migration/
2023-07-29 12:27:45.343 [WARN ] [HABApp.Rule ] - /opt/habapp/lib/python3.9/site-packages/pydantic/main.py:913: PydanticDeprecatedSince20:The `dict` method is deprecated; use `model_dump` instead. Deprecated in Pydantic V2.0 to be removed in V3.0. See Pydantic V2 Migration Guide at https://errors.pydantic.dev/2.1.1/migration/
2023-07-29 12:27:46.180 [INFO ] [HABApp.openhab.items ] - Updated 821 Items
2023-07-29 12:27:46.734 [ERROR] [HABApp.openhab.connection ] - "Server disconnected" (<class 'aiohttp.client_exceptions.ServerDisconnectedError'>)
2023-07-29 12:27:48.801 [ERROR] [HABApp ] - Error Server disconnected in on_connect_function:
2023-07-29 12:27:48.802 [ERROR] [HABApp ] - File "/opt/habapp/lib/python3.9/site-packages/HABApp/openhab/connection_logic/plugin_load_items.py", line 44 in on_connect_function
2023-07-29 12:27:48.802 [ERROR] [HABApp ] - --------------------------------------------------------------------------------
2023-07-29 12:27:48.802 [ERROR] [HABApp ] - 42 | @ignore_exception
2023-07-29 12:27:48.802 [ERROR] [HABApp ] - 43 | async def on_connect_function(self):
2023-07-29 12:27:48.803 [ERROR] [HABApp ] - --> 44 | if await self.load_items():
2023-07-29 12:27:48.803 [ERROR] [HABApp ] - 45 | return True
2023-07-29 12:27:48.803 [ERROR] [HABApp ] - ------------------------------------------------------------
2023-07-29 12:27:48.803 [ERROR] [HABApp ] - self = <HABApp.openhab.connection_logic.plugin_load_items.LoadAllOpenhabItems object at 0x6ccc8ec8>
2023-07-29 12:27:48.803 [ERROR] [HABApp ] - ------------------------------------------------------------
2023-07-29 12:27:48.804 [ERROR] [HABApp ] -
2023-07-29 12:27:48.804 [ERROR] [HABApp ] - File "/opt/habapp/lib/python3.9/site-packages/HABApp/openhab/connection_logic/plugin_load_items.py", line 84 in load_items
2023-07-29 12:27:48.804 [ERROR] [HABApp ] - --------------------------------------------------------------------------------
2023-07-29 12:27:48.804 [ERROR] [HABApp ] - 49 | async def load_items(self) -> bool:
2023-07-29 12:27:48.805 [ERROR] [HABApp ] - (...)
2023-07-29 12:27:48.805 [ERROR] [HABApp ] - 78 | # Sync missed updates (e.g. where we got a value updated/changed event during the item request)
2023-07-29 12:27:48.805 [ERROR] [HABApp ] - 79 | # Some bindings poll the item states directly after persistence and we might miss those during startup
2023-07-29 12:27:48.805 [ERROR] [HABApp ] - 80 | log.debug('Starting item state sync')
2023-07-29 12:27:48.805 [ERROR] [HABApp ] - 81 | created_items: Dict[str, Tuple[OpenhabItem, datetime]] = {
2023-07-29 12:27:48.806 [ERROR] [HABApp ] - 82 | i.name: (i, i.last_update) for i in Items.get_items() if isinstance(i, OpenhabItem)
2023-07-29 12:27:48.806 [ERROR] [HABApp ] - 83 | }
2023-07-29 12:27:48.806 [ERROR] [HABApp ] - --> 84 | if (data := await async_get_items(only_item_state=True)) is None:
2023-07-29 12:27:48.806 [ERROR] [HABApp ] - 85 | return True
2023-07-29 12:27:48.807 [ERROR] [HABApp ] - ------------------------------------------------------------
2023-07-29 12:27:48.807 [ERROR] [HABApp ] - _dict = {'link': 'http://localhost:8080/rest/items/num_CorridorFF_Light_EnergyCons', 'state': '97.6 kWh', 'stateDescription': {'pattern': '%.2f kWh', 'readOnly': True, 'options': []}, 'unitSymbol': 'kWh', 'metadata': {'unit': {'value': 'kWh'}}, 'editable': False, 'type': 'Number:Energy', 'name': 'num_CorridorFF_Light_EnergyCons', 'label': 'Licht Flur OG Strom', 'category': 'line', 'tags': [], 'groupNames': ['gCorridorFF_Light', 'gRestoreOnStartup', 'gLog', 'gDel1M', 'gConsumptionDevice']}
2023-07-29 12:27:48.807 [ERROR] [HABApp ] - _dict['groupNames'] = ['gCorridorFF_Light', 'gRestoreOnStartup', 'gLog', 'gDel1M', 'gConsumptionDevice']
2023-07-29 12:27:48.807 [ERROR] [HABApp ] - _dict['name'] = 'num_CorridorFF_Light_EnergyCons'
2023-07-29 12:27:48.807 [ERROR] [HABApp ] - _dict['state'] = '97.6 kWh'
2023-07-29 12:27:48.808 [ERROR] [HABApp ] - _dict['tags'] = []
2023-07-29 12:27:48.808 [ERROR] [HABApp ] - _dict['type'] = 'Number:Energy'
2023-07-29 12:27:48.808 [ERROR] [HABApp ] - created_items = {'num_Mower_Mowing_Duration': (<NumberItem name: num_Mower_Mowing_Duration, value: 0, last_change: 2023-07-29T12:27:46.019905, last_update: 2023-07-29T12:27:46.019905>, DateTime(2023, 7, 29, 12, 27, 46, 19905)), 'gRoomParents_Sensor': (<GroupItem name: gRoomParents_Sensor, value: None, last_change: 2023-07-29T12:27:46.020245, last_update: 2023-07-29T12:27:46.020245>, DateTime(2023, 7, 29, 12, 27, 46, 20245)), 'num_Entry_Light_EnergyCons_PreviousDay': (<NumberItem name: num_Entry_Light_EnergyCons_PreviousDay, value: 0, last_change: 2023-07-29T12:27:46.020424, last_update: 2023-07-29T12:27:46.020424>, DateTime(2023, 7, 29, 12, 27, 46, 20424)), 'gCorridorFF_Light':
.....
2023-07-29 12:27:48.810 [ERROR] [HABApp ] - created_items[item_name] = (<NumberItem name: num_CorridorFF_Light_EnergyCons, value: 97.6, last_change: 2023-07-29T12:27:46.178676, last_update: 2023-07-29T12:27:46.178676>, DateTime(2023, 7, 29, 12, 27, 46, 178676))
2023-07-29 12:27:48.811 [ERROR] [HABApp ] - data = [{'link': 'http://localhost:8080/rest/items/num_Mower_Mowing_Duration', 'state': '0 min', 'stateDescription': {'pattern': '%d', 'readOnly': False, 'options': []}, 'unitSymbol': 'min', 'metadata': {'unit': {'value': 'min'}}, 'editable': False, 'type': 'Number:Time', 'name': 'num_Mower_Mowing_Duration', 'label': 'Dauer des Mähvorgangs', 'category': 'none', 'tags': [], 'groupNames': ['gMower', 'gRestoreOnStartup', 'gLogChange', 'gDel1M']},
.....
2023-07-29 12:27:48.818 [ERROR] [HABApp ] - found_items = 821
2023-07-29 12:27:48.818 [ERROR] [HABApp ] - frozenset(_dict['groupNames']) = frozenset({'gConsumptionDevice', 'gRestoreOnStartup', 'gLog', 'gCorridorFF_Light', 'gDel1M'})
2023-07-29 12:27:48.819 [ERROR] [HABApp ] - frozenset(_dict['tags']) = frozenset()
2023-07-29 12:27:48.819 [ERROR] [HABApp ] - ist = {'dtm_DWDWarning3_Prev_Expires', 'num_WiGa_FloorLamp_ColorSat', 'gHouse', 'num_Radio_Tuner_Mode', 'str_DWDWarning4_Prev_Event', 'num_Wintergarden_AbsHumidity', 'num_Server_Heap_UsedPercent', 'swi_Karola_iButton', 'num_PVLogger_consYieldYear', 'rol_MowerShed_Gate', 'swi_Andrea_Window_Handle_Pause', 'dim_Radio_RadioWiGa_Volume', 'gDel1M', 'swi_DWDWarning3_Prev', 'num_Weather_WindSpeed', 'swi_System_HABAppTest', 'num_Weather_F24h_WindDirection', 'swi_WiFi_Welcome_Activate', 'gKitchen_Window', 'num_Telephone_LastEventCheck',
.....
2023-07-29 12:27:48.820 [ERROR] [HABApp ] - ist - soll = set()
2023-07-29 12:27:48.820 [ERROR] [HABApp ] - item_name = 'num_CorridorFF_Light_EnergyCons'
2023-07-29 12:27:48.820 [ERROR] [HABApp ] - Items = <HABApp.core.internals.item_registry.item_registry.ItemRegistry object at 0x767d10e8>
2023-07-29 12:27:48.820 [ERROR] [HABApp ] - len(data) = 821
2023-07-29 12:27:48.821 [ERROR] [HABApp ] - log = <Logger HABApp.openhab.items (INFO)>
2023-07-29 12:27:48.821 [ERROR] [HABApp ] - new_item = <NumberItem name: num_CorridorFF_Light_EnergyCons, value: 97.6, last_change: 2023-07-29T12:27:46.178676, last_update: 2023-07-29T12:27:46.178676>
2023-07-29 12:27:48.821 [ERROR] [HABApp ] - OpenhabItem, datetime = (<class 'HABApp.openhab.items.base_item.OpenhabItem'>, <class 'datetime.datetime'>)
2023-07-29 12:27:48.821 [ERROR] [HABApp ] - self = <HABApp.openhab.connection_logic.plugin_load_items.LoadAllOpenhabItems object at 0x6ccc8ec8>
2023-07-29 12:27:48.821 [ERROR] [HABApp ] - soll = {'dtm_DWDWarning3_Prev_Expires', 'num_WiGa_FloorLamp_ColorSat', 'gHouse', 'num_Radio_Tuner_Mode', 'str_DWDWarning4_Prev_Event', 'num_Wintergarden_AbsHumidity', 'num_Server_Heap_UsedPercent', 'swi_Karola_iButton', 'num_PVLogger_consYieldYear', 'rol_MowerShed_Gate', 'swi_Andrea_Window_Handle_Pause', 'dim_Radio_RadioWiGa_Volume', 'gDel1M', 'swi_DWDWarning3_Prev', 'num_Weather_WindSpeed', 'swi_System_HABAppTest', 'num_Weather_F24h_WindDirection', 'swi_WiFi_Welcome_Activate', 'gKitchen_Window', 'num_Telephone_LastEventCheck',
2023-07-29 12:27:48.822 [ERROR] [HABApp ] - ':' in _dict['type'] = True
2023-07-29 12:27:48.822 [ERROR] [HABApp ] - ------------------------------------------------------------
2023-07-29 12:27:48.822 [ERROR] [HABApp ] -
2023-07-29 12:27:48.822 [ERROR] [HABApp ] - File "/opt/habapp/lib/python3.9/site-packages/HABApp/openhab/connection_handler/func_async.py", line 79 in async_get_items
2023-07-29 12:27:48.823 [ERROR] [HABApp ] - --------------------------------------------------------------------------------
2023-07-29 12:27:48.823 [ERROR] [HABApp ] - 61 | async def async_get_items(include_habapp_meta=False, metadata: Optional[str] = None,
2023-07-29 12:27:48.823 [ERROR] [HABApp ] - 62 | all_metadata=False,
2023-07-29 12:27:48.823 [ERROR] [HABApp ] - 63 | only_item_state=False) -> Optional[List[Dict[str, Any]]]:
2023-07-29 12:27:48.824 [ERROR] [HABApp ] - (...)
2023-07-29 12:27:48.824 [ERROR] [HABApp ] - 75 | if params is None:
2023-07-29 12:27:48.824 [ERROR] [HABApp ] - 76 | params = {}
2023-07-29 12:27:48.824 [ERROR] [HABApp ] - 77 | params['fields'] = 'name,state,type'
2023-07-29 12:27:48.824 [ERROR] [HABApp ] - --> 79 | resp = await get('/rest/items', params=params)
2023-07-29 12:27:48.825 [ERROR] [HABApp ] - 80 | return await resp.json(loads=load_json, encoding='utf-8')
2023-07-29 12:27:48.825 [ERROR] [HABApp ] - ------------------------------------------------------------
2023-07-29 12:27:48.825 [ERROR] [HABApp ] - all_metadata = False
2023-07-29 12:27:48.825 [ERROR] [HABApp ] - include_habapp_meta = False
2023-07-29 12:27:48.825 [ERROR] [HABApp ] - metadata = None
2023-07-29 12:27:48.826 [ERROR] [HABApp ] - only_item_state = True
2023-07-29 12:27:48.826 [ERROR] [HABApp ] - params = {'fields': 'name,state,type'}
2023-07-29 12:27:48.826 [ERROR] [HABApp ] - params['fields'] = 'name,state,type'
2023-07-29 12:27:48.826 [ERROR] [HABApp ] - {'metadata': metadata} = {'metadata': None}
2023-07-29 12:27:48.826 [ERROR] [HABApp ] - metadata is not None = False
2023-07-29 12:27:48.827 [ERROR] [HABApp ] - params is not None = True
2023-07-29 12:27:48.827 [ERROR] [HABApp ] - ------------------------------------------------------------
2023-07-29 12:27:48.827 [ERROR] [HABApp ] -
2023-07-29 12:27:48.827 [ERROR] [HABApp ] - File "/opt/habapp/lib/python3.9/site-packages/HABApp/openhab/connection_handler/http_connection.py", line 53 in get
2023-07-29 12:27:48.827 [ERROR] [HABApp ] - --------------------------------------------------------------------------------
2023-07-29 12:27:48.828 [ERROR] [HABApp ] - 48 | async def get(url: str, log_404=True, **kwargs: Any) -> ClientResponse:
2023-07-29 12:27:48.828 [ERROR] [HABApp ] - 50 | mgr = _RequestContextManager(
2023-07-29 12:27:48.828 [ERROR] [HABApp ] - 51 | HTTP_SESSION._request(METH_GET, url, allow_redirects=HTTP_ALLOW_REDIRECTS, ssl=HTTP_VERIFY_SSL, **kwargs)
2023-07-29 12:27:48.828 [ERROR] [HABApp ] - 52 | )
2023-07-29 12:27:48.829 [ERROR] [HABApp ] - --> 53 | return await check_response(mgr, log_404=log_404)
2023-07-29 12:27:48.829 [ERROR] [HABApp ] - ------------------------------------------------------------
2023-07-29 12:27:48.829 [ERROR] [HABApp ] - _RequestContextManager = <class 'aiohttp.client._RequestContextManager'>
2023-07-29 12:27:48.829 [ERROR] [HABApp ] - HTTP_ALLOW_REDIRECTS = True
2023-07-29 12:27:48.829 [ERROR] [HABApp ] - HTTP_SESSION = None
2023-07-29 12:27:48.830 [ERROR] [HABApp ] - HTTP_VERIFY_SSL = None
2023-07-29 12:27:48.830 [ERROR] [HABApp ] - kwargs = {'params': {'fields': 'name,state,type'}}
2023-07-29 12:27:48.830 [ERROR] [HABApp ] - log_404 = True
2023-07-29 12:27:48.830 [ERROR] [HABApp ] - METH_GET = 'GET'
2023-07-29 12:27:48.830 [ERROR] [HABApp ] - mgr = <aiohttp.client._RequestContextManager object at 0x6bac9c70>
2023-07-29 12:27:48.831 [ERROR] [HABApp ] - url = '/rest/items'
2023-07-29 12:27:48.831 [ERROR] [HABApp ] - ------------------------------------------------------------
2023-07-29 12:27:48.831 [ERROR] [HABApp ] -
2023-07-29 12:27:48.831 [ERROR] [HABApp ] - File "/opt/habapp/lib/python3.9/site-packages/HABApp/openhab/connection_handler/http_connection.py", line 139 in check_response
2023-07-29 12:27:48.831 [ERROR] [HABApp ] - --------------------------------------------------------------------------------
2023-07-29 12:27:48.832 [ERROR] [HABApp ] - 136 | async def check_response(future: aiohttp.client._RequestContextManager, sent_data=None,
2023-07-29 12:27:48.832 [ERROR] [HABApp ] - 137 | log_404=True, disconnect_on_error=False) -> ClientResponse:
2023-07-29 12:27:48.832 [ERROR] [HABApp ] - 138 | try:
2023-07-29 12:27:48.832 [ERROR] [HABApp ] - --> 139 | resp = await future
2023-07-29 12:27:48.832 [ERROR] [HABApp ] - 140 | except Exception as e:
2023-07-29 12:27:48.833 [ERROR] [HABApp ] - ------------------------------------------------------------
2023-07-29 12:27:48.833 [ERROR] [HABApp ] - aiohttp.client._RequestContextManager = <class 'aiohttp.client._RequestContextManager'>
2023-07-29 12:27:48.833 [ERROR] [HABApp ] - logging.ERROR = 40
2023-07-29 12:27:48.833 [ERROR] [HABApp ] - logging.WARNING = 30
2023-07-29 12:27:48.834 [ERROR] [HABApp ] - disconnect_on_error = False
2023-07-29 12:27:48.834 [ERROR] [HABApp ] - disconnect_on_error and status >= 400 = False
2023-07-29 12:27:48.834 [ERROR] [HABApp ] - future = <aiohttp.client._RequestContextManager object at 0x6bac9c70>
2023-07-29 12:27:48.834 [ERROR] [HABApp ] - is_disconnect = False
2023-07-29 12:27:48.834 [ERROR] [HABApp ] - log = <Logger HABApp.openhab.connection (INFO)>
2023-07-29 12:27:48.835 [ERROR] [HABApp ] - log_404 = True
2023-07-29 12:27:48.835 [ERROR] [HABApp ] - not log_404 = False
2023-07-29 12:27:48.835 [ERROR] [HABApp ] - sent_data = None
2023-07-29 12:27:48.835 [ERROR] [HABApp ] - ------------------------------------------------------------
2023-07-29 12:27:48.836 [ERROR] [HABApp ] -
2023-07-29 12:27:48.836 [ERROR] [HABApp ] - --------------------------------------------------------------------------------
2023-07-29 12:27:48.836 [ERROR] [HABApp ] - Traceback (most recent call last):
2023-07-29 12:27:48.836 [ERROR] [HABApp ] - File "/opt/habapp/lib/python3.9/site-packages/HABApp/core/wrapper.py", line 71, in a
2023-07-29 12:27:48.836 [ERROR] [HABApp ] - return await func(*args, **kwargs)
2023-07-29 12:27:48.837 [ERROR] [HABApp ] - File "/opt/habapp/lib/python3.9/site-packages/HABApp/openhab/connection_logic/plugin_load_items.py", line 44, in on_connect_function
2023-07-29 12:27:48.837 [ERROR] [HABApp ] - if await self.load_items():
2023-07-29 12:27:48.837 [ERROR] [HABApp ] - File "/opt/habapp/lib/python3.9/site-packages/HABApp/openhab/connection_logic/plugin_load_items.py", line 84, in load_items
2023-07-29 12:27:48.837 [ERROR] [HABApp ] - if (data := await async_get_items(only_item_state=True)) is None:
2023-07-29 12:27:48.837 [ERROR] [HABApp ] - File "/opt/habapp/lib/python3.9/site-packages/HABApp/openhab/connection_handler/func_async.py", line 79, in async_get_items
2023-07-29 12:27:48.838 [ERROR] [HABApp ] - resp = await get('/rest/items', params=params)
2023-07-29 12:27:48.838 [ERROR] [HABApp ] - File "/opt/habapp/lib/python3.9/site-packages/HABApp/openhab/connection_handler/http_connection.py", line 53, in get
2023-07-29 12:27:48.838 [ERROR] [HABApp ] - return await check_response(mgr, log_404=log_404)
2023-07-29 12:27:48.838 [ERROR] [HABApp ] - File "/opt/habapp/lib/python3.9/site-packages/HABApp/openhab/connection_handler/http_connection.py", line 139, in check_response
2023-07-29 12:27:48.838 [ERROR] [HABApp ] - resp = await future
2023-07-29 12:27:48.839 [ERROR] [HABApp ] - File "/opt/habapp/lib/python3.9/site-packages/aiohttp/client.py", line 560, in _request
2023-07-29 12:27:48.839 [ERROR] [HABApp ] - await resp.start(conn)
2023-07-29 12:27:48.839 [ERROR] [HABApp ] - File "/opt/habapp/lib/python3.9/site-packages/aiohttp/client_reqrep.py", line 899, in start
2023-07-29 12:27:48.839 [ERROR] [HABApp ] - message, payload = await protocol.read() # type: ignore[union-attr]
2023-07-29 12:27:48.839 [ERROR] [HABApp ] - File "/opt/habapp/lib/python3.9/site-packages/aiohttp/streams.py", line 616, in read
2023-07-29 12:27:48.840 [ERROR] [HABApp ] - await self._waiter
2023-07-29 12:27:48.840 [ERROR] [HABApp ] - aiohttp.client_exceptions.ServerDisconnectedError: Server disconnected
2023-07-29 12:27:49.356 [WARN ] [HABApp.Rule ] - /opt/habapp/lib/python3.9/site-packages/HABApp/runtime/shutdown.py:71: ResourceWarning:unclosed file <_io.TextIOWrapper name='/var/log/openhab/HABApp_events.log' mode='a' encoding='utf-8'>
Does this still happen with the latest release?
I haven't seen it anymore, so ready for closing. I have seen something similar, but I will open a new topic.
Thank you for your reply
This happens on my test system if there are several restarts of HABApp in a short time (in my case it was every 10 seconds)