Edited by Marilyn Outerbridge
A very cheap and effective way to perform rudimentary packet-header capturing in IOS is to use the log/log-input keyword at the end of an ACE. This is very easily done. This blog will use the following simple topology for the demonstrations.
Basic ACL Logging (Default Settings)
The syslog configuration on R2 is kept to a minimum, while still being useful for the demonstration.
R2(config)#logg buffered 7 R2(config)#no logging console
For the baseline scenario, used for all the configurations, R2 is chosen to track all the packets sent from R3 (L0) to R1 (L0). This is done by configuring an extended access list shown below.
R2#show ip access-lists ip access-list extended ACL_TEST permit ip host 3.3.3.3 host 1.1.1.1 log
This ACL is now applied to R2’s Gig2 interface.
R2(config)#interface GigabitEthernet2 R2(config-if)#ip access-group ACL_TEST in
No other ACL “tuning” is configured yet. With this basic configuration in place, the IOS behavior is as documented by Cisco documentation:
“The first packet that triggers the access list entry causes an immediate logging message, and subsequent packets are collected over 5-minute intervals before they are displayed or logged. The logging message includes the access list number, whether the packet was permitted or denied, the source IP address of the packet, and the number of packets from that source permitted or denied in the prior 5-minute interval.”
From R3, the following command is issued to send ICMP packets to 1.1.1.1:
R3#ping 1.1.1.1 source 3.3.3.3
This results in five ICMP packets matching against the R2 ACE. The following syslog messages are generated by R2 (5m 17s apart):
*Jun 9 00:46:04.894: %FMANFP-6-IPACCESSLOGDP: F0: fman_fp_image: list ACL_TEST permitted icmp 3.3.3.3 -> 1.1.1.1 (8/0), 1 packet *Jun 9 00:51:21.343: %FMANFP-6-IPACCESSLOGDP: F0: fman_fp_image: list ACL_TEST permitted icmp 3.3.3.3 -> 1.1.1.1 (8/0), 4 packets
After the second message is generated on R2, the command is quickly issued again on R3:
R3#show clock *00:53:02.207 UTC Mon Jun 9 2014 R3#ping 1.1.1.1 source 3.3.3.3
The following message is seen on R2 after (5m 0s):
*Jun 9 00:56:21.353: %FMANFP-6-IPACCESSLOGDP: F0: fman_fp_image: list ACL_TEST permitted icmp 3.3.3.3 -> 1.1.1.1 (8/0), 5 packets
After this message, nothing is done on the devices for another five minutes. 5m 18s later, the ICMP packets are sent once again from R3:
R3#sho clock *01:01:39.643 UTC Mon Jun 9 2014 R3#ping 1.1.1.1 so 3.3.3.3
Immediately, log messages are generated on R2 (5m 29s apart):
*Jun 9 01:01:52.396: %FMANFP-6-IPACCESSLOGDP: F0: fman_fp_image: list ACL_TEST permitted icmp 3.3.3.3 -> 1.1.1.1 (8/0), 1 packet
After a short wait period, another log message is seen on R2 as expected:
*Jun 9 01:07:21.375: %FMANFP-6-IPACCESSLOGDP: F0: fman_fp_image: list ACL_TEST permitted icmp 3.3.3.3 -> 1.1.1.1 (8/0), 4 packets
The behavior is inline with the Cisco documentation and can be succinctly described as follows (default ACL logging behavior):
After a period of inactivity longer than 5 minutes, the first packet to match the ACE will trigger the syslog message. Roughly 5 minutes after this initial log message, a summary message is generated to account for the rest of the logged packets in the time period between the first packet and the log message generation. If activity continues for a period, the router generates a log message summarizing the number of packets every 5 minutes. If a period of longer than 5 minutes passes without any matches against the ACE, the first packet to match once again generates the syslog message and the same 5 minute cycle once again begins till the next occurrence of inactivity.
Log-Update Knob
At times, there may be a desire to get more frequent updates especially if the number of hits is abnormally high. A period of 5 minutes in such a case may be deemed too long. IOS provides a knob for such a case:
R2(config)#ip access-l log-update threshold ?
Access list log-update threshold (number of hits)
This knob causes IOS to:
- Generate a log message for the first packet that matches (after a period of inactivity greater than five minutes)
- Generate a log message for each X packets that match (X being the number specified in the command)
- Generate a log message at every 5 minute interval
Furthermore, this is a global tuning knob so it affects every single logging ACE. There is no option to filter or fine tune the effects.
To demonstrate the effect of this knob, R2 is configured as follows:
ip access-list log-update threshold 10
From R3, ICMP packets are sent towards 1.1.1.1 as follows:
R3#ping 1.1.1.1 so 3.3.3.3 repeat 25
On R2, the following log messages are generated:
*Jun 9 01:48:28.281: %FMANFP-6-IPACCESSLOGDP: F0: fman_fp_image: list ACL_TEST permitted icmp 3.3.3.3 -> 1.1.1.1 (8/0), 1 packet *Jun 9 01:48:28.914: %FMANFP-6-IPACCESSLOGDP: F0: fman_fp_image: list ACL_TEST permitted icmp 3.3.3.3 -> 1.1.1.1 (8/0), 10 packets *Jun 9 01:48:29.674: %FMANFP-6-IPACCESSLOGDP: F0: fman_fp_image: list ACL_TEST permitted icmp 3.3.3.3 -> 1.1.1.1 (8/0), 10 packets
After a period of 5m 22s after the first-hit syslog message was generated, the R2 generates the following 5 minute summary message:
*Jun 9 01:53:51.468: %FMANFP-6-IPACCESSLOGDP: F0: fman_fp_image: list ACL_TEST permitted icmp 3.3.3.3 -> 1.1.1.1 (8/0), 4 packets
Thus, all 25 of the packets sent by R3 were accounted for (1+10+10+4), and the syslog update messages were more frequent.
ACL Logging and Process Switching
In order for IOS to log the packets, each packet that matches an ACE configured with a log/log-input keyword has to be process switched instead of CEF switched. For ACEs that match a lot of packets, this aspect can be undesirable and lead to high CPU utilization.
IOS provides a knob to rate-limit the number of packets that are process switched due to logging ACEs. As with the log-update knob, this also has a global effect and there is no filtering or fine-tuning available. The command to issue is as follows:
R2(config)#ip access-list logging interval ?
Access list logging interval (milliseconds)
This command, once applied, allows only 1 packet to be process switched during the period described by the command. So if the value specified is 500, then 1 packet will be allowed to be process switched every .5s or in other words, two packets to be process switched every second. Similarly, a value of 5000 will allow 1 packet to be process switched every 5 seconds or in other words, 12 packets to be process switched every minute. Additionally, this limit applies globally to all logging ACEs, cumulatively. Thus, the sum total of all packets that will be allowed to be process switched (as a result of logging ACEs) by the router as a whole is determined by this command.
Where this command can surprise some is in the fact that it actually affects the ACL logging statistics. Only the packets that are allowed by the IOS to be process switched are accounted for in the syslog messages. As seen in the previous two demonstrations, by default IOS accounts for every single packet that matches the logging ACE.
Furthermore, this command works in conjunction with both the log-update command as well as the 5 minute interval discussed earlier.
To demonstrate the effect of this command, R2 is configured with the following command:
R2(config)#ip access-list logging interval 2000
Essentially, R2 will now allow 1 packet to be process switched every 2 seconds. To demonstrate the global effect of the command (i.e. affecting all logging ACEs), another ACE is added to the already present ACL on R2. The resulting ACL is:
R2#show access-lists
Extended IP access list ACL_TEST
10 permit ip host 3.3.3.3 host 1.1.1.1 log
20 permit ip host 33.33.33.33 host 11.11.11.11 log
Next, two simultaneous telnet connections (out of band) are opened to the R3 CLI and the following two commands will be issued, near simultaneously, one on each CLI:
ping 1.1.1.1 source 3.3.3.3 size 1500 repeat 50 ping 11.11.11.11 source 33.33.33.33 size 1500 repeat 50
But before the commands are issued, to ensure that the rate of packet flow through R2 is controlled, a shaper is added to the Gig2 interface of R3. The calculations for the shaper CIR are as follows:
Total bytes per stream per ping = 1500 B Total bytes cumulatively per ping = 2 * 1500 B = 3000 B Total bits cumulatively per ping = 3000 * 8 b = 24000 b
So, if the CIR of the shaper is kept to 24000 bps, and no other traffic passes between the routers, then R3 should be sending very close to a single packet of each ping per second (total 2 packets per second) to R2. Since this demonstration only uses static routes, the pings are indeed the only traffic traversing the interfaces.
The following configuration is applied to R3:
policy-map PM_TEST class class-default shape average 24000 ! interface GigabitEthernet2 service-policy output PM_TEST
After this configuration, the pings are launched (as mentioned before, near simultaneously) from R3. But before the pings are launched, enough time is given so that R2 has not had a logging ACE hit in the last 15 or so minutes. This ensures that no previously cached messages will generate log messages on R2.
The following messages are seen on R2 after the actions on R3:
*Jun 10 23:29:41.068: %FMANFP-6-IPACCESSLOGDP: F0: fman_fp_image: list ACL_TEST permitted icmp 3.3.3.3 -> 1.1.1.1 (8/0), 1 packet *Jun 10 23:29:43.550: %FMANFP-6-IPACCESSLOGDP: F0: fman_fp_image: list ACL_TEST permitted icmp 33.33.33.33 -> 11.11.11.11 (8/0), 1 packet *Jun 10 23:30:06.316: %FMANFP-6-IPACCESSLOGDP: F0: fman_fp_image: list ACL_TEST permitted icmp 3.3.3.3 -> 1.1.1.1 (8/0), 10 packets *Jun 10 23:30:26.558: %FMANFP-6-IPACCESSLOGDP: F0: fman_fp_image: list ACL_TEST permitted icmp 3.3.3.3 -> 1.1.1.1 (8/0), 10 packets *Jun 10 23:34:58.206: %FMANFP-6-IPACCESSLOGDP: F0: fman_fp_image: list ACL_TEST permitted icmp 33.33.33.33 -> 11.11.11.11 (8/0), 2 packets *Jun 10 23:35:28.207: %FMANFP-6-IPACCESSLOGDP: F0: fman_fp_image: list ACL_TEST permitted icmp 3.3.3.3 -> 1.1.1.1 (8/0), 1 packet
These messages are accounting for 25 (1+1+10+10+2+1) packets. Once again, the base principles do not change. The IOS logs the first packet of each ACE. After that it logs packets based on the log-update configuration (which was left at 10 after the previous demonstration). Then the IOS finally clears out the cache at the expiration of the 5 minute timer for each ACE.
NOTE: Even though in this case, the first ACE is generating nearly all the logs, the results that were seen were mostly unpredictable, with each ACE generating the majority of the logs at different times. The order of the ACEs was flipped, the order of the “near simultaneous” launch was changed amongst other things. Although IOS may have an algorithm working in the background to decide which ACE’s packets will be process switched, the discussion of it remains outside the scope of this document. One should note however that if the ACL logging is being used for the collection of statistics of any sort, the logging interval command will certainly interfere with it. The more logging ACEs configured, the less reliable the results.
For this article, what really matters is the fact that a total of 100 packets were sent from R3 to R1 in 50 seconds. R2’s log messages account for exactly 25 out of these. This proves that R2 is process switching only 1 packet every 2 seconds. In other words, it only process switches 1 out of the total 4 packets it routes every 2 seconds. Therefore 25 packets are logged in 50 seconds.
Excellent post. I have learned something new today.
Really good information. Thanks for posting it.