Skip to content

GitLab

Commit 2048471a authored by Dimitris Aragiorgis's avatar Dimitris Aragiorgis
Browse files

Change logging to be more informative 


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