I don't know if the following traceback, from my Pylons project, will shed light on this. But I have fixed the error that I'm about to mention, and it was not what it appeared, which makes me wonder if SqlAlchemy has a bug in its error reporting (or on the other hand maybe there's just something I don't understand in the process).
I was chasing down an error that said "Connection Already Closed" and having a tough time figuring it out. I read the FAQ on the subject and several of Mike's replies to people's posts. All of this existing material spoke about leaving a connection open too long, and other related issues with connection pooling and recycling. I was pretty sure that wasn't my problem. I even rebooted the machine that my project lives on, and the same error was happening on first access to the database after rebooting. Not merely restarting the paster webserver. Oddly, the error only happened on a call to session.flush() right after update() was called on an object. In other parts of my little CRUD app, I was able to create new values and save them just fine. It was only in the attempt to update an existing row that the error was happening. Finally after enough hair loss, I stopped poring over the tracebacks shown in the Pylons error response, and went directly to the paster debug logs. Hmm! What was actually happening was that a foreign key relationship was being violated (or i guess you could say just not satisfied) by the value I was trying to save (update). The foreign key error message went to the log where I wasn't looking, because I typically only look there if the in-browser Pylons error response is absent or otherwise hung up. Meanwhile for some reason the ultimate result was showing up as Connection Already Closed. So maybe the underlying Foreign Key error resulted in the connection closing, and something in the way SA handled that led to the Connection error, and I only saw the latter because I hadn't thought to look for an error beneath the error. Here's the trace from the Pylons error handler in the browser: URL: http://127.0.0.1:5000/FVal/update/1160 File 'h:\\Python25\\lib\\site-packages\\pylons-0.9.6.1-py2.5.egg\ \pylons\\error.py', line 245 in respond app_iter = self.application(environ, detect_start_response) File 'h:\\Python25\\lib\\site-packages\\pylons-0.9.6.1-py2.5.egg\ \pylons\\wsgiapp.py', line 315 in __call__ return self.app(environ, start_response) File 'h:\\python25\\lib\\site-packages\\Beaker-0.9.3-py2.5.egg\\beaker\ \middleware.py', line 74 in __call__ return self.app(environ, start_response) File 'h:\\python25\\lib\\site-packages\\Beaker-0.9.3-py2.5.egg\\beaker\ \middleware.py', line 145 in __call__ return self.wrap_app(environ, session_start_response) File 'h:\\python25\\lib\\site-packages\\Routes-1.7.2-py2.5.egg\\routes\ \middleware.py', line 104 in __call__ response = self.app(environ, start_response) File 'h:\\Python25\\lib\\site-packages\\pylons-0.9.6.1-py2.5.egg\ \pylons\\wsgiapp.py', line 95 in __call__ response = self.dispatch(controller, environ, start_response) File 'h:\\Python25\\lib\\site-packages\\pylons-0.9.6.1-py2.5.egg\ \pylons\\wsgiapp.py', line 237 in dispatch return controller(environ, start_response) File 'H:\\msys\\1.0\\home\\Eric\\rentals\\rentals\\lib\\base.py', line 30 in __call__ return WSGIController.__call__(self, environ, start_response) File 'h:\\Python25\\lib\\site-packages\\pylons-0.9.6.1-py2.5.egg\ \pylons\\controllers\\core.py', line 164 in __call__ response = self._dispatch_call() File 'h:\\Python25\\lib\\site-packages\\pylons-0.9.6.1-py2.5.egg\ \pylons\\controllers\\core.py', line 120 in _dispatch_call response = self._inspect_call(func) File 'h:\\Python25\\lib\\site-packages\\pylons-0.9.6.1-py2.5.egg\ \pylons\\controllers\\core.py', line 79 in _inspect_call result = func(**args) File 'H:\\msys\\1.0\\home\\Eric\\rentals\\rentals\\controllers\ \FVal.py', line 118 in update return render('/ShowFVal.mako') File 'h:\\Python25\\lib\\site-packages\\pylons-0.9.6.1-py2.5.egg\ \pylons\\templating.py', line 343 in render format=format, namespace=kargs, **cache_args) File 'h:\\Python25\\lib\\site-packages\\pylons-0.9.6.1-py2.5.egg\ \pylons\\templating.py', line 228 in render **options) File 'h:\\python25\\lib\\site-packages\\mako-0.1.10-py2.5.egg\\mako\ \ext\\turbogears.py', line 49 in render return template.render(**info) File 'h:\\python25\\lib\\site-packages\\mako-0.1.10-py2.5.egg\\mako\ \template.py', line 114 in render return runtime._render(self, self.callable_, args, data) File 'h:\\python25\\lib\\site-packages\\mako-0.1.10-py2.5.egg\\mako\ \runtime.py', line 287 in _render _render_context(template, callable_, context, *args, **_kwargs_for_callable(callable_, data)) File 'h:\\python25\\lib\\site-packages\\mako-0.1.10-py2.5.egg\\mako\ \runtime.py', line 304 in _render_context _exec_template(inherit, lclcontext, args=args, kwargs=kwargs) File 'h:\\python25\\lib\\site-packages\\mako-0.1.10-py2.5.egg\\mako\ \runtime.py', line 337 in _exec_template callable_(context, *args, **kwargs) File 'H:\\msys\\1.0\\home\\Eric\\rentals\\data\\templates\ \base.mako.py', line 28 in render_body context.write(unicode(next.body())) File 'h:\\python25\\lib\\site-packages\\mako-0.1.10-py2.5.egg\\mako\ \runtime.py', line 193 in <lambda> return lambda *args, **kwargs:callable_(self.context, *args, **kwargs) File 'H:\\msys\\1.0\\home\\Eric\\rentals\\data\\templates\ \ShowFVal.mako.py', line 36 in render_body feature = c.FVal.feature File 'h:\\python25\\lib\\site-packages\\sqlalchemy-0.4.3-py2.5.egg\ \sqlalchemy\\orm\\attributes.py', line 44 in __get__ return self.impl.get(instance._state) File 'h:\\python25\\lib\\site-packages\\sqlalchemy-0.4.3-py2.5.egg\ \sqlalchemy\\orm\\attributes.py', line 225 in get value = callable_() File 'h:\\python25\\lib\\site-packages\\sqlalchemy-0.4.3-py2.5.egg\ \sqlalchemy\\orm\\strategies.py', line 470 in __call__ return q.get(ident) File 'h:\\python25\\lib\\site-packages\\sqlalchemy-0.4.3-py2.5.egg\ \sqlalchemy\\orm\\query.py', line 154 in get return self._get(key, ident, **kwargs) File 'h:\\python25\\lib\\site-packages\\sqlalchemy-0.4.3-py2.5.egg\ \sqlalchemy\\orm\\query.py', line 975 in _get return q.all()[0] File 'h:\\python25\\lib\\site-packages\\sqlalchemy-0.4.3-py2.5.egg\ \sqlalchemy\\orm\\query.py', line 780 in all return list(self) File 'h:\\python25\\lib\\site-packages\\sqlalchemy-0.4.3-py2.5.egg\ \sqlalchemy\\orm\\query.py', line 841 in __iter__ return self._execute_and_instances(context) File 'h:\\python25\\lib\\site-packages\\sqlalchemy-0.4.3-py2.5.egg\ \sqlalchemy\\orm\\query.py', line 844 in _execute_and_instances result = self.session.execute(querycontext.statement, params=self._params, mapper=self.mapper, instance=self._refresh_instance) File 'h:\\python25\\lib\\site-packages\\sqlalchemy-0.4.3-py2.5.egg\ \sqlalchemy\\orm\\session.py', line 605 in execute return self.__connection(engine, close_with_result=True).execute(clause, params or {}) File 'h:\\python25\\lib\\site-packages\\sqlalchemy-0.4.3-py2.5.egg\ \sqlalchemy\\engine\\base.py', line 846 in execute return Connection.executors[c](self, object, multiparams, params) File 'h:\\python25\\lib\\site-packages\\sqlalchemy-0.4.3-py2.5.egg\ \sqlalchemy\\engine\\base.py', line 897 in execute_clauseelement return self._execute_compiled(elem.compile(dialect=self.dialect, column_keys=keys, inline=len(params) > 1), distilled_params=params) File 'h:\\python25\\lib\\site-packages\\sqlalchemy-0.4.3-py2.5.egg\ \sqlalchemy\\engine\\base.py', line 906 in _execute_compiled context = self.__create_execution_context(compiled=compiled, parameters=distilled_params) File 'h:\\python25\\lib\\site-packages\\sqlalchemy-0.4.3-py2.5.egg\ \sqlalchemy\\engine\\base.py', line 952 in __create_execution_context self._handle_dbapi_exception(e, kwargs.get('statement', None), kwargs.get('parameters', None), None) File 'h:\\python25\\lib\\site-packages\\sqlalchemy-0.4.3-py2.5.egg\ \sqlalchemy\\engine\\base.py', line 944 in _handle_dbapi_exception raise exceptions.DBAPIError.instance(statement, parameters, e, connection_invalidated=is_disconnect) InterfaceError: (InterfaceError) connection already closed None [{'{ANON 27984048 param}': 159}] ==== END OF TRACE ========== ## AND... here's what was in the logs in the shell window I unfortunately wasn't watching: 01:35:22,233 DEBUG [pylons.templating] Render called with [] args and {} keyword args 01:35:22,233 WARNI [sqlalchemy.pool.QueuePool.0x..10] Error closing cursor: cursor already closed Traceback (most recent call last): File "h:\Python25\lib\logging\__init__.py", line 744, in emit msg = self.format(record) File "h:\Python25\lib\logging\__init__.py", line 630, in format return fmt.format(record) File "h:\Python25\lib\logging\__init__.py", line 418, in format record.message = record.getMessage() File "h:\Python25\lib\logging\__init__.py", line 288, in getMessage msg = msg % self.args File "h:\Python25\lib\site-packages\pylons-0.9.6.1-py2.5.egg\pylons \util.py", line 94, in __repr__ value_repr = repr(value) File "H:\msys\1.0\home\Eric\rentals\rentals\model\__init__.py", line 402, in __repr__ Feature.by_id(self.feature_id).name, File "H:\msys\1.0\home\Eric\rentals\rentals\model\__init__.py", line 203, in by_id result = Session.query(Feature).filter_by(id=id).one() File "h:\python25\lib\site-packages\sqlalchemy-0.4.3-py2.5.egg \sqlalchemy\orm\query.py", line 827, in one ret = list(self[0:2]) File "h:\python25\lib\site-packages\sqlalchemy-0.4.3-py2.5.egg \sqlalchemy\orm\query.py", line 841, in __iter__ return self._execute_and_instances(context) File "h:\python25\lib\site-packages\sqlalchemy-0.4.3-py2.5.egg \sqlalchemy\orm\query.py", line 844, in _execute_and_instances result = self.session.execute(querycontext.statement, params=self._params, mapper=self.mapper, instance=self._refresh_instance) File "h:\python25\lib\site-packages\sqlalchemy-0.4.3-py2.5.egg \sqlalchemy\orm\session.py", line 605, in execute return self.__connection(engine, close_with_result=True).execute(clause, params or {}) File "h:\python25\lib\site-packages\sqlalchemy-0.4.3-py2.5.egg \sqlalchemy\engine\base.py", line 846, in execute return Connection.executors[c](self, object, multiparams, params) File "h:\python25\lib\site-packages\sqlalchemy-0.4.3-py2.5.egg \sqlalchemy\engine\base.py", line 897, in execute_clauseelement return self._execute_compiled(elem.compile(dialect=self.dialect, column_keys=keys, inline=len(params) > 1), distilled_params=params) File "h:\python25\lib\site-packages\sqlalchemy-0.4.3-py2.5.egg \sqlalchemy\engine\base.py", line 909, in _execute_compiled self.__execute_raw(context) File "h:\python25\lib\site-packages\sqlalchemy-0.4.3-py2.5.egg \sqlalchemy\engine\base.py", line 918, in __execute_raw self._cursor_execute(context.cursor, context.statement, context.parameters[0], context=context) File "h:\python25\lib\site-packages\sqlalchemy-0.4.3-py2.5.egg \sqlalchemy\engine\base.py", line 962, in _cursor_execute self._handle_dbapi_exception(e, statement, parameters, cursor) File "h:\python25\lib\site-packages\sqlalchemy-0.4.3-py2.5.egg \sqlalchemy\engine\base.py", line 944, in _handle_dbapi_exception raise exceptions.DBAPIError.instance(statement, parameters, e, connection_invalidated=is_disconnect) OperationalError: (OperationalError) insert or update on table "feature_values" violates foreign key constraint "fk > tokens" DETAIL: Key (value)=(2007) is not present in table "tokens". 'SELECT features.itemtype_id AS features_itemtype_id, features.name AS features_name, features.featuretype AS features_featuretype, features.ordinal AS features_ordinal, features.attachment AS features_attachment, features.id AS features_id, features.parent_id AS features_parent_id, features.dynattach AS features_dynattach \nFROM features \nWHERE features.id = %(features_id_1)s ORDER BY features.id \n LIMIT 2 OFFSET 0' {'features_id_1': 159} .. so it was only because I forgot to satisfy a foreign key before calling commit(). But I was held back for a long time in discovering that underlying problem, because I was digging all over the SA world trying to figure out why I was having this "Connection Already Closed" trouble. Moral of the story? Always watch the logs. But I submit this case here, in case it might indicate that some part of SqlAlchemy's error reporting / exception handling might need some adjusting. Available information out there seemed to unanimously agree that I was going to have to study up on connection lifetimes etc etc, when actually that was fully barking up the wrong tree in this case. - Eric --~--~---------~--~----~------------~-------~--~----~ You received this message because you are subscribed to the Google Groups "sqlalchemy" group. To post to this group, send email to sqlalchemy@googlegroups.com To unsubscribe from this group, send email to [EMAIL PROTECTED] For more options, visit this group at http://groups.google.com/group/sqlalchemy?hl=en -~----------~----~----~----~------~----~------~--~---
