From 0fbb25c0fdb926a01a9e5be1c4f977412b51b359 Mon Sep 17 00:00:00 2001
From: Dimitris Aragiorgis <dimara@grnet.gr>
Date: Mon, 17 Sep 2012 00:23:33 +0300
Subject: [PATCH] Nice logging

Signed-off-by: Dimitris Aragiorgis <dimara@grnet.gr>
---
 nfdhcpd | 152 ++++++++++++++++++++++++++++++--------------------------
 1 file changed, 81 insertions(+), 71 deletions(-)

diff --git a/nfdhcpd b/nfdhcpd
index ec1e63c..c23ffab 100755
--- a/nfdhcpd
+++ b/nfdhcpd
@@ -123,15 +123,15 @@ def get_indev(payload):
     try:
         indev_ifindex = payload.get_physindev()
         if indev_ifindex:
-            logging.debug("Incomming packet from bridge %s", indev_ifindex)
+            logging.debug(" - Incomming packet from bridge %s", indev_ifindex)
             return indev_ifindex
     except AttributeError:
         #TODO: return error value
-        logging.debug("No get_physindev supported")
+        logging.debug("No get_physindev() supported")
         return 0
 
     indev_ifindex = payload.get_indev()
-    logging.debug("Incomming packet from tap %s", indev_ifindex)
+    logging.debug(" - Incomming packet from tap %s", indev_ifindex)
 
     return indev_ifindex
 
@@ -139,14 +139,15 @@ def get_indev(payload):
 def get_binding(proxy, ifindex, mac):
     try:
         if proxy.mac_indexed_clients:
-            logging.debug("Getting binding for mac %s", mac)
+            logging.debug(" - Getting binding for mac %s", mac)
             b = proxy.clients[mac]
         else:
-            logging.debug("Getting binding for ifindex %s", ifindex)
+            logging.debug(" - Getting binding for ifindex %s", ifindex)
             b = proxy.clients[ifindex]
         return b
     except KeyError:
-        logging.debug("No client found for mac/ifindex %s/%s", mac, ifindex)
+        logging.debug(" - No client found for mac / ifindex %s / %s",
+                      mac, ifindex)
         return None
 
 
@@ -158,7 +159,7 @@ def parse_binding_file(path):
     try:
         iffile = open(path, 'r')
     except EnvironmentError, e:
-        logging.warn("Unable to open binding file %s: %s", path, str(e))
+        logging.warn(" - Unable to open binding file %s: %s", path, str(e))
         return None
 
     tap = os.path.basename(path)
@@ -203,7 +204,7 @@ def parse_binding_file(path):
                       indev=indev, subnet=subnet, gateway=gateway,
                       subnet6=subnet6, gateway6=gateway6, eui64=eui64 )
     except ValueError:
-        logging.warning("Cannot add client for host %s and IP %s on tap %s",
+        logging.warning(" - Cannot add client for host %s and IP %s on tap %s",
                         hostname, ip, tap)
         return None
 
@@ -257,7 +258,7 @@ class Subnet(object):
             try:
                 self.net = IPy.IP(net)
             except ValueError, e:
-                logging.warning("IPy error: %s", e)
+                logging.warning(" - IPy error: %s", e)
                 raise e
         else:
             self.net = net
@@ -386,7 +387,7 @@ class VMNetProxy(object):  # pylint: disable=R0902
             s = socket.socket(socket.AF_PACKET, socket.SOCK_RAW, ETH_P_ALL)
             s.setsockopt(socket.SOL_SOCKET, socket.SO_RCVBUF, 0)
         except socket.error, e:
-            logging.warning("Cannot open socket %s", e)
+            logging.warning(" - Cannot open socket %s", e)
         return s
 
     def _cleanup(self):
@@ -395,17 +396,17 @@ class VMNetProxy(object):  # pylint: disable=R0902
         """
         logging.info("Cleaning up")
 
-        logging.debug("Closing netfilter queues")
+        logging.debug(" - Closing netfilter queues")
         for q in self.nfq.values():
             q.close()
 
-        logging.debug("Closing socket")
+        logging.debug(" - Closing socket")
         self.l2socket.close()
 
-        logging.debug("Stopping inotify watches")
+        logging.debug(" - Stopping inotify watches")
         self.notifier.stop()
 
-        logging.info("Cleanup finished")
+        logging.info(" - Cleanup finished")
 
     def _setup_nfqueue(self, queue_num, family, callback):
         logging.info("Setting up NFQUEUE for queue %d, AF %s",
@@ -413,11 +414,11 @@ class VMNetProxy(object):  # pylint: disable=R0902
         q = nfqueue.queue()
         q.set_callback(callback)
         q.fast_open(queue_num, family)
-        q.set_queue_maxlen(5000)
+        q.set_queue_maxlen(30)
         # This is mandatory for the queue to operate
         q.set_mode(nfqueue.NFQNL_COPY_PACKET)
         self.nfq[q.get_fd()] = q
-        logging.debug("Successfully set up NFQUEUE %d", queue_num)
+        logging.debug(" - Successfully set up NFQUEUE %d", queue_num)
 
     def sendp(self, data, dev):
         """ Send a raw packet using a layer-2 socket
@@ -426,21 +427,21 @@ class VMNetProxy(object):  # pylint: disable=R0902
         if isinstance(data, BasePacket):
             data = str(data)
 
-        logging.debug("Sending raw packet %r", data)
+        logging.debug(" - Sending raw packet %s", data)
 
         self.l2socket.bind((dev, ETH_P_ALL))
         try:
             count = self.l2socket.send(data, socket.MSG_DONTWAIT)
         except socket.error, e:
-            logging.warn("Send with MSG_DONTWAIT failed: %s", str(e))
+            logging.warn(" - Send with MSG_DONTWAIT failed: %s", str(e))
             self.l2socket.close()
             self.l2socket = self._socket()
             raise e
 
         ldata = len(data)
-        logging.debug("Sent %d bytes to device %s", count, dev)
+        logging.debug(" - Sent %d bytes to device %s", count, dev)
         if count != ldata:
-            logging.warn("Truncated send on %s (%d/%d bytes sent)",
+            logging.warn(" - Truncated send on %s (%d/%d bytes sent)",
                          dev, count, ldata)
 
     def build_config(self):
@@ -457,7 +458,7 @@ class VMNetProxy(object):  # pylint: disable=R0902
         """ Get the interface index from sysfs
 
         """
-        logging.debug("Getting ifindex for interface %s from sysfs", iface)
+        logging.debug(" - Getting ifindex for interface %s from sysfs", iface)
 
         path = os.path.abspath(os.path.join(SYSFS_NET, iface, "ifindex"))
         if not path.startswith(SYSFS_NET):
@@ -468,7 +469,7 @@ class VMNetProxy(object):  # pylint: disable=R0902
         try:
             f = open(path, 'r')
         except EnvironmentError:
-            logging.debug("%s is probably down, removing", iface)
+            logging.debug(" - %s is probably down, removing", iface)
             self.remove_tap(iface)
 
             return ifindex
@@ -478,10 +479,10 @@ class VMNetProxy(object):  # pylint: disable=R0902
             try:
                 ifindex = int(ifindex)
             except ValueError, e:
-                logging.warn("Failed to get ifindex for %s, cannot parse sysfs"
-                             " output '%s'", iface, ifindex)
+                logging.warn(" - Failed to get ifindex for %s, cannot parse"
+                             " sysfs output '%s'", iface, ifindex)
         except EnvironmentError, e:
-            logging.warn("Error reading %s's ifindex from sysfs: %s",
+            logging.warn(" - Error reading %s's ifindex from sysfs: %s",
                          iface, str(e))
             self.remove_tap(iface)
         finally:
@@ -493,7 +494,7 @@ class VMNetProxy(object):  # pylint: disable=R0902
         """ Get the interface hardware address from sysfs
 
         """
-        logging.debug("Getting mac for iface %s", iface)
+        logging.debug(" - Getting mac for iface %s", iface)
         path = os.path.abspath(os.path.join(SYSFS_NET, iface, "address"))
         if not path.startswith(SYSFS_NET):
             return None
@@ -502,14 +503,14 @@ class VMNetProxy(object):  # pylint: disable=R0902
         try:
             f = open(path, 'r')
         except EnvironmentError:
-            logging.debug("%s is probably down, removing", iface)
+            logging.debug(" - %s is probably down, removing", iface)
             self.remove_tap(iface)
             return addr
 
         try:
             addr = f.readline().strip()
         except EnvironmentError, e:
-            logging.warn("Failed to read hw address for %s from sysfs: %s",
+            logging.warn(" - Failed to read hw address for %s from sysfs: %s",
                          iface, str(e))
         finally:
             f.close()
@@ -529,15 +530,15 @@ class VMNetProxy(object):  # pylint: disable=R0902
         ifindex = self.get_ifindex(b.tap)
 
         if ifindex is None:
-            logging.warn("Stale configuration for %s found", tap)
+            logging.warn(" - Stale configuration for %s found", tap)
         else:
             if b.is_valid():
                 if self.mac_indexed_clients:
                     self.clients[b.mac] = b
                 else:
                     self.clients[ifindex] = b
-                logging.debug("Added client:")
-                logging.debug("%5s: %10s %20s %7s %15s",
+                logging.debug(" - Added client:")
+                logging.debug(" + %5s: %10s %20s %7s %15s",
                                ifindex, b.hostname, b.mac, b.tap, b.ip)
 
     def remove_tap(self, tap):
@@ -549,8 +550,8 @@ class VMNetProxy(object):  # pylint: disable=R0902
                 b = self.clients[k]
                 if self.clients[k].tap == tap:
                     logging.debug("Removing client on interface %s", tap)
-                    logging.debug("%10s %20s %7s %15s",
-                                  b.hostname, b.mac, b.tap, b.ip)
+                    logging.debug(" - %5s: %10s %20s %7s %15s",
+                                  k, b.hostname, b.mac, b.tap, b.ip)
                     del self.clients[k]
         except:
             logging.debug("Client on %s disappeared!!!", tap)
@@ -559,9 +560,9 @@ class VMNetProxy(object):  # pylint: disable=R0902
         """ Generate a reply to bnetfilter-queue-deva BOOTP/DHCP request
 
         """
+        logging.debug(" * Processing pending DHCP request (NFQUEUE %d)", i)
         # Decode the response - NFQUEUE relays IP packets
         pkt = IP(payload.get_data())
-        logging.debug("Generating DHCP response")
         #logging.debug(pkt.show())
 
         # Get the client MAC address
@@ -580,7 +581,7 @@ class VMNetProxy(object):  # pylint: disable=R0902
         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 %d", indev)
+            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
             payload.set_verdict(nfqueue.NF_ACCEPT)
@@ -590,17 +591,20 @@ class VMNetProxy(object):  # pylint: disable=R0902
         payload.set_verdict(nfqueue.NF_DROP)
 
         if mac != binding.mac:
-            logging.warn("Received spoofed DHCP request for mac %s, tap %s",
-                         mac, indev)
+            logging.warn(" - Recieved spoofed DHCP request for mac %s from tap %s", mac, indev)
             return
 
+        logging.debug(" - Generating DHCP response for host %s (mac %s) on tap %s",
+                       binding.hostname, mac, binding.tap)
+
+
         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"
+            logging.warn(" - Invalid request from %s on %s, no DHCP"
                          " payload found", binding.mac, binding.tap)
             return
 
@@ -612,7 +616,7 @@ 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"),
+        logging.info(" - %s from %s on %s", DHCP_TYPES.get(req_type, "UNKNOWN"),
                      binding.mac, binding.tap)
 
         if self.dhcp_domain:
@@ -622,7 +626,7 @@ 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"
+            logging.info(" - Sending DHCPNAK to %s on %s: requested %s"
                          " instead of %s", binding.mac, binding.tap,
                          requested_addr, binding.ip)
 
@@ -651,7 +655,7 @@ class VMNetProxy(object):  # pylint: disable=R0902
 
         elif req_type == DHCPRELEASE:
             # Log and ignore
-            logging.info("DHCPRELEASE from %s on %s", binding.mac, binding.tap)
+            logging.info(" - DHCPRELEASE from %s on %s", binding.mac, binding.tap)
             return
 
         # Finally, always add the server identifier and end options
@@ -662,38 +666,36 @@ class VMNetProxy(object):  # pylint: disable=R0902
         ]
         resp /= DHCP(options=dhcp_options)
 
-        logging.info("%s to %s (%s) on %s", DHCP_TYPES[resp_type], mac,
+        logging.info(" - %s to %s (%s) on %s", DHCP_TYPES[resp_type], mac,
                      binding.ip, binding.tap)
         try:
             self.sendp(resp, binding.indev)
         except socket.error, e:
-            logging.warn("DHCP response on %s failed: %s", binding.indev, str(e))
+            logging.warn(" - DHCP response on %s failed: %s", binding.indev, str(e))
         except Exception, e:
-            logging.warn("Unkown error during DHCP response on %s: %s",
+            logging.warn(" - Unkown error during DHCP response on %s: %s",
                          binding.indev, str(e))
 
     def rs_response(self, i, payload):  # pylint: disable=W0613
         """ Generate a reply to a BOOTP/DHCP request
 
         """
-
+        logging.debug(" * Processing pending RS request (NFQUEUE %d)", i)
         pkt = IPv6(payload.get_data())
         #logging.debug(pkt.show())
         try:
             mac = pkt.lladdr
         except:
-            logging.debug("Cannot obtain lladdr in rs")
+            logging.debug(" - Cannot obtain lladdr in rs")
             return
 
-        logging.debug("Generating an rs response for mac %s", mac)
-
         indev = get_indev(payload)
 
         binding = get_binding(self, 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)
+            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
             payload.set_verdict(nfqueue.NF_ACCEPT)
@@ -703,14 +705,14 @@ class VMNetProxy(object):  # pylint: disable=R0902
         payload.set_verdict(nfqueue.NF_DROP)
 
         if mac != binding.mac:
-            logging.warn("Received spoofed RS request for mac %s from tap %s",
+            logging.warn(" - Received spoofed RS request for mac %s from tap %s",
                          mac, binding.tap)
             return
 
         subnet = binding.net6
 
         if subnet.net is None:
-            logging.debug("No IPv6 network assigned for the interface")
+            logging.debug(" - No IPv6 network assigned for tap %s", binding.tap)
             return
 
         indevmac = self.get_iface_hw_addr(binding.indev)
@@ -718,6 +720,9 @@ class VMNetProxy(object):  # pylint: disable=R0902
         if ifll is None:
             return
 
+        logging.debug(" - 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(routerlifetime=14400)/\
                ICMPv6NDOptPrefixInfo(prefix=str(subnet.prefix),
@@ -727,13 +732,12 @@ class VMNetProxy(object):  # pylint: disable=R0902
             resp /= ICMPv6NDOptRDNSS(dns=self.ipv6_nameservers,
                                      lifetime=self.ra_period * 3)
 
-        logging.info("RA on %s for %s", binding.indev, subnet.net)
         try:
             self.sendp(resp, binding.indev)
         except socket.error, e:
-            logging.warn("RA on %s failed: %s", binding.indev, str(e))
+            logging.warn(" - RA on %s failed: %s", binding.indev, str(e))
         except Exception, e:
-            logging.warn("Unkown error during RA on %s: %s",
+            logging.warn(" - Unkown error during RA on %s: %s",
                          binding.indev, str(e))
 
     def ns_response(self, i, payload):  # pylint: disable=W0613
@@ -741,15 +745,16 @@ class VMNetProxy(object):  # pylint: disable=R0902
 
         """
 
+        logging.debug(" * Processing pending NS request (NFQuEUE %d)", i)
+
         ns = IPv6(payload.get_data())
         #logging.debug(ns.show())
         try:
             mac = ns.lladdr
         except:
-            logging.debug("Cannot obtain lladdr from ns")
+            logging.debug(" - Cannot obtain lladdr from ns")
             return
 
-        logging.debug("Generating ns response, dst: %s  tgt: %s", ns.dst, ns.tgt)
 
         indev = get_indev(payload)
 
@@ -757,7 +762,8 @@ class VMNetProxy(object):  # pylint: disable=R0902
         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)
+            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
             payload.set_verdict(nfqueue.NF_ACCEPT)
@@ -766,13 +772,13 @@ class VMNetProxy(object):  # pylint: disable=R0902
         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(" - Received spoofed NS request"
+                         " for mac %s from tap %s", mac, binding.tap)
             return
 
         subnet = binding.net6
         if subnet.net is None:
-            logging.debug("No IPv6 network assigned for the interface")
+            logging.debug(" - No IPv6 network assigned for the interface")
             return
 
         indevmac = self.get_iface_hw_addr(binding.indev)
@@ -782,23 +788,23 @@ 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)
-            payload.set_verdict(nfqueue.NF_ACCEPT)
+            logging.debug(" - Received NS for a non-routable IP (%s)", ns.tgt)
             return 1
 
-        logging.debug("Sending NA response to client %s", binding.mac)
+        logging.debug(" - 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("NA on %s for %s", binding.indev, ns.tgt)
         try:
             self.sendp(resp, binding.indev)
         except socket.error, e:
-            logging.warn("NA on %s failed: %s", binding.indev, str(e))
+            logging.warn(" - NA on %s failed: %s", binding.indev, str(e))
         except Exception, e:
-            logging.warn("Unkown error during periodic NA on %s: %s",
+            logging.warn(" - Unkown error during periodic NA on %s: %s",
                          binding.indev, str(e))
 
     def send_periodic_ra(self):
@@ -816,7 +822,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,"
+                logging.debug(" - Skipping periodic RA on interface %s,"
                               " as it is not IPv6-connected", tap)
                 continue
             indevmac = self.get_iface_hw_addr(indev)
@@ -833,12 +839,12 @@ class VMNetProxy(object):  # pylint: disable=R0902
             try:
                 self.sendp(resp, indev)
             except socket.error, e:
-                logging.warn("Periodic RA on %s failed: %s", tap, str(e))
+                logging.warn(" - Periodic RA on %s failed: %s", tap, str(e))
             except Exception, e:
-                logging.warn("Unknown error during periodic RA on %s: %s",
+                logging.warn(" - Unkown error during periodic RA on %s: %s",
                              tap, str(e))
             i += 1
-        logging.debug("Sent %d RAs in %.2f seconds", i, time.time() - start)
+        logging.debug(" - Sent %d RAs in %.2f seconds", i, time.time() - start)
 
     def serve(self):
         """ Safely perform the main loop, freeing all resources upon exit
@@ -880,9 +886,13 @@ class VMNetProxy(object):  # pylint: disable=R0902
                     self.notifier.process_events()
                     rlist.remove(iwfd)
 
+                logging.debug("Pending requests on fds %s", rlist)
+
                 for fd in rlist:
                     try:
-                        self.nfq[fd].process_pending()
+                        cnt = self.nfq[fd].process_pending()
+                        logging.debug(" * Processed %d requests on NFQUEUE"
+                                      " with fd %d", cnt, fd)
                     except RuntimeError, e:
                         logging.warn("Error processing fd %d: %s", fd, str(e))
                     except Exception, e:
-- 
GitLab