Fortigate WAN DHCP problem

[Oluf]

Hi.

The "new" equipment from our local ISP delivers public IP's only by DHCP. We have a strange problem that keep happening from time to time. All of a sudden the Fortigate stops getting a new DHCP lease and we loose WAN connectivity.

Troubleshooting done by the ISP: Shutting the port which the Fortigate is connected to. Put the CPE in router mode with another subnet and dhcp scope and back to bridge mode again. Nothing helps.

The ISP says they get the dhcp request, sends the offer, but it looks like the Fortigate "closes its ears" and does not get the offer, from their point of view. When rebooting the Fortigate everything comes back up as normal. The strange thing is that when this first happens, it usually happens 2-3 times in a row when the lease expires, then it can work perfectly for months. This has so far happened on remote systems with companies that can not wait for me to get out there and debug on the Fortigate side, so we have just had to have some local people go over there and power cycle the Fortigate to get internet up and running again. So i have no debug info from the Fortigate.

So far this problem has shown itself on 60D, 90D and 300D. Firmware version 5.2.3, 5.2.4 and 5.2.5. I have googled the problem and have not found anyone that has this exact same problem. The release notes of said versions and those before/after does not include any known or resolved issues related to the Fortigate as a DHCP client.

The ISP says they have had a few other customers have this problem as well, and they also had Fortigates. Could this be some kind of bug between Fortigate and the DHCP server software the ISP is running?

This happened to a 90D today running 5.2.4, i will upgrade this one to 5.2.7 and see if that makes any difference. In the meantime, does anyone have any idea what could be causing this? I know debug data from the Fortigate would help a lot but unfortunately i have none at this time.

[rfolkers]

I'm not sure if anyone willl notice this post, but 'here goes nothing.

We just put a Fortigate in place at a branch office of one of our clients.

setup is like this:

<ISP>-----fiber-----<Ethernet NTU>-----<Fortigate WAN IF on VLAN 128>

I get an IP by DHCP.

At first everything was alright, until the first DHCP lease would expire. Every attempt to renew the IP fails and the only solutions is removing the VLAN interface and to recreate it.

So only the first DHCP request succeeds, every next request fails. Those requests and offers look like this look like this:

2016-12-15 12:53:09 timer 0x28a9a20 expired, take action 2016-12-15 12:53:09 Sending request! 2016-12-15 12:53:09 Send a packet out. 2016-12-15 12:53:09 add hw header 2016-12-15 12:53:09 set dst hw addr as: FF:FF:FF:FF:FF:FF 2016-12-15 12:53:09 src hw addr: 90:6C:AC:38:1E:19 2016-12-15 12:53:09 add ip udp header 2016-12-15 12:53:09 dhcpcd_send_packet,270:result:590, ifinde:15 2016-12-15 12:53:09 unregister timer:0x28a9a20 2016-12-15 12:53:09 register timer func=0x23ad58 arg=0x28a9b60 name=send_request -> send_request 2016-12-15 12:53:09 Allocate a new timer 2016-12-15 12:53:09 Registered timer 0x28a8c58 will expiry in 8 secs 2016-12-15 12:53:09 timer 0x28a8c58(send_request -> send_request) will expire in 8 secs 2016-12-15 12:53:09 fd 15 can be read now 2016-12-15 12:53:09 ###############3Receive packet: len=342 2016-12-15 12:53:09 del hw header 2016-12-15 12:53:09 ether_type:0800 2016-12-15 12:53:09 hw addr from: F4:B5:2F:78:4C:01 2016-12-15 12:53:09 del ip udp header 2016-12-15 12:53:09 final dhcp message len:300 2016-12-15 12:53:09 DHCP Message received. 2016-12-15 12:53:09 parse dhcp options 2016-12-15 12:53:09 parse dhcp option buffer (60 bytes) [size="2"]2016-12-15 12:53:09 option[53], len:1[/size] [size="2"]2016-12-15 12:53:09 option[54], len:4[/size] 2016-12-15 12:53:09 DHO_SUBNET_MASK option is missed 2016-12-15 12:53:09 DHO_BROADCAST_ADDRESS option is missed 2016-12-15 12:53:09 DHO_ROUTERS option is missed 2016-12-15 12:53:09 DHCPNAK received

I attached the entire log, file dhcp.log, a succesfull DHCP request is made at rule 6160, that was when i recreated the VLAN-interface. I also attached a PCAP with the data, requested by FTN support, with in the first 2 rule a succesful DHCP request and failed requests starting at rule 3.

To rule some things out I also tried the following:

 Place a switch in between my NTU and FGT, so the switch can add the VLAN tag, this didn't make any difference.

With the switch in between, requesting an IP on my notebook. Works like a charm, see attachment laptop1st.pac

To get the connection going, install a Draytek router, to do the DHCP-talking and put the FGT in the DMZ of the Draytek. Also works!

Bottom line is, that this seems to be some Fortigate DHCP issue, although Fortinet is pointing at my ISP and my ISP is pointing at Fortinet.

I reproduces the above on firmwares 5.2.10, 5.4.0, 5.4.2 on a 30D unit.

[rfolkers]

I'm not sure if anyone willl notice this post, but 'here goes nothing.

We just put a Fortigate in place at a branch office of one of our clients.

setup is like this:

<ISP>-----fiber-----<Ethernet NTU>-----<Fortigate WAN IF on VLAN 128>

I get an IP by DHCP.

At first everything was alright, until the first DHCP lease would expire. Every attempt to renew the IP fails and the only solutions is removing the VLAN interface and to recreate it.

So only the first DHCP request succeeds, every next request fails. Those requests and offers look like this look like this:

2016-12-15 12:53:09 timer 0x28a9a20 expired, take action 2016-12-15 12:53:09 Sending request! 2016-12-15 12:53:09 Send a packet out. 2016-12-15 12:53:09 add hw header 2016-12-15 12:53:09 set dst hw addr as: FF:FF:FF:FF:FF:FF 2016-12-15 12:53:09 src hw addr: 90:6C:AC:38:1E:19 2016-12-15 12:53:09 add ip udp header 2016-12-15 12:53:09 dhcpcd_send_packet,270:result:590, ifinde:15 2016-12-15 12:53:09 unregister timer:0x28a9a20 2016-12-15 12:53:09 register timer func=0x23ad58 arg=0x28a9b60 name=send_request -> send_request 2016-12-15 12:53:09 Allocate a new timer 2016-12-15 12:53:09 Registered timer 0x28a8c58 will expiry in 8 secs 2016-12-15 12:53:09 timer 0x28a8c58(send_request -> send_request) will expire in 8 secs 2016-12-15 12:53:09 fd 15 can be read now 2016-12-15 12:53:09 ###############3Receive packet: len=342 2016-12-15 12:53:09 del hw header 2016-12-15 12:53:09 ether_type:0800 2016-12-15 12:53:09 hw addr from: F4:B5:2F:78:4C:01 2016-12-15 12:53:09 del ip udp header 2016-12-15 12:53:09 final dhcp message len:300 2016-12-15 12:53:09 DHCP Message received. 2016-12-15 12:53:09 parse dhcp options 2016-12-15 12:53:09 parse dhcp option buffer (60 bytes) [size="2"]2016-12-15 12:53:09 option[53], len:1[/size] [size="2"]2016-12-15 12:53:09 option[54], len:4[/size] 2016-12-15 12:53:09 DHO_SUBNET_MASK option is missed 2016-12-15 12:53:09 DHO_BROADCAST_ADDRESS option is missed 2016-12-15 12:53:09 DHO_ROUTERS option is missed 2016-12-15 12:53:09 DHCPNAK received

I attached the entire log, file dhcp.log, a succesfull DHCP request is made at rule 6160, that was when i recreated the VLAN-interface. I also attached a PCAP with the data, requested by FTN support, with in the first 2 rule a succesful DHCP request and failed requests starting at rule 3.

To rule some things out I also tried the following:

 Place a switch in between my NTU and FGT, so the switch can add the VLAN tag, this didn't make any difference.

With the switch in between, requesting an IP on my notebook. Works like a charm, see attachment laptop1st.pac

To get the connection going, install a Draytek router, to do the DHCP-talking and put the FGT in the DMZ of the Draytek. Also works!

Bottom line is, that this seems to be some Fortigate DHCP issue, although Fortinet is pointing at my ISP and my ISP is pointing at Fortinet.

I reproduces the above on firmwares 5.2.10, 5.4.0, 5.4.2 on a 30D unit.

I cannot attach the Pcap's and logs to this post, so these files are available on my Onedrive 4 Business account, at

https://synlogicict-my.sharepoint.com/personal/rfolkers_synlogic_nl/_layouts/15/guestaccess.aspx?fol...

[fquiroga]

Hi, 

I've got the same issue and behavior,  with a Fortigate 60 E, FortiOS v5.6.1 build1484 (GA). 

Could anyone tell me how to debug the DHCP in my wan interface ? 

Thanks.

[Oluf]

Here is the command i have used:

diagnose debug application dhcpc 255

diagnose debug enable

The only bug i have seen in 5.4.x is if the service router of the ISP crashed or changes mac address. In this scenario there is a l2 over l3 connection between the fortigate and the ISP's service router (to the fortigate it looks like there is a l2 connection directly to the SR). The ISP had some problems with the SR a while back causing it to reboot from time to time, this caused the dhcpc service on the fortigate to loop on an endless dhcp discover/request and no new lease was achieved. Looks like the fortigate refuses the offers it gets. It looks to me like the fortigate does not do the realese sequence properly, because if i force a release manually it comes up again.

I have yet to try 5.6.1 on a fortigate with dhcp client on the wan interface.

[fquiroga]

Thanks Oluf, 

These are the output to the command: 

Sending discover!

Send a packet out.

add hw header

set dst hw addr as: FF:FF:FF:FF:FF:FF

src hw addr: 90:6C:AC:BC:7B:82

add ip udp header

dhcpcd_send_packet,265:result:590, ifinde:7

unregister timer:0x49c6cf8

register timer func=0x185b09 arg=0x49c28f0 name=send_discover -> send_discover

Allocate a new timer

Registered timer 0x49c6bf8 will expiry in 18 secs

timer 0x49c6bf8(send_discover -> send_discover) will expire in 18 secs

timer 0x49c6bf8(send_discover -> send_discover) will expire in 17 secs

timer 0x49c6bf8(send_discover -> send_discover) will expire in 16 secs

timer 0x49c6bf8(send_discover -> send_discover) will expire in 15 secs

timer 0x49c6bf8(send_discover -> send_discover) will expire in 14 secs

timer 0x49c6bf8(send_discover -> send_discover) will expire in 13 secs

timer 0x49c6bf8(send_discover -> send_discover) will expire in 12 secs

timer 0x49c6bf8(send_discover -> send_discover) will expire in 11 secs

timer 0x49c6bf8(send_discover -> send_discover) will expire in 10 secs

timer 0x49c6bf8(send_discover -> send_discover) will expire in 9 secs

timer 0x49c6bf8(send_discover -> send_discover) will expire in 8 secs

timer 0x49c6bf8(send_discover -> send_discover) will expire in 7 secs

timer 0x49c6bf8(send_discover -> send_discover) will expire in 6 secs

timer 0x49c6bf8(send_discover -> send_discover) will expire in 5 secs

timer 0x49c6bf8(send_discover -> send_discover) will expire in 4 secs

timer 0x49c6bf8(send_discover -> send_discover) will expire in 3 secs

timer 0x49c6bf8(send_discover -> send_discover) will expire in 2 secs

timer 0x49c6bf8(send_discover -> send_discover) will expire in 1 secs

timer 0x49c6bf8 expired, take action

Sending discover!

Send a packet out.

add hw header

set dst hw addr as: FF:FF:FF:FF:FF:FF

src hw addr: 90:6C:AC:BC:7B:82

add ip udp header

dhcpcd_send_packet,265:result:590, ifinde:7

unregister timer:0x49c6bf8

register timer func=0x185b09 arg=0x49c28f0 name=send_discover -> send_discover

Allocate a new timer

Registered timer 0x49c6c90 will expiry in 12 secs

timer 0x49c36b8(state_panic -> state_init) will expire in 1 secs

timer 0x49c36b8 expired, take action

state init.

make discover

make dhcp message, code=1

Insert option(255), len(0)

Insert option(53), len(1)

Insert max message len (1458)

Insert option(57), len(2)

Insert client ID

Insert option(61), len(7)

Insert requested options

Insert option(55), len(9)

Insert hostname

Insert option(12), len(12)

Insert class ID option

Insert option(60), len(13)

get_dhcp_msg_len, 293

too small, extend to 548

Sending discover!

Send a packet out.

add hw header

set dst hw addr as: FF:FF:FF:FF:FF:FF

src hw addr: 90:6C:AC:BC:7B:89

add ip udp header

dhcpcd_send_packet,265:result:590, ifinde:14

unregister timer:0x49c36b8

register timer func=0x185b09 arg=0x49c3808 name=send_discover -> send_discover

Allocate a new timer

Registered timer 0x49c6bf8 will expiry in 3 secs

timer 0x49c6bf8(send_discover -> send_discover) will expire in 3 secs

timer 0x49c6bf8(send_discover -> send_discover) will expire in 2 secs

timer 0x49c6bf8(send_discover -> send_discover) will expire in 1 secs

timer 0x49c6bf8 expired, take action

Sending discover!

Send a packet out.

add hw header

set dst hw addr as: FF:FF:FF:FF:FF:FF

src hw addr: 90:6C:AC:BC:7B:89

add ip udp header

dhcpcd_send_packet,265:result:590, ifinde:14

unregister timer:0x49c6bf8

register timer func=0x185b09 arg=0x49c3808 name=send_discover -> send_discover

Allocate a new timer

Registered timer 0x49c36b8 will expiry in 4 secs

timer 0x49c36b8(send_discover -> send_discover) will expire in 4 secs

timer 0x49c36b8(send_discover -> send_discover) will expire in 3 secs

timer 0x49c36b8(send_discover -> send_discover) will expire in 2 secs

timer 0x49c36b8(send_discover -> send_discover) will expire in 1 secs

timer 0x49c36b8 expired, take action

Sending discover!

Send a packet out.

add hw header

set dst hw addr as: FF:FF:FF:FF:FF:FF

src hw addr: 90:6C:AC:BC:7B:89

add ip udp header

dhcpcd_send_packet,265:result:590, ifinde:14

unregister timer:0x49c36b8

register timer func=0x185b09 arg=0x49c3808 name=send_discover -> send_discover

Allocate a new timer

Registered timer 0x49c6bf8 will expiry in 11 secs

timer 0x49c6c90(send_discover -> send_discover) will expire in 4 secs

timer 0x49c6c90(send_discover -> send_discover) will expire in 3 secs

timer 0x49c6c90(send_discover -> send_discover) will expire in 2 secs

timer 0x49c6c90(send_discover -> send_discover) will expire in 1 secs

timer 0x49c6c90 expired, take action

Sending discover!

Send a packet out.

add hw header

set dst hw addr as: FF:FF:FF:FF:FF:FF

src hw addr: 90:6C:AC:BC:7B:82

add ip udp header

dhcpcd_send_packet,265:result:590, ifinde:7

unregister timer:0x49c6c90

register timer func=0x185b09 arg=0x49c28f0 name=send_discover -> send_discover

Allocate a new timer

Registered timer 0x49c36b8 will expiry in 15 secs

timer 0x49c6bf8(send_discover -> send_discover) will expire in 7 secs

timer 0x49c6bf8(send_discover -> send_discover) will expire in 6 secs

timer 0x49c6bf8(send_discover -> send_discover) will expire in 5 secs

timer 0x49c6bf8(send_discover -> send_discover) will expire in 4 secs

timer 0x49c6bf8(send_discover -> send_discover) will expire in 3 secs

timer 0x49c6bf8(send_discover -> send_discover) will expire in 2 secs

timer 0x49c6bf8(send_discover -> send_discover) will expire in 1 secs

timer 0x49c6bf8 expired, take action

Sending discover!

Send a packet out.

add hw header

set dst hw addr as: FF:FF:FF:FF:FF:FF

src hw addr: 90:6C:AC:BC:7B:89

add ip udp header

dhcpcd_send_packet,265:result:590, ifinde:14

unregister timer:0x49c6bf8

register timer func=0x185b09 arg=0x49c3808 name=send_discover -> send_discover

Allocate a new timer

Registered timer 0x49c6c90 will expiry in 15 secs

timer 0x49c36b8(send_discover -> send_discover) will expire in 8 secs

timer 0x49c36b8(send_discover -> send_discover) will expire in 7 secs

timer 0x49c36b8(send_discover -> send_discover) will expire in 6 secs

timer 0x49c36b8(send_discover -> send_discover) will expire in 5 secs

timer 0x49c36b8(send_discover -> send_discover) will expire in 4 secs

timer 0x49c36b8(send_discover -> send_discover) will expire in 3 secs

timer 0x49c36b8(send_discover -> send_discover) will expire in 2 secs

timer 0x49c36b8(send_discover -> send_discover) will expire in 1 secs

timer 0x49c36b8 expired, take action

These problems appears after ugrade to v5.6.1 build1484 (GA). 

I'm going to write a ticket and then post the reply from Fortigate. 

Regards.

[Oluf]

Looks pretty much like my debug, but in my case i get a reply on the discover and it it loops on sending requests instead. Are you not able to get a ip adress at all or does this only happen in certain situations?

[lhou_FTNT]

Oluf, there is a DHCP improvement in FOS v5.6.1 and v5.4.6, which will make FG send out DHCP request whenever there is a interface flipping. In previous version, FG only send out DHCP request when the interface was down for 3 or more seconds, or at T1 expiry. We recently found the Comcast use the abnormal tech to renew DHCP. Comcast side reboot the modem or force interface down/up, and expect a DHCP request at that moment. Your case may be similar. Could you take a look at your system event logs if there are several interface up/down events every 1 or 2 days?

[bommi]

Do you have any information regarding the releasedate of 5.4.6?

[lhou_FTNT]

v5.4.6 GA should be by the end of Sept 2017. You can try interim image after build 1145 if you can access engineering image server.

[Oluf]

I don't have any interface up/down in the event log.