Bug 3019 - udhcpc fails to renew lease on SIGUSR1
Summary: udhcpc fails to renew lease on SIGUSR1
Status: RESOLVED INVALID
Alias: None
Product: Busybox
Classification: Unclassified
Component: Networking (show other bugs)
Version: 1.17.x
Hardware: Other Linux
: P5 normal
Target Milestone: ---
Assignee: unassigned
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2010-12-28 10:16 UTC by Andrew
Modified: 2011-01-06 14:27 UTC (History)
1 user (show)

See Also:
Host:
Target:
Build:

Attachments
Add an attachment (proposed patch, testcase, etc.)

Note You need to log in before you can comment on or make changes to this bug.
Description Andrew 2010-12-28 10:16:50 UTC 
I use udhcpc on embedded platform. When I tried to renew lease via sending SIGUSR1 (or release lease via sending SIGUSR2 and renew lease via sending SIGUSR1) - as result udhcpc can't obtain lease. tcpdump shows that dhcp server answers are present:

00:35:57.763252 1c:af:f7:41:9b:4f > ff:ff:ff:ff:ff:ff, ethertype IPv4 (0x0800), length 333: (tos 0x0, ttl 64, id 0, offset 0, flags [none], proto UDP (17), length 319)
    0.0.0.0.68 > 255.255.255.255.67: BOOTP/DHCP, Request [|bootp]
00:35:57.763527 00:18:f3:fd:22:fe > 1c:af:f7:41:9b:4f, ethertype IPv4 (0x0800), length 342: (tos 0x10, ttl 128, id 0, offset 0, flags [none], proto UDP (17), length 328)
    172.19.32.254.67 > 172.19.32.220.68: BOOTP/DHCP, Reply, length 300, xid 0xbc341d43, secs 3, Flags [none] (0x0000)
          Your-IP 172.19.32.220
          Server-IP 172.19.32.254 [|bootp]


In log - only retries of renew:
Dec 28 01:25:17 udhcpc[786]: Performing a DHCP renew
Dec 28 01:25:17 udhcpc[786]: Sending discover...
Dec 28 01:25:22 udhcpc[786]: Sending discover...
Dec 28 01:25:27 udhcpc[786]: Sending discover...
Dec 28 01:25:32 udhcpc[786]: Sending discover...

In usual mode udhcpc renews lease successful on lease timeout.
Comment 1 Denys Vlasenko 2010-12-28 22:42:50 UTC 
What version of busybox do you use?

Please make sure UDHCP_DEBUG is set at least to 3 in .config, run udhcpc with -vvv, reproduce the bug, capture udhcpc log (it is on stderr or in syslog) and post it to this bug.
Comment 2 Andrew 2010-12-29 17:37:23 UTC 
Dec 28 11:57:01 udhcpc[2469]: Adapter index 13
Dec 28 11:57:01 udhcpc[2469]: MAC 1c:af:f7:41:9b:4f
Dec 28 11:57:01 udhcpc[2469]: Adapter mtu 1500
Dec 28 11:57:01 udhcpc[2469]: Waiting on select...
Dec 28 11:57:01 udhcpc[2469]: Unicasting a release of 172.19.32.220 to 172.19.32.254
Dec 28 11:57:01 udhcpc[2469]: Adding option: 0x35 07
Dec 28 11:57:01 udhcpc[2469]: Adding option: 0x3d 011caff7419b4f
Dec 28 11:57:01 udhcpc[2469]: Adding option: 0x0c 4449522d333030
Dec 28 11:57:01 udhcpc[2469]: Adding option: 0x36 ac1320fe
Dec 28 11:57:01 udhcpc[2469]: Sending release...
Dec 28 11:57:01 udhcpc[2469]:  hlen 6 xid 3a48d7f5 ciaddr dc2013ac yiaddr 0 siaddr 0 giaddr 0
Dec 28 11:57:01 udhcpc[2469]:  chaddr 1caff7419b4f00000000000000000000
Dec 28 11:57:01 udhcpc[2469]: Executing /sbin/udhcpc.sh deconfig
Dec 28 11:57:02 udhcpc[2469]:  interface=eth2.2
Dec 28 11:57:02 udhcpc[2469]: Entering released state
Dec 28 11:57:02 udhcpc[2469]: Entering listen mode: none
Dec 28 11:57:02 udhcpc[2469]: Adapter index 13
Dec 28 11:57:02 udhcpc[2469]: MAC 1c:af:f7:41:9b:4f
Dec 28 11:57:02 udhcpc[2469]: Adapter mtu 1500
Dec 28 11:57:02 udhcpc[2469]: Waiting on select...
Dec 28 11:57:02 udhcpc[2469]: Performing a DHCP renew
Dec 28 11:57:02 udhcpc[2469]: Adapter index 13
Dec 28 11:57:02 udhcpc[2469]: MAC 1c:af:f7:41:9b:4f
Dec 28 11:57:02 udhcpc[2469]: Adapter mtu 1500
Dec 28 11:57:02 udhcpc[2469]: Adding option: 0x35 01
Dec 28 11:57:02 udhcpc[2469]: Adding option: 0x3d 011caff7419b4f
Dec 28 11:57:02 udhcpc[2469]: Adding option: 0x0c 4449522d333030
Dec 28 11:57:02 udhcpc[2469]: Adding option: 0x3c 756468637020312e31372e34
Dec 28 11:57:02 udhcpc[2469]: Adding option: 0x39 0240
Dec 28 11:57:02 udhcpc[2469]: Adding option: 0x32 ac1320dc
Dec 28 11:57:02 udhcpc[2469]: Sending discover...
Dec 28 11:57:02 udhcpc[2469]:  hlen 6 xid 1d3bf256 ciaddr 0 yiaddr 0 siaddr 0 giaddr 0
Dec 28 11:57:02 udhcpc[2469]:  chaddr 1caff7419b4f00000000000000000000
Dec 28 11:57:02 udhcpc[2469]: Adapter index 13
Dec 28 11:57:02 udhcpc[2469]: MAC 1c:af:f7:41:9b:4f
Dec 28 11:57:02 udhcpc[2469]: Adapter mtu 1500
Dec 28 11:57:02 udhcpc[2469]: Waiting on select...
Dec 28 11:57:07 udhcpc[2469]: Adding option: 0x35 01
Dec 28 11:57:07 udhcpc[2469]: Adding option: 0x3d 011caff7419b4f
Dec 28 11:57:07 udhcpc[2469]: Adding option: 0x0c 4449522d333030
Dec 28 11:57:07 udhcpc[2469]: Adding option: 0x3c 756468637020312e31372e34
Dec 28 11:57:07 udhcpc[2469]: Adding option: 0x39 0240
Dec 28 11:57:07 udhcpc[2469]: Adding option: 0x32 ac1320dc
Dec 28 11:57:07 udhcpc[2469]: Sending discover...
Dec 28 11:57:07 udhcpc[2469]:  hlen 6 xid 1d3bf256 ciaddr 0 yiaddr 0 siaddr 0 giaddr 0
Dec 28 11:57:07 udhcpc[2469]:  chaddr 1caff7419b4f00000000000000000000
Dec 28 11:57:07 udhcpc[2469]: Adapter index 13
Dec 28 11:57:07 udhcpc[2469]: MAC 1c:af:f7:41:9b:4f
Dec 28 11:57:07 udhcpc[2469]: Adapter mtu 1500
Dec 28 11:57:07 udhcpc[2469]: Waiting on select...
Dec 28 11:57:12 udhcpc[2469]: Adding option: 0x35 01
Dec 28 11:57:12 udhcpc[2469]: Adding option: 0x3d 011caff7419b4f
Dec 28 11:57:12 udhcpc[2469]: Adding option: 0x0c 4449522d333030
Dec 28 11:57:12 udhcpc[2469]: Adding option: 0x3c 756468637020312e31372e34
Dec 28 11:57:12 udhcpc[2469]: Adding option: 0x39 0240
Dec 28 11:57:12 udhcpc[2469]: Adding option: 0x32 ac1320dc
Dec 28 11:57:12 udhcpc[2469]: Sending discover...
Dec 28 11:57:12 udhcpc[2469]:  hlen 6 xid 1d3bf256 ciaddr 0 yiaddr 0 siaddr 0 giaddr 0
Dec 28 11:57:12 udhcpc[2469]:  chaddr 1caff7419b4f00000000000000000000
Dec 28 11:57:12 udhcpc[2469]: Adapter index 13
Dec 28 11:57:12 udhcpc[2469]: MAC 1c:af:f7:41:9b:4f
Dec 28 11:57:12 udhcpc[2469]: Adapter mtu 1500
Dec 28 11:57:12 udhcpc[2469]: Waiting on select...
Dec 28 11:57:17 udhcpc[2469]: Adding option: 0x35 01
Dec 28 11:57:17 udhcpc[2469]: Adding option: 0x3d 011caff7419b4f
Dec 28 11:57:17 udhcpc[2469]: Adding option: 0x0c 4449522d333030
Dec 28 11:57:17 udhcpc[2469]: Adding option: 0x3c 756468637020312e31372e34
Dec 28 11:57:17 udhcpc[2469]: Adding option: 0x39 0240
Dec 28 11:57:17 udhcpc[2469]: Adding option: 0x32 ac1320dc
Dec 28 11:57:17 udhcpc[2469]: Sending discover...
Dec 28 11:57:17 udhcpc[2469]:  hlen 6 xid 1d3bf256 ciaddr 0 yiaddr 0 siaddr 0 giaddr 0
Dec 28 11:57:17 udhcpc[2469]:  chaddr 1caff7419b4f00000000000000000000
Dec 28 11:57:17 udhcpc[2469]: Adapter index 13
Dec 28 11:57:17 udhcpc[2469]: MAC 1c:af:f7:41:9b:4f
Dec 28 11:57:17 udhcpc[2469]: Adapter mtu 1500
Dec 28 11:57:17 udhcpc[2469]: Waiting on select...
Dec 28 11:57:22 udhcpc[2469]: Adding option: 0x35 01
Dec 28 11:57:22 udhcpc[2469]: Adding option: 0x3d 011caff7419b4f
Dec 28 11:57:22 udhcpc[2469]: Adding option: 0x0c 4449522d333030
Dec 28 11:57:22 udhcpc[2469]: Adding option: 0x3c 756468637020312e31372e34
Dec 28 11:57:22 udhcpc[2469]: Adding option: 0x39 0240
Dec 28 11:57:22 udhcpc[2469]: Adding option: 0x32 ac1320dc
Dec 28 11:57:22 udhcpc[2469]: Sending discover...
Dec 28 11:57:22 udhcpc[2469]:  hlen 6 xid 1d3bf256 ciaddr 0 yiaddr 0 siaddr 0 giaddr 0
Dec 28 11:57:22 udhcpc[2469]:  chaddr 1caff7419b4f00000000000000000000
Dec 28 11:57:22 udhcpc[2469]: Adapter index 13
Dec 28 11:57:22 udhcpc[2469]: MAC 1c:af:f7:41:9b:4f
Dec 28 11:57:22 udhcpc[2469]: Adapter mtu 1500
Dec 28 11:57:22 udhcpc[2469]: Waiting on select...
Dec 28 11:57:27 udhcpc[2469]: Executing /sbin/udhcpc.sh leasefail
Dec 28 11:57:27 udhcpc[2469]:  interface=eth2.2
Dec 28 11:57:27 udhcpc[2469]: Adapter index 13
Dec 28 11:57:27 udhcpc[2469]: MAC 1c:af:f7:41:9b:4f
Dec 28 11:57:27 udhcpc[2469]: Adapter mtu 1500
Dec 28 11:57:27 udhcpc[2469]: Waiting on select...
Comment 3 Denys Vlasenko 2010-12-29 21:39:28 UTC 
with v1.18.0, I am getting this:

Have a lease, sitting idly:

2010-12-29_16:09:11.05116 Entering listen mode: none
2010-12-29_16:09:11.05377 Waiting on select...

got USR2:

2010-12-29_21:02:58.60089 Waiting on select...
2010-12-29_21:02:58.60097 Unicasting a release of 10.0.0.1 to 10.0.0.138
2010-12-29_21:02:58.60098 Adding option: 0x35 07
2010-12-29_21:02:58.60099 Adding option: 0x36 0a00008a
2010-12-29_21:02:58.60100 Sending release...
2010-12-29_21:02:58.60100  hlen 6 xid 633acdff ciaddr 100000a yiaddr 0 siaddr 0 giaddr 0
2010-12-29_21:02:58.60101  chaddr 001d7dc2ec7000000000000000000000
2010-12-29_21:02:58.60102 Executing /.local/var/service/dhcp_if/dhcp_handler deconfig
2010-12-29_21:02:58.62700  interface=if
2010-12-29_21:02:58.62702 Entering released state
2010-12-29_21:02:58.62703 Entering listen mode: none
2010-12-29_21:02:58.62704 Waiting on select...

Got USR1:

2010-12-29_21:03:05.58054 Waiting on select...
2010-12-29_21:03:05.58057 Performing a DHCP renew
2010-12-29_21:03:05.58058 Entering listen mode: raw
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^your log doesn't have this
2010-12-29_21:03:05.58059 Opening raw socket on ifindex 2
2010-12-29_21:03:05.58060 Got raw socket fd 5
2010-12-29_21:03:05.58061 Attached filter to raw socket fd 5
2010-12-29_21:03:05.58331 Created raw socket
2010-12-29_21:03:05.58334 Adapter index 2
2010-12-29_21:03:05.58335 MAC 00:1d:7d:c2:ec:70
2010-12-29_21:03:05.58336 Adding option: 0x35 01
2010-12-29_21:03:05.58337 Adding option: 0x32 0a000001
2010-12-29_21:03:05.58338 Adding option: 0x39 0240
2010-12-29_21:03:05.58339 Adding option: 0x0c 7a6f72726f
2010-12-29_21:03:05.58340 Sending discover...
2010-12-29_21:03:05.58728  hlen 6 xid 187dc0e1 ciaddr 0 yiaddr 0 siaddr 0 giaddr 0
2010-12-29_21:03:05.58731  chaddr 001d7dc2ec7000000000000000000000
2010-12-29_21:03:05.58927 Waiting on select...
2010-12-29_21:03:08.59232 Adapter index 2
2010-12-29_21:03:08.59236 MAC 00:1d:7d:c2:ec:70
2010-12-29_21:03:08.59236 Adding option: 0x35 01
2010-12-29_21:03:08.59237 Adding option: 0x32 0a000001
2010-12-29_21:03:08.59238 Adding option: 0x39 0240
2010-12-29_21:03:08.59239 Adding option: 0x0c 7a6f72726f
2010-12-29_21:03:08.59240 Sending discover...
2010-12-29_21:03:08.59628  hlen 6 xid 187dc0e1 ciaddr 0 yiaddr 0 siaddr 0 giaddr 0
2010-12-29_21:03:08.60040  chaddr 001d7dc2ec7000000000000000000000
2010-12-29_21:03:08.60043 Waiting on select...
2010-12-29_21:03:11.60132 Adapter index 2
2010-12-29_21:03:11.60134 MAC 00:1d:7d:c2:ec:70
2010-12-29_21:03:11.60135 Adding option: 0x35 01
2010-12-29_21:03:11.60136 Adding option: 0x32 0a000001
2010-12-29_21:03:11.60137 Adding option: 0x39 0240
2010-12-29_21:03:11.60138 Adding option: 0x0c 7a6f72726f
2010-12-29_21:03:11.60139 Sending discover...
2010-12-29_21:03:11.60528  hlen 6 xid 187dc0e1 ciaddr 0 yiaddr 0 siaddr 0 giaddr 0
2010-12-29_21:03:11.60531  chaddr 001d7dc2ec7000000000000000000000
2010-12-29_21:03:11.60735 Waiting on select...
2010-12-29_21:03:11.60737 Got valid DHCP packet
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ and here I've got a responce
2010-12-29_21:03:11.60738  hlen 6 xid 187dc0e1 ciaddr 0 yiaddr 100000a siaddr 8a00000a giaddr 0
2010-12-29_21:03:11.60739  chaddr 001d7dc2ec7000000000000000000000
2010-12-29_21:03:11.60740 Option found: 0x35 02
2010-12-29_21:03:11.60741 Option found: 0x36 0a00008a
...
2010-12-29_21:03:11.63306 Entering listen mode: none
2010-12-29_21:03:11.63514 Waiting on select...


Again, what's your version? udhcpc --help will let you know.
Comment 4 Andrew 2010-12-29 21:44:28 UTC 
I have bb 1.17.4.
Comment 5 Andrew 2011-01-06 14:27:47 UTC 
Ooops, I used patched busybox, and one of patches in tree breaks udhcpc.