1. 2012-08-09 10:56:13 DEBUG nova.rpc.amqp [-] received {u'_context_roles': [u'admin'], u'_msg_id': u'9a11c8cd012d4b09b91ce4855e97c919', u'_context_read_deleted': u'no', u'_context_request_id': u'req-90c724c0-203d-4cb2-aff1-266eb346365e', u'_context_auth_token': '<SANITIZED>', u'_context_is_admin': True, u'_context_project_id': u'f33437d869eb4c7783a62fdb070a0865', u'_context_timestamp': u'2012-08-09T14:56:13.000974', u'_context_user_id': u'9663883e2d7b485eb1a4e8746ef62b8e', u'method': u'get_floating_ips_by_project', u'_context_remote_address': u'10.173.16.1'} from (pid=20411) _safe_log /usr/lib/python2.6/site-packages/nova/rpc/common.py:160
  2. 2012-08-09 10:56:13 DEBUG nova.rpc.amqp [req-90c724c0-203d-4cb2-aff1-266eb346365e 9663883e2d7b485eb1a4e8746ef62b8e f33437d869eb4c7783a62fdb070a0865] unpacked context: {'user_id': u'9663883e2d7b485eb1a4e8746ef62b8e', 'roles': [u'admin'], 'timestamp': '2012-08-09T14:56:13.000974', 'auth_token': '<SANITIZED>', 'remote_address': u'10.173.16.1', 'is_admin': True, 'request_id': u'req-90c724c0-203d-4cb2-aff1-266eb346365e', 'project_id': u'f33437d869eb4c7783a62fdb070a0865', 'read_deleted': u'no'} from (pid=20411) _safe_log /usr/lib/python2.6/site-packages/nova/rpc/common.py:160
  3. 2012-08-09 10:56:21 DEBUG nova.rpc.amqp [-] received {u'_context_roles': [u'admin'], u'_msg_id': u'40e95a7e79c346af945b3f73ddb00b05', u'_context_read_deleted': u'no', u'_context_request_id': u'req-668aa908-ce59-4b80-b1b3-5c5090a78996', u'args': {u'instance_uuid': u'c9246cc1-7058-4927-b76b-06416b3c96b8', u'vpn': False, u'requested_networks': None, u'instance_id': 3, u'host': u'cloud016001', u'rxtx_factor': 1.0, u'project_id': u'f33437d869eb4c7783a62fdb070a0865'}, u'_context_auth_token': '<SANITIZED>', u'_context_is_admin': True, u'_context_project_id': u'f33437d869eb4c7783a62fdb070a0865', u'_context_timestamp': u'2012-08-09T14:56:20.214294', u'_context_user_id': u'9663883e2d7b485eb1a4e8746ef62b8e', u'method': u'allocate_for_instance', u'_context_remote_address': u'10.173.16.1'} from (pid=20411) _safe_log /usr/lib/python2.6/site-packages/nova/rpc/common.py:160
  4. 2012-08-09 10:56:21 DEBUG nova.rpc.amqp [req-668aa908-ce59-4b80-b1b3-5c5090a78996 9663883e2d7b485eb1a4e8746ef62b8e f33437d869eb4c7783a62fdb070a0865] unpacked context: {'user_id': u'9663883e2d7b485eb1a4e8746ef62b8e', 'roles': [u'admin'], 'timestamp': '2012-08-09T14:56:20.214294', 'auth_token': '<SANITIZED>', 'remote_address': u'10.173.16.1', 'is_admin': True, 'request_id': u'req-668aa908-ce59-4b80-b1b3-5c5090a78996', 'project_id': u'f33437d869eb4c7783a62fdb070a0865', 'read_deleted': u'no'} from (pid=20411) _safe_log /usr/lib/python2.6/site-packages/nova/rpc/common.py:160
  5. 2012-08-09 10:56:21 DEBUG nova.network.manager [req-668aa908-ce59-4b80-b1b3-5c5090a78996 9663883e2d7b485eb1a4e8746ef62b8e f33437d869eb4c7783a62fdb070a0865] floating IP allocation for instance |3| from (pid=20411) allocate_for_instance /usr/lib/python2.6/site-packages/nova/network/manager.py:315
  6. 2012-08-09 10:56:21 DEBUG nova.network.manager [req-668aa908-ce59-4b80-b1b3-5c5090a78996 9663883e2d7b485eb1a4e8746ef62b8e f33437d869eb4c7783a62fdb070a0865] network allocations for instance |3| from (pid=20411) allocate_for_instance /usr/lib/python2.6/site-packages/nova/network/manager.py:896
  7. 2012-08-09 10:56:21 DEBUG nova.network.manager [req-668aa908-ce59-4b80-b1b3-5c5090a78996 9663883e2d7b485eb1a4e8746ef62b8e f33437d869eb4c7783a62fdb070a0865] networks retrieved for instance |3|: |[<nova.db.sqlalchemy.models.Network object at 0x3a4e450>]| from (pid=20411) allocate_for_instance /usr/lib/python2.6/site-packages/nova/network/manager.py:902
  8. 2012-08-09 10:56:21 DEBUG nova.utils [req-668aa908-ce59-4b80-b1b3-5c5090a78996 9663883e2d7b485eb1a4e8746ef62b8e f33437d869eb4c7783a62fdb070a0865] Attempting to grab semaphore "get_dhcp" for method "_get_dhcp_ip"... from (pid=20411) inner /usr/lib/python2.6/site-packages/nova/utils.py:928
  9. 2012-08-09 10:56:21 DEBUG nova.utils [req-668aa908-ce59-4b80-b1b3-5c5090a78996 9663883e2d7b485eb1a4e8746ef62b8e f33437d869eb4c7783a62fdb070a0865] Got semaphore "get_dhcp" for method "_get_dhcp_ip"... from (pid=20411) inner /usr/lib/python2.6/site-packages/nova/utils.py:932
  10. 2012-08-09 10:56:21 DEBUG nova.utils [req-668aa908-ce59-4b80-b1b3-5c5090a78996 9663883e2d7b485eb1a4e8746ef62b8e f33437d869eb4c7783a62fdb070a0865] Attempting to grab semaphore "ensure_bridge" for method "ensure_bridge"... from (pid=20411) inner /usr/lib/python2.6/site-packages/nova/utils.py:928
  11. 2012-08-09 10:56:21 DEBUG nova.utils [req-668aa908-ce59-4b80-b1b3-5c5090a78996 9663883e2d7b485eb1a4e8746ef62b8e f33437d869eb4c7783a62fdb070a0865] Got semaphore "ensure_bridge" for method "ensure_bridge"... from (pid=20411) inner /usr/lib/python2.6/site-packages/nova/utils.py:932
  12. 2012-08-09 10:56:21 DEBUG nova.utils [req-668aa908-ce59-4b80-b1b3-5c5090a78996 9663883e2d7b485eb1a4e8746ef62b8e f33437d869eb4c7783a62fdb070a0865] Attempting to grab file lock "ensure_bridge" for method "ensure_bridge"... from (pid=20411) inner /usr/lib/python2.6/site-packages/nova/utils.py:936
  13. 2012-08-09 10:56:21 DEBUG nova.utils [req-668aa908-ce59-4b80-b1b3-5c5090a78996 9663883e2d7b485eb1a4e8746ef62b8e f33437d869eb4c7783a62fdb070a0865] Got file lock "ensure_bridge" for method "ensure_bridge"... from (pid=20411) inner /usr/lib/python2.6/site-packages/nova/utils.py:943
  14. 2012-08-09 10:56:21 DEBUG nova.utils [req-668aa908-ce59-4b80-b1b3-5c5090a78996 9663883e2d7b485eb1a4e8746ef62b8e f33437d869eb4c7783a62fdb070a0865] Running cmd (subprocess): ip link show dev br16 from (pid=20411) execute /usr/lib/python2.6/site-packages/nova/utils.py:220
  15. 2012-08-09 10:56:21 DEBUG nova.utils [req-668aa908-ce59-4b80-b1b3-5c5090a78996 9663883e2d7b485eb1a4e8746ef62b8e f33437d869eb4c7783a62fdb070a0865] Running cmd (subprocess): sudo nova-rootwrap brctl addif br16 br16 from (pid=20411) execute /usr/lib/python2.6/site-packages/nova/utils.py:220
  16. 2012-08-09 10:56:21 DEBUG nova.utils [req-668aa908-ce59-4b80-b1b3-5c5090a78996 9663883e2d7b485eb1a4e8746ef62b8e f33437d869eb4c7783a62fdb070a0865] Result was 1 from (pid=20411) execute /usr/lib/python2.6/site-packages/nova/utils.py:236
  17. 2012-08-09 10:56:21 DEBUG nova.utils [req-668aa908-ce59-4b80-b1b3-5c5090a78996 9663883e2d7b485eb1a4e8746ef62b8e f33437d869eb4c7783a62fdb070a0865] Running cmd (subprocess): sudo nova-rootwrap route -n from (pid=20411) execute /usr/lib/python2.6/site-packages/nova/utils.py:220
  18. 2012-08-09 10:56:21 DEBUG nova.utils [req-668aa908-ce59-4b80-b1b3-5c5090a78996 9663883e2d7b485eb1a4e8746ef62b8e f33437d869eb4c7783a62fdb070a0865] Running cmd (subprocess): sudo nova-rootwrap ip addr show dev br16 scope global from (pid=20411) execute /usr/lib/python2.6/site-packages/nova/utils.py:220
  19. 2012-08-09 10:56:21 DEBUG nova.utils [req-668aa908-ce59-4b80-b1b3-5c5090a78996 9663883e2d7b485eb1a4e8746ef62b8e f33437d869eb4c7783a62fdb070a0865] Running cmd (subprocess): sudo nova-rootwrap ip addr del 192.168.16.3/24 brd 192.168.16.255 scope global dev br16 from (pid=20411) execute /usr/lib/python2.6/site-packages/nova/utils.py:220
  20. 2012-08-09 10:56:21 DEBUG nova.utils [req-668aa908-ce59-4b80-b1b3-5c5090a78996 9663883e2d7b485eb1a4e8746ef62b8e f33437d869eb4c7783a62fdb070a0865] Running cmd (subprocess): sudo nova-rootwrap ip addr add 192.168.16.3/24 brd 192.168.16.255 scope global dev br16 from (pid=20411) execute /usr/lib/python2.6/site-packages/nova/utils.py:220
  21. 2012-08-09 10:56:21 DEBUG nova.utils [req-668aa908-ce59-4b80-b1b3-5c5090a78996 9663883e2d7b485eb1a4e8746ef62b8e f33437d869eb4c7783a62fdb070a0865] Attempting to grab semaphore "iptables" for method "apply"... from (pid=20411) inner /usr/lib/python2.6/site-packages/nova/utils.py:928
  22. 2012-08-09 10:56:21 DEBUG nova.utils [req-668aa908-ce59-4b80-b1b3-5c5090a78996 9663883e2d7b485eb1a4e8746ef62b8e f33437d869eb4c7783a62fdb070a0865] Got semaphore "iptables" for method "apply"... from (pid=20411) inner /usr/lib/python2.6/site-packages/nova/utils.py:932
  23. 2012-08-09 10:56:21 DEBUG nova.utils [req-668aa908-ce59-4b80-b1b3-5c5090a78996 9663883e2d7b485eb1a4e8746ef62b8e f33437d869eb4c7783a62fdb070a0865] Attempting to grab file lock "iptables" for method "apply"... from (pid=20411) inner /usr/lib/python2.6/site-packages/nova/utils.py:936
  24. 2012-08-09 10:56:21 DEBUG nova.utils [req-668aa908-ce59-4b80-b1b3-5c5090a78996 9663883e2d7b485eb1a4e8746ef62b8e f33437d869eb4c7783a62fdb070a0865] Got file lock "iptables" for method "apply"... from (pid=20411) inner /usr/lib/python2.6/site-packages/nova/utils.py:943
  25. 2012-08-09 10:56:21 DEBUG nova.utils [req-668aa908-ce59-4b80-b1b3-5c5090a78996 9663883e2d7b485eb1a4e8746ef62b8e f33437d869eb4c7783a62fdb070a0865] Running cmd (subprocess): sudo nova-rootwrap iptables-save -t filter from (pid=20411) execute /usr/lib/python2.6/site-packages/nova/utils.py:220
  26. 2012-08-09 10:56:22 DEBUG nova.utils [req-668aa908-ce59-4b80-b1b3-5c5090a78996 9663883e2d7b485eb1a4e8746ef62b8e f33437d869eb4c7783a62fdb070a0865] Running cmd (subprocess): sudo nova-rootwrap iptables-restore from (pid=20411) execute /usr/lib/python2.6/site-packages/nova/utils.py:220
  27. 2012-08-09 10:56:22 DEBUG nova.utils [req-668aa908-ce59-4b80-b1b3-5c5090a78996 9663883e2d7b485eb1a4e8746ef62b8e f33437d869eb4c7783a62fdb070a0865] Running cmd (subprocess): sudo nova-rootwrap iptables-save -t nat from (pid=20411) execute /usr/lib/python2.6/site-packages/nova/utils.py:220
  28. 2012-08-09 10:56:22 DEBUG nova.utils [req-668aa908-ce59-4b80-b1b3-5c5090a78996 9663883e2d7b485eb1a4e8746ef62b8e f33437d869eb4c7783a62fdb070a0865] Running cmd (subprocess): sudo nova-rootwrap iptables-restore from (pid=20411) execute /usr/lib/python2.6/site-packages/nova/utils.py:220
  29. 2012-08-09 10:56:22 DEBUG nova.network.linux_net [req-668aa908-ce59-4b80-b1b3-5c5090a78996 9663883e2d7b485eb1a4e8746ef62b8e f33437d869eb4c7783a62fdb070a0865] IPTablesManager.apply completed with success from (pid=20411) apply /usr/lib/python2.6/site-packages/nova/network/linux_net.py:335
  30. 2012-08-09 10:56:22 DEBUG nova.utils [req-668aa908-ce59-4b80-b1b3-5c5090a78996 9663883e2d7b485eb1a4e8746ef62b8e f33437d869eb4c7783a62fdb070a0865] Running cmd (subprocess): sudo nova-rootwrap ip addr show dev br16 scope global from (pid=20411) execute /usr/lib/python2.6/site-packages/nova/utils.py:220
  31. 2012-08-09 10:56:22 DEBUG nova.utils [req-668aa908-ce59-4b80-b1b3-5c5090a78996 9663883e2d7b485eb1a4e8746ef62b8e f33437d869eb4c7783a62fdb070a0865] Attempting to grab semaphore "dnsmasq_start" for method "restart_dhcp"... from (pid=20411) inner /usr/lib/python2.6/site-packages/nova/utils.py:928
  32. 2012-08-09 10:56:22 DEBUG nova.utils [req-668aa908-ce59-4b80-b1b3-5c5090a78996 9663883e2d7b485eb1a4e8746ef62b8e f33437d869eb4c7783a62fdb070a0865] Got semaphore "dnsmasq_start" for method "restart_dhcp"... from (pid=20411) inner /usr/lib/python2.6/site-packages/nova/utils.py:932
  33. 2012-08-09 10:56:22 DEBUG nova.utils [req-668aa908-ce59-4b80-b1b3-5c5090a78996 9663883e2d7b485eb1a4e8746ef62b8e f33437d869eb4c7783a62fdb070a0865] Running cmd (subprocess): cat /proc/17628/cmdline from (pid=20411) execute /usr/lib/python2.6/site-packages/nova/utils.py:220
  34. 2012-08-09 10:56:22 DEBUG nova.utils [req-668aa908-ce59-4b80-b1b3-5c5090a78996 9663883e2d7b485eb1a4e8746ef62b8e f33437d869eb4c7783a62fdb070a0865] Running cmd (subprocess): sudo nova-rootwrap kill -HUP 17628 from (pid=20411) execute /usr/lib/python2.6/site-packages/nova/utils.py:220
  35. 2012-08-09 10:56:22 DEBUG nova.utils [req-668aa908-ce59-4b80-b1b3-5c5090a78996 9663883e2d7b485eb1a4e8746ef62b8e f33437d869eb4c7783a62fdb070a0865] Attempting to grab semaphore "get_dhcp" for method "_get_dhcp_ip"... from (pid=20411) inner /usr/lib/python2.6/site-packages/nova/utils.py:928
  36. 2012-08-09 10:56:22 DEBUG nova.utils [req-668aa908-ce59-4b80-b1b3-5c5090a78996 9663883e2d7b485eb1a4e8746ef62b8e f33437d869eb4c7783a62fdb070a0865] Got semaphore "get_dhcp" for method "_get_dhcp_ip"... from (pid=20411) inner /usr/lib/python2.6/site-packages/nova/utils.py:932
  37. 2012-08-09 10:56:22 DEBUG nova.utils [req-668aa908-ce59-4b80-b1b3-5c5090a78996 9663883e2d7b485eb1a4e8746ef62b8e f33437d869eb4c7783a62fdb070a0865] Attempting to grab semaphore "get_dhcp" for method "_get_dhcp_ip"... from (pid=20411) inner /usr/lib/python2.6/site-packages/nova/utils.py:928
  38. 2012-08-09 10:56:22 DEBUG nova.utils [req-668aa908-ce59-4b80-b1b3-5c5090a78996 9663883e2d7b485eb1a4e8746ef62b8e f33437d869eb4c7783a62fdb070a0865] Got semaphore "get_dhcp" for method "_get_dhcp_ip"... from (pid=20411) inner /usr/lib/python2.6/site-packages/nova/utils.py:932