Troubleshooting Tip: Initial troubleshooting steps for traffic blocked by FortiGate

gmanea · ‎04-07-2021

Description

This article describes few basic steps of troubleshooting traffic over the FortiGate firewall, and is intended as a guide to perform the basic checks on the FortiGate when a problem occurs and certain traffic is not passing.
All these steps are important for diagnostics. The data collected in this guide is needed when opening a TAC support case.
When parts of this data are not present, the assigned TAC engineer will likely ask for it.

The resolution of a case is considerably faster when this data is already attached in the case from the moment it is created.

Scope

FortiGate.

Solution

When this stopped working/whether it worked before:

If it did not work before: For a new implementation, check once again if the setup guide was followed entirely to ensure nothing is missing.
Mention the setup guide that was followed (link) when opening a TAC case. Also attach the configuration backup so TAC can check what was configured.

If it did: Consider what has changed since the time it was working.

Standalone Upgrade: review the release notes for known problems. Check if the firewall can reach the internet, has DNS response (exec ping pu.bl.ic.IP, exec ping service.fortiguard.net).
HA Upgrade: make sure both units are in sync and have the same firmware (get system status).

Check if the primary unit has access to both WAN and LAN (exec ping pu.bl.ic.IP, exec ping lo.ca.l.IP).

If not, check the routing table (get router info routing-table all; get router info routing-table detail x.x.x.x ). If it is needed to revert to a working version, make sure to collect all the logs or call us, otherwise the support can’t investigate or provide a possible cause.

To downgrade quickly to a previous firmware (the previous firmware version is kept in memory).

Policy / inspection profiles changes: review the last change.

Whether it works after reverting the previous changes:

Yes: The root cause is isolated. Fine tune the profiles/policy recently added/removed, so that it allows the traffic.

No: Check why the traffic is blocked, per below, and note what is observed. This log is needed when creating a TAC support case.

Start with the policy that is expected to allow the traffic. Check the ID number of this policy.
Make sure that the session from source to destination is matching this policy:(check 'policy_id=' in the output).

( Use the following command to do a policy lookup in the CLI:

diagnose firewall iprope lookup <source ip> <source port number> <destination ip> <destination port number> <protocol> <incoming interface>

If the session exists, then check the existing UTM profiles in that policy (AV, WebFilter, IPS, etc)
Remove them one by one until the traffic is restored.
Check if the traffic flows ok when policy is changed to flow-based, instead of proxy-based.

Traffic logs, packet captures, and debug flow are the tools TAC use further to check that, always in conjunction with the configuration file (backup from GUI of 'Global' context). Debug log may also be required.
When opening a TAC support case, attach them and in more complex scenarios, the traffic path is needed as well:
(i.e: PC -> port1 (vlan 100, vdom TEST, policy 17) -> zone PROD -> VDOM link TEST_to_PROD -> port9 (VLAN 15, policy 413) -> internet port wa1).

Traffic logs (logging must be enabled in policy) or Security logs (AV/Webfilter/IPS/etc.):
either the traffic is blocked due to policy, or due to a security profile. When available, the logs are the most accessible way to check why traffic is blocked. Logs also tell us which policy and type of policy blocked the traffic. Sometimes also the reason why. Attach relevant logs of the traffic in question. Export a small group of such logs from the logging unit (FortiGate GUI, FortiAnalyzer, FortiCloud, Syslog, etc).

Packet capture (sniffer):
On models with hardware acceleration, this has to be disabled temporarily in order to capture the traffic.
It is better captured from command line and log the SSH output.
Debug flow (firewall logic):

Common cases where traffic is not passing, and shown in debug flow for new sessions:
'Denied by forward policy check'.
'iprope_in_check() check failed, drop.
' reverse path check fail, drop'.
Common cases where traffic is allowed:
'sent to AV' / 'sent to IPS': traffic is sent to AV inspection / to flow-based inspection.
'Trying to offloading session from port1 to wan1' : user session is being copied from one interface to another interface.
'Find an existing session, id-0xxxxxxxx, reply direction': a session is already established and the traffic is flowing (possibly Layer7 problem - packet capture needed).

Debug log (snapshot of the system parameters at the time it is downloaded):

If Authentication and user groups are used in policies, check also this guide related articles below.

For SIP/VoIP issues, a packet capture (usually with 'port 5060' as filter) is absolutely necessary, along with the configuration (backup from GUI of 'Global' context).

Troubleshooting Example:

With debug flow, capture interesting traffic and start noticing all fields:

dia de flow filter add 172.16.1.2 8.8.8.8 and <- 2 IPs that are troubleshooted are internal toward Google DNS Servers (the 'end' can be used to filter the traffic to only 2 IPs without needing to specify source and destination address in separate filters).

dia de flow filter proto 1 <- Protocol used is ICMP (ping).

dia de flow show iprope en <- This function will show iprope information (routing details that the packet will follow).

dia de flow show function-name en <- This will show function name in the flow.

dia de console time end <- This will also provide timestamp in the logs.

dia de flow trace start 2 <- This will capture only 2 packets while debugging (set it to a reasonable value to capture as much data as possible).

dia de en <- This command will start debugging.

After this step, analyze logs:

Results:

FGT1 # 2024-08-16 21:44:36 id=65308 trace_id=1 func=print_pkt_detail line=5894 msg="vd-root:0 received a packet(proto=1, 172.16.1.2:1->8.8.8.8:2048) tun_id=0.0.0.0 from port2. type=8, code=0, id=1, seq=3." <- This line will show packet information from 172.16.1.1 toward 8.8.8.8 and protocol ports used.
2024-08-16 21:44:36 id=65308 trace_id=1 func=init_ip_session_common line=6080 msg="allocate a new session-000a6c90, tun_id=0.0.0.0" <- This line will show information if this is a new session or an existing session already exists in the session table.
2024-08-16 21:44:36 id=65308 trace_id=1 func=iprope_dnat_check line=5281 msg="in-[port2], out-[]"
2024-08-16 21:44:36 id=65308 trace_id=1 func=iprope_dnat_tree_check line=824 msg="len=0"
2024-08-16 21:44:36 id=65308 trace_id=1 func=iprope_dnat_check line=5293 msg="result: skb_flags-02000000, vid-0, ret-no-match, act-accept, flag-00000000"
2024-08-16 21:44:36 id=65308 trace_id=1 func=__vf_ip_route_input_rcu line=1990 msg="find a route: flag=00000000 gw-10.191.31.254 via port1" ---> these 2 lines will show us routing information and ingress and egress ports and in this case default route on FortiGate as well as port2 for in traffic and port1 used for out traffic (packet sniffer below will also show this information)
2024-08-16 21:44:37 id=65308 trace_id=1 func=iprope_fwd_check line=768 msg="in-[port2], out-[port1], skb_flags-02000000, vid-0, app_id: 0, url_cat_id: 0"
2024-08-16 21:44:37 id=65308 trace_id=1 func=__iprope_tree_check line=535 msg="gnum-100004, use addr/intf hash, len=2"
2024-08-16 21:44:37 id=65308 trace_id=1 func=__iprope_check_one_policyline=2033 msg="checked gnum-100004 policy-2, ret-matched, act-accept" ---> __iprope_check_one_policyis the function that will check the matching policy after packet has arrived at FortiGate, routing has been checked and destination is also ready to be contacted
2024-08-16 21:44:37 id=65308 trace_id=1 func=__iprope_user_identity_check line=1807 msg="ret-matched"
2024-08-16 21:44:37 id=65308 trace_id=1 func=__iprope_check line=2281 msg="gnum-4e21, check-00000000a905ccbb"
2024-08-16 21:44:37 id=65308 trace_id=1 func=__iprope_check_one_policy line=2033 msg="checked gnum-4e21 policy-4294967295, ret-no-match, act-accept"
2024-08-16 21:44:37 id=65308 trace_id=1 func=__iprope_check_one_policy line=2033 msg="checked gnum-4e21 policy-9, ret-no-match, act-accept"
2024-08-16 21:44:37 id=65308 trace_id=1 func=__iprope_check_one_policy line=2033 msg="checked gnum-4e21 policy-10, ret-no-match, act-accept"
2024-08-16 21:44:37 id=65308 trace_id=1 func=__iprope_check_one_policy line=2033 msg="checked gnum-4e21 policy-11, ret-no-match, act-accept"
2024-08-16 21:44:37 id=65308 trace_id=1 func=__iprope_check_one_policy line=2033 msg="checked gnum-4e21 policy-12, ret-no-match, act-accept"
2024-08-16 21:44:37 id=65308 trace_id=1 func=__iprope_check_one_policy line=2033 msg="checked gnum-4e21 policy-1, ret-no-match, act-accept"
2024-08-16 21:44:37 id=65308 trace_id=1 func=__iprope_check_one_policy line=2033 msg="checked gnum-4e21 policy-14, ret-no-match, act-accept"
2024-08-16 21:44:37 id=65308 trace_id=1 func=__iprope_check_one_policy line=2033 msg="checked gnum-4e21 policy-5, ret-no-match, act-accept"
2024-08-16 21:44:37 id=65308 trace_id=1 func=__iprope_check_one_policy line=2033 msg="checked gnum-4e21 policy-16, ret-no-match, act-accept"
2024-08-16 21:44:37 id=65308 trace_id=1 func=__iprope_check_one_policy line=2033 msg="checked gnum-4e21 policy-2, ret-no-match, act-accept"
2024-08-16 21:44:37 id=65308 trace_id=1 func=__iprope_check_one_policy line=2033 msg="checked gnum-4e21 policy-3, ret-no-match, act-accept"
2024-08-16 21:44:37 id=65308 trace_id=1 func=__iprope_check_one_policy line=2033 msg="checked gnum-4e21 policy-4, ret-no-match, act-accept"
2024-08-16 21:44:37 id=65308 trace_id=1 func=__iprope_check_one_policy line=2033 msg="checked gnum-4e21 policy-8, ret-no-match, act-accept"
2024-08-16 21:44:37 id=65308 trace_id=1 func=__iprope_check_one_policy line=2033 msg="checked gnum-4e21 policy-6, ret-no-match, act-accept"
2024-08-16 21:44:37 id=65308 trace_id=1 func=__iprope_check_one_policy line=2033 msg="checked gnum-4e21 policy-6, ret-no-match, act-accept"
2024-08-16 21:44:37 id=65308 trace_id=1 func=__iprope_check_one_policy line=2033 msg="checked gnum-4e21 policy-6, ret-no-match, act-accept"
2024-08-16 21:44:37 id=65308 trace_id=1 func=__iprope_check_one_policy line=2033 msg="checked gnum-4e21 policy-7, ret-matched, act-accept"
2024-08-16 21:44:37 id=65308 trace_id=1 func=__iprope_check_one_policy line=2251 msg="policy-7 is matched, act-accept"
2024-08-16 21:44:37 id=65308 trace_id=1 func=__iprope_check line=2298 msg="gnum-4e21 check result: ret-matched, act-accept, flag-00202000, flag2-00000000"
2024-08-16 21:44:37 id=65308 trace_id=1 func=get_new_addr line=1213 msg="find SNAT: IP-10.191.19.117(from IPPOOL), port-60418" ---> NAT will happen to translate internal IP to External FortiGate IP or to the IP on FortiGate that is configured in outgoing interface.
2024-08-16 21:44:37 id=65308 trace_id=1 func=__iprope_check_one_policy line=2251 msg="policy-2 is matched, act-accept" ---> this line will confirm that a Firewall policy is found that has all above criteria specified to allow or deny traffic. In this case act-accept means that traffic is allowed to pass
2024-08-16 21:44:37 id=65308 trace_id=1 func=iprope_fwd_check line=805 msg="after iprope_captive_check(): is_captive-0, ret-matched, act-accept, idx-2"
2024-08-16 21:44:37 id=65308 trace_id=1 func=iprope_fwd_auth_check line=824 msg="after iprope_captive_check(): is_captive-0, ret-matched, act-accept, idx-2"
2024-08-16 21:44:37 id=65308 trace_id=1 func=iprope_reverse_dnat_check line=1292 msg="in-[port2], out-[port1], skb_flags-02000000, vid-0"
2024-08-16 21:44:37 id=65308 trace_id=1 func=iprope_reverse_dnat_tree_check line=916 msg="len=0"
2024-08-16 21:44:37 id=65308 trace_id=1 func=fw_forward_handler line=989 msg="Allowed by Policy-2: SNAT"
2024-08-16 21:44:37 id=65308 trace_id=1 func=ip_session_confirm_final line=3113 msg="npu_state=0x1100, hook=4"
2024-08-16 21:44:37 id=65308 trace_id=1 func=ids_receive line=431 msg="send to ips"
2024-08-16 21:44:37 id=65308 trace_id=1 func=__ip_session_run_tuple line=3458 msg="SNAT 172.16.1.2->10.191.19.117:60418"

Note that trace_id=1 means that all the lines up to the last one are actions that FortiGate takes only for the first package. When trace_id changes to 2, it means that this is the second package that enters FortiGate.

2024-08-16 21:44:37 id=65308 trace_id=2 func=print_pkt_detail line=5894 msg="vd-root:0 received a packet(proto=1, 8.8.8.8:60418->10.191.19.117:0) tun_id=0.0.0.0 from port1. type=0, code=0, id=60418, seq=3." <- This will be the returned traffic (reply direction from 8.8.8.8 to external interface of FortiGate - remember NAT that took place in the first packet trace_id=1).
2024-08-16 21:44:37 id=65308 trace_id=2 func=resolve_ip_tuple_fast line=5982 msg="Find an existing session, id-000a6c90, reply direction" <- For the reply traffic, there is an existing session that initiated on first package, so here it states that an existing session is present.
2024-08-16 21:44:37 id=65308 trace_id=2 func=__ip_session_run_tuple line=3471 msg="DNAT 10.191.19.117:0->172.16.1.2:1" <- Reply NAT happens again to translate external IP of FortiGate to the internal IP of client.
2024-08-16 21:44:37 id=65308 trace_id=2 func=__vf_ip_route_input_rcu line=1990 msg="find a route: flag=00000000 gw-0.0.0.0 via port2"
2024-08-16 21:44:37 id=65308 trace_id=2 func=npu_handle_session44 line=1327 msg="Trying to offloading session from port1 to port2, skb.npu_flag=00000000 ses.state=00002200 ses.npu_state=0x00001108"
2024-08-16 21:44:37 id=65308 trace_id=2 func=fw_forward_dirty_handler line=439 msg="state=00002200, state2=00000000, npu_state=00001108"
2024-08-16 21:44:37 id=65308 trace_id=2 func=ids_receive line=431 msg="send to ips"

Packet sniffer to see if packet is leaving FortiGate at all:

diag sniffer packet any "host 172.16.1.2 and host 8.8.8.8 and icmp" 4 3 l <- Here, capture is filtered to 2 hosts and 1 protocol. Values 4 2 l (lower L) mean that it is only necessary to capture the packet headers (4), and only 3 packets (2) are needed. The intent is to capture the timestamp in local FW time.

The results:
Using Original Sniffing Mode
interfaces=[any]
filters=[host 172.16.1.2 and host 8.8.8.8 and icmp]
Using Original Sniffing Mode
interfaces=[any]
filters=[icmp]
2024-08-16 22:04:21.844412 port2 in 172.16.1.2 -> 8.8.8.8: icmp: echo request <- Packet arrives from client via port2.
2024-08-16 22:04:21.845467 port1 out 10.191.19.117 -> 8.8.8.8: icmp: echo request <- Packet leaves via port1 toward 8.8.8.8.
2024-08-16 22:04:21.847570 port1 in 8.8.8.8 -> 10.191.19.117: icmp: echo reply <- As the message states, this is the reply traffic that enters port1.
2024-08-16 22:04:21.847776 port2 out 8.8.8.8 -> 172.16.1.2: icmp: echo reply <- After matching the right session, it will go out to the client via port2.

A check to the routing table will show if traffic for those 2 IPs corresponds to ports that traffic comes in and out of:

get router info routing details 172.16.1.2

Routing table for VRF=0
Routing entry for 172.16.1.0/24

Known via "connected", distance 0, metric 0, best

* is directly connected, port2 <- This IP is directly connected to port2 which is also the port that traffic comes in noticed in sniffer and it is directly connected because FortiGate has this subnet configured in port2.

show system interface port2
    config system interface
      edit "port2"
        set vdom "root"
        set ip 172.16.1.1 255.255.255.0
      set type physical
        set snmp-index 2
end
    next
end

Checking the second IP:

get router info routing details 8.8.8.8

Routing table for VRF=0
Routing entry for 0.0.0.0/0
Known via "static", distance 10, metric 0, best
* vrf 0 10.191.31.254, via port1 <- This information also corresponds with sniffer, where the packet leaves via port1 toward 8.8.8.8, but this time 'Known via static' means that a static route is configured to reach this network.

    config router static
      edit 1
            set gateway 10.191.31.254
            set dst 0.0.0.0 0.0.0.0
            set device "port1"
        next

end

Check IP Configuration and session information:

After all this information is gathered, it is also recommended to capture session information for the above traffic:

diag sys session filter src 172.16.1.2

diag sys session filter dst 8.8.8.8

diag sys session filter proto 1

session info: proto=1 proto_state=00 duration=2 expire=59 timeout=0 flags=00000000 socktype=0 sockport=0 av_idx=0 use=4
origin-shaper=
reply-shaper=
per_ip_shaper=
class_id=0 ha_id=0 policy_dir=0 tunnel=/ vlan_cos=0/255
state=may_dirty ndr
statistic(bytes/packets/allow_err): org=180/3/1 reply=180/3/1 tuples=3
tx speed(Bps/kbps): 65/0 rx speed(Bps/kbps): 65/0
orgin->sink: org pre->post, reply pre->post dev=4->3/3->4 gwy=10.191.31.254/0.0.0.0
hook=post dir=org act=snat 172.16.1.2:1->8.8.8.8:8(10.191.19.117:60418)
hook=pre dir=reply act=dnat 8.8.8.8:60418->10.191.19.117:0(172.16.1.2:1)
hook=post dir=reply act=noop 8.8.8.8:1->172.16.1.2:0(0.0.0.0:0)
misc=0 policy_id=2 pol_uuid_idx=15749 auth_info=0 chk_client_info=0 vd=0
serial=000a7123 tos=ff/ff app_list=0 app=0 url_cat=0
rpdb_link_id=00000000 ngfwid=n/a
npu_state=0x001108
no_ofld_reason: redir-to-ips denied-by-nturbo
total session 1

For additional information on how to interpret session information, see the following documentation:

FortiGate session table information - Fortinet Community

The focus in this article will be on interfaces that are used here.
The line of interest is:

orgin->sink: org pre->post, reply pre->post dev=4->3/3->4 gwy=10.191.31.254/0.0.0.0

dev=4->3/3->4 are related to interface index that can be found using command:

diag ip address list

IP=10.191.19.117->10.191.19.117/255.255.240.0 index=3 devname=port1 <- dev3.
IP=172.16.1.1->172.16.1.1/255.255.255.0 index=4 devname=port2 <- dev4.
IP=192.168.1.254->192.168.1.254/255.255.255.0 index=8 devname=port6
IP=127.0.0.1->127.0.0.1/255.0.0.0 index=14 devname=root
IP=10.255.1.1->10.255.1.1/255.255.255.0 index=18 devname=fortilink
IP=127.0.0.1->127.0.0.1/255.0.0.0 index=19 devname=vsys_ha
IP=127.0.0.1->127.0.0.1/255.0.0.0 index=21 devname=vsys_fgfm

Note that this is a working scenario. If some of these parameters do not match, check step-by-step to find what might be missing or needs to be changed.
The related articles below have all required information to troubleshoot each step in this path.

Related articles: