Comment 8 for bug 105251

@Guillaume (Blog post author): I tried your proposed workaround (adding "|new_server_name|old_server_name" to the dhcdbd exit hook) but unfortunately it didn't change the situation at all for me. I am still getting...:

Jul 16 03:18:44 motin-laptop NetworkManager: <info> dhclient started with pid 7017
Jul 16 03:18:44 motin-laptop NetworkManager: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) complete.
Jul 16 03:18:44 motin-laptop dhclient: Internet Systems Consortium DHCP Client V3.0.6
Jul 16 03:18:44 motin-laptop dhclient: Copyright 2004-2007 Internet Systems Consortium.
Jul 16 03:18:44 motin-laptop dhclient: All rights reserved.
Jul 16 03:18:44 motin-laptop dhclient: For info, please visit http://www.isc.org/sw/dhcp/
Jul 16 03:18:44 motin-laptop dhclient:
Jul 16 03:18:44 motin-laptop dhclient: wmaster0: unknown hardware address type 801
Jul 16 03:18:44 motin-laptop dhclient: wmaster0: unknown hardware address type 801
Jul 16 03:18:44 motin-laptop dhclient: Listening on LPF/wlan0/00:1f:3b:bb:dd:bf
Jul 16 03:18:44 motin-laptop dhclient: Sending on LPF/wlan0/00:1f:3b:bb:dd:bf
Jul 16 03:18:44 motin-laptop dhclient: Sending on Socket/fallback
Jul 16 03:18:48 motin-laptop dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 6
Jul 16 03:18:48 motin-laptop dhclient: DHCPOFFER of 192.168.1.127 from 192.168.1.1
Jul 16 03:18:48 motin-laptop dhclient: DHCPREQUEST of 192.168.1.127 on wlan0 to 255.255.255.255 port 67
Jul 16 03:18:48 motin-laptop dhclient: DHCPACK of 192.168.1.127 from 192.168.1.1
Jul 16 03:18:48 motin-laptop dhclient: bound to 192.168.1.127 -- renewal in 41230 seconds.
Jul 16 03:19:29 motin-laptop NetworkManager: <info> Device 'wlan0' DHCP transaction took too long (>45s), stopping it.
Jul 16 03:19:29 motin-laptop NetworkManager: <info> wlan0: canceled DHCP transaction, dhclient pid 7017

Do you, or any other around here, know if there is a way to manually send the correct dbus message to network manager? This way we can at least inspect the syslog ourselves and send the message when we are connected to the network, instead of having to wait for an inevitable disconnect...

Also, you write "It would be interesting to compare dhcp response messages between dnsmasq and dhcp-server in order to see if dhclient returns readable values in the server_name fields when using the latter.". How do we identify and compare these response messages? Logging? Some sort of debug mode? I'll happily debug further if you can put me on the right track... Thanks!

PS All I managed to do was an strace of dhclient shortly after I saw what pid that network manager was using and before and during the actual bound. I have no idea if it helps and or dbus messages can be spotted but here it is:

$ sudo strace -p 7646
Process 7646 attached - interrupt to quit
gettimeofday({1216171610, 812560}, NULL) = 0
select(8, [7], [], [], {0, 0}) = 0 (Timeout)
select(7, [6], [], [], {0, 0}) = 0 (Timeout)
gettimeofday({1216171610, 812983}, NULL) = 0
select(8, [6 7], [], [], {0, 187017}) = 0 (Timeout)
gettimeofday({1216171611, 1634}, NULL) = 0
time(NULL) = 1216171611
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
send(3, "<30>Jul 16 03:26:51 dhclient: DH"..., 89, MSG_NOSIGNAL) = 89
write(2, "DHCPDISCOVER on wlan0 to 255.255"..., 59) = 59
write(2, "\n", 1) = 1
sendto(7, "\377\377\377\377\377\377\0\37;\273\335\277\10\0E\20\1H"..., 342, 0, {sa_family=AF_PACKET, proto=0x776c, if3173985, pkttype=PACKET_HOST, addr(0)={0, }, 16) = 342
gettimeofday({1216171611, 3567}, NULL) = 0
select(8, [6 7], [], [], {2, 996433}) = 1 (in [7], left {2, 987000})
gettimeofday({1216171611, 13852}, NULL) = 0
read(7, "\0\37;\273\335\277\0\26\1\177\260\264\10\0E\0\1H\0\0@\0"..., 1536) = 342
time(NULL) = 1216171611
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
send(3, "<30>Jul 16 03:26:51 dhclient: DH"..., 73, MSG_NOSIGNAL) = 73
write(2, "DHCPOFFER of 192.168.1.127 from "..., 43) = 43
write(2, "\n", 1) = 1
time(NULL) = 1216171611
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
send(3, "<30>Jul 16 03:26:51 dhclient: DH"..., 94, MSG_NOSIGNAL) = 94
write(2, "DHCPREQUEST of 192.168.1.127 on "..., 64) = 64
write(2, "\n", 1) = 1
sendto(7, "\377\377\377\377\377\377\0\37;\273\335\277\10\0E\20\1H"..., 342, 0, {sa_family=AF_PACKET, proto=0x776c, if3173985, pkttype=PACKET_HOST, addr(0)={0, }, 16) = 342
gettimeofday({1216171611, 15764}, NULL) = 0
select(8, [6 7], [], [], {2, 984236}) = 1 (in [7], left {2, 980000})
gettimeofday({1216171611, 20532}, NULL) = 0
read(7, "\0\37;\273\335\277\0\26\1\177\260\264\10\0E\0\1N\0\0@\0"..., 1536) = 348
time(NULL) = 1216171611
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
send(3, "<30>Jul 16 03:26:51 dhclient: DH"..., 71, MSG_NOSIGNAL) = 71
write(2, "DHCPACK of 192.168.1.127 from 19"..., 41) = 41
write(2, "\n", 1) = 1
clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb7e33b18) = 7653
wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 1}], 0, NULL) = 7653
--- SIGCHLD (Child exited) @ 0 (0) ---
time(NULL) = 1216171611
fstat64(4, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f9c000
write(4, "lease {\n interface \"wlan0\";\n f"..., 516) = 516
time(NULL) = 1216171611
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
send(3, "<30>Jul 16 03:26:51 dhclient: bo"..., 81, MSG_NOSIGNAL) = 81
write(2, "bound to 192.168.1.127 -- renewa"..., 51) = 51
write(2, "\n", 1) = 1
gettimeofday({1216171611, 52097}, NULL) = 0
select(8, [6 7], [], [], {0, 947903}) = 0 (Timeout)
gettimeofday({1216171612, 552}, NULL) = 0
gettimeofday({1216171612, 752}, NULL) = 0
select(8, [6 7], [], [], {39231, 999248}

This way it stalls until 45s has gone, where after the last line turns into:
select(8, [6 7], [], [], {39231, 999248}) = -1 EINTR (Interrupted system call)
--- SIGTERM (Terminated) @ 0 (0) ---
Process 7646 detached