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
|
itsecworks 
Posted on June 6, 2012
0