overthesun / simoc

A scalable model of an interactive, off-world community
https://ngs.simoc.space/
GNU General Public License v3.0
2 stars 1 forks source link

`MySQL Connection not available` causes InvalidRequestError until the invalid transaction is rolled back #99

Open ezio-melotti opened 4 years ago

ezio-melotti commented 4 years ago

A few days ago, MySQLconnection was not available and apparently that created an invalid transaction that locked the DB until the transaction was rolled back. Since nothing rolled that transaction back, the DB was stuck until Kai noticed and I restarted the docker.

These are the logs for the day, with an analysis at the bottom:

flask-app_1      | 2019-11-11T16:05:54.246030210Z [2019-11-11 16:05:54 +0000] [10] [DEBUG] GET /
flask-app_1      | 2019-11-11T16:05:54.358893172Z [2019-11-11 16:05:54 +0000] [10] [DEBUG] GET /static/css/app.d9faf3a0.css
flask-app_1      | 2019-11-11T16:05:54.476968109Z [2019-11-11 16:05:54 +0000] [9] [DEBUG] GET /static/js/app.2e593f14.js
flask-app_1      | 2019-11-11T16:05:54.480498479Z [2019-11-11 16:05:54 +0000] [10] [DEBUG] GET /static/js/chunk-vendors.3f565d07.js
flask-app_1      | 2019-11-11T16:05:54.556054744Z [2019-11-11 16:05:54 +0000] [10] [DEBUG] GET /static/img/mars-bg.e05b3c2b.jpg
flask-app_1      | 2019-11-11T16:05:54.925984709Z [2019-11-11 16:05:54 +0000] [10] [DEBUG] GET /static/img/simoc-logo.610cb927.svg
flask-app_1      | 2019-11-11T16:05:54.928282693Z [2019-11-11 16:05:54 +0000] [10] [DEBUG] GET /static/img/orientation.cbac6a3a.svg
flask-app_1      | 2019-11-11T16:05:54.957859637Z [2019-11-11 16:05:54 +0000] [9] [DEBUG] GET /static/fonts/nasalization-rg-webfont.45e8fdee.woff
flask-app_1      | 2019-11-11T16:05:55.083678863Z [2019-11-11 16:05:55 +0000] [9] [DEBUG] GET /favicon.ico
flask-app_1      | 2019-11-11T16:05:55.085357233Z Traceback (most recent call last):
flask-app_1      | 2019-11-11T16:05:55.085387850Z   File "/usr/local/lib/python3.6/dist-packages/flask/app.py", line 1949, in full_dispatch_request
flask-app_1      | 2019-11-11T16:05:55.085413047Z     rv = self.dispatch_request()
flask-app_1      | 2019-11-11T16:05:55.085468536Z   File "/usr/local/lib/python3.6/dist-packages/flask/app.py", line 1925, in dispatch_request
flask-app_1      | 2019-11-11T16:05:55.085496125Z     self.raise_routing_exception(req)
flask-app_1      | 2019-11-11T16:05:55.085519049Z   File "/usr/local/lib/python3.6/dist-packages/flask/app.py", line 1907, in raise_routing_exception
flask-app_1      | 2019-11-11T16:05:55.085542191Z     raise request.routing_exception
flask-app_1      | 2019-11-11T16:05:55.085563407Z   File "/usr/local/lib/python3.6/dist-packages/flask/ctx.py", line 350, in match_request
flask-app_1      | 2019-11-11T16:05:55.085586636Z     result = self.url_adapter.match(return_rule=True)
flask-app_1      | 2019-11-11T16:05:55.085608685Z   File "/usr/local/lib/python3.6/dist-packages/werkzeug/routing.py", line 1799, in match
flask-app_1      | 2019-11-11T16:05:55.085630539Z     raise NotFound()
flask-app_1      | 2019-11-11T16:05:55.085671172Z werkzeug.exceptions.NotFound: 404 Not Found: The requested URL was not found on the server. If you entered the URL manually please check your spelling and try again.
flask-app_1      | 2019-11-11T16:05:55.085697347Z [2019-11-11 16:05:55 +0000] [9] [ERROR] ERROR: handling exception 404 Not Found: The requested URL was not found on the server. If you entered the URL manually please check your spelling and try again.
flask-app_1      | 2019-11-11T16:06:08.419549824Z [2019-11-11 16:06:08 +0000] [10] [DEBUG] POST /login
flask-app_1      | 2019-11-11T16:06:08.484956092Z [2019-11-11 16:06:08 +0000] [10] [ERROR] ERROR: handling error InvalidLogin('Invalid username or password.', 401)
flask-app_1      | 2019-11-11T16:06:43.892826712Z [2019-11-11 16:06:43 +0000] [9] [DEBUG] GET /favicon.ico
flask-app_1      | 2019-11-11T16:06:43.892902425Z [2019-11-11 16:06:43 +0000] [10] [DEBUG] POST /register
flask-app_1      | 2019-11-11T16:06:43.894398536Z Traceback (most recent call last):
flask-app_1      | 2019-11-11T16:06:43.894446494Z   File "/usr/local/lib/python3.6/dist-packages/flask/app.py", line 1949, in full_dispatch_request
flask-app_1      | 2019-11-11T16:06:43.894459503Z     rv = self.dispatch_request()
flask-app_1      | 2019-11-11T16:06:43.894470984Z   File "/usr/local/lib/python3.6/dist-packages/flask/app.py", line 1925, in dispatch_request
flask-app_1      | 2019-11-11T16:06:43.894482576Z     self.raise_routing_exception(req)
flask-app_1      | 2019-11-11T16:06:43.894497067Z   File "/usr/local/lib/python3.6/dist-packages/flask/app.py", line 1907, in raise_routing_exception
flask-app_1      | 2019-11-11T16:06:43.894508251Z     raise request.routing_exception
flask-app_1      | 2019-11-11T16:06:43.894534994Z   File "/usr/local/lib/python3.6/dist-packages/flask/ctx.py", line 350, in match_request
flask-app_1      | 2019-11-11T16:06:43.894546209Z     result = self.url_adapter.match(return_rule=True)
flask-app_1      | 2019-11-11T16:06:43.894556661Z   File "/usr/local/lib/python3.6/dist-packages/werkzeug/routing.py", line 1799, in match
flask-app_1      | 2019-11-11T16:06:43.894567956Z     raise NotFound()
flask-app_1      | 2019-11-11T16:06:43.894578047Z werkzeug.exceptions.NotFound: 404 Not Found: The requested URL was not found on the server. If you entered the URL manually please check your spelling and try again.
flask-app_1      | 2019-11-11T16:06:43.894589032Z [2019-11-11 16:06:43 +0000] [9] [ERROR] ERROR: handling exception 404 Not Found: The requested URL was not found on the server. If you entered the URL manually please check your spelling and try again.
flask-app_1      | 2019-11-11T16:06:43.954960712Z [2019-11-11 16:06:43 +0000] [9] [DEBUG] GET /favicon.ico
flask-app_1      | 2019-11-11T16:06:43.955769711Z Traceback (most recent call last):
flask-app_1      | 2019-11-11T16:06:43.955790591Z   File "/usr/local/lib/python3.6/dist-packages/flask/app.py", line 1949, in full_dispatch_request
flask-app_1      | 2019-11-11T16:06:43.955803025Z     rv = self.dispatch_request()
flask-app_1      | 2019-11-11T16:06:43.955813594Z   File "/usr/local/lib/python3.6/dist-packages/flask/app.py", line 1925, in dispatch_request
flask-app_1      | 2019-11-11T16:06:43.955824205Z     self.raise_routing_exception(req)
flask-app_1      | 2019-11-11T16:06:43.955860370Z   File "/usr/local/lib/python3.6/dist-packages/flask/app.py", line 1907, in raise_routing_exception
flask-app_1      | 2019-11-11T16:06:43.955873359Z     raise request.routing_exception
flask-app_1      | 2019-11-11T16:06:43.955883817Z   File "/usr/local/lib/python3.6/dist-packages/flask/ctx.py", line 350, in match_request
flask-app_1      | 2019-11-11T16:06:43.955894366Z     result = self.url_adapter.match(return_rule=True)
flask-app_1      | 2019-11-11T16:06:43.955904694Z   File "/usr/local/lib/python3.6/dist-packages/werkzeug/routing.py", line 1799, in match
flask-app_1      | 2019-11-11T16:06:43.955915203Z     raise NotFound()
flask-app_1      | 2019-11-11T16:06:43.955925678Z werkzeug.exceptions.NotFound: 404 Not Found: The requested URL was not found on the server. If you entered the URL manually please check your spelling and try again.
flask-app_1      | 2019-11-11T16:06:43.955936446Z [2019-11-11 16:06:43 +0000] [9] [ERROR] ERROR: handling exception 404 Not Found: The requested URL was not found on the server. If you entered the URL manually please check your spelling and try again.
flask-app_1      | 2019-11-11T16:06:44.095727458Z [2019-11-11 16:06:44 +0000] [10] [INFO] STATUS: Registration complete.
flask-app_1      | 2019-11-11T16:06:55.023412035Z [2019-11-11 16:06:55 +0000] [10] [DEBUG] GET /get_agent_types
flask-app_1      | 2019-11-11T16:10:32.985134883Z [2019-11-11 16:10:32 +0000] [9] [DEBUG] POST /new_game
celery-worker_2  | 2019-11-11T16:10:33.105825963Z [2019-11-11 16:10:33,104: INFO/MainProcess] Received task: celery_worker.tasks.new_game[301319d1-687d-46fb-a5d7-d1d32ee74a6a]  
celery-worker_2  | 2019-11-11T16:10:33.106397627Z [2019-11-11 16:10:33,105: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x7f00b3f84a60> (args:('celery_worker.tasks.new_game', '301319d1-687d-46fb-a5d7-d1d32ee74a6a', {'lang': 'py', 'task': 'celery_worker.tasks.new_game', 'id': '301319d1-687d-46fb-a5d7-d1d32ee74a6a', 'shadow': None, 'eta': None, 'expires': None, 'group': None, 'retries': 0, 'timelimit': [None, None], 'root_id': '301319d1-687d-46fb-a5d7-d1d32ee74a6a', 'parent_id': None, 'argsrepr': "('marquin', {'agents': {'human_agent': [...], 'solid_waste_aerobic_bioreactor': [...], 'multifiltration_purifier_post_treament': [...], 'oxygen_generation_SFWE': [...], 'urine_recycling_processor_VCD': [...], 'co2_removal_SAWD': [...], 'co2_reduction_sabatier': [...], 'crew_habitat_small': [...], 'solar_pv_array_mars': [...]}, 'storages': {'air_storage': [...], 'water_storage': [...], 'nutrient_storage': [...], 'power_storage': [...], 'food_storage': [...]}, 'termination': [{...}], 'single_agent': 1})", 'kwargsrepr': '{}', 'origin': 'gen9@a0d0c214c8a9', 'reply_to': '4e8724d3-904e-3195-b576-4bf8269aa98b', 'correlation_id':... kwargs:{})
celery-worker_2  | 2019-11-11T16:10:33.110989637Z [2019-11-11 16:10:33,110: DEBUG/MainProcess] Task accepted: celery_worker.tasks.new_game[301319d1-687d-46fb-a5d7-d1d32ee74a6a] pid:8904
celery-worker_2  | 2019-11-11T16:10:33.132437004Z [2019-11-11 16:10:33,130: ERROR/ForkPoolWorker-3] Task celery_worker.tasks.new_game[301319d1-687d-46fb-a5d7-d1d32ee74a6a] raised unexpected: OperationalError('(mysql.connector.errors.OperationalError) MySQL Connection not available.',)
celery-worker_2  | 2019-11-11T16:10:33.132493352Z Traceback (most recent call last):
celery-worker_2  | 2019-11-11T16:10:33.132506170Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1179, in _execute_context
celery-worker_2  | 2019-11-11T16:10:33.132518561Z     context = constructor(dialect, self, conn, *args)
celery-worker_2  | 2019-11-11T16:10:33.132530217Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/default.py", line 716, in _init_compiled
celery-worker_2  | 2019-11-11T16:10:33.132542313Z     self.cursor = self.create_cursor()
celery-worker_2  | 2019-11-11T16:10:33.132579986Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/default.py", line 1070, in create_cursor
celery-worker_2  | 2019-11-11T16:10:33.132593736Z     return self._dbapi_connection.cursor()
celery-worker_2  | 2019-11-11T16:10:33.132605368Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/pool/base.py", line 965, in cursor
celery-worker_2  | 2019-11-11T16:10:33.132617358Z     return self.connection.cursor(*args, **kwargs)
celery-worker_2  | 2019-11-11T16:10:33.132628945Z   File "/usr/local/lib/python3.6/dist-packages/mysql/connector/connection_cext.py", line 524, in cursor
celery-worker_2  | 2019-11-11T16:10:33.132640894Z     raise errors.OperationalError("MySQL Connection not available.")
celery-worker_2  | 2019-11-11T16:10:33.132653146Z mysql.connector.errors.OperationalError: MySQL Connection not available.
celery-worker_2  | 2019-11-11T16:10:33.132665231Z 
celery-worker_2  | 2019-11-11T16:10:33.132676486Z The above exception was the direct cause of the following exception:
celery-worker_2  | 2019-11-11T16:10:33.132688111Z 
celery-worker_2  | 2019-11-11T16:10:33.132699274Z Traceback (most recent call last):
celery-worker_2  | 2019-11-11T16:10:33.132710675Z   File "/usr/local/lib/python3.6/dist-packages/celery/app/trace.py", line 385, in trace_task
celery-worker_2  | 2019-11-11T16:10:33.132722519Z     R = retval = fun(*args, **kwargs)
celery-worker_2  | 2019-11-11T16:10:33.132733919Z   File "/usr/local/lib/python3.6/dist-packages/celery/app/trace.py", line 648, in __protected_call__
celery-worker_2  | 2019-11-11T16:10:33.132745712Z     return self.run(*args, **kwargs)
celery-worker_2  | 2019-11-11T16:10:33.132757107Z   File "/simoc/celery_worker/tasks.py", line 64, in new_game
celery-worker_2  | 2019-11-11T16:10:33.132769487Z     user = get_user(username)
celery-worker_2  | 2019-11-11T16:10:33.132780840Z   File "/simoc/celery_worker/tasks.py", line 34, in get_user
celery-worker_2  | 2019-11-11T16:10:33.132792404Z     user = User.query.filter_by(username=username).all()
celery-worker_2  | 2019-11-11T16:10:33.132803963Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py", line 3186, in all
celery-worker_2  | 2019-11-11T16:10:33.132815857Z     return list(self)
celery-worker_2  | 2019-11-11T16:10:33.132827312Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py", line 3342, in __iter__
celery-worker_2  | 2019-11-11T16:10:33.132870183Z     return self._execute_and_instances(context)
celery-worker_2  | 2019-11-11T16:10:33.132903080Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py", line 3367, in _execute_and_instances
celery-worker_2  | 2019-11-11T16:10:33.132916100Z     result = conn.execute(querycontext.statement, self._params)
celery-worker_2  | 2019-11-11T16:10:33.132927852Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 988, in execute
celery-worker_2  | 2019-11-11T16:10:33.132939679Z     return meth(self, multiparams, params)
celery-worker_2  | 2019-11-11T16:10:33.132951277Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/sql/elements.py", line 287, in _execute_on_connection
celery-worker_2  | 2019-11-11T16:10:33.132963206Z     return connection._execute_clauseelement(self, multiparams, params)
celery-worker_2  | 2019-11-11T16:10:33.132975371Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1107, in _execute_clauseelement
celery-worker_2  | 2019-11-11T16:10:33.132994116Z     distilled_params,
celery-worker_2  | 2019-11-11T16:10:33.133006819Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1182, in _execute_context
celery-worker_2  | 2019-11-11T16:10:33.133018512Z     e, util.text_type(statement), parameters, None, None
celery-worker_2  | 2019-11-11T16:10:33.133030125Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1473, in _handle_dbapi_exception
celery-worker_2  | 2019-11-11T16:10:33.133042110Z     util.raise_from_cause(sqlalchemy_exception, exc_info)
celery-worker_2  | 2019-11-11T16:10:33.133053990Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/util/compat.py", line 398, in raise_from_cause
celery-worker_2  | 2019-11-11T16:10:33.133066588Z     reraise(type(exception), exception, tb=exc_tb, cause=cause)
celery-worker_2  | 2019-11-11T16:10:33.133078219Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/util/compat.py", line 152, in reraise
celery-worker_2  | 2019-11-11T16:10:33.133090028Z     raise value.with_traceback(tb)
celery-worker_2  | 2019-11-11T16:10:33.133101377Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1179, in _execute_context
celery-worker_2  | 2019-11-11T16:10:33.133112919Z     context = constructor(dialect, self, conn, *args)
celery-worker_2  | 2019-11-11T16:10:33.133124439Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/default.py", line 716, in _init_compiled
celery-worker_2  | 2019-11-11T16:10:33.133136020Z     self.cursor = self.create_cursor()
celery-worker_2  | 2019-11-11T16:10:33.133147479Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/default.py", line 1070, in create_cursor
celery-worker_2  | 2019-11-11T16:10:33.133160101Z     return self._dbapi_connection.cursor()
celery-worker_2  | 2019-11-11T16:10:33.133171609Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/pool/base.py", line 965, in cursor
celery-worker_2  | 2019-11-11T16:10:33.133183145Z     return self.connection.cursor(*args, **kwargs)
celery-worker_2  | 2019-11-11T16:10:33.133194615Z   File "/usr/local/lib/python3.6/dist-packages/mysql/connector/connection_cext.py", line 524, in cursor
celery-worker_2  | 2019-11-11T16:10:33.133206438Z     raise errors.OperationalError("MySQL Connection not available.")
celery-worker_2  | 2019-11-11T16:10:33.133219239Z sqlalchemy.exc.OperationalError: (mysql.connector.errors.OperationalError) MySQL Connection not available.
celery-worker_2  | 2019-11-11T16:10:33.133231282Z [SQL: SELECT user.id AS user_id, user.username AS user_username, user.password_hash AS user_password_hash, user.date_created AS user_date_created, user.date_modified AS user_date_modified 
celery-worker_2  | 2019-11-11T16:10:33.133243870Z FROM user 
celery-worker_2  | 2019-11-11T16:10:33.133255158Z WHERE user.username = %(username_1)s]
celery-worker_2  | 2019-11-11T16:10:33.133266532Z [parameters: [{}]]
celery-worker_2  | 2019-11-11T16:10:33.133277833Z (Background on this error at: http://sqlalche.me/e/e3q8)
flask-app_1      | 2019-11-11T16:10:34.472292720Z [2019-11-11 16:10:34 +0000] [10] [DEBUG] POST /new_game
celery-worker_1  | 2019-11-11T16:10:34.535419449Z [2019-11-11 16:10:34,534: INFO/MainProcess] Received task: celery_worker.tasks.new_game[fc8f43ec-c728-4c8b-ab1e-2fccf198ad6b]  
celery-worker_1  | 2019-11-11T16:10:34.535775990Z [2019-11-11 16:10:34,535: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x7ff1ca9bb9d8> (args:('celery_worker.tasks.new_game', 'fc8f43ec-c728-4c8b-ab1e-2fccf198ad6b', {'lang': 'py', 'task': 'celery_worker.tasks.new_game', 'id': 'fc8f43ec-c728-4c8b-ab1e-2fccf198ad6b', 'shadow': None, 'eta': None, 'expires': None, 'group': None, 'retries': 0, 'timelimit': [None, None], 'root_id': 'fc8f43ec-c728-4c8b-ab1e-2fccf198ad6b', 'parent_id': None, 'argsrepr': "('marquin', {'agents': {'human_agent': [...], 'solid_waste_aerobic_bioreactor': [...], 'multifiltration_purifier_post_treament': [...], 'oxygen_generation_SFWE': [...], 'urine_recycling_processor_VCD': [...], 'co2_removal_SAWD': [...], 'co2_reduction_sabatier': [...], 'crew_habitat_small': [...], 'solar_pv_array_mars': [...]}, 'storages': {'air_storage': [...], 'water_storage': [...], 'nutrient_storage': [...], 'power_storage': [...], 'food_storage': [...]}, 'termination': [{...}], 'single_agent': 1})", 'kwargsrepr': '{}', 'origin': 'gen10@a0d0c214c8a9', 'reply_to': '1d83a10a-bd14-3594-b548-1af402ba2725', 'correlation_id':... kwargs:{})
celery-worker_1  | 2019-11-11T16:10:34.540762015Z [2019-11-11 16:10:34,540: DEBUG/MainProcess] Task accepted: celery_worker.tasks.new_game[fc8f43ec-c728-4c8b-ab1e-2fccf198ad6b] pid:10729
celery-worker_1  | 2019-11-11T16:10:34.841624609Z [2019-11-11 16:10:34,840: INFO/ForkPoolWorker-7] Task celery_worker.tasks.new_game[fc8f43ec-c728-4c8b-ab1e-2fccf198ad6b] succeeded in 0.3012387230992317s: {'worker_hostname': 'worker@47b1f9e9dd75', 'game_id': 8690493015110446075}
flask-app_1      | 2019-11-11T16:10:34.846940289Z [2019-11-11 16:10:34 +0000] [10] [INFO] STATUS: New game starts.
flask-app_1      | 2019-11-11T16:10:35.041610389Z [2019-11-11 16:10:35 +0000] [10] [DEBUG] POST /get_step_to
flask-app_1      | 2019-11-11T16:10:35.049327092Z [2019-11-11 16:10:35 +0000] [10] [INFO] STATUS: Steps requested.
celery-worker_1  | 2019-11-11T16:10:35.051267185Z [2019-11-11 16:10:35,050: INFO/MainProcess] Received task: celery_worker.tasks.get_step_to[77a155f1-578d-4c39-84d3-1445b6ade149]  
celery-worker_1  | 2019-11-11T16:10:35.051445210Z [2019-11-11 16:10:35,050: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x7ff1ca9bb9d8> (args:('celery_worker.tasks.get_step_to', '77a155f1-578d-4c39-84d3-1445b6ade149', {'lang': 'py', 'task': 'celery_worker.tasks.get_step_to', 'id': '77a155f1-578d-4c39-84d3-1445b6ade149', 'shadow': None, 'eta': None, 'expires': None, 'group': None, 'retries': 0, 'timelimit': [None, None], 'root_id': '77a155f1-578d-4c39-84d3-1445b6ade149', 'parent_id': None, 'argsrepr': "['marquin', 240]", 'kwargsrepr': '{}', 'origin': 'gen10@a0d0c214c8a9', 'reply_to': '1d83a10a-bd14-3594-b548-1af402ba2725', 'correlation_id': '77a155f1-578d-4c39-84d3-1445b6ade149', 'delivery_info': {'exchange': '', 'routing_key': 'worker@47b1f9e9dd75.dq2', 'priority': 0, 'redelivered': None}}, b'[["marquin", 240], {}, {"callbacks": null, "errbacks": null, "chain": null, "chord": null}]', 'application/json', 'utf-8') kwargs:{})
celery-worker_1  | 2019-11-11T16:10:35.055635094Z [2019-11-11 16:10:35,055: DEBUG/MainProcess] Task accepted: celery_worker.tasks.get_step_to[77a155f1-578d-4c39-84d3-1445b6ade149] pid:10729
celery-worker_1  | 2019-11-11T16:10:35.145635678Z [2019-11-11 16:10:35,145: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 1
celery-worker_1  | 2019-11-11T16:10:35.267577109Z [2019-11-11 16:10:35,267: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 2
celery-worker_1  | 2019-11-11T16:10:35.389390457Z [2019-11-11 16:10:35,389: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 3
celery-worker_1  | 2019-11-11T16:10:35.515318330Z [2019-11-11 16:10:35,514: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 4
celery-worker_1  | 2019-11-11T16:10:35.636580595Z [2019-11-11 16:10:35,636: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 5
celery-worker_1  | 2019-11-11T16:10:35.757944574Z [2019-11-11 16:10:35,757: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 6
celery-worker_1  | 2019-11-11T16:10:35.880026536Z [2019-11-11 16:10:35,879: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 7
celery-worker_1  | 2019-11-11T16:10:36.001780506Z [2019-11-11 16:10:36,001: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 8
celery-worker_1  | 2019-11-11T16:10:36.128636155Z [2019-11-11 16:10:36,127: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 9
celery-worker_1  | 2019-11-11T16:10:36.250367376Z [2019-11-11 16:10:36,249: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 10
celery-worker_1  | 2019-11-11T16:10:36.546153338Z [2019-11-11 16:10:36,545: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 11
celery-worker_1  | 2019-11-11T16:10:36.668100551Z [2019-11-11 16:10:36,667: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 12
celery-worker_1  | 2019-11-11T16:10:36.790269412Z [2019-11-11 16:10:36,789: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 13
celery-worker_1  | 2019-11-11T16:10:36.912164094Z [2019-11-11 16:10:36,911: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 14
celery-worker_1  | 2019-11-11T16:10:37.034586349Z [2019-11-11 16:10:37,034: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 15
flask-app_1      | 2019-11-11T16:10:37.110185913Z Traceback (most recent call last):
flask-app_1      | 2019-11-11T16:10:37.110214212Z   File "src/gevent/greenlet.py", line 766, in gevent._greenlet.Greenlet.run
flask-app_1      | 2019-11-11T16:10:37.110228270Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 82, in run
flask-app_1      | 2019-11-11T16:10:37.110240701Z     self.result_consumer.drain_events(timeout=1)
flask-app_1      | 2019-11-11T16:10:37.110252272Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/redis.py", line 129, in drain_events
flask-app_1      | 2019-11-11T16:10:37.110264109Z     self.on_state_change(self._decode_result(message['data']), message)
flask-app_1      | 2019-11-11T16:10:37.110275607Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/base.py", line 305, in decode_result
flask-app_1      | 2019-11-11T16:10:37.110288167Z     return self.meta_from_decoded(self.decode(payload))
flask-app_1      | 2019-11-11T16:10:37.110312070Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/base.py", line 301, in meta_from_decoded
flask-app_1      | 2019-11-11T16:10:37.110325421Z     meta['result'] = self.exception_to_python(meta['result'])
flask-app_1      | 2019-11-11T16:10:37.110336752Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/base.py", line 281, in exception_to_python
flask-app_1      | 2019-11-11T16:10:37.110348474Z     exc = cls(*exc_msg if isinstance(exc_msg, tuple) else exc_msg)
flask-app_1      | 2019-11-11T16:10:37.110359871Z TypeError: __init__() missing 2 required positional arguments: 'params' and 'orig'
flask-app_1      | 2019-11-11T16:10:37.110371365Z 2019-11-11T16:10:33Z <Greenlet at 0x7f5c2a7a1248: <bound method greenletDrainer.run of <celery.backends.asynchronous.geventDrainer object at 0x7f5c2a955780>>> failed with TypeError
flask-app_1      | 2019-11-11T16:10:37.110384818Z 
flask-app_1      | 2019-11-11T16:10:37.110396848Z [2019-11-11 16:10:37 +0000] [9] [DEBUG] POST /get_steps
celery-worker_1  | 2019-11-11T16:10:37.156713089Z [2019-11-11 16:10:37,156: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 16
celery-worker_1  | 2019-11-11T16:10:37.280381375Z [2019-11-11 16:10:37,279: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 17
celery-worker_1  | 2019-11-11T16:10:37.410056779Z [2019-11-11 16:10:37,409: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 18
celery-worker_1  | 2019-11-11T16:10:37.542429294Z [2019-11-11 16:10:37,541: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 19
flask-app_1      | 2019-11-11T16:10:37.597712377Z [2019-11-11 16:10:37 +0000] [9] [INFO] STATUS: Step data retrieved.
celery-worker_1  | 2019-11-11T16:10:37.667218694Z [2019-11-11 16:10:37,666: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 20
celery-worker_1  | 2019-11-11T16:10:37.912611085Z [2019-11-11 16:10:37,912: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 21
celery-worker_1  | 2019-11-11T16:10:38.036991479Z [2019-11-11 16:10:38,036: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 22
celery-worker_1  | 2019-11-11T16:10:38.163746327Z [2019-11-11 16:10:38,163: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 23
celery-worker_1  | 2019-11-11T16:10:38.290652171Z [2019-11-11 16:10:38,290: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 24
celery-worker_1  | 2019-11-11T16:10:38.418528153Z [2019-11-11 16:10:38,418: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 25
celery-worker_1  | 2019-11-11T16:10:38.552537440Z [2019-11-11 16:10:38,552: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 26
celery-worker_1  | 2019-11-11T16:10:38.681031109Z [2019-11-11 16:10:38,680: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 27
celery-worker_1  | 2019-11-11T16:10:38.810324107Z [2019-11-11 16:10:38,809: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 28
celery-worker_1  | 2019-11-11T16:10:38.939479281Z [2019-11-11 16:10:38,939: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 29
celery-worker_1  | 2019-11-11T16:10:39.070031068Z [2019-11-11 16:10:39,069: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 30
celery-worker_1  | 2019-11-11T16:10:39.310051675Z [2019-11-11 16:10:39,309: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 31
celery-worker_1  | 2019-11-11T16:10:39.439300835Z [2019-11-11 16:10:39,438: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 32
celery-worker_1  | 2019-11-11T16:10:39.567969441Z [2019-11-11 16:10:39,567: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 33
celery-worker_1  | 2019-11-11T16:10:39.697101145Z [2019-11-11 16:10:39,696: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 34
flask-app_1      | 2019-11-11T16:10:39.806933720Z [2019-11-11 16:10:39 +0000] [10] [DEBUG] POST /get_steps
celery-worker_1  | 2019-11-11T16:10:39.826037318Z [2019-11-11 16:10:39,825: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 35
celery-worker_1  | 2019-11-11T16:10:39.954651306Z [2019-11-11 16:10:39,954: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 36
celery-worker_1  | 2019-11-11T16:10:40.084328771Z [2019-11-11 16:10:40,083: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 37
flask-app_1      | 2019-11-11T16:10:40.111908035Z [2019-11-11 16:10:40 +0000] [10] [INFO] STATUS: Step data retrieved.
celery-worker_1  | 2019-11-11T16:10:40.215846029Z [2019-11-11 16:10:40,215: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 38
celery-worker_1  | 2019-11-11T16:10:40.345681640Z [2019-11-11 16:10:40,345: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 39
celery-worker_1  | 2019-11-11T16:10:40.475685592Z [2019-11-11 16:10:40,475: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 40
celery-worker_1  | 2019-11-11T16:10:40.716114317Z [2019-11-11 16:10:40,715: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 41
celery-worker_1  | 2019-11-11T16:10:40.846032510Z [2019-11-11 16:10:40,845: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 42
celery-worker_1  | 2019-11-11T16:10:40.973776738Z [2019-11-11 16:10:40,973: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 43
celery-worker_1  | 2019-11-11T16:10:41.101562519Z [2019-11-11 16:10:41,101: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 44
celery-worker_1  | 2019-11-11T16:10:41.229519774Z [2019-11-11 16:10:41,229: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 45
celery-worker_1  | 2019-11-11T16:10:41.357113947Z [2019-11-11 16:10:41,356: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 46
celery-worker_1  | 2019-11-11T16:10:41.485604322Z [2019-11-11 16:10:41,485: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 47
celery-worker_1  | 2019-11-11T16:10:41.611426867Z [2019-11-11 16:10:41,611: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 48
celery-worker_1  | 2019-11-11T16:10:41.739646633Z [2019-11-11 16:10:41,739: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 49
celery-worker_1  | 2019-11-11T16:10:41.867422861Z [2019-11-11 16:10:41,867: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 50
celery-worker_1  | 2019-11-11T16:10:42.121347497Z [2019-11-11 16:10:42,120: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 51
flask-app_1      | 2019-11-11T16:10:42.224145919Z [2019-11-11 16:10:42 +0000] [9] [DEBUG] POST /get_steps
celery-worker_1  | 2019-11-11T16:10:42.251811600Z [2019-11-11 16:10:42,251: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 52
celery-worker_1  | 2019-11-11T16:10:42.382699108Z [2019-11-11 16:10:42,382: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 53
celery-worker_1  | 2019-11-11T16:10:42.512594870Z [2019-11-11 16:10:42,512: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 54
flask-app_1      | 2019-11-11T16:10:42.527681208Z [2019-11-11 16:10:42 +0000] [9] [INFO] STATUS: Step data retrieved.
celery-worker_1  | 2019-11-11T16:10:42.645551923Z [2019-11-11 16:10:42,645: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 55
celery-worker_1  | 2019-11-11T16:10:42.775636905Z [2019-11-11 16:10:42,775: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 56
celery-worker_1  | 2019-11-11T16:10:42.906323428Z [2019-11-11 16:10:42,906: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 57
celery-worker_1  | 2019-11-11T16:10:43.036372286Z [2019-11-11 16:10:43,036: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 58
celery-worker_1  | 2019-11-11T16:10:43.167162097Z [2019-11-11 16:10:43,166: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 59
celery-worker_1  | 2019-11-11T16:10:43.297729566Z [2019-11-11 16:10:43,297: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 60
celery-worker_1  | 2019-11-11T16:10:43.544322549Z [2019-11-11 16:10:43,544: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 61
celery-worker_1  | 2019-11-11T16:10:43.674510543Z [2019-11-11 16:10:43,673: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 62
celery-worker_1  | 2019-11-11T16:10:43.805442582Z [2019-11-11 16:10:43,805: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 63
celery-worker_1  | 2019-11-11T16:10:43.935202061Z [2019-11-11 16:10:43,934: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 64
celery-worker_1  | 2019-11-11T16:10:44.065201812Z [2019-11-11 16:10:44,064: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 65
celery-worker_1  | 2019-11-11T16:10:44.193913486Z [2019-11-11 16:10:44,193: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 66
celery-worker_1  | 2019-11-11T16:10:44.324756479Z [2019-11-11 16:10:44,324: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 67
celery-worker_1  | 2019-11-11T16:10:44.453565576Z [2019-11-11 16:10:44,453: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 68
celery-worker_1  | 2019-11-11T16:10:44.582796817Z [2019-11-11 16:10:44,582: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 69
celery-worker_1  | 2019-11-11T16:10:44.711663179Z [2019-11-11 16:10:44,711: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 70
flask-app_1      | 2019-11-11T16:10:44.728441615Z [2019-11-11 16:10:44 +0000] [10] [DEBUG] POST /get_steps
celery-worker_1  | 2019-11-11T16:10:44.956576145Z [2019-11-11 16:10:44,956: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 71
celery-worker_1  | 2019-11-11T16:10:45.083166967Z [2019-11-11 16:10:45,082: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 72
flask-app_1      | 2019-11-11T16:10:45.189626791Z [2019-11-11 16:10:45 +0000] [10] [INFO] STATUS: Step data retrieved.
celery-worker_1  | 2019-11-11T16:10:45.212315595Z [2019-11-11 16:10:45,211: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 73
celery-worker_1  | 2019-11-11T16:10:45.342206699Z [2019-11-11 16:10:45,341: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 74
celery-worker_1  | 2019-11-11T16:10:45.472096794Z [2019-11-11 16:10:45,471: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 75
celery-worker_1  | 2019-11-11T16:10:45.602036345Z [2019-11-11 16:10:45,601: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 76
celery-worker_1  | 2019-11-11T16:10:45.732253370Z [2019-11-11 16:10:45,731: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 77
celery-worker_1  | 2019-11-11T16:10:45.863258410Z [2019-11-11 16:10:45,862: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 78
celery-worker_1  | 2019-11-11T16:10:45.992958474Z [2019-11-11 16:10:45,992: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 79
celery-worker_1  | 2019-11-11T16:10:46.122793010Z [2019-11-11 16:10:46,122: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 80
celery-worker_1  | 2019-11-11T16:10:46.376103367Z [2019-11-11 16:10:46,375: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 81
celery-worker_1  | 2019-11-11T16:10:46.506430798Z [2019-11-11 16:10:46,506: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 82
celery-worker_1  | 2019-11-11T16:10:46.636495284Z [2019-11-11 16:10:46,636: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 83
celery-worker_1  | 2019-11-11T16:10:46.767988483Z [2019-11-11 16:10:46,767: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 84
celery-worker_1  | 2019-11-11T16:10:46.898545627Z [2019-11-11 16:10:46,898: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 85
celery-worker_1  | 2019-11-11T16:10:47.026981469Z [2019-11-11 16:10:47,026: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 86
celery-worker_1  | 2019-11-11T16:10:47.155605962Z [2019-11-11 16:10:47,155: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 87
celery-worker_1  | 2019-11-11T16:10:47.283993180Z [2019-11-11 16:10:47,283: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 88
flask-app_1      | 2019-11-11T16:10:47.350716710Z [2019-11-11 16:10:47 +0000] [10] [DEBUG] POST /get_steps
celery-worker_1  | 2019-11-11T16:10:47.412802736Z [2019-11-11 16:10:47,412: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 89
celery-worker_1  | 2019-11-11T16:10:47.541027216Z [2019-11-11 16:10:47,540: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 90
flask-app_1      | 2019-11-11T16:10:47.662822284Z [2019-11-11 16:10:47 +0000] [10] [INFO] STATUS: Step data retrieved.
celery-worker_1  | 2019-11-11T16:10:47.795325814Z [2019-11-11 16:10:47,794: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 91
celery-worker_1  | 2019-11-11T16:10:47.925722076Z [2019-11-11 16:10:47,925: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 92
celery-worker_1  | 2019-11-11T16:10:48.056267959Z [2019-11-11 16:10:48,055: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 93
celery-worker_1  | 2019-11-11T16:10:48.186277752Z [2019-11-11 16:10:48,185: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 94
celery-worker_1  | 2019-11-11T16:10:48.315978731Z [2019-11-11 16:10:48,315: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 95
celery-worker_1  | 2019-11-11T16:10:48.447073375Z [2019-11-11 16:10:48,446: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 96
celery-worker_1  | 2019-11-11T16:10:48.577293939Z [2019-11-11 16:10:48,576: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 97
celery-worker_1  | 2019-11-11T16:10:48.707469633Z [2019-11-11 16:10:48,707: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 98
celery-worker_1  | 2019-11-11T16:10:48.837581641Z [2019-11-11 16:10:48,837: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 99
celery-worker_1  | 2019-11-11T16:10:48.968102316Z [2019-11-11 16:10:48,967: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 100
celery-worker_1  | 2019-11-11T16:10:49.221682313Z [2019-11-11 16:10:49,221: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 101
celery-worker_1  | 2019-11-11T16:10:49.353239561Z [2019-11-11 16:10:49,352: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 102
celery-worker_1  | 2019-11-11T16:10:49.481958508Z [2019-11-11 16:10:49,481: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 103
celery-worker_1  | 2019-11-11T16:10:49.610959788Z [2019-11-11 16:10:49,610: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 104
celery-worker_1  | 2019-11-11T16:10:49.741920004Z [2019-11-11 16:10:49,741: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 105
celery-worker_1  | 2019-11-11T16:10:49.870620242Z [2019-11-11 16:10:49,870: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 106
celery-worker_1  | 2019-11-11T16:10:50.000118586Z [2019-11-11 16:10:49,999: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 107
flask-app_1      | 2019-11-11T16:10:50.015644631Z [2019-11-11 16:10:50 +0000] [10] [DEBUG] POST /get_steps
celery-worker_1  | 2019-11-11T16:10:50.128932684Z [2019-11-11 16:10:50,128: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 108
celery-worker_1  | 2019-11-11T16:10:50.258170431Z [2019-11-11 16:10:50,257: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 109
flask-app_1      | 2019-11-11T16:10:50.321047692Z [2019-11-11 16:10:50 +0000] [10] [INFO] STATUS: Step data retrieved.
celery-worker_1  | 2019-11-11T16:10:50.391728677Z [2019-11-11 16:10:50,391: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 110
celery-worker_1  | 2019-11-11T16:10:50.651213449Z [2019-11-11 16:10:50,650: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 111
celery-worker_1  | 2019-11-11T16:10:50.784752831Z [2019-11-11 16:10:50,784: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 112
celery-worker_1  | 2019-11-11T16:10:50.917529316Z [2019-11-11 16:10:50,917: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 113
celery-worker_1  | 2019-11-11T16:10:51.051553403Z [2019-11-11 16:10:51,051: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 114
celery-worker_1  | 2019-11-11T16:10:51.185711946Z [2019-11-11 16:10:51,185: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 115
celery-worker_1  | 2019-11-11T16:10:51.322874613Z [2019-11-11 16:10:51,321: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 116
celery-worker_1  | 2019-11-11T16:10:51.455152471Z [2019-11-11 16:10:51,454: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 117
celery-worker_1  | 2019-11-11T16:10:51.589311935Z [2019-11-11 16:10:51,588: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 118
celery-worker_1  | 2019-11-11T16:10:51.722584104Z [2019-11-11 16:10:51,722: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 119
celery-worker_1  | 2019-11-11T16:10:51.854256037Z [2019-11-11 16:10:51,853: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 120
celery-worker_1  | 2019-11-11T16:10:52.102387971Z [2019-11-11 16:10:52,102: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 121
celery-worker_1  | 2019-11-11T16:10:52.233279375Z [2019-11-11 16:10:52,232: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 122
celery-worker_1  | 2019-11-11T16:10:52.363222838Z [2019-11-11 16:10:52,362: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 123
celery-worker_1  | 2019-11-11T16:10:52.492454632Z [2019-11-11 16:10:52,492: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 124
flask-app_1      | 2019-11-11T16:10:52.553297500Z [2019-11-11 16:10:52 +0000] [10] [DEBUG] POST /get_steps
celery-worker_1  | 2019-11-11T16:10:52.621709792Z [2019-11-11 16:10:52,621: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 125
celery-worker_1  | 2019-11-11T16:10:52.751337864Z [2019-11-11 16:10:52,750: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 126
flask-app_1      | 2019-11-11T16:10:52.866390699Z [2019-11-11 16:10:52 +0000] [10] [INFO] STATUS: Step data retrieved.
celery-worker_1  | 2019-11-11T16:10:52.882574713Z [2019-11-11 16:10:52,882: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 127
celery-worker_1  | 2019-11-11T16:10:53.011658693Z [2019-11-11 16:10:53,011: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 128
celery-worker_1  | 2019-11-11T16:10:53.142169378Z [2019-11-11 16:10:53,141: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 129
celery-worker_1  | 2019-11-11T16:10:53.271512523Z [2019-11-11 16:10:53,271: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 130
celery-worker_1  | 2019-11-11T16:10:53.516591918Z [2019-11-11 16:10:53,516: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 131
celery-worker_1  | 2019-11-11T16:10:53.647668578Z [2019-11-11 16:10:53,647: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 132
celery-worker_1  | 2019-11-11T16:10:53.777563733Z [2019-11-11 16:10:53,777: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 133
celery-worker_1  | 2019-11-11T16:10:53.908195751Z [2019-11-11 16:10:53,907: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 134
celery-worker_1  | 2019-11-11T16:10:54.036876666Z [2019-11-11 16:10:54,036: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 135
celery-worker_1  | 2019-11-11T16:10:54.164977354Z [2019-11-11 16:10:54,164: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 136
celery-worker_1  | 2019-11-11T16:10:54.293674917Z [2019-11-11 16:10:54,293: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 137
celery-worker_1  | 2019-11-11T16:10:54.422250970Z [2019-11-11 16:10:54,421: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 138
celery-worker_1  | 2019-11-11T16:10:54.551202741Z [2019-11-11 16:10:54,550: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 139
celery-worker_1  | 2019-11-11T16:10:54.679952152Z [2019-11-11 16:10:54,679: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 140
celery-worker_1  | 2019-11-11T16:10:54.926444074Z [2019-11-11 16:10:54,926: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 141
celery-worker_1  | 2019-11-11T16:10:55.057650547Z [2019-11-11 16:10:55,057: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 142
flask-app_1      | 2019-11-11T16:10:55.071486945Z [2019-11-11 16:10:55 +0000] [10] [DEBUG] POST /get_steps
celery-worker_1  | 2019-11-11T16:10:55.187182134Z [2019-11-11 16:10:55,186: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 143
celery-worker_1  | 2019-11-11T16:10:55.314214265Z [2019-11-11 16:10:55,313: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 144
flask-app_1      | 2019-11-11T16:10:55.386681483Z [2019-11-11 16:10:55 +0000] [10] [INFO] STATUS: Step data retrieved.
celery-worker_1  | 2019-11-11T16:10:55.443077492Z [2019-11-11 16:10:55,442: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 145
celery-worker_1  | 2019-11-11T16:10:55.572387889Z [2019-11-11 16:10:55,571: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 146
celery-worker_1  | 2019-11-11T16:10:55.701279408Z [2019-11-11 16:10:55,700: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 147
celery-worker_1  | 2019-11-11T16:10:55.831946767Z [2019-11-11 16:10:55,831: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 148
celery-worker_1  | 2019-11-11T16:10:55.961037029Z [2019-11-11 16:10:55,960: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 149
celery-worker_1  | 2019-11-11T16:10:56.097183403Z [2019-11-11 16:10:56,096: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 150
celery-worker_1  | 2019-11-11T16:10:56.348290178Z [2019-11-11 16:10:56,347: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 151
celery-worker_1  | 2019-11-11T16:10:56.481635138Z [2019-11-11 16:10:56,481: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 152
celery-worker_1  | 2019-11-11T16:10:56.614504753Z [2019-11-11 16:10:56,614: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 153
celery-worker_1  | 2019-11-11T16:10:56.746942217Z [2019-11-11 16:10:56,746: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 154
celery-worker_1  | 2019-11-11T16:10:56.879694717Z [2019-11-11 16:10:56,879: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 155
celery-worker_1  | 2019-11-11T16:10:57.012589803Z [2019-11-11 16:10:57,012: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 156
celery-worker_1  | 2019-11-11T16:10:57.146725842Z [2019-11-11 16:10:57,146: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 157
celery-worker_1  | 2019-11-11T16:10:57.279194273Z [2019-11-11 16:10:57,278: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 158
celery-worker_1  | 2019-11-11T16:10:57.411955214Z [2019-11-11 16:10:57,411: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 159
flask-app_1      | 2019-11-11T16:10:57.528194987Z [2019-11-11 16:10:57 +0000] [10] [DEBUG] POST /get_steps
celery-worker_1  | 2019-11-11T16:10:57.544747837Z [2019-11-11 16:10:57,544: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 160
celery-worker_1  | 2019-11-11T16:10:57.788688046Z [2019-11-11 16:10:57,788: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 161
flask-app_1      | 2019-11-11T16:10:57.847530977Z [2019-11-11 16:10:57 +0000] [10] [INFO] STATUS: Step data retrieved.
celery-worker_1  | 2019-11-11T16:10:57.918168949Z [2019-11-11 16:10:57,917: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 162
celery-worker_1  | 2019-11-11T16:10:58.047624425Z [2019-11-11 16:10:58,047: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 163
celery-worker_1  | 2019-11-11T16:10:58.176973840Z [2019-11-11 16:10:58,176: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 164
celery-worker_1  | 2019-11-11T16:10:58.306674206Z [2019-11-11 16:10:58,306: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 165
celery-worker_1  | 2019-11-11T16:10:58.435509828Z [2019-11-11 16:10:58,435: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 166
celery-worker_1  | 2019-11-11T16:10:58.566398590Z [2019-11-11 16:10:58,566: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 167
celery-worker_1  | 2019-11-11T16:10:58.696326283Z [2019-11-11 16:10:58,695: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 168
celery-worker_1  | 2019-11-11T16:10:58.826535258Z [2019-11-11 16:10:58,826: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 169
celery-worker_1  | 2019-11-11T16:10:58.956254266Z [2019-11-11 16:10:58,955: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 170
celery-worker_1  | 2019-11-11T16:10:59.199443614Z [2019-11-11 16:10:59,199: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 171
celery-worker_1  | 2019-11-11T16:10:59.329585044Z [2019-11-11 16:10:59,329: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 172
celery-worker_1  | 2019-11-11T16:10:59.458396776Z [2019-11-11 16:10:59,458: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 173
celery-worker_1  | 2019-11-11T16:10:59.587657919Z [2019-11-11 16:10:59,587: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 174
celery-worker_1  | 2019-11-11T16:10:59.716933687Z [2019-11-11 16:10:59,716: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 175
celery-worker_1  | 2019-11-11T16:10:59.845527154Z [2019-11-11 16:10:59,845: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 176
celery-worker_1  | 2019-11-11T16:10:59.975464612Z [2019-11-11 16:10:59,975: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 177
flask-app_1      | 2019-11-11T16:10:59.979179481Z [2019-11-11 16:10:59 +0000] [10] [DEBUG] POST /get_steps
celery-worker_1  | 2019-11-11T16:11:00.105734638Z [2019-11-11 16:11:00,105: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 178
celery-worker_1  | 2019-11-11T16:11:00.237274997Z [2019-11-11 16:11:00,236: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 179
flask-app_1      | 2019-11-11T16:11:00.291582849Z [2019-11-11 16:11:00 +0000] [10] [INFO] STATUS: Step data retrieved.
celery-worker_1  | 2019-11-11T16:11:00.370183760Z [2019-11-11 16:11:00,369: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 180
celery-worker_1  | 2019-11-11T16:11:00.609961718Z [2019-11-11 16:11:00,609: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 181
celery-worker_1  | 2019-11-11T16:11:00.739474380Z [2019-11-11 16:11:00,739: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 182
celery-worker_1  | 2019-11-11T16:11:00.868986233Z [2019-11-11 16:11:00,868: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 183
celery-worker_1  | 2019-11-11T16:11:01.000247974Z [2019-11-11 16:11:00,998: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 184
celery-worker_1  | 2019-11-11T16:11:01.128132114Z [2019-11-11 16:11:01,127: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 185
celery-worker_1  | 2019-11-11T16:11:01.256617597Z [2019-11-11 16:11:01,256: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 186
celery-worker_1  | 2019-11-11T16:11:01.386086055Z [2019-11-11 16:11:01,385: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 187
celery-worker_1  | 2019-11-11T16:11:01.516349247Z [2019-11-11 16:11:01,516: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 188
celery-worker_1  | 2019-11-11T16:11:01.649022680Z [2019-11-11 16:11:01,648: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 189
celery-worker_1  | 2019-11-11T16:11:01.783206449Z [2019-11-11 16:11:01,782: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 190
celery-worker_1  | 2019-11-11T16:11:02.033395759Z [2019-11-11 16:11:02,032: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 191
celery-worker_1  | 2019-11-11T16:11:02.165893747Z [2019-11-11 16:11:02,165: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 192
celery-worker_1  | 2019-11-11T16:11:02.300708034Z [2019-11-11 16:11:02,300: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 193
flask-app_1      | 2019-11-11T16:11:02.433095227Z [2019-11-11 16:11:02 +0000] [10] [DEBUG] POST /get_steps
celery-worker_1  | 2019-11-11T16:11:02.438442802Z [2019-11-11 16:11:02,435: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 194
celery-worker_1  | 2019-11-11T16:11:02.570637860Z [2019-11-11 16:11:02,570: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 195
celery-worker_1  | 2019-11-11T16:11:02.708342951Z [2019-11-11 16:11:02,707: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 196
celery-worker_1  | 2019-11-11T16:11:02.843118290Z [2019-11-11 16:11:02,842: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 197
flask-app_1      | 2019-11-11T16:11:02.870018588Z [2019-11-11 16:11:02 +0000] [10] [INFO] STATUS: Step data retrieved.
celery-worker_1  | 2019-11-11T16:11:02.978172064Z [2019-11-11 16:11:02,976: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 198
celery-worker_1  | 2019-11-11T16:11:03.111973062Z [2019-11-11 16:11:03,111: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 199
celery-worker_1  | 2019-11-11T16:11:03.247010327Z [2019-11-11 16:11:03,246: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 200
celery-worker_1  | 2019-11-11T16:11:03.497925712Z [2019-11-11 16:11:03,497: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 201
celery-worker_1  | 2019-11-11T16:11:03.628825288Z [2019-11-11 16:11:03,628: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 202
celery-worker_1  | 2019-11-11T16:11:03.758581026Z [2019-11-11 16:11:03,758: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 203
celery-worker_1  | 2019-11-11T16:11:03.888430186Z [2019-11-11 16:11:03,887: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 204
celery-worker_1  | 2019-11-11T16:11:04.017380803Z [2019-11-11 16:11:04,016: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 205
celery-worker_1  | 2019-11-11T16:11:04.146332176Z [2019-11-11 16:11:04,145: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 206
celery-worker_1  | 2019-11-11T16:11:04.277747365Z [2019-11-11 16:11:04,277: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 207
celery-worker_1  | 2019-11-11T16:11:04.408059989Z [2019-11-11 16:11:04,407: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 208
celery-worker_1  | 2019-11-11T16:11:04.538906781Z [2019-11-11 16:11:04,538: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 209
celery-worker_1  | 2019-11-11T16:11:04.669687729Z [2019-11-11 16:11:04,669: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 210
flask-app_1      | 2019-11-11T16:11:04.997498723Z [2019-11-11 16:11:04 +0000] [10] [DEBUG] POST /get_steps
celery-worker_1  | 2019-11-11T16:11:05.054391542Z [2019-11-11 16:11:05,053: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 211
celery-worker_1  | 2019-11-11T16:11:05.183615273Z [2019-11-11 16:11:05,183: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 212
celery-worker_1  | 2019-11-11T16:11:05.312980816Z [2019-11-11 16:11:05,312: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 213
celery-worker_1  | 2019-11-11T16:11:05.442171186Z [2019-11-11 16:11:05,441: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 214
celery-worker_1  | 2019-11-11T16:11:05.571910314Z [2019-11-11 16:11:05,571: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 215
celery-worker_1  | 2019-11-11T16:11:05.698735812Z [2019-11-11 16:11:05,698: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 216
celery-worker_1  | 2019-11-11T16:11:05.828636745Z [2019-11-11 16:11:05,828: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 217
celery-worker_1  | 2019-11-11T16:11:05.958973593Z [2019-11-11 16:11:05,958: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 218
celery-worker_1  | 2019-11-11T16:11:06.091281818Z [2019-11-11 16:11:06,090: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 219
celery-worker_1  | 2019-11-11T16:11:06.224559226Z [2019-11-11 16:11:06,224: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 220
celery-worker_1  | 2019-11-11T16:11:06.476822383Z [2019-11-11 16:11:06,476: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 221
celery-worker_1  | 2019-11-11T16:11:06.607638607Z [2019-11-11 16:11:06,607: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 222
celery-worker_1  | 2019-11-11T16:11:06.736626023Z [2019-11-11 16:11:06,736: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 223
celery-worker_1  | 2019-11-11T16:11:06.867390157Z [2019-11-11 16:11:06,866: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 224
celery-worker_1  | 2019-11-11T16:11:06.997049816Z [2019-11-11 16:11:06,996: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 225
celery-worker_1  | 2019-11-11T16:11:07.129058437Z [2019-11-11 16:11:07,128: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 226
celery-worker_1  | 2019-11-11T16:11:07.258547390Z [2019-11-11 16:11:07,258: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 227
flask-app_1      | 2019-11-11T16:11:07.378223524Z [2019-11-11 16:11:07 +0000] [10] [INFO] STATUS: Step data retrieved.
celery-worker_1  | 2019-11-11T16:11:07.387745679Z [2019-11-11 16:11:07,387: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 228
celery-worker_1  | 2019-11-11T16:11:07.521826827Z [2019-11-11 16:11:07,521: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 229
celery-worker_1  | 2019-11-11T16:11:07.655593242Z [2019-11-11 16:11:07,655: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 230
celery-worker_1  | 2019-11-11T16:11:07.902611031Z [2019-11-11 16:11:07,902: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 231
celery-worker_1  | 2019-11-11T16:11:08.037158668Z [2019-11-11 16:11:08,036: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 232
celery-worker_1  | 2019-11-11T16:11:08.171684209Z [2019-11-11 16:11:08,171: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 233
celery-worker_1  | 2019-11-11T16:11:08.304440883Z [2019-11-11 16:11:08,304: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 234
celery-worker_1  | 2019-11-11T16:11:08.437589540Z [2019-11-11 16:11:08,437: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 235
celery-worker_1  | 2019-11-11T16:11:08.570917102Z [2019-11-11 16:11:08,570: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 236
celery-worker_1  | 2019-11-11T16:11:08.703948984Z [2019-11-11 16:11:08,703: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 237
celery-worker_1  | 2019-11-11T16:11:08.840679811Z [2019-11-11 16:11:08,840: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 238
celery-worker_1  | 2019-11-11T16:11:08.974272186Z [2019-11-11 16:11:08,973: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 239
celery-worker_1  | 2019-11-11T16:11:09.103603400Z [2019-11-11 16:11:09,103: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 240
celery-worker_1  | 2019-11-11T16:11:09.356217677Z [2019-11-11 16:11:09,355: INFO/ForkPoolWorker-7] <simoc_server.agent_model.agent_model.AgentModel object at 0x7ff1fb191128> step_num 241
celery-worker_1  | 2019-11-11T16:11:09.418161118Z [2019-11-11 16:11:09,417: INFO/ForkPoolWorker-7] Task celery_worker.tasks.get_step_to[77a155f1-578d-4c39-84d3-1445b6ade149] succeeded in 34.364053443074226s: None
flask-app_1      | 2019-11-11T16:11:10.094544807Z [2019-11-11 16:11:10 +0000] [10] [DEBUG] POST /get_steps
flask-app_1      | 2019-11-11T16:11:10.882586675Z [2019-11-11 16:11:10 +0000] [10] [INFO] STATUS: Step data retrieved.
flask-app_1      | 2019-11-11T16:11:33.105856029Z Traceback (most recent call last):
flask-app_1      | 2019-11-11T16:11:33.105906830Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 255, in _wait_for_pending
flask-app_1      | 2019-11-11T16:11:33.105920981Z     on_interval=on_interval):
flask-app_1      | 2019-11-11T16:11:33.105932890Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 54, in drain_events_until
flask-app_1      | 2019-11-11T16:11:33.105944928Z     raise socket.timeout()
flask-app_1      | 2019-11-11T16:11:33.105955971Z socket.timeout
flask-app_1      | 2019-11-11T16:11:33.105967430Z 
flask-app_1      | 2019-11-11T16:11:33.105978842Z During handling of the above exception, another exception occurred:
flask-app_1      | 2019-11-11T16:11:33.105990759Z 
flask-app_1      | 2019-11-11T16:11:33.106002609Z Traceback (most recent call last):
flask-app_1      | 2019-11-11T16:11:33.106014537Z   File "/usr/local/lib/python3.6/dist-packages/flask/app.py", line 1949, in full_dispatch_request
flask-app_1      | 2019-11-11T16:11:33.106026748Z     rv = self.dispatch_request()
flask-app_1      | 2019-11-11T16:11:33.106038148Z   File "/usr/local/lib/python3.6/dist-packages/flask/app.py", line 1935, in dispatch_request
flask-app_1      | 2019-11-11T16:11:33.106050083Z     return self.view_functions[rule.endpoint](**req.view_args)
flask-app_1      | 2019-11-11T16:11:33.106061605Z   File "/usr/local/lib/python3.6/dist-packages/flask_login/utils.py", line 261, in decorated_view
flask-app_1      | 2019-11-11T16:11:33.106073479Z     return func(*args, **kwargs)
flask-app_1      | 2019-11-11T16:11:33.106085002Z   File "/simoc/simoc_server/views.py", line 119, in new_game
flask-app_1      | 2019-11-11T16:11:33.106096680Z     result = tasks.new_game.delay(get_standard_user_obj().username, game_config).get(timeout=60)
flask-app_1      | 2019-11-11T16:11:33.106108483Z   File "/usr/local/lib/python3.6/dist-packages/celery/result.py", line 226, in get
flask-app_1      | 2019-11-11T16:11:33.106120104Z     on_message=on_message,
flask-app_1      | 2019-11-11T16:11:33.106131562Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 188, in wait_for_pending
flask-app_1      | 2019-11-11T16:11:33.106143386Z     for _ in self._wait_for_pending(result, **kwargs):
flask-app_1      | 2019-11-11T16:11:33.106154788Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 259, in _wait_for_pending
flask-app_1      | 2019-11-11T16:11:33.106166921Z     raise TimeoutError('The operation timed out.')
flask-app_1      | 2019-11-11T16:11:33.106178658Z celery.exceptions.TimeoutError: The operation timed out.
flask-app_1      | 2019-11-11T16:11:33.106190333Z [2019-11-11 16:11:33 +0000] [9] [ERROR] ERROR: handling exception The operation timed out.
flask-app_1      | 2019-11-11T16:11:33.110444362Z [2019-11-11 16:11:33 +0000] [9] [DEBUG] Closing connection. 
flask-app_1      | 2019-11-11T16:12:56.774168560Z [2019-11-11 16:12:56 +0000] [10] [DEBUG] GET /get_agent_types
flask-app_1      | 2019-11-11T16:13:07.760699922Z [2019-11-11 16:13:07 +0000] [9] [DEBUG] GET /get_energy
flask-app_1      | 2019-11-11T16:13:07.763564329Z [2019-11-11 16:13:07 +0000] [10] [DEBUG] GET /get_energy
flask-app_1      | 2019-11-11T16:13:07.792021278Z [2019-11-11 16:13:07 +0000] [9] [DEBUG] GET /get_energy
flask-app_1      | 2019-11-11T16:13:07.812069991Z [2019-11-11 16:13:07 +0000] [9] [DEBUG] GET /get_energy
flask-app_1      | 2019-11-11T16:13:07.857822711Z [2019-11-11 16:13:07 +0000] [10] [DEBUG] GET /get_energy
flask-app_1      | 2019-11-11T16:14:08.101998040Z [2019-11-11 16:14:08 +0000] [9] [DEBUG] POST /new_game
celery-worker_2  | 2019-11-11T16:14:08.160376693Z [2019-11-11 16:14:08,158: INFO/MainProcess] Received task: celery_worker.tasks.new_game[030a4458-6179-439b-9902-7ba7426ffaa7]  
celery-worker_2  | 2019-11-11T16:14:08.160434752Z [2019-11-11 16:14:08,159: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x7f00b3f84a60> (args:('celery_worker.tasks.new_game', '030a4458-6179-439b-9902-7ba7426ffaa7', {'lang': 'py', 'task': 'celery_worker.tasks.new_game', 'id': '030a4458-6179-439b-9902-7ba7426ffaa7', 'shadow': None, 'eta': None, 'expires': None, 'group': None, 'retries': 0, 'timelimit': [None, None], 'root_id': '030a4458-6179-439b-9902-7ba7426ffaa7', 'parent_id': None, 'argsrepr': "('marquin', {'agents': {'human_agent': [...], 'solid_waste_aerobic_bioreactor': [...], 'multifiltration_purifier_post_treament': [...], 'oxygen_generation_SFWE': [...], 'urine_recycling_processor_VCD': [...], 'co2_removal_SAWD': [...], 'co2_reduction_sabatier': [...], 'crew_habitat_small': [...], 'solar_pv_array_mars': [...]}, 'storages': {'air_storage': [...], 'water_storage': [...], 'nutrient_storage': [...], 'power_storage': [...], 'food_storage': [...]}, 'termination': [{...}], 'single_agent': 1})", 'kwargsrepr': '{}', 'origin': 'gen9@a0d0c214c8a9', 'reply_to': '4e8724d3-904e-3195-b576-4bf8269aa98b', 'correlation_id':... kwargs:{})
celery-worker_2  | 2019-11-11T16:14:08.163745326Z [2019-11-11 16:14:08,163: DEBUG/MainProcess] Task accepted: celery_worker.tasks.new_game[030a4458-6179-439b-9902-7ba7426ffaa7] pid:8904
celery-worker_2  | 2019-11-11T16:14:08.172169209Z [2019-11-11 16:14:08,170: ERROR/ForkPoolWorker-3] Task celery_worker.tasks.new_game[030a4458-6179-439b-9902-7ba7426ffaa7] raised unexpected: StatementError("(sqlalchemy.exc.InvalidRequestError) Can't reconnect until invalid transaction is rolled back",)
celery-worker_2  | 2019-11-11T16:14:08.172193841Z Traceback (most recent call last):
celery-worker_2  | 2019-11-11T16:14:08.172207023Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1177, in _execute_context
celery-worker_2  | 2019-11-11T16:14:08.172219550Z     conn = self._revalidate_connection()
celery-worker_2  | 2019-11-11T16:14:08.172231176Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 463, in _revalidate_connection
celery-worker_2  | 2019-11-11T16:14:08.172243512Z     "Can't reconnect until invalid "
celery-worker_2  | 2019-11-11T16:14:08.172255431Z sqlalchemy.exc.InvalidRequestError: Can't reconnect until invalid transaction is rolled back
celery-worker_2  | 2019-11-11T16:14:08.172267418Z 
celery-worker_2  | 2019-11-11T16:14:08.172392174Z The above exception was the direct cause of the following exception:
celery-worker_2  | 2019-11-11T16:14:08.172406462Z 
celery-worker_2  | 2019-11-11T16:14:08.172418464Z Traceback (most recent call last):
celery-worker_2  | 2019-11-11T16:14:08.172430347Z   File "/usr/local/lib/python3.6/dist-packages/celery/app/trace.py", line 385, in trace_task
celery-worker_2  | 2019-11-11T16:14:08.172442490Z     R = retval = fun(*args, **kwargs)
celery-worker_2  | 2019-11-11T16:14:08.172454323Z   File "/usr/local/lib/python3.6/dist-packages/celery/app/trace.py", line 648, in __protected_call__
celery-worker_2  | 2019-11-11T16:14:08.172466511Z     return self.run(*args, **kwargs)
celery-worker_2  | 2019-11-11T16:14:08.172478216Z   File "/simoc/celery_worker/tasks.py", line 64, in new_game
celery-worker_2  | 2019-11-11T16:14:08.172490135Z     user = get_user(username)
celery-worker_2  | 2019-11-11T16:14:08.172501868Z   File "/simoc/celery_worker/tasks.py", line 34, in get_user
celery-worker_2  | 2019-11-11T16:14:08.172513739Z     user = User.query.filter_by(username=username).all()
celery-worker_2  | 2019-11-11T16:14:08.172526510Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py", line 3186, in all
celery-worker_2  | 2019-11-11T16:14:08.172538863Z     return list(self)
celery-worker_2  | 2019-11-11T16:14:08.172550510Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py", line 3342, in __iter__
celery-worker_2  | 2019-11-11T16:14:08.172571171Z     return self._execute_and_instances(context)
celery-worker_2  | 2019-11-11T16:14:08.172584053Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py", line 3367, in _execute_and_instances
celery-worker_2  | 2019-11-11T16:14:08.172595886Z     result = conn.execute(querycontext.statement, self._params)
celery-worker_2  | 2019-11-11T16:14:08.172607529Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 988, in execute
celery-worker_2  | 2019-11-11T16:14:08.172619213Z     return meth(self, multiparams, params)
celery-worker_2  | 2019-11-11T16:14:08.172631275Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/sql/elements.py", line 287, in _execute_on_connection
celery-worker_2  | 2019-11-11T16:14:08.172643251Z     return connection._execute_clauseelement(self, multiparams, params)
celery-worker_2  | 2019-11-11T16:14:08.172656403Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1107, in _execute_clauseelement
celery-worker_2  | 2019-11-11T16:14:08.172668828Z     distilled_params,
celery-worker_2  | 2019-11-11T16:14:08.172680386Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1182, in _execute_context
celery-worker_2  | 2019-11-11T16:14:08.172699954Z     e, util.text_type(statement), parameters, None, None
celery-worker_2  | 2019-11-11T16:14:08.172712503Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1473, in _handle_dbapi_exception
celery-worker_2  | 2019-11-11T16:14:08.172725052Z     util.raise_from_cause(sqlalchemy_exception, exc_info)
celery-worker_2  | 2019-11-11T16:14:08.172736916Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/util/compat.py", line 398, in raise_from_cause
celery-worker_2  | 2019-11-11T16:14:08.172748892Z     reraise(type(exception), exception, tb=exc_tb, cause=cause)
celery-worker_2  | 2019-11-11T16:14:08.172760373Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/util/compat.py", line 152, in reraise
celery-worker_2  | 2019-11-11T16:14:08.172772293Z     raise value.with_traceback(tb)
celery-worker_2  | 2019-11-11T16:14:08.172783650Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1177, in _execute_context
celery-worker_2  | 2019-11-11T16:14:08.172795637Z     conn = self._revalidate_connection()
celery-worker_2  | 2019-11-11T16:14:08.172807234Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 463, in _revalidate_connection
celery-worker_2  | 2019-11-11T16:14:08.172819484Z     "Can't reconnect until invalid "
celery-worker_2  | 2019-11-11T16:14:08.172868479Z sqlalchemy.exc.StatementError: (sqlalchemy.exc.InvalidRequestError) Can't reconnect until invalid transaction is rolled back
celery-worker_2  | 2019-11-11T16:14:08.172883417Z [SQL: SELECT user.id AS user_id, user.username AS user_username, user.password_hash AS user_password_hash, user.date_created AS user_date_created, user.date_modified AS user_date_modified 
celery-worker_2  | 2019-11-11T16:14:08.172896372Z FROM user 
celery-worker_2  | 2019-11-11T16:14:08.172908274Z WHERE user.username = %(username_1)s]
celery-worker_2  | 2019-11-11T16:14:08.172919850Z [parameters: [{}]]
flask-app_1      | 2019-11-11T16:14:21.204943411Z [2019-11-11 16:14:21 +0000] [9] [DEBUG] POST /new_game
celery-worker_1  | 2019-11-11T16:14:21.258669755Z [2019-11-11 16:14:21,257: INFO/MainProcess] Received task: celery_worker.tasks.new_game[64e7e590-710c-4ec5-bf19-bec16a6ff51e]  
celery-worker_1  | 2019-11-11T16:14:21.258956593Z [2019-11-11 16:14:21,258: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x7ff1ca9bb9d8> (args:('celery_worker.tasks.new_game', '64e7e590-710c-4ec5-bf19-bec16a6ff51e', {'lang': 'py', 'task': 'celery_worker.tasks.new_game', 'id': '64e7e590-710c-4ec5-bf19-bec16a6ff51e', 'shadow': None, 'eta': None, 'expires': None, 'group': None, 'retries': 0, 'timelimit': [None, None], 'root_id': '64e7e590-710c-4ec5-bf19-bec16a6ff51e', 'parent_id': None, 'argsrepr': "('marquin', {'agents': {'human_agent': [...], 'solid_waste_aerobic_bioreactor': [...], 'multifiltration_purifier_post_treament': [...], 'oxygen_generation_SFWE': [...], 'urine_recycling_processor_VCD': [...], 'co2_removal_SAWD': [...], 'co2_reduction_sabatier': [...], 'crew_habitat_small': [...], 'solar_pv_array_mars': [...]}, 'storages': {'air_storage': [...], 'water_storage': [...], 'nutrient_storage': [...], 'power_storage': [...], 'food_storage': [...]}, 'termination': [{...}], 'single_agent': 1})", 'kwargsrepr': '{}', 'origin': 'gen9@a0d0c214c8a9', 'reply_to': '4e8724d3-904e-3195-b576-4bf8269aa98b', 'correlation_id':... kwargs:{})
celery-worker_1  | 2019-11-11T16:14:21.263048640Z [2019-11-11 16:14:21,262: DEBUG/MainProcess] Task accepted: celery_worker.tasks.new_game[64e7e590-710c-4ec5-bf19-bec16a6ff51e] pid:10729
celery-worker_1  | 2019-11-11T16:14:21.542875265Z [2019-11-11 16:14:21,542: INFO/ForkPoolWorker-7] Task celery_worker.tasks.new_game[64e7e590-710c-4ec5-bf19-bec16a6ff51e] succeeded in 0.2794974762946367s: {'worker_hostname': 'worker@47b1f9e9dd75', 'game_id': 4879188189342065833}
flask-app_1      | 2019-11-11T16:14:23.679999315Z [2019-11-11 16:14:23 +0000] [10] [DEBUG] POST /new_game
celery-worker_2  | 2019-11-11T16:14:23.738414109Z [2019-11-11 16:14:23,737: INFO/MainProcess] Received task: celery_worker.tasks.new_game[ddfbd65f-0cb2-4a04-ad57-71f2af4010fe]  
celery-worker_2  | 2019-11-11T16:14:23.738624743Z [2019-11-11 16:14:23,738: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x7f00b3f84a60> (args:('celery_worker.tasks.new_game', 'ddfbd65f-0cb2-4a04-ad57-71f2af4010fe', {'lang': 'py', 'task': 'celery_worker.tasks.new_game', 'id': 'ddfbd65f-0cb2-4a04-ad57-71f2af4010fe', 'shadow': None, 'eta': None, 'expires': None, 'group': None, 'retries': 0, 'timelimit': [None, None], 'root_id': 'ddfbd65f-0cb2-4a04-ad57-71f2af4010fe', 'parent_id': None, 'argsrepr': "('marquin', {'agents': {'human_agent': [...], 'solid_waste_aerobic_bioreactor': [...], 'multifiltration_purifier_post_treament': [...], 'oxygen_generation_SFWE': [...], 'urine_recycling_processor_VCD': [...], 'co2_removal_SAWD': [...], 'co2_reduction_sabatier': [...], 'crew_habitat_small': [...], 'solar_pv_array_mars': [...]}, 'storages': {'air_storage': [...], 'water_storage': [...], 'nutrient_storage': [...], 'power_storage': [...], 'food_storage': [...]}, 'termination': [{...}], 'single_agent': 1})", 'kwargsrepr': '{}', 'origin': 'gen10@a0d0c214c8a9', 'reply_to': '1d83a10a-bd14-3594-b548-1af402ba2725', 'correlation_id':... kwargs:{})
celery-worker_2  | 2019-11-11T16:14:23.742019421Z [2019-11-11 16:14:23,741: DEBUG/MainProcess] Task accepted: celery_worker.tasks.new_game[ddfbd65f-0cb2-4a04-ad57-71f2af4010fe] pid:8904
celery-worker_2  | 2019-11-11T16:14:23.747691578Z [2019-11-11 16:14:23,746: ERROR/ForkPoolWorker-3] Task celery_worker.tasks.new_game[ddfbd65f-0cb2-4a04-ad57-71f2af4010fe] raised unexpected: StatementError("(sqlalchemy.exc.InvalidRequestError) Can't reconnect until invalid transaction is rolled back",)
celery-worker_2  | 2019-11-11T16:14:23.747717274Z Traceback (most recent call last):
celery-worker_2  | 2019-11-11T16:14:23.747730206Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1177, in _execute_context
celery-worker_2  | 2019-11-11T16:14:23.747742289Z     conn = self._revalidate_connection()
celery-worker_2  | 2019-11-11T16:14:23.747753641Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 463, in _revalidate_connection
celery-worker_2  | 2019-11-11T16:14:23.747765502Z     "Can't reconnect until invalid "
celery-worker_2  | 2019-11-11T16:14:23.747777458Z sqlalchemy.exc.InvalidRequestError: Can't reconnect until invalid transaction is rolled back
celery-worker_2  | 2019-11-11T16:14:23.747789113Z 
celery-worker_2  | 2019-11-11T16:14:23.747800554Z The above exception was the direct cause of the following exception:
celery-worker_2  | 2019-11-11T16:14:23.747812026Z 
celery-worker_2  | 2019-11-11T16:14:23.747823940Z Traceback (most recent call last):
celery-worker_2  | 2019-11-11T16:14:23.747855479Z   File "/usr/local/lib/python3.6/dist-packages/celery/app/trace.py", line 385, in trace_task
celery-worker_2  | 2019-11-11T16:14:23.747869436Z     R = retval = fun(*args, **kwargs)
celery-worker_2  | 2019-11-11T16:14:23.747880901Z   File "/usr/local/lib/python3.6/dist-packages/celery/app/trace.py", line 648, in __protected_call__
celery-worker_2  | 2019-11-11T16:14:23.747893023Z     return self.run(*args, **kwargs)
celery-worker_2  | 2019-11-11T16:14:23.747904478Z   File "/simoc/celery_worker/tasks.py", line 64, in new_game
celery-worker_2  | 2019-11-11T16:14:23.747916391Z     user = get_user(username)
celery-worker_2  | 2019-11-11T16:14:23.747928322Z   File "/simoc/celery_worker/tasks.py", line 34, in get_user
celery-worker_2  | 2019-11-11T16:14:23.747940720Z     user = User.query.filter_by(username=username).all()
celery-worker_2  | 2019-11-11T16:14:23.747952519Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py", line 3186, in all
celery-worker_2  | 2019-11-11T16:14:23.747973113Z     return list(self)
celery-worker_2  | 2019-11-11T16:14:23.747985305Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py", line 3342, in __iter__
celery-worker_2  | 2019-11-11T16:14:23.747997132Z     return self._execute_and_instances(context)
celery-worker_2  | 2019-11-11T16:14:23.748008657Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py", line 3367, in _execute_and_instances
celery-worker_2  | 2019-11-11T16:14:23.748020711Z     result = conn.execute(querycontext.statement, self._params)
celery-worker_2  | 2019-11-11T16:14:23.748032924Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 988, in execute
celery-worker_2  | 2019-11-11T16:14:23.748044649Z     return meth(self, multiparams, params)
celery-worker_2  | 2019-11-11T16:14:23.748056779Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/sql/elements.py", line 287, in _execute_on_connection
celery-worker_2  | 2019-11-11T16:14:23.748068901Z     return connection._execute_clauseelement(self, multiparams, params)
celery-worker_2  | 2019-11-11T16:14:23.748081900Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1107, in _execute_clauseelement
celery-worker_2  | 2019-11-11T16:14:23.748094366Z     distilled_params,
celery-worker_2  | 2019-11-11T16:14:23.748105604Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1182, in _execute_context
celery-worker_2  | 2019-11-11T16:14:23.748117377Z     e, util.text_type(statement), parameters, None, None
celery-worker_2  | 2019-11-11T16:14:23.748128742Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1473, in _handle_dbapi_exception
celery-worker_2  | 2019-11-11T16:14:23.748141629Z     util.raise_from_cause(sqlalchemy_exception, exc_info)
celery-worker_2  | 2019-11-11T16:14:23.748153075Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/util/compat.py", line 398, in raise_from_cause
celery-worker_2  | 2019-11-11T16:14:23.748164821Z     reraise(type(exception), exception, tb=exc_tb, cause=cause)
celery-worker_2  | 2019-11-11T16:14:23.748176067Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/util/compat.py", line 152, in reraise
celery-worker_2  | 2019-11-11T16:14:23.748187742Z     raise value.with_traceback(tb)
celery-worker_2  | 2019-11-11T16:14:23.748198988Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1177, in _execute_context
celery-worker_2  | 2019-11-11T16:14:23.748210849Z     conn = self._revalidate_connection()
celery-worker_2  | 2019-11-11T16:14:23.748222028Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 463, in _revalidate_connection
celery-worker_2  | 2019-11-11T16:14:23.748249577Z     "Can't reconnect until invalid "
celery-worker_2  | 2019-11-11T16:14:23.748264289Z sqlalchemy.exc.StatementError: (sqlalchemy.exc.InvalidRequestError) Can't reconnect until invalid transaction is rolled back
celery-worker_2  | 2019-11-11T16:14:23.748276291Z [SQL: SELECT user.id AS user_id, user.username AS user_username, user.password_hash AS user_password_hash, user.date_created AS user_date_created, user.date_modified AS user_date_modified 
celery-worker_2  | 2019-11-11T16:14:23.748288214Z FROM user 
celery-worker_2  | 2019-11-11T16:14:23.748299509Z WHERE user.username = %(username_1)s]
celery-worker_2  | 2019-11-11T16:14:23.748310660Z [parameters: [{}]]
flask-app_1      | 2019-11-11T16:14:42.545911379Z Traceback (most recent call last):
flask-app_1      | 2019-11-11T16:14:42.545964319Z   File "src/gevent/greenlet.py", line 766, in gevent._greenlet.Greenlet.run
flask-app_1      | 2019-11-11T16:14:42.545978103Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 82, in run
flask-app_1      | 2019-11-11T16:14:42.545991370Z     self.result_consumer.drain_events(timeout=1)
flask-app_1      | 2019-11-11T16:14:42.546002983Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/redis.py", line 129, in drain_events
flask-app_1      | 2019-11-11T16:14:42.546015186Z     self.on_state_change(self._decode_result(message['data']), message)
flask-app_1      | 2019-11-11T16:14:42.546027701Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/base.py", line 305, in decode_result
flask-app_1      | 2019-11-11T16:14:42.546039510Z     return self.meta_from_decoded(self.decode(payload))
flask-app_1      | 2019-11-11T16:14:42.546051222Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/base.py", line 301, in meta_from_decoded
flask-app_1      | 2019-11-11T16:14:42.546063324Z     meta['result'] = self.exception_to_python(meta['result'])
flask-app_1      | 2019-11-11T16:14:42.546074726Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/base.py", line 281, in exception_to_python
flask-app_1      | 2019-11-11T16:14:42.546086600Z     exc = cls(*exc_msg if isinstance(exc_msg, tuple) else exc_msg)
flask-app_1      | 2019-11-11T16:14:42.546098149Z TypeError: __init__() missing 3 required positional arguments: 'statement', 'params', and 'orig'
flask-app_1      | 2019-11-11T16:14:42.546110224Z 2019-11-11T16:14:23Z <Greenlet at 0x7f5c2b0e5e48: <bound method greenletDrainer.run of <celery.backends.asynchronous.geventDrainer object at 0x7f5c29c85a20>>> failed with TypeError
flask-app_1      | 2019-11-11T16:14:42.546123437Z 
flask-app_1      | 2019-11-11T16:14:42.546135412Z [2019-11-11 16:14:42 +0000] [10] [DEBUG] POST /new_game
celery-worker_1  | 2019-11-11T16:14:42.652579458Z [2019-11-11 16:14:42,651: INFO/MainProcess] Received task: celery_worker.tasks.new_game[cee52683-60d4-4ff9-aa5d-3ca392137e61]  
celery-worker_1  | 2019-11-11T16:14:42.652724673Z [2019-11-11 16:14:42,652: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x7ff1ca9bb9d8> (args:('celery_worker.tasks.new_game', 'cee52683-60d4-4ff9-aa5d-3ca392137e61', {'lang': 'py', 'task': 'celery_worker.tasks.new_game', 'id': 'cee52683-60d4-4ff9-aa5d-3ca392137e61', 'shadow': None, 'eta': None, 'expires': None, 'group': None, 'retries': 0, 'timelimit': [None, None], 'root_id': 'cee52683-60d4-4ff9-aa5d-3ca392137e61', 'parent_id': None, 'argsrepr': "('marquin', {'agents': {'human_agent': [...], 'solid_waste_aerobic_bioreactor': [...], 'multifiltration_purifier_post_treament': [...], 'oxygen_generation_SFWE': [...], 'urine_recycling_processor_VCD': [...], 'co2_removal_SAWD': [...], 'co2_reduction_sabatier': [...], 'crew_habitat_small': [...], 'solar_pv_array_mars': [...]}, 'storages': {'air_storage': [...], 'water_storage': [...], 'nutrient_storage': [...], 'power_storage': [...], 'food_storage': [...]}, 'termination': [{...}], 'single_agent': 1})", 'kwargsrepr': '{}', 'origin': 'gen10@a0d0c214c8a9', 'reply_to': '1d83a10a-bd14-3594-b548-1af402ba2725', 'correlation_id':... kwargs:{})
celery-worker_1  | 2019-11-11T16:14:42.658058974Z [2019-11-11 16:14:42,657: DEBUG/MainProcess] Task accepted: celery_worker.tasks.new_game[cee52683-60d4-4ff9-aa5d-3ca392137e61] pid:10729
celery-worker_1  | 2019-11-11T16:14:42.987438245Z [2019-11-11 16:14:42,986: INFO/ForkPoolWorker-7] Task celery_worker.tasks.new_game[cee52683-60d4-4ff9-aa5d-3ca392137e61] succeeded in 0.33084296993911266s: {'worker_hostname': 'worker@47b1f9e9dd75', 'game_id': 7465288035693794701}
flask-app_1      | 2019-11-11T16:14:43.003828718Z [2019-11-11 16:14:43 +0000] [9] [DEBUG] POST /new_game
celery-worker_2  | 2019-11-11T16:14:43.113065983Z [2019-11-11 16:14:43,112: INFO/MainProcess] Received task: celery_worker.tasks.new_game[4ded0cc1-dc4b-48a2-9f47-af83573634e2]  
celery-worker_2  | 2019-11-11T16:14:43.113261356Z [2019-11-11 16:14:43,112: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x7f00b3f84a60> (args:('celery_worker.tasks.new_game', '4ded0cc1-dc4b-48a2-9f47-af83573634e2', {'lang': 'py', 'task': 'celery_worker.tasks.new_game', 'id': '4ded0cc1-dc4b-48a2-9f47-af83573634e2', 'shadow': None, 'eta': None, 'expires': None, 'group': None, 'retries': 0, 'timelimit': [None, None], 'root_id': '4ded0cc1-dc4b-48a2-9f47-af83573634e2', 'parent_id': None, 'argsrepr': "('marquin', {'agents': {'human_agent': [...], 'solid_waste_aerobic_bioreactor': [...], 'multifiltration_purifier_post_treament': [...], 'oxygen_generation_SFWE': [...], 'urine_recycling_processor_VCD': [...], 'co2_removal_SAWD': [...], 'co2_reduction_sabatier': [...], 'crew_habitat_small': [...], 'solar_pv_array_mars': [...]}, 'storages': {'air_storage': [...], 'water_storage': [...], 'nutrient_storage': [...], 'power_storage': [...], 'food_storage': [...]}, 'termination': [{...}], 'single_agent': 1})", 'kwargsrepr': '{}', 'origin': 'gen9@a0d0c214c8a9', 'reply_to': '4e8724d3-904e-3195-b576-4bf8269aa98b', 'correlation_id':... kwargs:{})
celery-worker_2  | 2019-11-11T16:14:43.118259200Z [2019-11-11 16:14:43,117: DEBUG/MainProcess] Task accepted: celery_worker.tasks.new_game[4ded0cc1-dc4b-48a2-9f47-af83573634e2] pid:8904
celery-worker_2  | 2019-11-11T16:14:43.122750945Z [2019-11-11 16:14:43,121: ERROR/ForkPoolWorker-3] Task celery_worker.tasks.new_game[4ded0cc1-dc4b-48a2-9f47-af83573634e2] raised unexpected: StatementError("(sqlalchemy.exc.InvalidRequestError) Can't reconnect until invalid transaction is rolled back",)
celery-worker_2  | 2019-11-11T16:14:43.122790543Z Traceback (most recent call last):
celery-worker_2  | 2019-11-11T16:14:43.122804343Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1177, in _execute_context
celery-worker_2  | 2019-11-11T16:14:43.122884601Z     conn = self._revalidate_connection()
celery-worker_2  | 2019-11-11T16:14:43.122905274Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 463, in _revalidate_connection
celery-worker_2  | 2019-11-11T16:14:43.122918054Z     "Can't reconnect until invalid "
celery-worker_2  | 2019-11-11T16:14:43.122929628Z sqlalchemy.exc.InvalidRequestError: Can't reconnect until invalid transaction is rolled back
celery-worker_2  | 2019-11-11T16:14:43.122941686Z 
celery-worker_2  | 2019-11-11T16:14:43.122953015Z The above exception was the direct cause of the following exception:
celery-worker_2  | 2019-11-11T16:14:43.122964848Z 
celery-worker_2  | 2019-11-11T16:14:43.122976560Z Traceback (most recent call last):
celery-worker_2  | 2019-11-11T16:14:43.122988352Z   File "/usr/local/lib/python3.6/dist-packages/celery/app/trace.py", line 385, in trace_task
celery-worker_2  | 2019-11-11T16:14:43.123000070Z     R = retval = fun(*args, **kwargs)
celery-worker_2  | 2019-11-11T16:14:43.123011568Z   File "/usr/local/lib/python3.6/dist-packages/celery/app/trace.py", line 648, in __protected_call__
celery-worker_2  | 2019-11-11T16:14:43.123023359Z     return self.run(*args, **kwargs)
celery-worker_2  | 2019-11-11T16:14:43.123034899Z   File "/simoc/celery_worker/tasks.py", line 64, in new_game
celery-worker_2  | 2019-11-11T16:14:43.123046553Z     user = get_user(username)
celery-worker_2  | 2019-11-11T16:14:43.123058249Z   File "/simoc/celery_worker/tasks.py", line 34, in get_user
celery-worker_2  | 2019-11-11T16:14:43.123084890Z     user = User.query.filter_by(username=username).all()
celery-worker_2  | 2019-11-11T16:14:43.123097973Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py", line 3186, in all
celery-worker_2  | 2019-11-11T16:14:43.123109561Z     return list(self)
celery-worker_2  | 2019-11-11T16:14:43.123120751Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py", line 3342, in __iter__
celery-worker_2  | 2019-11-11T16:14:43.123132420Z     return self._execute_and_instances(context)
celery-worker_2  | 2019-11-11T16:14:43.123143749Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py", line 3367, in _execute_and_instances
celery-worker_2  | 2019-11-11T16:14:43.123155321Z     result = conn.execute(querycontext.statement, self._params)
celery-worker_2  | 2019-11-11T16:14:43.123166854Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 988, in execute
celery-worker_2  | 2019-11-11T16:14:43.123192469Z     return meth(self, multiparams, params)
celery-worker_2  | 2019-11-11T16:14:43.123207988Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/sql/elements.py", line 287, in _execute_on_connection
celery-worker_2  | 2019-11-11T16:14:43.123219804Z     return connection._execute_clauseelement(self, multiparams, params)
celery-worker_2  | 2019-11-11T16:14:43.123233022Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1107, in _execute_clauseelement
celery-worker_2  | 2019-11-11T16:14:43.123244902Z     distilled_params,
celery-worker_2  | 2019-11-11T16:14:43.123256216Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1182, in _execute_context
celery-worker_2  | 2019-11-11T16:14:43.123267704Z     e, util.text_type(statement), parameters, None, None
celery-worker_2  | 2019-11-11T16:14:43.123279156Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1473, in _handle_dbapi_exception
celery-worker_2  | 2019-11-11T16:14:43.123290680Z     util.raise_from_cause(sqlalchemy_exception, exc_info)
celery-worker_2  | 2019-11-11T16:14:43.123302141Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/util/compat.py", line 398, in raise_from_cause
celery-worker_2  | 2019-11-11T16:14:43.123313628Z     reraise(type(exception), exception, tb=exc_tb, cause=cause)
celery-worker_2  | 2019-11-11T16:14:43.123325154Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/util/compat.py", line 152, in reraise
celery-worker_2  | 2019-11-11T16:14:43.123336733Z     raise value.with_traceback(tb)
celery-worker_2  | 2019-11-11T16:14:43.123348036Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1177, in _execute_context
celery-worker_2  | 2019-11-11T16:14:43.123359547Z     conn = self._revalidate_connection()
celery-worker_2  | 2019-11-11T16:14:43.123370682Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 463, in _revalidate_connection
celery-worker_2  | 2019-11-11T16:14:43.123382314Z     "Can't reconnect until invalid "
celery-worker_2  | 2019-11-11T16:14:43.123393835Z sqlalchemy.exc.StatementError: (sqlalchemy.exc.InvalidRequestError) Can't reconnect until invalid transaction is rolled back
celery-worker_2  | 2019-11-11T16:14:43.123405387Z [SQL: SELECT user.id AS user_id, user.username AS user_username, user.password_hash AS user_password_hash, user.date_created AS user_date_created, user.date_modified AS user_date_modified 
celery-worker_2  | 2019-11-11T16:14:43.123425216Z FROM user 
celery-worker_2  | 2019-11-11T16:14:43.123437282Z WHERE user.username = %(username_1)s]
celery-worker_2  | 2019-11-11T16:14:43.123448611Z [parameters: [{}]]
flask-app_1      | 2019-11-11T16:14:43.189143812Z [2019-11-11 16:14:43 +0000] [10] [DEBUG] POST /new_game
celery-worker_1  | 2019-11-11T16:14:43.294362661Z [2019-11-11 16:14:43,293: INFO/MainProcess] Received task: celery_worker.tasks.new_game[106c0b7c-126c-4e7f-8939-abb4e68989ed]  
celery-worker_1  | 2019-11-11T16:14:43.294628215Z [2019-11-11 16:14:43,294: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x7ff1ca9bb9d8> (args:('celery_worker.tasks.new_game', '106c0b7c-126c-4e7f-8939-abb4e68989ed', {'lang': 'py', 'task': 'celery_worker.tasks.new_game', 'id': '106c0b7c-126c-4e7f-8939-abb4e68989ed', 'shadow': None, 'eta': None, 'expires': None, 'group': None, 'retries': 0, 'timelimit': [None, None], 'root_id': '106c0b7c-126c-4e7f-8939-abb4e68989ed', 'parent_id': None, 'argsrepr': "('marquin', {'agents': {'human_agent': [...], 'solid_waste_aerobic_bioreactor': [...], 'multifiltration_purifier_post_treament': [...], 'oxygen_generation_SFWE': [...], 'urine_recycling_processor_VCD': [...], 'co2_removal_SAWD': [...], 'co2_reduction_sabatier': [...], 'crew_habitat_small': [...], 'solar_pv_array_mars': [...]}, 'storages': {'air_storage': [...], 'water_storage': [...], 'nutrient_storage': [...], 'power_storage': [...], 'food_storage': [...]}, 'termination': [{...}], 'single_agent': 1})", 'kwargsrepr': '{}', 'origin': 'gen10@a0d0c214c8a9', 'reply_to': '1d83a10a-bd14-3594-b548-1af402ba2725', 'correlation_id':... kwargs:{})
celery-worker_1  | 2019-11-11T16:14:43.298909596Z [2019-11-11 16:14:43,298: DEBUG/MainProcess] Task accepted: celery_worker.tasks.new_game[106c0b7c-126c-4e7f-8939-abb4e68989ed] pid:10729
celery-worker_1  | 2019-11-11T16:14:43.692801716Z [2019-11-11 16:14:43,692: INFO/ForkPoolWorker-7] Task celery_worker.tasks.new_game[106c0b7c-126c-4e7f-8939-abb4e68989ed] succeeded in 0.3950897790491581s: {'worker_hostname': 'worker@47b1f9e9dd75', 'game_id': 370889776341674200}
flask-app_1      | 2019-11-11T16:15:08.159768217Z Traceback (most recent call last):
flask-app_1      | 2019-11-11T16:15:08.159819082Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 255, in _wait_for_pending
flask-app_1      | 2019-11-11T16:15:08.159868420Z     on_interval=on_interval):
flask-app_1      | 2019-11-11T16:15:08.159885063Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 54, in drain_events_until
flask-app_1      | 2019-11-11T16:15:08.159897441Z     raise socket.timeout()
flask-app_1      | 2019-11-11T16:15:08.159908513Z socket.timeout
flask-app_1      | 2019-11-11T16:15:08.159919571Z 
flask-app_1      | 2019-11-11T16:15:08.159930353Z During handling of the above exception, another exception occurred:
flask-app_1      | 2019-11-11T16:15:08.159941736Z 
flask-app_1      | 2019-11-11T16:15:08.159953129Z Traceback (most recent call last):
flask-app_1      | 2019-11-11T16:15:08.159964413Z   File "/usr/local/lib/python3.6/dist-packages/flask/app.py", line 1949, in full_dispatch_request
flask-app_1      | 2019-11-11T16:15:08.159975814Z     rv = self.dispatch_request()
flask-app_1      | 2019-11-11T16:15:08.159987175Z   File "/usr/local/lib/python3.6/dist-packages/flask/app.py", line 1935, in dispatch_request
flask-app_1      | 2019-11-11T16:15:08.159998434Z     return self.view_functions[rule.endpoint](**req.view_args)
flask-app_1      | 2019-11-11T16:15:08.160009699Z   File "/usr/local/lib/python3.6/dist-packages/flask_login/utils.py", line 261, in decorated_view
flask-app_1      | 2019-11-11T16:15:08.160021731Z     return func(*args, **kwargs)
flask-app_1      | 2019-11-11T16:15:08.160032936Z   File "/simoc/simoc_server/views.py", line 119, in new_game
flask-app_1      | 2019-11-11T16:15:08.160044267Z     result = tasks.new_game.delay(get_standard_user_obj().username, game_config).get(timeout=60)
flask-app_1      | 2019-11-11T16:15:08.160055681Z   File "/usr/local/lib/python3.6/dist-packages/celery/result.py", line 226, in get
flask-app_1      | 2019-11-11T16:15:08.160066917Z     on_message=on_message,
flask-app_1      | 2019-11-11T16:15:08.160078160Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 188, in wait_for_pending
flask-app_1      | 2019-11-11T16:15:08.160089724Z     for _ in self._wait_for_pending(result, **kwargs):
flask-app_1      | 2019-11-11T16:15:08.160101083Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 259, in _wait_for_pending
flask-app_1      | 2019-11-11T16:15:08.160129910Z     raise TimeoutError('The operation timed out.')
flask-app_1      | 2019-11-11T16:15:08.160144177Z celery.exceptions.TimeoutError: The operation timed out.
flask-app_1      | 2019-11-11T16:15:08.160155531Z [2019-11-11 16:15:08 +0000] [9] [ERROR] ERROR: handling exception The operation timed out.
flask-app_1      | 2019-11-11T16:15:08.163440031Z [2019-11-11 16:15:08 +0000] [9] [DEBUG] Closing connection. 
flask-app_1      | 2019-11-11T16:15:08.211271113Z [2019-11-11 16:15:08 +0000] [10] [DEBUG] GET /configuration
flask-app_1      | 2019-11-11T16:15:08.213312479Z Traceback (most recent call last):
flask-app_1      | 2019-11-11T16:15:08.213333569Z   File "/usr/local/lib/python3.6/dist-packages/flask/app.py", line 1949, in full_dispatch_request
flask-app_1      | 2019-11-11T16:15:08.213346357Z     rv = self.dispatch_request()
flask-app_1      | 2019-11-11T16:15:08.213357904Z   File "/usr/local/lib/python3.6/dist-packages/flask/app.py", line 1925, in dispatch_request
flask-app_1      | 2019-11-11T16:15:08.213369393Z     self.raise_routing_exception(req)
flask-app_1      | 2019-11-11T16:15:08.213388359Z   File "/usr/local/lib/python3.6/dist-packages/flask/app.py", line 1907, in raise_routing_exception
flask-app_1      | 2019-11-11T16:15:08.213401342Z     raise request.routing_exception
flask-app_1      | 2019-11-11T16:15:08.213412733Z   File "/usr/local/lib/python3.6/dist-packages/flask/ctx.py", line 350, in match_request
flask-app_1      | 2019-11-11T16:15:08.213424094Z     result = self.url_adapter.match(return_rule=True)
flask-app_1      | 2019-11-11T16:15:08.213435265Z   File "/usr/local/lib/python3.6/dist-packages/werkzeug/routing.py", line 1799, in match
flask-app_1      | 2019-11-11T16:15:08.213446976Z     raise NotFound()
flask-app_1      | 2019-11-11T16:15:08.213458369Z werkzeug.exceptions.NotFound: 404 Not Found: The requested URL was not found on the server. If you entered the URL manually please check your spelling and try again.
flask-app_1      | 2019-11-11T16:15:08.213470053Z [2019-11-11 16:15:08 +0000] [10] [ERROR] ERROR: handling exception 404 Not Found: The requested URL was not found on the server. If you entered the URL manually please check your spelling and try again.
flask-app_1      | 2019-11-11T16:15:08.278028394Z [2019-11-11 16:15:08 +0000] [10] [DEBUG] GET /get_energy
flask-app_1      | 2019-11-11T16:15:21.267792162Z Traceback (most recent call last):
flask-app_1      | 2019-11-11T16:15:21.267894600Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 255, in _wait_for_pending
flask-app_1      | 2019-11-11T16:15:21.267915478Z     on_interval=on_interval):
flask-app_1      | 2019-11-11T16:15:21.267927760Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 54, in drain_events_until
flask-app_1      | 2019-11-11T16:15:21.267940082Z     raise socket.timeout()
flask-app_1      | 2019-11-11T16:15:21.267951625Z socket.timeout
flask-app_1      | 2019-11-11T16:15:21.267963157Z 
flask-app_1      | 2019-11-11T16:15:21.267974409Z During handling of the above exception, another exception occurred:
flask-app_1      | 2019-11-11T16:15:21.267986167Z 
flask-app_1      | 2019-11-11T16:15:21.267997291Z Traceback (most recent call last):
flask-app_1      | 2019-11-11T16:15:21.268009189Z   File "/usr/local/lib/python3.6/dist-packages/flask/app.py", line 1949, in full_dispatch_request
flask-app_1      | 2019-11-11T16:15:21.268020934Z     rv = self.dispatch_request()
flask-app_1      | 2019-11-11T16:15:21.268032481Z   File "/usr/local/lib/python3.6/dist-packages/flask/app.py", line 1935, in dispatch_request
flask-app_1      | 2019-11-11T16:15:21.268044206Z     return self.view_functions[rule.endpoint](**req.view_args)
flask-app_1      | 2019-11-11T16:15:21.268055938Z   File "/usr/local/lib/python3.6/dist-packages/flask_login/utils.py", line 261, in decorated_view
flask-app_1      | 2019-11-11T16:15:21.268067650Z     return func(*args, **kwargs)
flask-app_1      | 2019-11-11T16:15:21.268096940Z   File "/simoc/simoc_server/views.py", line 119, in new_game
flask-app_1      | 2019-11-11T16:15:21.268110329Z     result = tasks.new_game.delay(get_standard_user_obj().username, game_config).get(timeout=60)
flask-app_1      | 2019-11-11T16:15:21.268122541Z   File "/usr/local/lib/python3.6/dist-packages/celery/result.py", line 226, in get
flask-app_1      | 2019-11-11T16:15:21.268134280Z     on_message=on_message,
flask-app_1      | 2019-11-11T16:15:21.268145799Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 188, in wait_for_pending
flask-app_1      | 2019-11-11T16:15:21.268169094Z     for _ in self._wait_for_pending(result, **kwargs):
flask-app_1      | 2019-11-11T16:15:21.268181784Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 259, in _wait_for_pending
flask-app_1      | 2019-11-11T16:15:21.268193579Z     raise TimeoutError('The operation timed out.')
flask-app_1      | 2019-11-11T16:15:21.268205087Z celery.exceptions.TimeoutError: The operation timed out.
flask-app_1      | 2019-11-11T16:15:21.268216626Z [2019-11-11 16:15:21 +0000] [9] [ERROR] ERROR: handling exception The operation timed out.
flask-app_1      | 2019-11-11T16:15:21.270122818Z [2019-11-11 16:15:21 +0000] [9] [DEBUG] Closing connection. 
flask-app_1      | 2019-11-11T16:15:23.736451867Z Traceback (most recent call last):
flask-app_1      | 2019-11-11T16:15:23.736494396Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 255, in _wait_for_pending
flask-app_1      | 2019-11-11T16:15:23.736511287Z     on_interval=on_interval):
flask-app_1      | 2019-11-11T16:15:23.736523343Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 54, in drain_events_until
flask-app_1      | 2019-11-11T16:15:23.736535343Z     raise socket.timeout()
flask-app_1      | 2019-11-11T16:15:23.736546719Z socket.timeout
flask-app_1      | 2019-11-11T16:15:23.736557819Z 
flask-app_1      | 2019-11-11T16:15:23.736571644Z During handling of the above exception, another exception occurred:
flask-app_1      | 2019-11-11T16:15:23.736583287Z 
flask-app_1      | 2019-11-11T16:15:23.736594499Z Traceback (most recent call last):
flask-app_1      | 2019-11-11T16:15:23.736605902Z   File "/usr/local/lib/python3.6/dist-packages/flask/app.py", line 1949, in full_dispatch_request
flask-app_1      | 2019-11-11T16:15:23.736617782Z     rv = self.dispatch_request()
flask-app_1      | 2019-11-11T16:15:23.736629142Z   File "/usr/local/lib/python3.6/dist-packages/flask/app.py", line 1935, in dispatch_request
flask-app_1      | 2019-11-11T16:15:23.736640955Z     return self.view_functions[rule.endpoint](**req.view_args)
flask-app_1      | 2019-11-11T16:15:23.736652691Z   File "/usr/local/lib/python3.6/dist-packages/flask_login/utils.py", line 261, in decorated_view
flask-app_1      | 2019-11-11T16:15:23.736664434Z     return func(*args, **kwargs)
flask-app_1      | 2019-11-11T16:15:23.736675844Z   File "/simoc/simoc_server/views.py", line 119, in new_game
flask-app_1      | 2019-11-11T16:15:23.736687225Z     result = tasks.new_game.delay(get_standard_user_obj().username, game_config).get(timeout=60)
flask-app_1      | 2019-11-11T16:15:23.736698825Z   File "/usr/local/lib/python3.6/dist-packages/celery/result.py", line 226, in get
flask-app_1      | 2019-11-11T16:15:23.736710274Z     on_message=on_message,
flask-app_1      | 2019-11-11T16:15:23.736721778Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 188, in wait_for_pending
flask-app_1      | 2019-11-11T16:15:23.736733671Z     for _ in self._wait_for_pending(result, **kwargs):
flask-app_1      | 2019-11-11T16:15:23.736745102Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 259, in _wait_for_pending
flask-app_1      | 2019-11-11T16:15:23.736756987Z     raise TimeoutError('The operation timed out.')
flask-app_1      | 2019-11-11T16:15:23.736768416Z celery.exceptions.TimeoutError: The operation timed out.
flask-app_1      | 2019-11-11T16:15:23.736785965Z [2019-11-11 16:15:23 +0000] [10] [ERROR] ERROR: handling exception The operation timed out.
flask-app_1      | 2019-11-11T16:15:23.741002065Z [2019-11-11 16:15:23 +0000] [10] [DEBUG] Closing connection. 
flask-app_1      | 2019-11-11T16:15:42.659649265Z Traceback (most recent call last):
flask-app_1      | 2019-11-11T16:15:42.659703539Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 255, in _wait_for_pending
flask-app_1      | 2019-11-11T16:15:42.659717545Z     on_interval=on_interval):
flask-app_1      | 2019-11-11T16:15:42.659729398Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 54, in drain_events_until
flask-app_1      | 2019-11-11T16:15:42.659741316Z     raise socket.timeout()
flask-app_1      | 2019-11-11T16:15:42.659752989Z socket.timeout
flask-app_1      | 2019-11-11T16:15:42.659764327Z 
flask-app_1      | 2019-11-11T16:15:42.659775799Z During handling of the above exception, another exception occurred:
flask-app_1      | 2019-11-11T16:15:42.659787489Z 
flask-app_1      | 2019-11-11T16:15:42.659798829Z Traceback (most recent call last):
flask-app_1      | 2019-11-11T16:15:42.659810517Z   File "/usr/local/lib/python3.6/dist-packages/flask/app.py", line 1949, in full_dispatch_request
flask-app_1      | 2019-11-11T16:15:42.659822543Z     rv = self.dispatch_request()
flask-app_1      | 2019-11-11T16:15:42.659864822Z   File "/usr/local/lib/python3.6/dist-packages/flask/app.py", line 1935, in dispatch_request
flask-app_1      | 2019-11-11T16:15:42.659879547Z     return self.view_functions[rule.endpoint](**req.view_args)
flask-app_1      | 2019-11-11T16:15:42.659891299Z   File "/usr/local/lib/python3.6/dist-packages/flask_login/utils.py", line 261, in decorated_view
flask-app_1      | 2019-11-11T16:15:42.659903232Z     return func(*args, **kwargs)
flask-app_1      | 2019-11-11T16:15:42.659914779Z   File "/simoc/simoc_server/views.py", line 119, in new_game
flask-app_1      | 2019-11-11T16:15:42.659926495Z     result = tasks.new_game.delay(get_standard_user_obj().username, game_config).get(timeout=60)
flask-app_1      | 2019-11-11T16:15:42.659938106Z   File "/usr/local/lib/python3.6/dist-packages/celery/result.py", line 226, in get
flask-app_1      | 2019-11-11T16:15:42.659949903Z     on_message=on_message,
flask-app_1      | 2019-11-11T16:15:42.659961852Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 188, in wait_for_pending
flask-app_1      | 2019-11-11T16:15:42.659987845Z     for _ in self._wait_for_pending(result, **kwargs):
flask-app_1      | 2019-11-11T16:15:42.660002552Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 259, in _wait_for_pending
flask-app_1      | 2019-11-11T16:15:42.660030695Z     raise TimeoutError('The operation timed out.')
flask-app_1      | 2019-11-11T16:15:42.660045815Z celery.exceptions.TimeoutError: The operation timed out.
flask-app_1      | 2019-11-11T16:15:42.660057702Z [2019-11-11 16:15:42 +0000] [10] [ERROR] ERROR: handling exception The operation timed out.
flask-app_1      | 2019-11-11T16:15:42.662635247Z [2019-11-11 16:15:42 +0000] [10] [DEBUG] Closing connection. 
flask-app_1      | 2019-11-11T16:15:43.121297465Z Traceback (most recent call last):
flask-app_1      | 2019-11-11T16:15:43.121339898Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 255, in _wait_for_pending
flask-app_1      | 2019-11-11T16:15:43.121361811Z     on_interval=on_interval):
flask-app_1      | 2019-11-11T16:15:43.121375375Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 54, in drain_events_until
flask-app_1      | 2019-11-11T16:15:43.121387965Z     raise socket.timeout()
flask-app_1      | 2019-11-11T16:15:43.121399217Z socket.timeout
flask-app_1      | 2019-11-11T16:15:43.121410434Z 
flask-app_1      | 2019-11-11T16:15:43.121421642Z During handling of the above exception, another exception occurred:
flask-app_1      | 2019-11-11T16:15:43.121432866Z 
flask-app_1      | 2019-11-11T16:15:43.121444043Z Traceback (most recent call last):
flask-app_1      | 2019-11-11T16:15:43.121455146Z   File "/usr/local/lib/python3.6/dist-packages/flask/app.py", line 1949, in full_dispatch_request
flask-app_1      | 2019-11-11T16:15:43.121466851Z     rv = self.dispatch_request()
flask-app_1      | 2019-11-11T16:15:43.121477808Z   File "/usr/local/lib/python3.6/dist-packages/flask/app.py", line 1935, in dispatch_request
flask-app_1      | 2019-11-11T16:15:43.121489541Z     return self.view_functions[rule.endpoint](**req.view_args)
flask-app_1      | 2019-11-11T16:15:43.121500842Z   File "/usr/local/lib/python3.6/dist-packages/flask_login/utils.py", line 261, in decorated_view
flask-app_1      | 2019-11-11T16:15:43.121513150Z     return func(*args, **kwargs)
flask-app_1      | 2019-11-11T16:15:43.121524547Z   File "/simoc/simoc_server/views.py", line 119, in new_game
flask-app_1      | 2019-11-11T16:15:43.121536231Z     result = tasks.new_game.delay(get_standard_user_obj().username, game_config).get(timeout=60)
flask-app_1      | 2019-11-11T16:15:43.121547985Z   File "/usr/local/lib/python3.6/dist-packages/celery/result.py", line 226, in get
flask-app_1      | 2019-11-11T16:15:43.121559440Z     on_message=on_message,
flask-app_1      | 2019-11-11T16:15:43.121570626Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 188, in wait_for_pending
flask-app_1      | 2019-11-11T16:15:43.121582192Z     for _ in self._wait_for_pending(result, **kwargs):
flask-app_1      | 2019-11-11T16:15:43.121593600Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 259, in _wait_for_pending
flask-app_1      | 2019-11-11T16:15:43.121605134Z     raise TimeoutError('The operation timed out.')
flask-app_1      | 2019-11-11T16:15:43.121616449Z celery.exceptions.TimeoutError: The operation timed out.
flask-app_1      | 2019-11-11T16:15:43.121628506Z [2019-11-11 16:15:43 +0000] [9] [ERROR] ERROR: handling exception The operation timed out.
flask-app_1      | 2019-11-11T16:15:43.123982807Z [2019-11-11 16:15:43 +0000] [9] [DEBUG] Closing connection. 
flask-app_1      | 2019-11-11T16:15:43.301378618Z Traceback (most recent call last):
flask-app_1      | 2019-11-11T16:15:43.301417582Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 255, in _wait_for_pending
flask-app_1      | 2019-11-11T16:15:43.301432652Z     on_interval=on_interval):
flask-app_1      | 2019-11-11T16:15:43.301444295Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 54, in drain_events_until
flask-app_1      | 2019-11-11T16:15:43.301456146Z     raise socket.timeout()
flask-app_1      | 2019-11-11T16:15:43.301475407Z socket.timeout
flask-app_1      | 2019-11-11T16:15:43.301487791Z 
flask-app_1      | 2019-11-11T16:15:43.301498934Z During handling of the above exception, another exception occurred:
flask-app_1      | 2019-11-11T16:15:43.301510026Z 
flask-app_1      | 2019-11-11T16:15:43.301521096Z Traceback (most recent call last):
flask-app_1      | 2019-11-11T16:15:43.301532372Z   File "/usr/local/lib/python3.6/dist-packages/flask/app.py", line 1949, in full_dispatch_request
flask-app_1      | 2019-11-11T16:15:43.301544039Z     rv = self.dispatch_request()
flask-app_1      | 2019-11-11T16:15:43.301555543Z   File "/usr/local/lib/python3.6/dist-packages/flask/app.py", line 1935, in dispatch_request
flask-app_1      | 2019-11-11T16:15:43.301566925Z     return self.view_functions[rule.endpoint](**req.view_args)
flask-app_1      | 2019-11-11T16:15:43.301578226Z   File "/usr/local/lib/python3.6/dist-packages/flask_login/utils.py", line 261, in decorated_view
flask-app_1      | 2019-11-11T16:15:43.301590058Z     return func(*args, **kwargs)
flask-app_1      | 2019-11-11T16:15:43.301600936Z   File "/simoc/simoc_server/views.py", line 119, in new_game
flask-app_1      | 2019-11-11T16:15:43.301612276Z     result = tasks.new_game.delay(get_standard_user_obj().username, game_config).get(timeout=60)
flask-app_1      | 2019-11-11T16:15:43.301623489Z   File "/usr/local/lib/python3.6/dist-packages/celery/result.py", line 226, in get
flask-app_1      | 2019-11-11T16:15:43.301635057Z     on_message=on_message,
flask-app_1      | 2019-11-11T16:15:43.301645950Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 188, in wait_for_pending
flask-app_1      | 2019-11-11T16:15:43.301657624Z     for _ in self._wait_for_pending(result, **kwargs):
flask-app_1      | 2019-11-11T16:15:43.301669151Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 259, in _wait_for_pending
flask-app_1      | 2019-11-11T16:15:43.301680982Z     raise TimeoutError('The operation timed out.')
flask-app_1      | 2019-11-11T16:15:43.301691903Z celery.exceptions.TimeoutError: The operation timed out.
flask-app_1      | 2019-11-11T16:15:43.301703110Z [2019-11-11 16:15:43 +0000] [10] [ERROR] ERROR: handling exception The operation timed out.
flask-app_1      | 2019-11-11T16:15:43.303279560Z [2019-11-11 16:15:43 +0000] [10] [DEBUG] Closing connection. 
celery-worker_1  | 2019-11-11T16:19:43.632042746Z [2019-11-11 16:19:43,630: INFO/ForkPoolWorker-7] Cleaning up save game for user with id 9
ezio-melotti commented 4 years ago

The next day a new user registered, tried to start a new game with similar results (celery-worker_1 returning earlier and celery-worker_2 giving errors), played a bit with the graphs in the config, and left.

ezio-melotti commented 4 years ago

I managed to accidentally reproduce this locally. Yesterday I ran a 10-humans sim on the websocket branch to completion, then left everything there for about ~30 hours. Today I picked up the browser again (tab still open), used the back button to go back to the config wizard, and started a 1-human sim and got the error below. Further attempts results in more celery.exceptions.TimeoutError: The operation timed out. errors from the flask-app_1 container. Even if I log out and log in again I get the same errors when I try to start a new sim. This is the error from celery-worker_1:

Traceback (most recent call last):
  File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1171, in _execute_context
    conn = self._revalidate_connection()
  File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 457, in _revalidate_connection
    "Can't reconnect until invalid "
sqlalchemy.exc.InvalidRequestError: Can't reconnect until invalid transaction is rolled back

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.6/dist-packages/celery/app/trace.py", line 385, in trace_task
    R = retval = fun(*args, **kwargs)
  File "/usr/local/lib/python3.6/dist-packages/celery/app/trace.py", line 648, in __protected_call__
    return self.run(*args, **kwargs)
  File "/simoc/celery_worker/tasks.py", line 64, in new_game
    user = get_user(username)
  File "/simoc/celery_worker/tasks.py", line 34, in get_user
    user = User.query.filter_by(username=username).all()
  File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py", line 3211, in all
    return list(self)
  File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py", line 3367, in __iter__
    return self._execute_and_instances(context)
  File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py", line 3392, in _execute_and_instances
    result = conn.execute(querycontext.statement, self._params)
  File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 982, in execute
    return meth(self, multiparams, params)
  File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/sql/elements.py", line 287, in _execute_on_connection
    return connection._execute_clauseelement(self, multiparams, params)
  File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1101, in _execute_clauseelement
    distilled_params,
  File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1176, in _execute_context
    e, util.text_type(statement), parameters, None, None
  File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1476, in _handle_dbapi_exception
    util.raise_from_cause(sqlalchemy_exception, exc_info)
  File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/util/compat.py", line 398, in raise_from_cause
    reraise(type(exception), exception, tb=exc_tb, cause=cause)
  File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/util/compat.py", line 152, in reraise
    raise value.with_traceback(tb)
  File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1171, in _execute_context
    conn = self._revalidate_connection()
  File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 457, in _revalidate_connection
    "Can't reconnect until invalid "
sqlalchemy.exc.StatementError: (sqlalchemy.exc.InvalidRequestError) Can't reconnect until invalid transaction is rolled back
[SQL: SELECT user.id AS user_id, user.username AS user_username, user.password_hash AS user_password_hash, user.date_created AS user_date_created, user.da
FROM user 
WHERE user.username = %(username_1)s]
[parameters: [immutabledict({})]]

And this is the error from flask-app_1 (after a 60s timeout):

Traceback (most recent call last):
  File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 255, in _wait_for_pending
    on_interval=on_interval):
  File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 54, in drain_events_until
    raise socket.timeout()
socket.timeout

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.6/dist-packages/flask/app.py", line 1949, in full_dispatch_request
    rv = self.dispatch_request()
  File "/usr/local/lib/python3.6/dist-packages/flask/app.py", line 1935, in dispatch_request
    return self.view_functions[rule.endpoint](**req.view_args)
  File "/usr/local/lib/python3.6/dist-packages/flask_login/utils.py", line 261, in decorated_view
    return func(*args, **kwargs)
  File "/simoc/simoc_server/views.py", line 196, in new_game
    result = tasks.new_game.delay(get_standard_user_obj().username, game_config).get(timeout=60)
  File "/usr/local/lib/python3.6/dist-packages/celery/result.py", line 226, in get
    on_message=on_message,
  File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 188, in wait_for_pending
    for _ in self._wait_for_pending(result, **kwargs):
  File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 259, in _wait_for_pending
    raise TimeoutError('The operation timed out.')
celery.exceptions.TimeoutError: The operation timed out.
[2019-12-17 02:23:57 +0000] [9] [ERROR] ERROR: handling exception The operation timed out.
[2019-12-17 02:24:52,997: INFO/ForkPoolWorker-2] Cleaning up save game for user with id 1

The containers all seem up and running since yesterday:

$ docker ps
CONTAINER ID        IMAGE                 COMMAND                  CREATED             STATUS                  PORTS                               NAMES
875c1c3698f3        simoc_celery-worker   "/bin/bash start_wor…"   30 hours ago        Up 30 hours                                                 simoc_celery-worker_1
c85a33855b29        simoc_flask-app       "/bin/bash run.sh"       30 hours ago        Up 30 hours             0.0.0.0:8000->8000/tcp              simoc_flask-app_1
d4c7e4488c61        simoc_celery-worker   "/bin/bash start_wor…"   30 hours ago        Up 30 hours                                                 simoc_celery-worker_2
fbd94d9c72a3        mysql/mysql-server    "/entrypoint.sh mysq…"   30 hours ago        Up 30 hours (healthy)   0.0.0.0:3306->3306/tcp, 33060/tcp   simoc_simoc-db_1
3609e29fc08c        redis                 "docker-entrypoint.s…"   30 hours ago        Up 30 hours             0.0.0.0:6379->6379/tcp              simoc_redis_1
iurii-milovanov commented 4 years ago

Should be fixed by this https://github.com/kstaats/simoc/commit/4a7bd9b8eca8466deaa239c1d2e0e65833a9f219. Please confirm.

ezio-melotti commented 4 years ago

I got the same error today, by leaving the browser open for ~9 hours on the config wizard screen and then clicking on "Finalize settings" to start a new game. It seems to me that after leaving it there for a while, MySQL disconnects, and this causes OperationalError: MySQL Connection not available.. This failure leaves an uncommited transaction that needs to be rolled back before being able to continue.

The first line of the log is the last operation before leaving the browser, then there's the request to /new_game that caused the OperationalError (followed by a timeout error after 1 minute), and a second attempt to start a new sim results in the InvalidRequestError.

flask-app_1      | 2019-12-19T08:21:14.175899110Z [2019-12-19 08:21:14 +0000] [9] [DEBUG] Closing connection. 
flask-app_1      | 2019-12-19T17:16:25.665428630Z [2019-12-19 17:16:25 +0000] [9] [DEBUG] POST /new_game
celery-worker_1  | 2019-12-19T17:16:26.005001868Z [2019-12-19 17:16:26,004: INFO/MainProcess] Received task: celery_worker.tasks.new_game[088b18c5-0c82-48ae-a6f6-0e6e595bc8a6]  
celery-worker_1  | 2019-12-19T17:16:26.005233839Z [2019-12-19 17:16:26,004: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x7f1781449c80> (args:('celery_worker.tasks.new_game', '088b18c5-0c82-48ae-a6f6-0e6e595bc8a6', {'lang': 'py', 'task': 'celery_worker.tasks.new_game', 'id': '088b18c5-0c82-48ae-a6f6-0e6e595bc8a6', 'shadow': None, 'eta': None, 'expires': None, 'group': None, 'retries': 0, 'timelimit': [None, None], 'root_id': '088b18c5-0c82-48ae-a6f6-0e6e595bc8a6', 'parent_id': None, 'argsrepr': "('eziom', {'agents': {'human_agent': [...], 'solid_waste_aerobic_bioreactor': [...], 'multifiltration_purifier_post_treament': [...], 'oxygen_generation_SFWE': [...], 'urine_recycling_processor_VCD': [...], 'co2_removal_SAWD': [...], 'co2_reduction_sabatier': [...], 'crew_habitat_small': [...], 'solar_pv_array_mars': [...]}, 'storages': {'air_storage': [...], 'water_storage': [...], 'nutrient_storage': [...], 'power_storage': [...], 'food_storage': [...]}, 'termination': [{...}], 'single_agent': 1})", 'kwargsrepr': '{}', 'origin': 'gen9@c85a33855b29', 'reply_to': '339f0422-8bfe-3808-b4e4-ae30c8a7322b', 'correlation_id':... kwargs:{})
celery-worker_1  | 2019-12-19T17:16:26.008052248Z [2019-12-19 17:16:26,007: DEBUG/MainProcess] Task accepted: celery_worker.tasks.new_game[088b18c5-0c82-48ae-a6f6-0e6e595bc8a6] pid:18
celery-worker_1  | 2019-12-19T17:16:26.121131284Z [2019-12-19 17:16:26,098: ERROR/ForkPoolWorker-2] Task celery_worker.tasks.new_game[088b18c5-0c82-48ae-a6f6-0e6e595bc8a6] raised unexpected: OperationalError('(mysql.connector.errors.OperationalError) MySQL Connection not available.',)
celery-worker_1  | 2019-12-19T17:16:26.121194594Z Traceback (most recent call last):
celery-worker_1  | 2019-12-19T17:16:26.121211491Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1173, in _execute_context
celery-worker_1  | 2019-12-19T17:16:26.121227751Z     context = constructor(dialect, self, conn, *args)
celery-worker_1  | 2019-12-19T17:16:26.121241766Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/default.py", line 768, in _init_compiled
celery-worker_1  | 2019-12-19T17:16:26.121257162Z     self.cursor = self.create_cursor()
celery-worker_1  | 2019-12-19T17:16:26.121270632Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/default.py", line 1122, in create_cursor
celery-worker_1  | 2019-12-19T17:16:26.121285412Z     return self._dbapi_connection.cursor()
celery-worker_1  | 2019-12-19T17:16:26.121302146Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/pool/base.py", line 965, in cursor
celery-worker_1  | 2019-12-19T17:16:26.121320344Z     return self.connection.cursor(*args, **kwargs)
celery-worker_1  | 2019-12-19T17:16:26.121338597Z   File "/usr/local/lib/python3.6/dist-packages/mysql/connector/connection_cext.py", line 524, in cursor
celery-worker_1  | 2019-12-19T17:16:26.121356893Z     raise errors.OperationalError("MySQL Connection not available.")
celery-worker_1  | 2019-12-19T17:16:26.121371083Z mysql.connector.errors.OperationalError: MySQL Connection not available.
celery-worker_1  | 2019-12-19T17:16:26.121384433Z 
celery-worker_1  | 2019-12-19T17:16:26.121398098Z The above exception was the direct cause of the following exception:
celery-worker_1  | 2019-12-19T17:16:26.121412142Z 
celery-worker_1  | 2019-12-19T17:16:26.121425566Z Traceback (most recent call last):
celery-worker_1  | 2019-12-19T17:16:26.121442342Z   File "/usr/local/lib/python3.6/dist-packages/celery/app/trace.py", line 385, in trace_task
celery-worker_1  | 2019-12-19T17:16:26.121484114Z     R = retval = fun(*args, **kwargs)
celery-worker_1  | 2019-12-19T17:16:26.121500900Z   File "/usr/local/lib/python3.6/dist-packages/celery/app/trace.py", line 648, in __protected_call__
celery-worker_1  | 2019-12-19T17:16:26.121518662Z     return self.run(*args, **kwargs)
celery-worker_1  | 2019-12-19T17:16:26.121535432Z   File "/simoc/celery_worker/tasks.py", line 64, in new_game
celery-worker_1  | 2019-12-19T17:16:26.121551855Z     user = get_user(username)
celery-worker_1  | 2019-12-19T17:16:26.121569232Z   File "/simoc/celery_worker/tasks.py", line 34, in get_user
celery-worker_1  | 2019-12-19T17:16:26.121585772Z     user = User.query.filter_by(username=username).all()
celery-worker_1  | 2019-12-19T17:16:26.121603748Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py", line 3211, in all
celery-worker_1  | 2019-12-19T17:16:26.121620087Z     return list(self)
celery-worker_1  | 2019-12-19T17:16:26.121634941Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py", line 3367, in __iter__
celery-worker_1  | 2019-12-19T17:16:26.121651034Z     return self._execute_and_instances(context)
celery-worker_1  | 2019-12-19T17:16:26.121670559Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py", line 3392, in _execute_and_instances
celery-worker_1  | 2019-12-19T17:16:26.121687732Z     result = conn.execute(querycontext.statement, self._params)
celery-worker_1  | 2019-12-19T17:16:26.121703074Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 982, in execute
celery-worker_1  | 2019-12-19T17:16:26.121719912Z     return meth(self, multiparams, params)
celery-worker_1  | 2019-12-19T17:16:26.121735740Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/sql/elements.py", line 287, in _execute_on_connection
celery-worker_1  | 2019-12-19T17:16:26.121752089Z     return connection._execute_clauseelement(self, multiparams, params)
celery-worker_1  | 2019-12-19T17:16:26.121768481Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1101, in _execute_clauseelement
celery-worker_1  | 2019-12-19T17:16:26.121785524Z     distilled_params,
celery-worker_1  | 2019-12-19T17:16:26.121800296Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1176, in _execute_context
celery-worker_1  | 2019-12-19T17:16:26.121816928Z     e, util.text_type(statement), parameters, None, None
celery-worker_1  | 2019-12-19T17:16:26.121832404Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1476, in _handle_dbapi_exception
celery-worker_1  | 2019-12-19T17:16:26.121847883Z     util.raise_from_cause(sqlalchemy_exception, exc_info)
celery-worker_1  | 2019-12-19T17:16:26.121863768Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/util/compat.py", line 398, in raise_from_cause
celery-worker_1  | 2019-12-19T17:16:26.121880291Z     reraise(type(exception), exception, tb=exc_tb, cause=cause)
celery-worker_1  | 2019-12-19T17:16:26.121896652Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/util/compat.py", line 152, in reraise
celery-worker_1  | 2019-12-19T17:16:26.121913385Z     raise value.with_traceback(tb)
celery-worker_1  | 2019-12-19T17:16:26.121929348Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1173, in _execute_context
celery-worker_1  | 2019-12-19T17:16:26.121959071Z     context = constructor(dialect, self, conn, *args)
celery-worker_1  | 2019-12-19T17:16:26.121974477Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/default.py", line 768, in _init_compiled
celery-worker_1  | 2019-12-19T17:16:26.121991535Z     self.cursor = self.create_cursor()
celery-worker_1  | 2019-12-19T17:16:26.122007070Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/default.py", line 1122, in create_cursor
celery-worker_1  | 2019-12-19T17:16:26.122023641Z     return self._dbapi_connection.cursor()
celery-worker_1  | 2019-12-19T17:16:26.122038439Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/pool/base.py", line 965, in cursor
celery-worker_1  | 2019-12-19T17:16:26.122054801Z     return self.connection.cursor(*args, **kwargs)
celery-worker_1  | 2019-12-19T17:16:26.122070443Z   File "/usr/local/lib/python3.6/dist-packages/mysql/connector/connection_cext.py", line 524, in cursor
celery-worker_1  | 2019-12-19T17:16:26.122085888Z     raise errors.OperationalError("MySQL Connection not available.")
celery-worker_1  | 2019-12-19T17:16:26.122103935Z sqlalchemy.exc.OperationalError: (mysql.connector.errors.OperationalError) MySQL Connection not available.
celery-worker_1  | 2019-12-19T17:16:26.122121490Z [SQL: SELECT user.id AS user_id, user.username AS user_username, user.password_hash AS user_password_hash, user.date_created AS user_date_created, user.date_modified AS user_date_modified 
celery-worker_1  | 2019-12-19T17:16:26.122138006Z FROM user 
celery-worker_1  | 2019-12-19T17:16:26.122153938Z WHERE user.username = %(username_1)s]
celery-worker_1  | 2019-12-19T17:16:26.122169866Z [parameters: [immutabledict({})]]
celery-worker_1  | 2019-12-19T17:16:26.122185555Z (Background on this error at: http://sqlalche.me/e/e3q8)
flask-app_1      | 2019-12-19T17:17:26.047373213Z Traceback (most recent call last):
flask-app_1      | 2019-12-19T17:17:26.047444956Z   File "src/gevent/greenlet.py", line 766, in gevent._greenlet.Greenlet.run
flask-app_1      | 2019-12-19T17:17:26.047462758Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 82, in run
flask-app_1      | 2019-12-19T17:17:26.047477833Z     self.result_consumer.drain_events(timeout=1)
flask-app_1      | 2019-12-19T17:17:26.047491810Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/redis.py", line 129, in drain_events
flask-app_1      | 2019-12-19T17:17:26.047532854Z     self.on_state_change(self._decode_result(message['data']), message)
flask-app_1      | 2019-12-19T17:17:26.047547076Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/base.py", line 305, in decode_result
flask-app_1      | 2019-12-19T17:17:26.047561236Z     return self.meta_from_decoded(self.decode(payload))
flask-app_1      | 2019-12-19T17:17:26.047574918Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/base.py", line 301, in meta_from_decoded
flask-app_1      | 2019-12-19T17:17:26.047589072Z     meta['result'] = self.exception_to_python(meta['result'])
flask-app_1      | 2019-12-19T17:17:26.047603211Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/base.py", line 281, in exception_to_python
flask-app_1      | 2019-12-19T17:17:26.047617358Z     exc = cls(*exc_msg if isinstance(exc_msg, tuple) else exc_msg)
flask-app_1      | 2019-12-19T17:17:26.047630160Z TypeError: __init__() missing 2 required positional arguments: 'params' and 'orig'
flask-app_1      | 2019-12-19T17:17:26.047643109Z 2019-12-19T17:16:26Z <Greenlet at 0x7efd45467e48: <bound method greenletDrainer.run of <celery.backends.asynchronous.geventDrainer object at 0x7efd44b55898>>> failed with TypeError
flask-app_1      | 2019-12-19T17:17:26.047661705Z 
flask-app_1      | 2019-12-19T17:17:26.047676597Z Traceback (most recent call last):
flask-app_1      | 2019-12-19T17:17:26.047689450Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 255, in _wait_for_pending
flask-app_1      | 2019-12-19T17:17:26.047703803Z     on_interval=on_interval):
flask-app_1      | 2019-12-19T17:17:26.047717065Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 54, in drain_events_until
flask-app_1      | 2019-12-19T17:17:26.047728717Z     raise socket.timeout()
flask-app_1      | 2019-12-19T17:17:26.047739268Z socket.timeout
flask-app_1      | 2019-12-19T17:17:26.047750965Z 
flask-app_1      | 2019-12-19T17:17:26.047762485Z During handling of the above exception, another exception occurred:
flask-app_1      | 2019-12-19T17:17:26.047774773Z 
flask-app_1      | 2019-12-19T17:17:26.047786956Z Traceback (most recent call last):
flask-app_1      | 2019-12-19T17:17:26.047799216Z   File "/usr/local/lib/python3.6/dist-packages/flask/app.py", line 1949, in full_dispatch_request
flask-app_1      | 2019-12-19T17:17:26.047811661Z     rv = self.dispatch_request()
flask-app_1      | 2019-12-19T17:17:26.047822671Z   File "/usr/local/lib/python3.6/dist-packages/flask/app.py", line 1935, in dispatch_request
flask-app_1      | 2019-12-19T17:17:26.047834915Z     return self.view_functions[rule.endpoint](**req.view_args)
flask-app_1      | 2019-12-19T17:17:26.047846796Z   File "/usr/local/lib/python3.6/dist-packages/flask_login/utils.py", line 261, in decorated_view
flask-app_1      | 2019-12-19T17:17:26.047859617Z     return func(*args, **kwargs)
flask-app_1      | 2019-12-19T17:17:26.047873889Z   File "/simoc/simoc_server/views.py", line 196, in new_game
flask-app_1      | 2019-12-19T17:17:26.047886338Z     result = tasks.new_game.delay(get_standard_user_obj().username, game_config).get(timeout=60)
flask-app_1      | 2019-12-19T17:17:26.047898795Z   File "/usr/local/lib/python3.6/dist-packages/celery/result.py", line 226, in get
flask-app_1      | 2019-12-19T17:17:26.047922069Z     on_message=on_message,
flask-app_1      | 2019-12-19T17:17:26.047934090Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 188, in wait_for_pending
flask-app_1      | 2019-12-19T17:17:26.047946914Z     for _ in self._wait_for_pending(result, **kwargs):
flask-app_1      | 2019-12-19T17:17:26.047958970Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 259, in _wait_for_pending
flask-app_1      | 2019-12-19T17:17:26.047971330Z     raise TimeoutError('The operation timed out.')
flask-app_1      | 2019-12-19T17:17:26.048044011Z celery.exceptions.TimeoutError: The operation timed out.
flask-app_1      | 2019-12-19T17:17:26.048057952Z [2019-12-19 17:17:26 +0000] [9] [ERROR] ERROR: handling exception The operation timed out.
flask-app_1      | 2019-12-19T17:17:26.060105233Z [2019-12-19 17:17:26 +0000] [9] [DEBUG] Closing connection. 

flask-app_1      | 2019-12-19T17:25:32.960851907Z [2019-12-19 17:25:32 +0000] [9] [DEBUG] POST /new_game
celery-worker_1  | 2019-12-19T17:25:33.030124502Z [2019-12-19 17:25:33,029: INFO/MainProcess] Received task: celery_worker.tasks.new_game[57e5f028-1af4-4fae-9f17-69014d227263]  
celery-worker_1  | 2019-12-19T17:25:33.030725899Z [2019-12-19 17:25:33,030: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x7f1781449c80> (args:('celery_worker.tasks.new_game', '57e5f028-1af4-4fae-9f17-69014d227263', {'lang': 'py', 'task': 'celery_worker.tasks.new_game', 'id': '57e5f028-1af4-4fae-9f17-69014d227263', 'shadow': None, 'eta': None, 'expires': None, 'group': None, 'retries': 0, 'timelimit': [None, None], 'root_id': '57e5f028-1af4-4fae-9f17-69014d227263', 'parent_id': None, 'argsrepr': "('eziom', {'agents': {'human_agent': [...], 'solid_waste_aerobic_bioreactor': [...], 'multifiltration_purifier_post_treament': [...], 'oxygen_generation_SFWE': [...], 'urine_recycling_processor_VCD': [...], 'co2_removal_SAWD': [...], 'co2_reduction_sabatier': [...], 'crew_habitat_small': [...], 'solar_pv_array_mars': [...]}, 'storages': {'air_storage': [...], 'water_storage': [...], 'nutrient_storage': [...], 'power_storage': [...], 'food_storage': [...]}, 'termination': [{...}], 'single_agent': 1})", 'kwargsrepr': '{}', 'origin': 'gen9@c85a33855b29', 'reply_to': '339f0422-8bfe-3808-b4e4-ae30c8a7322b', 'correlation_id':... kwargs:{})
celery-worker_1  | 2019-12-19T17:25:33.033779578Z [2019-12-19 17:25:33,033: DEBUG/MainProcess] Task accepted: celery_worker.tasks.new_game[57e5f028-1af4-4fae-9f17-69014d227263] pid:18
celery-worker_1  | 2019-12-19T17:25:33.038549962Z [2019-12-19 17:25:33,037: ERROR/ForkPoolWorker-2] Task celery_worker.tasks.new_game[57e5f028-1af4-4fae-9f17-69014d227263] raised unexpected: StatementError("(sqlalchemy.exc.InvalidRequestError) Can't reconnect until invalid transaction is rolled back",)
celery-worker_1  | 2019-12-19T17:25:33.038618556Z Traceback (most recent call last):
celery-worker_1  | 2019-12-19T17:25:33.038626460Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1171, in _execute_context
celery-worker_1  | 2019-12-19T17:25:33.038633363Z     conn = self._revalidate_connection()
celery-worker_1  | 2019-12-19T17:25:33.038639887Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 457, in _revalidate_connection
celery-worker_1  | 2019-12-19T17:25:33.038646058Z     "Can't reconnect until invalid "
celery-worker_1  | 2019-12-19T17:25:33.038652142Z sqlalchemy.exc.InvalidRequestError: Can't reconnect until invalid transaction is rolled back
celery-worker_1  | 2019-12-19T17:25:33.038658256Z 
celery-worker_1  | 2019-12-19T17:25:33.038664437Z The above exception was the direct cause of the following exception:
celery-worker_1  | 2019-12-19T17:25:33.038670877Z 
celery-worker_1  | 2019-12-19T17:25:33.038676895Z Traceback (most recent call last):
celery-worker_1  | 2019-12-19T17:25:33.038682710Z   File "/usr/local/lib/python3.6/dist-packages/celery/app/trace.py", line 385, in trace_task
celery-worker_1  | 2019-12-19T17:25:33.038689561Z     R = retval = fun(*args, **kwargs)
celery-worker_1  | 2019-12-19T17:25:33.038695586Z   File "/usr/local/lib/python3.6/dist-packages/celery/app/trace.py", line 648, in __protected_call__
celery-worker_1  | 2019-12-19T17:25:33.038701784Z     return self.run(*args, **kwargs)
celery-worker_1  | 2019-12-19T17:25:33.038707572Z   File "/simoc/celery_worker/tasks.py", line 64, in new_game
celery-worker_1  | 2019-12-19T17:25:33.038713853Z     user = get_user(username)
celery-worker_1  | 2019-12-19T17:25:33.038719735Z   File "/simoc/celery_worker/tasks.py", line 34, in get_user
celery-worker_1  | 2019-12-19T17:25:33.038725873Z     user = User.query.filter_by(username=username).all()
celery-worker_1  | 2019-12-19T17:25:33.038731446Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py", line 3211, in all
celery-worker_1  | 2019-12-19T17:25:33.038737755Z     return list(self)
celery-worker_1  | 2019-12-19T17:25:33.038743350Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py", line 3367, in __iter__
celery-worker_1  | 2019-12-19T17:25:33.038749559Z     return self._execute_and_instances(context)
celery-worker_1  | 2019-12-19T17:25:33.038755599Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py", line 3392, in _execute_and_instances
celery-worker_1  | 2019-12-19T17:25:33.038761869Z     result = conn.execute(querycontext.statement, self._params)
celery-worker_1  | 2019-12-19T17:25:33.038767952Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 982, in execute
celery-worker_1  | 2019-12-19T17:25:33.038774129Z     return meth(self, multiparams, params)
celery-worker_1  | 2019-12-19T17:25:33.038780904Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/sql/elements.py", line 287, in _execute_on_connection
celery-worker_1  | 2019-12-19T17:25:33.038787347Z     return connection._execute_clauseelement(self, multiparams, params)
celery-worker_1  | 2019-12-19T17:25:33.038794725Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1101, in _execute_clauseelement
celery-worker_1  | 2019-12-19T17:25:33.038801247Z     distilled_params,
celery-worker_1  | 2019-12-19T17:25:33.038807224Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1176, in _execute_context
celery-worker_1  | 2019-12-19T17:25:33.038818896Z     e, util.text_type(statement), parameters, None, None
celery-worker_1  | 2019-12-19T17:25:33.038825236Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1476, in _handle_dbapi_exception
celery-worker_1  | 2019-12-19T17:25:33.038831881Z     util.raise_from_cause(sqlalchemy_exception, exc_info)
celery-worker_1  | 2019-12-19T17:25:33.038838164Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/util/compat.py", line 398, in raise_from_cause
celery-worker_1  | 2019-12-19T17:25:33.038844837Z     reraise(type(exception), exception, tb=exc_tb, cause=cause)
celery-worker_1  | 2019-12-19T17:25:33.038850671Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/util/compat.py", line 152, in reraise
celery-worker_1  | 2019-12-19T17:25:33.038857087Z     raise value.with_traceback(tb)
celery-worker_1  | 2019-12-19T17:25:33.038863071Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1171, in _execute_context
celery-worker_1  | 2019-12-19T17:25:33.038869472Z     conn = self._revalidate_connection()
celery-worker_1  | 2019-12-19T17:25:33.038875422Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 457, in _revalidate_connection
celery-worker_1  | 2019-12-19T17:25:33.038881769Z     "Can't reconnect until invalid "
celery-worker_1  | 2019-12-19T17:25:33.038887605Z sqlalchemy.exc.StatementError: (sqlalchemy.exc.InvalidRequestError) Can't reconnect until invalid transaction is rolled back
celery-worker_1  | 2019-12-19T17:25:33.038893785Z [SQL: SELECT user.id AS user_id, user.username AS user_username, user.password_hash AS user_password_hash, user.date_created AS user_date_created, user.date_modified AS user_date_modified 
celery-worker_1  | 2019-12-19T17:25:33.038900557Z FROM user 
celery-worker_1  | 2019-12-19T17:25:33.038906401Z WHERE user.username = %(username_1)s]
celery-worker_1  | 2019-12-19T17:25:33.038912145Z [parameters: [immutabledict({})]]
flask-app_1      | 2019-12-19T17:26:33.029634407Z Traceback (most recent call last):
flask-app_1      | 2019-12-19T17:26:33.029705615Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 255, in _wait_for_pending
flask-app_1      | 2019-12-19T17:26:33.029715119Z     on_interval=on_interval):
flask-app_1      | 2019-12-19T17:26:33.029723639Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 54, in drain_events_until
flask-app_1      | 2019-12-19T17:26:33.029731901Z     raise socket.timeout()
flask-app_1      | 2019-12-19T17:26:33.029740936Z socket.timeout
flask-app_1      | 2019-12-19T17:26:33.042155720Z 
flask-app_1      | 2019-12-19T17:26:33.042255984Z During handling of the above exception, another exception occurred:
flask-app_1      | 2019-12-19T17:26:33.042277378Z 
flask-app_1      | 2019-12-19T17:26:33.042330996Z Traceback (most recent call last):
flask-app_1      | 2019-12-19T17:26:33.042351657Z   File "/usr/local/lib/python3.6/dist-packages/flask/app.py", line 1949, in full_dispatch_request
flask-app_1      | 2019-12-19T17:26:33.042403265Z     rv = self.dispatch_request()
flask-app_1      | 2019-12-19T17:26:33.042423643Z   File "/usr/local/lib/python3.6/dist-packages/flask/app.py", line 1935, in dispatch_request
flask-app_1      | 2019-12-19T17:26:33.042480512Z     return self.view_functions[rule.endpoint](**req.view_args)
flask-app_1      | 2019-12-19T17:26:33.042501409Z   File "/usr/local/lib/python3.6/dist-packages/flask_login/utils.py", line 261, in decorated_view
flask-app_1      | 2019-12-19T17:26:33.042555878Z     return func(*args, **kwargs)
flask-app_1      | 2019-12-19T17:26:33.042576874Z   File "/simoc/simoc_server/views.py", line 196, in new_game
flask-app_1      | 2019-12-19T17:26:33.042627248Z     result = tasks.new_game.delay(get_standard_user_obj().username, game_config).get(timeout=60)
flask-app_1      | 2019-12-19T17:26:33.042647660Z   File "/usr/local/lib/python3.6/dist-packages/celery/result.py", line 226, in get
flask-app_1      | 2019-12-19T17:26:33.042701269Z     on_message=on_message,
flask-app_1      | 2019-12-19T17:26:33.042720967Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 188, in wait_for_pending
flask-app_1      | 2019-12-19T17:26:33.042774252Z     for _ in self._wait_for_pending(result, **kwargs):
flask-app_1      | 2019-12-19T17:26:33.042811065Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 259, in _wait_for_pending
flask-app_1      | 2019-12-19T17:26:33.042861590Z     raise TimeoutError('The operation timed out.')
flask-app_1      | 2019-12-19T17:26:33.042881638Z celery.exceptions.TimeoutError: The operation timed out.
flask-app_1      | 2019-12-19T17:26:33.042929864Z [2019-12-19 17:26:33 +0000] [9] [ERROR] ERROR: handling exception The operation timed out.
flask-app_1      | 2019-12-19T17:26:33.042953888Z [2019-12-19 17:26:33 +0000] [9] [DEBUG] Closing connection. 
iurii-milovanov commented 4 years ago

I tried to fix it with my latest commit (https://github.com/kstaats/simoc/commit/02b071c735c0ffc346494e7558ff55a2bb827024).

Could you please test it one more time?

ezio-melotti commented 4 years ago

I got the another error today. I pulled the latest changes you pushed a couple of days ago, restarted the containers, launched SIMOC, run a sim, went back to the config wizard and left it there with the browser open. Now I selected the "one human" preset from the tab I left open, did "Finalize settings" and got the same error message.

The first time I did "Finalize settings" I got the usual OperationalError: MySQL Connection not available.:

flask-app_1      | 2019-12-24T22:20:25.433543694Z [2019-12-24 22:20:25 +0000] [9] [DEBUG] POST /new_game
celery-worker_1  | 2019-12-24T22:20:26.474008962Z [2019-12-24 22:20:26,409: INFO/MainProcess] Received task: celery_worker.tasks.new_game[2e827696-2b05-4bb5-b726-fdac7f46fb02]  
celery-worker_1  | 2019-12-24T22:20:26.521595268Z [2019-12-24 22:20:26,410: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x7ffa30169c80> (args:('celery_worker.tasks.new_game', '2e827696-2b05-4bb5-b726-fdac7f46fb02', {'lang': 'py', 'task': 'celery_worker.tasks.new_game', 'id': '2e827696-2b05-4bb5-b726-fdac7f46fb02', 'shadow': None, 'eta': None, 'expires': None, 'group': None, 'retries': 0, 'timelimit': [None, None], 'root_id': '2e827696-2b05-4bb5-b726-fdac7f46fb02', 'parent_id': None, 'argsrepr': "('eziom', {'agents': {'human_agent': [...], 'solid_waste_aerobic_bioreactor': [...], 'multifiltration_purifier_post_treament': [...], 'oxygen_generation_SFWE': [...], 'urine_recycling_processor_VCD': [...], 'co2_removal_SAWD': [...], 'co2_reduction_sabatier': [...], 'crew_habitat_small': [...], 'solar_pv_array_mars': [...]}, 'storages': {'air_storage': [...], 'water_storage': [...], 'nutrient_storage': [...], 'power_storage': [...], 'food_storage': [...]}, 'termination': [{...}], 'single_agent': 1})", 'kwargsrepr': '{}', 'origin': 'gen9@c85a33855b29', 'reply_to': '749757ed-da6e-341a-ad80-61221d9877e6', 'correlation_id':... kwargs:{})
celery-worker_1  | 2019-12-24T22:20:26.521658682Z [2019-12-24 22:20:26,413: DEBUG/MainProcess] Task accepted: celery_worker.tasks.new_game[2e827696-2b05-4bb5-b726-fdac7f46fb02] pid:18
celery-worker_1  | 2019-12-24T22:20:26.748598751Z [2019-12-24 22:20:26,725: ERROR/ForkPoolWorker-2] Task celery_worker.tasks.new_game[2e827696-2b05-4bb5-b726-fdac7f46fb02] raised unexpected: OperationalError('(mysql.connector.errors.OperationalError) MySQL Connection not available.',)
celery-worker_1  | 2019-12-24T22:20:26.748656875Z Traceback (most recent call last):
celery-worker_1  | 2019-12-24T22:20:26.748673499Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1173, in _execute_context
celery-worker_1  | 2019-12-24T22:20:26.748682459Z     context = constructor(dialect, self, conn, *args)
celery-worker_1  | 2019-12-24T22:20:26.748689427Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/default.py", line 768, in _init_compiled
celery-worker_1  | 2019-12-24T22:20:26.748696663Z     self.cursor = self.create_cursor()
celery-worker_1  | 2019-12-24T22:20:26.748703219Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/default.py", line 1122, in create_cursor
celery-worker_1  | 2019-12-24T22:20:26.748710946Z     return self._dbapi_connection.cursor()
celery-worker_1  | 2019-12-24T22:20:26.748717712Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/pool/base.py", line 965, in cursor
celery-worker_1  | 2019-12-24T22:20:26.748724549Z     return self.connection.cursor(*args, **kwargs)
celery-worker_1  | 2019-12-24T22:20:26.748731644Z   File "/usr/local/lib/python3.6/dist-packages/mysql/connector/connection_cext.py", line 524, in cursor
celery-worker_1  | 2019-12-24T22:20:26.748739101Z     raise errors.OperationalError("MySQL Connection not available.")
celery-worker_1  | 2019-12-24T22:20:26.748765806Z mysql.connector.errors.OperationalError: MySQL Connection not available.
celery-worker_1  | 2019-12-24T22:20:26.748775466Z 
celery-worker_1  | 2019-12-24T22:20:26.748782084Z The above exception was the direct cause of the following exception:
celery-worker_1  | 2019-12-24T22:20:26.748815497Z 
celery-worker_1  | 2019-12-24T22:20:26.748822927Z Traceback (most recent call last):
celery-worker_1  | 2019-12-24T22:20:26.748857302Z   File "/usr/local/lib/python3.6/dist-packages/celery/app/trace.py", line 385, in trace_task
celery-worker_1  | 2019-12-24T22:20:26.748864143Z     R = retval = fun(*args, **kwargs)
celery-worker_1  | 2019-12-24T22:20:26.748870246Z   File "/usr/local/lib/python3.6/dist-packages/celery/app/trace.py", line 648, in __protected_call__
celery-worker_1  | 2019-12-24T22:20:26.748877246Z     return self.run(*args, **kwargs)
celery-worker_1  | 2019-12-24T22:20:26.748883256Z   File "/simoc/celery_worker/tasks.py", line 64, in new_game
celery-worker_1  | 2019-12-24T22:20:26.748889357Z     user = get_user(username)
celery-worker_1  | 2019-12-24T22:20:26.748895153Z   File "/simoc/celery_worker/tasks.py", line 34, in get_user
celery-worker_1  | 2019-12-24T22:20:26.748901226Z     user = User.query.filter_by(username=username).all()
celery-worker_1  | 2019-12-24T22:20:26.748907223Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py", line 3211, in all
celery-worker_1  | 2019-12-24T22:20:26.748913288Z     return list(self)
celery-worker_1  | 2019-12-24T22:20:26.748919112Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py", line 3367, in __iter__
celery-worker_1  | 2019-12-24T22:20:26.748926214Z     return self._execute_and_instances(context)
celery-worker_1  | 2019-12-24T22:20:26.748935519Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py", line 3392, in _execute_and_instances
celery-worker_1  | 2019-12-24T22:20:26.748941951Z     result = conn.execute(querycontext.statement, self._params)
celery-worker_1  | 2019-12-24T22:20:26.748948108Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 982, in execute
celery-worker_1  | 2019-12-24T22:20:26.748954516Z     return meth(self, multiparams, params)
celery-worker_1  | 2019-12-24T22:20:26.748960638Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/sql/elements.py", line 287, in _execute_on_connection
celery-worker_1  | 2019-12-24T22:20:26.748966927Z     return connection._execute_clauseelement(self, multiparams, params)
celery-worker_1  | 2019-12-24T22:20:26.748972937Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1101, in _execute_clauseelement
celery-worker_1  | 2019-12-24T22:20:26.748979273Z     distilled_params,
celery-worker_1  | 2019-12-24T22:20:26.748985201Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1176, in _execute_context
celery-worker_1  | 2019-12-24T22:20:26.748992057Z     e, util.text_type(statement), parameters, None, None
celery-worker_1  | 2019-12-24T22:20:26.748997947Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1476, in _handle_dbapi_exception
celery-worker_1  | 2019-12-24T22:20:26.749004204Z     util.raise_from_cause(sqlalchemy_exception, exc_info)
celery-worker_1  | 2019-12-24T22:20:26.749010798Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/util/compat.py", line 398, in raise_from_cause
celery-worker_1  | 2019-12-24T22:20:26.749016923Z     reraise(type(exception), exception, tb=exc_tb, cause=cause)
celery-worker_1  | 2019-12-24T22:20:26.749022755Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/util/compat.py", line 152, in reraise
celery-worker_1  | 2019-12-24T22:20:26.749029222Z     raise value.with_traceback(tb)
celery-worker_1  | 2019-12-24T22:20:26.749035121Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1173, in _execute_context
celery-worker_1  | 2019-12-24T22:20:26.749047522Z     context = constructor(dialect, self, conn, *args)
celery-worker_1  | 2019-12-24T22:20:26.749053647Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/default.py", line 768, in _init_compiled
celery-worker_1  | 2019-12-24T22:20:26.749059805Z     self.cursor = self.create_cursor()
celery-worker_1  | 2019-12-24T22:20:26.749065649Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/default.py", line 1122, in create_cursor
celery-worker_1  | 2019-12-24T22:20:26.749071850Z     return self._dbapi_connection.cursor()
celery-worker_1  | 2019-12-24T22:20:26.749077871Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/pool/base.py", line 965, in cursor
celery-worker_1  | 2019-12-24T22:20:26.749083995Z     return self.connection.cursor(*args, **kwargs)
celery-worker_1  | 2019-12-24T22:20:26.749089857Z   File "/usr/local/lib/python3.6/dist-packages/mysql/connector/connection_cext.py", line 524, in cursor
celery-worker_1  | 2019-12-24T22:20:26.749096099Z     raise errors.OperationalError("MySQL Connection not available.")
celery-worker_1  | 2019-12-24T22:20:26.749103125Z sqlalchemy.exc.OperationalError: (mysql.connector.errors.OperationalError) MySQL Connection not available.
celery-worker_1  | 2019-12-24T22:20:26.749109382Z [SQL: SELECT user.id AS user_id, user.username AS user_username, user.password_hash AS user_password_hash, user.date_created AS user_date_created, user.date_modified AS user_date_modified 
celery-worker_1  | 2019-12-24T22:20:26.749116105Z FROM user 
celery-worker_1  | 2019-12-24T22:20:26.749121874Z WHERE user.username = %(username_1)s]
celery-worker_1  | 2019-12-24T22:20:26.749127562Z [parameters: [immutabledict({})]]
celery-worker_1  | 2019-12-24T22:20:26.749133371Z (Background on this error at: http://sqlalche.me/e/e3q8)

When I did it again I got first a TypeError: __init__() missing 2 required positional arguments: 'params' and 'orig', and then an InvalidRequestError: Can't reconnect until invalid transaction is rolled back:

flask-app_1      | 2019-12-24T22:20:54.348815918Z Traceback (most recent call last):
flask-app_1      | 2019-12-24T22:20:54.348865173Z   File "src/gevent/greenlet.py", line 766, in gevent._greenlet.Greenlet.run
flask-app_1      | 2019-12-24T22:20:54.348874569Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 82, in run
flask-app_1      | 2019-12-24T22:20:54.348882683Z     self.result_consumer.drain_events(timeout=1)
flask-app_1      | 2019-12-24T22:20:54.348889679Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/redis.py", line 129, in drain_events
flask-app_1      | 2019-12-24T22:20:54.348896715Z     self.on_state_change(self._decode_result(message['data']), message)
flask-app_1      | 2019-12-24T22:20:54.348903785Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/base.py", line 305, in decode_result
flask-app_1      | 2019-12-24T22:20:54.348910685Z     return self.meta_from_decoded(self.decode(payload))
flask-app_1      | 2019-12-24T22:20:54.348920671Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/base.py", line 301, in meta_from_decoded
flask-app_1      | 2019-12-24T22:20:54.348930202Z     meta['result'] = self.exception_to_python(meta['result'])
flask-app_1      | 2019-12-24T22:20:54.348939286Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/base.py", line 281, in exception_to_python
flask-app_1      | 2019-12-24T22:20:54.348948707Z     exc = cls(*exc_msg if isinstance(exc_msg, tuple) else exc_msg)
flask-app_1      | 2019-12-24T22:20:54.348958847Z TypeError: __init__() missing 2 required positional arguments: 'params' and 'orig'
flask-app_1      | 2019-12-24T22:20:54.348965721Z 2019-12-24T22:20:26Z <Greenlet at 0x7f0de0f8ee48: <bound method greenletDrainer.run of <celery.backends.asynchronous.geventDrainer object at 0x7f0de06ba048>>> failed with TypeError
flask-app_1      | 2019-12-24T22:20:54.348973551Z 
flask-app_1      | 2019-12-24T22:20:54.348979823Z [2019-12-24 22:20:54 +0000] [9] [DEBUG] POST /new_game
celery-worker_1  | 2019-12-24T22:20:54.451641333Z [2019-12-24 22:20:54,451: INFO/MainProcess] Received task: celery_worker.tasks.new_game[932f0b38-ea56-4898-acd0-19892db962e2]  
celery-worker_1  | 2019-12-24T22:20:54.454404762Z [2019-12-24 22:20:54,451: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x7ffa30169c80> (args:('celery_worker.tasks.new_game', '932f0b38-ea56-4898-acd0-19892db962e2', {'lang': 'py', 'task': 'celery_worker.tasks.new_game', 'id': '932f0b38-ea56-4898-acd0-19892db962e2', 'shadow': None, 'eta': None, 'expires': None, 'group': None, 'retries': 0, 'timelimit': [None, None], 'root_id': '932f0b38-ea56-4898-acd0-19892db962e2', 'parent_id': None, 'argsrepr': "('eziom', {'agents': {'human_agent': [...], 'solid_waste_aerobic_bioreactor': [...], 'multifiltration_purifier_post_treament': [...], 'oxygen_generation_SFWE': [...], 'urine_recycling_processor_VCD': [...], 'co2_removal_SAWD': [...], 'co2_reduction_sabatier': [...], 'crew_habitat_small': [...], 'solar_pv_array_mars': [...]}, 'storages': {'air_storage': [...], 'water_storage': [...], 'nutrient_storage': [...], 'power_storage': [...], 'food_storage': [...]}, 'termination': [{...}], 'single_agent': 1})", 'kwargsrepr': '{}', 'origin': 'gen9@c85a33855b29', 'reply_to': '749757ed-da6e-341a-ad80-61221d9877e6', 'correlation_id':... kwargs:{})
celery-worker_1  | 2019-12-24T22:20:54.455449226Z [2019-12-24 22:20:54,454: DEBUG/MainProcess] Task accepted: celery_worker.tasks.new_game[932f0b38-ea56-4898-acd0-19892db962e2] pid:18
celery-worker_1  | 2019-12-24T22:20:54.461136466Z [2019-12-24 22:20:54,460: ERROR/ForkPoolWorker-2] Task celery_worker.tasks.new_game[932f0b38-ea56-4898-acd0-19892db962e2] raised unexpected: StatementError("(sqlalchemy.exc.InvalidRequestError) Can't reconnect until invalid transaction is rolled back",)
celery-worker_1  | 2019-12-24T22:20:54.461248957Z Traceback (most recent call last):
celery-worker_1  | 2019-12-24T22:20:54.461263105Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1171, in _execute_context
celery-worker_1  | 2019-12-24T22:20:54.461270125Z     conn = self._revalidate_connection()
celery-worker_1  | 2019-12-24T22:20:54.461281491Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 457, in _revalidate_connection
celery-worker_1  | 2019-12-24T22:20:54.461292566Z     "Can't reconnect until invalid "
celery-worker_1  | 2019-12-24T22:20:54.461303048Z sqlalchemy.exc.InvalidRequestError: Can't reconnect until invalid transaction is rolled back
celery-worker_1  | 2019-12-24T22:20:54.461314479Z 
celery-worker_1  | 2019-12-24T22:20:54.461323409Z The above exception was the direct cause of the following exception:
celery-worker_1  | 2019-12-24T22:20:54.461334862Z 
celery-worker_1  | 2019-12-24T22:20:54.461341619Z Traceback (most recent call last):
celery-worker_1  | 2019-12-24T22:20:54.461352327Z   File "/usr/local/lib/python3.6/dist-packages/celery/app/trace.py", line 385, in trace_task
celery-worker_1  | 2019-12-24T22:20:54.461362310Z     R = retval = fun(*args, **kwargs)
celery-worker_1  | 2019-12-24T22:20:54.461368645Z   File "/usr/local/lib/python3.6/dist-packages/celery/app/trace.py", line 648, in __protected_call__
celery-worker_1  | 2019-12-24T22:20:54.461381238Z     return self.run(*args, **kwargs)
celery-worker_1  | 2019-12-24T22:20:54.461391241Z   File "/simoc/celery_worker/tasks.py", line 64, in new_game
celery-worker_1  | 2019-12-24T22:20:54.461402702Z     user = get_user(username)
celery-worker_1  | 2019-12-24T22:20:54.461413602Z   File "/simoc/celery_worker/tasks.py", line 34, in get_user
celery-worker_1  | 2019-12-24T22:20:54.461424517Z     user = User.query.filter_by(username=username).all()
celery-worker_1  | 2019-12-24T22:20:54.461434487Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py", line 3211, in all
celery-worker_1  | 2019-12-24T22:20:54.461441686Z     return list(self)
celery-worker_1  | 2019-12-24T22:20:54.461452948Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py", line 3367, in __iter__
celery-worker_1  | 2019-12-24T22:20:54.461462291Z     return self._execute_and_instances(context)
celery-worker_1  | 2019-12-24T22:20:54.461468875Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py", line 3392, in _execute_and_instances
celery-worker_1  | 2019-12-24T22:20:54.461482665Z     result = conn.execute(querycontext.statement, self._params)
celery-worker_1  | 2019-12-24T22:20:54.461490135Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 982, in execute
celery-worker_1  | 2019-12-24T22:20:54.461501492Z     return meth(self, multiparams, params)
celery-worker_1  | 2019-12-24T22:20:54.461511482Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/sql/elements.py", line 287, in _execute_on_connection
celery-worker_1  | 2019-12-24T22:20:54.461522622Z     return connection._execute_clauseelement(self, multiparams, params)
celery-worker_1  | 2019-12-24T22:20:54.461535886Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1101, in _execute_clauseelement
celery-worker_1  | 2019-12-24T22:20:54.461543447Z     distilled_params,
celery-worker_1  | 2019-12-24T22:20:54.461558655Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1176, in _execute_context
celery-worker_1  | 2019-12-24T22:20:54.461565658Z     e, util.text_type(statement), parameters, None, None
celery-worker_1  | 2019-12-24T22:20:54.461578357Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1476, in _handle_dbapi_exception
celery-worker_1  | 2019-12-24T22:20:54.461588049Z     util.raise_from_cause(sqlalchemy_exception, exc_info)
celery-worker_1  | 2019-12-24T22:20:54.461594968Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/util/compat.py", line 398, in raise_from_cause
celery-worker_1  | 2019-12-24T22:20:54.461604822Z     reraise(type(exception), exception, tb=exc_tb, cause=cause)
celery-worker_1  | 2019-12-24T22:20:54.461611559Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/util/compat.py", line 152, in reraise
celery-worker_1  | 2019-12-24T22:20:54.461618473Z     raise value.with_traceback(tb)
celery-worker_1  | 2019-12-24T22:20:54.461624651Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1171, in _execute_context
celery-worker_1  | 2019-12-24T22:20:54.461630716Z     conn = self._revalidate_connection()
celery-worker_1  | 2019-12-24T22:20:54.461636819Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 457, in _revalidate_connection
celery-worker_1  | 2019-12-24T22:20:54.461645012Z     "Can't reconnect until invalid "
celery-worker_1  | 2019-12-24T22:20:54.461651466Z sqlalchemy.exc.StatementError: (sqlalchemy.exc.InvalidRequestError) Can't reconnect until invalid transaction is rolled back
celery-worker_1  | 2019-12-24T22:20:54.461658260Z [SQL: SELECT user.id AS user_id, user.username AS user_username, user.password_hash AS user_password_hash, user.date_created AS user_date_created, user.date_modified AS user_date_modified 
celery-worker_1  | 2019-12-24T22:20:54.461665643Z FROM user 
celery-worker_1  | 2019-12-24T22:20:54.461674985Z WHERE user.username = %(username_1)s]
celery-worker_1  | 2019-12-24T22:20:54.461683848Z [parameters: [immutabledict({})]]
flask-app_1      | 2019-12-24T22:21:26.408251611Z Traceback (most recent call last):
flask-app_1      | 2019-12-24T22:21:26.408325693Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 255, in _wait_for_pending
flask-app_1      | 2019-12-24T22:21:26.408335547Z     on_interval=on_interval):
flask-app_1      | 2019-12-24T22:21:26.408344096Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 54, in drain_events_until
flask-app_1      | 2019-12-24T22:21:26.408353328Z     raise socket.timeout()
flask-app_1      | 2019-12-24T22:21:26.408360155Z socket.timeout
flask-app_1      | 2019-12-24T22:21:26.408367372Z 
flask-app_1      | 2019-12-24T22:21:26.408374685Z During handling of the above exception, another exception occurred:
flask-app_1      | 2019-12-24T22:21:26.408382822Z 
flask-app_1      | 2019-12-24T22:21:26.408389821Z Traceback (most recent call last):
flask-app_1      | 2019-12-24T22:21:26.408397729Z   File "/usr/local/lib/python3.6/dist-packages/flask/app.py", line 1949, in full_dispatch_request
flask-app_1      | 2019-12-24T22:21:26.408405915Z     rv = self.dispatch_request()
flask-app_1      | 2019-12-24T22:21:26.408413186Z   File "/usr/local/lib/python3.6/dist-packages/flask/app.py", line 1935, in dispatch_request
flask-app_1      | 2019-12-24T22:21:26.408449008Z     return self.view_functions[rule.endpoint](**req.view_args)
flask-app_1      | 2019-12-24T22:21:26.408456571Z   File "/usr/local/lib/python3.6/dist-packages/flask_login/utils.py", line 261, in decorated_view
flask-app_1      | 2019-12-24T22:21:26.408463728Z     return func(*args, **kwargs)
flask-app_1      | 2019-12-24T22:21:26.408470799Z   File "/simoc/simoc_server/views.py", line 196, in new_game
flask-app_1      | 2019-12-24T22:21:26.408477679Z     result = tasks.new_game.delay(get_standard_user_obj().username, game_config).get(timeout=60)
flask-app_1      | 2019-12-24T22:21:26.408487712Z   File "/usr/local/lib/python3.6/dist-packages/celery/result.py", line 226, in get
flask-app_1      | 2019-12-24T22:21:26.408494320Z     on_message=on_message,
flask-app_1      | 2019-12-24T22:21:26.408501596Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 188, in wait_for_pending
flask-app_1      | 2019-12-24T22:21:26.408508632Z     for _ in self._wait_for_pending(result, **kwargs):
flask-app_1      | 2019-12-24T22:21:26.408515871Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 259, in _wait_for_pending
flask-app_1      | 2019-12-24T22:21:26.408522955Z     raise TimeoutError('The operation timed out.')
flask-app_1      | 2019-12-24T22:21:26.408529741Z celery.exceptions.TimeoutError: The operation timed out.
flask-app_1      | 2019-12-24T22:21:26.408536463Z [2019-12-24 22:21:26 +0000] [9] [ERROR] ERROR: handling exception The operation timed out.
flask-app_1      | 2019-12-24T22:21:26.421127656Z [2019-12-24 22:21:26 +0000] [9] [DEBUG] Closing connection. 
flask-app_1      | 2019-12-24T22:21:54.457629898Z Traceback (most recent call last):
flask-app_1      | 2019-12-24T22:21:54.457700262Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 255, in _wait_for_pending
flask-app_1      | 2019-12-24T22:21:54.457710245Z     on_interval=on_interval):
flask-app_1      | 2019-12-24T22:21:54.457717970Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 54, in drain_events_until
flask-app_1      | 2019-12-24T22:21:54.457726384Z     raise socket.timeout()
flask-app_1      | 2019-12-24T22:21:54.457733231Z socket.timeout
flask-app_1      | 2019-12-24T22:21:54.457739869Z 
flask-app_1      | 2019-12-24T22:21:54.457745642Z During handling of the above exception, another exception occurred:
flask-app_1      | 2019-12-24T22:21:54.457751452Z 
flask-app_1      | 2019-12-24T22:21:54.457756527Z Traceback (most recent call last):
flask-app_1      | 2019-12-24T22:21:54.457761751Z   File "/usr/local/lib/python3.6/dist-packages/flask/app.py", line 1949, in full_dispatch_request
flask-app_1      | 2019-12-24T22:21:54.457767511Z     rv = self.dispatch_request()
flask-app_1      | 2019-12-24T22:21:54.457772740Z   File "/usr/local/lib/python3.6/dist-packages/flask/app.py", line 1935, in dispatch_request
flask-app_1      | 2019-12-24T22:21:54.457778194Z     return self.view_functions[rule.endpoint](**req.view_args)
flask-app_1      | 2019-12-24T22:21:54.457783482Z   File "/usr/local/lib/python3.6/dist-packages/flask_login/utils.py", line 261, in decorated_view
flask-app_1      | 2019-12-24T22:21:54.457789064Z     return func(*args, **kwargs)
flask-app_1      | 2019-12-24T22:21:54.457794193Z   File "/simoc/simoc_server/views.py", line 196, in new_game
flask-app_1      | 2019-12-24T22:21:54.457829194Z     result = tasks.new_game.delay(get_standard_user_obj().username, game_config).get(timeout=60)
flask-app_1      | 2019-12-24T22:21:54.457835166Z   File "/usr/local/lib/python3.6/dist-packages/celery/result.py", line 226, in get
flask-app_1      | 2019-12-24T22:21:54.457840717Z     on_message=on_message,
flask-app_1      | 2019-12-24T22:21:54.457845823Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 188, in wait_for_pending
flask-app_1      | 2019-12-24T22:21:54.457851309Z     for _ in self._wait_for_pending(result, **kwargs):
flask-app_1      | 2019-12-24T22:21:54.457856430Z   File "/usr/local/lib/python3.6/dist-packages/celery/backends/asynchronous.py", line 259, in _wait_for_pending
flask-app_1      | 2019-12-24T22:21:54.457861959Z     raise TimeoutError('The operation timed out.')
flask-app_1      | 2019-12-24T22:21:54.457867138Z celery.exceptions.TimeoutError: The operation timed out.
flask-app_1      | 2019-12-24T22:21:54.457872428Z [2019-12-24 22:21:54 +0000] [9] [ERROR] ERROR: handling exception The operation timed out.
flask-app_1      | 2019-12-24T22:21:54.462508640Z [2019-12-24 22:21:54 +0000] [9] [DEBUG] Closing connection.
ezio-melotti commented 4 years ago

I got this again with the websockets. I ran a sim, left the browser opened on the dashboard for ~10 hours, came back to it and edited some file (that caused the dashboard to reload and re-request the steps) and got the error:

celery-worker_2  | 2020-01-08T15:41:52.061826897Z [2020-01-08 15:41:52,060: INFO/ForkPoolWorker-2] Cleaning up save game for user with id 1
flask-app_1      | 2020-01-09T01:23:47.717703001Z [2020-01-09 01:23:47 +0000] [9] [DEBUG] POST /get_step_to
flask-app_1      | 2020-01-09T01:23:47.794902574Z [2020-01-09 01:23:47 +0000] [9] [DEBUG] POST /kill_game
flask-app_1      | 2020-01-09T01:23:47.833790293Z [2020-01-09 01:23:47 +0000] [9] [INFO] STATUS: Steps requested.
flask-app_1      | 2020-01-09T01:23:47.836561224Z [2020-01-09 01:23:47 +0000] [9] [DEBUG] Closing connection. 
flask-app_1      | 2020-01-09T01:23:47.837038365Z [2020-01-09 01:23:47 +0000] [9] [INFO] STATUS: Game 5912925101529154487 killed.
celery-worker_2  | 2020-01-09T01:23:47.833984305Z [2020-01-09 01:23:47,833: INFO/MainProcess] Received task: celery_worker.tasks.get_step_to[51d42bb6-b4c4-46d4-9ff4-c240f1bee08e]  
celery-worker_2  | 2020-01-09T01:23:47.834009894Z [2020-01-09 01:23:47,833: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x7fa036ed0c80> (args:('celery_worker.tasks.get_step_to', '51d42bb6-b4c4-46d4-9ff4-c240f1bee08e', {'lang': 'py', 'task': 'celery_worker.tasks.get_step_to', 'id': '51d42bb6-b4c4-46d4-9ff4-c240f1bee08e', 'shadow': None, 'eta': None, 'expires': None, 'group': None, 'retries': 0, 'timelimit': [None, None], 'root_id': '51d42bb6-b4c4-46d4-9ff4-c240f1bee08e', 'parent_id': None, 'argsrepr': "['eziom', 240]", 'kwargsrepr': '{}', 'origin': 'gen9@c85a33855b29', 'reply_to': '6547237e-245c-3952-bf82-72b03e20f16a', 'correlation_id': '51d42bb6-b4c4-46d4-9ff4-c240f1bee08e', 'delivery_info': {'exchange': '', 'routing_key': 'worker@d4c7e4488c61.dq2', 'priority': 0, 'redelivered': None}}, b'[["eziom", 240], {}, {"callbacks": null, "errbacks": null, "chain": null, "chord": null}]', 'application/json', 'utf-8') kwargs:{})
celery-worker_2  | 2020-01-09T01:23:47.837753623Z [2020-01-09 01:23:47,837: DEBUG/MainProcess] pidbox received method revoke(task_id='e04a0889-2f14-428d-ab44-3dc8dd46d2a0', terminate=True, signal='SIGKILL') [reply_to:None ticket:None]
celery-worker_1  | 2020-01-09T01:23:47.835386183Z [2020-01-09 01:23:47,835: DEBUG/MainProcess] pidbox received method revoke(task_id='e04a0889-2f14-428d-ab44-3dc8dd46d2a0', terminate=True, signal='SIGKILL') [reply_to:None ticket:None]
flask-app_1      | 2020-01-09T01:23:47.839204036Z [2020-01-09 01:23:47 +0000] [9] [DEBUG] Closing connection. 
celery-worker_2  | 2020-01-09T01:23:47.838654627Z [2020-01-09 01:23:47,838: DEBUG/MainProcess] Task accepted: celery_worker.tasks.get_step_to[51d42bb6-b4c4-46d4-9ff4-c240f1bee08e] pid:18
celery-worker_2  | 2020-01-09T01:23:47.913084510Z [2020-01-09 01:23:47,912: ERROR/ForkPoolWorker-2] Task celery_worker.tasks.get_step_to[51d42bb6-b4c4-46d4-9ff4-c240f1bee08e] raised unexpected: OperationalError('(mysql.connector.errors.OperationalError) MySQL Connection not available.',)
celery-worker_2  | 2020-01-09T01:23:47.913125097Z Traceback (most recent call last):
celery-worker_2  | 2020-01-09T01:23:47.913132807Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1173, in _execute_context
celery-worker_2  | 2020-01-09T01:23:47.913139701Z     context = constructor(dialect, self, conn, *args)
celery-worker_2  | 2020-01-09T01:23:47.913146409Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/default.py", line 768, in _init_compiled
celery-worker_2  | 2020-01-09T01:23:47.913152897Z     self.cursor = self.create_cursor()
celery-worker_2  | 2020-01-09T01:23:47.913159526Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/default.py", line 1122, in create_cursor
celery-worker_2  | 2020-01-09T01:23:47.913166897Z     return self._dbapi_connection.cursor()
celery-worker_2  | 2020-01-09T01:23:47.913176977Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/pool/base.py", line 965, in cursor
celery-worker_2  | 2020-01-09T01:23:47.913183995Z     return self.connection.cursor(*args, **kwargs)
celery-worker_2  | 2020-01-09T01:23:47.913190234Z   File "/usr/local/lib/python3.6/dist-packages/mysql/connector/connection_cext.py", line 524, in cursor
celery-worker_2  | 2020-01-09T01:23:47.913211911Z     raise errors.OperationalError("MySQL Connection not available.")
celery-worker_2  | 2020-01-09T01:23:47.913217959Z mysql.connector.errors.OperationalError: MySQL Connection not available.
celery-worker_2  | 2020-01-09T01:23:47.913223600Z 
celery-worker_2  | 2020-01-09T01:23:47.913229526Z The above exception was the direct cause of the following exception:
celery-worker_2  | 2020-01-09T01:23:47.913236499Z 
celery-worker_2  | 2020-01-09T01:23:47.913242169Z Traceback (most recent call last):
celery-worker_2  | 2020-01-09T01:23:47.913247923Z   File "/usr/local/lib/python3.6/dist-packages/celery/app/trace.py", line 385, in trace_task
celery-worker_2  | 2020-01-09T01:23:47.913255092Z     R = retval = fun(*args, **kwargs)
celery-worker_2  | 2020-01-09T01:23:47.913261815Z   File "/usr/local/lib/python3.6/dist-packages/celery/app/trace.py", line 648, in __protected_call__
celery-worker_2  | 2020-01-09T01:23:47.913267820Z     return self.run(*args, **kwargs)
celery-worker_2  | 2020-01-09T01:23:47.913273310Z   File "/simoc/celery_worker/tasks.py", line 74, in get_step_to
celery-worker_2  | 2020-01-09T01:23:47.913279077Z     user = get_user(username)
celery-worker_2  | 2020-01-09T01:23:47.913285124Z   File "/simoc/celery_worker/tasks.py", line 34, in get_user
celery-worker_2  | 2020-01-09T01:23:47.913290220Z     user = User.query.filter_by(username=username).all()
celery-worker_2  | 2020-01-09T01:23:47.913295640Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py", line 3211, in all
celery-worker_2  | 2020-01-09T01:23:47.913301106Z     return list(self)
celery-worker_2  | 2020-01-09T01:23:47.913307718Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py", line 3367, in __iter__
celery-worker_2  | 2020-01-09T01:23:47.913313792Z     return self._execute_and_instances(context)
celery-worker_2  | 2020-01-09T01:23:47.913321538Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/orm/query.py", line 3392, in _execute_and_instances
celery-worker_2  | 2020-01-09T01:23:47.913327771Z     result = conn.execute(querycontext.statement, self._params)
celery-worker_2  | 2020-01-09T01:23:47.913333079Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 982, in execute
celery-worker_2  | 2020-01-09T01:23:47.913338274Z     return meth(self, multiparams, params)
celery-worker_2  | 2020-01-09T01:23:47.913343695Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/sql/elements.py", line 287, in _execute_on_connection
celery-worker_2  | 2020-01-09T01:23:47.913349976Z     return connection._execute_clauseelement(self, multiparams, params)
celery-worker_2  | 2020-01-09T01:23:47.913355458Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1101, in _execute_clauseelement
celery-worker_2  | 2020-01-09T01:23:47.913360891Z     distilled_params,
celery-worker_2  | 2020-01-09T01:23:47.913366124Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1176, in _execute_context
celery-worker_2  | 2020-01-09T01:23:47.913371820Z     e, util.text_type(statement), parameters, None, None
celery-worker_2  | 2020-01-09T01:23:47.913377283Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1476, in _handle_dbapi_exception
celery-worker_2  | 2020-01-09T01:23:47.913382919Z     util.raise_from_cause(sqlalchemy_exception, exc_info)
celery-worker_2  | 2020-01-09T01:23:47.913393191Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/util/compat.py", line 398, in raise_from_cause
celery-worker_2  | 2020-01-09T01:23:47.913399131Z     reraise(type(exception), exception, tb=exc_tb, cause=cause)
celery-worker_2  | 2020-01-09T01:23:47.913404904Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/util/compat.py", line 152, in reraise
celery-worker_2  | 2020-01-09T01:23:47.913410956Z     raise value.with_traceback(tb)
celery-worker_2  | 2020-01-09T01:23:47.913416856Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/base.py", line 1173, in _execute_context
celery-worker_2  | 2020-01-09T01:23:47.913423808Z     context = constructor(dialect, self, conn, *args)
celery-worker_2  | 2020-01-09T01:23:47.913429488Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/default.py", line 768, in _init_compiled
celery-worker_2  | 2020-01-09T01:23:47.913435148Z     self.cursor = self.create_cursor()
celery-worker_2  | 2020-01-09T01:23:47.913440464Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/engine/default.py", line 1122, in create_cursor
celery-worker_2  | 2020-01-09T01:23:47.913446252Z     return self._dbapi_connection.cursor()
celery-worker_2  | 2020-01-09T01:23:47.913451937Z   File "/usr/local/lib/python3.6/dist-packages/sqlalchemy/pool/base.py", line 965, in cursor
celery-worker_2  | 2020-01-09T01:23:47.913457537Z     return self.connection.cursor(*args, **kwargs)
celery-worker_2  | 2020-01-09T01:23:47.913462953Z   File "/usr/local/lib/python3.6/dist-packages/mysql/connector/connection_cext.py", line 524, in cursor
celery-worker_2  | 2020-01-09T01:23:47.913468836Z     raise errors.OperationalError("MySQL Connection not available.")
celery-worker_2  | 2020-01-09T01:23:47.913474765Z sqlalchemy.exc.OperationalError: (mysql.connector.errors.OperationalError) MySQL Connection not available.
celery-worker_2  | 2020-01-09T01:23:47.913480448Z [SQL: SELECT user.id AS user_id, user.username AS user_username, user.password_hash AS user_password_hash, user.date_created AS user_date_created, user.date_modified AS user_date_modified 
celery-worker_2  | 2020-01-09T01:23:47.913486716Z FROM user 
celery-worker_2  | 2020-01-09T01:23:47.913492025Z WHERE user.username = %(username_1)s]
celery-worker_2  | 2020-01-09T01:23:47.913498485Z [parameters: [immutabledict({})]]
celery-worker_2  | 2020-01-09T01:23:47.913503706Z (Background on this error at: http://sqlalche.me/e/e3q8)
flask-app_1      | 2020-01-09T01:23:48.153331853Z [2020-01-09 01:23:48 +0000] [9] [DEBUG] GET /socket.io/