Description
When troubleshooting why certain traffic is not matching a specified firewall policy, it is often helpful to enable tracking of policy checking in the debug flow output to understand exactly which firewall policies are checked and eventually matched or not matched.
Solution
In addition to the other debug flow CLI commands, use the CLI command diag debug flow show iprope enable to show debug messages indicating which policies are checked and eventually matched or not matched with traffic specified in the debug flow filter.
Sample Output:
FGT60D4613018571 # 2016-05-27 11:12:19 id=20085 trace_id=1001 func=print_pkt_detail line=4478 msg="vd-root received a packet(proto=6, 192.168.1.110:51663->93.184.216.34:80) from internal. flag [S], seq 112318697,"
2016-05-27 11:12:19 id=20085 trace_id=1001 func=init_ip_session_common line=4629 msg="allocate a new session-00002d4b"
2016-05-27 11:12:19 id=20085 trace_id=1001 func=iprope_dnat_check line=4637 msg="in-[internal], out-[]"
2016-05-27 11:12:19 id=20085 trace_id=1001 func=iprope_dnat_tree_check line=834 msg="len=0"
2016-05-27 11:12:19 id=20085 trace_id=1001 func=iprope_dnat_check line=4650 msg="result: skb_flags-00800000, vid-0, ret-no-match, act-accept, flag-00000000"
2016-05-27 11:12:19 id=20085 trace_id=1001 func=vf_ip4_route_input line=1596 msg="find a route: flags=00000000 gw-172.17.97.3 via wan1"
2016-05-27 11:12:19 id=20085 trace_id=1001 func=iprope_fwd_check line=630 msg="in-[internal], out-[wan1], skb_flags-00800000, vid-0"
2016-05-27 11:12:19 id=20085 trace_id=1001 func=__iprope_tree_check line=543 msg="gnum-100004, use addr/intf hash, len=5"
2016-05-27 11:12:19 id=20085 trace_id=1001 func=__iprope_check_one_policy line=1841 msg="checked gnum-100004 policy-7, ret-no-match, act-accept"
2016-05-27 11:12:19 id=20085 trace_id=1001 func=__iprope_check_one_policy line=1841 msg="checked gnum-100004 policy-9, ret-matched, act-accept"
2016-05-27 11:12:19 id=20085 trace_id=1001 func=__iprope_user_identity_check line=1676 msg="ret-matched"
2016-05-27 11:12:19 id=20085 trace_id=1001 func=__iprope_check line=2051 msg="gnum-4e21, check-f8afc480"
2016-05-27 11:12:19 id=20085 trace_id=1001 func=__iprope_check_one_policy line=1841 msg="checked gnum-4e21 policy-0, ret-no-match, act-accept"
2016-05-27 11:12:19 id=20085 trace_id=1001 func=__iprope_check_one_policy line=1841 msg="checked gnum-4e21 policy-1, ret-no-match, act-accept"
2016-05-27 11:12:19 id=20085 trace_id=1001 func=__iprope_check_one_policy line=1841 msg="checked gnum-4e21 policy-1, ret-matched, act-accept"
2016-05-27 11:12:19 id=20085 trace_id=1001 func=__iprope_check_one_policy line=2022 msg="policy-1 is matched, act-accept"
2016-05-27 11:12:19 id=20085 trace_id=1001 func=__iprope_check line=2070 msg="gnum-4e21 check result: ret-matched, act-accept, flag-00200008, flag2-00000000"
2016-05-27 11:12:19 id=20085 trace_id=1001 func=get_new_addr line=2766 msg="find SNAT: IP-172.17.96.32(from IPPOOL), port-51663"
2016-05-27 11:12:19 id=20085 trace_id=1001 func=__iprope_check_one_policy line=2022 msg="policy-9 is matched, act-accept"
2016-05-27 11:12:19 id=20085 trace_id=1001 func=iprope_fwd_auth_check line=682 msg="after iprope_captive_check(): is_captive-0, ret-matched, act-accept, idx-9"
2016-05-27 11:12:19 id=20085 trace_id=1001 func=iprope_reverse_dnat_check line=800 msg="in-[internal], out-[wan1], skb_flags-00800000, vid-0"
2016-05-27 11:12:19 id=20085 trace_id=1001 func=fw_forward_handler line=675 msg="Allowed by Policy-9: AV SNAT"
2016-05-27 11:12:19 id=20085 trace_id=1001 func=av_receive line=262 msg="send to application layer"
Note that in the output in bold above, the FortiGate provides more information about the policy matching process and along with the "Allowed by Policy-XX" output, provides a means for confirming which policies were checked against the corresponding traffic based on matching criteria and which policy was the best match and ended up allowing or denying the traffic.
