Friday, May 29, 2020

Palo Alto firewall - Troubleshooting High DP CPU



    ▶ Symptom

    A number of factors can cause the dataplane's CPUs to spike or continuously run high: a sudden increase due to the implementation of a new service or resource, or a buildup over time due to added connected networks, segments and hosts. These factors and more can cause increases in packet rate, packet buffer utilization, or a huge amount of new connections per second that lead to the dataplane CPU reaching a critical level.

    Learn to troubleshoot high dataplane CPU. This article shows a couple of ways to verify the actual load of the dataplane and help determine the potential impact on your network.

    The first step is to isolate where the performance issue is occurring:

    • Data Plane (DP) CPU
    • Packet Buffers
    • Session
    • Management Plane (MP)

    • How to identify high dataplane CPU

    When you see a performance issue, generate a tech support file while the issue is occurring. Look for the "---panio" string in the dp-monitor log for historic logs (this information is logged every 15 minutes) or run the
    show running resource-monitor command from the CLI to view DP resource usage.

    less dp-log dp-monitor.log

    If you are running the command on the PA-5200 series, use the following command:
    less dp0-log dp-monitor.log


    show running resource-monitor

    This command can be used to review dataplane CPU usage. Add a time operator to reflect a timeframe you would like to review.
    - 'second' shows the last 60 seconds of CPU usage in per second increments
    - 'minute' shows the last 60 minutes in minute increments and so on
    - If no time operator is used, all views will be listed in one long output

    > show running resource-monitor
       > day Per-day monitoring statistics
       > hour Per-hour monitoring statistics
       > ingress-backlogs show statistics
       > minute Per-minute monitoring statistics
       > second Per-second monitoring statistics
       > week Per-week monitoring statistics


    The actual output will look similar to this but may differ slightly depending on the amount of dataplanes and cores your system has.

    > show running resource-monitor
    DP dp0:

    Resource monitoring sampling data (per second):

    This first section shows CPU utilization by processes running on the dataplane
    CPU load sampling by group:
    flow_lookup : 0%
    flow_fastpath : 0%
    flow_slowpath : 0%
    flow_forwarding : 0%
    flow_mgmt : 0%
    flow_ctrl : 1%
    nac_result : 0%
    flow_np : 0%
    dfa_result : 0%
    module_internal : 0%
    aho_result : 0%
    zip_result : 0%
    pktlog_forwarding : 0%
    lwm : 0%
    flow_host : 1%
    This part of the output shows utilization of individual cores on the dataplane.
    Many cores regularly surpassing 75% warrants an investigation.

    CPU load (%) during last 60 seconds:
    core  0  1  2  3  4  5  6  7  8  9  10  11
          0  39 47 38 46 73 81 73 81 82 88  83
          0  39 46 38 45 73 82 73 82 82 89  82
          0  39 46 39 45 73 81 73 81 83 88  83
          0  38 52 37 50 71 81 71 80 82 98  82
          0  40 46 39 45 74 82 74 82 83 89  83
          0  40 50 39 49 74 85 74 84 83 90  83
          0  39 46 38 45 72 81 72 81 81 88  81
          0  42 52 41 50 75 86 75 86 84 91  84
          0  42 76 79 85 75 10075 100100100 85  >>> indicates actual high CPU
          0  44 51 43 50 78 85 78 86 86 91  86
          0  42 51 41 50 76 86 76 86 85 92  85
          0  43 53 43 52 77 89 77 89 86 93  86
          0  38 46 37 45 71 81 72 81 81 88  81
          0  42 50 41 50 76 85 76 85 85 90  85

    ... cut for brevity

                      
    This section shows session table utilization, which is the maximum number of active sessions supported by the platform. Any value above 80% warrants investigation.

    Resource utilization (%) during last 60 seconds:
    session:
      0   0   0   0   0   0   0   0   0   0   0   0   0   0   0
      0   0   0   0   0   0   0   0   0   0   0   0   0   0   0
      0   0   0   0   0   0   0   0   0   0   0   0   0   0   0
      0   0   0   0   0   0   0   0   0   0   0   0   0   0   0


    The next 3 sections show packet buffer utilization.  Packet buffers are used to ensure no packets are lost while a previous packet is still being processed by a core or process. Any value above 80% needs to be investigated.

    packet buffer:
      0   0   0   0   0   0   0   0   0   0   0   0   0   0   0
      0   0   0   0   0   0   0   0   0   0   0   0   0   0   0
      0   0   0   0   0   0   0   0   0   0   0   0   0   0   0
      0   0   0   0   0   0   0   0   0   0   0   0   0   0   0
     
    packet descriptor:
      0   0   0   0   0   0   0   0   0   0   0   0   0   0   0
      0   0   0   0   0   0   0   0   0   0   0   0   0   0   0
      0   0   0   0   0   0   0   0   0   0   0   0   0   0   0
      0   0   0   0   0   0   0   0   0   0   0   0   0   0   0
     

    packet descriptor (on-chip):
      2   2   2   2   2   2   2   2   2   2   2   2   2   2   2
      2   2   2   2   2   2   2   2   2   2   2   2   2   2   2
      2   2   2   2   2   2   2   2   2   2   2   2   2   2   2
      2   2   2   2   2   2   2   2   2   2   2   2   2   2   2

    Things to check in the output:
    1. Check the CPU load during the last 60 seconds. If any number is at or close to 100, then high CPU is likely the cause of the performance issue.
    2. Check the "packet buffer" and "packet descriptor" sections. If any number is at or close to 100, then the issue is likely caused by running out of packet buffers.

    [AnalysisMan] Observed 5~10 packet losses from time to time when the packet descriptor hits at 100.

    3. Check the session section. If any number is close to or above 80, then the performance issue is most likely session related.


    • [AnalysisMan Case]


    ▶ Symptom
    - Losing network connectivity.
    - HA links down and got Packet buffer congestion logs.
    - The issue is packet-descriptor on chip and buffers fill up.
    - The packet buffer abusive session-id returns bad key.
    - The Packet Buffer Protection (PBP) was not effective.

    show running resource-monitor minute last 30

    admin@PA-3220(active)> show running resource-monitor minute last 30

    packet descriptor (on-chip) (average):
    5 5 5 5 5 5 5 5 5 5 5 5 5 13 5
    5 5 5 10 5 5 5 5 5 5 5 19 10 9 5

    packet descriptor (on-chip) (maximum):
    6 6 6 8 6 6 6 10 6 6 7 6 6 100 10
    6 6 6 100 7 6 8 6 7 6 6 100 100 100 6

    admin@PA-3220(active)> show session id 3145733
    Session 3145733
    Bad Key: c2s: 'c2s'
    Bad Key: s2c: 's2c'


    ▶ Root Cause
    Bug ID: PAN-125534
    (PA-5200 Series and PA-7000 Series firewalls only) Fixed an issue where firewalls experienced high packet descriptor (on-chip) usage during uploads to the WildFire Cloud or WF-500 appliance.

    This bug was also triggered on PA-3220.

    ▶ Resolution
    Upgrade to PAN-OS 9.0.8.
    A workaround was changing the WildFire File Size Limits to default values.


    ---
    Several commands are available that can help identify why certain measurements are above the threshold in the resource monitor:
    show session info

    Outputs all data relevant to how many sessions are supported, how many are currently active and will inform you about the packet rate, new connection establish rate and throughput. If any of these parameters are exceptionally high, they can cause the dataplane CPU to rise.
    > show session info
    target-dp: *.dp0
    --------------------------------------------------------------------------------
    Number of sessions supported: 262142
    Number of active sessions: 3   
    < If this figure rises to the level of the supported sessions,
    Number of active TCP sessions: 0       the platform is reaching maximum capacity.
    Number of active UDP sessions: 1
    Number of active ICMP sessions: 0
    Number of active BCAST sessions: 0
    Number of active MCAST sessions: 0
    Number of active predict sessions: 0
    Session table utilization: 0%
    Number of sessions created since bootup: 332481
    Packet rate: 28/s  An unusual and sudden high packet rate could indicate a DoS attack.
    Throughput: 13 kbps
    New connection establish rate: 0 cps
    --------------------------------------------------------------------------------
    Session timeout 
    If timeouts values are too aggressive or too relaxed, the system could run out of resources.
    TCP default timeout: 3600 secs
    TCP session timeout before SYN-ACK received: 5 secs
    TCP session timeout before 3-way handshaking: 10 secs
    TCP half-closed session timeout: 120 secs
    TCP session timeout in TIME_WAIT: 15 secs
    TCP session timeout for unverified RST: 30 secs
    UDP default timeout: 30 secs
    ICMP default timeout: 6 secs
    other IP default timeout: 30 secs
    Captive Portal session timeout: 30 secs
    Session timeout in discard state:
    TCP: 90 secs, UDP: 60 secs, other IP protocols: 60 secs
    --------------------------------------------------------------------------------
    Session accelerated aging: True
    If accelerated aging has been turned off, some sessions may remain active in the session table
    longer than needed and take up resources.

    Accelerated aging threshold: 80% of utilization
    Scaling factor: 2 X
    --------------------------------------------------------------------------------
    Session setup
    If any of these have been turned off for troubleshooting and not turned back on, they can
    consume additional resources to inspect malformed packets that would otherwise
    be discarded.

    TCP - reject non-SYN first packet: True
    Hardware session offloading: True
    IPv6 firewalling: True
    Strict TCP/IP checksum: True
    ICMP Unreachable Packet Rate: 200 pps
    --------------------------------------------------------------------------------
    Application trickling scan parameters:
    Timeout to determine application trickling: 10 secs
    Resource utilization threshold to start scan: 80%
    Scan scaling factor over regular aging: 8
    --------------------------------------------------------------------------------
    Session behavior when resource limit is reached: drop
    This indicates the behavior of the firewall when it has reached its extreme limit of
    resource depletion.

    --------------------------------------------------------------------------------
    Pcap token bucket rate : 10485760
    --------------------------------------------------------------------------------
    Max pending queued mcast packets per session : 0
    --------------------------------------------------------------------------------

    debug dataplane pool statistics
    Returns the status of all the buffers being used by the system and their status.
    • The number on the left indicates how much buffer is still available
    • The number on the right indicates the total size
    • If the number on the left drops to 0, the buffer is depleted

    > debug dataplane pool statistics
    Hardware Pools
    [ 0] Packet Buffers : 57223/57344 0x8000000030c00000
    [ 1] Work Queue Entries : 229315/229376 0x8000000037c00000
    [ 2] Output Buffers : 1007/1024 0x800000000fc00000
    [ 3] DFA Result : 3995/4000 0x8000000039800000
    [ 4] Timer Buffers : 4096/4096 0x8000000039be8000
    [ 5] PAN_FPA_LWM_POOL : 1024/1024 0x800000000fd00000
    [ 6] ZIP Commands : 1023/1024 0x800000000fd40000
    [ 7] PAN_FPA_BLAST_PO : 1024/1024 0x800000000ff40000
    Software Pools
    [ 0] software packet buffer 0 ( 512): 32767/32768 0x8000000043b2a680
    [ 1] software packet buffer 1 ( 1024): 32768/32768 0x8000000044b4a780
    [ 2] software packet buffer 2 ( 2048): 81920/81920 0x8000000046b6a880
    [ 3] software packet buffer 3 (33280): 20480/20480 0x8000000050bba980
    [ 4] software packet buffer 4 (66048): 304/304 0x80000000795cea80
    [ 5] Shared Pool 24 ( 24): 560000/560000 0x800000007a8f6780
    [ 6] Shared Pool 32 ( 32): 530000/530000 0x800000007b7eaa80
    [ 7] Shared Pool 40 ( 40): 70000/70000 0x800000007ca1cf00
    [ 8] Shared Pool 192 ( 192): 1269999/1270000 0x800000007cd0cf80
    [ 9] Shared Pool 256 ( 256): 140000/140000 0x800000008ba70880
    [10] ZIP Results ( 184): 1024/1024 0x80000000a1827300
    [11] CTD AV Block ( 1024): 32/32 0x80000000be43d380
    [12] Regex Results (11544): 8000/8000 0x80000000be466100
    [13] SSH Handshake State ( 6512): 64/64 0x80000000c580c680
    [14] SSH State ( 3248): 512/512 0x80000000c5872480
    [15] TCP host connections ( 176): 15/16 0x80000000c5a08e80



    show counter global filter delta yes
    Returns, from the second time the command is issued onward, a snapshot of the global counters triggered during the timeframe between the current and previous iteration, and could expose unusual numbers of discarded packets.

    > show counter global filter delta yes
    Global counters:
    Elapsed time since last sampling: 2.981 seconds
    name                value  rate severity category aspect    description
    --------------------------------------------------------------------------------
    pkt_recv               89    29 info     packet   pktproc   Packets received
    pkt_recv_zero          87    29 info     packet   pktproc   Packets received from QoS 0
    pkt_sent                3     1 info     packet   pktproc   Packets transmitted
    session_allocated       1     0 info     session  resource  Sessions allocated
    session_freed           1     0 info     session  resource  Sessions freed
    session_installed       1     0 info     session  resource  Sessions installed
    flow_arp_pkt_rcv       83    27 info     flow     arp       ARP packets received
    flow_host_pkt_rcv       2     0 info     flow     mgmt      Packets received from control plane
    flow_host_pkt_xmt       2     0 info     flow     mgmt      Packets transmitted to control plane
    flow_host_service_allow 2     0 info     flow     mgmt      Device management session allowed
    appid_ident_by_icmp     1     0 info     appid    pktproc   Application identified by icmp type
    dfa_sw                  2     0 info     dfa      pktproc   The total number of dfa match using software
    aho_sw                  1     0 info     aho      pktproc   The total usage of software for AHO
    ctd_pkt_slowpath        2     0 info     ctd      pktproc   Packets processed by slowpath
    pkt_flow_np            87    29 info     packet   resource  Packets entered module flow stage np
    pkt_flow_host           2     0 info     packet   resource  Packets entered module flow stage host
    --------------------------------------------------------------------------------
    Total counters shown: 16
    --------------------------------------------------------------------------------
    Some common counters explained:
    CounterDescription
    pkt_recvpacket received
    session_allocatedsession allocate
    flow_ipfrag_recvipfrag receive rate
    dfa_swdfa matching by sw
    dfa_fpgadfa matching by fpga
    ctd_pkt_slowpathpkt processed by ctd slowpath
    aho_swaho by sw
    aho_fpgaaho by fpga
    log_traffic_cnttraffic log count
    flow_fwd_l3_ttl_zeropackets dropped: IP TTL
    fpga_pktpkt hold by fpga request.
    Note: this is not a cumulative counter but represents
    how many packets are being currently held waiting on FPGA.

      show system statistics session

      Displays aggregated packet rate and throughput values of all dataplanes in a live dashboard fashion, which refreshes automatically

      System Statistics: ('q' to quit, 'h' for help) 
      Device is up : 0 day 2 hours 34 mins 57 sec
      Packet rate : 32/s
      Throughput : 92 Kbps
      Total active sessions : 14
      Active TCP sessions : 8
      Active UDP sessions : 4
      Active ICMP sessions : 2
      Toggle to view 'top 20 applications' by pressing 'a' and back by pressing 's'

      Top 20 Application Statistics: ('q' to quit, 'h' for help)

      Top 20 Application Statistics: ('q' to quit, 'h' for help)

      Virtual System: vsys1
      application                      sessions   packets      bytes
      -------------------------------- ---------- ------------ ------------
      ssl                              349        47051        53368023
      firefox-update                   4          32503        31679603
      google-base                      57         19879        17687367
      ms-update                        30         2513         2413399
      tor                              1          715          710161
      web-browsing                     60         1140         588357
      ping                             2920       5840         572320
      windows-push-notifications       57         819          266737
      apt-get                          6          662          260149
      dns                              728        1484         185056
      dhcp                             124        248          86800
      ms-spynet                        3          71           45382
      ocsp                             9          215          33311
      google-update                    2          28           8624
      ntp                              45         90           8100
      ipv6                             2          64           5248
      sip                              5          5            2283
      ldap                             8          9            2241
      insufficient-data                5          13           780
      icmp                             6          6            520

      It is also important to note that type of traffic and complexity in configuration can also add to CPU utilization. Hence it is important to look at the traffic pattern to understand the potential application causing the high CPU utilization.



      • Identify Sessions That Use an Excessive Percentage of the Packet Buffer


      Monitor for Abusers in Real Time
      The 'show running resource-monitor ingress-backlogs' CLI command can be used to find out packet buffer abusers at runtime:

      show running resource-monitor ingress-backlogs

      admin@PA-7050> show running resource-monitor ingress-backlogs
      -- SLOT:s1, DP:dp1 -- USAGE - ATOMIC: 92%  TOTAL: 93% 

      TOP SESSIONS:
      SESS-ID      PCT   GRP-ID   COUNT 
      6               92%   1            156                   
                               7        1732 
      SESSION DETAILS SESS-ID PROTO SZONESRC       SPORT  DST       DPORT  IGR-IF    EGR-IF       APP 
      6    6     trust 192.168.2.35 55653  10.1.8.89 80  ethernet1/21 ethernet1/22 undecided 

      The command displays a maximum of the top five sessions that each use 2% or more of the packet buffer.
      The sample output above indicates that Session 6 is using 92% of the packet buffer with TCP packets (protocol 6) coming from source IP address 192.168.2.35.

      • SESS-ID—Indicates the global session ID that is used in all other
      show session commands. The global session ID is unique within the firewall.
      • GRP-ID—Indicates an internal stage of processing packets.
      • COUNT—Indicates how many packets are in that GRP-ID for that session.
      • APP—Indicates the App-ID extracted from the Session information, which can help you determine whether the traffic is legitimate. For example, if packets use a common TCP or UDP port but the CLI output indicates an APP of undecided, the packets are possibly attack traffic. The APP is
      undecided when Application IP Decoders cannot get enough information to determine the application. An APP of unknown indicates that Application IP Decoders cannot determine the application; a session of unknown APP that uses a high percentage of the packet buffer is also suspicious.

      ATOMIC queues of work must be executed by a single CPU core. Orderable queues of work may be distributed among multiple CPU cores. (The root/etymological meaning of 'atomic' is indivisible (or more literally, non-cuttable).

      To restrict the display output:
      On a PA-7000 Series model only, you can limit output to a slot, a dataplane, or both. For example:

      admin@PA-7050> show running resource-monitor ingress-backlogs slot s1 
      admin@PA-7050> show running resource-monitor ingress-backlogs slot s1 dp dp1

      On PA-5000 Series, PA-5200 Series, and PA-7000 Series models only, you can limit output to a dataplane. For example:
      admin@PA-5060> show running resource-monitor ingress-backlogs dp dp1

      Use the command output to determine whether the source at the source IP address using a high percentage of the packet buffer is sending legitimate or attack traffic.

      In the sample output above, a single-session attack is likely occurring. A single session (Session ID 6) is using 92% of the packet buffer for Slot 1, DP 1, and the application at that point is
      undecided.

      • If you determine a single user is sending an attack and the traffic is not offloaded, you can End a Single Session DoS Attack. At a minimum, you can Configure DoS Protection Against Flooding of New Sessions.
      • On a hardware model that has a field-programmable gate array (FPGA), the firewall offloads traffic to the FPGA when possible to increase performance. If the traffic is offloaded to hardware, clearing the session does not help because then it is the software that must handle the barrage of packets. You should instead Discard a Session Without a Commit.

      To see whether a session is offloaded or not, use the show session id operational command in the CLI as shown in the following example. The layer7 processing value indicates completed for sessions offloaded or enabled for sessions not offloaded.

      admin@PA-3220(active)> show session id 353706
      Session 353706

      c2s flow:
      source: 10.24.65.6 [Trust_Lab]
      dst: 134.141.79.85
      proto: 6
      sport: 824 dport: 834
      state: ACTIVE type: FLOW
      src user: unknown
      dst user: unknown

      s2c flow:
      source: 134.141.79.85 [Trust_WAN_local]
      dst: 10.24.65.6
      proto: 6
      sport: 834 dport: 824
      state: ACTIVE type: FLOW
      src user: unknown
      dst user: unknown
      qos node: ethernet1/20.12, qos member N/A Qid 0

      start time : Wed Feb 19 21:49:50 2020
      timeout : 15 sec
      time to live : 6 sec
      total byte count(c2s) : 13520
      total byte count(s2c) : 440902
      layer7 packet count(c2s) : 210
      layer7 packet count(s2c) : 311
      vsys : vsys1
      application : ypserv
      rule : lab_to_corp
      service timeout override(index) : False
      session to be logged at end : True
      session in session ager : True
      session updated by HA peer : False
      layer7 processing : enabled
      ctd version : 6
      URL filtering enabled : True
      URL category : any
      session via prediction : True
      use parent's policy : False
      session via syn-cookies : False
      session terminated on host : False
      session traverses tunnel : True
      session terminate tunnel : False
      captive portal session : False
      ingress interface : ethernet1/20.12
      egress interface : tunnel.9
      session QoS rule : N/A (class 4)
      tracker stage firewall : TCP FIN
      end-reason : tcp-fin


      ▶ Discard hose sessions using the 'request session-discard' command:
      request session-discard id 128232

      admin@PA-3220(active)> request session-discard id 128232

      session id: 128232 vsys: vsys1 szone: Trust_Lab src: 10.68.216.48 sport: 57745 dst: 10.204.108.89 dport: 2500 protocol_6 igr-if: ethernet1/20.12 egr- if: tunnel.24 app: veeam discarded by admin: admin timeout: 3600

      No comments: