Re: NetworkManager does not like my dhcp offer

[Bill Moss <bmoss clemson edu>]

Richard Torkar wrote
I get this in my log when connected to a wired ethernet at school.
(NetworkManager-0.3.3-1.cvs20050112.1.fc3)

NetworkManager: DHCP: Sending request packet...
NetworkManager: DHCP: Sent request packet.
NetworkManager: DHCP: Waiting for reply...
NetworkManager: DHCP waiting for data, overall end_time = {1105947290s,
976021us}
NetworkManager: DHCP waiting for data of minimum size 28, remaining
timeout = {13s, 13103us}
NetworkManager: DHCP waiting for data of minimum size 28, remaining
timeout = {12s, 13685us}
NetworkManager: DHCP waiting for data of minimum size 28, remaining
timeout = {11s, 13814us}
NetworkManager: DHCP: Got some data to check for reply packet.
NetworkManager: DHCP: actual data length was 328
NetworkManager: DHCP: Reply message's source port was not the DHCP
server port number, won't use it.

Especially the last line is interesting... What has changed? Is this a
security feature? Is the network I'm using not set up correctly? Can you
refer me to an RFC which contain information regarding this matter?

Best,

Richard Torkar

Here is similar syslog output from my system: IBMT42, ipw2200, FC3, kernel-2.6.9-1.724
This what you should expect to see more or less. I have inlined comments to explain what you are seeing.

Jan 17 09:56:33 localhost NetworkManager: dhcp_interface_init: MAC address = 00:0e:35:14:60:d0
Jan 17 09:56:33 localhost NetworkManager: Broadcasting DHCP_DISCOVERJan 17 09:56:33 localhost NetworkManager: DHCP: Starting request loop
Jan 17 09:56:33 localhost NetworkManager: DHCP: Sending request packet...Jan 17 09:56:33 localhost NetworkManager: DHCP: Sent request packet.
[comment: First the client broadcasts a DHCP DISCOVER to see if there are DHCP servers available, then it waits for a reply.]
Jan 17 09:56:33 localhost NetworkManager: DHCP: Waiting for reply...Jan 17 09:56:33 localhost NetworkManager: DHCP waiting for data, overall end_time = {1105973799s, -696120us}
Jan 17 09:56:33 localhost NetworkManager: DHCP waiting for data of minimum size 28, remaining timeout = {5s, 55973us}
Jan 17 09:56:33 localhost NetworkManager: DHCP: Got some data to check for reply packet.Jan 17 09:56:33 localhost NetworkManager: DHCP: actual data length was 331
Jan 17 09:56:33 localhost NetworkManager: DHCP: Reply message's source port was not the DHCP server port number, won't use it.
[comment: HM has received its own broadcast. This not an error. An interface will receive its own broadcast. NM is properly rejecting this message.]
Jan 17 09:56:33 localhost NetworkManager: DHCP: Waiting for reply...Jan 17 09:56:33 localhost NetworkManager: DHCP waiting for data, overall end_time = {1105973799s, -696120us}
Jan 17 09:56:33 localhost NetworkManager: DHCP waiting for data of minimum size 28, remaining timeout = {4s, 993212us}
[comment: beginning in the next line, NM is receiving and analyzing a DHCP offer from DHCP server in the AP.]
Jan 17 09:56:34 localhost NetworkManager: DHCP: Got some data to check for reply packet.Jan 17 09:56:34 localhost NetworkManager: DHCP: actual data length was 576
Jan 17 09:56:34 localhost NetworkManager: debug_dump_dhcp_options: 9 options received:Jan 17 09:56:34 localhost NetworkManager: i=1  (subnetMask)  len=4   option = 255.255.255.0
Jan 17 09:56:34 localhost NetworkManager: i=3  (routersOnSubnet)  len=4   option = 192.168.2.1Jan 17 09:56:34 localhost NetworkManager: i=6  (dns)  len=4   option = 192.168.2.1
Jan 17 09:56:34 localhost NetworkManager: i=15 (domainName)  len=9   option = "WorkGroup"Jan 17 09:56:34 localhost NetworkManager: i=28 (broadcastAddr)  len=4   option = 255.255.255.255
Jan 17 09:56:34 localhost NetworkManager: i=51 (dhcpMessageType)  len=4   option = 7200      
Jan 17 09:56:34 localhost NetworkManager: i=52 (dhcpServerIdentifier)  len=1   option = "^C"
Jan 17 09:56:34 localhost NetworkManager: i=53 (dhcpParamRequest)  len=1   option = 2
Jan 17 09:56:34 localhost NetworkManager: i=54 (dhcpMsg)  len=4   option = 192.168.2.1
Jan 17 09:56:34 localhost NetworkManager: dhcp_msg->yiaddr  = 192.168.2.4
Jan 17 09:56:34 localhost NetworkManager: dhcp_msg->siaddr  = 0.0.0.0
Jan 17 09:56:34 localhost NetworkManager: dhcp_msg->giaddr  = 0.0.0.0
Jan 17 09:56:34 localhost NetworkManager: dhcp_msg->sname   = "ÿ"
Jan 17 09:56:34 localhost NetworkManager: Server Hardware Address   = 00.04.E2.1E.55.C8
Jan 17 09:56:34 localhost NetworkManager: DHCP_OFFER received from ÿ (192.168.2.1)
[comment: after analysis, NM correctly classifies this message as a DHCP OFFER.]
[comment: next NM will broadcast a DHCP REQUEST asking to use a list of options, then it waits for a reply.]
Jan 17 09:56:34 localhost NetworkManager: Broadcasting DHCP_REQUEST for 192.168.2.4
Jan 17 09:56:34 localhost NetworkManager: DHCP: Starting request loop
Jan 17 09:56:34 localhost NetworkManager: DHCP: Sending request packet...
Jan 17 09:56:34 localhost NetworkManager: DHCP: Sent request packet.
Jan 17 09:56:34 localhost NetworkManager: DHCP: Waiting for reply...
Jan 17 09:56:34 localhost NetworkManager: DHCP waiting for data, overall end_time = {1105973800s, -594542us}
Jan 17 09:56:34 localhost NetworkManager: DHCP waiting for data of minimum size 28, remaining timeout = {5s, 125189us}
[comment: NM has received a DHCP ACK[nowledgement] and will analyze it.]
Jan 17 09:56:34 localhost NetworkManager: DHCP: Got some data to check for reply packet.
Jan 17 09:56:34 localhost NetworkManager: DHCP: actual data length was 576
Jan 17 09:56:34 localhost NetworkManager: debug_dump_dhcp_options: 11 options received:
Jan 17 09:56:34 localhost NetworkManager: i=1  (subnetMask)  len=4   option = 255.255.255.0
Jan 17 09:56:34 localhost NetworkManager: i=3  (routersOnSubnet)  len=4   option = 192.168.2.1
Jan 17 09:56:34 localhost NetworkManager: i=6  (dns)  len=4   option = 192.168.2.1
Jan 17 09:56:34 localhost NetworkManager: i=15 (domainName)  len=9   option = "WorkGroup"
Jan 17 09:56:34 localhost NetworkManager: i=28 (broadcastAddr)  len=4   option = 255.255.255.255
Jan 17 09:56:34 localhost NetworkManager: i=51 (dhcpMessageType)  len=4   option = 7200
Jan 17 09:56:34 localhost NetworkManager: i=52 (dhcpServerIdentifier)  len=1   option = "^C"
Jan 17 09:56:34 localhost NetworkManager: i=53 (dhcpParamRequest)  len=1   option = 5
Jan 17 09:56:34 localhost NetworkManager: i=54 (dhcpMsg)  len=4   option = 192.168.2.1
Jan 17 09:56:34 localhost NetworkManager: i=58 (dhcpClassIdentifier)  len=4   option = 0
Jan 17 09:56:34 localhost NetworkManager: i=59 (dhcpClientIdentifier)  len=4   option = 0
Jan 17 09:56:34 localhost NetworkManager: dhcp_msg->yiaddr  = 192.168.2.4
Jan 17 09:56:34 localhost NetworkManager: dhcp_msg->siaddr  = 0.0.0.0
Jan 17 09:56:34 localhost NetworkManager: dhcp_msg->giaddr  = 0.0.0.0
Jan 17 09:56:34 localhost NetworkManager: dhcp_msg->sname   = "ÿ"
Jan 17 09:56:34 localhost NetworkManager: Server Hardware Address   = 00.04.E2.1E.55.C8
Jan 17 09:56:34 localhost NetworkManager: DHCP_ACK received from ÿ (192.168.2.1)
[comment: NM correctly concludes that it has received a DHCP ACK.]
[comment: NM sets the ip address, the nameserver, and the domain.]
Jan 17 09:56:34 localhost NetworkManager: Your IP address = 192.168.2.4
Jan 17 09:56:34 localhost NetworkManager: : Adding nameserver: 192.168.2.1
Jan 17 09:56:34 localhost NetworkManager: : Adding domain search: WorkGroup
Jan 17 09:56:34 localhost NetworkManager: nm_device_activation_worker(eth1): device activated
Jan 17 09:56:34 localhost NetworkManager: nm_state_modification_monitor() activated device eth1
                     

My experience is limited to the ipw2200 wireless, an SMC 7004 AWBR at home, and Cisco AP's at work. 
NM dhcp is working well with these. A colleague has an IBMT41, built-in Cisco 350 mini-PCI wireless,
FC3 kernel-2.6.9-1.681. He loaded the CVS2005112. The syslog showed similar results to what Richard 
Torkar reported. Unfortunately, I did not have time to trace down the problem. It could have just
been a nonresponsive DHCP server. We see this fairly often but I expect it was more. I usually will
immediately check the DHCP server. I
kill NM and NMInfo, reset the wireless interface, and then manually configure essid, key, and
then use dhclient or dhcpcd to get an ip address. I have a script to do all this quickly.

Eventually it will be useful to maintain a NM hardware verification list that contains kernel version, 
wireless card, laptop vendor, and access points. 


--
Bill Moss
Professor, Mathematical Sciences
Clemson University