Fortinet Fortigate troubleshooting traffic flows

When we’re trying to figure out why a particular traffic flow is not working, we’d first check the logs on Fortianalyzer or locally in our Fortigate; sometimes this process will work just fine, but other times we’ll see something like “denied by policy id X” – being X the implicit/explicit deny any rule at the bottom of the policy.

For those situations, we can leverage the following commands in order to get a more meaningful output as to why that traffic is being denied.

Bear in mind that there is some data plane traffic that is off-loaded to the Fortinet ASIC’s NP$s (for example NP4) so you may not be able to see it after running some of those commands. If that’s the case, you’ll need to turn off hardware acceleration for a moment so that all traffic is punted to the CPU – be careful as this can be very CPU intensive.

Diagnose debug flow

This is the first command and probably the most powerful,  it allows us to debug the traffic that is passing through our Fortigate.

This command is as powerful as dangerous, without any filtering we could create so much CPU load that the device will become unusable.

We can filter the flow we’re after based on the below:

FortiGate-VM64 # diagnose debug flow filter 
clear     Clear filter.
vd        Index of virtual domain.
proto     Protocol number.
addr      IP address.
saddr     Source IP address.
daddr     Destination IP address.
port      port
sport     Source port.
dport     Destination port.
negate    Inverse filter.

Useful protocol numbers:

  • Protocol number 1: ICMP
  • Protocol number 6: TCP
  • Protocol number 17: UDP

You can find the full list here.

I’d recommend limiting the number of packets so that even if the filter catches too many, we’ll never capture more packets than a fixed predefined amount. For this matter, we can use:

FortiGate-VM64 # diagnose debug flow trace start 
    Repeat number.

A good practice will also be to check if there is any debug running and if so, reset it.

FortiGate-VM64 # diagnose debug info 
debug output:           enable
console timestamp:      disable
console no user log message:    disable
zebos debug level:      306783954 (0x124926d2)
CLI debug level:        3

FortiGate-VM64 # diagnose debug reset 

FortiGate-VM64 # diagnose debug info 
debug output:           disable
console timestamp:      disable
console no user log message:    disable
CLI debug level:        3

Finally, if we want the output of the debug to be shown on a console session:

FortiGate-VM64 # diagnose debug flow show console 
enable     Show on console.
disable    Enable/disable show on console.

Once we put all the pieces together, we have this:

FortiGate-VM64 # diagnose debug reset 

FortiGate-VM64 # diagnose debug flow filter addr 172.16.15.1

FortiGate-VM64 # diagnose debug flow show console
show trace messages on console

FortiGate-VM64 # diagnose debug enable
FortiGate-VM64 # diagnose debug flow trace start 5

And this is the output we’ll get:

FortiGate-VM64 # id=20085 trace_id=154 func=print_pkt_detail line=4484 msg="vd-root received a packet(proto=6, 172.16.155.11:22->172.16.155.1:64308) from local. flag [.], seq 2479512906, ack 2875087907, win 9600"
id=20085 trace_id=154 func=resolve_ip_tuple_fast line=4545 msg="Find an existing session, id-00029856, reply direction"
id=20085 trace_id=155 func=print_pkt_detail line=4484 msg="vd-root received a packet(proto=6, 172.16.155.11:22->172.16.155.1:64308) from local. flag [.], seq 2479512958, ack 2875087907, win 9600"
id=20085 trace_id=155 func=resolve_ip_tuple_fast line=4545 msg="Find an existing session, id-00029856, reply direction"
id=20085 trace_id=156 func=print_pkt_detail line=4484 msg="vd-root received a packet(proto=6, 172.16.155.1:64308->172.16.155.11:22) from port1. flag [.], seq 2875087907, ack 2479512958, win 4094"
id=20085 trace_id=156 func=resolve_ip_tuple_fast line=4545 msg="Find an existing session, id-00029856, original direction"
id=20085 trace_id=157 func=print_pkt_detail line=4484 msg="vd-root received a packet(proto=6, 172.16.155.1:64308->172.16.155.11:22) from port1. flag [.], seq 2875087907, ack 2479513026, win 4093"
id=20085 trace_id=157 func=resolve_ip_tuple_fast line=4545 msg="Find an existing session, id-00029856, original direction"
id=20085 trace_id=158 func=print_pkt_detail line=4484 msg="vd-root received a packet(proto=6, 172.16.155.11:22->172.16.155.1:64308) from local. flag [.], seq 2479513026, ack 2875087907, win 9600"
id=20085 trace_id=158 func=resolve_ip_tuple_fast line=4545 msg="Find an existing session, id-00029856, reply direction"

FortiGate-VM64 #

For the example above, the TCP flags are a bit cryptic, the meanings are:

[.] = Ack set

[S] = Syn set
[S.] = Syn set, Ack Set

[F] = Fin set
[F.] = Fin set, Ack Set

[R] = Reset set
[R.] = Reset set , Ack Set

 

Diagnose sys session

This command comes in handy when we want to check the session table in our firewall.

As there will most likely be many sessions running, it’s recommended to narrow down the specific flow we’re after by leveraging one or more of the following filters:

FortiGate-VM64 # diagnose sys session filter 
vd             Index of virtual domain. -1 matches all.
sintf          Source interface.
dintf          Destination interface.
src            Source IP address.
nsrc           NAT'd source ip address
dst            Destination IP address.
proto          Protocol number.
sport          Source port.
nport          NAT'd source port
dport          Destination port.
policy         Policy ID.
expire         expire
duration       duration
proto-state    Protocol state.
clear          Clear session filter.
negate         Inverse filter.

One of the many use cases of looking at the session table may be that you want to quickly know if there is two-way communication for a particular traffic flow. This command will allow you to figure that out in (at least) two different ways.

1) Looking at the number of packets originated and the replies.

In the example below, we can determine that we have two-way communication since we’re sending and receiving packets.

FortiGate-VM64 # diagnose sys session list | grep statistic
statistic(bytes/packets/allow_err): org=168/2/1 reply=168/2/1 tuples=2

2) Looking at the protocol state code.

In the output below, we can find on the first line the protocol number and the protocol state. We know from the previous command that protocol number 6 is TCP, so we just need to figure out what protocol state 01 means.

FortiGate-VM64 # diagnose sys session list

session info: proto=6 proto_state=01 duration=8 expire=3599 timeout=3600 flags=00000000 sockflag=00000000 sockport=0 av_idx=0 use=3
origin-shaper=
reply-shaper=
per_ip_shaper=
ha_id=0 policy_dir=0 tunnel=/ vlan_cos=8/8
state=local may_dirty 
statistic(bytes/packets/allow_err): org=7410/90/1 reply=4518/36/1 tuples=2
orgin->sink: org pre->in, reply out->post dev=2->15/15->2 gwy=172.16.155.11/0.0.0.0
hook=pre dir=org act=noop 172.16.155.1:52712->172.16.155.11:22(0.0.0.0:0)
hook=post dir=reply act=noop 172.16.155.11:22->172.16.155.1:52712(0.0.0.0:0)
pos/(before,after) 0/(0,0), 0/(0,0)
src_mac=00:50:56:c0:00:08
misc=0 policy_id=0 auth_info=0 chk_client_info=0 vd=0
serial=0002dea7 tos=ff/ff ips_view=0 app_list=0 app=0
dd_type=0 dd_mode=0
total session 1

Protocol states are tied to the protocol being used, for TCP, UDP and ICMP the meanings are as follows:

TCP:

State
Value
Expire Timer (default)
NONE
00
10 s
ESTABLISHED
01
3600 s
SYN_SENT
02
120 s
SYN & SYN/ACK
03
60 s
FIN_WAIT
04
120 s
TIME_WAIT
05
120 s
CLOSE
06
10 s
CLOSE_WAIT
07
120 s
LAST_ACK
08
30 s
LISTEN
09
120 s

UDP:

State Value
UDP Reply not seen 00
UDP Reply seen 01

ICMP:

There are no states for ICMP, it always shows proto_state=00.

Naturally, from those tables, we can extract the status of a flow, things like whether the TCP three-way-handshake has been established, or if a UDP packet reply has been seen. Unfortunately, for ICMP we need to stick to the first method of counting return packets as the protocol state is always the same.

We can also see the session duration, as well as the expire time (all in seconds) of a session:

FortiGate-VM64 # diagnose sys session list | grep expire
session info: proto=1 proto_state=00 duration=2 expire=57 timeout=0 flags=00000000 sockflag=00000000 sockport=0 av_idx=0 use=3

Another great use case of this command is understanding if we’re NATing as expected – it could happen that we’re NATing behind the IP address of one of our Fortigate’s interfaces when we’re expecting to NAT behind an “ippool”.

We can see in red the action (SNAT), and the SNAT’d IP address:

FortiGate-VM64 # diagnose sys session filter dst 172.16.155.254

FortiGate-VM64 # diagnose sys session list

session info: proto=1 proto_state=00 duration=7 expire=54 timeout=0 flags=00000000 sockflag=00000000 sockport=0 av_idx=0 use=3
origin-shaper=
reply-shaper=
per_ip_shaper=
ha_id=0 policy_dir=0 tunnel=/ vlan_cos=0/255
state=may_dirty 
statistic(bytes/packets/allow_err): org=252/3/1 reply=0/0/0 tuples=2
orgin->sink: org pre->post, reply pre->post dev=2->2/2->2 gwy=172.16.155.254/0.0.0.0
hook=post dir=org act=snat 172.16.155.1:18246->172.16.155.254:8(172.16.155.11:62464)
hook=pre dir=reply act=dnat 172.16.155.254:62464->172.16.155.11:0(172.16.155.1:18246)
src_mac=00:50:56:c0:00:08
misc=0 policy_id=2 auth_info=0 chk_client_info=0 vd=0
serial=00033e69 tos=ff/ff ips_view=0 app_list=0 app=0
dd_type=0 dd_mode=0
total session 1

Note: When running a physical Fortigate, we’ll see an extra couple of lines per session. These have to do with NPU offloading – you’ll either see and npu info line with some flags regarding what’s being offloaded or “npu_state=00000000” which means that the session is not hardware processed (traffic originated by the firewall itself won’t be offloaded).

Finally, there are a couple of extra commands that can be very useful when we want to get a quick overview of the currently active sessions:

FortiGate-VM64 # get system session stat
The total number of sessions for the current VDOM: 3

FortiGate-VM64 # get system session list
PROTO   EXPIRE SOURCE           SOURCE-NAT       DESTINATION      DESTINATION-NAT 
icmp    47     172.16.155.1:13894 172.16.155.11:62464 172.16.155.254:8 -               
icmp    50     172.16.155.1:14150 -                172.16.155.11:8  -               
tcp     3599   172.16.155.1:64973 -                172.16.155.11:22 -


As can be seen above, the latter command also shows us NAT information.

Diagnose sniffer packet

This is equivalent to running tcpdump, there are multiple filters and verbose modes that can be used, I’ve put the more interesting ones below.

Command syntax:

diagnose sniffer packet  <interface> <“filter”> <verbose mode><count> <time format>

Filters:

  • “src host X”
  • “dst host X”
  • “host X”
  • “src port Y”
  • “dst port Y”

X == IP address

Y == Port number

You can find the full list here

Verbose mode:

Value Meaning
1 print header of packets
2 print header and data from IP of packets
3 print header and data from Ethernet of packets
4 print header of packets with interface name
5 print header and data from IP of packets with interface name
6 print header and data from Ethernet of packets with interface name

The best options for quick troubleshooting would be number 4.

Time format:

  • “a” == UTC time
  • “l” == local time


Example:

FortiGate-VM64 # diagnose sniffer packet any "host 172.16.155.1 and host 172.16.155.254 and icmp" 4 2 a
interfaces=[any]
filters=[host 172.16.155.1 and host 172.16.155.254 and icmp]
2018-07-27 05:43:37.451965 port1 in 172.16.155.1 -> 172.16.155.254: icmp: echo request
2018-07-27 05:43:38.454017 port1 in 172.16.155.1 -> 172.16.155.254: icmp: echo request

Bonus: Enabling timestamps

Another useful thing to do is to enable timestamps in our debug outputs. This can be done as follows:

FortiGate-VM64 # diagnose debug console timestamp 
enable     Enable timestamp.
disable    Disable timestamp.

The above command will be applied to the output of any debug command.

FortiGate-VM64 # 2018-07-14 07:20:29 id=20085 trace_id=21 func=print_pkt_detail line=4484 msg="vd-root received a packet(proto=6, 172.16.155.11:22->172.16.155.1:62647) from local. flag [.], seq 172801126, ack 468995700, win 9600"
2018-07-14 07:20:29 id=20085 trace_id=21 func=resolve_ip_tuple_fast line=4545 msg="Find an existing session, id-000145a9, reply direction"
2018-07-14 07:20:29 id=20085 trace_id=22 func=print_pkt_detail line=4484 msg="vd-root received a packet(proto=6, 172.16.155.1:62647->172.16.155.11:22) from port1. flag [.], seq 468995700, ack 172801178, win 4094"
2018-07-14 07:20:29 id=20085 trace_id=22 func=resolve_ip_tuple_fast line=4545 msg="Find an existing session, id-000145a9, original direction"

 

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out /  Change )

Google photo

You are commenting using your Google account. Log Out /  Change )

Twitter picture

You are commenting using your Twitter account. Log Out /  Change )

Facebook photo

You are commenting using your Facebook account. Log Out /  Change )

Connecting to %s