From: YAMAMOTO Takashi Date: Mon, 8 Sep 2014 02:29:05 +0000 (+0900) Subject: ofagent: Clean up logging X-Git-Url: https://review.fuel-infra.org/gitweb?a=commitdiff_plain;h=49546cc106972af1f476e7809daaa6a844c052d3;p=openstack-build%2Fneutron-build.git ofagent: Clean up logging - Use _LI, _LW, _LE - Remove localization from debug logs - Replace LOG.debug calls with @log.log decorator where appropriate Change-Id: I9c80c556003db7b0b8e99da0340a26beb1e00e16 --- diff --git a/neutron/plugins/ofagent/agent/arp_lib.py b/neutron/plugins/ofagent/agent/arp_lib.py index 403227344..c83e94352 100644 --- a/neutron/plugins/ofagent/agent/arp_lib.py +++ b/neutron/plugins/ofagent/agent/arp_lib.py @@ -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) diff --git a/neutron/plugins/ofagent/agent/ofa_neutron_agent.py b/neutron/plugins/ofagent/agent/ofa_neutron_agent.py index 15c3735d3..de1516933 100644 --- a/neutron/plugins/ofagent/agent/ofa_neutron_agent.py +++ b/neutron/plugins/ofagent/agent/ofa_neutron_agent.py @@ -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,11 +453,11 @@ 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 " - "net-id=%(net_uuid)s"), + 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, physical_network, @@ -467,8 +468,8 @@ 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 " - "net-id=%(net_uuid)s - tunneling disabled"), + 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}) elif network_type in [p_const.TYPE_VLAN, p_const.TYPE_FLAT]: @@ -478,9 +479,9 @@ class OFANeutronAgent(n_rpc.RpcCallback, segmentation_id, phys_port) else: - LOG.error(_("Cannot provision %(network_type)s network for " - "net-id=%(net_uuid)s - no bridge for " - "physical_network %(physical_network)s"), + 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, 'net_uuid': net_uuid, 'physical_network': physical_network}) @@ -488,8 +489,8 @@ class OFANeutronAgent(n_rpc.RpcCallback, # no flows needed for local networks pass else: - LOG.error(_("Cannot provision unknown network type " - "%(network_type)s for net-id=%(net_uuid)s"), + 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,8 +527,8 @@ class OFANeutronAgent(n_rpc.RpcCallback, # no flows needed for local networks pass else: - LOG.error(_("Cannot reclaim unknown network type " - "%(network_type)s for net-id=%(net_uuid)s"), + 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,15 +655,15 @@ 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 " - "bridge %(bridge)s"), + 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 " - "%(physical_network)s does not exist. Agent " - "terminated!"), + LOG.error(_LE("Bridge %(bridge)s for physical network " + "%(physical_network)s does not exist. Agent " + "terminated!"), {'physical_network': physical_network, 'bridge': bridge}) raise SystemExit(1) @@ -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 " - "interpreted as an integer")) + 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,13 +784,13 @@ 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 " - "and will therefore not be processed"), device) + LOG.info(_LI("Port %s was not found on the integration bridge " + "and will therefore not be processed"), device) continue port = all_ports[device] try: @@ -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 - " - "treat_devices_added_or_updated completed " - "in %(elapsed).3f"), + LOG.debug("process_network_ports - iteration:%(iter_num)d - " + "treat_devices_added_or_updated completed " + "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