Revision 2048471a

b/nfdhcpd
281 281
            logging.warn(" - Truncated msg: %d/%d bytes sent",
282 282
                         count, ldata)
283 283

  
284
    def __repr__(self):
285
        ret =  "hostname %s, tap %s, mac %s" % \
286
               (self.hostname, self.tap, self.mac)
287
        if self.ip:
288
            ret += ", ip %s" % self.ip
289
        if self.eui64:
290
            ret += ", eui64 %s" % self.eui64
291
        return ret
292

  
284 293

  
285 294
class Subnet(object):
286 295
    def __init__(self, net=None, gw=None, dev=None):
......
428 437
            else:
429 438
                logging.debug(" - Getting binding for ifindex %s", ifindex)
430 439
                b = self.clients[ifindex]
440
            logging.info(" - Client found. %s", b)
431 441
            return b
432 442
        except KeyError:
433
            logging.debug(" - No client found for mac / ifindex %s / %s",
434
                          mac, ifindex)
443
            logging.info(" - No client found. mac: %s, ifindex: %s",
444
                         mac, ifindex)
435 445
            return None
436 446

  
437 447
    def _cleanup(self):
......
554 564
                else:
555 565
                    self.clients[ifindex] = b
556 566
                    k = ifindex
557
                logging.info(" - Added client:")
558
                logging.info(" + %10s | %20s %20s %10s %20s %40s",
559
                             k, b.hostname, b.mac, b.tap, b.ip, b.eui64)
567
                logging.info(" - Added client %s. %s", k, b)
560 568

  
561 569
    def remove_tap(self, tap):
562 570
        """ Cleanup clients on a removed interface
......
565 573
        try:
566 574
            for k, cl in self.clients.items():
567 575
                if cl.tap == tap:
568
                    logging.info("Removing client %s and closing socket on %s",
569
                                 cl.hostname, cl.tap)
570
                    logging.info(" - %10s | %20s %20s %10s %20s %40s",
571
                                 k, cl.hostname, cl.mac, cl.tap, cl.ip, cl.eui64)
572 576
                    cl.socket.close()
573 577
                    del self.clients[k]
578
                    logging.info("Removed client %s. %s", k, cl)
574 579
        except:
575 580
            logging.debug("Client on %s disappeared!!!", tap)
576 581

  
......
579 584
        """ Generate a reply to bnetfilter-queue-deva BOOTP/DHCP request
580 585

  
581 586
        """
582
        logging.info(" * Processing pending DHCP request")
587
        logging.info(" * DHCP: Processing pending request")
583 588
        # Workaround for supporting both squeezy's nfqueue-bindings-python
584 589
        # and wheezy's python-nfqueue because for some reason the function's
585 590
        # signature has changed and has broken compatibility
......
607 612
        binding = self.get_binding(indev, mac)
608 613
        if binding is None:
609 614
            # We don't know anything about this interface, so accept the packet
610
            # and return
611
            logging.debug(" - Ignoring DHCP request on unknown iface %s", indev)
612
            # We don't know what to do with this packet, so let the kernel
613
            # handle it
615
            # and return an let the kernel handle it
614 616
            payload.set_verdict(nfqueue.NF_ACCEPT)
615 617
            return
616 618

  
......
618 620
        payload.set_verdict(nfqueue.NF_DROP)
619 621

  
620 622
        if mac != binding.mac:
621
            logging.warn(" - Recieved spoofed DHCP request: mac %s, indev %s",
622
                         mac, indev)
623
            logging.warn(" - DHCP: Recieved spoofed request from %s (and not %s)",
624
                         mac, binding)
623 625
            return
624 626

  
625 627
        if not binding.ip:
626
            logging.info(" - No IP found in binding file.")
628
            logging.info(" - DHCP: No IP found in binding file %s.", binding)
627 629
            return
628 630

  
629
        logging.info(" - Generating DHCP response:"
630
                     " host %s, mac %s, tap %s, indev %s",
631
                       binding.hostname, mac, binding.tap, indev)
632

  
631
        if not DHCP in pkt:
632
            logging.warn(" - DHCP: Invalid request with no DHCP payload found. %s", binding)
633
            return
633 634

  
634 635
        resp = Ether(dst=mac, src=self.get_iface_hw_addr(binding.indev))/\
635 636
               IP(src=DHCP_DUMMY_SERVER_IP, dst=binding.ip)/\
636 637
               UDP(sport=pkt.dport, dport=pkt.sport)/resp
637 638
        subnet = binding.net
638 639

  
639
        if not DHCP in pkt:
640
            logging.warn(" - Invalid request from %s on %s, no DHCP"
641
                         " payload found", binding.mac, binding.tap)
642
            return
643

  
644 640
        dhcp_options = []
645 641
        requested_addr = binding.ip
646 642
        for opt in pkt[DHCP].options:
......
649 645
            if type(opt) is tuple and opt[0] == "requested_addr":
650 646
                requested_addr = opt[1]
651 647

  
652
        logging.info(" - %s from %s on %s", DHCP_TYPES.get(req_type, "UNKNOWN"),
653
                     binding.mac, binding.tap)
648
        logging.info(" - DHCP: %s from %s",
649
                     DHCP_TYPES.get(req_type, "UNKNOWN"), binding)
654 650

  
655 651
        if self.dhcp_domain:
656 652
            domainname = self.dhcp_domain
......
659 655

  
660 656
        if req_type == DHCPREQUEST and requested_addr != binding.ip:
661 657
            resp_type = DHCPNAK
662
            logging.info(" - Sending DHCPNAK to %s on %s: requested %s"
663
                         " instead of %s", binding.mac, binding.tap,
664
                         requested_addr, binding.ip)
658
            logging.info(" - DHCP: Sending DHCPNAK to %s (because requested %s)",
659
                         binding, requested_addr)
665 660

  
666 661
        elif req_type in (DHCPDISCOVER, DHCPREQUEST):
667 662
            resp_type = DHCP_REQRESP[req_type]
......
688 683

  
689 684
        elif req_type == DHCPRELEASE:
690 685
            # Log and ignore
691
            logging.info(" - DHCPRELEASE from %s on %s",
692
                         binding.hostname, binding.tap)
686
            logging.info(" - DHCP: DHCPRELEASE from %s", binding)
693 687
            return
694 688

  
695 689
        # Finally, always add the server identifier and end options
......
700 694
        ]
701 695
        resp /= DHCP(options=dhcp_options)
702 696

  
703
        logging.info(" - %s to %s (%s) on %s", DHCP_TYPES[resp_type], mac,
704
                     binding.ip, binding.tap)
697
        logging.info(" - RESPONSE: %s for %s", DHCP_TYPES[resp_type], binding)
705 698
        try:
706 699
            binding.sendp(resp)
707 700
        except socket.error, e:
708
            logging.warn(" - DHCP response on %s (%s) failed: %s",
709
                         binding.tap, binding.hostname, str(e))
701
            logging.warn(" - DHCP: Response on %s failed: %s", binding, str(e))
710 702
        except Exception, e:
711
            logging.warn(" - Unkown error during DHCP response on %s (%s): %s",
712
                         binding.tap, binding.hostname, str(e))
703
            logging.warn(" - DHCP: Unkown error during response on %s: %s",
704
                         binding, str(e))
713 705

  
714 706
    def dhcpv6_response(self, arg1, arg2=None):  # pylint: disable=W0613
715 707

  
716
        logging.info(" * Processing pending DHCPv6 request")
708
        logging.info(" * DHCPv6: Processing pending request")
717 709
        # Workaround for supporting both squeezy's nfqueue-bindings-python
718 710
        # and wheezy's python-nfqueue because for some reason the function's
719 711
        # signature has changed and has broken compatibility
......
730 722
        binding = self.get_binding(indev, mac)
731 723
        if binding is None:
732 724
            # We don't know anything about this interface, so accept the packet
733
            # and return
734
            logging.debug(" - Ignoring dhcpv6 request for mac %s", mac)
735
            # We don't know what to do with this packet, so let the kernel
736
            # handle it
725
            # and return and let the kernel handle it
737 726
            payload.set_verdict(nfqueue.NF_ACCEPT)
738 727
            return
739 728

  
......
743 732
        subnet = binding.net6
744 733

  
745 734
        if subnet.net is None:
746
            logging.debug(" - No IPv6 network assigned for tap %s", binding.tap)
735
            logging.debug(" - DHCPv6: No IPv6 network assigned to %s", binding)
747 736
            return
748 737

  
749 738
        indevmac = self.get_iface_hw_addr(binding.indev)
......
755 744
        if ofll is None:
756 745
            return
757 746

  
758
        logging.info(" - Generating DHCPv6 response for host %s (mac %s) on tap %s",
759
                      binding.hostname, binding.mac, binding.tap)
760

  
761 747
        if self.dhcpv6_domains:
762 748
            domains = self.dhcpv6_domains
763 749
        else:
......
776 762
               DHCP6OptDNSDomains(dnsdomains)/\
777 763
               DHCP6OptDNSServers(dnsservers)
778 764

  
765
        logging.info(" - RESPONSE: DHCPv6 reply for %s", binding)
766

  
779 767
        try:
780 768
            binding.sendp(resp)
781 769
        except socket.error, e:
782
            logging.warn(" - DHCPv6 on %s (%s) failed: %s",
783
                         binding.tap, binding.hostname, str(e))
770
            logging.warn(" - DHCPv6: Response on %s failed: %s",
771
                         binding, str(e))
784 772
        except Exception, e:
785
            logging.warn(" - Unkown error during DHCPv6 on %s (%s): %s",
786
                         binding.tap, binding.hostname, str(e))
773
            logging.warn(" - DHCPv6: Unkown error during response on %s: %s",
774
                         binding, str(e))
787 775

  
788 776

  
789 777
    def rs_response(self, arg1, arg2=None):  # pylint: disable=W0613
790
        """ Generate a reply to a BOOTP/DHCP request
778
        """ Generate a reply to an ICMPv6 router solicitation
791 779

  
792 780
        """
793
        logging.info(" * Processing pending RS request")
781
        logging.info(" * RS: Processing pending request")
794 782
        # Workaround for supporting both squeezy's nfqueue-bindings-python
795 783
        # and wheezy's python-nfqueue because for some reason the function's
796 784
        # signature has changed and has broken compatibility
......
804 792
        try:
805 793
            mac = pkt.lladdr
806 794
        except:
807
            logging.debug(" - Cannot obtain lladdr in rs")
795
            logging.debug(" - RS: Cannot obtain lladdr")
808 796
            return
809 797

  
810 798
        indev = get_indev(payload)
......
812 800
        binding = self.get_binding(indev, mac)
813 801
        if binding is None:
814 802
            # We don't know anything about this interface, so accept the packet
815
            # and return
816
            logging.debug(" - Ignoring router solicitation on for mac %s", mac)
817
            # We don't know what to do with this packet, so let the kernel
818
            # handle it
803
            # and return and let the kernel handle it
819 804
            payload.set_verdict(nfqueue.NF_ACCEPT)
820 805
            return
821 806

  
......
823 808
        payload.set_verdict(nfqueue.NF_DROP)
824 809

  
825 810
        if mac != binding.mac:
826
            logging.warn(" - Received spoofed RS request: mac %s, tap %s",
827
                         mac, binding.tap)
811
            logging.warn(" - RS: Received spoofed request from %s (and not %s)",
812
                         mac, binding)
828 813
            return
829 814

  
830 815
        subnet = binding.net6
831 816

  
832 817
        if subnet.net is None:
833
            logging.debug(" - No IPv6 network assigned for tap %s", binding.tap)
818
            logging.debug(" - RS: No IPv6 network assigned to %s", binding)
834 819
            return
835 820

  
836 821
        indevmac = self.get_iface_hw_addr(binding.indev)
......
838 823
        if ifll is None:
839 824
            return
840 825

  
841
        logging.info(" - Generating RA for host %s (mac %s) on tap %s",
842
                      binding.hostname, mac, binding.tap)
843

  
844 826
        resp = Ether(src=indevmac)/\
845 827
               IPv6(src=str(ifll))/ICMPv6ND_RA(O=1, routerlifetime=14400)/\
846 828
               ICMPv6NDOptPrefixInfo(prefix=str(subnet.prefix),
......
850 832
            resp /= ICMPv6NDOptRDNSS(dns=self.ipv6_nameservers,
851 833
                                     lifetime=self.ra_period * 3)
852 834

  
835
        logging.info(" - RESPONSE: RA for %s", binding)
836

  
853 837
        try:
854 838
            binding.sendp(resp)
855 839
        except socket.error, e:
856
            logging.warn(" - RA on %s (%s) failed: %s",
857
                         binding.tap, binding.hostname, str(e))
840
            logging.warn(" - RS: RA failed on %s: %s",
841
                         binding, str(e))
858 842
        except Exception, e:
859
            logging.warn(" - Unkown error during RA on %s (%s): %s",
860
                         binding.tap, binding.hostname, str(e))
843
            logging.warn(" - RS: Unkown error during RA on %s: %s",
844
                         binding, str(e))
861 845

  
862 846
    def ns_response(self, arg1, arg2=None):  # pylint: disable=W0613
863 847
        """ Generate a reply to an ICMPv6 neighbor solicitation
864 848

  
865 849
        """
866 850

  
867
        logging.info(" * Processing pending NS request")
851
        logging.info(" * NS: Processing pending request")
868 852
        # Workaround for supporting both squeezy's nfqueue-bindings-python
869 853
        # and wheezy's python-nfqueue because for some reason the function's
870 854
        # signature has changed and has broken compatibility
......
879 863
        try:
880 864
            mac = ns.lladdr
881 865
        except:
882
            logging.debug(" - Cannot obtain lladdr from ns")
866
            logging.debug(" - NS: Cannot obtain lladdr")
883 867
            return
884 868

  
885 869

  
......
888 872
        binding = self.get_binding(indev, mac)
889 873
        if binding is None:
890 874
            # We don't know anything about this interface, so accept the packet
891
            # and return
892
            logging.debug(" - Ignoring neighbour solicitation for eui64 %s",
893
                          ns.tgt)
894
            # We don't know what to do with this packet, so let the kernel
895
            # handle it
875
            # and return and let the kernel handle it
896 876
            payload.set_verdict(nfqueue.NF_ACCEPT)
897 877
            return
898 878

  
899 879
        payload.set_verdict(nfqueue.NF_DROP)
900 880

  
901 881
        if mac != binding.mac:
902
            logging.warn(" - Received spoofed NS request"
903
                         " for mac %s from tap %s", mac, binding.tap)
882
            logging.warn(" - NS: Received spoofed request from %s (and not %s)",
883
                         mac, binding)
904 884
            return
905 885

  
906 886
        subnet = binding.net6
907 887
        if subnet.net is None:
908
            logging.debug(" - No IPv6 network assigned for the interface")
888
            logging.debug(" - NS: No IPv6 network assigned to %s", binding)
909 889
            return
910 890

  
911 891
        indevmac = self.get_iface_hw_addr(binding.indev)
......
915 895
            return
916 896

  
917 897
        if not (subnet.net.overlaps(ns.tgt) or str(ns.tgt) == str(ifll)):
918
            logging.debug(" - Received NS for a non-routable IP (%s)", ns.tgt)
898
            logging.debug(" - NS: Received NS for a non-routable IP (%s)", ns.tgt)
919 899
            return 1
920 900

  
921
        logging.info(" - Generating NA for host %s (mac %s) on tap %s",
922
                     binding.hostname, mac, binding.tap)
923

  
924 901
        resp = Ether(src=indevmac, dst=binding.mac)/\
925 902
               IPv6(src=str(ifll), dst=ns.src)/\
926 903
               ICMPv6ND_NA(R=1, O=0, S=1, tgt=ns.tgt)/\
927 904
               ICMPv6NDOptDstLLAddr(lladdr=indevmac)
928 905

  
906
        logging.info(" - RESPONSE: NA for %s ", binding)
907

  
929 908
        try:
930 909
            binding.sendp(resp)
931 910
        except socket.error, e:
932
            logging.warn(" - NA on %s (%s) failed: %s",
933
                         binding.tap, binding.hostname, str(e))
911
            logging.warn(" - NS: NA on %s failed: %s",
912
                         binding, str(e))
934 913
        except Exception, e:
935
            logging.warn(" - Unkown error during periodic NA to %s (%s): %s",
936
                         binding.tap, binding.hostname, str(e))
914
            logging.warn(" - NS: Unkown error during NA to %s: %s",
915
                         binding, str(e))
937 916

  
938 917
    def send_periodic_ra(self):
939 918
        # Use a separate thread as this may take a _long_ time with
......
941 920
        threading.Thread(target=self._send_periodic_ra).start()
942 921

  
943 922
    def _send_periodic_ra(self):
944
        logging.info("Sending out periodic RAs")
923
        logging.info(" * Periodic RA: Starting...")
945 924
        start = time.time()
946 925
        i = 0
947 926
        for binding in self.clients.values():
......
950 929
            # mac = binding.mac
951 930
            subnet = binding.net6
952 931
            if subnet.net is None:
953
                logging.debug(" - Skipping periodic RA on interface %s,"
954
                              " as it is not IPv6-connected", tap)
932
                logging.debug(" - Periodic RA: Skipping %s", binding)
955 933
                continue
956 934
            indevmac = self.get_iface_hw_addr(indev)
957 935
            ifll = subnet.make_ll64(indevmac)
......
964 942
            if self.ipv6_nameservers:
965 943
                resp /= ICMPv6NDOptRDNSS(dns=self.ipv6_nameservers,
966 944
                                         lifetime=self.ra_period * 3)
945
            logging.info(" - RESPONSE: NA for %s ", binding)
967 946
            try:
968 947
                binding.sendp(resp)
969 948
            except socket.error, e:
970
                logging.warn(" - Periodic RA on %s (%s) failed: %s",
971
                             tap, binding.hostname, str(e))
949
                logging.warn(" - Periodic RA: Failed on %s: %s",
950
                             binding, str(e))
972 951
            except Exception, e:
973
                logging.warn(" - Unkown error during periodic RA on %s (%s):"
974
                             " %s", tap, binding.hostname, str(e))
952
                logging.warn(" - Periodic RA: Unkown error on %s: %s",
953
                             binding, str(e))
975 954
            i += 1
976
        logging.info(" - Sent %d RAs in %.2f seconds", i, time.time() - start)
955
        logging.info(" - Periodic RA: Sent %d RAs in %.2f seconds", i, time.time() - start)
977 956

  
978 957
    def serve(self):
979 958
        """ Safely perform the main loop, freeing all resources upon exit

Also available in: Unified diff