x/vmware-nsx
Code Issues Proposed changes

ofagent: Clean up logging

Browse Source 
- Use _LI, _LW, _LE
- Remove localization from debug logs
- Replace LOG.debug calls with @log.log decorator where appropriate

Change-Id: I9c80c556003db7b0b8e99da0340a26beb1e00e16
This commit is contained in:
YAMAMOTO Takashi 2014-09-08 11:29:05 +09:00
parent 7c8cb7bd7a
commit b9015c5040
2 changed files with 74 additions and 75 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

29
neutron/plugins/ofagent/agent/arp_lib.py
View File

@ -22,6 +22,8 @@ from ryu.lib.packet import ethernet
from ryu.lib.packet import packet
from ryu.lib.packet import vlan
from neutron.common import log
from neutron.openstack.common.gettextutils import _LI
from neutron.openstack.common import log as logging
import neutron.plugins.ofagent.agent.metadata as meta
@ -50,8 +52,8 @@ class ArpLib(object):
def set_bridge(self, br):
self.br = br
@log.log
def _send_arp_reply(self, datapath, port, pkt):
LOG.debug("packet-out %s", pkt)
ofp = datapath.ofproto
ofpp = datapath.ofproto_parser
pkt.serialize()
@ -64,10 +66,8 @@ class ArpLib(object):
data=data)
ryu_api.send_msg(self.ryuapp, out)
@log.log
def _send_unknown_packet(self, msg, in_port, out_port):
LOG.debug("unknown packet-out in-port %(in_port)s "
"out-port %(out_port)s msg %(msg)s",
{'in_port': in_port, 'out_port': out_port, 'msg': msg})
datapath = msg.datapath
ofp = datapath.ofproto
ofpp = datapath.ofproto_parser
@ -111,18 +111,15 @@ class ArpLib(object):
self._send_arp_reply(datapath, port, pkt)
return True
@log.log
def add_arp_table_entry(self, network, ip, mac):
LOG.debug("added arp table entry: "
"network %(network)s ip %(ip)s mac %(mac)s",
{'network': network, 'ip': ip, 'mac': mac})
if network in self._arp_tbl:
self._arp_tbl[network][ip] = mac
else:
self._arp_tbl[network] = {ip: mac}
@log.log
def del_arp_table_entry(self, network, ip):
LOG.debug("deleted arp table entry: network %(network)s ip %(ip)s",
{'network': network, 'ip': ip})
del self._arp_tbl[network][ip]
if not self._arp_tbl[network]:
del self._arp_tbl[network]
@ -137,32 +134,32 @@ class ArpLib(object):
LOG.debug("packet-in msg %s", msg)
datapath = msg.datapath
if self.br is None:
LOG.info(_("No bridge is set"))
LOG.info(_LI("No bridge is set"))
return
if self.br.datapath.id != datapath.id:
LOG.info(_("Unknown bridge %(dpid)s ours %(ours)s"),
LOG.info(_LI("Unknown bridge %(dpid)s ours %(ours)s"),
{"dpid": datapath.id, "ours": self.br.datapath.id})
return
ofp = datapath.ofproto
port = msg.match['in_port']
metadata = msg.match.get('metadata')
pkt = packet.Packet(msg.data)
LOG.info(_("packet-in dpid %(dpid)s in_port %(port)s pkt %(pkt)s"),
LOG.info(_LI("packet-in dpid %(dpid)s in_port %(port)s pkt %(pkt)s"),
{'dpid': dpid_lib.dpid_to_str(datapath.id),
'port': port, 'pkt': pkt})
if metadata is None:
LOG.info(_("drop non tenant packet"))
LOG.info(_LI("drop non tenant packet"))
return
network = metadata & meta.NETWORK_MASK
pkt_ethernet = pkt.get_protocol(ethernet.ethernet)
if not pkt_ethernet:
LOG.info(_("drop non-ethernet packet"))
LOG.info(_LI("drop non-ethernet packet"))
return
pkt_vlan = pkt.get_protocol(vlan.vlan)
pkt_arp = pkt.get_protocol(arp.arp)
if not pkt_arp:
LOG.info(_("drop non-arp packet"))
LOG.info(_LI("drop non-arp packet"))
return
arptbl = self._arp_tbl.get(network)
@ -171,7 +168,7 @@ class ArpLib(object):
pkt_ethernet, pkt_vlan, pkt_arp):
return
else:
LOG.info(_("unknown network %s"), network)
LOG.info(_LI("unknown network %s"), network)
# add a flow to skip a packet-in to a controller.
self.br.arp_passthrough(network=network, tpa=pkt_arp.dst_ip)

96
neutron/plugins/ofagent/agent/ofa_neutron_agent.py
View File

@ -43,6 +43,7 @@ from neutron.common import rpc as n_rpc
from neutron.common import topics
from neutron.common import utils as n_utils
from neutron import context
from neutron.openstack.common.gettextutils import _LE, _LI, _LW
from neutron.openstack.common import log as logging
from neutron.openstack.common import loopingcall
from neutron.plugins.common import constants as p_const
@ -98,7 +99,7 @@ class Bridge(flows.OFAgentIntegrationBridge, ovs_lib.OVSBridge):
int(self.datapath_id, 16))
retry += 1
if retry >= retry_max:
LOG.error(_('Agent terminated!: Failed to get a datapath.'))
LOG.error(_LE('Agent terminated!: Failed to get a datapath.'))
raise SystemExit(1)
time.sleep(1)
self.set_dp(self.datapath)
@ -117,7 +118,7 @@ class Bridge(flows.OFAgentIntegrationBridge, ovs_lib.OVSBridge):
self.set_protocols(protocols)
self.set_controller(controller_names)
except RuntimeError:
LOG.exception(_("Agent terminated"))
LOG.exception(_LE("Agent terminated"))
raise SystemExit(1)
self.find_datapath_id()
self.get_datapath(retry_max)
@ -154,7 +155,7 @@ class OFANeutronAgentRyuApp(app_manager.RyuApp):
try:
agent_config = create_agent_config_map(cfg.CONF)
except ValueError:
LOG.exception(_("Agent failed to create agent config map"))
LOG.exception(_LE("Agent failed to create agent config map"))
raise SystemExit(1)
is_xen_compute_host = ('rootwrap-xen-dom0' in
@ -168,7 +169,7 @@ class OFANeutronAgentRyuApp(app_manager.RyuApp):
self.arplib.set_bridge(agent.int_br)
# Start everything.
LOG.info(_("Agent initialized successfully, now running... "))
LOG.info(_LI("Agent initialized successfully, now running... "))
agent.daemon_loop()
@handler.set_ev_cls(ofp_event.EventOFPPacketIn, handler.MAIN_DISPATCHER)
@ -286,15 +287,15 @@ class OFANeutronAgent(n_rpc.RpcCallback,
self.agent_state)
self.agent_state.pop('start_flag', None)
except Exception:
LOG.exception(_("Failed reporting state!"))
LOG.exception(_LE("Failed reporting state!"))
def _create_tunnel_port_name(self, tunnel_type, ip_address):
try:
ip_hex = '%08x' % netaddr.IPAddress(ip_address, version=4)
return '%s-%s' % (tunnel_type, ip_hex)
except Exception:
LOG.warn(_("Unable to create tunnel port. Invalid remote IP: %s"),
ip_address)
LOG.warn(_LW("Unable to create tunnel port. "
"Invalid remote IP: %s"), ip_address)
def setup_rpc(self):
mac = self.int_br.get_local_port_mac()
@ -342,6 +343,7 @@ class OFANeutronAgent(n_rpc.RpcCallback,
if vif_id in vlan_mapping.vif_ports:
return network_id
@log.log
def port_update(self, context, **kwargs):
port = kwargs.get('port')
# Put the port identifier in the updated_ports set.
@ -349,10 +351,9 @@ class OFANeutronAgent(n_rpc.RpcCallback,
# they are not used since there is no guarantee the notifications
# are processed in the same order as the relevant API requests
self.updated_ports.add(ports.get_normalized_port_name(port['id']))
LOG.debug("port_update received port %s", port['id'])
@log.log
def fdb_add(self, context, fdb_entries):
LOG.debug("fdb_add received")
for lvm, agent_ports in self.get_agent_ports(fdb_entries,
self.local_vlan_map):
if lvm.network_type in self.tunnel_types:
@ -365,8 +366,8 @@ class OFANeutronAgent(n_rpc.RpcCallback,
else:
self._fdb_add_arp(lvm, agent_ports)
@log.log
def fdb_remove(self, context, fdb_entries):
LOG.debug("fdb_remove received")
for lvm, agent_ports in self.get_agent_ports(fdb_entries,
self.local_vlan_map):
if lvm.network_type in self.tunnel_types:
@ -435,8 +436,8 @@ class OFANeutronAgent(n_rpc.RpcCallback,
elif action == 'remove':
self.ryuapp.del_arp_table_entry(local_vid, ip_address)
@log.log
def _fdb_chg_ip(self, context, fdb_entries):
LOG.debug("update chg_ip received")
self.fdb_chg_ip_tun(context, self.int_br, fdb_entries, self.local_ip,
self.local_vlan_map)
@ -452,10 +453,10 @@ class OFANeutronAgent(n_rpc.RpcCallback,
"""
if not self.available_local_vlans:
LOG.error(_("No local VLAN available for net-id=%s"), net_uuid)
LOG.error(_LE("No local VLAN available for net-id=%s"), net_uuid)
return
lvid = self.available_local_vlans.pop()
LOG.info(_("Assigning %(vlan_id)s as local vlan for "
LOG.info(_LI("Assigning %(vlan_id)s as local vlan for "
"net-id=%(net_uuid)s"),
{'vlan_id': lvid, 'net_uuid': net_uuid})
self.local_vlan_map[net_uuid] = LocalVLANMapping(lvid, network_type,
@ -467,7 +468,7 @@ class OFANeutronAgent(n_rpc.RpcCallback,
self.int_br.provision_tenant_tunnel(network_type, lvid,
segmentation_id)
else:
LOG.error(_("Cannot provision %(network_type)s network for "
LOG.error(_LE("Cannot provision %(network_type)s network for "
"net-id=%(net_uuid)s - tunneling disabled"),
{'network_type': network_type,
'net_uuid': net_uuid})
@ -478,7 +479,7 @@ class OFANeutronAgent(n_rpc.RpcCallback,
segmentation_id,
phys_port)
else:
LOG.error(_("Cannot provision %(network_type)s network for "
LOG.error(_LE("Cannot provision %(network_type)s network for "
"net-id=%(net_uuid)s - no bridge for "
"physical_network %(physical_network)s"),
{'network_type': network_type,
@ -488,7 +489,7 @@ class OFANeutronAgent(n_rpc.RpcCallback,
# no flows needed for local networks
pass
else:
LOG.error(_("Cannot provision unknown network type "
LOG.error(_LE("Cannot provision unknown network type "
"%(network_type)s for net-id=%(net_uuid)s"),
{'network_type': network_type,
'net_uuid': net_uuid})
@ -502,10 +503,11 @@ class OFANeutronAgent(n_rpc.RpcCallback,
"""
lvm = self.local_vlan_map.pop(net_uuid, None)
if lvm is None:
LOG.debug(_("Network %s not used on agent."), net_uuid)
LOG.debug("Network %s not used on agent.", net_uuid)
return
LOG.info(_("Reclaiming vlan = %(vlan_id)s from net-id = %(net_uuid)s"),
LOG.info(_LI("Reclaiming vlan = %(vlan_id)s from "
"net-id = %(net_uuid)s"),
{'vlan_id': lvm.vlan,
'net_uuid': net_uuid})
@ -525,7 +527,7 @@ class OFANeutronAgent(n_rpc.RpcCallback,
# no flows needed for local networks
pass
else:
LOG.error(_("Cannot reclaim unknown network type "
LOG.error(_LE("Cannot reclaim unknown network type "
"%(network_type)s for net-id=%(net_uuid)s"),
{'network_type': lvm.network_type,
'net_uuid': net_uuid})
@ -572,7 +574,7 @@ class OFANeutronAgent(n_rpc.RpcCallback,
net_uuid = net_uuid or self.get_net_uuid(vif_id)
if not self.local_vlan_map.get(net_uuid):
LOG.info(_('port_unbound() net_uuid %s not in local_vlan_map'),
LOG.info(_LI('port_unbound() net_uuid %s not in local_vlan_map'),
net_uuid)
return
@ -653,13 +655,13 @@ class OFANeutronAgent(n_rpc.RpcCallback,
self.phys_ofports = {}
ip_wrapper = ip_lib.IPWrapper(self.root_helper)
for physical_network, bridge in bridge_mappings.iteritems():
LOG.info(_("Mapping physical network %(physical_network)s to "
LOG.info(_LI("Mapping physical network %(physical_network)s to "
"bridge %(bridge)s"),
{'physical_network': physical_network,
'bridge': bridge})
# setup physical bridge
if not ip_lib.device_exists(bridge, self.root_helper):
LOG.error(_("Bridge %(bridge)s for physical network "
LOG.error(_LE("Bridge %(bridge)s for physical network "
"%(physical_network)s does not exist. Agent "
"terminated!"),
{'physical_network': physical_network,
@ -715,15 +717,16 @@ class OFANeutronAgent(n_rpc.RpcCallback,
# for being treated. If that does not happen, it is a potential
# error condition of which operators should be aware
if not vif_port.ofport:
LOG.warn(_("VIF port: %s has no ofport configured, and might "
"not be able to transmit"), vif_port.port_name)
LOG.warn(_LW("VIF port: %s has no ofport configured, "
"and might not be able to transmit"),
vif_port.port_name)
if admin_state_up:
self.port_bound(vif_port, network_id, network_type,
physical_network, segmentation_id)
else:
self.port_dead(vif_port)
else:
LOG.debug(_("No VIF port for port %s defined on agent."), port_id)
LOG.debug("No VIF port for port %s defined on agent.", port_id)
def _setup_tunnel_port(self, br, port_name, remote_ip, tunnel_type):
ofport_str = br.add_tunnel_port(port_name,
@ -736,10 +739,10 @@ class OFANeutronAgent(n_rpc.RpcCallback,
try:
ofport = int(ofport_str)
except (TypeError, ValueError):
LOG.exception(_("ofport should have a value that can be "
LOG.exception(_LE("ofport should have a value that can be "
"interpreted as an integer"))
if ofport < 0:
LOG.error(_("Failed to set-up %(type)s tunnel port to %(ip)s"),
LOG.error(_LE("Failed to set-up %(type)s tunnel port to %(ip)s"),
{'type': tunnel_type, 'ip': remote_ip})
return 0
@ -781,12 +784,12 @@ class OFANeutronAgent(n_rpc.RpcCallback,
all_ports = dict((p.normalized_port_name(), p) for p in
self._get_ports(self.int_br) if p.is_neutron_port())
for device in devices:
LOG.debug(_("Processing port %s"), device)
LOG.debug("Processing port %s", device)
if device not in all_ports:
# The port has disappeared and should not be processed
# There is no need to put the port DOWN in the plugin as
# it never went up in the first place
LOG.info(_("Port %s was not found on the integration bridge "
LOG.info(_LI("Port %s was not found on the integration bridge "
"and will therefore not be processed"), device)
continue
port = all_ports[device]
@ -795,13 +798,12 @@ class OFANeutronAgent(n_rpc.RpcCallback,
device,
self.agent_id)
except Exception as e:
LOG.debug(_("Unable to get port details for "
"%(device)s: %(e)s"),
LOG.debug("Unable to get port details for %(device)s: %(e)s",
{'device': device, 'e': e})
resync = True
continue
if 'port_id' in details:
LOG.info(_("Port %(device)s updated. Details: %(details)s"),
LOG.info(_LI("Port %(device)s updated. Details: %(details)s"),
{'device': device, 'details': details})
port.vif_mac = details.get('mac_address')
self.treat_vif_port(port, details['port_id'],
@ -813,16 +815,16 @@ class OFANeutronAgent(n_rpc.RpcCallback,
# update plugin about port status
if details.get('admin_state_up'):
LOG.debug(_("Setting status for %s to UP"), device)
LOG.debug("Setting status for %s to UP", device)
self.plugin_rpc.update_device_up(
self.context, device, self.agent_id, cfg.CONF.host)
else:
LOG.debug(_("Setting status for %s to DOWN"), device)
LOG.debug("Setting status for %s to DOWN", device)
self.plugin_rpc.update_device_down(
self.context, device, self.agent_id, cfg.CONF.host)
LOG.info(_("Configuration for device %s completed."), device)
LOG.info(_LI("Configuration for device %s completed."), device)
else:
LOG.warn(_("Device %s not defined on plugin"), device)
LOG.warn(_LW("Device %s not defined on plugin"), device)
if (port and port.ofport != -1):
self.port_dead(port)
return resync
@ -831,14 +833,14 @@ class OFANeutronAgent(n_rpc.RpcCallback,
resync = False
self.sg_agent.remove_devices_filter(devices)
for device in devices:
LOG.info(_("Attachment %s removed"), device)
LOG.info(_LI("Attachment %s removed"), device)
try:
self.plugin_rpc.update_device_down(self.context,
device,
self.agent_id,
cfg.CONF.host)
except Exception as e:
LOG.debug(_("port_removed failed for %(device)s: %(e)s"),
LOG.debug("port_removed failed for %(device)s: %(e)s",
{'device': device, 'e': e})
resync = True
continue
@ -863,16 +865,16 @@ class OFANeutronAgent(n_rpc.RpcCallback,
start = time.time()
resync_add = self.treat_devices_added_or_updated(
devices_added_updated)
LOG.debug(_("process_network_ports - iteration:%(iter_num)d - "
LOG.debug("process_network_ports - iteration:%(iter_num)d - "
"treat_devices_added_or_updated completed "
"in %(elapsed).3f"),
"in %(elapsed).3f",
{'iter_num': self.iter_num,
'elapsed': time.time() - start})
if 'removed' in port_info:
start = time.time()
resync_removed = self.treat_devices_removed(port_info['removed'])
LOG.debug(_("process_network_ports - iteration:%(iter_num)d - "
"treat_devices_removed completed in %(elapsed).3f"),
LOG.debug("process_network_ports - iteration:%(iter_num)d - "
"treat_devices_removed completed in %(elapsed).3f",
{'iter_num': self.iter_num,
'elapsed': time.time() - start})
# If one of the above opertaions fails => resync with plugin
@ -886,7 +888,7 @@ class OFANeutronAgent(n_rpc.RpcCallback,
self.local_ip,
tunnel_type)
except Exception as e:
LOG.debug(_("Unable to sync tunnel IP %(local_ip)s: %(e)s"),
LOG.debug("Unable to sync tunnel IP %(local_ip)s: %(e)s",
{'local_ip': self.local_ip, 'e': e})
resync = True
return resync
@ -909,16 +911,16 @@ class OFANeutronAgent(n_rpc.RpcCallback,
LOG.debug("Agent daemon_loop - iteration:%d started",
self.iter_num)
if sync:
LOG.info(_("Agent out of sync with plugin!"))
LOG.info(_LI("Agent out of sync with plugin!"))
ports.clear()
sync = False
# Notify the plugin of tunnel IP
if self.enable_tunneling and tunnel_sync:
LOG.info(_("Agent tunnel out of sync with plugin!"))
LOG.info(_LI("Agent tunnel out of sync with plugin!"))
try:
tunnel_sync = self.tunnel_sync()
except Exception:
LOG.exception(_("Error while synchronizing tunnels"))
LOG.exception(_LE("Error while synchronizing tunnels"))
tunnel_sync = True
LOG.debug("Agent daemon_loop - iteration:%(iter_num)d - "
"starting polling. Elapsed:%(elapsed).3f",
@ -958,7 +960,7 @@ class OFANeutronAgent(n_rpc.RpcCallback,
port_stats['regular']['removed'] = (
len(port_info.get('removed', [])))
except Exception:
LOG.exception(_("Error while processing VIF ports"))
LOG.exception(_LE("Error while processing VIF ports"))
# Put the ports back in self.updated_port
self.updated_ports |= updated_ports_copy
sync = True