fix loggers (using LoggerAdapter) & added join_prune_logger in...

fix loggers (using LoggerAdapter) & added join_prune_logger in Downstream/Upstream prune state machine & added originator_logger & fix downstream/upstream state machines

InterfaceIGMP.py

@@ -15,7 +15,6 @@ class InterfaceIGMP(Interface):
     ETH_P_IP = 0x0800		# Internet Protocol packet
     SO_ATTACH_FILTER = 26
 
-    # TODO filtro nao esta a funcionar bem no netkit
     FILTER_IGMP = [
         struct.pack('HBBI', 0x28, 0, 0, 0x0000000c),
         struct.pack('HBBI', 0x15, 0, 3, 0x00000800),
@@ -36,15 +35,7 @@ class InterfaceIGMP(Interface):
         rcv_s = socket.socket(socket.AF_PACKET, socket.SOCK_RAW, socket.htons(InterfaceIGMP.ETH_P_IP))
 
         # receive only IGMP packets by setting a BPF filter
-        # TODO filtro nao esta a funcionar bem no netkit
-        cmd = "tcpdump -ddd \"ip proto 2\""
-        result = subprocess.Popen(cmd, shell=True, stdout=subprocess.PIPE)
-        bpf_filter = b''
-
-        tmp = result.stdout.read().splitlines()
-        for line in tmp[1:]:
-            bpf_filter += struct.pack("HBBI", *tuple(map(int, line.split(b' '))))
-
+        bpf_filter = b''.join(InterfaceIGMP.FILTER_IGMP)
         b = create_string_buffer(bpf_filter)
         mem_addr_of_filters = addressof(b)
         fprog = struct.pack('HL', len(InterfaceIGMP.FILTER_IGMP), mem_addr_of_filters)
@@ -74,8 +65,7 @@ class InterfaceIGMP(Interface):
             packet = ReceivedPacket(raw_bytes, self)
             ip_src = packet.ip_header.ip_src
             if not (ip_src == "0.0.0.0" or IPv4Address(ip_src).is_multicast):
-                self.PKT_FUNCTIONS[packet.payload.get_igmp_type()](self, packet)
-
+                self.PKT_FUNCTIONS.get(packet.payload.get_igmp_type(), InterfaceIGMP.receive_unknown_type)(self, packet)
 
     ###########################################
     # Recv packets
@@ -104,6 +94,9 @@ class InterfaceIGMP(Interface):
         if ip_dst == igmp_group or (ip_dst == "224.0.0.1" and igmp_group == "0.0.0.0"):
             self.interface_state.receive_query(packet)
 
+    def receive_unknown_type(self, packet):
+        return
+
     PKT_FUNCTIONS = {
         Version_1_Membership_Report: receive_version_1_membership_report,
         Version_2_Membership_Report: receive_version_2_membership_report,

InterfacePIM.py

@@ -185,7 +185,21 @@ class InterfacePim(Interface):
 
             return state_refresh_capable
 
-
+    '''
+    def change_interface(self):
+        old_ip_address = self.ip_interface
+        self._recv_socket.setsockopt(socket.IPPROTO_IP, socket.IP_DROP_MEMBERSHIP,
+                     socket.inet_aton(Interface.MCAST_GRP) + socket.inet_aton(old_ip_address))
+
+        new_ip_interface = netifaces.ifaddresses(self.interface_name)[netifaces.AF_INET][0]['addr']
+        self._recv_socket.setsockopt(socket.IPPROTO_IP, socket.IP_ADD_MEMBERSHIP,
+                                     socket.inet_aton(Interface.MCAST_GRP) + socket.inet_aton(new_ip_interface))
+
+        self._send_socket.setsockopt(socket.SOL_IP, socket.IP_MULTICAST_IF, socket.inet_aton(new_ip_interface))
+        self.ip_interface = new_ip_interface
+        import Main
+        Main.kernel.vif_dic[new_ip_interface] = Main.kernel.vif_dic.pop(old_ip_address)
+    '''
 
     ###########################################
     # Recv packets

Kernel.py

 import socket
 import struct
-import netifaces
-from threading import Lock
+from threading import Lock, Thread
 import traceback
 
 import ipaddress
@@ -9,8 +8,8 @@ import ipaddress
 from RWLock.RWLock import RWLockWrite
 import Main
 
-from tree.tree_if_upstream import *
-from tree.tree_if_downstream import *
+from InterfacePIM import InterfacePim
+from InterfaceIGMP import InterfaceIGMP
 from tree.KernelEntry import KernelEntry
 
 
@@ -85,7 +84,7 @@ class Kernel:
         self.tree_logger = Main.logger.getChild('KernelTree')
 
         # receive signals from kernel with a background thread
-        handler_thread = threading.Thread(target=self.handler)
+        handler_thread = Thread(target=self.handler)
         handler_thread.daemon = True
         handler_thread.start()
 
@@ -103,34 +102,7 @@ class Kernel:
         struct in_addr vifc_rmt_addr;	/* IPIP tunnel addr */
     };
     '''
-    '''
-    def create_virtual_interface(self, ip_interface: str or bytes, interface_name: str, flags=0x0):
-        with self.interface_lock:
-            index = list(range(0, self.MAXVIFS) - self.vif_index_to_name_dic.keys())[0]
-
-
-            if type(ip_interface) is str:
-                ip_interface = socket.inet_aton(ip_interface)
-
-            struct_mrt_add_vif = struct.pack("HBBI 4s 4s", index, flags, 1, 0, ip_interface, socket.inet_aton("0.0.0.0"))
-            self.socket.setsockopt(socket.IPPROTO_IP, Kernel.MRT_ADD_VIF, struct_mrt_add_vif)
-            self.vif_dic[socket.inet_ntoa(ip_interface)] = index
-            self.vif_index_to_name_dic[index] = interface_name
-            self.vif_name_to_index_dic[interface_name] = index
-
-
-            with self.rwlock.genWlock():
-                for kernel_entry in list(self.routing.values()):
-                    kernel_entry.new_interface(index)
-
-            return index
-    '''
-
-
-
-######################### new create virtual if
     def create_virtual_interface(self, ip_interface: str or bytes, interface_name: str, index, flags=0x0):
-        #with self.interface_lock:
         if type(ip_interface) is str:
             ip_interface = socket.inet_aton(ip_interface)
 
@@ -151,7 +123,6 @@ class Kernel:
 
 
     def create_pim_interface(self, interface_name: str, state_refresh_capable:bool):
-        from InterfacePIM import InterfacePim
         with self.interface_lock:
             pim_interface = self.pim_interface.get(interface_name)
             igmp_interface = self.igmp_interface.get(interface_name)
@@ -174,7 +145,6 @@ class Kernel:
                 self.create_virtual_interface(ip_interface=ip_interface, interface_name=interface_name, index=index)
 
     def create_igmp_interface(self, interface_name: str):
-        from InterfaceIGMP import InterfaceIGMP
         with self.interface_lock:
             pim_interface = self.pim_interface.get(interface_name)
             igmp_interface = self.igmp_interface.get(interface_name)
@@ -197,41 +167,6 @@ class Kernel:
                 self.create_virtual_interface(ip_interface=ip_interface, interface_name=interface_name, index=index)
 
 
-
-    '''
-    def create_interface(self, interface_name: str, igmp:bool = False, pim:bool = False):
-        from InterfaceIGMP import InterfaceIGMP
-        from InterfacePIM import InterfacePim
-        if (not igmp and not pim):
-            return
-        with self.interface_lock:
-            pim_interface = self.pim_interface.get(interface_name)
-            igmp_interface = self.igmp_interface.get(interface_name)
-            vif_already_exists = pim_interface or igmp_interface
-            if pim_interface:
-                index = pim_interface.vif_index
-            elif igmp_interface:
-                index = igmp_interface.vif_index
-            else:
-                index = list(range(0, self.MAXVIFS) - self.vif_index_to_name_dic.keys())[0]
-
-            ip_interface = None
-            if pim and interface_name not in self.pim_interface:
-                pim_interface = InterfacePim(interface_name, index)
-                self.pim_interface[interface_name] = pim_interface
-                ip_interface = pim_interface.ip_interface
-            if igmp and interface_name not in self.igmp_interface:
-                igmp_interface = InterfaceIGMP(interface_name, index)
-                self.igmp_interface[interface_name] = igmp_interface
-                ip_interface = igmp_interface.ip_interface
-
-
-            if not vif_already_exists:
-                self.create_virtual_interface(ip_interface=ip_interface, interface_name=interface_name, index=index)
-    '''
-
-
-
     def remove_interface(self, interface_name, igmp:bool=False, pim:bool=False):
         with self.interface_lock:
             ip_interface = None
@@ -252,10 +187,6 @@ class Kernel:
                 self.remove_virtual_interface(ip_interface)
 
 
-
-
-
-
     def remove_virtual_interface(self, ip_interface):
         #with self.interface_lock:
         index = self.vif_dic[ip_interface]
@@ -292,10 +223,6 @@ class Kernel:
     '''
     def set_multicast_route(self, kernel_entry: KernelEntry):
         source_ip = socket.inet_aton(kernel_entry.source_ip)
-        print("============")
-        print(type(kernel_entry.group_ip))
-        print(kernel_entry.group_ip)
-        print("============")
         group_ip = socket.inet_aton(kernel_entry.group_ip)
 
         outbound_interfaces = kernel_entry.get_outbound_interfaces_indexes()
@@ -422,11 +349,11 @@ class Kernel:
     # notify KernelEntries about changes at the unicast routing table
     def notify_unicast_changes(self, subnet):
         with self.rwlock.genWlock():
-            for source_ip in self.routing.keys():
+            for source_ip in list(self.routing.keys()):
                 source_ip_obj = ipaddress.ip_address(source_ip)
                 if source_ip_obj not in subnet:
                     continue
-                for group_ip in self.routing[source_ip].keys():
+                for group_ip in list(self.routing[source_ip].keys()):
                     self.routing[source_ip][group_ip].network_update()
 
 

TestLogger.py

@@ -17,36 +17,6 @@ class RootFilter(logging.Filter):
             record.tree = ''
         if not hasattr(record, 'vif'):
             record.vif = ''
-
-        return True
-
-class NonRootFilter(logging.Filter):
-    """
-    This is a filter which injects contextual information into the log.
-
-    Rather than use actual contextual information, we just use random
-    data in this demo.
-    """
-    def __init__(self, tree):
-        super().__init__()
-        self.tree = tree
-
-    def filter(self, record):
-        record.tree = self.tree
-        return True
-
-
-class InterfaceFilter(logging.Filter):
-    """
-    This is a filter which injects contextual information into the log.
-
-    Rather than use actual contextual information, we just use random
-    data in this demo.
-    """
-    def __init__(self, vif):
-        super().__init__()
-        self.vif = vif
-
-    def filter(self, record):
-        record.vif = self.vif
+        if not hasattr(record, 'interfacename'):
+            record.interfacename = ''
         return True

UnicastRouting.py

@@ -101,7 +101,19 @@ class UnicastRouting(object):
             Main.kernel.notify_unicast_changes(subnet)
         elif action == "RTM_NEWADDR" or action == "RTM_DELADDR":
             # TODO ALTERACOES NA INTERFACE
-            print("a")
+            '''
+            print(msg)
+            attrs = msg["attrs"]
+            for (key, value) in attrs:
+                print((key, value))
+                if key == "IFA_LABEL":
+                    interface_name = value
+                    break
+            pim_interface = Main.kernel.pim_interface.get(interface_name)
+            pim_interface.change_interface()
+            igmp_interface = Main.kernel.igmp_interface.get(interface_name)
+            '''
+            pass
 
 
     def stop(self):

tree/KernelEntry.py

-import Main
-import socket
-
-from tree.originator import OriginatorState
 from tree.tree_if_upstream import TreeInterfaceUpstream
 from tree.tree_if_downstream import TreeInterfaceDownstream
 from .tree_interface import TreeInterface
@@ -10,20 +6,16 @@ from tree.metric import AssertMetric
 import UnicastRouting
 from time import time
 import Main
-from TestLogger import NonRootFilter, logging
+import logging
 
 class KernelEntry:
     TREE_TIMEOUT = 180
-
+    KERNEL_LOGGER = logging.getLogger('pim.KernelEntry')
 
     def __init__(self, source_ip: str, group_ip: str, inbound_interface_index: int):
-        self.kernel_entry_logger = Main.logger.getChild('KernelEntry')
-        ch = logging.NullHandler()
-        ch.addFilter(NonRootFilter('(' + source_ip + ',' + group_ip + ')'))
-        self.kernel_entry_logger.addHandler(ch)
+        self.kernel_entry_logger = logging.LoggerAdapter(KernelEntry.KERNEL_LOGGER, {'tree': '(' + source_ip + ',' + group_ip + ')'})
         self.kernel_entry_logger.debug('Create KernelEntry')
 
-
         self.source_ip = source_ip
         self.group_ip = group_ip
 
@@ -50,24 +42,27 @@ class KernelEntry:
         # (S,G) starts IG state
         self._was_olist_null = False
 
+        # Locks
+        self._multicast_change = Lock()
+        self._lock_test2 = RLock()
+        self.CHANGE_STATE_LOCK = RLock()
+
         # decide inbound interface based on rpf check
         self.inbound_interface_index = Main.kernel.vif_dic[self.check_rpf()]
 
         self.interface_state = {}  # type: Dict[int, TreeInterface]
-        for i in Main.kernel.vif_index_to_name_dic.keys():
-            try:
-                if i == self.inbound_interface_index:
-                    self.interface_state[i] = TreeInterfaceUpstream(self, i, False)
-                else:
-                    self.interface_state[i] = TreeInterfaceDownstream(self, i)
-            except:
-                import traceback
-                print(traceback.print_exc())
-                continue
+        with self.CHANGE_STATE_LOCK:
+            for i in Main.kernel.vif_index_to_name_dic.keys():
+                try:
+                    if i == self.inbound_interface_index:
+                        self.interface_state[i] = TreeInterfaceUpstream(self, i, False)
+                    else:
+                        self.interface_state[i] = TreeInterfaceDownstream(self, i)
+                except:
+                    import traceback
+                    print(traceback.print_exc())
+                    continue
 
-        self._multicast_change = Lock()
-        self._lock_test2 = RLock()
-        self.CHANGE_STATE_LOCK = RLock()
         self.change()
         self.evaluate_olist_change()
         self.timestamp_of_last_state_refresh_message_received = 0
@@ -213,9 +208,10 @@ class KernelEntry:
                 old_downstream_interface.delete(change_type_interface=True)
 
                 # atualizar tabela de encaminhamento multicast
-                self._was_olist_null = False
+                #self._was_olist_null = False
                 self.change()
                 self.evaluate_olist_change()
+                new_upstream_interface.change_on_unicast_routing(interface_change=True)
             elif self.rpf_node != rpf_node:
                 self.rpf_node = rpf_node
                 self.interface_state[self.inbound_interface_index].change_on_unicast_routing()

tree/downstream_prune.py

@@ -96,7 +96,8 @@ class NoInfo(DownstreamStateABS):
 
         interface.set_prune_pending_timer(time)
 
-        print("receivedPrune, NI -> PP")
+        #print("receivedPrune, NI -> PP")
+        interface.join_prune_logger.debug("receivedPrune, NI -> PP")
 
     @staticmethod
     def receivedJoin(interface: "TreeInterfaceDownstream"):
@@ -107,7 +108,8 @@ class NoInfo(DownstreamStateABS):
         """
 
         # Do nothing
-        print("receivedJoin, NI -> NI")
+        #print("receivedJoin, NI -> NI")
+        interface.join_prune_logger.debug("receivedJoin, NI -> NI")
 
     @staticmethod
     def receivedGraft(interface: "TreeInterfaceDownstream", source_ip):
@@ -118,7 +120,8 @@ class NoInfo(DownstreamStateABS):
         """
         interface.send_graft_ack(source_ip)
 
-        print('receivedGraft, NI -> NI')
+        #print('receivedGraft, NI -> NI')
+        interface.join_prune_logger.debug('receivedGraft, NI -> NI')
 
     @staticmethod
     def PPTexpires(interface: "TreeInterfaceDownstream"):
@@ -127,7 +130,7 @@ class NoInfo(DownstreamStateABS):
 
         @type interface: TreeInterfaceDownstreamDownstream
         """
-        #assert False
+        #assert False, "PPTexpires in state NI"
         return
 
     @staticmethod
@@ -137,7 +140,7 @@ class NoInfo(DownstreamStateABS):
 
         @type interface: TreeInterfaceDownstreamDownstream
         """
-        #assert False
+        #assert False, "PTexpires in state NI"
         return
 
     @staticmethod
@@ -147,9 +150,8 @@ class NoInfo(DownstreamStateABS):
 
         @type interface: TreeInterfaceDownstreamDownstream
         """
-        pass
-
         # Do nothing
+        return
 
     @staticmethod
     def send_state_refresh(interface: "TreeInterfaceDownstream"):
@@ -158,9 +160,12 @@ class NoInfo(DownstreamStateABS):
 
         @type interface: TreeInterfaceDownstreamDownstream
         """
-        pass
-
         # Do nothing
+        return
+
+    def __str__(self):
+        return "NI"
+
 
 
 class PrunePending(DownstreamStateABS):
@@ -181,7 +186,9 @@ class PrunePending(DownstreamStateABS):
         @type interface: TreeInterfaceDownstreamDownstream
         """
 
-        print('receivedPrune, PP -> PP')
+        #print('receivedPrune, PP -> PP')
+        interface.join_prune_logger.debug('receivedPrune, PP -> PP')
+
 
     @staticmethod
     def receivedJoin(interface: "TreeInterfaceDownstream"):
@@ -190,13 +197,12 @@ class PrunePending(DownstreamStateABS):
 
         @type interface: TreeInterfaceDownstreamDownstream
         """
-
-        #interface.get_ppt().stop()
         interface.clear_prune_pending_timer()
 
         interface.set_prune_state(DownstreamState.NoInfo)
 
-        print('receivedJoin, PP -> NI')
+        #print('receivedJoin, PP -> NI')
+        interface.join_prune_logger.debug('receivedJoin, PP -> NI')
 
     @staticmethod
     def receivedGraft(interface: "TreeInterfaceDownstream", source_ip):
@@ -210,7 +216,8 @@ class PrunePending(DownstreamStateABS):
         interface.set_prune_state(DownstreamState.NoInfo)
         interface.send_graft_ack(source_ip)
 
-        print('receivedGraft, PP -> NI')
+        #print('receivedGraft, PP -> NI')
+        interface.join_prune_logger.debug('receivedGraft, PP -> NI')
 
     @staticmethod
     def PPTexpires(interface: "TreeInterfaceDownstream"):
@@ -225,7 +232,8 @@ class PrunePending(DownstreamStateABS):
         if len(interface.get_interface().neighbors) > 1:
             interface.send_pruneecho()
 
-        print('PPTexpires, PP -> P')
+        #print('PPTexpires, PP -> P')
+        interface.join_prune_logger.debug('PPTexpires, PP -> P')
 
     @staticmethod
     def PTexpires(interface: "TreeInterfaceDownstream"):
@@ -235,7 +243,7 @@ class PrunePending(DownstreamStateABS):
         @type interface: TreeInterfaceDownstreamDownstream
         """
 
-        #assert False
+        #assert False, "PTexpires in state PP"
         return
 
     @staticmethod
@@ -245,8 +253,6 @@ class PrunePending(DownstreamStateABS):
 
         @type interface: TreeInterfaceDownstreamDownstream
         """
-
-        # todo understand better
         interface.clear_prune_pending_timer()
 
         interface.set_prune_state(DownstreamState.NoInfo)
@@ -260,8 +266,10 @@ class PrunePending(DownstreamStateABS):
 
         @type interface: TreeInterfaceDownstreamDownstream
         """
-        pass
+        return
 
+    def __str__(self):
+        return "PP"
 
 class Pruned(DownstreamStateABS):
     '''
@@ -279,10 +287,11 @@ class Pruned(DownstreamStateABS):
 
         @type interface: TreeInterfaceDownstreamDownstream
         """
-        if interface.get_received_prune_holdtime() > interface.remaining_prune_timer():
+        if holdtime > interface.remaining_prune_timer():
             interface.set_prune_timer(holdtime)
 
-        print('receivedPrune, P -> P')
+        #print('receivedPrune, P -> P')
+        interface.join_prune_logger.debug('receivedPrune, P -> P')
 
     @staticmethod
     def receivedJoin(interface: "TreeInterfaceDownstream"):
@@ -295,7 +304,8 @@ class Pruned(DownstreamStateABS):
 
         interface.set_prune_state(DownstreamState.NoInfo)
 
-        print('receivedPrune, P -> NI')
+        #print('receivedPrune, P -> NI')
+        interface.join_prune_logger.debug('receivedPrune, P -> NI')
 
     @staticmethod
     def receivedGraft(interface: "TreeInterfaceDownstream", source_ip):
@@ -308,7 +318,8 @@ class Pruned(DownstreamStateABS):
         interface.set_prune_state(DownstreamState.NoInfo)
         interface.send_graft_ack(source_ip)
 
-        print('receivedGraft, P -> NI')
+        #print('receivedGraft, P -> NI')
+        interface.join_prune_logger.debug('receivedGraft, P -> NI')
 
     @staticmethod
     def PPTexpires(interface: "TreeInterfaceDownstream"):
@@ -317,7 +328,7 @@ class Pruned(DownstreamStateABS):
 
         @type interface: TreeInterfaceDownstreamDownstream
         """
-        #assert False
+        #assert False, "PPTexpires in state P"
         return
 
     @staticmethod
@@ -327,10 +338,10 @@ class Pruned(DownstreamStateABS):
 
         @type interface: TreeInterfaceDownstreamDownstream
         """
-
         interface.set_prune_state(DownstreamState.NoInfo)
 
-        print('PTexpires, P -> NI')
+        #print('PTexpires, P -> NI')
+        interface.join_prune_logger.debug('PTexpires, P -> NI')
 
     @staticmethod
     def is_now_RPF_Interface(interface: "TreeInterfaceDownstream"):
@@ -339,8 +350,6 @@ class Pruned(DownstreamStateABS):
 
         @type interface: TreeInterfaceDownstreamDownstream
         """
-        # todo ver melhor
-        #interface.get_pt().stop()
         interface.clear_prune_timer()
         interface.set_prune_state(DownstreamState.NoInfo)
 
@@ -356,8 +365,11 @@ class Pruned(DownstreamStateABS):
         if interface.get_interface().is_state_refresh_capable():
             interface.set_prune_timer(interface.get_received_prune_holdtime())
 
-        print('send_state_refresh, P -> P')
+        #print('send_state_refresh, P -> P')
+        interface.join_prune_logger.debug('send_state_refresh, P -> P')
 
+    def __str__(self):
+        return "P"
 
 class DownstreamState():
     NoInfo = NoInfo()

tree/originator.py

@@ -30,26 +30,28 @@ class Originator(OriginatorStateABC):
         '''
         @type tree: Tree
         '''
-        print('SRT expired, O to O')
-
         tree.set_state_refresh_timer()
         tree.create_state_refresh_msg()
+        #print('SRT expired, O to O')
+        tree.originator_logger.debug('SRT expired, O -> O')
 
     @staticmethod
     def SATexpires(tree):
-        print('SAT expired, O to NO')
-
         tree.clear_state_refresh_timer()
         tree.set_originator_state(OriginatorState.NotOriginator)
 
+        #print('SAT expired, O to NO')
+        tree.originator_logger.debug('SAT expired, O -> NO')
+
     @staticmethod
     def SourceNotConnected(tree):
-        print('Source no longer directly connected, O to NO')
-
         tree.clear_state_refresh_timer()
         tree.clear_source_active_timer()
         tree.set_originator_state(OriginatorState.NotOriginator)
 
+        #print('Source no longer directly connected, O to NO')
+        tree.originator_logger.debug('Source no longer directly connected, O -> NO')
+
 
 class NotOriginator(OriginatorStateABC):
     @staticmethod
@@ -62,15 +64,16 @@ class NotOriginator(OriginatorStateABC):
         tree.set_state_refresh_timer()
         tree.set_source_active_timer()
 
-        print('new DataMsg from Source, NO to O')
+        #print('new DataMsg from Source, NO to O')
+        tree.originator_logger.debug('new DataMsg from Source, NO -> O')
 
     @staticmethod
     def SRTexpires(tree):
-        assert False
+        assert False, "SRTexpires in NO"
 
     @staticmethod
     def SATexpires(tree):
-        assert False
+        assert False, "SATexpires in NO"
 
     @staticmethod
     def SourceNotConnected(tree):

tree/tree_if_downstream.py

@@ -12,14 +12,20 @@ from Packet.PacketPimStateRefresh import PacketPimStateRefresh
 from Packet.Packet import Packet
 from Packet.PacketPimHeader import PacketPimHeader
 import traceback
-
+import logging
+import Main
 
 class TreeInterfaceDownstream(TreeInterface):
+    LOGGER = logging.getLogger('pim.KernelEntry.DownstreamInterface')
+
     def __init__(self, kernel_entry, interface_id):
-        logger = kernel_entry.kernel_entry_logger.getChild('DownstreamInterface')
+        extra_dict_logger = kernel_entry.kernel_entry_logger.extra.copy()
+        extra_dict_logger['vif'] = interface_id
+        extra_dict_logger['interfacename'] = Main.kernel.vif_index_to_name_dic[interface_id]
+        logger = logging.LoggerAdapter(TreeInterfaceDownstream.LOGGER, extra_dict_logger)
         TreeInterface.__init__(self, kernel_entry, interface_id, logger)
         self.logger.debug('Created DownstreamInterface')
-
+        self.join_prune_logger.debug(str(self._prune_state))
 
     ##########################################
     # Set state
@@ -28,6 +34,7 @@ class TreeInterfaceDownstream(TreeInterface):
         with self.get_state_lock():
             if new_state != self._prune_state:
                 self._prune_state = new_state
+                self.join_prune_logger.debug(str(new_state))
 
                 self.change_tree()
                 self.evaluate_ingroup()
@@ -121,11 +128,6 @@ class TreeInterfaceDownstream(TreeInterface):
         if self.is_pruned():
             prune_indicator_bit = 1
 
-            # TODO set timer
-            # todo maybe ja feito na maquina de estados Prune downstream
-            # if state_refresh_capable
-            #   set PT....
-
         import UnicastRouting
         (metric_preference, metric, mask) = UnicastRouting.get_metric(state_refresh_msg_received.source_address)
 

tree/tree_if_upstream.py

@@ -6,6 +6,7 @@ Created on Jul 16, 2015
 from .tree_interface import TreeInterface
 from .upstream_prune import UpstreamState
 from threading import Timer
+from CustomTimer.RemainingTimer import RemainingTimer
 from .globals import *
 import random
 from .metric import AssertMetric
@@ -14,11 +15,18 @@ from Packet.PacketPimStateRefresh import PacketPimStateRefresh
 import traceback
 from . import DataPacketsSocket
 import threading
+import logging
+import Main
 
 
 class TreeInterfaceUpstream(TreeInterface):
+    LOGGER = logging.getLogger('pim.KernelEntry.UpstreamInterface')
+
     def __init__(self, kernel_entry, interface_id, is_originater: bool):
-        logger = kernel_entry.kernel_entry_logger.getChild('UpstreamInterface')
+        extra_dict_logger = kernel_entry.kernel_entry_logger.extra.copy()
+        extra_dict_logger['vif'] = interface_id
+        extra_dict_logger['interfacename'] = Main.kernel.vif_index_to_name_dic[interface_id]
+        logger = logging.LoggerAdapter(TreeInterfaceUpstream.LOGGER, extra_dict_logger)
         TreeInterface.__init__(self, kernel_entry, interface_id, logger)
 
         # Graft/Prune State:
@@ -27,12 +35,14 @@ class TreeInterfaceUpstream(TreeInterface):
         self._override_timer = None
         self._prune_limit_timer = None
         self._last_rpf = self.get_neighbor_RPF()
+        self.join_prune_logger.debug(str(self._graft_prune_state))
 
         # Originator state
         self._originator_state = OriginatorState.NotOriginator
         self._state_refresh_timer = None
         self._source_active_timer = None
         self._prune_now_counter = 0
+        self.originator_logger = logging.LoggerAdapter(TreeInterfaceUpstream.LOGGER, extra_dict_logger)
 
         if self.is_S_directly_conn():
             self._graft_prune_state.sourceIsNowDirectConnect(self)
@@ -71,6 +81,7 @@ class TreeInterfaceUpstream(TreeInterface):
         with self.get_state_lock():
             if new_state != self._graft_prune_state:
                 self._graft_prune_state = new_state
+                self.join_prune_logger.debug(str(new_state))
 
                 self.change_tree()
                 self.evaluate_ingroup()
@@ -91,6 +102,9 @@ class TreeInterfaceUpstream(TreeInterface):
     def is_prune_limit_timer_running(self):
         return self._prune_limit_timer is not None and self._prune_limit_timer.is_alive()
 
+    def remaining_prune_limit_timer(self):
+        return 0 if not self._prune_limit_timer else self._prune_limit_timer.time_remaining()
+
     ##########################################
     # Set timers
     ##########################################
@@ -114,7 +128,7 @@ class TreeInterfaceUpstream(TreeInterface):
 
     def set_prune_limit_timer(self, time=T_LIMIT):
         self.clear_prune_limit_timer()
-        self._prune_limit_timer = Timer(time, self.prune_limit_timeout)
+        self._prune_limit_timer = RemainingTimer(time, self.prune_limit_timeout)
         self._prune_limit_timer.start()
 
     def clear_prune_limit_timer(self):
@@ -177,6 +191,7 @@ class TreeInterfaceUpstream(TreeInterface):
 
     def recv_prune_msg(self, upstream_neighbor_address, holdtime):
         super().recv_prune_msg(upstream_neighbor_address, holdtime)
+        self.set_receceived_prune_holdtime(holdtime)
         self._graft_prune_state.seePrune(self)
 
     def recv_graft_ack_msg(self, source_ip_of_graft_ack):
@@ -232,13 +247,13 @@ class TreeInterfaceUpstream(TreeInterface):
         self.change_rpf(self.is_olist_null())
 
     # caused by unicast routing table:
-    def change_on_unicast_routing(self):
-        self.change_rpf(self.is_olist_null())
+    def change_on_unicast_routing(self, interface_change=False):
+        self.change_rpf(self.is_olist_null(), interface_change)
 
 
-    def change_rpf(self, olist_is_null):
+    def change_rpf(self, olist_is_null, interface_change=False):
         current_rpf = self.get_neighbor_RPF()
-        if self._last_rpf != current_rpf:
+        if interface_change or self._last_rpf != current_rpf:
             self._last_rpf = current_rpf
             if olist_is_null:
                 self._graft_prune_state.RPFnbrChanges_olistIsNull(self)

tree/tree_interface.py

@@ -24,18 +24,15 @@ from .metric import AssertMetric
 from threading import Timer
 from .local_membership import LocalMembership
 from .globals import *
-from TestLogger import InterfaceFilter, logging
+import logging
 
 class TreeInterface(metaclass=ABCMeta):
-    def __init__(self, kernel_entry, interface_id, logger):
+    def __init__(self, kernel_entry, interface_id, logger: logging.LoggerAdapter):
         self._kernel_entry = kernel_entry
         self._interface_id = interface_id
         self.logger = logger
-        ch = logging.NullHandler()
-        ch.addFilter(InterfaceFilter(interface_id))
-        self.logger.addHandler(ch)
-        self.assert_logger = logger.getChild('Assert')
-        self.join_prune_logger = logger.getChild('JoinPrune')
+        self.assert_logger = logging.LoggerAdapter(logger.logger.getChild('Assert'), logger.extra)
+        self.join_prune_logger = logging.LoggerAdapter(logger.logger.getChild('JoinPrune'), logger.extra)
 
         # Local Membership State
         try:
@@ -58,6 +55,7 @@ class TreeInterface(metaclass=ABCMeta):
         self._assert_state = AssertState.NoInfo
         self._assert_winner_metric = AssertMetric()
         self._assert_timer = None
+        self.assert_logger.debug("NI")
 
         # Received prune hold time
         self._received_prune_holdtime = None
@@ -265,9 +263,6 @@ class TreeInterface(metaclass=ABCMeta):
     def is_forwarding(self):
         pass
 
-    def nbr_died(self):
-        pass
-
     def nbr_connected(self):
         pass
 
@@ -331,9 +326,6 @@ class TreeInterface(metaclass=ABCMeta):
         with self._igmp_lock:
             return self._local_membership_state.has_members()
 
-    def __str__(self):
-        return '{}<{}>'.format(self.__class__, self._interface.get_link())
-
     def get_interface(self):
         kernel = Main.kernel
         interface_name = kernel.vif_index_to_name_dic[self._interface_id]
@@ -377,12 +369,6 @@ class TreeInterface(metaclass=ABCMeta):
         else:
             return self._kernel_entry.rpf_node
 
-    def i_am_assert_loser(self):
-        return self._assert_state == AssertState.Loser
-
-    def is_assert_winner(self):
-        return not self.is_downstream() and not self._assert_state == AssertState.Loser
-
     def is_S_directly_conn(self):
         return self._kernel_entry.rpf_node == self._kernel_entry.source_ip
 
@@ -404,6 +390,9 @@ class TreeInterface(metaclass=ABCMeta):
             return not self._assert_winner_metric.i_am_assert_winner(self) and \
                    self._assert_winner_metric.is_better_than(AssertMetric.spt_assert_metric(self))
 
+    def i_am_assert_loser(self):
+        return self._assert_state == AssertState.Loser
+
     def could_assert(self):
         return self.is_downstream()
 

tree/upstream_prune.py

@@ -149,17 +149,11 @@ class Forward(UpstreamStateABC):
         """
         if not interface.is_S_directly_conn():
             interface.set_state(UpstreamState.Pruned)
-
-            #interface.get_ot().stop()
-
-            #timer = interface._prune_limit_timer
-            #timer.set_timer(interface.t_override)
-            #timer.start()
-            interface.set_prune_limit_timer()
-
             interface.send_prune()
+            interface.set_prune_limit_timer()
 
-            print("dataArrivesRPFinterface_OListNull_PLTstoped, F -> P")
+            #print("dataArrivesRPFinterface_OListNull_PLTstoped, F -> P")
+            interface.join_prune_logger.debug("dataArrivesRPFinterface_OListNull_PLTstoped, F -> P")
 
     @staticmethod
     def stateRefreshArrivesRPFnbr_pruneIs1(interface: "TreeInterfaceUpstream"):
@@ -173,7 +167,8 @@ class Forward(UpstreamStateABC):
         if not interface.is_override_timer_running():
             interface.set_override_timer()
 
-        print('stateRefreshArrivesRPFnbr_pruneIs1, F -> F')
+        #print('stateRefreshArrivesRPFnbr_pruneIs1, F -> F')
+        interface.join_prune_logger.debug('stateRefreshArrivesRPFnbr_pruneIs1, F -> F')
 
     @staticmethod
     def stateRefreshArrivesRPFnbr_pruneIs0_PLTstoped(interface: "TreeInterfaceUpstream"):
@@ -184,9 +179,8 @@ class Forward(UpstreamStateABC):
 
         @type interface: TreeInterfaceUpstream
         """
-
-        print(
-            'stateRefreshArrivesRPFnbr_pruneIs0_PLTstoped, F -> F')
+        #print('stateRefreshArrivesRPFnbr_pruneIs0_PLTstoped, F -> F')
+        interface.join_prune_logger.debug('stateRefreshArrivesRPFnbr_pruneIs0_PLTstoped, F -> F')
 
     @staticmethod
     def seeJoinToRPFnbr(interface: "TreeInterfaceUpstream"):
@@ -197,7 +191,8 @@ class Forward(UpstreamStateABC):
         """
         interface.clear_override_timer()
 
-        print('seeJoinToRPFnbr, F -> F')
+        #print('seeJoinToRPFnbr, F -> F')
+        interface.join_prune_logger.debug('seeJoinToRPFnbr, F -> F')
 
     @staticmethod
     def seePrune(interface: "TreeInterfaceUpstream"):
@@ -206,11 +201,11 @@ class Forward(UpstreamStateABC):
 
         @type interface: TreeInterfaceUpstream
         """
-        #interface.set_ot()
-        if not interface.is_S_directly_conn():
+        if not interface.is_S_directly_conn() and not interface.is_override_timer_running():
             interface.set_override_timer()
 
-            print('seePrune, F -> F')
+        #print('seePrune, F -> F')
+        interface.join_prune_logger.debug('seePrune, F -> F')
 
     @staticmethod
     def OTexpires(interface: "TreeInterfaceUpstream"):
@@ -222,7 +217,8 @@ class Forward(UpstreamStateABC):
         if not interface.is_S_directly_conn():
             interface.send_join()
 
-            print('OTexpires, F -> F')
+        #print('OTexpires, F -> F')
+        interface.join_prune_logger.debug('OTexpires, F -> F')
 
     @staticmethod
     def olistIsNowNull(interface: "TreeInterfaceUpstream"):
@@ -231,18 +227,15 @@ class Forward(UpstreamStateABC):
 
         @type interface: TreeInterfaceUpstream
         """
-        print("is direct con -> ", interface.is_S_directly_conn())
         if not interface.is_S_directly_conn():
             interface.set_state(UpstreamState.Pruned)
 
-            #timer = interface._prune_limit_timer
-            #timer.set_timer(interface.t_override)
-            #timer.start()
+            interface.send_prune()
             interface.set_prune_limit_timer()
 
-            interface.send_prune()
+            #print("olistIsNowNull, F -> P")
+            interface.join_prune_logger.debug("olistIsNowNull, F -> P")
 
-            print("olistIsNowNull, F -> P")
 
     @staticmethod
     def olistIsNowNotNull(interface: "TreeInterfaceUpstream"):
@@ -251,7 +244,7 @@ class Forward(UpstreamStateABC):
 
         @type interface: TreeInterfaceUpstream
         """
-        #assert False
+        #assert False, "olistIsNowNotNull (in state F)"
         return
 
     @staticmethod
@@ -264,11 +257,13 @@ class Forward(UpstreamStateABC):
         @type interface: TreeInterfaceUpstream
         """
         if not interface.is_S_directly_conn():
+            interface.set_state(UpstreamState.AckPending)
+
             interface.send_graft()
             interface.set_graft_retry_timer()
-            interface.set_state(UpstreamState.AckPending)
 
-            print('RPFnbrChanges_olistIsNotNull, F -> AP')
+            #print('RPFnbrChanges_olistIsNotNull, F -> AP')
+            interface.join_prune_logger.debug('RPFnbrChanges_olistIsNotNull, F -> AP')
 
     @staticmethod
     def RPFnbrChanges_olistIsNull(interface: "TreeInterfaceUpstream"):
@@ -280,7 +275,8 @@ class Forward(UpstreamStateABC):
         """
         interface.set_state(UpstreamState.Pruned)
 
-        print('RPFnbrChanges_olistIsNull, F -> P')
+        #print('RPFnbrChanges_olistIsNull, F -> P')
+        interface.join_prune_logger.debug('RPFnbrChanges_olistIsNull, F -> P')
 
     @staticmethod
     def sourceIsNowDirectConnect(interface: "TreeInterfaceUpstream"):
@@ -289,7 +285,8 @@ class Forward(UpstreamStateABC):
 
         @type interface: TreeInterfaceUpstream
         """
-        print("sourceIsNowDirectConnect, F -> F")
+        #print("sourceIsNowDirectConnect, F -> F")
+        interface.join_prune_logger.debug("sourceIsNowDirectConnect, F -> F")
 
     @staticmethod
     def GRTexpires(interface: "TreeInterfaceUpstream"):
@@ -298,7 +295,7 @@ class Forward(UpstreamStateABC):
 
         @type interface: TreeInterfaceUpstream
         """
-        #assert False
+        #assert False, "GRTexpires (in state F)"
         return
 
     @staticmethod
@@ -308,7 +305,11 @@ class Forward(UpstreamStateABC):
 
         @type interface: TreeInterfaceUpstream
         """
-        print('recvGraftAckFromRPFnbr, F -> F')
+        #print('recvGraftAckFromRPFnbr, F -> F')
+        interface.join_prune_logger.debug("recvGraftAckFromRPFnbr, F -> F")
+
+    def __str__(self):
+        return "F"
 
 
 class Pruned(UpstreamStateABC):
@@ -331,7 +332,8 @@ class Pruned(UpstreamStateABC):
             interface.set_prune_limit_timer()
             interface.send_prune()
 
-            print("dataArrivesRPFinterface_OListNull_PLTstoped, P -> P")
+            #print("dataArrivesRPFinterface_OListNull_PLTstoped, P -> P")
+            interface.join_prune_logger.debug("dataArrivesRPFinterface_OListNull_PLTstoped, P -> P")
 
     @staticmethod
     def stateRefreshArrivesRPFnbr_pruneIs1(interface: "TreeInterfaceUpstream"):
@@ -342,7 +344,8 @@ class Pruned(UpstreamStateABC):
         @type interface: TreeInterfaceUpstream
         """
         interface.set_prune_limit_timer()
-        print('stateRefreshArrivesRPFnbr_pruneIs1, P -> P')
+        #print('stateRefreshArrivesRPFnbr_pruneIs1, P -> P')
+        interface.join_prune_logger.debug('stateRefreshArrivesRPFnbr_pruneIs1, P -> P')
 
     @staticmethod
     def stateRefreshArrivesRPFnbr_pruneIs0_PLTstoped(interface: "TreeInterfaceUpstream"):
@@ -355,8 +358,8 @@ class Pruned(UpstreamStateABC):
         """
         interface.send_prune()
         interface.set_prune_limit_timer()
-        print(
-            'stateRefreshArrivesRPFnbr_pruneIs0_PLTstoped, P -> P')
+        #print('stateRefreshArrivesRPFnbr_pruneIs0_PLTstoped, P -> P')
+        interface.join_prune_logger.debug('stateRefreshArrivesRPFnbr_pruneIs0_PLTstoped, P -> P')
 
     @staticmethod
     def seeJoinToRPFnbr(interface: "TreeInterfaceUpstream"):
@@ -366,8 +369,8 @@ class Pruned(UpstreamStateABC):
         @type interface: TreeInterfaceUpstream
         """
         # Do nothing
-
-        print('seeJoinToRPFnbr, P -> P')
+        #print('seeJoinToRPFnbr, P -> P')
+        interface.join_prune_logger.debug('seeJoinToRPFnbr, P -> P')
 
     @staticmethod
     def seePrune(interface: "TreeInterfaceUpstream"):
@@ -376,8 +379,10 @@ class Pruned(UpstreamStateABC):
 
         @type interface: TreeInterfaceUpstream
         """
-
-        print('seePrune, P -> P')
+        if interface.get_received_prune_holdtime() > interface.remaining_prune_limit_timer():
+            interface.set_prune_limit_timer(time=interface.get_received_prune_holdtime())
+        #print('seePrune, P -> P')
+        interface.join_prune_logger.debug('seePrune, P -> P')
 
     @staticmethod
     def OTexpires(interface: "TreeInterfaceUpstream"):
@@ -386,8 +391,7 @@ class Pruned(UpstreamStateABC):
 
         @type interface: TreeInterfaceUpstream
         """
-
-        #assert False
+        #assert False, "OTexpires in state Pruned"
         return
 
     @staticmethod
@@ -397,7 +401,7 @@ class Pruned(UpstreamStateABC):
 
         @type interface: TreeInterfaceUpstream
         """
-        #assert False
+        #assert False, "olistIsNowNull in state Pruned"
         return
 
     @staticmethod
@@ -408,14 +412,15 @@ class Pruned(UpstreamStateABC):
         @type interface: TreeInterfaceUpstream
         """
         if not interface.is_S_directly_conn():
-            interface.send_graft()
-
-            #interface.get_grt().start()
-            interface.set_graft_retry_timer()
+            interface.clear_prune_limit_timer()
 
             interface.set_state(UpstreamState.AckPending)
 
-            print('olistIsNowNotNull, P -> AP')
+            interface.send_graft()
+            interface.set_graft_retry_timer()
+
+            #print('olistIsNowNotNull, P -> AP')
+            interface.join_prune_logger.debug('olistIsNowNotNull, P -> AP')
 
     @staticmethod
     def RPFnbrChanges_olistIsNotNull(interface: "TreeInterfaceUpstream"):
@@ -427,14 +432,15 @@ class Pruned(UpstreamStateABC):
         @type interface: TreeInterfaceUpstream
         """
         if not interface.is_S_directly_conn():
-            interface.set_state(UpstreamState.AckPending)
-
             interface.clear_prune_limit_timer()
 
+            interface.set_state(UpstreamState.AckPending)
+
             interface.send_graft()
             interface.set_graft_retry_timer()
 
-            print('olistIsNowNotNull, P -> AP')
+            #print('RPFnbrChanges_olistIsNotNull, P -> AP')
+            interface.join_prune_logger.debug('RPFnbrChanges_olistIsNotNull, P -> AP')
 
     @staticmethod
     def RPFnbrChanges_olistIsNull(interface: "TreeInterfaceUpstream"):
@@ -447,7 +453,8 @@ class Pruned(UpstreamStateABC):
         if not interface.is_S_directly_conn():
             interface.clear_prune_limit_timer()
 
-            print('RPFnbrChanges_olistIsNull, P -> P')
+            #print('RPFnbrChanges_olistIsNull, P -> P')
+            interface.join_prune_logger.debug('RPFnbrChanges_olistIsNull, P -> P')
 
     @staticmethod
     def sourceIsNowDirectConnect(interface: "TreeInterfaceUpstream"):
@@ -456,7 +463,8 @@ class Pruned(UpstreamStateABC):
 
         @type interface: TreeInterfaceUpstream
         """
-        print("sourceIsNowDirectConnect, P -> P")
+        #print("sourceIsNowDirectConnect, P -> P")
+        interface.join_prune_logger.debug('sourceIsNowDirectConnect, P -> P')
 
     @staticmethod
     def GRTexpires(interface: "TreeInterfaceUpstream"):
@@ -465,7 +473,7 @@ class Pruned(UpstreamStateABC):
 
         @type interface: TreeInterfaceUpstream
         """
-        #assert False
+        #assert False, "GRTexpires in state Pruned"
         return
 
     @staticmethod
@@ -475,8 +483,12 @@ class Pruned(UpstreamStateABC):
 
         @type interface: TreeInterfaceUpstream
         """
+        #print('recvGraftAckFromRPFnbr, P -> P')
+        interface.join_prune_logger.debug('recvGraftAckFromRPFnbr, P -> P')
+
+    def __str__(self):
+        return "P"
 
-        print('recvGraftAckFromRPFnbr, P -> P')
 
 class AckPending(UpstreamStateABC):
     """
@@ -498,8 +510,7 @@ class AckPending(UpstreamStateABC):
 
         @type interface: TreeInterfaceUpstream
         """
-
-        #assert False
+        #assert False, "dataArrivesRPFinterface_OListNull_PLTstoped in state AP"
         return
 
     @staticmethod
@@ -510,9 +521,11 @@ class AckPending(UpstreamStateABC):
 
         @type interface: TreeInterfaceUpstream
         """
-        interface.set_override_timer()
+        if not interface.is_override_timer_running():
+            interface.set_override_timer()
 
-        print('stateRefreshArrivesRPFnbr_pruneIs1, AP -> AP')
+        #print('stateRefreshArrivesRPFnbr_pruneIs1, AP -> AP')
+        interface.join_prune_logger.debug('stateRefreshArrivesRPFnbr_pruneIs1, AP -> AP')
 
     @staticmethod
     def stateRefreshArrivesRPFnbr_pruneIs0_PLTstoped(interface: "TreeInterfaceUpstream"):
@@ -523,11 +536,11 @@ class AckPending(UpstreamStateABC):
 
         @type interface: TreeInterfaceUpstream
         """
-        interface.set_state(UpstreamState.Forward)
         interface.clear_graft_retry_timer()
+        interface.set_state(UpstreamState.Forward)
 
-        print(
-            'stateRefreshArrivesRPFnbr_pruneIs0_PLTstoped, AP -> P')
+        #print('stateRefreshArrivesRPFnbr_pruneIs0_PLTstoped, AP -> F')
+        interface.join_prune_logger.debug('stateRefreshArrivesRPFnbr_pruneIs0_PLTstoped, AP -> F')
 
     @staticmethod
     def seeJoinToRPFnbr(interface: "TreeInterfaceUpstream"):
@@ -538,7 +551,8 @@ class AckPending(UpstreamStateABC):
         """
         interface.clear_override_timer()
 
-        print('seeJoinToRPFnbr, AP -> AP')
+        #print('seeJoinToRPFnbr, AP -> AP')
+        interface.join_prune_logger.debug('seeJoinToRPFnbr, AP -> AP')
 
     @staticmethod
     def seePrune(interface: "TreeInterfaceUpstream"):
@@ -547,9 +561,11 @@ class AckPending(UpstreamStateABC):
 
         @type interface: TreeInterfaceUpstream
         """
-        interface.set_override_timer()
+        if not interface.is_override_timer_running():
+            interface.set_override_timer()
 
-        print('seePrune, AP -> AP')
+        #print('seePrune, AP -> AP')
+        interface.join_prune_logger.debug('seePrune, AP -> AP')
 
     @staticmethod
     def OTexpires(interface: "TreeInterfaceUpstream"):
@@ -560,7 +576,8 @@ class AckPending(UpstreamStateABC):
         """
         interface.send_join()
 
-        print('OTexpires, AP -> AP')
+        #print('OTexpires, AP -> AP')
+        interface.join_prune_logger.debug('OTexpires, AP -> AP')
 
     @staticmethod
     def olistIsNowNull(interface: "TreeInterfaceUpstream"):
@@ -571,18 +588,13 @@ class AckPending(UpstreamStateABC):
         """
         interface.set_state(UpstreamState.Pruned)
 
-        #timer = interface._prune_limit_timer
-        #timer.set_timer(interface.t_override)
-        interface.set_prune_limit_timer()
-
-        #timer.start()
+        interface.send_prune()
 
-        #interface.get_grt().stop()
         interface.clear_graft_retry_timer()
+        interface.set_prune_limit_timer()
 
-        interface.send_prune()
-
-        print("olistIsNowNull, AP -> P")
+        #print("olistIsNowNull, AP -> P")
+        interface.join_prune_logger.debug('olistIsNowNull, AP -> P')
 
     @staticmethod
     def olistIsNowNotNull(interface: "TreeInterfaceUpstream"):
@@ -591,7 +603,7 @@ class AckPending(UpstreamStateABC):
 
         @type interface: TreeInterfaceUpstream
         """
-        #assert False
+        #assert False, "olistIsNowNotNull in state AP"
         return
 
     @staticmethod
@@ -607,7 +619,8 @@ class AckPending(UpstreamStateABC):
             interface.send_graft()
             interface.set_graft_retry_timer()
 
-            print('olistIsNowNotNull, AP -> AP')
+            #print('RPFnbrChanges_olistIsNotNull, AP -> AP')
+            interface.join_prune_logger.debug('RPFnbrChanges_olistIsNotNull, AP -> AP')
 
     @staticmethod
     def RPFnbrChanges_olistIsNull(interface: "TreeInterfaceUpstream"):
@@ -621,7 +634,8 @@ class AckPending(UpstreamStateABC):
             interface.clear_graft_retry_timer()
             interface.set_state(UpstreamState.Pruned)
 
-            print('RPFnbrChanges_olistIsNull, AP -> P')
+            #print('RPFnbrChanges_olistIsNull, AP -> P')
+            interface.join_prune_logger.debug('RPFnbrChanges_olistIsNull, AP -> P')
 
     @staticmethod
     def sourceIsNowDirectConnect(interface: "TreeInterfaceUpstream"):
@@ -631,10 +645,10 @@ class AckPending(UpstreamStateABC):
         @type interface: TreeInterfaceUpstream
         """
         interface.set_state(UpstreamState.Forward)
-        #interface.get_grt().stop()
         interface.clear_graft_retry_timer()
 
-        print("sourceIsNowDirectConnect, AP -> F")
+        #print("sourceIsNowDirectConnect, AP -> F")
+        interface.join_prune_logger.debug('sourceIsNowDirectConnect, AP -> F')
 
     @staticmethod
     def GRTexpires(interface: "TreeInterfaceUpstream"):
@@ -643,12 +657,11 @@ class AckPending(UpstreamStateABC):
 
         @type interface: TreeInterfaceUpstream
         """
-
-        #interface.get_grt().start()
         interface.set_graft_retry_timer()
         interface.send_graft()
 
-        print('GRTexpires, AP -> AP')
+        #print('GRTexpires, AP -> AP')
+        interface.join_prune_logger.debug('GRTexpires, AP -> AP')
 
     @staticmethod
     def recvGraftAckFromRPFnbr(interface: "TreeInterfaceUpstream"):
@@ -657,13 +670,14 @@ class AckPending(UpstreamStateABC):
 
         @type interface: TreeInterfaceUpstream
         """
-
-        interface.set_state(UpstreamState.Forward)
-        #interface.get_grt().stop()
         interface.clear_graft_retry_timer()
+        interface.set_state(UpstreamState.Forward)
 
-        print('recvGraftAckFromRPFnbr, AP -> F')
+        #print('recvGraftAckFromRPFnbr, AP -> F')
+        interface.join_prune_logger.debug('recvGraftAckFromRPFnbr, AP -> F')
 
+    def __str__(self):
+        return "AP"
 
 class UpstreamState():
     Forward = Forward()