From: Dimitris Aragiorgis Date: Wed, 19 Feb 2014 17:23:37 +0000 (+0200) Subject: Change logging to be more informative X-Git-Tag: 0.12.3~1^2 X-Git-Url: https://code.grnet.gr/git/snf-nfdhcpd/commitdiff_plain/2048471aab7f772d79b2fb56c1f9c584e61ab852 Change logging to be more informative Signed-off-by: Dimitris Aragiorgis --- diff --git a/nfdhcpd b/nfdhcpd index c66c435..25b4a96 100755 --- a/nfdhcpd +++ b/nfdhcpd @@ -281,6 +281,15 @@ class Client(object): logging.warn(" - Truncated msg: %d/%d bytes sent", count, ldata) + def __repr__(self): + ret = "hostname %s, tap %s, mac %s" % \ + (self.hostname, self.tap, self.mac) + if self.ip: + ret += ", ip %s" % self.ip + if self.eui64: + ret += ", eui64 %s" % self.eui64 + return ret + class Subnet(object): def __init__(self, net=None, gw=None, dev=None): @@ -428,10 +437,11 @@ class VMNetProxy(object): # pylint: disable=R0902 else: logging.debug(" - Getting binding for ifindex %s", ifindex) b = self.clients[ifindex] + logging.info(" - Client found. %s", b) return b except KeyError: - logging.debug(" - No client found for mac / ifindex %s / %s", - mac, ifindex) + logging.info(" - No client found. mac: %s, ifindex: %s", + mac, ifindex) return None def _cleanup(self): @@ -554,9 +564,7 @@ class VMNetProxy(object): # pylint: disable=R0902 else: self.clients[ifindex] = b k = ifindex - logging.info(" - Added client:") - logging.info(" + %10s | %20s %20s %10s %20s %40s", - k, b.hostname, b.mac, b.tap, b.ip, b.eui64) + logging.info(" - Added client %s. %s", k, b) def remove_tap(self, tap): """ Cleanup clients on a removed interface @@ -565,12 +573,9 @@ class VMNetProxy(object): # pylint: disable=R0902 try: for k, cl in self.clients.items(): if cl.tap == tap: - logging.info("Removing client %s and closing socket on %s", - cl.hostname, cl.tap) - logging.info(" - %10s | %20s %20s %10s %20s %40s", - k, cl.hostname, cl.mac, cl.tap, cl.ip, cl.eui64) cl.socket.close() del self.clients[k] + logging.info("Removed client %s. %s", k, cl) except: logging.debug("Client on %s disappeared!!!", tap) @@ -579,7 +584,7 @@ class VMNetProxy(object): # pylint: disable=R0902 """ Generate a reply to bnetfilter-queue-deva BOOTP/DHCP request """ - logging.info(" * Processing pending DHCP request") + logging.info(" * DHCP: Processing pending request") # Workaround for supporting both squeezy's nfqueue-bindings-python # and wheezy's python-nfqueue because for some reason the function's # signature has changed and has broken compatibility @@ -607,10 +612,7 @@ class VMNetProxy(object): # pylint: disable=R0902 binding = self.get_binding(indev, mac) if binding is None: # We don't know anything about this interface, so accept the packet - # and return - logging.debug(" - Ignoring DHCP request on unknown iface %s", indev) - # We don't know what to do with this packet, so let the kernel - # handle it + # and return an let the kernel handle it payload.set_verdict(nfqueue.NF_ACCEPT) return @@ -618,29 +620,23 @@ class VMNetProxy(object): # pylint: disable=R0902 payload.set_verdict(nfqueue.NF_DROP) if mac != binding.mac: - logging.warn(" - Recieved spoofed DHCP request: mac %s, indev %s", - mac, indev) + logging.warn(" - DHCP: Recieved spoofed request from %s (and not %s)", + mac, binding) return if not binding.ip: - logging.info(" - No IP found in binding file.") + logging.info(" - DHCP: No IP found in binding file %s.", binding) return - logging.info(" - Generating DHCP response:" - " host %s, mac %s, tap %s, indev %s", - binding.hostname, mac, binding.tap, indev) - + if not DHCP in pkt: + logging.warn(" - DHCP: Invalid request with no DHCP payload found. %s", binding) + return resp = Ether(dst=mac, src=self.get_iface_hw_addr(binding.indev))/\ IP(src=DHCP_DUMMY_SERVER_IP, dst=binding.ip)/\ UDP(sport=pkt.dport, dport=pkt.sport)/resp subnet = binding.net - if not DHCP in pkt: - logging.warn(" - Invalid request from %s on %s, no DHCP" - " payload found", binding.mac, binding.tap) - return - dhcp_options = [] requested_addr = binding.ip for opt in pkt[DHCP].options: @@ -649,8 +645,8 @@ class VMNetProxy(object): # pylint: disable=R0902 if type(opt) is tuple and opt[0] == "requested_addr": requested_addr = opt[1] - logging.info(" - %s from %s on %s", DHCP_TYPES.get(req_type, "UNKNOWN"), - binding.mac, binding.tap) + logging.info(" - DHCP: %s from %s", + DHCP_TYPES.get(req_type, "UNKNOWN"), binding) if self.dhcp_domain: domainname = self.dhcp_domain @@ -659,9 +655,8 @@ class VMNetProxy(object): # pylint: disable=R0902 if req_type == DHCPREQUEST and requested_addr != binding.ip: resp_type = DHCPNAK - logging.info(" - Sending DHCPNAK to %s on %s: requested %s" - " instead of %s", binding.mac, binding.tap, - requested_addr, binding.ip) + logging.info(" - DHCP: Sending DHCPNAK to %s (because requested %s)", + binding, requested_addr) elif req_type in (DHCPDISCOVER, DHCPREQUEST): resp_type = DHCP_REQRESP[req_type] @@ -688,8 +683,7 @@ class VMNetProxy(object): # pylint: disable=R0902 elif req_type == DHCPRELEASE: # Log and ignore - logging.info(" - DHCPRELEASE from %s on %s", - binding.hostname, binding.tap) + logging.info(" - DHCP: DHCPRELEASE from %s", binding) return # Finally, always add the server identifier and end options @@ -700,20 +694,18 @@ class VMNetProxy(object): # pylint: disable=R0902 ] resp /= DHCP(options=dhcp_options) - logging.info(" - %s to %s (%s) on %s", DHCP_TYPES[resp_type], mac, - binding.ip, binding.tap) + logging.info(" - RESPONSE: %s for %s", DHCP_TYPES[resp_type], binding) try: binding.sendp(resp) except socket.error, e: - logging.warn(" - DHCP response on %s (%s) failed: %s", - binding.tap, binding.hostname, str(e)) + logging.warn(" - DHCP: Response on %s failed: %s", binding, str(e)) except Exception, e: - logging.warn(" - Unkown error during DHCP response on %s (%s): %s", - binding.tap, binding.hostname, str(e)) + logging.warn(" - DHCP: Unkown error during response on %s: %s", + binding, str(e)) def dhcpv6_response(self, arg1, arg2=None): # pylint: disable=W0613 - logging.info(" * Processing pending DHCPv6 request") + logging.info(" * DHCPv6: Processing pending request") # Workaround for supporting both squeezy's nfqueue-bindings-python # and wheezy's python-nfqueue because for some reason the function's # signature has changed and has broken compatibility @@ -730,10 +722,7 @@ class VMNetProxy(object): # pylint: disable=R0902 binding = self.get_binding(indev, mac) if binding is None: # We don't know anything about this interface, so accept the packet - # and return - logging.debug(" - Ignoring dhcpv6 request for mac %s", mac) - # We don't know what to do with this packet, so let the kernel - # handle it + # and return and let the kernel handle it payload.set_verdict(nfqueue.NF_ACCEPT) return @@ -743,7 +732,7 @@ class VMNetProxy(object): # pylint: disable=R0902 subnet = binding.net6 if subnet.net is None: - logging.debug(" - No IPv6 network assigned for tap %s", binding.tap) + logging.debug(" - DHCPv6: No IPv6 network assigned to %s", binding) return indevmac = self.get_iface_hw_addr(binding.indev) @@ -755,9 +744,6 @@ class VMNetProxy(object): # pylint: disable=R0902 if ofll is None: return - logging.info(" - Generating DHCPv6 response for host %s (mac %s) on tap %s", - binding.hostname, binding.mac, binding.tap) - if self.dhcpv6_domains: domains = self.dhcpv6_domains else: @@ -776,21 +762,23 @@ class VMNetProxy(object): # pylint: disable=R0902 DHCP6OptDNSDomains(dnsdomains)/\ DHCP6OptDNSServers(dnsservers) + logging.info(" - RESPONSE: DHCPv6 reply for %s", binding) + try: binding.sendp(resp) except socket.error, e: - logging.warn(" - DHCPv6 on %s (%s) failed: %s", - binding.tap, binding.hostname, str(e)) + logging.warn(" - DHCPv6: Response on %s failed: %s", + binding, str(e)) except Exception, e: - logging.warn(" - Unkown error during DHCPv6 on %s (%s): %s", - binding.tap, binding.hostname, str(e)) + logging.warn(" - DHCPv6: Unkown error during response on %s: %s", + binding, str(e)) def rs_response(self, arg1, arg2=None): # pylint: disable=W0613 - """ Generate a reply to a BOOTP/DHCP request + """ Generate a reply to an ICMPv6 router solicitation """ - logging.info(" * Processing pending RS request") + logging.info(" * RS: Processing pending request") # Workaround for supporting both squeezy's nfqueue-bindings-python # and wheezy's python-nfqueue because for some reason the function's # signature has changed and has broken compatibility @@ -804,7 +792,7 @@ class VMNetProxy(object): # pylint: disable=R0902 try: mac = pkt.lladdr except: - logging.debug(" - Cannot obtain lladdr in rs") + logging.debug(" - RS: Cannot obtain lladdr") return indev = get_indev(payload) @@ -812,10 +800,7 @@ class VMNetProxy(object): # pylint: disable=R0902 binding = self.get_binding(indev, mac) if binding is None: # We don't know anything about this interface, so accept the packet - # and return - logging.debug(" - Ignoring router solicitation on for mac %s", mac) - # We don't know what to do with this packet, so let the kernel - # handle it + # and return and let the kernel handle it payload.set_verdict(nfqueue.NF_ACCEPT) return @@ -823,14 +808,14 @@ class VMNetProxy(object): # pylint: disable=R0902 payload.set_verdict(nfqueue.NF_DROP) if mac != binding.mac: - logging.warn(" - Received spoofed RS request: mac %s, tap %s", - mac, binding.tap) + logging.warn(" - RS: Received spoofed request from %s (and not %s)", + mac, binding) return subnet = binding.net6 if subnet.net is None: - logging.debug(" - No IPv6 network assigned for tap %s", binding.tap) + logging.debug(" - RS: No IPv6 network assigned to %s", binding) return indevmac = self.get_iface_hw_addr(binding.indev) @@ -838,9 +823,6 @@ class VMNetProxy(object): # pylint: disable=R0902 if ifll is None: return - logging.info(" - Generating RA for host %s (mac %s) on tap %s", - binding.hostname, mac, binding.tap) - resp = Ether(src=indevmac)/\ IPv6(src=str(ifll))/ICMPv6ND_RA(O=1, routerlifetime=14400)/\ ICMPv6NDOptPrefixInfo(prefix=str(subnet.prefix), @@ -850,21 +832,23 @@ class VMNetProxy(object): # pylint: disable=R0902 resp /= ICMPv6NDOptRDNSS(dns=self.ipv6_nameservers, lifetime=self.ra_period * 3) + logging.info(" - RESPONSE: RA for %s", binding) + try: binding.sendp(resp) except socket.error, e: - logging.warn(" - RA on %s (%s) failed: %s", - binding.tap, binding.hostname, str(e)) + logging.warn(" - RS: RA failed on %s: %s", + binding, str(e)) except Exception, e: - logging.warn(" - Unkown error during RA on %s (%s): %s", - binding.tap, binding.hostname, str(e)) + logging.warn(" - RS: Unkown error during RA on %s: %s", + binding, str(e)) def ns_response(self, arg1, arg2=None): # pylint: disable=W0613 """ Generate a reply to an ICMPv6 neighbor solicitation """ - logging.info(" * Processing pending NS request") + logging.info(" * NS: Processing pending request") # Workaround for supporting both squeezy's nfqueue-bindings-python # and wheezy's python-nfqueue because for some reason the function's # signature has changed and has broken compatibility @@ -879,7 +863,7 @@ class VMNetProxy(object): # pylint: disable=R0902 try: mac = ns.lladdr except: - logging.debug(" - Cannot obtain lladdr from ns") + logging.debug(" - NS: Cannot obtain lladdr") return @@ -888,24 +872,20 @@ class VMNetProxy(object): # pylint: disable=R0902 binding = self.get_binding(indev, mac) if binding is None: # We don't know anything about this interface, so accept the packet - # and return - logging.debug(" - Ignoring neighbour solicitation for eui64 %s", - ns.tgt) - # We don't know what to do with this packet, so let the kernel - # handle it + # and return and let the kernel handle it payload.set_verdict(nfqueue.NF_ACCEPT) return payload.set_verdict(nfqueue.NF_DROP) if mac != binding.mac: - logging.warn(" - Received spoofed NS request" - " for mac %s from tap %s", mac, binding.tap) + logging.warn(" - NS: Received spoofed request from %s (and not %s)", + mac, binding) return subnet = binding.net6 if subnet.net is None: - logging.debug(" - No IPv6 network assigned for the interface") + logging.debug(" - NS: No IPv6 network assigned to %s", binding) return indevmac = self.get_iface_hw_addr(binding.indev) @@ -915,25 +895,24 @@ class VMNetProxy(object): # pylint: disable=R0902 return if not (subnet.net.overlaps(ns.tgt) or str(ns.tgt) == str(ifll)): - logging.debug(" - Received NS for a non-routable IP (%s)", ns.tgt) + logging.debug(" - NS: Received NS for a non-routable IP (%s)", ns.tgt) return 1 - logging.info(" - Generating NA for host %s (mac %s) on tap %s", - binding.hostname, mac, binding.tap) - resp = Ether(src=indevmac, dst=binding.mac)/\ IPv6(src=str(ifll), dst=ns.src)/\ ICMPv6ND_NA(R=1, O=0, S=1, tgt=ns.tgt)/\ ICMPv6NDOptDstLLAddr(lladdr=indevmac) + logging.info(" - RESPONSE: NA for %s ", binding) + try: binding.sendp(resp) except socket.error, e: - logging.warn(" - NA on %s (%s) failed: %s", - binding.tap, binding.hostname, str(e)) + logging.warn(" - NS: NA on %s failed: %s", + binding, str(e)) except Exception, e: - logging.warn(" - Unkown error during periodic NA to %s (%s): %s", - binding.tap, binding.hostname, str(e)) + logging.warn(" - NS: Unkown error during NA to %s: %s", + binding, str(e)) def send_periodic_ra(self): # Use a separate thread as this may take a _long_ time with @@ -941,7 +920,7 @@ class VMNetProxy(object): # pylint: disable=R0902 threading.Thread(target=self._send_periodic_ra).start() def _send_periodic_ra(self): - logging.info("Sending out periodic RAs") + logging.info(" * Periodic RA: Starting...") start = time.time() i = 0 for binding in self.clients.values(): @@ -950,8 +929,7 @@ class VMNetProxy(object): # pylint: disable=R0902 # mac = binding.mac subnet = binding.net6 if subnet.net is None: - logging.debug(" - Skipping periodic RA on interface %s," - " as it is not IPv6-connected", tap) + logging.debug(" - Periodic RA: Skipping %s", binding) continue indevmac = self.get_iface_hw_addr(indev) ifll = subnet.make_ll64(indevmac) @@ -964,16 +942,17 @@ class VMNetProxy(object): # pylint: disable=R0902 if self.ipv6_nameservers: resp /= ICMPv6NDOptRDNSS(dns=self.ipv6_nameservers, lifetime=self.ra_period * 3) + logging.info(" - RESPONSE: NA for %s ", binding) try: binding.sendp(resp) except socket.error, e: - logging.warn(" - Periodic RA on %s (%s) failed: %s", - tap, binding.hostname, str(e)) + logging.warn(" - Periodic RA: Failed on %s: %s", + binding, str(e)) except Exception, e: - logging.warn(" - Unkown error during periodic RA on %s (%s):" - " %s", tap, binding.hostname, str(e)) + logging.warn(" - Periodic RA: Unkown error on %s: %s", + binding, str(e)) i += 1 - logging.info(" - Sent %d RAs in %.2f seconds", i, time.time() - start) + logging.info(" - Periodic RA: Sent %d RAs in %.2f seconds", i, time.time() - start) def serve(self): """ Safely perform the main loop, freeing all resources upon exit