search

geoadmin / mf-chsdi3

api3.geo.admin.ch source code
https://api3.geo.admin.ch
Other
33 stars 15 forks source link

Interface errors in mf-chsdi3 #1603

Closed cedricmoullet closed 9 years ago

cedricmoullet commented 9 years ago

[Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] mod_wsgi (pid=30722): Exception occurred processing WSGI script '/var/www/vhosts/mf-chsdi3/private/chsdi/buildout/parts/modwsgi/wsgi'. [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] Traceback (most recent call last): [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] File "/var/www/vhosts/mf-chsdi3/private/chsdi/buildout/eggs/pyramid-1.5.2-py2.7.egg/pyramid/router.py", line 242, in call [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] response = self.invoke_subrequest(request, use_tweens=True) [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] File "/var/www/vhosts/mf-chsdi3/private/chsdi/buildout/eggs/pyramid-1.5.2-py2.7.egg/pyramid/router.py", line 217, in invoke_subrequest [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] response = handle_request(request) [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] File "/var/www/vhosts/mf-chsdi3/private/chsdi/buildout/eggs/pyramid-1.5.2-py2.7.egg/pyramid/tweens.py", line 21, in excview_tween [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] response = handler(request) [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] File "/var/www/vhosts/mf-chsdi3/private/chsdi/buildout/eggs/pyramid_tm-0.12-py2.7.egg/pyramid_tm/init.py", line 99, in tm_tween [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] reraise(_exc_info) [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] File "/var/www/vhosts/mf-chsdi3/private/chsdi/buildout/eggs/pyramid_tm-0.12-py2.7.egg/pyramid_tm/init.py", line 80, in tm_tween [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] response = handler(request) [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] File "/var/www/vhosts/mf-chsdi3/private/chsdi/buildout/eggs/pyramid-1.5.2-py2.7.egg/pyramid/router.py", line 163, in handle_request [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] response = view_callable(context, request) [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] File "/var/www/vhosts/mf-chsdi3/private/chsdi/buildout/eggs/pyramid-1.5.2-py2.7.egg/pyramid/config/views.py", line 218, in wrapper [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] response = view(context, request) [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] File "/var/www/vhosts/mf-chsdi3/private/chsdi/buildout/eggs/pyramid-1.5.2-py2.7.egg/pyramid/config/views.py", line 385, in viewresult_to_response [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] result = view(context, request) [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] File "/var/www/vhosts/mf-chsdi3/private/chsdi/buildout/eggs/pyramid-1.5.2-py2.7.egg/pyramid/config/views.py", line 472, in _class_requestonly_view [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] inst = view(request) [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] File "/var/www/vhosts/mf-chsdi3/private/chsdi/chsdi/views/wmtscapabilities.py", line 48, in init [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] self.hasMap(request.db, self.mapName) [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] File "/var/www/vhosts/mf-chsdi3/private/chsdi/chsdi/lib/validation/init.py", line 11, in hasMap [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] availableMaps = [q[0] for q in db.query(Topics.id)] [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] File "/var/www/vhosts/mf-chsdi3/private/chsdi/buildout/eggs/SQLAlchemy-0.9.8-py2.7-linux-x86_64.egg/sqlalchemy/orm/query.py", line 2438, in iter [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] return self._execute_and_instances(context) [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] File "/var/www/vhosts/mf-chsdi3/private/chsdi/buildout/eggs/SQLAlchemy-0.9.8-py2.7-linux-x86_64.egg/sqlalchemy/orm/query.py", line 2453, in _execute_and_instances [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] result = conn.execute(querycontext.statement, self._params) [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] File "/var/www/vhosts/mf-chsdi3/private/chsdi/buildout/eggs/SQLAlchemy-0.9.8-py2.7-linux-x86_64.egg/sqlalchemy/engine/base.py", line 729, in execute [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] return meth(self, multiparams, params) [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] File "/var/www/vhosts/mf-chsdi3/private/chsdi/buildout/eggs/SQLAlchemy-0.9.8-py2.7-linux-x86_64.egg/sqlalchemy/sql/elements.py", line 322, in _execute_on_connection [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] return connection._execute_clauseelement(self, multiparams, params) [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] File "/var/www/vhosts/mf-chsdi3/private/chsdi/buildout/eggs/SQLAlchemy-0.9.8-py2.7-linux-x86_64.egg/sqlalchemy/engine/base.py", line 826, in _execute_clauseelement [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] compiled_sql, distilled_params [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] File "/var/www/vhosts/mf-chsdi3/private/chsdi/buildout/eggs/SQLAlchemy-0.9.8-py2.7-linux-x86_64.egg/sqlalchemy/engine/base.py", line 893, in _execute_context [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] None, None) [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] File "/var/www/vhosts/mf-chsdi3/private/chsdi/buildout/eggs/SQLAlchemy-0.9.8-py2.7-linux-x86_64.egg/sqlalchemy/engine/base.py", line 1159, in _handle_dbapi_exception [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] exc_info [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] File "/var/www/vhosts/mf-chsdi3/private/chsdi/buildout/eggs/SQLAlchemy-0.9.8-py2.7-linux-x86_64.egg/sqlalchemy/util/compat.py", line 199, in raise_from_cause [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] reraise(type(exception), exception, tb=exc_tb) [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] File "/var/www/vhosts/mf-chsdi3/private/chsdi/buildout/eggs/SQLAlchemy-0.9.8-py2.7-linux-x86_64.egg/sqlalchemy/engine/base.py", line 889, in _execute_context [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] context = constructor(dialect, self, conn, *args) [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] File "/var/www/vhosts/mf-chsdi3/private/chsdi/buildout/eggs/SQLAlchemy-0.9.8-py2.7-linux-x86_64.egg/sqlalchemy/engine/default.py", line 555, in _init_compiled [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] self.cursor = self.create_cursor() [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] File "/var/www/vhosts/mf-chsdi3/private/chsdi/buildout/eggs/SQLAlchemy-0.9.8-py2.7-linux-x86_64.egg/sqlalchemy/dialects/postgresql/psycopg2.py", line 368, in create_cursor [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] return self._dbapi_connection.cursor() [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] File "/var/www/vhosts/mf-chsdi3/private/chsdi/buildout/eggs/SQLAlchemy-0.9.8-py2.7-linux-x86_64.egg/sqlalchemy/pool.py", line 769, in cursor [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] return self.connection.cursor(_args, **kwargs) [Thu Aug 13 08:31:30 2015] [error] [client 10.220.6.61] InterfaceError: (InterfaceError) connection already closed u'SELECT re3.topics.topic AS re3_topics_topic \nFROM re3.topics' [immutabledict({})]

gjn commented 9 years ago

This article points to a potential crash of the db.

In any case, it looks like the connection to the db was cut for some reason. Might be network, db or other reasons. Would certainly help to analyse postgres logs during those times. If have found other occurences at other times (this is from one server only)

I repeated some of the requests that gave this error (they are visible in the access.log with a 500 error around the same time) and couldn't reproduce. I therefore assume that not a specific request is triggering this error.

@ltclm What do db logs tell?

cedricmoullet commented 9 years ago

@ltclm ?

ltclm commented 9 years ago

On database side we could not find anything suspicious, related to these connection problems. We can observe only the following errors in postgres logs:

2015-08-24 17:43:18.404 CEST www-data bod_prod LOG:  could not receive data from client: Connection reset by peer

These errors seem to be caused by collectd monitoring connections which are not closed properly [1].

Actually it is hard to say where the source of this error is. It could come somewhere from our db access stack (wsgi,sqlalchemy,etc.). @procrastinatio opened a ticket at c2c (rt193292).

[1] https://devcenter.heroku.com/articles/postgres-logs-errors#log-could-not-receive-data-from-client-connection-reset-by-peer