Unable to see policy deny message when running debug flow check, fortiOS 7.0

[bhuo]

Hey Guys,

I have been testing this debug command for a while.

I have setup a firewall security policy to deny "gmail" traffic from inside to outside (all services deny), I have tested via cmd (tired to ping the gmail FQDN or ip address, confirmed it got blocked)

The issue I have is I couldn't see any denied message from debug flow logs, the command I run is in below:

diagnose debug flow filter addr 142.250.70.197

diagnose debug flow filter proto 1

diagnose debug flow show function-name enabled 

diagnose debug flow show ipprobe enabled

diagnose debug flow trace start 100

diagnose debug flow enabled

This is output from those commands.

abc-101f-fw01 # id=20085 trace_id=622 func=print_pkt_detail line=5723 msg="vd-root:0 received a packet(proto=1, 192.168.253.69:1->142.250.70.197:2048) from vlan_si. type=8, code=0, id=1, seq=98." id=20085 trace_id=622 func=init_ip_session_common line=5894 msg="allocate a new session-02b91e97" id=20085 trace_id=622 func=iprope_dnat_check line=5061 msg="in-[vlan_si], out-[]" id=20085 trace_id=622 func=iprope_dnat_tree_check line=830 msg="len=0" id=20085 trace_id=622 func=iprope_dnat_check line=5074 msg="result: skb_flags-02000000, vid-0, ret-no-match, act-accept, flag-00000000" id=20085 trace_id=622 func=vf_ip_route_input_common line=2621 msg="find a route: flag=04000000 gw-27.33.116.97 via wan1" id=20085 trace_id=622 func=iprope_fwd_check line=781 msg="in-[vlan_si], out-[wan1], skb_flags-02000000, vid-0, app_id: 0, url_cat_id: 0" id=20085 trace_id=622 func=__iprope_tree6_check line=51 msg="gnum-100004, use addr/intf hash, len=3" id=20085 trace_id=622 func=__iprope_check_one_policy line=1941 msg="checked gnum-100004 policy-6, ret-matched, act-accept" id=20085 trace_id=622 func=__iprope_user_identity_check line=1761 msg="ret-matched" id=20085 trace_id=622 func=get_new_addr line=1176 msg="find SNAT: IP-27.33.116.98(from IPPOOL), port-60417" id=20085 trace_id=622 func=__iprope_check_one_policy line=2159 msg="policy-6 is matched, act-accept" id=20085 trace_id=622 func=iprope_fwd_auth_check line=832 msg="after iprope_captive_check(): is_captive-0, ret-matched, act-accept, idx-6" id=20085 trace_id=622 func=iprope_shaping_check line=921 msg="in-[vlan_si], out-[wan1], skb_flags-02000000, vid-0" id=20085 trace_id=622 func=__iprope_check line=2188 msg="15, chegnum-1000ck-ffffffbffc0294c8" id=20085 trace_id=622 func=__iprope_check_one_policy line=1941 msg="checked gnum-100015 policy-1, ret-no-match, act-accept" id=20085 trace_id=622 func=__iprope_check line=2207 msg="gnum-100015 check result: ret-no-match, act-accept, flag-00000000, flag2-00000000" id=20085 trace_id=622 func=iprope_policy_group_check line=4500 msg="after check: ret-no-match, act-accept, flag-00000000, flag2-00000000" id=20085 trace_id=622 func=iprope_reverse_dnat_check line=1252 msg="in-[vlan_si], out-[wan1], skb_flags-02000000, vid-0" id=20085 trace_id=622 func=iprope_reverse_dnat_tree_check line=923 msg="len=0" id=20085 trace_id=622 func=iprope_central_nat_check line=1275 msg="in-[vlan_si], out-[wan1], skb_flags-02000000, vid-0" id=20085 trace_id=622 func=__iprope_check_one_policy line=1941 msg="checked gnum-10000d policy-1, ret-matched, act-accept" id=20085 trace_id=622 func=get_new_addr line=1176 msg="find DNAT: IP-27.33.116.98, port-60417" id=20085 trace_id=622 func=__iprope_check_one_policy line=2159 msg="policy-1 is matched, act-accept" id=20085 trace_id=622 func=fw_forward_handler line=819 msg="Allowed by Policy-6: SNAT" id=20085 trace_id=622 func=ids_receive line=298 msg="send to ips" id=20085 trace_id=623 func=print_pkt_detail line=5723 msg="vd-root:0 received a packet(proto=1, 192.168.253.69:1->142.250.70.197:2048) from vlan_si. type=8, code=0, id=1, seq=99." id=20085 trace_id=623 func=resolve_ip_tuple_fast line=5804 msg="Find an existing session, id-02b91e97, original direction" id=20085 trace_id=623 func=npu_handle_session44 line=1163 msg="Trying to offloading session from vlan_si to wan1, skb.npu_flag=00000000 ses.state=00013204 ses.npu_state=0x00001008" id=20085 trace_id=623 func=fw_forward_dirty_handler line=396 msg="state=00013204, state2=00000000, npu_state=00001008" id=20085 trace_id=624 func=print_pkt_detail line=5723 msg="vd-root:0 received a packet(proto=1, 192.168.253.69:1->142.250.70.197:2048) from vlan_si. type=8, code=0, id=1, seq=100." id=20085 trace_id=624 func=resolve_ip_tuple_fast line=5804 msg="Find an existing session, id-02b91e97, original direction" id=20085 trace_id=624 func=npu_handle_session44 line=1163 msg="Trying to offloading session from vlan_si to wan1, skb.npu_flag=00000000 ses.state=00013204 ses.npu_state=0x00001008" id=20085 trace_id=624 func=fw_forward_dirty_handler line=396 msg="state=00013204, state2=00000000, npu_state=00001008" id=20085 trace_id=625 func=print_pkt_detail line=5723 msg="vd-root:0 received a packet(proto=1, 192.168.253.69:1->142.250.70.197:2048) from vlan_si. type=8, code=0, id=1, seq=101." id=20085 trace_id=625 func=resolve_ip_tuple_fast line=5804 msg="Find an existing session, id-02b91e97, original direction" id=20085 trace_id=625 func=npu_handle_session44 line=1163 msg="Trying to offloading session from vlan_si to wan1, skb.npu_flag=00000000 ses.state=00013204 ses.npu_state=0x00001008" id=20085 trace_id=625 func=fw_forward_dirty_handler line=396 msg="state=00013204, state2=00000000, npu_state=00001008"

I just couldn't see any message re firewall policy deny, so it is really hard for me to troubleshoot traffics flow in production environment.

Any help will be greatly appreciated.

Thanks,

Bill 

[Kangming]

bhuo wrote:

Hey LiuKangming,

Thanks for reply, please see output below,

filters=[host 142.250.70.197] 3.716728 vlan_si in 192.168.253.69 -> 142.250.70.197: icmp: echo request 8.409288 vlan_si in 192.168.253.69 -> 142.250.70.197: icmp: echo request 13.403180 vlan_si in 192.168.253.69 -> 142.250.70.197: icmp: echo request 18.413922 vlan_si in 192.168.253.69 -> 142.250.70.197: icmp: echo request

Hi bhuo, 

Maybe the NGFW mode you are running, this NGFW mode will perform APP/IPS detection by default, so the last result you see is "sent to ips" for processing. At this time, we can only observe the violation log to determine the packet loss. In my LAB environment, the situation is the same as yours.

id=20085 trace_id=622 func=fw_forward_handler line=819 msg="Allowed by Policy-6: SNAT" id=20085 trace_id=622 func=ids_receive line=298 msg="send to ips"

Thank you.