Technical Tip: How to Interpret FortiGate debug flow output and send to IPS log in the flow trace

[amrit]

Description	This article explains interface selection logs in the debug flow and the 'send to ips' logs received in debug output.
Scope	FortiGate.
Solution	When FortiGate receives a packet, it performs a routing lookup on the first packet from the source and on the first reply packet. To understand the routing process, see Technical Tip: FortiGate Route-Lookup Process  Example: Below is an output of a TCP Session in the original direction: FGT # id=65308 trace_id=571 func=print_pkt_detail line=5942 msg="vd-root:0 received a packet(proto=6, 192.168.20.2:63611->63.137.229.1:443) tun_id=0.0.0.0 from port6. flag [S], seq 3839416144, ack 0, win 64240" id=65308 trace_id=571 func=init_ip_session_common line=6127 msg="allocate a new session-015a96aa" id=65308 trace_id=571 func=__vf_ip_route_input_rcu line=1988 msg="find a route: flag=00000000 gw-10.9.15.254 via port1" id=65308 trace_id=571 func=__iprope_tree_check line=524 msg="gnum-100004, use int hash, slot=67, len=2" id=65308 trace_id=571 func=get_new_addr line=1274 msg="find SNAT: IP-10.9.10.51(from IPPOOL), port-63611" id=65308 trace_id=571 func=fw_forward_handler line=997 msg="Allowed by Policy-22: SNAT" id=65308 trace_id=571 func=ip_session_confirm_final line=3141 msg="npu_state=0x1100, hook=4" id=65308 trace_id=571 func=ids_receive line=466 msg="send to ips" id=65308 trace_id=571 func=__ip_session_run_tuple line=3474 msg="SNAT 192.168.20.2->10.9.10.51:63611" The packet above is a TCP SYN packet which can be identified with the flag [S]. Since it is the first packet for this stream, FortiGate performed a route lookup and identified that the packet should be routed via port1. A session table entry has been created, which can be verified using the commands mentioned in the article Session Table Information. After SNAT is complete on this session a 'send to ips' log is received.  If one or more UTM profiles are enabled in the policy, the log 'send to ips' will be displayed and it will indicate that UTM inspection is being performed. Reply Direction: id=65308 trace_id=574 func=print_pkt_detail line=5942 msg="vd-root:0 received a packet(proto=6, 63.137.229.1:443->10.9.10.51:63611) tun_id=0.0.0.0 from port1. flag [S.], seq 107956612, ack 3839416145, win 65535" id=65308 trace_id=574 func=resolve_ip_tuple_fast line=6030 msg="Find an existing session, id-015a96aa, reply direction" id=65308 trace_id=574 func=__ip_session_run_tuple line=3487 msg="DNAT 10.9.10.51:63611->192.168.20.2:63611" id=65308 trace_id=574 func=__vf_ip_route_input_rcu line=1988 msg="find a route: flag=00000000 gw-0.0.0.0 via port6" id=65308 trace_id=574 func=npu_handle_session44 line=1355 msg="Trying to offloading session from port1 to port6, skb.npu_flag=00000400 ses.state=00002204 ses.npu_state=0x00001108" id=65308 trace_id=574 func=fw_forward_dirty_handler line=443 msg="state=00002204, state2=00000001, npu_state=00001108" id=65308 trace_id=574 func=ids_receive line=466 msg="send to ips" Flag [S.] indicate the TCP SYN ACK packet. Since this is the first reply packet FortiGate also performed a route lookup for this to get the outgoing interface and also found an existing session. Subsequent Packets : id=65308 trace_id=576 func=print_pkt_detail line=5942 msg="vd-root:0 received a packet(proto=6, 192.168.20.2:63611->63.137.229.1:443) tun_id=0.0.0.0 from port6. flag [.], seq 3839416145, ack 107956613, win 1026" id=65308 trace_id=576 func=resolve_ip_tuple_fast line=6030 msg="Find an existing session, id-015a96aa, original direction" id=65308 trace_id=576 func=npu_handle_session44 line=1355 msg="Trying to offloading session from port6 to port1, skb.npu_flag=00000400 ses.state=00002204 ses.npu_state=0x00001108" id=65308 trace_id=576 func=fw_forward_dirty_handler line=443 msg="state=00002204, state2=00000001, npu_state=00001108" id=65308 trace_id=576 func=ids_receive line=466 msg="send to ips" id=65308 trace_id=585 func=print_pkt_detail line=5942 msg="vd-root:0 received a packet(proto=6, 63.137.229.1:443->10.9.10.51:63611) tun_id=0.0.0.0 from port1. flag [.], seq 107956613, ack 3839417971, win 2231" id=65308 trace_id=585 func=resolve_ip_tuple_fast line=6030 msg="Find an existing session, id-015a96aa, reply direction" id=65308 trace_id=585 func=ipv4_fast_cb line=53 msg="enter fast path" id=65308 trace_id=585 func=ip_session_run_all_tuple line=7257 msg="DNAT 10.9.10.51:63611->192.168.20.2:63611" Once the TCP handshake is complete, subsequent packets within the same TCP flow do not need to undergo repeated parameter checks unless there are changes in routing, SNAT, DNAT, address, or policy etc. Essentially, the session table stores the routing information, and the remaining traffic in the flow references this table for processing. As a result, TCP handhsake packets always follow the full processing path. However,  subsequent packets are handled differently as they leverage the session table for faster forwarding, which is the expected behavior. So, if a session ends with 'send to ips' logs in the debug flow, it does not indicate a packet drop. Related document: Packet flow ingress and egress - FortiGate documentation