'Protocol error, expecting EOF' and AssertionError('Result length not requested length:\nExpected=8. Actual=4. Position: 1. Data Length: 5',)

1,536 views

Skip to first unread message

luckyboy

unread,

Nov 24, 2011, 1:08:10 PM11/24/11

to PyMySQL Users

Hey,
We've been facing some weird problems recently with pymysql, updating
to 0.5 doesn't fix the problems. The problem happens randomly and we
cannot reproduce it consistently. That's a python web server hosted on
amazon ec2 instances, connecting to mysql 5.1 (also hosted on ec2),
through haproxy so that we switch instances(to a fail-over db ec2
instance) in case of failure. We're using gevent so all IO python
libraries (including sockets) are patched for asynchronous support.

Any ideas ?
Thanks...

Three different exceptions:

1- Traceback (most recent call last):
File "/opt/fg-python-backend/lib/python2.7/site-packages/repoze/
errorlog/__init__.py", line 84, in __call__
return self.application(environ, start_response)
File "/opt/fg-python-backend/lib/python2.7/site-packages/pyramid/
router.py", line 158, in __call__
response = view_callable(context, request)
File "/opt/fg-python-backend/lib/python2.7/site-packages/pyramid/
config.py", line 2824, in _rendered_view
response = wrapped_view(context, request)
File "/opt/fg-python-backend/lib/python2.7/site-packages/pyramid/
config.py", line 2892, in _class_requestonly_view
response = getattr(inst, attr)()
File "/opt/fg-python-backend/lib/python2.7/site-packages/socialcore/
lib/social_mixpanel.py", line 82, in callback
log.error('track_page: %s', e)
File "/usr/lib/python2.7/logging/__init__.py", line 1158, in error
self._log(ERROR, msg, args, **kwargs)
File "/usr/lib/python2.7/logging/__init__.py", line 1250, in _log
self.handle(record)
File "/usr/lib/python2.7/logging/__init__.py", line 1260, in handle
self.callHandlers(record)
File "/usr/lib/python2.7/logging/__init__.py", line 1300, in
callHandlers
hdlr.handle(record)
File "/usr/lib/python2.7/logging/__init__.py", line 740, in handle
rv = self.filter(record)
File "/usr/lib/python2.7/logging/__init__.py", line 604, in filter
if not f.filter(record):
File "/opt/fg-python-backend/lib/python2.7/site-packages/socialcore/
lib/social_logging.py", line 69, in filter
record.locals = pformat(frame.f_locals)
File "/usr/lib/python2.7/pprint.py", line 60, in pformat
return PrettyPrinter(indent=indent, width=width,
depth=depth).pformat(object)
File "/usr/lib/python2.7/pprint.py", line 119, in pformat
self._format(object, sio, 0, 0, {}, 0)
File "/usr/lib/python2.7/pprint.py", line 137, in _format
rep = self._repr(object, context, level - 1)
File "/usr/lib/python2.7/pprint.py", line 230, in _repr
self._depth, level)
File "/usr/lib/python2.7/pprint.py", line 242, in format
return _safe_repr(object, context, maxlevels, level)
File "/usr/lib/python2.7/pprint.py", line 286, in _safe_repr
vrepr, vreadable, vrecur = saferepr(v, context, maxlevels, level)
File "/usr/lib/python2.7/pprint.py", line 327, in _safe_repr
rep = repr(object)
File "/opt/fg-python-backend/lib/python2.7/site-packages/socialcore/
model/application.py", line 36, in __repr__
return '<Application(id=%s)>' % self.id
File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/
orm/attributes.py", line 168, in __get__
return self.impl.get(instance_state(instance),dict_)
File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/
orm/attributes.py", line 418, in get
value = callable_(passive)
File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/
orm/state.py", line 271, in __call__
self.manager.deferred_scalar_loader(self, toload)
File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/
orm/mapper.py", line 1584, in _load_scalar_attributes
only_load_props=attribute_names)
File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/
orm/query.py", line 2119, in _load_on_ident
return q.one()
File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/
orm/query.py", line 1796, in one
ret = list(self)
File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/
orm/query.py", line 1839, in __iter__
return self._execute_and_instances(context)
File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/
orm/query.py", line 1854, in _execute_and_instances
result = conn.execute(querycontext.statement, self._params)
File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/
engine/base.py", line 1399, in execute
params)
File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/
engine/base.py", line 1532, in _execute_clauseelement
compiled_sql, distilled_params
File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/
engine/base.py", line 1640, in _execute_context
context)
File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/
engine/base.py", line 1633, in _execute_context
context)
File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/
engine/default.py", line 325, in do_execute
cursor.execute(statement, parameters)
File "/opt/fg-python-backend/lib/python2.7/site-packages/pymysql/
cursors.py", line 108, in execute
query = query.encode(charset)
File "/opt/fg-python-backend/lib/python2.7/site-packages/pymysql/
connections.py", line 182, in defaulterrorhandler
connection.messages.append(err)
DBAPIError: (Error) (<type 'exceptions.AssertionError'>,
AssertionError('Result length not requested length:\nExpected=8.
Actual=4. Position: 1. Data Length: 5',)) 'SELECT application.id AS
application_id, application.creation_time AS
application_creation_time, application.api_key AS application_api_key,
application.secret_key AS application_secret_key, application.name AS
application_name, application.canvas_name AS application_canvas_name,
application.json_properties AS application_json_properties \nFROM
application \nWHERE application.id = %s' (111868428901374L,)

2- Traceback:
['Traceback (most recent call last):\n',
' File "/opt/fg-python-backend/lib/python2.7/site-packages/pyamf/
remoting/amf0.py", line 108, in __call__\n *args, **kwargs)\n',
' File "/opt/fg-python-backend/lib/python2.7/site-packages/pyamf/
remoting/amf0.py", line 61, in _getBody\n **kwargs)\n',
' File "/opt/fg-python-backend/lib/python2.7/site-packages/pyamf/
remoting/gateway/__init__.py", line 513, in callServiceRequest\n
return service_request(*args)\n',
' File "/opt/fg-python-backend/lib/python2.7/site-packages/pyamf/
remoting/gateway/__init__.py", line 233, in __call__\n return
self.service(self.method, args)\n',
' File "/opt/fg-python-backend/lib/python2.7/site-packages/pyamf/
remoting/gateway/__init__.py", line 133, in __call__\n return
func(*params)\n',
' File "/opt/fg-python-backend/lib/python2.7/site-packages/socialcore/
lib/amf.py", line 42, in inject_request_wrapper\n return target(ob,
*args, **kwargs)\n',
' File "/opt/fg-python-backend/lib/python2.7/site-packages/socialcore/
lib/amf.py", line 75, in authenticate_wrapper\n ob.user_application
= auth(ob.user_id, ob.oauth_token)\n',
' File "/opt/fg-python-backend/lib/python2.7/site-packages/socialcore/
model/user_application.py", line 70, in validate_and_get\n u_app =
cls.get((user_id, app_id))\n',
' File "/opt/fg-python-backend/lib/python2.7/site-packages/socialcore/
lib/social_elixir.py", line 67, in get\n return
dbsess.query(cls).get(*args, **kwargs)\n', ' File "/opt/fg-python-
backend/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line
722, in get\n return self._load_on_ident(key)\n', ' File "/opt/fg-
python-backend/lib/python2.7/site-packages/sqlalchemy/orm/query.py",
line 2119, in _load_on_ident\n return q.one()\n', ' File "/opt/fg-
python-backend/lib/python2.7/site-packages/sqlalchemy/orm/query.py",
line 1796, in one\n ret = list(self)\n',
' File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/
orm/query.py", line 1839, in __iter__\n return
self._execute_and_instances(context)\n',
' File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/
orm/query.py", line 1854, in _execute_and_instances\n result =
conn.execute(querycontext.statement, self._params)\n',
' File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/
engine/base.py", line 1399, in execute\n params)\n',
' File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/
engine/base.py", line 1532, in _execute_clauseelement\n
compiled_sql, distilled_params\n',
' File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/
engine/base.py", line 1640, in _execute_context\n context)\n',
' File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/
engine/base.py", line 1633, in _execute_context\n context)\n',
' File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/
engine/default.py", line 325, in do_execute\n
cursor.execute(statement, parameters)\n',
' File "/opt/fg-python-backend/lib/python2.7/site-packages/pymysql/
cursors.py", line 108, in execute\n query = query.encode(charset)
\n',
' File "/opt/fg-python-backend/lib/python2.7/site-packages/pymysql/
connections.py", line 182, in defaulterrorhandler\n
connection.messages.append(err)\n', "DBAPIError: (Error) (<type
'exceptions.AssertionError'>, AssertionError('Protocol error,
expecting EOF',)) 'SELECT user_application.user_id AS
user_application_user_id, user_application.application_id AS
user_application_application_id, user_application.creation_time AS
user_application_creation_time, user_application.likes AS
user_application_likes, user_application.token_expiration_time AS
user_application_token_expiration_time, user_application.email AS
user_application_email, user_application.third_party_id AS
user_application_third_party_id, user_application.oauth_token AS
user_application_oauth_token, user_application.is_paying AS
user_application_is_paying \\nFROM user_application \\nWHERE
user_application.user_id = %s AND user_application.application_id =
%s' (100002946994232L, 111868428901374L)\n"

3- Note that the datetime that's being casted as int ('2011-11-07
15:57:18') has nothing to do with any column value stored for this
row. So I have no idea where's it coming from.

Traceback (most recent call last):
File "/opt/fg-python-backend/lib/python2.7/site-packages/repoze/
errorlog/__init__.py", line 84, in __call__
return self.application(environ, start_response)
File "/opt/fg-python-backend/lib/python2.7/site-packages/pyramid/
router.py", line 158, in __call__
response = view_callable(context, request)
File "/opt/fg-python-backend/lib/python2.7/site-packages/pyramid/
config.py", line 2824, in _rendered_view
response = wrapped_view(context, request)
File "/opt/fg-python-backend/lib/python2.7/site-packages/pyramid/
config.py", line 2892, in _class_requestonly_view
response = getattr(inst, attr)()
File "/opt/fg-python-backend/lib/python2.7/site-packages/socialcore/
lib/social_mixpanel.py", line 82, in callback
log.error('track_page: %s', e)
File "/usr/lib/python2.7/logging/__init__.py", line 1158, in error
self._log(ERROR, msg, args, **kwargs)
File "/usr/lib/python2.7/logging/__init__.py", line 1250, in _log
self.handle(record)
File "/usr/lib/python2.7/logging/__init__.py", line 1260, in handle
self.callHandlers(record)
File "/usr/lib/python2.7/logging/__init__.py", line 1300, in
callHandlers
hdlr.handle(record)
File "/usr/lib/python2.7/logging/__init__.py", line 740, in handle
rv = self.filter(record)
File "/usr/lib/python2.7/logging/__init__.py", line 604, in filter
if not f.filter(record):
File "/opt/fg-python-backend/lib/python2.7/site-packages/socialcore/
lib/social_logging.py", line 69, in filter
record.locals = pformat(frame.f_locals)
File "/usr/lib/python2.7/pprint.py", line 60, in pformat
return PrettyPrinter(indent=indent, width=width,
depth=depth).pformat(object)
File "/usr/lib/python2.7/pprint.py", line 119, in pformat
self._format(object, sio, 0, 0, {}, 0)
File "/usr/lib/python2.7/pprint.py", line 137, in _format
rep = self._repr(object, context, level - 1)
File "/usr/lib/python2.7/pprint.py", line 230, in _repr
self._depth, level)
File "/usr/lib/python2.7/pprint.py", line 242, in format
return _safe_repr(object, context, maxlevels, level)
File "/usr/lib/python2.7/pprint.py", line 286, in _safe_repr
vrepr, vreadable, vrecur = saferepr(v, context, maxlevels, level)
File "/usr/lib/python2.7/pprint.py", line 327, in _safe_repr
rep = repr(object)
File "/opt/fg-python-backend/lib/python2.7/site-packages/socialcore/
model/application.py", line 36, in __repr__
return '<Application(id=%s)>' % self.id
File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/
orm/attributes.py", line 168, in __get__
return self.impl.get(instance_state(instance),dict_)
File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/
orm/attributes.py", line 418, in get
value = callable_(passive)
File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/
orm/state.py", line 275, in __call__
self.manager.deferred_scalar_loader(self, toload)
File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/
orm/mapper.py", line 1571, in _load_scalar_attributes
only_load_props=attribute_names)
File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/
orm/query.py", line 2071, in _load_on_ident
return q.one()
File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/
orm/query.py", line 1744, in one
ret = list(self)
File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/
orm/query.py", line 1787, in __iter__
return self._execute_and_instances(context)
File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/
orm/query.py", line 1802, in _execute_and_instances
result = conn.execute(querycontext.statement, self._params)
File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/
engine/base.py", line 1358, in execute
params)
File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/
engine/base.py", line 1491, in _execute_clauseelement
compiled_sql, distilled_params
File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/
engine/base.py", line 1599, in _execute_context
context)
File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/
engine/base.py", line 1592, in _execute_context
context)
File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/
engine/default.py", line 325, in do_execute
cursor.execute(statement, parameters)
File "/opt/fg-python-backend/lib/python2.7/site-packages/pymysql/
cursors.py", line 108, in execute
self.errorhandler(self, exc, value)
File "/opt/fg-python-backend/lib/python2.7/site-packages/pymysql/
connections.py", line 182, in defaulterrorhandler
raise Error(errorclass, errorvalue)
DBAPIError: (Error) (<type 'exceptions.ValueError'>,
ValueError("invalid literal for int() with base 10: '2011-11-07
15:57:18'",)) 'SELECT application.id AS application_id,
application.creation_time AS application_creation_time,
application.api_key AS application_api_key, application.secret_key AS
application_secret_key, application.name AS application_name,
application.canvas_name AS application_canvas_name,
application.json_properties AS application_json_properties \nFROM
application \nWHERE application.id = %s' (111868428901374L,)

luckyboy

unread,

Nov 24, 2011, 1:10:19 PM11/24/11

to PyMySQL Users

Follow up:

Things were working fine with that setup until some recent changesets
in the web application, that have no business whatsoever with simple
select queries executed like the ones shown below (e.g select * from
application)
In order to get more details, I had to comment out the try/except
block that was screening the full stack trace.. (cursors.py, line
111). Here's what I have:

config.py", line 2617, in __call__
return view(context, request)
File "/opt/fg-python-backend/lib/python2.7/site-packages/pyramid/
config.py", line 2805, in attr_view
return view(context, request)
File "/opt/fg-python-backend/lib/python2.7/site-packages/pyramid/
config.py", line 2784, in predicate_wrapper
return view(context, request)
File "/opt/fg-python-backend/lib/python2.7/site-packages/fifthgrader/
views/base.py", line 17, in decorated_view
action_response = view(context, request)

File "/opt/fg-python-backend/lib/python2.7/site-packages/pyramid/
config.py", line 2824, in _rendered_view
response = wrapped_view(context, request)
File "/opt/fg-python-backend/lib/python2.7/site-packages/pyramid/

File "/opt/fg-python-backend/lib/python2.7/site-packages/socialcore/
lib/social_elixir.py", line 67, in get

return dbsess.query(cls).get(*args, **kwargs)

File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/
orm/query.py", line 722, in get

return self._load_on_ident(key)

File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/
orm/query.py", line 2119, in _load_on_ident
return q.one()
File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/
orm/query.py", line 1796, in one
ret = list(self)
File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/
orm/query.py", line 1839, in __iter__
return self._execute_and_instances(context)
File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/
orm/query.py", line 1854, in _execute_and_instances
result = conn.execute(querycontext.statement, self._params)
File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/
engine/base.py", line 1399, in execute
params)
File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/
engine/base.py", line 1532, in _execute_clauseelement
compiled_sql, distilled_params
File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/

engine/base.py", line 1633, in _execute_context
context)
File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/
engine/default.py", line 325, in do_execute
cursor.execute(statement, parameters)
File "/opt/fg-python-backend/lib/python2.7/site-packages/pymysql/

cursors.py", line 112, in execute
result = self._query(query)
File "/opt/fg-python-backend/lib/python2.7/site-packages/pymysql/
cursors.py", line 230, in _query
conn.query(q)
File "/opt/fg-python-backend/lib/python2.7/site-packages/pymysql/
connections.py", line 607, in query
self._affected_rows = self._read_query_result()
File "/opt/fg-python-backend/lib/python2.7/site-packages/pymysql/
connections.py", line 691, in _read_query_result
result.read()
File "/opt/fg-python-backend/lib/python2.7/site-packages/pymysql/
connections.py", line 875, in read
self._read_result_packet()
File "/opt/fg-python-backend/lib/python2.7/site-packages/pymysql/
connections.py", line 887, in _read_result_packet
self._get_descriptions()
File "/opt/fg-python-backend/lib/python2.7/site-packages/pymysql/
connections.py", line 926, in _get_descriptions
field = self.connection.read_packet(FieldDescriptorPacket)
File "/opt/fg-python-backend/lib/python2.7/site-packages/pymysql/
connections.py", line 685, in read_packet
packet = packet_type(self)
File "/opt/fg-python-backend/lib/python2.7/site-packages/pymysql/
connections.py", line 343, in __init__
self.__parse_field_descriptor()
File "/opt/fg-python-backend/lib/python2.7/site-packages/pymysql/
connections.py", line 357, in __parse_field_descriptor
self.charsetnr = struct.unpack('<H', self.read(2))[0]
File "/opt/fg-python-backend/lib/python2.7/site-packages/pymysql/
connections.py", line 227, in read
result = self.peek(size)
File "/opt/fg-python-backend/lib/python2.7/site-packages/pymysql/
connections.py", line 264, in peek
raise AssertionError(error)
AssertionError: Result length not requested length:
Expected=8. Actual=4. Position: 1. Data Length: 5

File "/opt/fg-python-backend/lib/python2.7/site-packages/socialcore/
lib/social_elixir.py", line 67, in get

return dbsess.query(cls).get(*args, **kwargs)

File "/opt/fg-python-backend/lib/python2.7/site-packages/sqlalchemy/
orm/query.py", line 722, in get

return self._load_on_ident(key)

config.py", line 2887, in _class_requestonly_view
inst = view(request)
File "/opt/fg-python-backend/lib/python2.7/site-packages/fifthgrader/
views/facebook_controller.py", line 40, in __init__
FacebookHandler.__init__(self, request, GameApp().app)
File "/opt/fg-python-backend/lib/python2.7/site-packages/socialcore/
abstract/controllers/facebook_handler.py", line 47, in __init__
self._process_fb_signed_request()
File "/opt/fg-python-backend/lib/python2.7/site-packages/socialcore/
abstract/controllers/facebook_handler.py", line 92, in
_process_fb_signed_request
install_user()
File "/opt/fg-python-backend/lib/python2.7/site-packages/socialcore/
abstract/controllers/facebook_handler.py", line 77, in install_user
% (user_id, self.app))

I appreciate you help,
Thanks.

Pete Hunt

unread,

Nov 28, 2011, 4:54:15 PM11/28/11

to pymysq...@googlegroups.com

OK, I wonder if this is an issue with the gevent patching. I will add a test case for gevent at some point and see if I can get a consistent repro. Thanks for the report.

luckyboy

unread,

Nov 28, 2011, 5:07:41 PM11/28/11

to PyMySQL Users

Useful update:

Last changeset of our webapp contained some methods that were
decorated with a custom decorator (called async_task), that basically
spawns a gevent greenlet and execute those methods.. Note that the
these executed methods have nothing to do with Mysql (mostly some
facebook api calls).... When I turned off that decorator so that
methods are executed in a normal blocking way, I didn't get the
problems reported above..
In all cases, socket was patched with gevent, and paster_gevent was
run to serve our http requests..

My guess is that it's something with gevent patching so I'm looking
into that myself. I wonder if it has anything to do with that fact
that you're using file descriptors to read and write from sockets
(using makefile), even though this is inappropriate for non-blocking
sockets(with timeout set to zero), which is the case for patched
gevent sockets..