This service will be undergoing maintenance at 00:00 UTC, 2017-10-23 It is expected to last about 30 minutes
Bug 976327 - nova: running nova-manage service list after changing nova.conf to debug=True prints out debug's from log
nova: running nova-manage service list after changing nova.conf to debug=True...
Status: CLOSED NOTABUG
Product: Red Hat OpenStack
Classification: Red Hat
Component: openstack-nova (Show other bugs)
unspecified
x86_64 Linux
unspecified Severity high
: ---
: 4.0
Assigned To: Vladan Popovic
Ami Jeain
:
: 1039654 (view as bug list)
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2013-06-20 07:38 EDT by Dafna Ron
Modified: 2016-04-26 15:16 EDT (History)
7 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2013-11-21 00:13:14 EST
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
logs (13.69 KB, application/x-gzip)
2013-06-20 07:38 EDT, Dafna Ron
no flags Details

  None (edit)
Description Dafna Ron 2013-06-20 07:38:57 EDT
Created attachment 763444 [details]
logs

Description of problem:

I changed nova.conf to debug=true and verbose=true and restarted the service. 
after that, when I run nova-manage service list the output is showing debug prints and the table for the services list is only shown when we use |less 

Version-Release number of selected component (if applicable):

openstack-nova-compute-2013.1.2-2.el6ost.noarch
openstack-nova-api-2013.1.2-2.el6ost.noarch
python-nova-2013.1.2-2.el6ost.noarch

How reproducible:

100%

Steps to Reproduce:
1. run nova-manage service list when debug and verbose=false 
2. run nova-manage service list when debug and verbose=true
3. run nova-manage service list |less when debug and verbose=true

Actual results:

once debug=true we print out debug messages with the command output and the table is shown only when we add |less to the command. 
 
Expected results:

print for the command should not change and the debug messages should only be printed to the nova log

Additional info:


[root@opens-vdsb ~(keystone_admin)]# nova-manage service list 
2013-06-20 14:35:39.449 4020 DEBUG nova.servicegroup.api [-] ServiceGroup driver defined as an instance of db __new__ /usr/lib/python2.6/site-packages/nova/servicegroup/api.py:61
2013-06-20 14:35:39.527 DEBUG nova.openstack.common.lockutils [req-356b43f2-560d-422c-84bc-6c2496b874ad None None] Got semaphore "dbapi_backend" for method "__get_backend"... inner /usr/lib/python2.6/site-packages/nova/openstack/common/lockutils.py:186
Binary           Host                                 Zone             Status     State Updated_At
2013-06-20 14:35:39.830 DEBUG nova.servicegroup.api [req-356b43f2-560d-422c-84bc-6c2496b874ad None None] Check if the given member [{'binary': u'nova-cert', 'availability_zone': 'internal', 'deleted': 0L, 'created_at': datetime.datetime(2013, 6, 20, 8, 40, 12), 'updated_at': datetime.datetime(2013, 6, 20, 11, 35, 37), 'report_count': 1020L, 'topic': u'cert', 'host': u'opens-vdsb.qa.lab.tlv.redhat.com', 'disabled': False, 'deleted_at': None, 'id': 1L}] is part of the ServiceGroup, is up service_is_up /usr/lib/python2.6/site-packages/nova/servicegroup/api.py:92
2013-06-20 14:35:39.831 DEBUG nova.servicegroup.drivers.db [req-356b43f2-560d-422c-84bc-6c2496b874ad None None] DB_Driver.is_up last_heartbeat = 2013-06-20 11:35:37 elapsed = 2.831032 is_up /usr/lib/python2.6/site-packages/nova/servicegroup/drivers/db.py:67
nova-cert        opens-vdsb.qa.lab.tlv.redhat.com     internal         enabled    :-)   2013-06-20 11:35:37
2013-06-20 14:35:39.831 DEBUG nova.servicegroup.api [req-356b43f2-560d-422c-84bc-6c2496b874ad None None] Check if the given member [{'binary': u'nova-scheduler', 'availability_zone': 'internal', 'deleted': 0L, 'created_at': datetime.datetime(2013, 6, 20, 8, 40, 13), 'updated_at': datetime.datetime(2013, 6, 20, 11, 35, 37), 'report_count': 1020L, 'topic': u'scheduler', 'host': u'opens-vdsb.qa.lab.tlv.redhat.com', 'disabled': False, 'deleted_at': None, 'id': 2L}] is part of the ServiceGroup, is up service_is_up /usr/lib/python2.6/site-packages/nova/servicegroup/api.py:92
2013-06-20 14:35:39.831 DEBUG nova.servicegroup.drivers.db [req-356b43f2-560d-422c-84bc-6c2496b874ad None None] DB_Driver.is_up last_heartbeat = 2013-06-20 11:35:37 elapsed = 2.831693 is_up /usr/lib/python2.6/site-packages/nova/servicegroup/drivers/db.py:67
nova-scheduler   opens-vdsb.qa.lab.tlv.redhat.com     internal         enabled    :-)   2013-06-20 11:35:37
2013-06-20 14:35:39.832 DEBUG nova.servicegroup.api [req-356b43f2-560d-422c-84bc-6c2496b874ad None None] Check if the given member [{'binary': u'nova-conductor', 'availability_zone': 'internal', 'deleted': 0L, 'created_at': datetime.datetime(2013, 6, 20, 8, 40, 13), 'updated_at': datetime.datetime(2013, 6, 20, 11, 35, 36), 'report_count': 1021L, 'topic': u'conductor', 'host': u'opens-vdsb.qa.lab.tlv.redhat.com', 'disabled': False, 'deleted_at': None, 'id': 3L}] is part of the ServiceGroup, is up service_is_up /usr/lib/python2.6/site-packages/nova/servicegroup/api.py:92
2013-06-20 14:35:39.832 DEBUG nova.servicegroup.drivers.db [req-356b43f2-560d-422c-84bc-6c2496b874ad None None] DB_Driver.is_up last_heartbeat = 2013-06-20 11:35:36 elapsed = 3.832306 is_up /usr/lib/python2.6/site-packages/nova/servicegroup/drivers/db.py:67
nova-conductor   opens-vdsb.qa.lab.tlv.redhat.com     internal         enabled    :-)   2013-06-20 11:35:36
2013-06-20 14:35:39.832 DEBUG nova.servicegroup.api [req-356b43f2-560d-422c-84bc-6c2496b874ad None None] Check if the given member [{'binary': u'nova-consoleauth', 'availability_zone': 'internal', 'deleted': 0L, 'created_at': datetime.datetime(2013, 6, 20, 8, 40, 13), 'updated_at': datetime.datetime(2013, 6, 20, 11, 35, 37), 'report_count': 1021L, 'topic': u'consoleauth', 'host': u'opens-vdsb.qa.lab.tlv.redhat.com', 'disabled': False, 'deleted_at': None, 'id': 4L}] is part of the ServiceGroup, is up service_is_up /usr/lib/python2.6/site-packages/nova/servicegroup/api.py:92
2013-06-20 14:35:39.833 DEBUG nova.servicegroup.drivers.db [req-356b43f2-560d-422c-84bc-6c2496b874ad None None] DB_Driver.is_up last_heartbeat = 2013-06-20 11:35:37 elapsed = 2.832966 is_up /usr/lib/python2.6/site-packages/nova/servicegroup/drivers/db.py:67
nova-consoleauth opens-vdsb.qa.lab.tlv.redhat.com     internal         enabled    :-)   2013-06-20 11:35:37
2013-06-20 14:35:39.833 DEBUG nova.servicegroup.api [req-356b43f2-560d-422c-84bc-6c2496b874ad None None] Check if the given member [{'binary': u'nova-network', 'availability_zone': 'internal', 'deleted': 0L, 'created_at': datetime.datetime(2013, 6, 20, 8, 40, 14), 'updated_at': datetime.datetime(2013, 6, 20, 11, 35, 38), 'report_count': 1020L, 'topic': u'network', 'host': u'opens-vdsb.qa.lab.tlv.redhat.com', 'disabled': False, 'deleted_at': None, 'id': 5L}] is part of the ServiceGroup, is up service_is_up /usr/lib/python2.6/site-packages/nova/servicegroup/api.py:92
2013-06-20 14:35:39.833 DEBUG nova.servicegroup.drivers.db [req-356b43f2-560d-422c-84bc-6c2496b874ad None None] DB_Driver.is_up last_heartbeat = 2013-06-20 11:35:38 elapsed = 1.833587 is_up /usr/lib/python2.6/site-packages/nova/servicegroup/drivers/db.py:67
nova-network     opens-vdsb.qa.lab.tlv.redhat.com     internal         enabled    :-)   2013-06-20 11:35:38
2013-06-20 14:35:39.833 DEBUG nova.servicegroup.api [req-356b43f2-560d-422c-84bc-6c2496b874ad None None] Check if the given member [{'binary': u'nova-compute', 'availability_zone': 'nova', 'deleted': 0L, 'created_at': datetime.datetime(2013, 6, 20, 8, 40, 15), 'updated_at': datetime.datetime(2013, 6, 20, 11, 35, 33), 'report_count': 1017L, 'topic': u'compute', 'host': u'opens-vdsb.qa.lab.tlv.redhat.com', 'disabled': False, 'deleted_at': None, 'id': 6L}] is part of the ServiceGroup, is up service_is_up /usr/lib/python2.6/site-packages/nova/servicegroup/api.py:92
2013-06-20 14:35:39.834 DEBUG nova.servicegroup.drivers.db [req-356b43f2-560d-422c-84bc-6c2496b874ad None None] DB_Driver.is_up last_heartbeat = 2013-06-20 11:35:33 elapsed = 6.834207 is_up /usr/lib/python2.6/site-packages/nova/servicegroup/drivers/db.py:67
nova-compute     opens-vdsb.qa.lab.tlv.redhat.com     nova             enabled    :-)   2013-06-20 11:35:33
2013-06-20 14:35:39.834 DEBUG nova.servicegroup.api [req-356b43f2-560d-422c-84bc-6c2496b874ad None None] Check if the given member [{'binary': u'nova-compute', 'availability_zone': 'nova', 'deleted': 0L, 'created_at': datetime.datetime(2013, 6, 20, 8, 40, 41), 'updated_at': datetime.datetime(2013, 6, 20, 11, 35, 32), 'report_count': 1008L, 'topic': u'compute', 'host': u'nott-vdsa.qa.lab.tlv.redhat.com', 'disabled': False, 'deleted_at': None, 'id': 7L}] is part of the ServiceGroup, is up service_is_up /usr/lib/python2.6/site-packages/nova/servicegroup/api.py:92
2013-06-20 14:35:39.834 DEBUG nova.servicegroup.drivers.db [req-356b43f2-560d-422c-84bc-6c2496b874ad None None] DB_Driver.is_up last_heartbeat = 2013-06-20 11:35:32 elapsed = 7.834906 is_up /usr/lib/python2.6/site-packages/nova/servicegroup/drivers/db.py:67
nova-compute     nott-vdsa.qa.lab.tlv.redhat.com      nova             enabled    :-)   2013-06-20 11:35:32
[root@opens-vdsb ~(keystone_admin)]# 


with less:

.509206 is_up /usr/lib/python2.6/site-packages/nova/servicegroup/drivers/db.py:67
2013-06-20 14:36:09.509 DEBUG nova.servicegroup.api [req-d8df85c7-972e-4734-a10f-3efbec291d24 None None] Check if the given member [{'binary': u'nova-network', 'availability_zone': 'internal', 'deleted': 0L, 'created_at': datetime.datetime(2013, 6, 20, 8, 40, 14), 'updated_at': datetime.datetime(2013, 6, 20, 11, 36, 8), 'report_count': 1023L, 'topic': u'network', 'host': u'opens-vdsb.qa.lab.tlv.redhat.com', 'disabled': False, 'deleted_at': None, 'id': 5L}] is part of the ServiceGroup, is up service_is_up /usr/lib/python2.6/site-packages/nova/servicegroup/api.py:92
2013-06-20 14:36:09.509 DEBUG nova.servicegroup.drivers.db [req-d8df85c7-972e-4734-a10f-3efbec291d24 None None] DB_Driver.is_up last_heartbeat = 2013-06-20 11:36:08 elapsed = 1.509822 is_up /usr/lib/python2.6/site-packages/nova/servicegroup/drivers/db.py:67
2013-06-20 14:36:09.510 DEBUG nova.servicegroup.api [req-d8df85c7-972e-4734-a10f-3efbec291d24 None None] Check if the given member [{'binary': u'nova-compute', 'availability_zone': 'nova', 'deleted': 0L, 'created_at': datetime.datetime(2013, 6, 20, 8, 40, 15), 'updated_at': datetime.datetime(2013, 6, 20, 11, 36, 4), 'report_count': 1020L, 'topic': u'compute', 'host': u'opens-vdsb.qa.lab.tlv.redhat.com', 'disabled': False, 'deleted_at': None, 'id': 6L}] is part of the ServiceGroup, is up service_is_up /usr/lib/python2.6/site-packages/nova/servicegroup/api.py:92
2013-06-20 14:36:09.510 DEBUG nova.servicegroup.drivers.db [req-d8df85c7-972e-4734-a10f-3efbec291d24 None None] DB_Driver.is_up last_heartbeat = 2013-06-20 11:36:04 elapsed = 5.510428 is_up /usr/lib/python2.6/site-packages/nova/servicegroup/drivers/db.py:67
2013-06-20 14:36:09.510 DEBUG nova.servicegroup.api [req-d8df85c7-972e-4734-a10f-3efbec291d24 None None] Check if the given member [{'binary': u'nova-compute', 'availability_zone': 'nova', 'deleted': 0L, 'created_at': datetime.datetime(2013, 6, 20, 8, 40, 41), 'updated_at': datetime.datetime(2013, 6, 20, 11, 36, 2), 'report_count': 1011L, 'topic': u'compute', 'host': u'nott-vdsa.qa.lab.tlv.redhat.com', 'disabled': False, 'deleted_at': None, 'id': 7L}] is part of the ServiceGroup, is up service_is_up /usr/lib/python2.6/site-packages/nova/servicegroup/api.py:92
2013-06-20 14:36:09.511 DEBUG nova.servicegroup.drivers.db [req-d8df85c7-972e-4734-a10f-3efbec291d24 None None] DB_Driver.is_up last_heartbeat = 2013-06-20 11:36:02 elapsed = 7.511056 is_up /usr/lib/python2.6/site-packages/nova/servicegroup/drivers/db.py:67
Binary           Host                                 Zone             Status     State Updated_At
nova-cert        opens-vdsb.qa.lab.tlv.redhat.com     internal         enabled    :-)   2013-06-20 11:36:07
nova-scheduler   opens-vdsb.qa.lab.tlv.redhat.com     internal         enabled    :-)   2013-06-20 11:36:07
nova-conductor   opens-vdsb.qa.lab.tlv.redhat.com     internal         enabled    :-)   2013-06-20 11:36:07
nova-consoleauth opens-vdsb.qa.lab.tlv.redhat.com     internal         enabled    :-)   2013-06-20 11:36:07
nova-network     opens-vdsb.qa.lab.tlv.redhat.com     internal         enabled    :-)   2013-06-20 11:36:08
nova-compute     opens-vdsb.qa.lab.tlv.redhat.com     nova             enabled    :-)   2013-06-20 11:36:04
nova-compute     nott-vdsa.qa.lab.tlv.redhat.com      nova             enabled    :-)   2013-06-20 11:36:02
(END)
Comment 1 Vladan Popovic 2013-11-08 18:17:05 EST
The logging module is setup by default to print to stderr:
https://github.com/openstack/nova/blob/master/nova/openstack/common/log.py#L105
So, setting this option to "false" in the config file would supress the messages printed to stderr.
The reason you see the output when the debug/verbose options are set to "true" is because only debug info is printed when running the command, i.e. if there were some warnings they would be printed out with debug/verbose unset.
https://github.com/openstack/nova/blob/master/nova/openstack/common/log.py#L438

But, setting use_stderr=False would only redirect the output to stdout if no log_file is present in the configuration:
https://github.com/openstack/nova/blob/master/nova/openstack/common/log.py#L414
Setting the log_file option would completely supress the output in the terminal.

I don't think we should patch something in the manager since it's a matter of configuring nova.
Comment 2 Russell Bryant 2013-11-21 00:13:14 EST
Yes, this sounds expected.

Also, note that nova-manage is deprecated for this, and you should be using the API for doing a service list, anyway.
Comment 3 Vladan Popovic 2014-03-31 09:44:20 EDT
*** Bug 1039654 has been marked as a duplicate of this bug. ***

Note You need to log in before you can comment on or make changes to this bug.