search

spacemanspiff2007 / HABApp

Easy home automation with MQTT and/or openHAB
Apache License 2.0
54 stars 23 forks source link

limited logging for Server disconnected error #398

Closed UrsusS closed 1 year ago

UrsusS commented 1 year ago

On my test system which is running with very limited functionality, I found twice the "Server disconnected" error. Expecting that this might happen without having to worry, I think it would be good if that error could be catched with limited logging. 

2023-06-16 21:59:07.948 [INFO ] [HABApp                    ] - HABApp Version 1.1.1
2023-06-16 22:00:57.398 [INFO ] [HABApp.openhab.connection ] - Connected to OpenHAB version 4.0.0.M3 (Milestone Build)

2023-06-28 05:21:31.379 [ERROR] [HABApp.openhab.connection ] - "Server disconnected" (<class 'aiohttp.client_exceptions.ServerDisconnectedError'>)
2023-06-28 05:21:42.535 [ERROR] [HABApp.openhab.connection ] - Error Server disconnected in output_queue_listener:
2023-06-28 05:21:42.536 [ERROR] [HABApp.openhab.connection ] - File "/opt/habapp/lib/python3.9/site-packages/HABApp/openhab/connection_handler/http_connection.py", line 301 in output_queue_listener
2023-06-28 05:21:42.536 [ERROR] [HABApp.openhab.connection ] - --------------------------------------------------------------------------------
2023-06-28 05:21:42.537 [ERROR] [HABApp.openhab.connection ] -      282 | async def output_queue_listener():
2023-06-28 05:21:42.537 [ERROR] [HABApp.openhab.connection ] -      283 |     # clear Queue
2023-06-28 05:21:42.537 [ERROR] [HABApp.openhab.connection ] -        (...)
2023-06-28 05:21:42.538 [ERROR] [HABApp.openhab.connection ] -      298 |                 if is_cmd:
2023-06-28 05:21:42.538 [ERROR] [HABApp.openhab.connection ] -      299 |                     await post(f'/rest/items/{item:s}', data=state)
2023-06-28 05:21:42.538 [ERROR] [HABApp.openhab.connection ] -      300 |                 else:
2023-06-28 05:21:42.539 [ERROR] [HABApp.openhab.connection ] - -->  301 |                     await put(f'/rest/items/{item:s}/state', data=state)
2023-06-28 05:21:42.539 [ERROR] [HABApp.openhab.connection ] -      302 |         except Exception as e:
2023-06-28 05:21:42.539 [ERROR] [HABApp.openhab.connection ] -    ------------------------------------------------------------
2023-06-28 05:21:42.540 [ERROR] [HABApp.openhab.connection ] -      e = ServerDisconnectedError('Server disconnected')
2023-06-28 05:21:42.540 [ERROR] [HABApp.openhab.connection ] -      is_cmd = False
2023-06-28 05:21:42.540 [ERROR] [HABApp.openhab.connection ] -      item = 'num_Server_HABApp_Ping'
2023-06-28 05:21:42.540 [ERROR] [HABApp.openhab.connection ] -      item, state, is_cmd = ('num_Server_HABApp_Ping', '34.3', False)
2023-06-28 05:21:42.540 [ERROR] [HABApp.openhab.connection ] -      log = <Logger HABApp.openhab.connection (INFO)>
2023-06-28 05:21:42.541 [ERROR] [HABApp.openhab.connection ] -      QUEUE = <Queue at 0x74ba7148 maxsize=0 _queue=[('num_Server_HABApp_Ping', None, False), ('num_Server_OH_UpTime', 16277, False), ('num_Server_HABApp_Ping', None, False), ('num_Server_HABApp_Ping', None, False), ('num_Server_HABApp_Ping', None, False), ('num_Server_HABApp_Ping', None, False), ('num_Server_HABApp_Ping', None, False), ('num_Server_HABApp_Ping', None, False), ('num_Server_OH_UpTime', 16278, False), ('num_Server_HABApp_Ping', None, False), ('num_Server_HABApp_Ping', None, False), ('num_Server_HABApp_Ping', None, False), ('num_Server_HABApp_Ping', None, False), ('num_Server_HABApp_Ping', None, False)] tasks=264173>
2023-06-28 05:21:42.541 [ERROR] [HABApp.openhab.connection ] -      state = '34.3'
2023-06-28 05:21:42.541 [ERROR] [HABApp.openhab.connection ] -    ------------------------------------------------------------
2023-06-28 05:21:42.541 [ERROR] [HABApp.openhab.connection ] - 
2023-06-28 05:21:42.542 [ERROR] [HABApp.openhab.connection ] - File "/opt/habapp/lib/python3.9/site-packages/HABApp/openhab/connection_handler/http_connection.py", line 87 in put
2023-06-28 05:21:42.542 [ERROR] [HABApp.openhab.connection ] - --------------------------------------------------------------------------------
2023-06-28 05:21:42.542 [ERROR] [HABApp.openhab.connection ] -      73 | async def put(url: str, log_404=True, json=None, data=None, **kwargs: Any) -> Optional[ClientResponse]:
2023-06-28 05:21:42.542 [ERROR] [HABApp.openhab.connection ] -       (...)
2023-06-28 05:21:42.542 [ERROR] [HABApp.openhab.connection ] -      78 |     mgr = _RequestContextManager(
2023-06-28 05:21:42.543 [ERROR] [HABApp.openhab.connection ] -      79 |         HTTP_SESSION._request(
2023-06-28 05:21:42.543 [ERROR] [HABApp.openhab.connection ] -       (...)
2023-06-28 05:21:42.543 [ERROR] [HABApp.openhab.connection ] -      82 |         )
2023-06-28 05:21:42.543 [ERROR] [HABApp.openhab.connection ] -      83 |     )
2023-06-28 05:21:42.544 [ERROR] [HABApp.openhab.connection ] -      85 |     if data is None:
2023-06-28 05:21:42.544 [ERROR] [HABApp.openhab.connection ] -      86 |         data = json
2023-06-28 05:21:42.544 [ERROR] [HABApp.openhab.connection ] - -->  87 |     return await check_response(mgr, log_404=log_404, sent_data=data)
2023-06-28 05:21:42.544 [ERROR] [HABApp.openhab.connection ] -    ------------------------------------------------------------
2023-06-28 05:21:42.545 [ERROR] [HABApp.openhab.connection ] -      _RequestContextManager = <class 'aiohttp.client._RequestContextManager'>
2023-06-28 05:21:42.545 [ERROR] [HABApp.openhab.connection ] -      Any = typing.Any
2023-06-28 05:21:42.545 [ERROR] [HABApp.openhab.connection ] -      data = '34.3'
2023-06-28 05:21:42.546 [ERROR] [HABApp.openhab.connection ] -      HTTP_ALLOW_REDIRECTS = True
2023-06-28 05:21:42.546 [ERROR] [HABApp.openhab.connection ] -      HTTP_SESSION = <aiohttp.client.ClientSession object at 0x74284bf8>
2023-06-28 05:21:42.546 [ERROR] [HABApp.openhab.connection ] -      HTTP_VERIFY_SSL = None
2023-06-28 05:21:42.547 [ERROR] [HABApp.openhab.connection ] -      IS_ONLINE = True
2023-06-28 05:21:42.547 [ERROR] [HABApp.openhab.connection ] -      IS_READ_ONLY = False
2023-06-28 05:21:42.547 [ERROR] [HABApp.openhab.connection ] -      IS_READ_ONLY or not IS_ONLINE = False
2023-06-28 05:21:42.548 [ERROR] [HABApp.openhab.connection ] -      json = None
2023-06-28 05:21:42.548 [ERROR] [HABApp.openhab.connection ] -      kwargs = {}
2023-06-28 05:21:42.548 [ERROR] [HABApp.openhab.connection ] -      log_404 = True
2023-06-28 05:21:42.548 [ERROR] [HABApp.openhab.connection ] -      METH_PUT = 'PUT'
2023-06-28 05:21:42.549 [ERROR] [HABApp.openhab.connection ] -      mgr = <aiohttp.client._RequestContextManager object at 0x706fb6e8>
2023-06-28 05:21:42.549 [ERROR] [HABApp.openhab.connection ] -      not IS_ONLINE = False
2023-06-28 05:21:42.549 [ERROR] [HABApp.openhab.connection ] -      url = '/rest/items/num_Server_HABApp_Ping/state'
2023-06-28 05:21:42.549 [ERROR] [HABApp.openhab.connection ] -    ------------------------------------------------------------
2023-06-28 05:21:42.550 [ERROR] [HABApp.openhab.connection ] - 
2023-06-28 05:21:42.550 [ERROR] [HABApp.openhab.connection ] - File "/opt/habapp/lib/python3.9/site-packages/HABApp/openhab/connection_handler/http_connection.py", line 139 in check_response
2023-06-28 05:21:42.550 [ERROR] [HABApp.openhab.connection ] - --------------------------------------------------------------------------------
2023-06-28 05:21:42.550 [ERROR] [HABApp.openhab.connection ] -      136 | async def check_response(future: aiohttp.client._RequestContextManager, sent_data=None,
2023-06-28 05:21:42.551 [ERROR] [HABApp.openhab.connection ] -      137 |                          log_404=True, disconnect_on_error=False) -> ClientResponse:
2023-06-28 05:21:42.551 [ERROR] [HABApp.openhab.connection ] -      138 |     try:
2023-06-28 05:21:42.551 [ERROR] [HABApp.openhab.connection ] - -->  139 |         resp = await future
2023-06-28 05:21:42.551 [ERROR] [HABApp.openhab.connection ] -      140 |     except Exception as e:
2023-06-28 05:21:42.552 [ERROR] [HABApp.openhab.connection ] -    ------------------------------------------------------------
2023-06-28 05:21:42.552 [ERROR] [HABApp.openhab.connection ] -      aiohttp.client._RequestContextManager = <class 'aiohttp.client._RequestContextManager'>
2023-06-28 05:21:42.552 [ERROR] [HABApp.openhab.connection ] -      logging.ERROR = 40
2023-06-28 05:21:42.552 [ERROR] [HABApp.openhab.connection ] -      logging.WARNING = 30
2023-06-28 05:21:42.552 [ERROR] [HABApp.openhab.connection ] -      disconnect_on_error = False
2023-06-28 05:21:42.553 [ERROR] [HABApp.openhab.connection ] -      disconnect_on_error and status >= 400 = False
2023-06-28 05:21:42.553 [ERROR] [HABApp.openhab.connection ] -      future = <aiohttp.client._RequestContextManager object at 0x706fb6e8>
2023-06-28 05:21:42.553 [ERROR] [HABApp.openhab.connection ] -      is_disconnect = False
2023-06-28 05:21:42.553 [ERROR] [HABApp.openhab.connection ] -      log = <Logger HABApp.openhab.connection (INFO)>
2023-06-28 05:21:42.554 [ERROR] [HABApp.openhab.connection ] -      log_404 = True
2023-06-28 05:21:42.554 [ERROR] [HABApp.openhab.connection ] -      not log_404 = False
2023-06-28 05:21:42.554 [ERROR] [HABApp.openhab.connection ] -      sent_data = '34.3'
2023-06-28 05:21:42.554 [ERROR] [HABApp.openhab.connection ] -    ------------------------------------------------------------
2023-06-28 05:21:42.555 [ERROR] [HABApp.openhab.connection ] - 
2023-06-28 05:21:42.555 [ERROR] [HABApp.openhab.connection ] - --------------------------------------------------------------------------------
2023-06-28 05:21:42.555 [ERROR] [HABApp.openhab.connection ] - Traceback (most recent call last):
2023-06-28 05:21:42.555 [ERROR] [HABApp.openhab.connection ] -   File "/opt/habapp/lib/python3.9/site-packages/HABApp/openhab/connection_handler/http_connection.py", line 301, in output_queue_listener
2023-06-28 05:21:42.555 [ERROR] [HABApp.openhab.connection ] -     await put(f'/rest/items/{item:s}/state', data=state)
2023-06-28 05:21:42.556 [ERROR] [HABApp.openhab.connection ] -   File "/opt/habapp/lib/python3.9/site-packages/HABApp/openhab/connection_handler/http_connection.py", line 87, in put
2023-06-28 05:21:42.556 [ERROR] [HABApp.openhab.connection ] -     return await check_response(mgr, log_404=log_404, sent_data=data)
2023-06-28 05:21:42.556 [ERROR] [HABApp.openhab.connection ] -   File "/opt/habapp/lib/python3.9/site-packages/HABApp/openhab/connection_handler/http_connection.py", line 139, in check_response
2023-06-28 05:21:42.556 [ERROR] [HABApp.openhab.connection ] -     resp = await future
2023-06-28 05:21:42.557 [ERROR] [HABApp.openhab.connection ] -   File "/opt/habapp/lib/python3.9/site-packages/aiohttp/client.py", line 560, in _request
2023-06-28 05:21:42.557 [ERROR] [HABApp.openhab.connection ] -     await resp.start(conn)
2023-06-28 05:21:42.557 [ERROR] [HABApp.openhab.connection ] -   File "/opt/habapp/lib/python3.9/site-packages/aiohttp/client_reqrep.py", line 899, in start
2023-06-28 05:21:42.557 [ERROR] [HABApp.openhab.connection ] -     message, payload = await protocol.read()  # type: ignore[union-attr]
2023-06-28 05:21:42.558 [ERROR] [HABApp.openhab.connection ] -   File "/opt/habapp/lib/python3.9/site-packages/aiohttp/streams.py", line 616, in read
2023-06-28 05:21:42.558 [ERROR] [HABApp.openhab.connection ] -     await self._waiter
2023-06-28 05:21:42.558 [ERROR] [HABApp.openhab.connection ] - aiohttp.client_exceptions.ServerDisconnectedError: Server disconnected
spacemanspiff2007 commented 1 year ago

Does this bug still exist with 1.1.2? Logging changed there ...

UrsusS commented 1 year ago

I haven't seen it again, but also the ServerDisconnectedError hasn't been there again.

spacemanspiff2007 commented 1 year ago

I'm closing this, but if the disconnect with the extensive logging happens again please reopen it. That's not how it should be.