The dhcpc process on Fortigate

Posted on June 6, 2012

0



Just a little bit zoom in a dhcp traffic, too see how it really works in the background. It is a memory Post of an old story at Cisco TAC:
I had a big problem with the DHCP Client on a PIX Firewall and at the end I managed to prove it that this was a Cisco Bug.
Okay, okay that was not me, that was my colleague but anyway I was the techlead ;-)

Now this is a Fortigate dhcp client and this is just a quick demonstation how easy to debug that application.

The DHCP operation is in RFC 2131 standard See this link for details: http://www.ietf.org/rfc/rfc2131.txt or the networksorcery page: http://www.networksorcery.com/enp/protocol/dhcp.htm
The RFC standard is about 40 Pages long, but now it is enoug to know the messages used to get an IP Address:

Message –  Usage

DHCPDISCOVER – Client broadcast to locate available servers.

DHCPOFFER – Server to client in response to DHCPDISCOVER with
offer of configuration parameters.

DHCPREQUEST – Client message to servers either (a) requesting
offered parameters from one server and implicitly
declining offers from all others, (b) confirming
correctness of previously allocated address after,
e.g., system reboot, or (c) extending the lease on a
particular network address.

DHCPACK – Server to client with configuration parameters,
including committed network address.

DHCPNAK – Server to client indicating client’s notion of network
address is incorrect (e.g., client has moved to new
subnet) or client’s lease as expired

DHCPDECLINE – Client to server indicating network address is already
in use.

DHCPRELEASE – Client to server relinquishing network address and
cancelling remaining lease.

DHCPINFORM – Client to server, asking only for local configuration
parameters; client already has externally configured
network address.

And the order of messages in time:

Client -> “Air” – DHCPDISCOVER
Server -> Client – DHCPOFFER
Client -> Server – DHCPREQUEST
Server -> Client – DHCPACK

Disconnect

Client -> Server – DHCPRELEASE

Lets see what do we see from that in the fortigate debugs. Configure an interface with dhcp and the debug for dhcpc.
In the fortigate documentations the timestamp is not mentioned enough where they wrote about debugging. We should use it all the time when we use the debug.

myfirewall # config system interface
myfirewall (interface) # edit "wan1"
myfirewall (wan1) # set mode dhcp
myfirewall (wan1) # end
myfirewall #
myfirewall # diagnose debug enable
myfirewall # diagnose debug console timestamp enable
myfirewall # diagnose debug application dhcpc 190
myfirewall # diagnose debug info
debug output:           enable
console timestamp:      enable
dhcpc debug level:      190
zebos debug level:      38347922
CLI debug level:        3

As we already got an IP I have to release it:

myfirewall # config system interface
myfirewall (interface) # edit "wan1"
myfirewall (wan1) # set status down
myfirewall (wan1) # end.
2012-05-30 09:43:47 release interface:wan1
2012-05-30 09:43:47 Send an arp packet out.
2012-05-30 09:43:47 add hw header
2012-05-30 09:43:47 set dst hw addr as: FF:FF:FF:FF:FF:FF
2012-05-30 09:43:47 src hw addr: 02:09:0F:72:6F:95
2012-05-30 09:43:47 result:-1
2012-05-30 09:43:47 make release
2012-05-30 09:43:47 make dhcp message, code=7
2012-05-30 09:43:47 Insert option(255), len(0)
2012-05-30 09:43:47 Insert option(53), len(1)
2012-05-30 09:43:47 Insert client ID
2012-05-30 09:43:47 Insert option(61), len(7)
2012-05-30 09:43:47 Insert server ID
2012-05-30 09:43:47 Insert option(54), len(4)
2012-05-30 09:43:47 get_dhcp_msg_len, 255
2012-05-30 09:43:47 too small, extend to 548
2012-05-30 09:43:47 Sending release!
2012-05-30 09:43:47 Send a packet out.
2012-05-30 09:43:47 add hw header
2012-05-30 09:43:47 dst hw addr: 00:04:38:62:0A:11
2012-05-30 09:43:47 src hw addr: 02:09:0F:72:6F:95
2012-05-30 09:43:47 add ip udp header
2012-05-30 09:43:47 result:-1
2012-05-30 09:43:47 unregister timer:0x8ba23c0
2012-05-30 09:43:47 no dhcp client interface found, exiting...

And renew it:

myfirewall # config system interface
myfirewall (interface) # edit "wan1"
myfirewall (wan1) # set status up
myfirewall (wan1) # end 

This is the DHCP Discover:

2012-05-30 09:44:08 Register interface.
2012-05-30 09:44:08 sock: 6
2012-05-30 09:44:08 Bind sock: 6 to interface wan1
2012-05-30 09:44:08 register timer func=0x80a9b87 arg=0x8ba1d68
2012-05-30 09:44:08 Allocate a new timer
2012-05-30 09:44:08 Registered timer 0x8ba26f0 will expiry in 3 secs
2012-05-30 09:44:08 timer 0x8ba26f0 will expire in 3 secs
2012-05-30 09:44:08 Poll the file descriptors
2012-05-30 09:44:09 fd 6 can be read now
2012-05-30 09:44:09 Receive packet:
len=60
2012-05-30 09:44:09 del hw header
2012-05-30 09:44:09 ether_type:0806
2012-05-30 09:44:09 hw addr from: 00:23:04:10:6E:92
2012-05-30 09:44:09 arp packet received, len:46
2012-05-30 09:44:09 timer 0x8ba26f0 will expire in 2 secs
2012-05-30 09:44:09 Poll the file descriptors
2012-05-30 09:44:11 timer 0x8ba26f0 expired, take action
2012-05-30 09:44:11 state reboot.
2012-05-30 09:44:11 state init.
2012-05-30 09:44:11 make discover
2012-05-30 09:44:11 make dhcp message, code=1
2012-05-30 09:44:11 Insert option(255), len(0)
2012-05-30 09:44:11 Insert option(53), len(1)
2012-05-30 09:44:11 Insert max message len (1458)
2012-05-30 09:44:11 Insert option(57), len(2)
2012-05-30 09:44:11 Insert client ID
2012-05-30 09:44:11 Insert option(61), len(7)
2012-05-30 09:44:11 Insert requested options
2012-05-30 09:44:11 Insert option(55), len(9)
2012-05-30 09:44:11 Insert hostname
2012-05-30 09:44:11 Insert option(12), len(14)
2012-05-30 09:44:11 Insert class ID option
2012-05-30 09:44:11 Insert option(60), len(9)
2012-05-30 09:44:11 get_dhcp_msg_len, 291
2012-05-30 09:44:11 too small, extend to 548
2012-05-30 09:44:11 Sending discover!
2012-05-30 09:44:11 Send a packet out.
2012-05-30 09:44:11 add hw header
2012-05-30 09:44:11 set dst hw addr as: FF:FF:FF:FF:FF:FF
2012-05-30 09:44:11 src hw addr: 02:09:0F:72:6F:95
2012-05-30 09:44:11 add ip udp header
2012-05-30 09:44:11 result:590
2012-05-30 09:44:11 register timer func=0x80a9f82 arg=0x8ba1d68
2012-05-30 09:44:11 Allocate a new timer
2012-05-30 09:44:11 Registered timer 0x8ba2708 will expiry in 3 secs
2012-05-30 09:44:11 timer 0x8ba2708 will expire in 3 secs
2012-05-30 09:44:11 Poll the file descriptors
2012-05-30 09:44:12 fd 6 can be read now

This is the DHCP Offer:
The IP and the other options are in HEX. If you have to convert it to a readable format copy the Hex value to the link: http://tuxgraphics.org/toolbox/network_address_calculator_add.html
The offered IP is 970A0A0A = 10.10.10.151

2012-05-30 09:44:12 Receive packet:
len=349
2012-05-30 09:44:12 del hw header
2012-05-30 09:44:12 ether_type:0800
2012-05-30 09:44:12 hw addr from: 00:04:38:62:0A:11
2012-05-30 09:44:12 del ip udp header
2012-05-30 09:44:12 final dhcp message len:307
2012-05-30 09:44:12 DHCP Message received.
2012-05-30 09:44:12 parse dhcp options
2012-05-30 09:44:12 parse dhcp option buffer (67 bytes)
2012-05-30 09:44:12 option[53], len:1
2012-05-30 09:44:12 option[54], len:4
2012-05-30 09:44:12 option[51], len:4
2012-05-30 09:44:12 option[1], len:4
2012-05-30 09:44:12 option[3], len:4
2012-05-30 09:44:12 option[6], len:8
2012-05-30 09:44:12 option[12], len:14
2012-05-30 09:44:12 option[15], len:11
2012-05-30 09:44:12 DHO_BROADCAST_ADDRESS option is missed
2012-05-30 09:44:12 DHCPOFFER received on wan1
2012-05-30 09:44:12 client Xid:0x04934B57 in state:2, pkt Xid:0x04934B57
2012-05-30 09:44:12 handle received dhcp options!
2012-05-30 09:44:12 lease ip:970A0A0A
lease time: 3600, renew: 0, rebind: 0

This is the DHCP Request:

2012-05-30 09:44:12 unregister timer:0x8ba2708
2012-05-30 09:44:12 register timer func=0x80a9d09 arg=0x8ba1d68
2012-05-30 09:44:12 Allocate a new timer
2012-05-30 09:44:12 Registered timer 0x8ba2708 will expiry in 0 secs
2012-05-30 09:44:12 timer 0x8ba2708 expired, take action
2012-05-30 09:44:12 state selecting.
2012-05-30 09:44:12 make request
2012-05-30 09:44:12 make dhcp message, code=3
2012-05-30 09:44:12 Insert option(255), len(0)
2012-05-30 09:44:12 Insert option(53), len(1)
2012-05-30 09:44:12 Insert max message len (1458)
2012-05-30 09:44:12 Insert option(57), len(2)
2012-05-30 09:44:12 Insert client ID
2012-05-30 09:44:12 Insert option(61), len(7)
2012-05-30 09:44:12 Insert requested address (970A0A0A)
2012-05-30 09:44:12 Insert option(50), len(4)
2012-05-30 09:44:12 Insert server id
2012-05-30 09:44:12 Insert option(54), len(4)
2012-05-30 09:44:12 Insert requested options
2012-05-30 09:44:12 Insert option(55), len(9)
2012-05-30 09:44:12 Insert hostname
2012-05-30 09:44:12 Insert option(12), len(14)
2012-05-30 09:44:12 Insert class ID option
2012-05-30 09:44:12 Insert option(60), len(9)
2012-05-30 09:44:12 get_dhcp_msg_len, 303
2012-05-30 09:44:12 too small, extend to 548
2012-05-30 09:44:12 Sending request!
2012-05-30 09:44:12 Send a packet out.
2012-05-30 09:44:12 add hw header
2012-05-30 09:44:12 set dst hw addr as: FF:FF:FF:FF:FF:FF
2012-05-30 09:44:12 src hw addr: 02:09:0F:72:6F:95
2012-05-30 09:44:12 add ip udp header
2012-05-30 09:44:12 result:590
2012-05-30 09:44:12 register timer func=0x80aa076 arg=0x8ba1d68
2012-05-30 09:44:12 Allocate a new timer
2012-05-30 09:44:12 Registered timer 0x8ba26f0 will expiry in 3 secs
2012-05-30 09:44:12 timer 0x8ba26f0 will expire in 3 secs
2012-05-30 09:44:12 Poll the file descriptors
2012-05-30 09:44:12 fd 6 can be read now

and the DHCP Ack:

At the end we can see the following setting will be used on the wan1 interface:

ip:970A0A0A = 10.10.10.151
netmast:00FFFFFF = 255.255.255.0
broadcast:FF0A0A0A = 10.10.10.255
default gateway:010A0A0A = 10.10.10.1
dns1:750A0A0A = 10.10.10.117
dns2:120A0A0A = 10.10.10.18

2012-05-30 09:44:12 Receive packet:
len=349
2012-05-30 09:44:12 del hw header
2012-05-30 09:44:12 ether_type:0800
2012-05-30 09:44:12 hw addr from: 00:04:38:62:0A:11
2012-05-30 09:44:12 del ip udp header
2012-05-30 09:44:12 final dhcp message len:307
2012-05-30 09:44:12 DHCP Message received.
2012-05-30 09:44:12 parse dhcp options
2012-05-30 09:44:12 parse dhcp option buffer (67 bytes)
2012-05-30 09:44:12 option[53], len:1
2012-05-30 09:44:12 option[54], len:4
2012-05-30 09:44:12 option[51], len:4
2012-05-30 09:44:12 option[1], len:4
2012-05-30 09:44:12 option[3], len:4
2012-05-30 09:44:12 option[6], len:8
2012-05-30 09:44:12 option[12], len:14
2012-05-30 09:44:12 option[15], len:11
2012-05-30 09:44:12 DHO_BROADCAST_ADDRESS oDHCP Message rec
2012-05-30 09:44:13 timer 0x8ba26f0 expired, take action

2012-05-30 09:44:13 Sending arpcheck!
2012-05-30 09:44:13 Send an arp packet out.
2012-05-30 09:44:13 add hw header
2012-05-30 09:44:13 set dst hw addr as: FF:FF:FF:FF:FF:FF
2012-05-30 09:44:13 src hw addr: 02:09:0F:72:6F:95
2012-05-30 09:44:13 result:60
2012-05-30 09:44:13 register timer func=0x80aa260 arg=0x8ba1d68
2012-05-30 09:44:13 Allocate a new timer
2012-05-30 09:44:13 Registered timer 0x8ba2fd8 will expiry in 1 secs
2012-05-30 09:44:13 timer 0x8ba2fd8 will expire in 1 secs
2012-05-30 09:44:13 Poll the file descriptors
2012-05-30 09:44:14 timer 0x8ba2fd8 expired, take action

2012-05-30 09:44:14 Sending arpcheck!
2012-05-30 09:44:14 Send an arp packet out.
2012-05-30 09:44:14 add hw header
2012-05-30 09:44:14 set dst hw addr as: FF:FF:FF:FF:FF:FF
2012-05-30 09:44:14 src hw addr: 02:09:0F:72:6F:95
2012-05-30 09:44:14 result:60
2012-05-30 09:44:14 register timer func=0x80aa260 arg=0x8ba1d68
2012-05-30 09:44:14 Allocate a new timer
2012-05-30 09:44:14 Registered timer 0x8ba26f0 will expiry in 1 secs
2012-05-30 09:44:14 timer 0x8ba26f0 will expire in 1 secs
2012-05-30 09:44:14 Poll the file descriptors
2012-05-30 09:44:15 timer 0x8ba26f0 expired, take action

2012-05-30 09:44:15 Sending arpcheck!
2012-05-30 09:44:15 Send an arp packet out.
2012-05-30 09:44:15 add hw header
2012-05-30 09:44:15 set dst hw addr as: FF:FF:FF:FF:FF:FF
2012-05-30 09:44:15 src hw addr: 02:09:0F:72:6F:95
2012-05-30 09:44:15 result:60
2012-05-30 09:44:15 register timer func=0x80aa260 arg=0x8ba1d68
2012-05-30 09:44:15 Allocate a new timer
2012-05-30 09:44:15 Registered timer 0x8ba2fd8 will expiry in 1 secs
2012-05-30 09:44:15 timer 0x8ba2fd8 will expire in 1 secs
2012-05-30 09:44:15 Poll the file descriptors
2012-05-30 09:44:16 timer 0x8ba2fd8 expired, take action

2012-05-30 09:44:16 Sending arpcheck!
2012-05-30 09:44:16 bind lease
2012-05-30 09:44:16 register timer func=0x80a9e9d arg=0x8ba1d68
2012-05-30 09:44:16 Allocate a new timer
2012-05-30 09:44:16 Registered timer 0x8ba26f0 will expiry in 1796 secs
2012-05-30 09:44:16 config interface:wan1
2012-05-30 09:44:16 config interface ip:970A0A0A
2012-05-30 09:44:16 config interface netmast:00FFFFFF
2012-05-30 09:44:16 config interface broadcast:FF0A0A0A
2012-05-30 09:44:16 config interface default gateway:010A0A0A
2012-05-30 09:44:16 config interface dns1:750A0A0A
2012-05-30 09:44:16 config interface dns2:120A0A0A
2012-05-30 09:44:16 Send an arp packet out.
2012-05-30 09:44:16 add hw header
2012-05-30 09:44:16 set dst hw addr as: FF:FF:FF:FF:FF:FF
2012-05-30 09:44:16 src hw addr: 02:09:0F:72:6F:95
2012-05-30 09:44:16 result:60
2012-05-30 09:44:16 timer 0x8ba26f0 will expire in 1796 secs
2012-05-30 09:44:16 Poll the file descriptors
2012-05-30 09:44:16 fd 6 can be read now
2012-05-30 09:44:16 Receive packet:
len=60
2012-05-30 09:44:16 del hw header
2012-05-30 09:44:16 ether_type:0806
2012-05-30 09:44:16 hw addr from: 02:09:0F:72:6F:95
2012-05-30 09:44:16 arp packet received, len:46
2012-05-30 09:44:17 timer 0x8ba26f0 will expire in 1795 secs
2012-05-30 09:44:17 Poll the file descriptors
2012-05-30 09:44:49 fd 6 can be read now
2012-05-30 09:44:49 Receive packet:
len=60
2012-05-30 09:44:49 del hw header
2012-05-30 09:44:49 ether_type:0806
2012-05-30 09:44:49 hw addr from: 00:23:04:10:6D:E8
2012-05-30 09:44:49 arp packet received, len:46
2012-05-30 09:44:49 timer 0x8ba26f0 will expire in 1763 secs
2012-05-30 09:44:49 Poll the file descriptors

2012-05-30 09:44:57 fd 6 can be read now
2012-05-30 09:44:57 Receive packet:
len=60
2012-05-30 09:44:57 del hw header
2012-05-30 09:44:57 ether_type:0806
2012-05-30 09:44:57 hw addr from: 00:23:04:10:6E:E8
2012-05-30 09:44:57 arp packet received, len:46
2012-05-30 09:44:57 timer 0x8ba26f0 will expire in 1755 secs
2012-05-30 09:44:57 Poll the file descriptors

2012-05-30 09:45:09 fd 6 can be read now
2012-05-30 09:45:09 Receive packet:
len=60
2012-05-30 09:45:09 del hw header
2012-05-30 09:45:09 ether_type:0806
2012-05-30 09:45:09 hw addr from: 00:23:04:10:6E:92
2012-05-30 09:45:09 arp packet received, len:46
2012-05-30 09:45:09 timer 0x8ba26f0 will expire in 1743 secs
2012-05-30 09:45:09 Poll the file descriptors

At the and we can see the dynamic IP with “get system interface” command:

myfirewall # get system interface
== [ wlan ]
name: wlan    mode: static    ip: 192.168.227.177 255.255.255.240   status: up    netbios-forward: disable    type: wireless
== [ internal ]
name: internal    mode: static    ip: 0.0.0.0 0.0.0.0   status: down    netbios-forward: disable    type: physical   mtu-override: disable
== [ wan2 ]
name: wan2    mode: static    ip: 0.0.0.0 0.0.0.0   status: down    netbios-forward: disable    type: physical   mtu-override: disable
== [ wan1 ]
name: wan1    mode: dhcp    ip: 10.10.10.151 255.255.255.0   status: up    netbios-forward: disable    type: physical   mtu-override: disable
== [ forti50-300 ]
name: forti50-300    ip: 0.0.0.0 0.0.0.0   status: up    netbios-forward: disable    type: tunnel

And the default route from DHCP Server:

myfirewall # get route info routing-table all
Codes: K - kernel, C - connected, S - static, R - RIP, B - BGP
       O - OSPF, IA - OSPF inter area
       N1 - OSPF NSSA external type 1, N2 - OSPF NSSA external type 2
       E1 - OSPF external type 1, E2 - OSPF external type 2
       i - IS-IS, L1 - IS-IS level-1, L2 - IS-IS level-2, ia - IS-IS inter area
       * - candidate default

S*      0.0.0.0/0 [5/0] via 10.10.10.1, wan1
C       10.10.10.0/24 is directly connected, wan1
Advertisements
Tagged: ,