Unauthorized command: kill -9

[Joe Gordon]

 Stderr: '/usr/local/bin/neutron-rootwrap: Unauthorized command: kill -9 30601 (no filter matched)\n'

2013-09-30 17:56:22.682 2684 ERROR neutron.agent.dhcp_agent [-] Unable to disable dhcp.
2013-09-30 17:56:22.682 2684 TRACE neutron.agent.dhcp_agent Traceback (most recent call last):
2013-09-30 17:56:22.682 2684 TRACE neutron.agent.dhcp_agent File "/opt/stack/new/neutron/neutron/agent/dhcp_agent.py", line 126, in call_driver
2013-09-30 17:56:22.682 2684 TRACE neutron.agent.dhcp_agent getattr(driver, action)(**action_kwargs)
2013-09-30 17:56:22.682 2684 TRACE neutron.agent.dhcp_agent File "/opt/stack/new/neutron/neutron/agent/linux/dhcp.py", line 180, in disable
2013-09-30 17:56:22.682 2684 TRACE neutron.agent.dhcp_agent utils.execute(cmd, self.root_helper)
2013-09-30 17:56:22.682 2684 TRACE neutron.agent.dhcp_agent File "/opt/stack/new/neutron/neutron/agent/linux/utils.py", line 61, in execute
2013-09-30 17:56:22.682 2684 TRACE neutron.agent.dhcp_agent raise RuntimeError(m)
2013-09-30 17:56:22.682 2684 TRACE neutron.agent.dhcp_agent RuntimeError:
2013-09-30 17:56:22.682 2684 TRACE neutron.agent.dhcp_agent Command: ['sudo', '/usr/local/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'kill', '-9', '30601']
2013-09-30 17:56:22.682 2684 TRACE neutron.agent.dhcp_agent Exit code: 99
2013-09-30 17:56:22.682 2684 TRACE neutron.agent.dhcp_agent Stdout: ''
2013-09-30 17:56:22.682 2684 TRACE neutron.agent.dhcp_agent Stderr: '/usr/local/bin/neutron-rootwrap: Unauthorized command: kill -9 30601 (no filter matched)\n'
2013-09-30 17:56:22.682 2684 TRACE neutron.agent.dhcp_agent

http://logs.openstack.org/03/47503/16/check/check-tempest-devstack-vm-neutron/0b35b85/logs/screen-q-dhcp.txt.gz?level=TRACE

logstash query: "Unauthorized command: kill -9" shows this has happened about 100 times in past 24 hours and sometimes happens on 'successful' tempest runs.

[Akihiro Motoki (amotoki)]

http://logs.openstack.org/03/47503/16/check/check-tempest-devstack-vm-neutron/0b35b85/logs/screen-q-dhcp.txt.gz?#_2013-09-30_17_56_22_169

"kill -9 30601" is called twice. KillFilter checks a specified PID exists and the process PID 30601 no longer exists when the second call exists. This causes Unauthorized command error.

This seems to be caused by race condition in network delete (RPC call error for the network and network_delete notification).

Anyway dnsmasq process is removed as expected, so it is not critical.

[Akihiro Motoki (amotoki)]

both bug 1234026 and this come from the race condition in disable_dhcp_helper.

The difference is this error is caused from the race condition of refresh_dhcp_helper (from subnet_delete_end)
and disable_delete_helper (from network_delete_end).
Before this error, three notification: port_delete, subnet_delete, and network_delete are received almost at the same time (looks consecutive events).

http://logs.openstack.org/03/47503/16/check/check-tempest-devstack-vm-neutron/0b35b85/logs/screen-q-dhcp.txt.gz?#_2013-09-30_17_56_21_785

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Change abandoned by Sam Betts (<email address hidden>) on branch: master
Review: https://review.openstack.org/113617
Reason: Bugs already fixed by https://review.openstack.org/56785.

[Sam Betts (sambetts)]

Fixed in master by https://review.openstack.org/56785