libvirtError: Cannot recv data: Connection reset by peer

[Peter Portante]

tempest.api.compute.servers.test_servers_negative.ServersNegativeTestJSON fails sporadically.

See: http://logs.openstack.org/66/54966/2/check/check-tempest-devstack-vm-full/d611ed0/console.html

2013-11-19 22:24:52.379 | ======================================================================
2013-11-19 22:24:52.380 | FAIL: setUpClass (tempest.api.compute.servers.test_servers_negative.ServersNegativeTestJSON)
2013-11-19 22:24:52.380 | setUpClass (tempest.api.compute.servers.test_servers_negative.ServersNegativeTestJSON)
2013-11-19 22:24:52.380 | ----------------------------------------------------------------------
2013-11-19 22:24:52.380 | _StringException: Traceback (most recent call last):
2013-11-19 22:24:52.380 | File "tempest/api/compute/servers/test_servers_negative.py", line 46, in setUpClass
2013-11-19 22:24:52.380 | resp, server = cls.create_test_server(wait_until='ACTIVE')
2013-11-19 22:24:52.381 | File "tempest/api/compute/base.py", line 118, in create_test_server
2013-11-19 22:24:52.381 | server['id'], kwargs['wait_until'])
2013-11-19 22:24:52.381 | File "tempest/services/compute/json/servers_client.py", line 160, in wait_for_server_status
2013-11-19 22:24:52.381 | extra_timeout=extra_timeout)
2013-11-19 22:24:52.381 | File "tempest/common/waiters.py", line 73, in wait_for_server_status
2013-11-19 22:24:52.381 | raise exceptions.BuildErrorException(server_id=server_id)
2013-11-19 22:24:52.381 | BuildErrorException: Server 62bfeebd-8878-477f-9eac-a8b21ec5ac26 failed to build and is in ERROR status

[Ollie Leahy (oliver-leahy-l)]

 tempest.api.compute.servers.test_list_servers_negative.ListServersNegativeTestJSON has also been reported to have leaked resources, see http://logs.openstack.org/67/59967/4/check/check-tempest-dsvm-postgres-full/54dadda/console.html

2013-12-12 16:36:30.396 | OK (skipped=117)
2013-12-12 16:36:30.397 | ___________________________________ summary ____________________________________
2013-12-12 16:36:30.400 | full: commands succeeded
2013-12-12 16:36:30.404 | congratulations :)
2013-12-12 16:36:30.406 | Checking logs...
2013-12-12 16:36:31.982 | Log File: n-api
2013-12-12 16:36:31.982 | 2013-12-12 16:23:47.368 ERROR nova.api.openstack [req-a60466bb-2b71-4df5-9223-601caa1a9e98 ServersNegativeTestJSON-tempest-1555050594-user ServersNegativeTestJSON-tempest-1555050594-t2013-12-12 16:23:47.377 24881 DEBUG routes.middleware [-] Route path: '/servers/:(id)', defaults: {'action': u'show', 'controller': <nova.api.openstack.wsgi.Resource object at 0x3ad5fd0>} __call__ /usr/lib/python2.7/dist-packages/routes/middleware.py:102
2013-12-12 16:36:31.983 |
2013-12-12 16:36:37.617 | Logs have errors
2013-12-12 16:36:37.618 | FAILED
2013-12-12 16:38:58.566 | Process leaked file descriptors. See http://wiki.jenkins-ci.org/display/JENKINS/Spawning+processes+from+build for more information
2013-12-12 16:38:58.704 | Build step 'Execute shell' marked build as failure

[Matt Riedemann (mriedem)]

There is one hit in the last 2 weeks in the gate on this:

http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOlwiRkFJTDogc2V0VXBDbGFzcyAodGVtcGVzdC5hcGkuY29tcHV0ZS5zZXJ2ZXJzLnRlc3Rfc2VydmVyc19uZWdhdGl2ZS5TZXJ2ZXJzTmVnYXRpdmVUZXN0SlNPTilcIiBBTkQgZmlsZW5hbWU6XCJjb25zb2xlLmh0bWxcIiBBTkQgYnVpbGRfcXVldWU6Z2F0ZSIsImZpZWxkcyI6W10sIm9mZnNldCI6MCwidGltZWZyYW1lIjoiYWxsIiwiZ3JhcGhtb2RlIjoiY291bnQiLCJ0aW1lIjp7InVzZXJfaW50ZXJ2YWwiOjB9LCJzdGFtcCI6MTM5MDg0MTE2ODkyNX0=

And that one run has 58 failures, so guessing something snowballed it.

http://logs.openstack.org/49/55449/14/gate/gate-tempest-dsvm-full/7154785/console.html.gz

Given the age of this and the fact it's not showing up in the gate reliably makes me think we can close it.

[Matt Riedemann (mriedem)]

Going back to the original logs, the instance does show up with the build failure in the nova scheduler logs here:

http://logs.openstack.org/66/54966/2/check/check-tempest-devstack-vm-full/d611ed0/logs/screen-n-sch.txt.gz#_2013-11-19_22_06_38_278

Which then shows up in the n-cpu logs here:

http://logs.openstack.org/66/54966/2/check/check-tempest-devstack-vm-full/d611ed0/logs/screen-n-cpu.txt.gz#_2013-11-19_22_06_33_235

2013-11-19 22:06:33.235 ERROR nova.compute.manager [req-873bc199-a51e-4f4c-a085-3ae084c0d4dc ServersNegativeTestJSON-tempest-616305902-user ServersNegativeTestJSON-tempest-616305902-tenant] [instance: 62bfeebd-8878-477f-9eac-a8b21ec5ac26] Instance failed to spawn
2013-11-19 22:06:33.235 24775 TRACE nova.compute.manager [instance: 62bfeebd-8878-477f-9eac-a8b21ec5ac26] Traceback (most recent call last):
2013-11-19 22:06:33.235 24775 TRACE nova.compute.manager [instance: 62bfeebd-8878-477f-9eac-a8b21ec5ac26] File "/opt/stack/new/nova/nova/compute/manager.py", line 1436, in _spawn
2013-11-19 22:06:33.235 24775 TRACE nova.compute.manager [instance: 62bfeebd-8878-477f-9eac-a8b21ec5ac26] block_device_info)
2013-11-19 22:06:33.235 24775 TRACE nova.compute.manager [instance: 62bfeebd-8878-477f-9eac-a8b21ec5ac26] File "/opt/stack/new/nova/nova/virt/libvirt/driver.py", line 2107, in spawn
2013-11-19 22:06:33.235 24775 TRACE nova.compute.manager [instance: 62bfeebd-8878-477f-9eac-a8b21ec5ac26] block_device_info, context=context)
2013-11-19 22:06:33.235 24775 TRACE nova.compute.manager [instance: 62bfeebd-8878-477f-9eac-a8b21ec5ac26] File "/opt/stack/new/nova/nova/virt/libvirt/driver.py", line 3296, in _create_domain_and_network
2013-11-19 22:06:33.235 24775 TRACE nova.compute.manager [instance: 62bfeebd-8878-477f-9eac-a8b21ec5ac26] self.firewall_driver.setup_basic_filtering(instance, network_info)
2013-11-19 22:06:33.235 24775 TRACE nova.compute.manager [instance: 62bfeebd-8878-477f-9eac-a8b21ec5ac26] File "/opt/stack/new/nova/nova/virt/libvirt/firewall.py", line 305, in setup_basic_filtering
2013-11-19 22:06:33.235 24775 TRACE nova.compute.manager [instance: 62bfeebd-8878-477f-9eac-a8b21ec5ac26] self.nwfilter.setup_basic_filtering(instance, network_info)
2013-11-19 22:06:33.235 24775 TRACE nova.compute.manager [instance: 62bfeebd-8878-477f-9eac-a8b21ec5ac26] File "/opt/stack/new/nova/nova/virt/libvirt/firewall.py", line 134, in setup_basic_filtering
2013-11-19 22:06:33.235 24775 TRACE nova.compute.manager [instance: 62bfeebd-8878-477f-9eac-a8b21ec5ac26] vif))
2013-11-19 22:06:33.235 24775 TRACE nova.compute.manager [instance: 62bfeebd-8878-477f-9eac-a8b21ec5ac26] File "/opt/stack/new/nova/nova/virt/libvirt/firewall.py", line 249, in _define_filter
2013-11-19 22:06:33.235 24775 TRACE nova.compute.manager [instance: 62bfeebd-8878-477f-9eac-a8b21ec5ac26] self._conn.nwfilterDefineXML(xml)
2013-11-19 22:06:33.235 24775 TRACE nova.compute.manager [instance: 62bfeebd-8878-477f-9eac-a8b21ec5ac26] File "/usr/local/lib/python2.7/dist-packages/eventlet/tpool.py", line 179, in doit
2013-11-19 22:06:33.235 24775 TRACE nova.compute.manager [instance: 62bfeebd-8878-477f-9eac-a8b21ec5ac26] result = proxy_call...

[Joe Gordon (jogo)]

No hits in logstash (we keep logs for 2 weeks), so marking as resolved.

[Matt Riedemann (mriedem)]

This is still around:

http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOlwibGlidmlydEVycm9yOiBDYW5ub3QgcmVjdiBkYXRhOiBDb25uZWN0aW9uIHJlc2V0IGJ5IHBlZXJcIiBBTkQgdGFnczpcInNjcmVlbi1uLWNwdS50eHRcIiIsImZpZWxkcyI6W10sIm9mZnNldCI6MCwidGltZWZyYW1lIjoiNjA0ODAwIiwiZ3JhcGhtb2RlIjoiY291bnQiLCJ0aW1lIjp7ImZyb20iOiIyMDE1LTA0LTIyVDIzOjA0OjQ3KzAwOjAwIiwidG8iOiIyMDE1LTA1LTA2VDIzOjA0OjQ3KzAwOjAwIiwidXNlcl9pbnRlcnZhbCI6IjAifSwic3RhbXAiOjE0MzA5NTM1NjIyMTR9

[Markus Zoeller (markus_z) (mzoeller)]

This is an automated cleanup. This bug report has been closed because it
is older than 18 months and there is no open code change to fix this.
After this time it is unlikely that the circumstances which lead to
the observed issue can be reproduced.

If you can reproduce the bug, please:
* reopen the bug report (set to status "New")
* AND add the detailed steps to reproduce the issue (if applicable)
* AND leave a comment "CONFIRMED FOR: <RELEASE_NAME>"
  Only still supported release names are valid (LIBERTY, MITAKA, OCATA, NEWTON).
  Valid example: CONFIRMED FOR: LIBERTY