Bug 1075833 - Reduce debug logging of qpid output
Summary: Reduce debug logging of qpid output
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat OpenStack
Classification: Red Hat
Component: openstack-neutron
Version: 4.0
Hardware: Unspecified
OS: Unspecified
low
unspecified
Target Milestone: z4
: 4.0
Assignee: Ian Wienand
QA Contact: Nir Magnezi
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2014-03-13 00:01 UTC by Ian Wienand
Modified: 2022-07-09 06:16 UTC (History)
8 users (show)

Fixed In Version: openstack-neutron-2013.2.3-4.el6ost
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2014-05-29 20:19:16 UTC
Target Upstream Version:
Embargoed:
pm-rhel: internal-review+


Attachments (Terms of Use)
neutron logs (1.09 MB, text/plain)
2014-04-28 07:57 UTC, Nir Magnezi
no flags Details


Links
System ID Private Priority Status Summary Last Updated
Red Hat Product Errata RHSA-2014:0516 0 normal SHIPPED_LIVE Moderate: openstack-neutron security, bug fix, and enhancement update 2014-05-30 00:15:59 UTC

Description Ian Wienand 2014-03-13 00:01:20 UTC
Description of problem:

When turning on debugging for neutron agents the logs get filled with very detailed qpid debug messages.  These are very unlikely to be useful and increase the volume of logging so much it makes it very difficult to mange the log files.

Upstream did already turn this down in [1], we should add this by default too  

[1] https://github.com/openstack/oslo-incubator/commit/fb8075a19d475ad7f2868242ab59507bc1fb229e

Comment 7 Nir Magnezi 2014-04-28 07:53:25 UTC
Ian,
I still see these type of debug messages in logs (in debug mode).
Tested with: 2014-04-25.2 --> openstack-neutron-2013.2.3-7.el6ost.noarch

Comment 8 Nir Magnezi 2014-04-28 07:57:15 UTC
Created attachment 890367 [details]
neutron logs

[root@rhel ~(keystone_admin)]# grep neutron.openstack.common.rpc.amqp /var/log/neutron/* | wc -l
3642

Comment 9 Ian Wienand 2014-04-28 10:37:33 UTC
sorry, i didn't paste the full problem.  The thing that was fillingup the logs was the qpid messaging outputs ... see below anything starting with qpid.*

---
2014-04-28 13:32:24.157 7039 DEBUG neutron.openstack.common.rpc.amqp [-] received {u'_context_roles': [u'admin'], u'_context_read_deleted': u'no', u'_context_tenant_id': None, u'args': {u'agent_state': {u'agent_state': {u'topic': u'N/A', u'binary': u'neutron-openvswitch-agent', u'host': u'puma06.scl.lab.tlv.redhat.com', u'agent_type': u'Open vSwitch agent', u'configurations': {u'tunnel_types': [], u'tunneling_ip': u'', u'bridge_mappings': {u'int_vlan_range': u'br-nodes'}, u'l2_population': False, u'devices': 3}}}, u'time': u'2014-04-28T10:32:24.118087'}, u'namespace': None, u'_unique_id': u'7b19f3282d92445eb2bde9c0775492fd', u'_context_is_admin': True, u'version': u'1.0', u'_context_project_id': None, u'_context_timestamp': u'2014-04-27 11:07:19.091078', u'_context_user_id': None, u'method': u'report_state'} _safe_log /usr/lib/python2.6/site-packages/neutron/openstack/common/rpc/common.py:276
2014-04-28 13:32:24.157 7039 DEBUG neutron.openstack.common.rpc.amqp [-] unpacked context: {'user_id': None, 'roles': [u'admin'], 'tenant_id': None, 'is_admin': True, 'timestamp': u'2014-04-27 11:07:19.091078', 'project_id': None, 'read_deleted': u'no'} _safe_log /usr/lib/python2.6/site-packages/neutron/openstack/common/rpc/common.py:276
2014-04-28 13:32:24.157 7039 DEBUG qpid.messaging.io.ops [-] SENT[1f6c488]: SessionCompleted(commands=[0-46]) write_op /usr/lib/python2.6/site-packages/qpid/messaging/driver.py:685
2014-04-28 13:32:24.161 7039 DEBUG qpid.messaging.io.raw [-] SENT[1f6c488]: '\x0f\x01\x00\x19\x00\x01\x00\x00\x00\x00\x00\x00\x04\n\x01\x00\x07\x00\x011\x00\x00\x00\x00\x01\x0f\x00\x00\x1a\x00\x00\x00\x00\x00\x00\x00\x00\x02\n\x01\x00\x00\x08\x00\x00\x00\x00\x00\x00\x00.' writeable /usr/lib/python2.6/site-packages/qpid/messaging/driver.py:480
2014-04-28 13:32:24.232 7039 DEBUG qpid.messaging.io.raw [-] READ[1f6c488]: '\x0b\x01\x00\x16\x00\x01\x00\x00\x00\x00\x00\x00\x04\x01\x01\x00\x07\x00\x011\x01\x00\x03\x02\x00t\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00;\x04\x03\x10\x01\x08amqp/map\x00\x00\x00*\x00\x00\x00\x01\x0cqpid.subject\x95\x00\x16topic/neutron/q-plugin\x00\x00\x00%\x04\x01\x00\x03\tamq.topic\x16topic/neutron/q-plugin\x07\x03\x02\xf1\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x02\xe1\x00\x00\x00\x02\x0coslo.message\x95\x02\xba{"_context_roles": ["admin"], "_context_read_deleted": "no", "args": {"agent_state": {"agent_state": {"binary": "neutron-openvswitch-agent", "topic": "N/A", "host": "puma08.scl.lab.tlv.redhat.com", "agent_type": "Open vSwitch agent", "configurations": {"tunnel_types": [], "tunneling_ip": "", "bridge_mappings": {"int_vlan_range": "br-nodes"}, "l2_population": false, "devices": 3}}}, "time": "2014-04-28T10:32:24.193589"}, "namespace": null, "_unique_id": "3cc43fe0ca854dfab7912c62d9b3adad", "_context_timestamp": "2014-04-27 11:07:17.599803", "_context_is_admin": true, "version": "1.0", "_context_project_id": null, "_context_tenant_id": null, "_context_user_id": null, "method": "report_state"}\x0coslo.version\x95\x00\x032.0' readable /usr/lib/python2.6/site-packages/qpid/messaging/driver.py:416
2014-04-28 13:32:24.232 7039 DEBUG qpid.messaging.io.ops [-] RCVD[1f6c488]: MessageTransfer(destination=u'1', accept_mode=1, acquire_mode=0, id=serial(47), headers=[MessageProperties(content_type=u'amqp/map', application_headers={u'qpid.subject': u'topic/neutron/q-plugin'}), DeliveryProperties(exchange=u'amq.topic', routing_key=u'topic/neutron/q-plugin')], payload='\x00\x00\x02\xe1\x00\x00\x00\x02\x0coslo.message\x95\x02\xba{"_context_roles": ["admin"], "_context_read_deleted": "no", "args": {"agent_state": {"agent_state": {"binary": "neutron-openvswitch-agent", "topic": "N/A", "host": "puma08.scl.lab.tlv.redhat.com", "agent_type": "Open vSwitch agent", "configurations": {"tunnel_types": [], "tunneling_ip": "", "bridge_mappings": {"int_vlan_range": "br-nodes"}, "l2_population": false, "devices": 3}}}, "time": "2014-04-28T10:32:24.193589"}, "namespace": null, "_unique_id": "3cc43fe0ca854dfab7912c62d9b3adad", "_context_timestamp": "2014-04-27 11:07:17.599803", "_context_is_admin": true, "version": "1.0", "_context_project_id": null, "_context_tenant_id": null, "_context_user_id": null, "method": "report_state"}\x0coslo.version\x95\x00\x032.0') write /usr/lib/python2.6/site-packages/qpid/messaging/driver.py:653
2014-04-28 13:32:24.233 7039 DEBUG qpid.messaging [-] RCVD[1fd9e60]: Message(subject=u'topic/neutron/q-plugin', properties={u'qpid.subject': u'topic/neutron/q-plugin', 'x-amqp-0-10.routing-key': u'topic/neutron/q-plugin'}, content={u'oslo.message': u'{"_context_roles": ["admin"], "_context_read_deleted": "no", "args": {"agent_state": {"agent_state": {"binary": "neutron-openvswitch-agent", "topic": "N/A", "host": "puma08.scl.lab.tlv.redhat.com", "agent_type": "Open vSwitch agent", "configurations": {"tunnel_types": [], "tunneling_ip": "", "bridge_mappings": {"int_vlan_range": "br-nodes"}, "l2_population": false, "devices": 3}}}, "time": "2014-04-28T10:32:24.193589"}, "namespace": null, "_unique_id": "3cc43fe0ca854dfab7912c62d9b3adad", "_context_timestamp": "2014-04-27 11:07:17.599803", "_context_is_admin": true, "version": "1.0", "_context_project_id": null, "_context_tenant_id": null, "_context_user_id": null, "method": "report_state"}', u'oslo.version': u'2.0'}) do_message_transfer /usr/lib/python2.6/site-packages/qpid/messaging/driver.py:1297
2014-04-28 13:32:24.233 7039 DEBUG qpid.messaging [-] RETR[1fd9e60]: Message(subject=u'topic/neutron/q-plugin', properties={u'qpid.subject': u'topic/neutron/q-plugin', 'x-amqp-0-10.routing-key': u'topic/neutron/q-plugin'}, content={u'oslo.message': u'{"_context_roles": ["admin"], "_context_read_deleted": "no", "args": {"agent_state": {"agent_state": {"binary": "neutron-openvswitch-agent", "topic": "N/A", "host": "puma08.scl.lab.tlv.redhat.com", "agent_type": "Open vSwitch agent", "configurations": {"tunnel_types": [], "tunneling_ip": "", "bridge_mappings": {"int_vlan_range": "br-nodes"}, "l2_population": false, "devices": 3}}}, "time": "2014-04-28T10:32:24.193589"}, "namespace": null, "_unique_id": "3cc43fe0ca854dfab7912c62d9b3adad", "_context_timestamp": "2014-04-27 11:07:17.599803", "_context_is_admin": true, "version": "1.0", "_context_project_id": null, "_context_tenant_id": null, "_context_user_id": null, "method": "report_state"}', u'oslo.version': u'2.0'}) _get /usr/lib/python2.6/site-packages/qpid/messaging/endpoints.py:654
---

the neutron.openstack.common.rpc.amqp messages are the "top-level" and are expected to be shown

Comment 11 Nir Magnezi 2014-04-29 07:11:34 UTC
Verified NVR: openstack-neutron-2013.2.3-7.el6ost.noarch

1. /usr/lib/python2.6/site-packages/neutron/openstack/common/log.py contains the changes described in https://github.com/openstack/oslo-incubator/commit/fb8075a19d475ad7f2868242ab59507bc1fb229e
2. logs no longer contain the discussed qpid messages

Comment 13 errata-xmlrpc 2014-05-29 20:19:16 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

http://rhn.redhat.com/errata/RHSA-2014-0516.html


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