Troubleshooting Tip: Traffic matches the wrong Proxy policy

[pareenat]

Description

This article describes steps to troubleshoot when traffic matches the wrong Proxy policy (applied on both explicit and transparent Proxy).

Scope

FortiProxy/FortiGate.

Solution

A wrong traffic matching normally will be noticed under the traffic log. Verify more details of the Web proxy policy lookup process.

The sample proxy policy that was wrongly matched has a source IP setting to 10.1.1.1/32 on policy id 1, however from the log, it is noticeable that source IP 172.1.1.1 matches this policy:

date="2001-01-01" time="01:01:01" id=7280056209095263907 bid=7537396 dvid=1048 itime=1695020173 euid=1 epid=1 dsteuid=1 dstepid=1 logid="0010000099" type="traffic" subtype="http-transaction" level="notice" eventtime=1695020173951620540 srcip="172.1.1.1" srcport=57222 dstip="2.2.2.2" dstport=443 policyid=1 sessionid=1728486804 duration=5 sentbyte=123 rcvdbyte=0 appcat="unscanned" utmaction="allow" countweb=1 hostname="1.abc.com" url="https://1.abc.com/" scheme="https" reqlength=123 resplength=0 resptype="generated" reqtime=1695020173 resptime=0 respfinishtime=1695020173 tz="+0700" devid="FPX1" vd="root" devname="FPX1"

config firewall policy
    edit 1
        set type explicit-web
        set dstintf "port7"
        set srcaddr "addr-10.1.1.1"
        set dstaddr "all"
        set action accept
        set schedule "always"
        set service "webproxy"
        set explicit-web-proxy "web-proxy"
        set utm-status enable
        set logtraffic all
    next
        config firewall address
            edit "addr-10.1.1.1"
                set subnet 10.1.1.1 255.255.255.255
            next

It is necessary to collect the WAD debug on HTTP and policy category:

diagnose wad debug enable category http
diagnose wad debug enable category policy
diagnose wad debug enable level info
diagnose debug enable

Note: Apply the below command to stop the WAD debug:

diagnose wad debug disable category http
diagnose wad debug disable category policy

Sample WAD debug:

[I]2001-01-01 01:01:01.282586 [p:26905][s:850013118][r:745327669] wad_dump_http_request :2698 hreq=0x7f6ebfe005a8 Received request from client: 172.1.1.1:55221
CONNECT http://1.abc.com:443 HTTP/1.1

Host: http://1.abc.com:443

Proxy-Connection: keep-alive

User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/117.0.0.0 Safari/537.36 Edg/117.0.2045.31
[I]2001-01-01 01:01:01.282623 [p:26905][s:850013118][r:745327669] wad_http_str_canonicalize :2188 enc=0 path=/ len=1 changes=0
[I]2001-01-01 01:01:01.282630 [p:26905][s:850013118][r:745327669] wad_http_conn_req_classify :6044 no security profile HTTPS/HTTP, tport=443
[V]2001-01-01 01:01:01.282633 [p:26905][s:850013118][r:745327669] wad_url_match_find :141 Empty url-matcher!
[V]2001-01-01 01:01:01.282637 [p:26905][s:850013118][r:745327669] wad_http_req_check_dns :76 hn=0x7f6ebe3796d0 sn=(nil)
[I]2001-01-01 01:01:01.282641 [p:26905][s:850013118][r:745327669] wad_http_dns_resolve :7749 [0x7f6ebfe005a8] DNS request name=http://1.abc.com len=14 type/pref=0/0
[V]2001-01-01 01:01:01.282663 [p:26905][s:850013118][r:745327669] wad_http_msg_strm_pause :1007 strm paused, flag=0x2 is_clt=1
[V]2001-01-01 01:01:01.282668 [p:26905][s:850013118][r:745327669] wad_http_clt_read_sync :1952 hs=0x7f6ec1508688 pause=(1/0x2) ret=1 execute=wad_http_clt_read_req_line
[I]2001-01-01 01:01:01.298035 [p:26905][s:850013118][r:745327669] wad_http_dns_request_done :12360 [0x7f6ebfe005a8] DNS resolved: 2.2.2.2
[V]2001-01-01 01:01:01.298055 [p:26905][s:850013118][r:745327669] wad_http_msg_strm_resume :1030 strm resumed, execute=wad_http_clt_read_req_line is_clt=1
[V]2001-01-01 01:01:01.298104 [p:26905][s:850013118][r:745327669] wad_http_req_get_dst_intf :12068 vd=0 dst=2.2.2.2 ifidx=14
[V]2001-01-01 01:01:01.298110 [p:26905][s:850013118][r:745327669] wad_http_req_proc_dst :12280 HTTP req=0x7f6ebfe005a8 check destination/quarantine ret=0
[V]2001-01-01 01:01:01.298118 [p:26905][s:850013118][r:745327669] wad_http_req_check_policy :11905 start match policy vd=0(ses_ctx:x|Phx|M|Hh|C|A7|O) (172.1.1.1:55221@14->2.2.2.2:443@14) absUrl=1
[I]2001-01-01 01:01:01.298125 [p:26905][s:850013118][r:745327669] wad_fast_match_is_enable :3845 fast matching is enabled <<<<<<<<<<<<<
[V]2001-01-01 01:01:01.298130 [p:26905][s:850013118][r:745327669] wad_fast_match_get_addr :3555 Get key src:172.1.1.1 <<<<<<<<<<<<<
[V]2001-01-01 01:01:01.298136 [p:26905][s:850013118][r:745327669] wad_fast_match_get_addr :3555 Get key dst:2.2.2.2 <<<<<<<<<<<<<
[V]2001-01-01 01:01:01.298140 [p:26905][s:850013118][r:745327669] wad_fast_match_get_dst_intf :3585 Get key dst intf:8 <<<<<<<<<<<<<
[V]2001-01-01 01:01:01.298148 [p:26905][s:850013118][r:745327669] wad_fast_match_pol_array :3622 Try to maching pol:10, 0/159(pos/sz)
[I]2001-01-01 01:01:01.299095 [p:26905][s:850013118][r:745327669] wad_fast_match_pol_array :3652 fw_pol_id=1(pol_ctx:xhcf|Ad|7?|=p) pol_id=247(pflag:Hf|W|U|A) asyn_info=1
[V]2001-01-01 01:01:01.299117 [p:26905][s:850013118][r:745327669] wad_fw_policy_set_check_id :6273 pol_id=1 dev_cked=0
[I]2001-01-01 01:01:01.299121 [p:26905][s:850013118][r:745327669] wad_fw_policy_async_match :6407 pol_ctx:xhcf|Ad|7?|=d
[I]2001-01-01 01:01:01.299128 [p:26905][s:850013118][r:745327669] wad_http_req_policy_set :10293 match policy-id=1(pol_ctx:xhcf|Ad|7?|=d) vd=0(ses_ctx:x|Phx|Mde|Hh|C|A7|O) (172.1.1.1:55221@14 -> 2.2.2.2:443@14) <--

From the WAD debug result, it is possible to see that the Proxy policy matching has been handled by fast-policy-match. 

When fast policy matching is enabled, the FortiProxy/FortiGate will build a fast searching table based on the different proxy policy matching criteria.

When fast policy matching is disabled, web proxy traffic is compared to the policies one at a time from the beginning of the policy list.

Fast policy matching is enabled by default, and can be configured with the following CLI command:

config web-proxy global
    set fast-policy-match {enable | disable}
end

Since the wrong policy match is based on a fast searching table, it should collect details of the current fast searching table on WAD algo and WAD worker that handles this traffic (from the WAD debug the WAD worker that handles this test traffic has pid=26905).  Then check the worker ID from PID by command:

diagnose debug enable

diagnose test application wad 1000

Use the following command to list out fast searching table on WAD algo and WAD worker:

diagnose debug enable
diagnose test application wad 220x --> x represents WAD worker id.
diagnose test application wad 156
diagnose test application wad 101
diagnose test application wad 2300
diagnose test application wad 156
diagnose test application wad 101

Then try to isolate the root cause by disabling the fast-policy-match feature. If the match turns correctly, then keep the disable fast-policy-match as a workaround while reporting symptoms to the Fortinet Support team https://support.fortinet.com/.

Informations that the support team will request would be:

1. Config File.
2. TAC report: diagnose debug report.
3. Traffic log and wad debug that prove the wrong policy matching.
4. Fast searching table during symptoms still persists.
5. Eventlog system/router/HA cover period before symptom surface still time of disable fast-policy-match.