bad heat-engine logging at verbose=true in Juno

[Tom Fifield]

Hi,

I'm not sure if this is already fixed in kilo, but with default settings installed as per the official install guide http://docs.openstack.org/juno/install-guide/install/apt/content and then setting verbose=true in /etc/heat/heat.conf it is possible to get a /var/log/heat/heat-engine.log that looks almost entirely like the below (controller is the hostname).

Aside from being 'spammy', it also provides no information about what it's actually trying to do. So, this is not helpful to ops.

2015-03-27 16:19:20.852 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller
2015-03-27 16:19:20.868 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller
2015-03-27 16:19:22.226 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller
2015-03-27 16:19:22.267 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller
2015-03-27 16:19:23.308 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller
2015-03-27 16:19:24.348 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller
2015-03-27 16:19:25.406 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller
2015-03-27 16:19:26.450 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller
2015-03-27 16:19:27.490 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller
2015-03-27 16:19:28.541 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller
2015-03-27 16:19:29.585 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller
2015-03-27 16:19:30.630 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller
2015-03-27 16:19:31.683 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller
2015-03-27 16:19:32.723 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller
2015-03-27 16:19:33.760 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller
2015-03-27 16:19:34.801 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller
2015-03-27 16:19:35.841 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller
2015-03-27 16:19:36.884 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller
2015-03-27 16:19:37.921 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller
2015-03-27 16:19:38.961 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller
2015-03-27 16:19:40.007 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller
2015-03-27 16:19:41.050 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller
2015-03-27 16:19:42.095 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller
2015-03-27 16:19:43.139 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller
2015-03-27 16:19:44.180 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller
2015-03-27 16:19:45.219 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller
2015-03-27 16:19:46.260 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller
2015-03-27 16:19:47.376 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller
2015-03-27 16:19:48.417 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller
2015-03-27 16:19:49.454 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller
2015-03-27 16:19:50.502 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller
2015-03-27 16:19:51.541 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller
2015-03-27 16:19:52.586 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller
2015-03-27 16:19:53.632 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller
2015-03-27 16:19:54.673 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller
2015-03-27 16:19:55.726 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller
2015-03-27 16:19:56.768 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller
2015-03-27 16:19:57.818 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller
2015-03-27 16:19:58.868 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller
2015-03-27 16:19:59.978 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller
2015-03-27 16:20:01.028 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller
2015-03-27 16:20:02.063 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller
2015-03-27 16:20:03.109 6990 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): controller

[Steve Baker (steve-stevebaker)]

Marking this as High as a general bug to make sure verbose=True logging is sane and useful for the Kilo release.

[Ethan Lynn (ethanlynn)]

Can not find related messages in kilo codes after setting verbose=True in heat.conf.
Maybe it's fixed in kilo.

[Tom Fifield (fifieldt)]

The above test was in Juno.

So, if you've got a kilo handy to reproduce:

1) Turn off your nova-scheduler service to make it continually ask for the status of the VM that will never exist
2) Make a new simple stack

[Angus Salkeld (asalkeld)]

Since it's exactly every second, it's probably heat's scheduler running a check job which calls novaclient. novaclient will then log this stuff in debug mode.

However the default_log_level config setting *should* set "urllib3.connectionpool" to warning and above.

https://github.com/openstack/oslo.log/blob/master/oslo_log/_options.py#L90
https://github.com/openstack/oslo.log/blob/master/oslo_log/log.py#L320-L329

[Angus Salkeld (asalkeld)]

On master I am only getting this:

2015-03-31 13:49:50.922 DEBUG heat.engine.scheduler [-] Task stack_task from Stack "foo" [9273323b-0ef5-4b7a-ad3f-aefcf94fe70e] sleeping from (pid=25013) _sleep /home/angus/work/heat/heat/engine/scheduler.py:164
2015-03-31 13:49:51.923 DEBUG heat.engine.scheduler [-] Task stack_task from Stack "foo" [9273323b-0ef5-4b7a-ad3f-aefcf94fe70e] running from (pid=25013) step /home/angus/work/heat/heat/engine/scheduler.py:219
2015-03-31 13:49:51.924 DEBUG heat.engine.scheduler [-] Task resource_action running from (pid=25013) step /home/angus/work/heat/heat/engine/scheduler.py:219

I'll re-target this as it is not applicable to master.

[Tom Fifield (fifieldt)]

(noting just in case people jump to this comment, my report was only tested on Juno, not Kilo, if you're busy with releasing please ignore)

Thanks for looking into things Angus.

Is that what you get on master for INFO, or DEBUG?

If it's DEBUG, does that mean there's no log for this situation in info?

If I remember correctly, heat will kill a VM that has failed to schedule and try again. In this case, probably there should be a line saying "I'm trying to start a new stack, and the VM I started up failed to schedule within my timeout"...

[Neetu Jain (nutshi)]

will test it in Kilo

[Neetu Jain (nutshi)]

did not see it followed these steps
1) edited /etc/heat/heat.conf conf file for verbose=true ( in general section)
2) stopped nova-scheduler
   service openstack-nova-scheduler stop
3) created heat stack
4) checked logs

[Neetu Jain (nutshi)]

could not reproduce the error in Kilo i meant

[Steve Baker (steve-stevebaker)]

Juno is EOL so there is no place to fix this now, and this appears to be fixed from Kilo onwards.