Ironic does not honor the intervals passed to the @periodic decorators

[Haomeng,Wang]

I changed default value of conductor.sync_power_state_interval from 60 to30 seconds, restart conductor service, however, according to the log, it indicated the conductor.sync_power_state_interval option is changed to 30, however, the period of _sync_power_states still be called every 60 seconds, so this should be a bug, which period is set by below codes, think this is called before the ironic.conf options are loaded, so default value 60 is used for ever.

@periodics.periodic(spacing=CONF.conductor.sync_power_state_interval)

[Haomeng,Wang (whaom)]

ubuntu@ironic-clone-dev:~$ ironic-conductor
2016-03-26 06:54:54.186 DEBUG ironic.cmd.conductor [-] Configuration: from (pid=20501) main /opt/stack/ironic/ironic/cmd/conductor.py:43
2016-03-26 06:54:54.187 DEBUG ironic.cmd.conductor [-] ******************************************************************************** from (pid=20501) log_opt_values /usr/local/lib/python2.7/dist-packages/oslo_config/cfg.py:2503
2016-03-26 06:54:54.187 DEBUG ironic.cmd.conductor [-] Configuration options gathered from: from (pid=20501) log_opt_values /usr/local/lib/python2.7/dist-packages/oslo_config/cfg.py:2504
2016-03-26 06:54:54.188 DEBUG ironic.cmd.conductor [-] command line args: [] from (pid=20501) log_opt_values /usr/local/lib/python2.7/dist-packages/oslo_config/cfg.py:2505
2016-03-26 06:54:54.188 DEBUG ironic.cmd.conductor [-] config files: ['/etc/ironic/ironic.conf'] from (pid=20501) log_opt_values /usr/local/lib/python2.7/dist-packages/oslo_config/cfg.py:2507
2016-03-26 06:54:54.188 DEBUG ironic.cmd.conductor [-] ================================================================================ from (pid=20501) log_opt_values /usr/local/lib/python2.7/dist-packages/oslo_config/cfg.py:2508
2016-03-26 06:54:54.189 DEBUG ironic.cmd.conductor [-] auth_strategy = keystone from (pid=20501) log_opt_values /usr/local/lib/python2.7/dist-packages/oslo_config/cfg.py:2517
2016-03-26 06:54:54.189 DEBUG ironic.cmd.conductor [-] bindir = /opt/stack/ironic/ironic/bin from (pid=20501) log_opt_values /usr/local/lib/python2.7/dist-packages/oslo_config/cfg.py:2517
2016-03-26 06:54:54.190 DEBUG ironic.cmd.conductor [-] config_dir = None from (pid=20501) log_opt_values /usr/local/lib/python2.7/dist-packages/oslo_config/cfg.py:2517
2016-03-26 06:54:54.190 DEBUG ironic.cmd.conductor [-] config_file = ['/etc/ironic/ironic.conf'] from (pid=20501) log_opt_values /usr/local/lib/python2.7/dist-packages/oslo_config/cfg.py:2517
2016-03-26 06:54:54.190 DEBUG ironic.cmd.conductor [-] control_exchange = ironic from (pid=20501) log_opt_values /usr/local/lib/python2.7/dist-packages/oslo_config/cfg.py:2517
2016-03-26 06:54:54.191 DEBUG ironic.cmd.conductor [-] debug = True from (pid=20501) log_opt_values /usr/local/lib/python2.7/dist-packages/oslo_config/cfg.py:2517
2016-03-26 06:54:54.191 DEBUG ironic.cmd.conductor [-] debug_tracebacks_in_api = False from (pid=20501) log_opt_values /usr/local/lib/python2.7/dist-packages/oslo_config/cfg.py:2517
2016-03-26 06:54:54.191 DEBUG ironic.cmd.conductor [-] default_log_levels = ['amqp=WARNING', 'amqplib=WARNING', 'qpid.messaging=INFO', 'oslo_messaging=INFO', 'sqlalchemy=WARNING', 'keystoneclient=INFO', 'stevedore=INFO', 'eventlet.wsgi.server=WARNING', 'iso8601=WARNING', 'paramiko=WARNING', 'requests=WARNING', 'neutronclient=WARNING', 'glanceclient=WARNING', 'urllib3.connectionpool=WARNING'] from (pid=20501) log_opt_values /usr/local/lib/python2.7/dist-packages/oslo_config/cfg.py:2517
2016-03-26 06:54:54.192 DEBUG ironic.cmd.conductor [-] enabled_drivers = ['fake', 'agent_ssh', 'agent_ipmitool', 'pxe_s...

[Haomeng,Wang (whaom)]

Finding - @periodics.periodic code is called before the ironic.conf is loaded, so only default values are set, and if we change the default value in ironic.conf, not working, still run with default option value for these periodic tasks.

[Haomeng,Wang (whaom)]

So this is common issue which all options used by @periodics.periodic(spacing=CONF.xxx) not working.

[Haomeng,Wang (whaom)]

Got the trace back stack as below, so we need to change this call path to avoid load manager first than conf.

Traceback (most recent call last):
  File "/usr/local/bin/ironic-conductor", line 6, in <module>
    from ironic.cmd.conductor import main
  File "/opt/stack/ironic/ironic/cmd/conductor.py", line 29, in <module>
    from ironic.common import service as ironic_service
  File "/opt/stack/ironic/ironic/common/service.py", line 29, in <module>
    from ironic.api import app
  File "/opt/stack/ironic/ironic/api/app.py", line 25, in <module>
    from ironic.api import hooks
  File "/opt/stack/ironic/ironic/api/hooks.py", line 24, in <module>
    from ironic.conductor import rpcapi
  File "/opt/stack/ironic/ironic/conductor/rpcapi.py", line 29, in <module>
    from ironic.conductor import manager
  File "/opt/stack/ironic/ironic/conductor/manager.py", line 55, in <module>
    from oslo_service import periodic_task

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Change abandoned by Haomeng,Wang (<email address hidden>) on branch: master
Review: https://review.openstack.org/299781
Reason: This will not be issue once https://review.openstack.org/#/c/301967 is landed, it will add conf/__init__ to make sure all configurations will be loaded first.

[Lucas Alvares Gomes (lucasagomes)]

The patch [0] has landed. Is this problem fixed now ?

[0] https://review.openstack.org/#/c/301967

[Haomeng,Wang (whaom)]

Ok, Lucas, I will test if have time, recent months, busy on company's new project.

[Lucas Alvares Gomes (lucasagomes)]

Tested it on a local environment, #301967 does not seem to fix it. I've set it to run every 180 seconds, but it ran every 60 seconds (the default):

2016-09-02 14:54:41.951 DEBUG oslo_service.service [-] conductor.sync_power_state_interval = 180 from (pid=2230) log_opt_values /usr/lib/python2.7/site-packages/oslo_config/cfg.py:2626

2016-09-02 14:57:52.836 DEBUG ironic.conductor.task_manager [req-fc7e7916-5328-4abf-a002-91e3759e8f01 None None] Successfully released shared lock for power state sync on node a4d20b2d-85d7-4eb6-bce8-9d3b7925a4ef (lock was held 5.05 sec) from (pid=2230) release_resources /opt/stack/ironic/ironic/conductor/task_manager.py:331

2016-09-02 14:58:52.791 DEBUG ironic.conductor.task_manager [req-fc7e7916-5328-4abf-a002-91e3759e8f01 None None] Successfully released shared lock for power state sync on node a4d20b2d-85d7-4eb6-bce8-9d3b7925a4ef (lock was held 5.02 sec) from (pid=2230) release_resources /opt/stack/ironic/ironic/conductor/task_manager.py:331

2016-09-02 14:59:52.777 DEBUG ironic.conductor.task_manager [req-fc7e7916-5328-4abf-a002-91e3759e8f01 None None] Successfully released shared lock for power state sync on node a4d20b2d-85d7-4eb6-bce8-9d3b7925a4e
f (lock was held 5.04 sec) from (pid=2230) release_resources /opt/stack/ironic/ironic/conductor/task_manager.py:331

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Change abandoned by Lucas Alvares Gomes (<email address hidden>) on branch: master
Review: https://review.openstack.org/369000
Reason: Thanks Ruby, yes let's continue on ur patch.

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/369724
Committed: https://git.openstack.org/cgit/openstack/ironic/commit/?id=ec202c444ba159797403407c771e24fbc2ddcd4f
Submitter: Jenkins
Branch: master

commit ec202c444ba159797403407c771e24fbc2ddcd4f
Author: Ruby Loo <email address hidden>
Date: Tue Sep 13 17:46:27 2016 -0400

    Separate WSGIService from RPCService

    This patch fixes a problem which prevented Ironic from honoring the
    interval values configuration for the periodic tasks. Since the interval
    values are passed to a decorator, the configuration options should be
    evaluated prior to importing the module which contains the periodic tasks.

    In our case this was not happening due to the chain of imports going
    from ironic.cmd.conductor -> ironic.common.service -> ironic.api.app
    -> ... -> ironic.conductor.manager. This caused the @periodic
    decorators to be evaluated before the configuration options were loaded.

    This patch breaks that chain of imports by separating the WSGIService
    and RPCService classes into two separate files. The conductor uses the
    RPCService, and since it is now in a separate file from WSGIService, it
    no longer pulls in ironic.api.app, ..., and ironic.conductor.manager.
    (ironic.api.app was being imported because WSGIService needed it.)

    Change-Id: Ie318e7bb2d2c2d971a796ab8960be33fccbd88f3
    Closes-Bug: #1562258
    Co-Authored-By: Lucas Alvares Gomes <email address hidden>