search

tillsteinbach / VWsFriend

VW WeConnect visualization and control
MIT License
252 stars 21 forks source link

Container crash when charging session started #393

Open amenychtas opened 1 year ago

amenychtas commented 1 year ago

Today I noticed the the contairer crashed and this is probably related to a charging session that started. The car is ID.3 v3.0.

Here is the log:

2023-01-12T06:19:39+0000:INFO:vwsfriend_base:Updating data from WeConnect
Traceback (most recent call last):
  File "/opt/venv/bin/vwsfriend", line 8, in <module>
    sys.exit(main())
             ^^^^^^
  File "/opt/venv/lib/python3.11/site-packages/vwsfriend/vwsfriend_base.py", line 501, in main
    weConnect.update(updateCapabilities=True, updatePictures=True, force=True)
  File "/opt/venv/lib/python3.11/site-packages/weconnect/weconnect.py", line 193, in update
    self.updateComplete()
  File "/opt/venv/lib/python3.11/site-packages/weconnect/addressable.py", line 534, in updateComplete
    child.updateComplete()
  File "/opt/venv/lib/python3.11/site-packages/weconnect/addressable.py", line 534, in updateComplete
    child.updateComplete()
  File "/opt/venv/lib/python3.11/site-packages/weconnect/addressable.py", line 534, in updateComplete
    child.updateComplete()
  [Previous line repeated 3 more times]
  File "/opt/venv/lib/python3.11/site-packages/weconnect/addressable.py", line 97, in updateComplete
    observer(element=self, flags=self.onCompleteNotifyFlags)
  File "/opt/venv/lib/python3.11/site-packages/vwsfriend/agents/charge_agent.py", line 115, in __onChargingStateChange
    self.session.refresh(self.chargingSession)
  File "/opt/venv/lib/python3.11/site-packages/sqlalchemy/orm/session.py", line 2350, in refresh
    raise sa_exc.InvalidRequestError(
sqlalchemy.exc.InvalidRequestError: Could not refresh instance '<ChargingSession at 0x7fc6ea326a90>'

And here are the last recorded events (GMT+2): image

tillsteinbach commented 1 year ago

I have seen that before, but until now I cannot reproduce the issue. This needs further investigation.

Gregoire-M commented 1 year ago

Hi, Same problem here, updates are frozen since yesterday, when I started an AC charge.

Capture d’écran 2023-04-06 à 14 05 16

Even if I stop, pull, and restart my containers, I get the following error. So I'm stuck. Is there any way to unblock me?

vwsfriend_1   | 2023-04-06T07:32:51+0000:ERROR:_internal:Error on request:
vwsfriend_1   | Traceback (most recent call last):
vwsfriend_1   |   File "/opt/venv/lib/python3.11/site-packages/sqlalchemy/engine/base.py", line 1964, in _exec_single_context
vwsfriend_1   |     self.dialect.do_execute(
vwsfriend_1   |   File "/opt/venv/lib/python3.11/site-packages/sqlalchemy/engine/default.py", line 747, in do_execute
vwsfriend_1   |     cursor.execute(statement, parameters)
vwsfriend_1   | psycopg2.errors.AdminShutdown: terminating connection due to administrator command
vwsfriend_1   | server closed the connection unexpectedly
vwsfriend_1   |     This probably means the server terminated abnormally
vwsfriend_1   |     before or while processing the request.
vwsfriend_1   | 
vwsfriend_1   | 
vwsfriend_1   | The above exception was the direct cause of the following exception:
vwsfriend_1   | 
vwsfriend_1   | Traceback (most recent call last):
vwsfriend_1   |   File "/opt/venv/lib/python3.11/site-packages/werkzeug/serving.py", line 333, in run_wsgi
vwsfriend_1   |     execute(self.server.app)
vwsfriend_1   |   File "/opt/venv/lib/python3.11/site-packages/werkzeug/serving.py", line 320, in execute
vwsfriend_1   |     application_iter = app(environ, start_response)
vwsfriend_1   |                        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
vwsfriend_1   |   File "/opt/venv/lib/python3.11/site-packages/flask/app.py", line 2551, in __call__
vwsfriend_1   |     return self.wsgi_app(environ, start_response)
vwsfriend_1   |            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
vwsfriend_1   |   File "/opt/venv/lib/python3.11/site-packages/flask/app.py", line 2531, in wsgi_app
vwsfriend_1   |     response = self.handle_exception(e)
vwsfriend_1   |                ^^^^^^^^^^^^^^^^^^^^^^^^
vwsfriend_1   |   File "/opt/venv/lib/python3.11/site-packages/flask/app.py", line 2528, in wsgi_app
vwsfriend_1   |     response = self.full_dispatch_request()
vwsfriend_1   |                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
vwsfriend_1   |   File "/opt/venv/lib/python3.11/site-packages/flask/app.py", line 1825, in full_dispatch_request
vwsfriend_1   |     rv = self.handle_user_exception(e)
vwsfriend_1   |          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
vwsfriend_1   |   File "/opt/venv/lib/python3.11/site-packages/flask/app.py", line 1821, in full_dispatch_request
vwsfriend_1   |     rv = self.preprocess_request()
vwsfriend_1   |          ^^^^^^^^^^^^^^^^^^^^^^^^^
vwsfriend_1   |   File "/opt/venv/lib/python3.11/site-packages/flask/app.py", line 2312, in preprocess_request
vwsfriend_1   |     rv = self.ensure_sync(before_func)()
vwsfriend_1   |          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
vwsfriend_1   |   File "/opt/venv/lib/python3.11/site-packages/vwsfriend/ui/vwsfriend_ui.py", line 101, in before_request_callback
vwsfriend_1   |     flask.g.dbsettings = self.app.db.session.query(Settings).first()
vwsfriend_1   |                          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
vwsfriend_1   |   File "/opt/venv/lib/python3.11/site-packages/sqlalchemy/orm/query.py", line 2752, in first
vwsfriend_1   |     return self.limit(1)._iter().first()  # type: ignore
vwsfriend_1   |            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
vwsfriend_1   |   File "/opt/venv/lib/python3.11/site-packages/sqlalchemy/orm/query.py", line 2855, in _iter
vwsfriend_1   |     result: Union[ScalarResult[_T], Result[_T]] = self.session.execute(
vwsfriend_1   |                                                   ^^^^^^^^^^^^^^^^^^^^^
vwsfriend_1   |   File "/opt/venv/lib/python3.11/site-packages/sqlalchemy/orm/session.py", line 2229, in execute
vwsfriend_1   |     return self._execute_internal(
vwsfriend_1   |            ^^^^^^^^^^^^^^^^^^^^^^^
vwsfriend_1   |   File "/opt/venv/lib/python3.11/site-packages/sqlalchemy/orm/session.py", line 2124, in _execute_internal
vwsfriend_1   |     result: Result[Any] = compile_state_cls.orm_execute_statement(
vwsfriend_1   |                           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
vwsfriend_1   |   File "/opt/venv/lib/python3.11/site-packages/sqlalchemy/orm/context.py", line 253, in orm_execute_statement
vwsfriend_1   |     result = conn.execute(
vwsfriend_1   |              ^^^^^^^^^^^^^
vwsfriend_1   |   File "/opt/venv/lib/python3.11/site-packages/sqlalchemy/engine/base.py", line 1414, in execute
vwsfriend_1   |     return meth(
vwsfriend_1   |            ^^^^^
vwsfriend_1   |   File "/opt/venv/lib/python3.11/site-packages/sqlalchemy/sql/elements.py", line 485, in _execute_on_connection
vwsfriend_1   |     return connection._execute_clauseelement(
vwsfriend_1   |            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
vwsfriend_1   |   File "/opt/venv/lib/python3.11/site-packages/sqlalchemy/engine/base.py", line 1638, in _execute_clauseelement
vwsfriend_1   |     ret = self._execute_context(
vwsfriend_1   |           ^^^^^^^^^^^^^^^^^^^^^^
vwsfriend_1   |   File "/opt/venv/lib/python3.11/site-packages/sqlalchemy/engine/base.py", line 1842, in _execute_context
vwsfriend_1   |     return self._exec_single_context(
vwsfriend_1   |            ^^^^^^^^^^^^^^^^^^^^^^^^^^
vwsfriend_1   |   File "/opt/venv/lib/python3.11/site-packages/sqlalchemy/engine/base.py", line 1983, in _exec_single_context
vwsfriend_1   |     self._handle_dbapi_exception(
vwsfriend_1   |   File "/opt/venv/lib/python3.11/site-packages/sqlalchemy/engine/base.py", line 2325, in _handle_dbapi_exception
vwsfriend_1   |     raise sqlalchemy_exception.with_traceback(exc_info[2]) from e
vwsfriend_1   |   File "/opt/venv/lib/python3.11/site-packages/sqlalchemy/engine/base.py", line 1964, in _exec_single_context
vwsfriend_1   |     self.dialect.do_execute(
vwsfriend_1   |   File "/opt/venv/lib/python3.11/site-packages/sqlalchemy/engine/default.py", line 747, in do_execute
vwsfriend_1   |     cursor.execute(statement, parameters)
vwsfriend_1   | sqlalchemy.exc.OperationalError: (psycopg2.errors.AdminShutdown) terminating connection due to administrator command
vwsfriend_1   | server closed the connection unexpectedly
vwsfriend_1   |     This probably means the server terminated abnormally
vwsfriend_1   |     before or while processing the request.
vwsfriend_1   | 
vwsfriend_1   | [SQL: SELECT settings.id AS settings_id, settings.unit_of_length AS settings_unit_of_length, settings.unit_of_temperature AS settings_unit_of_temperature, settings.grafana_url AS settings_grafana_url, settings.vwsfriend_url AS settings_vwsfriend_url, settings.locale AS settings_locale 
vwsfriend_1   | FROM settings 
vwsfriend_1   |  LIMIT %(param_1)s]
vwsfriend_1   | [parameters: {'param_1': 1}]
vwsfriend_1   | (Background on this error at: https://sqlalche.me/e/20/e3q8)
tillsteinbach commented 1 year ago

This looks like the postgres database was shutdown

amenychtas commented 1 year ago

I managed to recreate the issue either by starting / stoping charging from the charger side right after connecting the cable, or by connecting the cable and not starting the session from the charger. In the latter case a notification that "charging failed to start" is received in the WeConnect app.

Here is the log in v0.23.9:

Traceback (most recent call last):
  File "/opt/venv/bin/vwsfriend", line 8, in <module>
    sys.exit(main())
             ^^^^^^
  File "/opt/venv/lib/python3.11/site-packages/vwsfriend/vwsfriend_base.py", line 516, in main
    weConnect.update(updateCapabilities=True, updatePictures=True, force=True)
  File "/opt/venv/lib/python3.11/site-packages/weconnect/weconnect.py", line 195, in update
    self.updateComplete()
  File "/opt/venv/lib/python3.11/site-packages/weconnect/addressable.py", line 533, in updateComplete
    child.updateComplete()
  File "/opt/venv/lib/python3.11/site-packages/weconnect/addressable.py", line 533, in updateComplete
    child.updateComplete()
  File "/opt/venv/lib/python3.11/site-packages/weconnect/addressable.py", line 533, in updateComplete
    child.updateComplete()
  [Previous line repeated 3 more times]
  File "/opt/venv/lib/python3.11/site-packages/weconnect/addressable.py", line 96, in updateComplete
    observer(element=self, flags=self.onCompleteNotifyFlags)
  File "/opt/venv/lib/python3.11/site-packages/vwsfriend/agents/charge_agent.py", line 259, in __onPlugConnectionStateChange
    self.updatePosition()
  File "/opt/venv/lib/python3.11/site-packages/vwsfriend/agents/charge_agent.py", line 368, in updatePosition
    self.chargingSession.charger = chargerFromLatLonWithGeofence(weConnect=self.vehicle.weConnectVehicle.weConnect, session=self.session,
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/venv/lib/python3.11/site-packages/sqlalchemy/orm/attributes.py", line 528, in __set__
    self.impl.set(
  File "/opt/venv/lib/python3.11/site-packages/sqlalchemy/orm/attributes.py", line 1453, in set
    value = self.fire_replace_event(state, dict_, value, old, initiator)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/venv/lib/python3.11/site-packages/sqlalchemy/orm/attributes.py", line 1496, in fire_replace_event
    state._modified_event(dict_, self, previous)
  File "/opt/venv/lib/python3.11/site-packages/sqlalchemy/orm/state.py", line 926, in _modified_event
    session._autobegin_t()
  File "/opt/venv/lib/python3.11/site-packages/sqlalchemy/orm/session.py", line 1755, in _autobegin_t
    trans = SessionTransaction(
            ^^^^^^^^^^^^^^^^^^^
  File "/opt/venv/lib/python3.11/site-packages/sqlalchemy/orm/session.py", line 865, in __init__
    TransactionalContext._trans_ctx_check(session)
  File "/opt/venv/lib/python3.11/site-packages/sqlalchemy/engine/util.py", line 110, in _trans_ctx_check
    raise exc.InvalidRequestError(
sqlalchemy.exc.InvalidRequestError: Can't operate on closed transaction inside context manager.  Please complete the context manager before emitting further commands.

And here is the partially logged charging session:

image

After this error, no data are logged and the container has to be restarted. Definitely postgres is working fine. I'm thinking that this may be the cause for the other data recording issues: #442 #317 #294

blackmarlin4 commented 1 week ago

Same here. After 16 days of operation without any problem I get the following error with version 0.24.7: Restarting the container helps in my case. This error occured every time after > 10 days of operation in my case.

2024/11/26 16:19:05 stderr sqlalchemy.exc.InvalidRequestError: Can't operate on closed transaction inside context manager.  Please complete the context manager before emitting further commands.
2024/11/26 16:19:05 stderr raise exc.InvalidRequestError(
2024/11/26 16:19:05 stderr File "/opt/venv/lib/python3.12/site-packages/sqlalchemy/engine/util.py", line 111, in _trans_ctx_check
2024/11/26 16:19:05 stderr TransactionalContext._trans_ctx_check(session)
2024/11/26 16:19:05 stderr File "/opt/venv/lib/python3.12/site-packages/sqlalchemy/orm/session.py", line 931, in init
2024/11/26 16:19:05 stderr ^^^^^^^^^^^^^^^^^^^
2024/11/26 16:19:05 stderr trans = SessionTransaction(
2024/11/26 16:19:05 stderr File "/opt/venv/lib/python3.12/site-packages/sqlalchemy/orm/session.py", line 1877, in _autobegin_t
2024/11/26 16:19:05 stderr session._autobegin_t()
2024/11/26 16:19:05 stderr File "/opt/venv/lib/python3.12/site-packages/sqlalchemy/orm/state.py", line 927, in _modified_event
2024/11/26 16:19:05 stderr state._modifiedevent(dict, self, previous)
2024/11/26 16:19:05 stderr File "/opt/venv/lib/python3.12/site-packages/sqlalchemy/orm/attributes.py", line 1510, in fire_replace_event
2024/11/26 16:19:05 stderr ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024/11/26 16:19:05 stderr value = self.fire_replaceevent(state, dict, value, old, initiator)
2024/11/26 16:19:05 stderr File "/opt/venv/lib/python3.12/site-packages/sqlalchemy/orm/attributes.py", line 1467, in set
2024/11/26 16:19:05 stderr self.impl.set(
2024/11/26 16:19:05 stderr File "/opt/venv/lib/python3.12/site-packages/sqlalchemy/orm/attributes.py", line 537, in set
2024/11/26 16:19:05 stderr ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024/11/26 16:19:05 stderr self.chargingSession.charger = chargerFromLatLonWithGeofence(weConnect=self.vehicle.weConnectVehicle.weConnect, session=self.session,
2024/11/26 16:19:05 stderr File "/opt/venv/lib/python3.12/site-packages/vwsfriend/agents/charge_agent.py", line 385, in updatePosition
2024/11/26 16:19:05 stderr self.updatePosition()
2024/11/26 16:19:05 stderr File "/opt/venv/lib/python3.12/site-packages/vwsfriend/agents/charge_agent.py", line 329, in __onPlugLockStateChange
2024/11/26 16:19:05 stderr observer(element=self, flags=self.onCompleteNotifyFlags)
2024/11/26 16:19:05 stderr File "/opt/venv/lib/python3.12/site-packages/weconnect/addressable.py", line 96, in updateComplete
2024/11/26 16:19:05 stderr [Previous line repeated 3 more times]
2024/11/26 16:19:05 stderr child.updateComplete()
2024/11/26 16:19:05 stderr File "/opt/venv/lib/python3.12/site-packages/weconnect/addressable.py", line 533, in updateComplete
2024/11/26 16:19:05 stderr child.updateComplete()
2024/11/26 16:19:05 stderr File "/opt/venv/lib/python3.12/site-packages/weconnect/addressable.py", line 533, in updateComplete
2024/11/26 16:19:05 stderr child.updateComplete()
2024/11/26 16:19:05 stderr File "/opt/venv/lib/python3.12/site-packages/weconnect/addressable.py", line 533, in updateComplete
2024/11/26 16:19:05 stderr self.updateComplete()
2024/11/26 16:19:05 stderr File "/opt/venv/lib/python3.12/site-packages/weconnect/weconnect.py", line 197, in update
2024/11/26 16:19:05 stderr weConnect.update(updateCapabilities=True, updatePictures=True, force=True, selective=[Domain.ACCESS,
2024/11/26 16:19:05 stderr File "/opt/venv/lib/python3.12/site-packages/vwsfriend/vwsfriend_base.py", line 519, in main
2024/11/26 16:19:05 stderr ^^^^^^
2024/11/26 16:19:05 stderr sys.exit(main())
2024/11/26 16:19:05 stderr File "/opt/venv/bin/vwsfriend", line 8, in 
2024/11/26 16:19:05 stderr Traceback (most recent call last):