CodecException: Cannot encode 68527 as uint16

[Dan Prince]

As of 6b16c8731c44e4a6c80b803f3e8afdd88386d577 (Call scheduler for run_instance from conductor) I'm now getting consistent failures when using Nova w/ qpid. See the stack trace below:

==> /var/log/nova/scheduler.log <==
2013-06-05 00:32:15.215 10750 ERROR nova.scheduler.driver [req-cbf2bc32-b206-4f00-9216-ad3db8c79567 d01f4833227947a08af2a35dcc3835fc 69c74074c2ed4d7797e2b7cd25e78993] Exception during scheduler.run_instance
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver Traceback (most recent call last):
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver File "/usr/lib/python2.7/site-packages/nova/scheduler/filter_scheduler.py", line 110, in schedule_run_instance
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver instance_uuid=instance_uuid)
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver File "/usr/lib/python2.7/site-packages/nova/scheduler/filter_scheduler.py", line 195, in _provision_resource
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver node=weighed_host.obj.nodename)
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver File "/usr/lib/python2.7/site-packages/nova/compute/rpcapi.py", line 550, in run_instance
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver version='2.19')
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver File "/usr/lib/python2.7/site-packages/nova/openstack/common/rpc/proxy.py", line 166, in cast
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver rpc.cast(context, self._get_topic(topic), msg)
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver File "/usr/lib/python2.7/site-packages/nova/openstack/common/rpc/__init__.py", line 158, in cast
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver return _get_impl().cast(CONF, context, topic, msg)
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver File "/usr/lib/python2.7/site-packages/nova/openstack/common/rpc/impl_qpid.py", line 618, in cast
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver rpc_amqp.get_connection_pool(conf, Connection))
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver File "/usr/lib/python2.7/site-packages/nova/openstack/common/rpc/amqp.py", line 627, in cast
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver conn.topic_send(topic, rpc_common.serialize_msg(msg))
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver File "/usr/lib/python2.7/site-packages/nova/openstack/common/rpc/amqp.py", line 152, in __exit__
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver self._done()
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver File "/usr/lib/python2.7/site-packages/nova/openstack/common/rpc/amqp.py", line 141, in _done
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver self.connection.reset()
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver File "/usr/lib/python2.7/site-packages/nova/openstack/common/rpc/impl_qpid.py", line 394, in reset
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver self.session.close()
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver File "<string>", line 6, in close
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver File "/usr/lib/python2.7/site-packages/qpid/messaging/endpoints.py", line 739, in close
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver self.sync(timeout=timeout)
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver File "<string>", line 6, in sync
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver File "/usr/lib/python2.7/site-packages/qpid/messaging/endpoints.py", line 730, in sync
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver snd.sync(timeout=timeout)
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver File "<string>", line 6, in sync
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver File "/usr/lib/python2.7/site-packages/qpid/messaging/endpoints.py", line 885, in sync
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver if not self._ewait(lambda: self.acked >= mno, timeout=timeout):
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver File "/usr/lib/python2.7/site-packages/qpid/messaging/endpoints.py", line 799, in _ewait
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver result = self.session._ewait(lambda: self.error or predicate(), timeout)
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver File "/usr/lib/python2.7/site-packages/qpid/messaging/endpoints.py", line 566, in _ewait
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver result = self.connection._ewait(lambda: self.error or predicate(), timeout)
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver File "/usr/lib/python2.7/site-packages/qpid/messaging/endpoints.py", line 209, in _ewait
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver self.check_error()
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver File "/usr/lib/python2.7/site-packages/qpid/messaging/endpoints.py", line 202, in check_error
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver raise self.error
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver InternalError: Traceback (most recent call last):
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver File "/usr/lib/python2.7/site-packages/qpid/messaging/driver.py", line 497, in dispatch
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver self.engine.dispatch()
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver File "/usr/lib/python2.7/site-packages/qpid/messaging/driver.py", line 802, in dispatch
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver self.process(ssn)
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver File "/usr/lib/python2.7/site-packages/qpid/messaging/driver.py", line 1037, in process
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver self.send(snd, msg)
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver File "/usr/lib/python2.7/site-packages/qpid/messaging/driver.py", line 1248, in send
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver body = enc(msg.content)
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver File "/usr/lib/python2.7/site-packages/qpid/messaging/message.py", line 28, in encode
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver sc.write_primitive(type, x)
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver File "/usr/lib/python2.7/site-packages/qpid/codec010.py", line 73, in write_primitive
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver getattr(self, "write_%s" % type.NAME)(v)
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver File "/usr/lib/python2.7/site-packages/qpid/codec010.py", line 257, in write_map
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver sc.write(string.joinfields(map(self._write_map_elem, m.keys(), m.values()), ""))
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver File "/usr/lib/python2.7/site-packages/qpid/codec010.py", line 250, in _write_map_elem
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver sc.write_primitive(type, v)
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver File "/usr/lib/python2.7/site-packages/qpid/codec010.py", line 73, in write_primitive
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver getattr(self, "write_%s" % type.NAME)(v)
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver File "/usr/lib/python2.7/site-packages/qpid/codec010.py", line 190, in write_str16
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver self.write_vbin16(s.encode("utf8"))
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver File "/usr/lib/python2.7/site-packages/qpid/codec010.py", line 203, in write_vbin16
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver self.write_uint16(len(b))
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver File "/usr/lib/python2.7/site-packages/qpid/codec010.py", line 116, in write_uint16
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver raise CodecException("Cannot encode %d as uint16" % n)
2013-06-05 00:32:15.215 10750 TRACE nova.scheduler.driver CodecException: Cannot encode 68527 as uint16

[Mark McLoughlin (markmc)]

The commit Dan mentions is https://review.openstack.org/29091

[Dan Prince (dan-prince)]

Normally I'd revert things but this commit seemed a bit large for a revert.

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/31791

[Hans Lindgren (hanlind)]

Is this maybe related to bug 1175808?
The error from the trace is the same.

[Andrew Laski (alaski)]

Thanks Hans, that does appear to be it. I was striving for no fundamental changes to the parameters to scheduler_run_instance in https://review.openstack.org/31791 but there were minor changes that must have pushed the message size over the limit.

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/31803

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/31803
Committed: http://github.com/openstack/nova/commit/781a8f908cd3e5e69ff8b88d998fa93c48532e15
Submitter: Jenkins
Branch: master

commit 781a8f908cd3e5e69ff8b88d998fa93c48532e15
Author: Andrew Laski <email address hidden>
Date: Wed Jun 5 10:02:07 2013 -0400

    Update rpc/impl_qpid.py from oslo

    The current qpid driver cannot serialize objects containing strings
    longer than 65535 characters. This just became a breaking issue when
    the message to scheduler_run_instance went over that limit. The fix has
    been commited to oslo, so this just syncs it over to Nova.

    Bug 1175808
    Bug 1187595

    Change-Id: If95c11a7e03c81d89133f6cad0dcbb6d8acb8148