3.7 PBR and ACL logging

Hi folks. I have this lab working in GNS3 using 3700 12.4. While testing, I realized when using logging on the ACL I am actually receiving 40% ICMP sucess rate. My understanding is that when logging on an ACE it interuppts the CPU so the packet is processed switch, rather than CEF. If that is the case, then why does the below log have a FIB policy rejections, followed by a match, followed by another rejection?  Removing CEF allows me to use logging on the ACL.

 

I did read that "log" is not supported with PBRs, but I am trying to understand why it is not supported. 

 

Mar  1 00:10:37.535: IP: s=155.1.146.6 (FastEthernet0/0), d=150.1.5.5, len 100, FIB policy rejected(no match) - normal forwarding

*Mar  1 00:10:37.539: IP: s=155.1.146.6 (FastEthernet0/0), d=150.1.5.5, len 100, policy match

*Mar  1 00:10:37.543: IP: route map R4_R6_ROUTING, item 20, permit

*Mar  1 00:10:37.547: IP: s=155.1.146.6 (FastEthernet0/0), d=150.1.5.5 (Serial0/0.1), len 100, policy routed

*Mar  1 00:10:37.551: IP: FastEthernet0/0 to Serial0/0.1 155.1.0.5

*Mar  1 00:10:37.595: IP: s=155.1.146.6 (FastEthernet0/0), d=150.1.5.5, len 100, FIB policy rejected(no match) - normal forwarding



Cheers! 


John

Comments

  • Hi Johnny,

    What do you mean when you say "I did read that "log" is not supported with PBRs, but I am trying to understand why it is not supported. " ?

    The debug output you presented (which I assume is from debug ip policy command)  reveals the fact that some of the packets are not policy routed. This means that there is something wrong with your config, unless this is a GNS3 related problem.

    Below, my config for this task, PBR related :

    R1#sh run | s route-map|access-list

    ! Define ACLs for traffic matching 

    ip access-list extended FROM_R4

     permit ip host 155.1.146.4 any

    ip access-list extended FROM_R6

     permit ip host 155.1.146.6 any

    ! Define route-map PBR

    route-map PBR permit 10

     match ip address FROM_R4

     set ip next-hop verify-availability 155.1.13.3 1 track 1

     set ip next-hop 155.1.13.3

     set ip default next-hop 155.1.0.5

    route-map PBR permit 20

     match ip address FROM_R6

     set ip next-hop 155.1.0.5

     set ip next-hop verify-availability

     set ip default next-hop 155.1.13.3 

    ! Apply route-map under PBR interface configuration mode

    ip policy route-map PBR

     

    TESTING : 

     

    Currently no hits recorded under FROM_R6 ACL :

    R1#sh ip access-lists 

    Extended IP access list FROM_R4

        10 permit ip host 155.1.146.4 any

    Extended IP access list FROM_R6

        10 permit ip host 155.1.146.6 any

    Run a 10 pkts ping from R6 to R5's loopback :

    R6#ping 150.1.5.5 re 10

    Type escape sequence to abort.

    Sending 10, 100-byte ICMP Echos to 150.1.5.5, timeout is 2 seconds:

    !!!!!!!!!!

    Success rate is 100 percent (10/10), round-trip min/avg/max = 5/5/7 ms

    Debug ip policy command has been executed on PBR in charge router - R1 : 

    R1#

    IP: s=155.1.146.6 (Ethernet0/1.146), d=150.1.5.5, len 100, FIB policy match

    IP: s=155.1.146.6 (Ethernet0/1.146), d=150.1.5.5, len 100, PBR Counted

    IP: s=155.1.146.6 (Ethernet0/1.146), d=150.1.5.5, g=155.1.0.5, len 100, FIB policy routed

    IP: s=155.1.146.6 (Ethernet0/1.146), d=150.1.5.5, len 100, FIB policy match

    IP: s=155.1.146.6 (Ethernet0/1.146), d=150.1.5.5, len 100, PBR Counted

    IP: s=155.1.146.6 (Ethernet0/1.146), d=150.1.5.5, g=155.1.0.5, len 100, FIB policy routed

    IP: s=155.1.146.6 (Ethernet0/1.146), d=150.1.5.5, len 100, FIB policy match

    IP: s=155.1.146.6 (Ethernet0/1.146), d=150.1.5.5, len 100, PBR Counted

    IP: s=155.1.146.6 (Ethernet0/1.146), d=150.1.5.5, g=155.1.0.5, len 100, FIB policy routed

    IP: s=155.1.146.6 (Ethernet0/1.146), d=150.1.5.5, len 100, FIB policy match

    IP: s=155.1.146.6 (Ethernet0/1.146), d=150.1.5.5, len 100, PBR Counted

    IP: s=155.1.146.6 (Ethernet0/1.146), d=150.1.5.5, g=155.1.0.5, len 100, FIB policy routed

    IP: s=155.1.146.6 (Ethernet0/1.146), d=150.1.5.5, len 100, FIB policy match

    IP: s=155.1.146.6 (Ethernet0/1.146), d=150.1.5.5, len 100, PBR Counted

    IP: s=155.1.146.6 (Ethernet0/1.146), d=150.1.5.5, g=155.1.0.5, len 100, FIB policy routed

    IP: s=155.1.146.6 (Ethernet0/1.146), d=150.1.5.5, len 100, FIB policy match

    IP: s=155.1.146.6 (Ethernet0/1.146), d=150.1.5.5, len 100, PBR Counted

    IP: s=155.1.146.6 (Ethernet0/1.146), d=150.1.5.5, g=155.1.0.5, len 100, FIB policy routed

    IP: s=155.1.146.6 (Ethernet0/1.146), d=150.1.5.5, len 100, FIB policy match

    IP: s=155.1.146.6 (Ethernet0/1.146), d=150.1.5.5, len 100, PBR Counted

    IP: s=155.1.146.6 (Ethernet0/1.146), d=150.1.5.5, g=155.1.0.5, len 100, FIB policy routed

    IP: s=155.1.146.6 (Ethernet0/1.146), d=150.1.5.5, len 100, FIB policy match

    IP: s=155.1.146.6 (Ethernet0/1.146), d=150.1.5.5, len 100, PBR Counted

    IP: s=155.1.146.6 (Ethernet0/1.146), d=150.1.5.5, g=155.1.0.5, len 100, FIB policy routed

    IP: s=155.1.146.6 (Ethernet0/1.146), d=150.1.5.5, len 100, FIB policy match

    IP: s=155.1.146.6 (Ethernet0/1.146), d=150.1.5.5, len 100, PBR Counted

    IP: s=155.1.146.6 (Ethernet0/1.146), d=150.1.5.5, g=155.1.0.5, len 100, FIB policy routed

    IP: s=155.1.146.6 (Ethernet0/1.146), d=150.1.5.5, len 100, FIB policy match

    IP: s=155.1.146.6 (Ethernet0/1.146), d=150.1.5.5, len 100, PBR Counted

    IP: s=155.1.146.6 (Ethernet0/1.146), d=150.1.5.5, g=155.1.0.5, len 100, FIB policy routed

    R1#

     

    Check ACL hits on R1 :

    R1#sh ip access-lists      

    Extended IP access list FROM_R4

        10 permit ip host 155.1.146.4 any

    Extended IP access list FROM_R6

        10 permit ip host 155.1.146.6 any (10 matches)

     

    If your configuration doesn't mimic the configuration presented above then give it another try and let me know how it went. It could also be a GNS3 related issue, but unless it works, then present your current configurations and I'll try to help.

     

  • Thank you for your reply! Perhaps it is a GNS3 related issue then. As you can see below, my config is pretty similar to yours. I left the ACL for R6 with the log option to show the difference in the debug when pinging from R4 and R6.

     

    Rack1R1#sh run | s route-map|access-list

     ip policy route-map R4_R6_ROUTING

    ip access-list extended FROM_R4

     permit ip host 155.1.146.4 any

    ip access-list extended FROM_R6

     permit ip host 155.1.146.6 any log

    route-map R4_R6_ROUTING permit 10

     match ip address FROM_R4

     set ip next-hop 155.1.13.3

    route-map R4_R6_ROUTING permit 20

     match ip address FROM_R6

     set ip next-hop 155.1.0.5


    -------------------------------------


    Rack1R4#ping 150.1.3.3 repeat 2


    Type escape sequence to abort.

    Sending 2, 100-byte ICMP Echos to 150.1.3.3, timeout is 2 seconds:

    !!

    Success rate is 100 percent (2/2), round-trip min/avg/max = 28/32/36 ms

    Rack1R4#




    Rack1R1#

    *Mar  1 04:13:16.898: IP: s=155.1.146.4 (FastEthernet0/0), d=150.1.3.3, len 100, FIB policy match

    *Mar  1 04:13:16.902: IP: s=155.1.146.4 (FastEthernet0/0), d=150.1.3.3, g=155.1.13.3, len 100, FIB policy routed

    *Mar  1 04:13:16.942: IP: s=155.1.146.4 (FastEthernet0/0), d=150.1.3.3, len 100, FIB policy match

    *Mar  1 04:13:16.942: IP: s=155.1.146.4 (FastEthernet0/0), d=150.1.3.3, g=155.1.13.3, len 100, FIB policy routed

    Rack1R1#



    -------------------------------------


    Rack1R6#ping 150.1.5.5 repeat 3


    Type escape sequence to abort.

    Sending 3, 100-byte ICMP Echos to 150.1.5.5, timeout is 2 seconds:

    !.!

    Success rate is 66 percent (2/3), round-trip min/avg/max = 44/50/56 ms

    Rack1R6#




    Rack1R1#

    *Mar  1 04:13:36.226: IP: s=155.1.146.6 (FastEthernet0/0), d=150.1.5.5, len 100, FIB policy rejected(no match) - normal forwarding

    *Mar  1 04:13:36.230: IP: s=155.1.146.6 (FastEthernet0/0), d=150.1.5.5, len 100, policy match

    *Mar  1 04:13:36.234: IP: route map R4_R6_ROUTING, item 20, permit

    *Mar  1 04:13:36.238: IP: s=155.1.146.6 (FastEthernet0/0), d=150.1.5.5 (Serial0/0.1), len 100, policy routed

    *Mar  1 04:13:36.242: IP: FastEthernet0/0 to Serial0/0.1 155.1.0.5

    *Mar  1 04:13:36.286: IP: s=155.1.146.6 (FastEthernet0/0), d=150.1.5.5, len 100, FIB policy rejected(no match) - normal forwarding

    Rack1R1#

    *Mar  1 04:13:38.270: IP: s=155.1.146.6 (FastEthernet0/0), d=150.1.5.5, len 100, FIB policy rejected(no match) - normal forwarding

    *Mar  1 04:13:38.282: IP: s=155.1.146.6 (FastEthernet0/0), d=150.1.5.5, len 100, policy match

    *Mar  1 04:13:38.286: IP: route map R4_R6_ROUTING, item 20, permit

    *Mar  1 04:13:38.286: IP: s=155.1.146.6 (FastEthernet0/0), d=150.1.5.5 (Serial0/0.1), len 100, policy routed

    *Mar  1 04:13:38.290: IP: FastEthernet0/0 to Serial0/0.1 155.1.0.5

    Rack1R1#




    Rack1R1#sh ip access-lists

    Extended IP access list FROM_R4

        10 permit ip host 155.1.146.4 any (2 matches)

    Extended IP access list FROM_R6

        10 permit ip host 155.1.146.6 any log (4 matches)

    Rack1R1#



    Removed LOG from ACE


    ack1R6#ping 150.1.5.5 repeat 3


    Type escape sequence to abort.

    Sending 3, 100-byte ICMP Echos to 150.1.5.5, timeout is 2 seconds:

    !!!

    Success rate is 100 percent (3/3), round-trip min/avg/max = 28/40/52 ms

    Rack1R6#




    Rack1R1#sh ip access-lists

    Extended IP access list FROM_R4

        10 permit ip host 155.1.146.4 any (2 matches)

    Extended IP access list FROM_R6

        10 permit ip host 155.1.146.6 any (3 matches)

    Rack1R1#

    *Mar  1 04:18:11.810: IP: s=155.1.146.6 (FastEthernet0/0), d=150.1.5.5, len 100, FIB policy match

    *Mar  1 04:18:11.814: IP: s=155.1.146.6 (FastEthernet0/0), d=150.1.5.5, g=155.1.0.5, len 100, FIB policy routed

    *Mar  1 04:18:11.858: IP: s=155.1.146.6 (FastEthernet0/0), d=150.1.5.5, len 100, FIB policy match

    *Mar  1 04:18:11.858: IP: s=155.1.146.6 (FastEthernet0/0), d=150.1.5.5, g=155.1.0.5, len 100, FIB policy routed

    *Mar  1 04:18:11.902: IP: s=155.1.146.6 (FastEthernet0/0), d=150.1.5.5, len 100, FIB policy match

    *Mar  1 04:18:11.902: IP: s=155.1.146.6 (FastEthernet0/0), d=150.1.5.5, g=155.1.0.5, len 100, FIB policy routed

    Rack1R1#




    In regards to not using logging with ACL, the statement "The examples shown below involve the use of the access-list command (ACL). The log keyword should not be used with this command in policy-based routing (PBR) because logging is not supported at the interrupt level for ACLs" is from this cisco link. I would love to try this out on a physical router running 12.4 code to see if it's similar or not. 
  • Hi,

    Thanks for your input, log keyword is definitely tricky in PBR scenarios.

Sign In or Register to comment.