Print eui64 too while printing clients
[snf-nfdhcpd] / nfdhcpd
diff --git a/nfdhcpd b/nfdhcpd
index 1e645b9..c66c435 100755 (executable)
--- a/nfdhcpd
+++ b/nfdhcpd
@@ -20,6 +20,8 @@
 #
 
 import os
+import signal
+import errno
 import re
 import sys
 import glob
@@ -28,18 +30,18 @@ import logging
 import logging.handlers
 import threading
 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
-from select import select
+import select
 from socket import AF_INET, AF_INET6
 
 from scapy.data import ETH_P_ALL
@@ -51,6 +53,10 @@ from scapy.layers.inet6 import IPv6, ICMPv6ND_RA, ICMPv6ND_NA, \
                                ICMPv6NDOptPrefixInfo, \
                                ICMPv6NDOptRDNSS
 from scapy.layers.dhcp import BOOTP, DHCP
+from scapy.layers.dhcp6 import DHCP6_Reply, DHCP6OptDNSServers, \
+                               DHCP6OptServerId, DHCP6OptClientId, \
+                               DUID_LLT, DHCP6_InfoRequest, DHCP6OptDNSDomains
+
 
 DEFAULT_CONFIG = "/etc/nfdhcpd/nfdhcpd.conf"
 DEFAULT_PATH = "/var/run/ganeti-dhcpd"
@@ -64,7 +70,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 = """
@@ -88,7 +94,9 @@ enable_ipv6 = boolean(default=True)
 ra_period = integer(min=1, max=4294967295)
 rs_queue = integer(min=0, max=65535)
 ns_queue = integer(min=0, max=65535)
+dhcp_queue = integer(min=0, max=65535)
 nameservers = ip_addr_list(family=6)
+domains = force_list(default=None)
 """
 
 
@@ -123,33 +131,20 @@ def get_indev(payload):
     try:
         indev_ifindex = payload.get_physindev()
         if indev_ifindex:
-            logging.debug("Incomming packet from bridge %s", indev_ifindex)
+            logging.debug(" - Incoming packet from bridge with ifindex %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(" - Incoming packet from tap with ifindex %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
 
@@ -158,7 +153,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)
@@ -199,11 +194,12 @@ def parse_binding_file(path):
             eui64 = get_value(line)
 
     try:
-        client = Client(tap=tap, mac=mac, ip=ip,
-                  hostname=hostname, indev=indev, subnet=subnet,
-                  gateway=gateway, subnet6=subnet6, gateway6=gateway6, eui64=eui64 )
-        return client
-    except:
+        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
 
 
@@ -230,8 +226,10 @@ class ClientFileHandler(pyinotify.ProcessEvent):
 
 
 class Client(object):
-    def __init__(self, tap=None, indev=None, mac=None, ip=None, hostname=None,
-                 subnet=None, gateway=None, subnet6=None, gateway6=None, eui64=None ):
+    def __init__(self, tap=None, indev=None,
+                 mac=None, ip=None, hostname=None,
+                 subnet=None, gateway=None,
+                 subnet6=None, gateway6=None, eui64=None):
         self.mac = mac
         self.ip = ip
         self.hostname = hostname
@@ -244,10 +242,44 @@ class Client(object):
         self.gateway6 = gateway6
         self.net6 = Subnet(net=subnet6, gw=gateway6, dev=tap)
         self.eui64 = eui64
+        self.open_socket()
 
     def is_valid(self):
-        return self.mac is not None and self.ip is not None\
-               and self.hostname is not None
+        return self.mac is not None and self.hostname is not None
+
+
+    def open_socket(self):
+
+        logging.info(" - Opening L2 socket and binding to %s", self.tap)
+        try:
+            s = socket.socket(socket.AF_PACKET, socket.SOCK_RAW, ETH_P_ALL)
+            s.setsockopt(socket.SOL_SOCKET, socket.SO_RCVBUF, 0)
+            s.bind((self.tap, ETH_P_ALL))
+            self.socket = s
+        except socket.error, e:
+            logging.warning(" - Cannot open socket %s", e)
+
+
+    def sendp(self, data):
+
+        if isinstance(data, BasePacket):
+            data = str(data)
+
+        logging.debug(" - Sending raw packet %r", data)
+
+        try:
+            count = self.socket.send(data, socket.MSG_DONTWAIT)
+        except socket.error, e:
+            logging.warn(" - Send with MSG_DONTWAIT failed: %s", str(e))
+            self.socket.close()
+            self.open_socket()
+            raise e
+
+        ldata = len(data)
+        logging.debug(" - Sent %d bytes on %s", count, self.tap)
+        if count != ldata:
+            logging.warn(" - Truncated msg: %d/%d bytes sent",
+                         count, ldata)
 
 
 class Subnet(object):
@@ -255,8 +287,9 @@ class Subnet(object):
         if isinstance(net, str):
             try:
                 self.net = IPy.IP(net)
-            except:
-                raise Exception
+            except ValueError, e:
+                logging.warning(" - IPy error: %s", e)
+                raise e
         else:
             self.net = net
         self.gw = gw
@@ -321,12 +354,13 @@ class Subnet(object):
 
 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,
+                 rs_queue_num=None, ns_queue_num=None, dhcpv6_queue_num=None,
                  dhcp_lease_lifetime=DEFAULT_LEASE_LIFETIME,
                  dhcp_lease_renewal=DEFAULT_LEASE_RENEWAL,
-                 dhcp_domain='',
+                 dhcp_domain=None,
                  dhcp_server_ip=DHCP_DUMMY_SERVER_IP, dhcp_nameservers=None,
-                 ra_period=DEFAULT_RA_PERIOD, ipv6_nameservers=None):
+                 ra_period=DEFAULT_RA_PERIOD, ipv6_nameservers=None,
+                 dhcpv6_domains=None):
 
         try:
             getattr(nfqueue.payload, 'get_physindev')
@@ -349,6 +383,11 @@ class VMNetProxy(object):  # pylint: disable=R0902
         else:
             self.ipv6_nameservers = ipv6_nameservers
 
+        if dhcpv6_domains is None:
+            self.dhcpv6_domains = []
+        else:
+            self.dhcpv6_domains = dhcpv6_domains
+
         self.ipv6_enabled = False
 
         self.clients = {}
@@ -356,9 +395,6 @@ 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)
 
         # Inotify setup
         self.wm = pyinotify.WatchManager()
@@ -370,35 +406,50 @@ class VMNetProxy(object):  # pylint: disable=R0902
 
         # NFQUEUE setup
         if dhcp_queue_num is not None:
-            self._setup_nfqueue(dhcp_queue_num, AF_INET, self.dhcp_response)
+            self._setup_nfqueue(dhcp_queue_num, AF_INET, self.dhcp_response, 0)
 
         if rs_queue_num is not None:
-            self._setup_nfqueue(rs_queue_num, AF_INET6, self.rs_response)
+            self._setup_nfqueue(rs_queue_num, AF_INET6, self.rs_response, 10)
             self.ipv6_enabled = True
 
         if ns_queue_num is not None:
-            self._setup_nfqueue(ns_queue_num, AF_INET6, self.ns_response)
+            self._setup_nfqueue(ns_queue_num, AF_INET6, self.ns_response, 10)
+            self.ipv6_enabled = True
+
+        if dhcpv6_queue_num is not None:
+            self._setup_nfqueue(dhcpv6_queue_num, AF_INET6, self.dhcpv6_response, 10)
             self.ipv6_enabled = True
 
+    def get_binding(self, ifindex, mac):
+        try:
+            if self.mac_indexed_clients:
+                logging.debug(" - Getting binding for mac %s", mac)
+                b = self.clients[mac]
+            else:
+                logging.debug(" - Getting binding for ifindex %s", ifindex)
+                b = self.clients[ifindex]
+            return b
+        except KeyError:
+            logging.debug(" - No client found for mac / ifindex %s / %s",
+                          mac, ifindex)
+            return None
+
     def _cleanup(self):
         """ Free all resources for a graceful exit
 
         """
         logging.info("Cleaning up")
 
-        logging.debug("Closing netfilter queues")
-        for q in self.nfq.values():
+        logging.debug(" - Closing netfilter queues")
+        for q, _ in self.nfq.values():
             q.close()
 
-        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):
+    def _setup_nfqueue(self, queue_num, family, callback, pending):
         logging.info("Setting up NFQUEUE for queue %d, AF %s",
                       queue_num, family)
         q = nfqueue.queue()
@@ -407,23 +458,8 @@ class VMNetProxy(object):  # pylint: disable=R0902
         q.set_queue_maxlen(5000)
         # 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("Sending raw packet %s", data)
-        if isinstance(data, BasePacket):
-            data = str(data)
-
-        self.l2socket.bind((dev, ETH_P_ALL))
-        count = self.l2socket.send(data)
-        ldata = len(data)
-        if count != ldata:
-            logging.warn("Truncated send on %s (%d/%d bytes sent)",
-                         dev, count, ldata)
+        self.nfq[q.get_fd()] = (q, pending)
+        logging.debug(" - Successfully set up NFQUEUE %d", queue_num)
 
     def build_config(self):
         self.clients.clear()
@@ -431,15 +467,13 @@ 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)
+        self.print_clients()
 
     def get_ifindex(self, iface):
         """ 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):
@@ -450,7 +484,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
@@ -460,10 +494,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:
@@ -475,7 +509,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
@@ -484,14 +518,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()
@@ -504,46 +538,58 @@ class VMNetProxy(object):  # pylint: disable=R0902
         """
         tap = os.path.basename(path)
 
-        logging.debug("Updating configuration for %s", tap)
+        logging.info("Updating configuration for %s", tap)
         b = parse_binding_file(path)
         if b is None:
             return
         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
+                    k = b.mac
                 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)
+                    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)
 
     def remove_tap(self, tap):
         """ Cleanup clients on a removed interface
 
         """
         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("%10s %20s %7s %15s",
-                                  b.hostname, b.mac, b.tap, b.ip)
+            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]
         except:
             logging.debug("Client on %s disappeared!!!", tap)
 
-    def dhcp_response(self, i, payload):  # pylint: disable=W0613,R0914
+
+    def dhcp_response(self, arg1, arg2=None):  # pylint: disable=W0613,R0914
         """ Generate a reply to bnetfilter-queue-deva BOOTP/DHCP request
 
         """
+        logging.info(" * Processing pending DHCP 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
+        # See bug http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=718894
+        if arg2:
+            payload = arg2
+        else:
+            payload = arg1
         # 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
@@ -558,11 +604,11 @@ class VMNetProxy(object):  # pylint: disable=R0902
 
         indev = get_indev(payload)
 
-        binding = get_binding(self, indev, mac)
+        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 %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)
@@ -572,16 +618,26 @@ class VMNetProxy(object):  # pylint: disable=R0902
         payload.set_verdict(nfqueue.NF_DROP)
 
         if mac != binding.mac:
-            logging.warn("Recieved spoofed DHCP request for mac %s from tap %s", mac, indev)
+            logging.warn(" - Recieved spoofed DHCP request: mac %s, indev %s",
+                         mac, indev)
+            return
+
+        if not binding.ip:
+            logging.info(" - No IP found in binding file.")
             return
 
+        logging.info(" - Generating DHCP response:"
+                     " host %s, mac %s, tap %s, indev %s",
+                       binding.hostname, mac, binding.tap, indev)
+
+
         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
 
@@ -593,7 +649,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:
@@ -603,7 +659,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)
 
@@ -632,7 +688,8 @@ 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.hostname, binding.tap)
             return
 
         # Finally, always add the server identifier and end options
@@ -643,38 +700,120 @@ 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)
+            binding.sendp(resp)
+        except socket.error, e:
+            logging.warn(" - DHCP response on %s (%s) failed: %s",
+                         binding.tap, binding.hostname, str(e))
+        except Exception, e:
+            logging.warn(" - Unkown error during DHCP response on %s (%s): %s",
+                         binding.tap, binding.hostname, str(e))
+
+    def dhcpv6_response(self, arg1, arg2=None):  # pylint: disable=W0613
+
+        logging.info(" * Processing pending DHCPv6 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
+        # See bug http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=718894
+        if arg2:
+            payload = arg2
+        else:
+            payload = arg1
+        pkt = IPv6(payload.get_data())
+        indev = get_indev(payload)
+
+        #TODO: figure out how to find the src mac
+        mac = None
+        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
+            payload.set_verdict(nfqueue.NF_ACCEPT)
+            return
+
+        # Signal the kernel that it shouldn't further process the packet
+        payload.set_verdict(nfqueue.NF_DROP)
+
+        subnet = binding.net6
+
+        if subnet.net is None:
+            logging.debug(" - No IPv6 network assigned for tap %s", binding.tap)
+            return
+
+        indevmac = self.get_iface_hw_addr(binding.indev)
+        ifll = subnet.make_ll64(indevmac)
+        if ifll is None:
+            return
+
+        ofll = subnet.make_ll64(binding.mac)
+        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:
+            domains = [binding.hostname.split('.', 1)[-1]]
+
+        # We do this in order not to caclulate optlen ourselves
+        dnsdomains = str(DHCP6OptDNSDomains(dnsdomains=domains))
+        dnsservers = str(DHCP6OptDNSServers(dnsservers=self.ipv6_nameservers))
+
+        resp = Ether(src=indevmac, dst=binding.mac)/\
+               IPv6(tc=192, src=str(ifll), dst=str(ofll))/\
+               UDP(sport=pkt.dport, dport=pkt.sport)/\
+               DHCP6_Reply(trid=pkt[DHCP6_InfoRequest].trid)/\
+               DHCP6OptClientId(duid=pkt[DHCP6OptClientId].duid)/\
+               DHCP6OptServerId(duid=DUID_LLT(lladdr=indevmac, timeval=time.time()))/\
+               DHCP6OptDNSDomains(dnsdomains)/\
+               DHCP6OptDNSServers(dnsservers)
+
+        try:
+            binding.sendp(resp)
         except socket.error, e:
-            logging.warn("DHCP response on %s failed: %s", binding.indev, str(e))
+            logging.warn(" - DHCPv6 on %s (%s) failed: %s",
+                         binding.tap, binding.hostname, str(e))
         except Exception, e:
-            logging.warn("Unkown error during DHCP response on %s: %s",
-                         binding.indev, str(e))
+            logging.warn(" - Unkown error during DHCPv6 on %s (%s): %s",
+                         binding.tap, binding.hostname, str(e))
+
 
-    def rs_response(self, i, payload):  # pylint: disable=W0613
+    def rs_response(self, arg1, arg2=None):  # pylint: disable=W0613
         """ Generate a reply to a BOOTP/DHCP request
 
         """
-
+        logging.info(" * Processing pending RS 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
+        # See bug http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=718894
+        if arg2:
+            payload = arg2
+        else:
+            payload = arg1
         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)
+        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)
+            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)
@@ -684,14 +823,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: mac %s, 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)
@@ -699,8 +838,11 @@ 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(routerlifetime=14400)/\
+               IPv6(src=str(ifll))/ICMPv6ND_RA(O=1, routerlifetime=14400)/\
                ICMPv6NDOptPrefixInfo(prefix=str(subnet.prefix),
                                      prefixlen=subnet.prefixlen)
 
@@ -708,37 +850,47 @@ 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)
+            binding.sendp(resp)
         except socket.error, e:
-            logging.warn("RA on %s failed: %s", binding.indev, str(e))
+            logging.warn(" - RA on %s (%s) failed: %s",
+                         binding.tap, binding.hostname, str(e))
         except Exception, e:
-            logging.warn("Unkown error during RA on %s: %s",
-                         binding.indev, str(e))
+            logging.warn(" - Unkown error during RA on %s (%s): %s",
+                         binding.tap, binding.hostname, str(e))
 
-    def ns_response(self, i, payload):  # pylint: disable=W0613
+    def ns_response(self, arg1, arg2=None):  # pylint: disable=W0613
         """ Generate a reply to an ICMPv6 neighbor solicitation
 
         """
 
+        logging.info(" * Processing pending NS 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
+        # See bug http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=718894
+        if arg2:
+            payload = arg2
+        else:
+            payload = arg1
+
         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)
 
-        binding = get_binding(self, indev, mac)
+        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)
+            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)
@@ -747,13 +899,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)
@@ -763,24 +915,25 @@ 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.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("NA on %s for %s", binding.indev, ns.tgt)
         try:
-            self.sendp(resp, binding.indev)
+            binding.sendp(resp)
         except socket.error, e:
-            logging.warn("NA on %s failed: %s", binding.indev, str(e))
+            logging.warn(" - NA on %s (%s) failed: %s",
+                         binding.tap, binding.hostname, str(e))
         except Exception, e:
-            logging.warn("Unkown error during periodic NA on %s: %s",
-                         binding.indev, str(e))
+            logging.warn(" - Unkown error during periodic NA to %s (%s): %s",
+                         binding.tap, binding.hostname, str(e))
 
     def send_periodic_ra(self):
         # Use a separate thread as this may take a _long_ time with
@@ -788,7 +941,7 @@ class VMNetProxy(object):  # pylint: disable=R0902
         threading.Thread(target=self._send_periodic_ra).start()
 
     def _send_periodic_ra(self):
-        logging.debug("Sending out periodic RAs")
+        logging.info("Sending out periodic RAs")
         start = time.time()
         i = 0
         for binding in self.clients.values():
@@ -797,7 +950,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)
@@ -805,21 +958,22 @@ class VMNetProxy(object):  # pylint: disable=R0902
             if ifll is None:
                 continue
             resp = Ether(src=indevmac)/\
-                   IPv6(src=str(ifll))/ICMPv6ND_RA(routerlifetime=14400)/\
+                   IPv6(src=str(ifll))/ICMPv6ND_RA(O=1, routerlifetime=14400)/\
                    ICMPv6NDOptPrefixInfo(prefix=str(subnet.prefix),
                                          prefixlen=subnet.prefixlen)
             if self.ipv6_nameservers:
                 resp /= ICMPv6NDOptRDNSS(dns=self.ipv6_nameservers,
                                          lifetime=self.ra_period * 3)
             try:
-                self.sendp(resp, indev)
+                binding.sendp(resp)
             except socket.error, e:
-                logging.warn("Periodic RA on %s failed: %s", tap, str(e))
+                logging.warn(" - Periodic RA on %s (%s) failed: %s",
+                             tap, binding.hostname, str(e))
             except Exception, e:
-                logging.warn("Unkown error during periodic RA on %s: %s",
-                             tap, str(e))
+                logging.warn(" - Unkown error during periodic RA on %s (%s):"
+                             " %s", tap, binding.hostname, str(e))
             i += 1
-        logging.debug("Sent %d RAs in %.2f seconds", i, time.time() - start)
+        logging.info(" - Sent %d RAs in %.2f seconds", i, time.time() - start)
 
     def serve(self):
         """ Safely perform the main loop, freeing all resources upon exit
@@ -848,7 +1002,14 @@ class VMNetProxy(object):  # pylint: disable=R0902
             timeout = None
 
         while True:
-            rlist, _, xlist = select(self.nfq.keys() + [iwfd], [], [], timeout)
+            try:
+                rlist, _, xlist = select.select(self.nfq.keys() + [iwfd],
+                                                [], [], timeout)
+            except select.error, e:
+                if e[0] == errno.EINTR:
+                    logging.debug("select() got interrupted")
+                    continue
+
             if xlist:
                 logging.warn("Warning: Exception on %s",
                              ", ".join([str(fd) for fd in xlist]))
@@ -861,9 +1022,14 @@ 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()
+                        q, num = self.nfq[fd]
+                        cnt = q.process_pending(num)
+                        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:
@@ -879,6 +1045,14 @@ class VMNetProxy(object):  # pylint: disable=R0902
                     self.send_periodic_ra()
                     timeout = self.ra_period - (time.time() - start)
 
+    def print_clients(self):
+        logging.info("%10s   %20s %20s %10s %20s %40s",
+                     'Key', 'Client', 'MAC', 'TAP', 'IP', 'IPv6')
+        for k, cl in self.clients.items():
+            logging.info("%10s | %20s %20s %10s %20s %40s",
+                         k, cl.hostname, cl.mac, cl.tap, cl.ip, cl.eui64)
+
+
 
 if __name__ == "__main__":
     import capng
@@ -945,6 +1119,30 @@ 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)
@@ -953,14 +1151,21 @@ if __name__ == "__main__":
 
     if opts.daemonize:
         logfile = os.path.join(config["general"]["logdir"], LOG_FILENAME)
-        handler = logging.handlers.RotatingFileHandler(logfile,
-                                                       maxBytes=2097152)
+        handler = logging.handlers.WatchedFileHandler(logfile)
     else:
         handler = logging.StreamHandler()
 
     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)
@@ -982,6 +1187,8 @@ if __name__ == "__main__":
             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"):
@@ -996,35 +1203,28 @@ if __name__ == "__main__":
 
     if config["ipv6"].as_bool("enable_ipv6"):
         proxy_opts.update({
+            "dhcpv6_queue_num": config["ipv6"].as_int("dhcp_queue"),
             "rs_queue_num": config["ipv6"].as_int("rs_queue"),
             "ns_queue_num": config["ipv6"].as_int("ns_queue"),
             "ra_period": config["ipv6"].as_int("ra_period"),
             "ipv6_nameservers": config["ipv6"]["nameservers"],
+            "dhcpv6_domains": config["ipv6"]["domains"],
         })
 
     # 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.info("Ready to serve requests")
 
-    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)
+    def debug_handler(signum, _):
+        logging.debug('Received signal %d. Printing proxy state...', signum)
+        proxy.print_clients()
+
+    # Set the signal handler for debuging clients
+    signal.signal(signal.SIGUSR1, debug_handler)
+    signal.siginterrupt(signal.SIGUSR1, False)
 
-    logging.info("Ready to serve requests")
     try:
         proxy.serve()
     except Exception: