Re: About "Received DHCP event from unexpected PID xxxx (expected xxxx)"

[Dan Williams <dcbw redhat com>]

On Wed, 2009-02-18 at 17:10 +0800, cee1 wrote:
> Hi,
>      I'm using NetwokManager-0.7(using dhcpcd) with wifi, and see a
> lot of messages like  "Received DHCP event from unexpected PID xxxx
> (expected xxxx)" in the syslog. 

What version of NM specifically?  The final NM release from late
November 2008, or a snapshot from some other point in time?

>      I also see more than one dhcpcd processes running. Sometimes,
> only one dhcpcd process lefts at last, but sometimes not. (searching
> google, find the same problem someone has reported:
> https://bugs.launchpad.net/ubuntu/+source/network-manager/+bug/255829)
>      Following the source code(NM-0.7), in the function
> <nm_dhcp_client_start> (nm-dhcp-dhcpcd.c), it kills the previous
> dhcpcd process and saves the new one's pid in device->pid. But the
> function <dhcp_watch_cb>, knowing the termination of the previous
> dhcpd process, sets device->pid to zero. So the current dhcp process's
> pid is lost, and <nm_dhcp_manager_handle_event> will print log like
> "Received DHCP event from unexpected PID 8812 (expected 0)".

Obviously the previous one isn't getting cleaned up correctly.  It might
be that dhcpcd returns a state NM doesn't expect, and thus isn't getting
cleaned up in nm_dhcp_manager_begin_transaction():

	if (state_is_bound (device->state) || (device->state == DHC_START)) {
		/* Cancel any DHCP transaction already in progress */
		nm_dhcp_manager_cancel_transaction_real (device);
	}

Basically, it should *always* be the case that a previous dhcp client
instance is cleaned up before starting a new one, so the watch callback
should certainly be removed before starting a new dhcp client run.

>      Also the previous dhcpcd process's time_out handler may expire,
> and affects the current running dhcpcd process?

The timeout gets cleared whenever DHCP options get returned, or when the
dhcp device gets destroyed, or when nm_dhcp_manager_cancel_transaction()
is called to clean up any ongoing DHCP transaction.
cancel_transaction() gets called when the device is deactivated.

In any case, I've fixed up a few issues with the DHCP client handling
code and made it somewhat more robust against this issue.  If you can
possibly test the latest git, or at least figure out what state the DHCP
client is left in (device->state) when
nm_dhcp_manager_begin_transaction() gets called, that would be great.

Dan

>      It seems the function <supplicant_interface_acquire>
> (nm-device-wifi.c) registers a function
> <supplicant_iface_connection_state_cb> as the handler of the signal
> "connection-state" .
> And:
> <supplicant_iface_connection_state_cb> shcedules
> <supplicant_iface_connection_state_cb_handler>, which calls
> <nm_device_activate_schedule_stage3_ip_config_start>, which shcedules
> <nm_device_activate_stage3_ip_config_start> , which calls
> <real_act_stage3_ip_config_start>, which calls
> <nm_dhcp_manager_begin_transaction>.
> So it is possiable that more than one dhcpcd processes running
> meanwhile.
>  
>     To fix this, shoud I do:
> 1) Protect the corresponding data struct 
> or 
> 2) Add a clean step when a second dhcpcd process to be started
> 
>      Any ideas? Thanks. 
> _______________________________________________
> NetworkManager-list mailing list
> NetworkManager-list gnome org
> http://mail.gnome.org/mailman/listinfo/networkmanager-list