Change id before becoming a daemon
[snf-nfdhcpd] / nfdhcpd
diff --git a/nfdhcpd b/nfdhcpd
index 0de1301..ceef7d6 100755 (executable)
--- a/nfdhcpd
+++ b/nfdhcpd
@@ -31,9 +31,12 @@ import traceback
 import subprocess
 
 import daemon
+import daemon.runner
 import daemon.pidlockfile
 import nfqueue
 import pyinotify
+import setproctitle
+from lockfile import LockTimeout
 
 import IPy
 import socket
@@ -50,6 +53,7 @@ from scapy.layers.inet6 import IPv6, ICMPv6ND_RA, ICMPv6ND_NA, \
                                ICMPv6NDOptRDNSS
 from scapy.layers.dhcp import BOOTP, DHCP
 
+
 DEFAULT_CONFIG = "/etc/nfdhcpd/nfdhcpd.conf"
 DEFAULT_PATH = "/var/run/ganeti-dhcpd"
 DEFAULT_USER = "nobody"
@@ -62,7 +66,7 @@ LOG_FILENAME = "nfdhcpd.log"
 
 SYSFS_NET = "/sys/class/net"
 
-LOG_FORMAT = "%(asctime)-15s %(levelname)-6s %(message)s"
+LOG_FORMAT = "%(asctime)-15s %(levelname)-8s %(message)s"
 
 # Configuration file specification (see configobj documentation)
 CONFIG_SPEC = """
@@ -117,14 +121,47 @@ DHCP_REQRESP = {
     }
 
 
+def get_indev(payload):
+    try:
+        indev_ifindex = payload.get_physindev()
+        if 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")
+        return 0
+
+    indev_ifindex = payload.get_indev()
+    logging.debug(" - Incomming packet from tap %s", indev_ifindex)
+
+    return indev_ifindex
+
+
+def get_binding(proxy, ifindex, mac):
+    try:
+        if proxy.mac_indexed_clients:
+            logging.debug(" - Getting binding for mac %s", mac)
+            b = proxy.clients[mac]
+        else:
+            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)
+        return None
+
+
 def parse_binding_file(path):
     """ Read a client configuration from a tap file
 
     """
+    logging.info("Parsing binding file %s", 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)
@@ -141,7 +178,7 @@ def parse_binding_file(path):
     def get_value(line):
         v = line.strip().split('=')[1]
         if v == '':
-          return None
+            return None
         return v
 
     for line in iffile:
@@ -164,16 +201,22 @@ def parse_binding_file(path):
         elif line.startswith("EUI64="):
             eui64 = get_value(line)
 
-    return Client(tap=tap, mac=mac, ip=ip,
-                  hostname=hostname, indev=indev, subnet=subnet,
-                  gateway=gateway, subnet6=subnet6, gateway6=gateway6, eui64=eui64 )
+    try:
+        return Client(tap=tap, mac=mac, ip=ip, hostname=hostname,
+                      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",
+                        hostname, ip, tap)
+        return None
+
 
 class ClientFileHandler(pyinotify.ProcessEvent):
     def __init__(self, server):
         pyinotify.ProcessEvent.__init__(self)
         self.server = server
 
-    def process_IN_DELETE(self, event): # pylint: disable=C0103
+    def process_IN_DELETE(self, event):  # pylint: disable=C0103
         """ Delete file handler
 
         Currently this removes an interface from the watch list
@@ -181,7 +224,7 @@ class ClientFileHandler(pyinotify.ProcessEvent):
         """
         self.server.remove_tap(event.name)
 
-    def process_IN_CLOSE_WRITE(self, event): # pylint: disable=C0103
+    def process_IN_CLOSE_WRITE(self, event):  # pylint: disable=C0103
         """ Add file handler
 
         Currently this adds an interface to the watch list
@@ -214,7 +257,11 @@ class Client(object):
 class Subnet(object):
     def __init__(self, net=None, gw=None, dev=None):
         if isinstance(net, str):
-            self.net = IPy.IP(net)
+            try:
+                self.net = IPy.IP(net)
+            except ValueError, e:
+                logging.warning(" - IPy error: %s", e)
+                raise e
         else:
             self.net = net
         self.gw = gw
@@ -253,6 +300,8 @@ class Subnet(object):
         """ Compute an EUI-64 address from an EUI-48 (MAC) address
 
         """
+        if mac is None:
+            return None
         comp = mac.split(":")
         prefix = IPy.IP(net).net().strFullsize().split(":")[:4]
         eui64 = comp[:3] + ["ff", "fe"] + comp[3:]
@@ -275,8 +324,8 @@ class Subnet(object):
         return self._make_eui64("fe80::", mac)
 
 
-class VMNetProxy(object): # pylint: disable=R0902
-    def __init__(self, data_path, dhcp_queue_num=None, # pylint: disable=R0913
+class VMNetProxy(object):  # pylint: disable=R0902
+    def __init__(self, data_path, dhcp_queue_num=None,  # pylint: disable=R0913
                  rs_queue_num=None, ns_queue_num=None,
                  dhcp_lease_lifetime=DEFAULT_LEASE_LIFETIME,
                  dhcp_lease_renewal=DEFAULT_LEASE_RENEWAL,
@@ -284,6 +333,11 @@ class VMNetProxy(object): # pylint: disable=R0902
                  dhcp_server_ip=DHCP_DUMMY_SERVER_IP, dhcp_nameservers=None,
                  ra_period=DEFAULT_RA_PERIOD, ipv6_nameservers=None):
 
+        try:
+            getattr(nfqueue.payload, 'get_physindev')
+            self.mac_indexed_clients = False
+        except AttributeError:
+            self.mac_indexed_clients = True
         self.data_path = data_path
         self.lease_lifetime = dhcp_lease_lifetime
         self.lease_renewal = dhcp_lease_renewal
@@ -307,9 +361,7 @@ class VMNetProxy(object): # pylint: disable=R0902
         #self.ifaces = {}
         #self.v6nets = {}
         self.nfq = {}
-        self.l2socket = socket.socket(socket.AF_PACKET,
-                                      socket.SOCK_RAW, ETH_P_ALL)
-        self.l2socket.setsockopt(socket.SOL_SOCKET, socket.SO_RCVBUF, 0)
+        self.l2socket = self._socket()
 
         # Inotify setup
         self.wm = pyinotify.WatchManager()
@@ -331,26 +383,35 @@ class VMNetProxy(object): # pylint: disable=R0902
             self._setup_nfqueue(ns_queue_num, AF_INET6, self.ns_response)
             self.ipv6_enabled = True
 
+    def _socket(self):
+        logging.info("Opening L2 socket")
+        try:
+            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)
+        return s
+
     def _cleanup(self):
         """ Free all resources for a graceful exit
 
         """
         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.debug("Setting up NFQUEUE for queue %d, AF %s",
+        logging.info("Setting up NFQUEUE for queue %d, AF %s",
                       queue_num, family)
         q = nfqueue.queue()
         q.set_callback(callback)
@@ -359,20 +420,30 @@ class VMNetProxy(object): # pylint: disable=R0902
         # 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)
 
     def sendp(self, data, dev):
         """ Send a raw packet using a layer-2 socket
 
         """
-        logging.debug("%s", data)
         if isinstance(data, BasePacket):
             data = str(data)
 
+        logging.debug(" - Sending raw packet %r", data)
+
         self.l2socket.bind((dev, ETH_P_ALL))
-        count = self.l2socket.send(data)
+        try:
+            count = self.l2socket.send(data, socket.MSG_DONTWAIT)
+        except socket.error, 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)
         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):
@@ -381,10 +452,16 @@ class VMNetProxy(object): # pylint: disable=R0902
         for path in glob.glob(os.path.join(self.data_path, "*")):
             self.add_tap(path)
 
+        logging.debug("%15s %20s %7s %15s", 'Client', 'MAC', 'TAP', 'IP')
+        for b in self.clients.values():
+            logging.debug("%15s %20s %7s %15s", b.hostname, b.mac, b.tap, b.ip)
+
     def get_ifindex(self, iface):
         """ Get the interface index from sysfs
 
         """
+        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):
             return None
@@ -394,7 +471,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
@@ -404,10 +481,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:
@@ -415,11 +492,11 @@ class VMNetProxy(object): # pylint: disable=R0902
 
         return ifindex
 
-
     def get_iface_hw_addr(self, iface):
         """ Get the interface hardware address from sysfs
 
         """
+        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
@@ -428,14 +505,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()
@@ -455,65 +532,81 @@ 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():
-                self.clients[b.mac] = b
-                logging.debug("Added client:")
-                logging.debug("%10s %20s %7s %15s", b.hostname, b.mac, b.tap, b.ip)
-        logging.debug("%10s %20s %7s %15s", 'Client', 'MAC', 'TAP', 'IP')
-        for mac in self.clients.keys():
-          b = self.clients[mac]
-          logging.debug("%10s %20s %7s %15s", b.hostname, b.mac, b.tap, b.ip)
+                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",
+                               ifindex, b.hostname, b.mac, b.tap, b.ip)
 
     def remove_tap(self, tap):
         """ Cleanup clients on a removed interface
 
         """
-        for b in self.clients.values():
-            if b.tap == tap:
-                #os.remove(self.data_path+'/'+tap)
-                logging.debug("Removed interface %s", self.data_path+'/'+tap)
-                logging.debug("%10s %20s %7s %15s", b.hostname, b.mac, b.tap, b.ip)
-                del b
-
+        try:
+            for k in self.clients.keys():
+                b = self.clients[k]
+                if self.clients[k].tap == tap:
+                    logging.debug("Removing client on interface %s", tap)
+                    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)
 
-    def dhcp_response(self, i, payload): # pylint: disable=W0613,R0914
+    def dhcp_response(self, i, payload):  # pylint: disable=W0613,R0914
         """ 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("IN DHCP RESPONCE")
-        logging.debug(pkt.show())
+        #logging.debug(pkt.show())
 
         # Get the client MAC address
         resp = pkt.getlayer(BOOTP).copy()
         hlen = resp.hlen
         mac = resp.chaddr[:hlen].encode("hex")
-        mac, _ = re.subn(r'([0-9a-fA-F]{2})', r'\1:', mac, hlen-1)
+        mac, _ = re.subn(r'([0-9a-fA-F]{2})', r'\1:', mac, hlen - 1)
 
         # Server responses are always BOOTREPLYs
         resp.op = "BOOTREPLY"
         del resp.payload
 
-        try:
-            binding = self.clients[mac]
-        except KeyError:
-            logging.warn("Invalid client 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 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)
             return
 
         # Signal the kernel that it shouldn't further process the packet
         payload.set_verdict(nfqueue.NF_DROP)
 
+        if mac != binding.mac:
+            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
 
@@ -525,7 +618,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:
@@ -535,13 +628,13 @@ 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(" - Sending DHCPNAK to %s on %s: requested %s"
+                         " instead of %s", binding.mac, binding.tap,
+                         requested_addr, binding.ip)
 
         elif req_type in (DHCPDISCOVER, DHCPREQUEST):
             resp_type = DHCP_REQRESP[req_type]
-            resp.yiaddr = self.clients[mac].ip
+            resp.yiaddr = binding.ip
             dhcp_options += [
                  ("hostname", binding.hostname),
                  ("domain", domainname),
@@ -551,7 +644,7 @@ class VMNetProxy(object): # pylint: disable=R0902
                  ("lease_time", self.lease_lifetime),
             ]
             if subnet.gw:
-              dhcp_options += [("router", subnet.gw)]
+                dhcp_options += [("router", subnet.gw)]
             dhcp_options += [("name_server", x) for x in self.dhcp_nameservers]
 
         elif req_type == DHCPINFORM:
@@ -564,7 +657,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
@@ -575,29 +668,36 @@ class VMNetProxy(object): # pylint: disable=R0902
         ]
         resp /= DHCP(options=dhcp_options)
 
-        if payload.get_indev() != self.get_ifindex(binding.indev):
-            logging.warn("Received spoofed DHCP request for %s from interface"
-                         " %s instead of %s", mac, payload.get_indev(), binding.indev)
-            return
-
-        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)
-        self.sendp(resp, binding.indev)
-
-    def rs_response(self, i, payload): # pylint: disable=W0613
+        try:
+            self.sendp(resp, binding.indev)
+        except socket.error, 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",
+                         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("IN RS RESPONCE")
-        logging.debug(pkt.show())
-        mac = pkt.lladdr
-        logging.debug("rs for mac %s", mac)
+        #logging.debug(pkt.show())
         try:
-          binding = self.clients[mac]
-        except KeyError:
-            logging.debug("Ignoring router solicitation on"
-                          " for mac %s", mac)
+            mac = pkt.lladdr
+        except:
+            logging.debug(" - Cannot obtain lladdr in rs")
+            return
+
+        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)
             # We don't know what to do with this packet, so let the kernel
             # handle it
             payload.set_verdict(nfqueue.NF_ACCEPT)
@@ -606,17 +706,26 @@ class VMNetProxy(object): # pylint: disable=R0902
         # Signal the kernel that it shouldn't further process the packet
         payload.set_verdict(nfqueue.NF_DROP)
 
+        if mac != binding.mac:
+            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")
-          return
+            logging.debug(" - No IPv6 network assigned for tap %s", binding.tap)
+            return
 
-        ifmac = self.get_iface_hw_addr(binding.indev)
-        ifll = subnet.make_ll64(ifmac)
+        indevmac = self.get_iface_hw_addr(binding.indev)
+        ifll = subnet.make_ll64(indevmac)
+        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=ifmac)/\
+        resp = Ether(src=indevmac)/\
                IPv6(src=str(ifll))/ICMPv6ND_RA(routerlifetime=14400)/\
                ICMPv6NDOptPrefixInfo(prefix=str(subnet.prefix),
                                      prefixlen=subnet.prefixlen)
@@ -625,53 +734,80 @@ 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)
-        self.sendp(resp, binding.indev)
-
-    def ns_response(self, i, payload): # pylint: disable=W0613
+        try:
+            self.sendp(resp, binding.indev)
+        except socket.error, e:
+            logging.warn(" - RA on %s failed: %s", binding.indev, str(e))
+        except Exception, e:
+            logging.warn(" - Unkown error during RA on %s: %s",
+                         binding.indev, str(e))
+
+    def ns_response(self, i, payload):  # pylint: disable=W0613
         """ Generate a reply to an ICMPv6 neighbor solicitation
 
         """
-        ns = IPv6(payload.get_data())
-        logging.debug("IN NS RESPONCE")
-        logging.debug(ns.show())
 
-        logging.debug("dst %s  tgt %s" , ns.dst, ns.tgt)
+        logging.debug(" * Processing pending NS request (NFQuEUE %d)", i)
 
+        ns = IPv6(payload.get_data())
+        #logging.debug(ns.show())
         try:
-          binding = self.clients[ns.lladdr]
+            mac = ns.lladdr
         except:
-          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)
-          return
+            logging.debug(" - Cannot obtain lladdr from ns")
+            return
 
-        subnet = binding.net6
-        if subnet.net is None:
-          logging.debug("No IPv6 network assigned for the interface")
-          payload.set_verdict(nfqueue.NF_ACCEPT)
-          return
+
+        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 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)
+            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)
+            return
+
+        subnet = binding.net6
+        if subnet.net is None:
+            logging.debug(" - No IPv6 network assigned for the interface")
+            return
+
         indevmac = self.get_iface_hw_addr(binding.indev)
 
         ifll = subnet.make_ll64(indevmac)
+        if ifll is None:
+            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("na ether %s %s", binding.mac, ns.src)
+        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)
-        self.sendp(resp, binding.indev)
+        try:
+            self.sendp(resp, binding.indev)
+        except socket.error, 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",
+                         binding.indev, str(e))
 
     def send_periodic_ra(self):
         # Use a separate thread as this may take a _long_ time with
@@ -685,14 +821,16 @@ class VMNetProxy(object): # pylint: disable=R0902
         for binding in self.clients.values():
             tap = binding.tap
             indev = binding.indev
-            mac = binding.mac
+            # 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)
             ifll = subnet.make_ll64(indevmac)
+            if ifll is None:
+                continue
             resp = Ether(src=indevmac)/\
                    IPv6(src=str(ifll))/ICMPv6ND_RA(routerlifetime=14400)/\
                    ICMPv6NDOptPrefixInfo(prefix=str(subnet.prefix),
@@ -703,12 +841,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("Unkown 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
@@ -727,7 +865,7 @@ class VMNetProxy(object): # pylint: disable=R0902
 
         # Yes, we are accessing _fd directly, but it's the only way to have a
         # single select() loop ;-)
-        iwfd = self.notifier._fd # pylint: disable=W0212
+        iwfd = self.notifier._fd  # pylint: disable=W0212
 
         start = time.time()
         if self.ipv6_enabled:
@@ -740,7 +878,7 @@ class VMNetProxy(object): # pylint: disable=R0902
             rlist, _, xlist = select(self.nfq.keys() + [iwfd], [], [], timeout)
             if xlist:
                 logging.warn("Warning: Exception on %s",
-                             ", ".join([ str(fd) for fd in xlist]))
+                             ", ".join([str(fd) for fd in xlist]))
 
             if rlist:
                 if iwfd in rlist:
@@ -750,9 +888,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:
@@ -803,7 +945,6 @@ if __name__ == "__main__":
     validator.functions["ip_addr_list"] = is_ip_list
     config_spec = StringIO(CONFIG_SPEC)
 
-
     parser = optparse.OptionParser()
     parser.add_option("-c", "--config", dest="config_file",
                       help="The location of the data files", metavar="FILE",
@@ -814,7 +955,6 @@ if __name__ == "__main__":
                       dest="daemonize", default=True,
                       help="Do not daemonize, stay in the foreground")
 
-
     opts, args = parser.parse_args()
 
     try:
@@ -836,6 +976,29 @@ if __name__ == "__main__":
                               ", ".join(section_list))
         sys.exit(1)
 
+    try:
+        uid = getpwuid(config["general"].as_int("user"))
+    except ValueError:
+        uid = getpwnam(config["general"]["user"])
+
+    # Keep only the capabilities we need
+    # CAP_NET_ADMIN: we need to send nfqueue packet verdicts to a netlinkgroup
+    # CAP_NET_RAW: we need to reopen socket in case the buffer gets full
+    # CAP_SETPCAP: needed by capng_change_id()
+    capng.capng_clear(capng.CAPNG_SELECT_BOTH)
+    capng.capng_update(capng.CAPNG_ADD,
+                       capng.CAPNG_EFFECTIVE | capng.CAPNG_PERMITTED,
+                       capng.CAP_NET_ADMIN)
+    capng.capng_update(capng.CAPNG_ADD,
+                       capng.CAPNG_EFFECTIVE | capng.CAPNG_PERMITTED,
+                       capng.CAP_NET_RAW)
+    capng.capng_update(capng.CAPNG_ADD,
+                       capng.CAPNG_EFFECTIVE | capng.CAPNG_PERMITTED,
+                       capng.CAP_SETPCAP)
+    # change uid
+    capng.capng_change_id(uid.pw_uid, uid.pw_gid,
+                          capng.CAPNG_DROP_SUPP_GRP | capng.CAPNG_CLEAR_BOUNDING)
+
     logger = logging.getLogger()
     if opts.debug:
         logger.setLevel(logging.DEBUG)
@@ -852,18 +1015,37 @@ if __name__ == "__main__":
     handler.setFormatter(logging.Formatter(LOG_FORMAT))
     logger.addHandler(handler)
 
+    # Rename this process so 'ps' output looks like
+    # this is a native executable.
+    # NOTE: due to a bug in python-setproctitle, one cannot yet
+    # set individual values for command-line arguments, so only show
+    # the name of the executable instead.
+    # setproctitle.setproctitle("\x00".join(sys.argv))
+    setproctitle.setproctitle(sys.argv[0])
+
     if opts.daemonize:
         pidfile = daemon.pidlockfile.TimeoutPIDLockFile(
             config["general"]["pidfile"], 10)
+        # Remove any stale PID files, left behind by previous invocations
+        if daemon.runner.is_pidfile_stale(pidfile):
+            logger.warning("Removing stale PID lock file %s", pidfile.path)
+            pidfile.break_lock()
 
         d = daemon.DaemonContext(pidfile=pidfile,
+                                 umask=0022,
                                  stdout=handler.stream,
                                  stderr=handler.stream,
                                  files_preserve=[handler.stream])
-        d.umask = 0022
-        d.open()
+        try:
+            d.open()
+        except (daemon.pidlockfile.AlreadyLocked, LockTimeout):
+            logger.critical("Failed to lock pidfile %s,"
+                            " another instance running?", pidfile.path)
+            sys.exit(1)
 
     logging.info("Starting up")
+    logging.info("Running as %s (uid:%d, gid: %d)",
+                  config["general"]["user"], uid.pw_uid, uid.pw_gid)
 
     proxy_opts = {}
     if config["dhcp"].as_bool("enable_dhcp"):
@@ -887,25 +1069,6 @@ if __name__ == "__main__":
     # pylint: disable=W0142
     proxy = VMNetProxy(data_path=config["general"]["datapath"], **proxy_opts)
 
-    # Drop all capabilities except CAP_NET_RAW and change uid
-    try:
-        uid = getpwuid(config["general"].as_int("user"))
-    except ValueError:
-        uid = getpwnam(config["general"]["user"])
-
-    logging.debug("Setting capabilities and changing uid")
-    logging.debug("User: %s, uid: %d, gid: %d",
-                  config["general"]["user"], uid.pw_uid, uid.pw_gid)
-
-    # Keep only the capabilities we need
-    # CAP_NET_ADMIN: we need to send nfqueue packet verdicts to a netlinkgroup
-    capng.capng_clear(capng.CAPNG_SELECT_BOTH)
-    capng.capng_update(capng.CAPNG_ADD,
-                       capng.CAPNG_EFFECTIVE|capng.CAPNG_PERMITTED,
-                       capng.CAP_NET_ADMIN)
-    capng.capng_change_id(uid.pw_uid, uid.pw_gid,
-                          capng.CAPNG_DROP_SUPP_GRP|capng.CAPNG_CLEAR_BOUNDING)
-
     logging.info("Ready to serve requests")
     try:
         proxy.serve()