#1 by jkemp
I just ran into an issue that I could not resolve on my own.
I deployed an otreezip to Heroku. This ran fine for several days, until today, when all I could access was the Heroku Application Error page when trying to go to my app. The logs indicate that the connection to the PostgreSQL database was closed. I did not issue a manual administrator command to terminate the connection to the PostgreSQL database.
I used Heroku Dataclips to save the most important data and created a backup of the database to be able to restore at a later time. I tried restarting the dynos and checked that the credentials for the database were still correct. I was only able to bring the app back to life when I chose another database tier in the Otreehub interface and deployed the same otreezip again.
This may possibly be a bug?
By the way, is there another way to simply restart the Heroku server and database?
Here are the server logs:
Jun 08 03:18:32 ude-empol app/heroku-redis source=REDIS addon=redis-spherical-03746 sample#active-connections=1 sample#load-avg-1m=0.225 sample#load-avg-5m=0.27 sample#load-avg-15m=0.225 sample#read-iops=0 sample#write-iops=0 sample#memory-total=15618680kB sample#memory-free=12368204kB sample#memory-cached=1967368kB sample#memory-redis=334176bytes sample#hit-rate=1 sample#evicted-keys=0
Jun 08 03:19:45 ude-empol app/web.1 Traceback (most recent call last):
Jun 08 03:19:45 ude-empol app/web.1 File "/app/.heroku/python/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 1276, in _execute_context
Jun 08 03:19:45 ude-empol app/web.1 self.dialect.do_execute(
Jun 08 03:19:45 ude-empol app/web.1 File "/app/.heroku/python/lib/python3.9/site-packages/sqlalchemy/engine/default.py", line 609, in do_execute
Jun 08 03:19:45 ude-empol app/web.1 cursor.execute(statement, parameters)
Jun 08 03:19:45 ude-empol app/web.1 psycopg2.OperationalError: terminating connection due to administrator command
Jun 08 03:19:45 ude-empol app/web.1 SSL connection has been closed unexpectedly
Jun 08 03:19:45 ude-empol app/web.1 The above exception was the direct cause of the following exception:
Jun 08 03:19:45 ude-empol app/web.1 Traceback (most recent call last):
Jun 08 03:19:45 ude-empol app/web.1 File "/app/.heroku/python/bin/otree", line 8, in <module>
Jun 08 03:19:45 ude-empol app/web.1 sys.exit(execute_from_command_line())
Jun 08 03:19:45 ude-empol app/web.1 File "/app/.heroku/python/lib/python3.9/site-packages/otree/main.py", line 113, in execute_from_command_line
Jun 08 03:19:45 ude-empol app/web.1 call_command(cmd, *argv[2:])
Jun 08 03:19:45 ude-empol app/web.1 File "/app/.heroku/python/lib/python3.9/site-packages/otree/cli/base.py", line 32, in call_command
Jun 08 03:19:45 ude-empol app/web.1 module.Command().outer_handle(args)
Jun 08 03:19:45 ude-empol app/web.1 File "/app/.heroku/python/lib/python3.9/site-packages/otree/cli/base.py", line 10, in outer_handle
Jun 08 03:19:45 ude-empol app/web.1 return self.handle(**vars(options))
Jun 08 03:19:45 ude-empol app/web.1 File "/app/.heroku/python/lib/python3.9/site-packages/otree/cli/timeoutsubprocess.py", line 12, in handle
Jun 08 03:19:45 ude-empol app/web.1 Worker(port).listen()
Jun 08 03:19:45 ude-empol app/web.1 File "/app/.heroku/python/lib/python3.9/site-packages/otree/tasks.py", line 53, in listen
Jun 08 03:19:45 ude-empol app/web.1 for task in TaskQueueMessage.objects_filter(
Jun 08 03:19:45 ude-empol app/web.1 File "/app/.heroku/python/lib/python3.9/site-packages/sqlalchemy/orm/query.py", line 3535, in __iter__
Jun 08 03:19:45 ude-empol app/web.1 return self._execute_and_instances(context)
Jun 08 03:19:45 ude-empol app/web.1 File "/app/.heroku/python/lib/python3.9/site-packages/sqlalchemy/orm/query.py", line 3560, in _execute_and_instances
Jun 08 03:19:45 ude-empol app/web.1 result = conn.execute(querycontext.statement, self._params)
Jun 08 03:19:45 ude-empol app/web.1 File "/app/.heroku/python/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 1011, in execute
Jun 08 03:19:45 ude-empol app/web.1 return meth(self, multiparams, params)
Jun 08 03:19:45 ude-empol app/web.1 File "/app/.heroku/python/lib/python3.9/site-packages/sqlalchemy/sql/elements.py", line 298, in _execute_on_connection
Jun 08 03:19:45 ude-empol app/web.1 return connection._execute_clauseelement(self, multiparams, params)
Jun 08 03:19:45 ude-empol app/web.1 File "/app/.heroku/python/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 1124, in _execute_clauseelement
Jun 08 03:19:45 ude-empol app/web.1 ret = self._execute_context(
Jun 08 03:19:45 ude-empol app/web.1 File "/app/.heroku/python/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 1316, in _execute_context
Jun 08 03:19:45 ude-empol app/web.1 self._handle_dbapi_exception(
Jun 08 03:19:45 ude-empol app/web.1 File "/app/.heroku/python/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 1510, in _handle_dbapi_exception
Jun 08 03:19:45 ude-empol app/web.1 util.raise_(
Jun 08 03:19:45 ude-empol app/web.1 File "/app/.heroku/python/lib/python3.9/site-packages/sqlalchemy/util/compat.py", line 182, in raise_
Jun 08 03:19:45 ude-empol app/web.1 raise exception
Jun 08 03:19:45 ude-empol app/web.1 File "/app/.heroku/python/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 1276, in _execute_context
Jun 08 03:19:45 ude-empol app/web.1 self.dialect.do_execute(
Jun 08 03:19:45 ude-empol app/web.1 File "/app/.heroku/python/lib/python3.9/site-packages/sqlalchemy/engine/default.py", line 609, in do_execute
Jun 08 03:19:45 ude-empol app/web.1 cursor.execute(statement, parameters)
Jun 08 03:19:45 ude-empol app/web.1 sqlalchemy.exc.OperationalError: (psycopg2.OperationalError) terminating connection due to administrator command
Jun 08 03:19:45 ude-empol app/web.1 SSL connection has been closed unexpectedly
Jun 08 03:19:45 ude-empol app/web.1 [SQL: SELECT otree_taskqueuemessage.id AS otree_taskqueuemessage_id, otree_taskqueuemessage.method AS otree_taskqueuemessage_method, otree_taskqueuemessage.kwargs_json AS otree_taskqueuemessage_kwargs_json, otree_taskqueuemessage.epoch_time AS otree_taskqueuemessage_epoch_time
Jun 08 03:19:45 ude-empol app/web.1 FROM otree_taskqueuemessage
Jun 08 03:19:45 ude-empol app/web.1 WHERE otree_taskqueuemessage.epoch_time <= %(epoch_time_1)s ORDER BY otree_taskqueuemessage.epoch_time]
Jun 08 03:19:45 ude-empol app/web.1 [parameters: {'epoch_time_1': 1654683583.8356202}]
Jun 08 03:19:45 ude-empol app/web.1 (Background on this error at: http://sqlalche.me/e/13/e3q8)
Jun 08 03:20:38 ude-empol app/heroku-redis source=REDIS addon=redis-spherical-03746 sample#active-connections=1 sample#load-avg-1m=0.115 sample#load-avg-5m=0.235 sample#load-avg-15m=0.215 sample#read-iops=0 sample#write-iops=0 sample#memory-total=15618680kB sample#memory-free=12368464kB sample#memory-cached=1967368kB sample#memory-redis=334176bytes sample#hit-rate=1 sample#evicted-keys=0
#2 by Chris_oTree
I'm not sure. I have seen that error before, but it was a transient thing that may be due to things like the server re-starting. You got this error in your logs repeatedly, every time you loaded the page? (I ask to check if the error was actually something else).
#3 by jkemp
I have to admit that this was likely caused by a Heroku Server maintenance, that only completed shortly before I encountered the error. Therefore, I don't think there was an issue with oTree.