Troubleshooting Tip: Debug flow shows error ‘iprope_auth_portal_check() result: ret-matched, act-drop’

[Kush_Patel]

Description	This article describes how to handle a case where the policy is configured to allow traffic, but it is not allowed as expected, and 'iprope_auth_portal_check() result: ret-matched, act-drop' errors show in debug logs.
Scope	FortiGate.
Solution	The following is an example of typical debug commands used in this situation: diagnose debug flow filter addr x.x.x.x diagnose debug flow sh func en diagnose debug flow sh iprope en diagnose debug flow trace start 999 diagnose debug en Example debug flow: # 2023-06-23 10:43:28 id=20085 trace_id=360 func=print_pkt_detail line=5529 msg="vd-root received a packet(proto=6, x.x.x.x:50087->10.1.10.2:8454) from wan2. flag [S], seq 1370505890, ack 0, win 64240" 2023-06-23 10:43:28 id=20085 trace_id=360 func=init_ip_session_common line=5693 msg="allocate a new session-0001017d" 2023-06-23 10:43:28 id=20085 trace_id=360 func=iprope_dnat_check line=4927 msg="in-[wan2], out-[]" 2023-06-23 10:43:28 id=20085 trace_id=360 func=iprope_dnat_tree_check line=812 msg="len=1" 2023-06-23 10:43:28 id=20085 trace_id=360 func=__iprope_check_one_dnat_policy line=4802 msg="checking gnum-100000 policy-3" 2023-06-23 10:43:28 id=20085 trace_id=360 func=get_new_addr line=3090 msg="find DNAT: IP-10.2.20.2, port-8050" 2023-06-23 10:43:28 id=20085 trace_id=360 func=__iprope_check_one_dnat_policy line=4884 msg="matched policy-3, act=accept, vip=3, flag=100, sflag=800000" 2023-06-23 10:43:28 id=20085 trace_id=360 func=iprope_dnat_check line=4940 msg="result: skb_flags-00800000, vid-3, ret-matched, act-accept, flag-00000100" 2023-06-23 10:43:28 id=20085 trace_id=360 func=fw_pre_route_handler line=180 msg="VIP-10.2.20.2:8050, outdev-wan2" 2023-06-23 10:43:28 id=20085 trace_id=360 func=__ip_session_run_tuple line=3366 msg="DNAT 10.1.10.2:8454->10.2.20.2:8050" 2023-06-23 10:43:28 id=20085 trace_id=360 func=vf_ip4_route_input line=1604 msg="find a route: flags=00000000 gw-10.2.20.2 via VLAN24" 2023-06-23 10:43:28 id=20085 trace_id=360 func=iprope_fwd_check line=736 msg="in-[wan2], out-[VLAN24], skb_flags-008000c0, vid-3, app_id: 0, url_cat_id: 0" 2023-06-23 10:43:28 id=20085 trace_id=360 func=__iprope_tree_check line=546 msg="gnum-100004, use addr/intf hash, len=2" 2023-06-23 10:43:28 id=20085 trace_id=360 func=__iprope_check_one_policy line=1753 msg="checked gnum-100004 policy-53, ret-matched, act-accept" 2023-06-23 10:43:28 id=20085 trace_id=360 func=__iprope_user_identity_check line=1561 msg="ret-matched" 2023-06-23 10:43:28 id=20085 trace_id=360 func=__iprope_check line=1995 msg="gnum-4e20, check-f8ae2ae8" 2023-06-23 10:43:28 id=20085 trace_id=360 func=__iprope_check_one_policy line=1753 msg="checked gnum-4e20 policy-6, ret-no-match, act-accept" 2023-06-23 10:43:28 id=20085 trace_id=360 func=__iprope_check_one_policy line=1753 msg="checked gnum-4e20 policy-6, ret-no-match, act-accept" 2023-06-23 10:43:28 id=20085 trace_id=360 func=__iprope_check_one_policy line=1753 msg="checked gnum-4e20 policy-6, ret-no-match, act-accept" 2023-06-23 10:43:28 id=20085 trace_id=360 func=__iprope_check line=2014 msg="gnum-4e20 check result: ret-no-match, act-accept, flag-00000000, flag2-00000000" 2023-06-23 10:43:28 id=20085 trace_id=360 func=__iprope_check_one_policy line=1966 msg="policy-53 is matched, act-accept" 2023-06-23 10:43:28 id=20085 trace_id=360 func=__iprope_check line=1995 msg="gnum-1, check-f8ae2ae8" 2023-06-23 10:43:28 id=20085 trace_id=360 func=__iprope_check_one_policy line=1753 msg="checked gnum-1 policy-4294967295, ret-no-match, act-drop" 2023-06-23 10:43:28 id=20085 trace_id=360 func=__iprope_check line=2014 msg="gnum-1 check result: ret-no-match, act-drop, flag-00000000, flag2-00000000" 2023-06-23 10:43:28 id=20085 trace_id=360 func=iprope_policy_group_check line=4339 msg="after check: ret-no-match, act-drop, flag-00000000, flag2-00000000" 2023-06-23 10:43:28 id=20085 trace_id=360 func=__iprope_check line=1995 msg="gnum-100013, check-f8adecf8" 2023-06-23 10:43:28 id=20085 trace_id=360 func=iprope_policy_group_check line=4339 msg="after check: ret-no-match, act-drop, flag-00000000, flag2-00000000" 2023-06-23 10:43:28 id=20085 trace_id=360 func=__iprope_check line=1995 msg="gnum-100014, check-f8ae16a8" 2023-06-23 10:43:28 id=20085 trace_id=360 func=iprope_policy_group_check line=4339 msg="after check: ret-no-match, act-drop, flag-00000000, flag2-00000000" 2023-06-23 10:43:28 id=20085 trace_id=360 func=iprope_fwd_auth_check line=791 msg="after iprope_captive_check(): is_captive-1, ret-matched, act-drop, idx-0" 2023-06-23 10:43:28 id=20085 trace_id=360 func=__iprope_check line=1995 msg="gnum-3, check-f8ae2ae8" 2023-06-23 10:43:28 id=20085 trace_id=360 func=__iprope_check_one_policy line=1753 msg="checked gnum-3 policy-4294967295, ret-no-match, act-drop" 2023-06-23 10:43:28 id=20085 trace_id=360 func=__iprope_check_one_policy line=1753 msg="checked gnum-3 policy-4294967295, ret-no-match, act-drop" 2023-06-23 10:43:28 id=20085 trace_id=360 func=__iprope_check_one_policy line=1753 msg="checked gnum-3 policy-4294967295, ret-no-match, act-drop" 2023-06-23 10:43:28 id=20085 trace_id=360 func=__iprope_check_one_policy line=1753 msg="checked gnum-3 policy-4294967295, ret-no-match, act-drop" 2023-06-23 10:43:28 id=20085 trace_id=360 func=__iprope_check_one_policy line=1753 msg="checked gnum-3 policy-4294967295, ret-no-match, act-drop" 2023-06-23 10:43:28 id=20085 trace_id=360 func=__iprope_check_one_policy line=1753 msg="checked gnum-3 policy-4294967295, ret-no-match, act-drop" 2023-06-23 10:43:28 id=20085 trace_id=360 func=__iprope_check_one_policy line=1753 msg="checked gnum-3 policy-4294967295, ret-no-match, act-drop" 2023-06-23 10:43:28 id=20085 trace_id=360 func=__iprope_check_one_policy line=1753 msg="checked gnum-3 policy-4294967295, ret-matched, act-drop" 2023-06-23 10:43:28 id=20085 trace_id=360 func=__iprope_check_one_policy line=1966 msg="policy-4294967295 is matched, act-drop" 2023-06-23 10:43:28 id=20085 trace_id=360 func=__iprope_check line=2014 msg="gnum-3 check result: ret-matched, act-drop, flag-00100020, flag2-00000000" 2023-06-23 10:43:28 id=20085 trace_id=360 func=iprope_policy_group_check line=4339 msg="after check: ret-matched, act-drop, flag-00100020, flag2-00000000" 2023-06-23 10:43:28 id=20085 trace_id=360 func=iprope_fwd_auth_check line=816 msg="iprope_auth_portal_check() result: ret-matched, act-drop" 2023-06-23 10:43:28 id=20085 trace_id=360 func=fw_forward_handler line=601 msg="Denied by forward policy check (policy 0)" VIP and policy were configured to allow the traffic, but the traffic was denied. The error explains that the captive portal is enabled on the interface, so it was trying to authenticate users but failing to do so.  config system interface     edit wan2 (wan2) # set security-mode none              No security option. captive-portal    Captive portal authentication (wan2) # get | grep security-mode security-mode : captive-portal     # set security-mode none end Another workaround to resolve this issue is to configure exemptions for the captive portal using the security-exempt-list feature (applied per interface) and add the source segment address to the exempt list to bypass the captive portal. Example debug flow output before configuring captive portal exemptions: FGT_600F# id=20085 trace_id=228 func=print_pkt_detail line=5940 msg="vd-root:0 received a packet(proto=1, 10.80.1.20:1536->10.50.4.5:2048) tun_id=0.0.0.0 from PORT_LAN. type=8, code=0, id=1536, seq=0." id=20085 trace_id=228 func=iprope_dnat_check line=5338 msg="in-[PORT_LAN], out-[]" <----- Route is evaluated. id=20085 trace_id=228 func=__vf_ip_route_input_rcu line=1999 msg="find a route: flag=00000000 gw-x.x.x.x via VPN_INTERFACE" <----- Finds the route through the VPN. id=20085 trace_id=228 func=__iprope_check_one_policy line=2031 msg="checked gnum-100004 policy-727, ret-matched, act-accept" <----- Partially match the policy 727 and accept the traffic. id=20085 trace_id=228 func=__iprope_check_one_policy line=2248 msg="policy-727 is matched, act-accept" id=20085 trace_id=228 func=iprope_fwd_auth_check line=838 msg="after iprope_captive_check(): is_captive-1, ret-matched, act-drop, idx-0" <----- Requests captive portal authentication. id=20085 trace_id=228 func=iprope_fwd_auth_check line=867 msg="iprope_auth_portal_check() result: ret-matched, act-drop" <----- FortiGate tried to authenticate the packet against a captive portal but gets dropped. id=20085 trace_id=228 func=fw_forward_handler line=726 msg="Denied by forward policy check (policy 0)" Example debug flow output after configuring captive portal exemptions: FGT_600F# id=20085 trace_id=238 func=print_pkt_detail line=5940 msg="vd-root:0 received a packet(proto=1, 10.80.1.20:2048->10.50.4.5:2048) tun_id=0.0.0.0 from PORT_LAN. type=8, code=0, id=2048, seq=0." id=20085 trace_id=238 func=iprope_dnat_check line=5338 msg="in-[PORT_LAN], out-[]" --> Route is evaluated id=20085 trace_id=238 func=__vf_ip_route_input_rcu line=1999 msg="find a route: flag=00000000 gw-x.x.x.x via VPN_INTERFACE" id=20085 trace_id=238 func=__iprope_check_one_policy line=2248 msg="policy-727 is matched, act-accept" --> Matching policy 727 id=20085 trace_id=238 func=iprope_fwd_auth_check line=838 msg="after iprope_captive_check(): is_captive-0, ret-matched, act-accept, idx-727" --> Skipped the captive portal authentication id=20085 trace_id=238 func=fw_forward_handler line=888 msg="Allowed by Policy-727:" --> Policy correctly allowed the traffic id=20085 trace_id=238 func=ipsecdev_hard_start_xmit line=662 msg="enter IPSec interface VPN_INTERFACE, tun_id=0.0.0.0" id=20085 trace_id=238 func=_do_ipsecdev_hard_start_xmit line=222 msg="output to IPSec tunnel VPN_INTERFACE" id=20085 trace_id=238 func=esp_output4 line=874 msg="IPsec encrypt/auth" id=20085 trace_id=238 func=ipsec_output_finish line=556 msg="send to y.y.y.y via intf-WAN" Related article: Technical Tip: How to configure exemptions for Captive Portal on the FortiGate (captive-portal-exemp...