Mirantis OpenStack

Neutron agents restart with unknown reason

Bug #1405227 reported by Ilya Shakhat on 2014-12-23

This bug affects 1 person

	Status	Importance	Assigned to	Milestone
Mirantis OpenStack	Invalid	High	Ilya Shakhat	Mirantis OpenStack 6.0-updates
6.0.x	Invalid	High	Ilya Shakhat	Mirantis OpenStack 6.0-updates
6.1.x	Invalid	High	Ilya Shakhat	Mirantis OpenStack 6.1

Bug Description

Neutron agents were restarted several times during the day. E.g.:

[root@node-85 ~]# cat /var/log/neutron/openvswitch-agent.log | grep "Logging enabled" | tail
2014-12-22 21:10:59.754 6261 INFO neutron.common.config [-] Logging enabled!
2014-12-22 22:02:33.194 19421 INFO neutron.common.config [-] Logging enabled!
2014-12-22 22:30:55.002 31136 INFO neutron.common.config [-] Logging enabled!
2014-12-23 00:31:00.457 16748 INFO neutron.common.config [-] Logging enabled!
2014-12-23 03:51:00.000 22297 INFO neutron.common.config [-] Logging enabled!
2014-12-23 04:30:59.025 17910 INFO neutron.common.config [-] Logging enabled!
2014-12-23 08:51:08.241 11698 INFO neutron.common.config [-] Logging enabled!
2014-12-23 09:41:05.374 22035 INFO neutron.common.config [-] Logging enabled!
2014-12-23 10:21:05.733 15980 INFO neutron.common.config [-] Logging enabled!
2014-12-23 14:02:10.021 14841 INFO neutron.common.config [-] Logging enabled!

[root@node-85 ~]# cat /var/log/neutron/metadata-agent.log | grep "Logging enabled"
2014-12-21 13:03:06.509 13866 INFO neutron.common.config [-] Logging enabled!
2014-12-22 22:01:53.949 18405 INFO neutron.common.config [-] Logging enabled!
2014-12-23 08:40:59.309 29049 INFO neutron.common.config [-] Logging enabled!

[root@node-85 ~]# cat /var/log/neutron/l3-agent.log | grep "Logging enabled" | grep -v metadata | tail
2014-12-23 05:19:38.666 26401 INFO neutron.common.config [-] Logging enabled!
2014-12-23 05:25:03.271 3183 INFO neutron.common.config [-] Logging enabled!
2014-12-23 06:41:07.230 16165 INFO neutron.common.config [-] Logging enabled!
2014-12-23 07:41:11.925 6591 INFO neutron.common.config [-] Logging enabled!
2014-12-23 08:41:13.299 29540 INFO neutron.common.config [-] Logging enabled!
2014-12-23 08:51:10.035 11821 INFO neutron.common.config [-] Logging enabled!
2014-12-23 09:41:07.168 22158 INFO neutron.common.config [-] Logging enabled!
2014-12-23 10:21:07.981 16257 INFO neutron.common.config [-] Logging enabled!
2014-12-23 13:31:08.157 1749 INFO neutron.common.config [-] Logging enabled!
2014-12-23 14:02:11.803 14963 INFO neutron.common.config [-] Logging enabled!

Tags:

Revision history for this message

Ilya Shakhat (shakhat) wrote on 2014-12-23:

VERSION:
  feature_groups:
    - mirantis
  production: "docker"
  release: "6.0"
  api: "1.0"
  build_number: "56"
  build_id: "2014-12-18_01-32-01"
  astute_sha: "16b252d93be6aaa73030b8100cf8c5ca6a970a91"
  fuellib_sha: "73332192a257ea02c40a39885c502ad1ebdf3eda"
  ostf_sha: "a9afb68710d809570460c29d6c3293219d3624d4"
  nailgun_sha: "5f91157daa6798ff522ca9f6d34e7e135f150a90"
  fuelmain_sha: "45caacadb878abfbd9d60e134d72229698b469c9"

DEPLOYMENT:
CentOS + HA + Full

Revision history for this message

Ilya Shakhat (shakhat) wrote on 2014-12-23:

Download full text (6.8 KiB)

The latest issue in ovs agent:
2014-12-23 14:02:07.661 15980 DEBUG neutron.plugins.openvswitch.agent.ovs_neutron_agent [req-cf189383-3a01-4e10-9586-ef74c550b0e1 None] Loop iteration e
xceeded interval (2 vs. 19.6092391014)! rpc_loop /usr/lib/python2.6/site-packages/neutron/plugins/openvswitch/agent/ovs_neutron_agent.py:1463
2014-12-23 14:02:07.661 15980 DEBUG neutron.agent.linux.async_process [req-cf189383-3a01-4e10-9586-ef74c550b0e1 None] Halting async process [['ovsdb-cli
ent', 'monitor', 'Interface', 'name,ofport', '--format=json']]. stop /usr/lib/python2.6/site-packages/neutron/agent/linux/async_process.py:88
2014-12-23 14:02:07.662 15980 DEBUG neutron.agent.linux.utils [req-cf189383-3a01-4e10-9586-ef74c550b0e1 None] Running command: ['ps', '--ppid', '16431',
'-o', 'pid='] create_process /usr/lib/python2.6/site-packages/neutron/agent/linux/utils.py:46
2014-12-23 14:02:07.714 15980 DEBUG neutron.agent.linux.utils [req-cf189383-3a01-4e10-9586-ef74c550b0e1 None]
Command: ['ps', '--ppid', '16431', '-o', 'pid=']
Exit code: 0
Stdout: '16433\n'
Stderr: '' execute /usr/lib/python2.6/site-packages/neutron/agent/linux/utils.py:81
2014-12-23 14:02:07.715 15980 DEBUG neutron.agent.linux.utils [req-cf189383-3a01-4e10-9586-ef74c550b0e1 None] Running command: ['ps', '--ppid', '16433',
'-o', 'pid='] create_process /usr/lib/python2.6/site-packages/neutron/agent/linux/utils.py:46
2014-12-23 14:02:07.766 15980 DEBUG neutron.agent.linux.utils [req-cf189383-3a01-4e10-9586-ef74c550b0e1 None]
Command: ['ps', '--ppid', '16433', '-o', 'pid=']
Exit code: 0
Stdout: '16435\n'
Stderr: '' execute /usr/lib/python2.6/site-packages/neutron/agent/linux/utils.py:81
2014-12-23 14:02:07.767 15980 DEBUG neutron.agent.linux.utils [req-cf189383-3a01-4e10-9586-ef74c550b0e1 None] Running command: ['ps', '--ppid', '16435',
'-o', 'pid='] create_process /usr/lib/python2.6/site-packages/neutron/agent/linux/utils.py:46
2014-12-23 14:02:07.815 15980 ERROR neutron.agent.linux.utils [req-cf189383-3a01-4e10-9586-ef74c550b0e1 None]
Command: ['ps', '--ppid', '16435', '-o', 'pid=']
Exit code: 1
Stdout: ''
Stderr: ''
2014-12-23 14:02:07.816 15980 DEBUG neutron.agent.linux.utils [req-cf189383-3a01-4e10-9586-ef74c550b0e1 None] Running command: ['sudo', 'neutron-rootwra
p', '/etc/neutron/rootwrap.conf', 'kill', '-9', '16435'] create_process /usr/lib/python2.6/site-packages/neutron/agent/linux/utils.py:46
2014-12-23 14:02:07.932 15980 DEBUG neutron.agent.linux.utils [req-cf189383-3a01-4e10-9586-ef74c550b0e1 None]
Command: ['sudo', 'neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'kill', '-9', '16435']
Exit code: 0
Stdout: ''
Stderr: '' execute /usr/lib/python2.6/site-packages/neutron/agent/linux/utils.py:81
2014-12-23 14:02:10.021 14841 INFO neutron.common.config [-] Logging enabled!
2014-12-23 14:02:10.022 14841 DEBUG neutron.plugins.openvswitch.agent.ovs_neutron_agent [-] ************************************************************
******************** log_opt_values /usr/lib/python2.6/site-packages/oslo/config/cfg.py:1979

l3-agent:
2014-12-23 14:01:42.416 1749 INFO neutron.openstack.common.service [req-f0f0760f-f517-46fe-9ba7-ef121298d875 None] Caught SIGTERM, exiting
2014-12-23 14:0...

The latest issue in ovs agent:
2014-12-23 14:02:07.661 15980 DEBUG neutron.plugins.openvswitch.agent.ovs_neutron_agent [req-cf189383-3a01-4e10-9586-ef74c550b0e1 None] Loop iteration e
xceeded interval (2 vs. 19.6092391014)! rpc_loop /usr/lib/python2.6/site-packages/neutron/plugins/openvswitch/agent/ovs_neutron_agent.py:1463
2014-12-23 14:02:07.661 15980 DEBUG neutron.agent.linux.async_process [req-cf189383-3a01-4e10-9586-ef74c550b0e1 None] Halting async process [['ovsdb-cli
ent', 'monitor', 'Interface', 'name,ofport', '--format=json']]. stop /usr/lib/python2.6/site-packages/neutron/agent/linux/async_process.py:88
2014-12-23 14:02:07.662 15980 DEBUG neutron.agent.linux.utils [req-cf189383-3a01-4e10-9586-ef74c550b0e1 None] Running command: ['ps', '--ppid', '16431',
 '-o', 'pid='] create_process /usr/lib/python2.6/site-packages/neutron/agent/linux/utils.py:46
2014-12-23 14:02:07.714 15980 DEBUG neutron.agent.linux.utils [req-cf189383-3a01-4e10-9586-ef74c550b0e1 None] 
Command: ['ps', '--ppid', '16431', '-o', 'pid=']
Exit code: 0
Stdout: '16433\n'
Stderr: '' execute /usr/lib/python2.6/site-packages/neutron/agent/linux/utils.py:81
2014-12-23 14:02:07.715 15980 DEBUG neutron.agent.linux.utils [req-cf189383-3a01-4e10-9586-ef74c550b0e1 None] Running command: ['ps', '--ppid', '16433',
 '-o', 'pid='] create_process /usr/lib/python2.6/site-packages/neutron/agent/linux/utils.py:46
2014-12-23 14:02:07.766 15980 DEBUG neutron.agent.linux.utils [req-cf189383-3a01-4e10-9586-ef74c550b0e1 None] 
Command: ['ps', '--ppid', '16433', '-o', 'pid=']
Exit code: 0
Stdout: '16435\n'
Stderr: '' execute /usr/lib/python2.6/site-packages/neutron/agent/linux/utils.py:81
2014-12-23 14:02:07.767 15980 DEBUG neutron.agent.linux.utils [req-cf189383-3a01-4e10-9586-ef74c550b0e1 None] Running command: ['ps', '--ppid', '16435',
 '-o', 'pid='] create_process /usr/lib/python2.6/site-packages/neutron/agent/linux/utils.py:46
2014-12-23 14:02:07.815 15980 ERROR neutron.agent.linux.utils [req-cf189383-3a01-4e10-9586-ef74c550b0e1 None] 
Command: ['ps', '--ppid', '16435', '-o', 'pid=']
Exit code: 1
Stdout: ''
Stderr: ''
2014-12-23 14:02:07.816 15980 DEBUG neutron.agent.linux.utils [req-cf189383-3a01-4e10-9586-ef74c550b0e1 None] Running command: ['sudo', 'neutron-rootwra
p', '/etc/neutron/rootwrap.conf', 'kill', '-9', '16435'] create_process /usr/lib/python2.6/site-packages/neutron/agent/linux/utils.py:46
2014-12-23 14:02:07.932 15980 DEBUG neutron.agent.linux.utils [req-cf189383-3a01-4e10-9586-ef74c550b0e1 None] 
Command: ['sudo', 'neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'kill', '-9', '16435']
Exit code: 0
Stdout: ''
Stderr: '' execute /usr/lib/python2.6/site-packages/neutron/agent/linux/utils.py:81
2014-12-23 14:02:10.021 14841 INFO neutron.common.config [-] Logging enabled!
2014-12-23 14:02:10.022 14841 DEBUG neutron.plugins.openvswitch.agent.ovs_neutron_agent [-] ************************************************************
******************** log_opt_values /usr/lib/python2.6/site-packages/oslo/config/cfg.py:1979

l3-agent:
2014-12-23 14:01:42.416 1749 INFO neutron.openstack.common.service [req-f0f0760f-f517-46fe-9ba7-ef121298d875 None] Caught SIGTERM, exiting
2014-12-23 14:02:11.803 14963 INFO neutron.common.config [-] Logging enabled!

pacemaker.log
<29>Dec 23 14:01:50 node-85 lrmd[26806]:   notice: operation_finished: p_neutron-l3-agent_stop_0:13684:stderr [ /usr/lib/python2.6/site-packages/keyston
eclient/apiclient/__init__.py:27: DeprecationWarning: The 'keystoneclient.apiclient' module is deprecated since v.0.7.1. Use 'keystoneclient.exceptions' instead of this module. ]
<29>Dec 23 14:01:50 node-85 lrmd[26806]:   notice: operation_finished: p_neutron-l3-agent_stop_0:13684:stderr [   "module.", DeprecationWarning) ]
<29>Dec 23 14:01:50 node-85 lrmd[26806]:   notice: operation_finished: p_neutron-l3-agent_stop_0:13684:stderr [ /usr/lib/python2.6/site-packages/keystoneclient/apiclient/exceptions.py:33: DeprecationWarning: The 'keystoneclient.apiclient.exceptions' module is deprecated since v.0.7.1. Use 'keystoneclient.exceptions' instead of this module. ]
<29>Dec 23 14:01:50 node-85 lrmd[26806]:   notice: operation_finished: p_neutron-l3-agent_stop_0:13684:stderr [   "module.", DeprecationWarning) ]
<29>Dec 23 14:01:50 node-85 crmd[26809]:   notice: process_lrm_event: LRM operation p_neutron-l3-agent_stop_0 (call=4528, rc=0, cib-update=1559, confirmed=true) ok
<29>Dec 23 14:02:08 node-85 crmd[26809]:   notice: process_lrm_event: LRM operation p_neutron-openvswitch-agent_stop_0 (call=4544, rc=0, cib-update=1560, confirmed=true) ok
<29>Dec 23 14:02:09 node-85 lrmd[26806]:   notice: operation_finished: p_neutron-openvswitch-agent_start_0:14815:stderr [ sh: $OCF_RESKEY_pid: ambiguous redirect ]
<29>Dec 23 14:02:09 node-85 lrmd[26806]:   notice: operation_finished: p_neutron-openvswitch-agent_start_0:14815:stderr [ cat: /var/run/resource-agents/neutron-agent-ovs/neutron-agent-ovs.pid: No such file or directory ]
<29>Dec 23 14:02:09 node-85 crmd[26809]:   notice: process_lrm_event: LRM operation p_neutron-openvswitch-agent_start_0 (call=4548, rc=0, cib-update=1561, confirmed=true) ok
<29>Dec 23 14:02:09 node-85 crmd[26809]:   notice: process_lrm_event: LRM operation p_neutron-openvswitch-agent_monitor_20000 (call=4551, rc=0, cib-update=1562, confirmed=false) ok
<29>Dec 23 14:02:10 node-85 lrmd[26806]:   notice: operation_finished: p_neutron-l3-agent_start_0:14866:stderr [ /usr/lib/python2.6/site-packages/keystoneclient/apiclient/__init__.py:27: DeprecationWarning: The 'keystoneclient.apiclient' module is deprecated since v.0.7.1. Use 'keystoneclient.exceptions' instead of this module. ]
<29>Dec 23 14:02:10 node-85 lrmd[26806]:   notice: operation_finished: p_neutron-l3-agent_start_0:14866:stderr [   "module.", DeprecationWarning) ]
<29>Dec 23 14:02:10 node-85 lrmd[26806]:   notice: operation_finished: p_neutron-l3-agent_start_0:14866:stderr [ /usr/lib/python2.6/site-packages/keystoneclient/apiclient/exceptions.py:33: DeprecationWarning: The 'keystoneclient.apiclient.exceptions' module is deprecated since v.0.7.1. Use 'keystoneclient.exceptions' instead of this module. ]
<29>Dec 23 14:02:10 node-85 lrmd[26806]:   notice: operation_finished: p_neutron-l3-agent_start_0:14866:stderr [   "module.", DeprecationWarning) ]
<29>Dec 23 14:02:10 node-85 lrmd[26806]:   notice: operation_finished: p_neutron-l3-agent_start_0:14866:stderr [ sh: $OCF_RESKEY_pid: ambiguous redirect ]
<29>Dec 23 14:02:10 node-85 lrmd[26806]:   notice: operation_finished: p_neutron-l3-agent_start_0:14866:stderr [ cat: /var/run/resource-agents/neutron-agent-l3/neutron-agent-l3.pid: No such file or directory ]
<29>Dec 23 14:02:10 node-85 crmd[26809]:   notice: process_lrm_event: LRM operation p_neutron-l3-agent_start_0 (call=4553, rc=0, cib-update=1563, confirmed=true) ok
<29>Dec 23 14:02:10 node-85 crmd[26809]:   notice: process_lrm_event: LRM operation p_neutron-l3-agent_monitor_20000 (call=4557, rc=0, cib-update=1564, confirmed=false) ok

Ilya Shakhat (shakhat) on 2014-12-23

tags:	added: neutron
Changed in mos:
assignee:	nobody → MOS Neutron (mos-neutron)

Alexander Ignatov (aignatov) on 2014-12-24

Changed in mos:
status:	New → Confirmed
importance:	Undecided → High
milestone:	none → 6.1

Revision history for this message

Eugene Nikanorov (enikanorov) wrote on 2014-12-25:

I think the first step should be to improve logging of monitoring OCF scripts that should log reasons for agent restart.

Revision history for this message

Ilya Shakhat (shakhat) wrote on 2015-02-18:

Unable to reproduce. The issue is not observed in scale logs

Report a bug

This report contains Public information

Everyone can see this information.

You are

Subscribing...

Edit bug mail

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.