udhcpc taking 100% CPU in 1.9.2.7-9

[sesamebike]

Hi,

After upgrading to 1.9.2.7-9 I started to have problem with the udhcpc process taking all CPU. It happends after a about a day or two. Sofar I've restarted the router when it happends after which the udhcpc process behaves correctly for another day or two until it goes havoc again and drains the CPU.

Has anyone else had similar problems with udhcppc in 1.9.2.7-9?

I didn't have this problem with 1.9.2.7-8. I'm running the wl500g which unfortunately isn't supported in the latest 1.9.2.7-10 release.. :(

[wiz]

Hi,

Has anyone else had similar problems with udhcppc in 1.9.2.7-9?


I have seen udhcpd not renewing my ip address, but frankly I did not look at if it would have hogged the cpu or not. All I saw was that I was offline every four ours (lease time is 14400) so I am back at 1.9.2.7-8. A manual renew did the trick though, but to manually renew it is kinda silly.

I also have a wl500g.

[Oleg]

Well, ok. :) wiz, could you please check 1.9.2.7-9 once again? Use top to check CPU usage.

I could prepare test version for the original wl500g with all udhcpc changes rolled back and then add changes one-by-one. Are you ready to perform such tests?

[Oleg]

BTW, could you please type this:

nvram show|grep ^wanx_

and post results?

Also, I need a process list, type

/bin/ps w

[sesamebike]

Hi Oleg,

I'd be happy to help debug this. Note however that I takes about a day before the problem manifest itself for me.

In the meantime, while waiting for it to happen again, here's the info you requested:


[admin@wl500g root]$ nvram show|grep ^wanx_
wanx_gateway=80.252.185.1
size: 10613 bytes (22155 left)



[admin@wl500g root]$ /bin/ps w
PID Uid VmSize Stat Command
1 admin 632 S /sbin/init
2 admin SW [keventd]
3 admin RWN [ksoftirqd_CPU0]
4 admin SW [kswapd]
5 admin SW
6 admin SW [kupdated]
7 admin SW [mtdblockd]
45 admin 380 S httpd eth1
46 admin 552 S nas /tmp/nas.lan.conf /tmp/nas.lan.pid lan
50 admin 408 S syslogd -m 0 -O /tmp/syslog.log -S -l 7
51 admin 360 S klogd
53 nobody 484 S [dnsmasq]
54 admin SW [khubd]
70 admin SW [usb-storage-0]
71 admin SW [scsi_eh_0]
109 admin 468 S watchdog
112 admin 344 S ntp
128 admin 400 S dropbear -s
129 admin 436 S crond
143 admin SW [usb-storage-1]
144 admin SW [scsi_eh_1]
168 admin 436 S udhcpc -i eth1 -p /var/run/udhcpc0.pid -s /tmp/udhcpc
174 admin SW [kjournald]
175 admin SW [kjournald]
203 admin 412 S /opt/sbin/httpd -c /opt/etc/httpd.conf -p 8080 -h /opt/web
270 admin 692 R dropbear -s
271 admin 548 S -sh
290 admin 392 R /bin/ps w

I double checked my iptables settings and realised that this might be the culprit:


Chain INPUT (policy DROP 0 packets, 0 bytes)
pkts bytes target prot opt in out source destination
0 0 logdrop all -- * * 0.0.0.0/0 0.0.0.0/0 state INVALID
3416 399K ACCEPT all -- * * 0.0.0.0/0 0.0.0.0/0 state RELATED,ESTABLISHED
240 14400 ACCEPT all -- lo * 0.0.0.0/0 0.0.0.0/0 state NEW
170 13877 ACCEPT all -- br0 * 0.0.0.0/0 0.0.0.0/0 state NEW
68 23238 SECURITY all -- eth1 * 0.0.0.0/0 0.0.0.0/0 state NEW
[B] 0 0 DROP udp -- eth1 * 0.0.0.0/0 255.255.255.255 udp spt:67 dpt:68
37 13712 DROP udp -- eth1 * 0.0.0.0/0 255.255.255.255 udp spt:68 dpt:67

I'll remove the UDP rules for port 67/68 in order to eliminate it as a probable source of the problem.

[wiz]

Well, ok. :) wiz, could you please check 1.9.2.7-9 once again? Use top to check CPU usage.

I could prepare test version for the original wl500g with all udhcpc changes rolled back and then add changes one-by-one. Are you ready to perform such tests?

Sure, but give me time for that as I currently will be using the internet connection to work from home. Nearer the weekend I will have opportunity to have a closer look at this to see if we can trace this odd behaviour.

And off course I am willing to test and put different stuff on my wl500 to see if we can get this working stable.

cheers,

Wiz

[Oleg]

0 0 DROP udp -- eth1 * 0.0.0.0/0 255.255.255.255 udp spt:67 dpt:68
37 13712 DROP udp -- eth1 * 0.0.0.0/0 255.255.255.255 udp spt:68 dpt:67

I'll remove the UDP rules for port 67/68 in order to eliminate it as a probable source of the problem.
Hm. Do you've something in the post-firewall? Could you please post

cat /tmp/filter_rules ?

[sesamebike]

Hi Oleg,

Yes I did put the following lines in my post-firewall


iptables -I INPUT 8 -i "$1" -d 255.255.255.255 -p udp --sport 68 --dport 67 -j DROP
iptables -I INPUT 8 -i "$1" -d 255.255.255.255 -p udp --sport 67 --dport 68 -j DROP

I remember why I did this. The first line is filtering out broadcasts from other dhcp clients on the network. The other line is actually pointless as there's no broadcasting to port 68 in the dhcp protocol. Anyway I put these lines in there deliberately since I wanted to remove them from the default logdrop rules which were flooding the syslog. (I send my iptables logs to dshield, http://isc.sans.org/howto.html every hour)

Anyway I'ts now happened again:


Mem: 13304K used, 660K free, 0K shrd, 1240K buff, 5364K cached
CPU: 97% usr 2% sys 0% nice 0% idle 0% io 0% irq 0% softirq
Load average: 1.65 1.53 1.25
PID PPID USER STAT VSZ %MEM %CPU COMMAND
166 1 admin R 2712 19% 98% udhcpc -i eth1 -p /var/run/udhcpc0.pi
2253 2238 admin R 1792 13% 2% top
50 1 admin S 2700 19% 0% syslogd -m 0 -O /tmp/syslog.log -S -l
2237 131 admin S 1824 13% 0% dropbear -s
2238 2237 admin S 2736 20% 0% -sh
132 1 admin S 2716 19% 0% crond
51 1 admin S 2696 19% 0% klogd
110 1 admin S 2380 17% 0% watchdog
1 0 admin S 2380 17% 0% /sbin/init
112 110 admin S 2372 17% 0% ntp
45 1 admin S 1932 14% 0% httpd eth1
46 1 admin S 1900 14% 0% nas /tmp/nas.lan.conf /tmp/nas.lan.pi
197 1 admin S 1788 13% 0% /opt/sbin/httpd -c /opt/etc/httpd.con
131 1 admin S 1752 13% 0% dropbear -s
53 1 nobody S 960 7% 0% [dnsmasq]
70 1 admin SW 0 0% 0% [usb-storage-0]
3 1 admin RWN 0 0% 0% [ksoftirqd_CPU0]
7 1 admin SW 0 0% 0% [mtdblockd]
171 1 admin SW 0 0% 0% [kjournald]
4 1 admin SW 0 0% 0% [kswapd]


There's nothing unusal in the /tmp/syslog.log. I'll keep the system running like this for a while in case you need me to extract any additional data.

[sesamebike]

Sorry, I needed to free CPU resources and killed the udhcpc process. When starting it manually I get:


[admin@wl500g /]$ udhcpc -i eth1 -p /var/run/udhcpc0.pid -s /tmp/udhcpc
udhcpc (v0.9.9-pre) started
eth1: No such process
Sending discover...
Sending select for 80.252.185.xxx...
Lease of 80.252.185.xxx obtained, lease time 43200
(full ipaddress censored out by me)

Is the output "eth1: No such process" anything to worry about?

[sesamebike]

Hi again,

Altough it did compain about eth1 it seems to be working ok. I can force a renewal by sending it SIGUSR1 as described in the source (http://busybox.net/cgi-bin/viewcvs.cgi/trunk/udhcp/README.udhcpc?rev=15050&view=auto).


[admin@wl500g root]$ kill -SIGUSR1 `pidof udhcpc`


[admin@wl500g root]$ tail /tmp/syslog.log
Apr 1 18:38:21 udhcpc[2588]: Performing a DHCP renew
Apr 1 18:38:21 udhcpc[2588]: Lease of 80.252.185.xxx obtained, lease time 43200
Apr 1 18:38:21 dnsmasq[53]: read /etc/hosts - 11 addresses
Apr 1 18:38:21 dnsmasq[53]: read /etc/ethers - 6 addresses
Apr 1 18:38:21 dnsmasq[53]: reading /tmp/resolv.conf
Apr 1 18:38:21 dnsmasq[53]: using nameserver 80.252.160.164#53
Apr 1 18:38:21 dnsmasq[53]: using nameserver 80.252.160.162#53
Apr 1 18:38:22 iptables: Running post-firewall script
Apr 1 18:38:24 dhcp client: bound IP : 80.252.185.xxx from 80.252.185.1

Note that there seems to be a bug here somewhere, why is the firewall reconfigured when the DHCP client renewed the IP-adress? Intuitively it only needs to done when udhcpc issues deconfig, bound or nak. I would prefer if the firewall wasn't reconfigured as a result of udhcpc renew but that's maybe more of an opinion about function than an actual bug.

Bug or not, I haven't found a way to trigger the problem other than waiting for it to happen.

[sesamebike]

Small update:

I've found that if the process is in the havoc mode and runs with 100% cpu, then sending a SIGUSR1 to it thus forcing it to renew the address, actually solves it.

I have now a workaround with a cronjob that checks regulary if the udhcpc process is consuming all resources, if so it send SIGUSR1 to it.

[Oleg]

I need

cat /tmp/filter_rules

output.

There should be dhcp related rule which is missing in the iptables output. Also, disable your post-firewall completely for testing.

[sesamebike]

Hi Oleg,

Thanks again for your time.


[admin@wl500g root]$ cat /tmp/filter_rules
*filter
:INPUT ACCEPT [0:0]
:FORWARD ACCEPT [0:0]
:OUTPUT ACCEPT [0:0]
:MACS - [0:0]
:SECURITY - [0:0]
:logaccept - [0:0]
:logdrop - [0:0]
-A SECURITY -p tcp --syn -m limit --limit 1/s -j RETURN
-A SECURITY -p tcp --tcp-flags SYN,ACK,FIN,RST RST -m limit --limit 1/s -j RETUR N
-A SECURITY -p udp -m limit --limit 5/s -j RETURN
-A SECURITY -p icmp -m limit --limit 5/s -j RETURN
-A SECURITY -j logdrop
-A INPUT -m state --state INVALID -j logdrop
-A INPUT -m state --state ESTABLISHED,RELATED -j ACCEPT
-A INPUT -i lo -m state --state NEW -j ACCEPT
-A INPUT -i br0 -m state --state NEW -j ACCEPT
-A INPUT -i eth1 -m state --state NEW -j SECURITY
-A INPUT -p udp --sport 67 --dport 68 -j ACCEPT
-A INPUT -j logdrop
-A FORWARD -i br0 -o br0 -j ACCEPT
-A FORWARD -m state --state INVALID -j logdrop
-A FORWARD -m state --state ESTABLISHED,RELATED -j ACCEPT
-A FORWARD -o eth1 ! -i br0 -j logdrop
-A FORWARD ! -i br0 -m state --state NEW -j SECURITY
-A FORWARD -m conntrack --ctstate DNAT -j ACCEPT
-A FORWARD -o br0 -j logdrop
-A logaccept -m state --state NEW -j LOG --log-prefix "ACCEPT " --log-tcp-sequen ce --log-tcp-options --log-ip-options
-A logaccept -j ACCEPT
-A logdrop -m state --state NEW -j LOG --log-prefix "DROP " --log-tcp-sequence - -log-tcp-options --log-ip-options
-A logdrop -j DROP
COMMIT


[admin@wl500g root]$ cat /usr/local/sbin/post-firewall
#!/bin/sh
logger -t iptables -p user.notice "Running post-firewall script"
iptables -I INPUT 6 -i "$1" -s xxxxxx-d "$2" -p tcp --syn --dport 22 -j logaccept
iptables -R INPUT 7 -i "$1" -d "$2" -p tcp --syn --dport 21 -j logaccept
iptables -t nat -A PREROUTING -i "$1" -p tcp --dport 8080 -j DROP
iptables -t nat -A VSERVER -p tcp --dport 80 -j REDIRECT --to-ports 8080
iptables -I INPUT 8 -i "$1" -d "$2" -p tcp --syn --dport 8080 -j ACCEPT
iptables -I INPUT 8 -i "$1" -d 255.255.255.255 -p udp --sport 68 --dport 67 -j DROP
iptables -I INPUT 8 -i "$1" -d 255.255.255.255 -p udp --sport 67 --dport 68 -j DROP
iptables -I INPUT 6 -i "$1" -s yyyyyy -d "$2" -p tcp --syn --dport 22 -j logaccept
iptables -I SECURITY -i "$1" -d "$2" -p tcp --syn --dport 8080 -j RETURN
if [ -f /etc/blacklist ]; then
awk '{ print "iptables -I SECURITY -s " $1 " -j logdrop" }' /etc/blacklist | /bin/sh
fi
iptables -P INPUT DROP
(some adresses censored by me)

The /etc/blacklist blocks out certain ip ranges which has has been known for trying to doing bruteforce attacks against my machine:


[admin@wl500g root]$ cat /etc/blacklist
60.0.0.0/8
61.0.0.0/8
66.150.0.0/15
81.29.229.1
85.255.112.0/14
133.0.0.0/8
155.158.0.0/16
193.86.0.0/16
202.0.0.0/8
203.0.0.0/8
204.16.208.0/22
218.0.0.0/8
219.0.0.0/8
220.0.0.0/8
221.0.0.0/8
222.0.0.0/8

Yes, you're line seems to be there in /tmp/filter_rules. However I've accidently overwrite it in the post-firewall script. My mistake.

However, doesn't the fact that a SIGUSR signal seems to kick the udhcpc process back to normal indicate that it's not a firewall problem?

Anyway, I'll update/disable my post-firewall too see if it solves the problem.

Hopefully this was all due to my bad post-firewall settings. I'll post an update to verify this later when it has run for a while.

[sesamebike]

Nope, today the same thing happened.


Mem: 13536K used, 428K free, 0K shrd, 1372K buff, 6200K cached
CPU: 99% usr 0% sys 0% nice 0% idle 0% io 0% irq 0% softirq
Load average: 1.14 1.04 1.01
PID PPID USER STAT VSZ %MEM %CPU COMMAND
2588 1 admin R 2712 19% 98% udhcpc -i eth1 -p /var/run/udhcpc0.pi
10007 10003 admin R 1792 13% 1% top



[admin@wl500g root]$ iptables -L INPUT -v -n
Chain INPUT (policy DROP 0 packets, 0 bytes)
pkts bytes target prot opt in out source destination
0 0 logdrop all -- * * 0.0.0.0/0 0.0.0.0/0 state INVALID
63948 7810K ACCEPT all -- * * 0.0.0.0/0 0.0.0.0/0 state RELATED,ESTABLISHED
5216 313K ACCEPT all -- lo * 0.0.0.0/0 0.0.0.0/0 state NEW
256 21076 ACCEPT all -- br0 * 0.0.0.0/0 0.0.0.0/0 state NEW
21615 2044K SECURITY all -- eth1 * 0.0.0.0/0 0.0.0.0/0 state NEW
0 0 ACCEPT udp -- * * 0.0.0.0/0 0.0.0.0/0 udp spt:67 dpt:68
0 0 logaccept tcp -- eth1 * x.x.x.x 80.252.185.xxx tcp dpt:22 flags:0x16/0x02
74 4216 ACCEPT tcp -- eth1 * 0.0.0.0/0 80.252.185.xxx tcp dpt:8080 flags:0x16/0x02
1 48 logaccept tcp -- eth1 * y.y.y.y 80.252.185.xxx tcp dpt:22 flags:0x16/0x02
20287 1900K logdrop all -- * * 0.0.0.0/0 0.0.0.0/0

[Oleg]

Try this one: http://oleg.wl500g.info/wlhdd/WL500g-1.9.2.7-9.2.1.trx

[sesamebike]

ok, it's installed now. I'll keep you posted.

[dholliday]

Hi,

After upgrading to 1.9.2.7-9 I started to have problem with the udhcpc process taking all CPU. It happends after a about a day or two. Sofar I've restarted the router when it happends after which the udhcpc process behaves correctly for another day or two until it goes havoc again and drains the CPU.

Has anyone else had similar problems with udhcppc in 1.9.2.7-9?

I didn't have this problem with 1.9.2.7-8. I'm running the wl500g which unfortunately isn't supported in the latest 1.9.2.7-10 release.. :(

Hello Oleg!

First I have to thank you and to others who contributed to such great firmwares.
I'll tell you my story about this release.
I was using 1.9.2.7-6b for a long time and for my purposes it was working fine. I didn't have any troubles. Some time ago I migrate to 1.9.2.7-7g and also didn't have problems, except with UPnP which was sometimes working and sometimes didn't (any kind of reset didn’t help). So I wanted to load 1.9.2.7-8, but when I came to this forum I saw that there is newer release. I skipped release 8 and took 1.9.2.7-9, especially because I saw that there are some changes in UPnP (as I explained release notes to me), no more stupid-ftp and support for USB storage with ftp turned off (without manual loading services).
Anyway, I reset my router WL-500g to factory default at web page and with button, flash the new firmware (at web page) and did a quick configuration. Everything worked well, also UPnP. Then I entered all my old settings (manually, but all at once) and UPnP didn’t work, again. I was playing little with settings and I realized that when I turn on WDS (because of my friend with WL-500gP), UPnP didn’t work and when I turned it off it was working well. After reset (turn off electricity) it started to work well (WDS on). After I solved this, I plug USB hub with USB stick and USB disk (ordinary disk in USB case). I followed Wengi-s tutorial to install optware packages. I put /opt on USB stick, swap on disk and installed these packages (vsftp turned off):


[dholliday@mig root]$ ipkg list_installed
ipkg-opt - 0.99.163-9 - The Itsy Package Manager
nano - 2.1.0-1 - A pico like editor
ncurses - 5.6-3 - NCurses libraries
openssh-sftp-server - 4.9p1-1 - sftp-server only from a FREE version of the SSH protocol suite of network connectivity tools.
openssl - 0.9.7m-3 - Openssl provides the ssl implementation in libraries libcrypto and libssl, and is needed by many other applications and librari
uclibc-opt - 0.9.28-13 - micro C library for embedded Linux systems
zlib - 1.2.3-2 - zlib is a library implementing the 'deflate' compression system.


When I tried to connect with sftp, it didn’t work (I realized that problem was disk, because it have some troubles and sometimes work and sometimes don’t. Because of disk failure, partitions didn’t mount correct – different dev ID – and I stayed without /opt directory – this partition was auto mounted). I disconnected disk, remount partitions and tried to connect with sftp. I was also looking if correct process was started. Sftp connected, but then I saw that udhcpc is taking 100% of CPU. I restarted router and another try of sftp. Soon udhcpc take 100%. Did this once more and the result was equal. Today I didn’t run sftp, but udhcpc is taking 100 % again after about 16 hours after reboot. So I don’t know if this is somehow connected. I also notice once, that UPnP showed some strange IP (in win xp UPnP status) of my friend computer. IP assigned via dhcp was correct (as I set it in manual assignment at web page settings), but program BCDC++, which opened ports showed IP 0.1.0.1 (in win xp UPnP status). Also don’t know if this has some meaning.
My post-firewall file exist but it’s empty. Post-boot has only dropbear and pre-mount line with /opt mount.


Load average: 1.40, 1.20, 1.13 (State: S=sleeping R=running, W=waiting)

PID USER STATUS RSS PPID %CPU %MEM COMMAND
86 dhollida R 428 1 92.4 3.0 udhcpc
13772 dhollida R 444 12434 1.9 3.1 top
109 dhollida S 556 1 1.3 3.9 upnp
12433 dhollida S 728 105 0.5 5.2 dropbear
89 dhollida S 552 1 0.1 3.9 watchdog
48 dhollida S 428 1 0.1 3.0 httpd
3 dhollida SWN 0 1 0.1 0.0 ksoftirqd_CPU0
87 dhollida S 656 1 0.0 4.6 pppd
1 dhollida S 640 0 0.0 4.5 init
12434 dhollida S 576 12433 0.0 4.1 sh
56 nobody S 492 1 0.0 3.5 dnsmasq
52 dhollida S 404 1 0.0 2.8 syslogd
105 dhollida S 404 1 0.0 2.8 dropbear
53 dhollida S 364 1 0.0 2.6 klogd
92 dhollida S 344 89 0.0 2.4 ntp
43 dhollida S 312 1 0.0 2.2 telnetd
7 dhollida SW 0 1 0.0 0.0 mtdblockd
4 dhollida SW 0 1 0.0 0.0 kswapd
75 dhollida SW 0 1 0.0 0.0 usb-storage-0
2 dhollida SW 0 1 0.0 0.0 keventd



[dholliday@mig root]$ nvram show|grep ^wanx_
wanx_ipaddr=0.0.0.0
size: 11123 bytes (21645 left)


[dholliday@mig root]$ /bin/ps w
PID Uid VmSize Stat Command
1 dhollida 640 S /sbin/init
2 dhollida SW [keventd]
3 dhollida SWN [ksoftirqd_CPU0]
4 dhollida SW [kswapd]
5 dhollida SW [bdflush]
6 dhollida SW [kupdated]
7 dhollida SW [mtdblockd]
43 dhollida 312 S telnetd
48 dhollida 428 S httpd eth1
52 dhollida 404 S syslogd -m 0 -O /tmp/syslog.log -S -l 7
53 dhollida 364 S klogd
56 nobody 492 S [dnsmasq]
61 dhollida SW [khubd]
75 dhollida SW [usb-storage-0]
76 dhollida SW [scsi_eh_0]
86 dhollida 428 R udhcpc -i eth1 -p /var/run/udhcpc0.pid -s /tmp/udhcpc -b
87 dhollida 656 S pppd file /tmp/ppp/options.wan0
89 dhollida 556 S watchdog
92 dhollida 344 S ntp
105 dhollida 404 S dropbear
109 dhollida 556 S upnp -D -L br0 -W ppp0
115 dhollida SW [kjournald]
12433 dhollida 728 S dropbear
12434 dhollida 576 S -sh
14213 dhollida 392 R /bin/ps w


[dholliday@mig root]$ cat /tmp/filter_rules
*filter
:INPUT ACCEPT [0:0]
:FORWARD ACCEPT [0:0]
:OUTPUT ACCEPT [0:0]
:MACS - [0:0]
:SECURITY - [0:0]
:logaccept - [0:0]
:logdrop - [0:0]
-A SECURITY -p tcp --syn -m limit --limit 1/s -j RETURN
-A SECURITY -p tcp --tcp-flags SYN,ACK,FIN,RST RST -m limit --limit 1/s -j RETURN
-A SECURITY -p udp -m limit --limit 5/s -j RETURN
-A SECURITY -p icmp -m limit --limit 5/s -j RETURN
-A SECURITY -j DROP
-A INPUT -m state --state INVALID -j DROP
-A INPUT -m state --state ESTABLISHED,RELATED -j ACCEPT
-A INPUT -i lo -m state --state NEW -j ACCEPT
-A INPUT -i br0 -m state --state NEW -j ACCEPT
-A INPUT -i ppp0 -m state --state NEW -j SECURITY
-A INPUT -p udp --sport 67 --dport 68 -j ACCEPT
-A INPUT -j DROP
-A FORWARD -i br0 -o br0 -j ACCEPT
-A FORWARD -m state --state INVALID -j DROP
-A FORWARD -p tcp --syn -j TCPMSS --clamp-mss-to-pmtu
-A FORWARD -m state --state ESTABLISHED,RELATED -j ACCEPT
-A FORWARD -o ppp0 ! -i br0 -j DROP
-A FORWARD -o eth1 ! -i br0 -j DROP
-A FORWARD ! -i br0 -m state --state NEW -j SECURITY
-A FORWARD -m conntrack --ctstate DNAT -j ACCEPT
-A FORWARD -o br0 -j DROP
-A logaccept -m state --state NEW -j LOG --log-prefix "ACCEPT " --log-tcp-sequence --log-tcp-options --log-ip-options
-A logaccept -j ACCEPT
-A logdrop -m state --state NEW -j LOG --log-prefix "DROP " --log-tcp-sequence --log-tcp-options --log-ip-options
-A logdrop -j DROP
COMMIT

I didn’t try anything to solve this, except reboot. Tomorrow I’ll try new firmware that you gave it in post before.
I hope this long story will help you and that this problem will be solved. Thank you again and sorry for my bad English and such a long novel. :D

[Oleg]

Well, I see now. Thank you for your report.

Btw, another idea: could you please attach strace to udhcpc while it takes 100%? Use 1.9.2.7-9 version.

You should install strace package first, then check udhcpc pid and type

strace -p udhcpc_pid

Perhaps something weird happen with udhcpc timers...

[dholliday]

Well, I see now. Thank you for your report.

Btw, another idea: could you please attach strace to udhcpc while it takes 100%? Use 1.9.2.7-9 version.

You should install strace package first, then check udhcpc pid and type

strace -p udhcpc_pid

Perhaps something weird happen with udhcpc timers...

Hi


Mem: 11872K used, 2092K free, 0K shrd, 1384K buff, 4144K cached
Load average: 1.42, 1.23, 1.13 (State: S=sleeping R=running, W=waiting)

PID USER STATUS RSS PPID %CPU %MEM COMMAND
86 dhollida R 428 1 77.8 3.0 udhcpc
14656 dhollida R 432 12434 7.3 3.0 top
14658 dhollida R 304 92 2.7 2.1 ntpclient
89 dhollida S 560 1 0.9 4.0 watchdog
12433 dhollida S 728 105 0.0 5.2 dropbear
87 dhollida S 656 1 0.0 4.6 pppd
1 dhollida S 640 0 0.0 4.5 init
12434 dhollida S 576 12433 0.0 4.1 sh
109 dhollida S 556 1 0.0 3.9 upnp
56 nobody S 492 1 0.0 3.5 dnsmasq
48 dhollida S 428 1 0.0 3.0 httpd
52 dhollida S 404 1 0.0 2.8 syslogd
105 dhollida S 404 1 0.0 2.8 dropbear
53 dhollida S 364 1 0.0 2.6 klogd
92 dhollida S 344 89 0.0 2.4 ntp
43 dhollida S 312 1 0.0 2.2 telnetd
3 dhollida SWN 0 1 0.0 0.0 ksoftirqd_CPU0
7 dhollida SW 0 1 0.0 0.0 mtdblockd
4 dhollida SW 0 1 0.0 0.0 kswapd
75 dhollida SW 0 1 0.0 0.0 usb-storage-0
2 dhollida SW 0 1 0.0 0.0 keventd
5 dhollida SW 0 1 0.0 0.0 bdflush
76 dhollida SW 0 1 0.0 0.0 scsi_eh_0
115 dhollida SW 0 1 0.0 0.0 kjournald
6 dhollida SW 0 1 0.0 0.0 kupdated
61 dhollida SW 0 1 0.0 0.0 khubd
[dholliday@mig root]$ strace -p 86
Process 86 attached - interrupt to quit
Process 86 detached

This is what I get. Should I wait more time or paste something else? I interrupted it after minute.

EDIT: I forgot to tell you that I have disabled virtual server all the time and that I have all the time one port forwarded. I added port manually via UPnP in win xp, but not "used" it yet.
Also forgot, that my WAN IP is dynamic (change every 24 hours regardless of my connection – no manual disconnect or reboot – IP is changed after 24 hours of being connected to my isp…)

[sesamebike]

Status update:


[admin@wl500g root]$ uptime
11:10:23 up 16:10, load average: 0.00, 0.00, 0.00

The system has now been up 16 hours, my lease time is 12 hours. So far everything looks great. With the 1.9.2.7-9 firmware I would have seen udhcpc consuming all resources by now.

So a big thank you again to you Oleg.

PS:
Out of curiosity i I noticed the following difference:

With 1.9.2.7-9:

[admin@wl500g root]$ ls -al /proc/`pidof udhcpc`/fd/
dr-x------ 2 admin root 0 Apr 3 13:32 .
dr-xr-xr-x 3 admin root 0 Apr 3 13:32 ..
lrwx------ 1 admin root 64 Apr 3 13:32 0 -> /dev/null
lrwx------ 1 admin root 64 Apr 3 13:32 1 -> /dev/null
lrwx------ 1 admin root 64 Apr 3 13:32 2 -> /dev/null
lrwx------ 1 admin root 64 Apr 3 13:32 3 -> socket:[74496]
lrwx------ 1 admin root 64 Apr 3 13:32 4 -> socket:[74498]
lrwx------ 1 admin root 64 Apr 3 13:32 5 -> socket:[74499]
l-wx------ 1 admin root 64 Apr 3 13:32 7 -> pipe:[68617]

With 1.9.2.7-9.2.1:

[admin@wl500g root]$ ls -la /proc/`pidof udhcpc`/fd/
dr-x------ 2 admin root 0 Apr 4 11:07 .
dr-xr-xr-x 3 admin root 0 Apr 4 11:07 ..
lrwx------ 1 admin root 64 Apr 4 11:07 0 -> /dev/null
lrwx------ 1 admin root 64 Apr 4 11:07 1 -> /dev/null
lrwx------ 1 admin root 64 Apr 4 11:07 2 -> /dev/null
lrwx------ 1 admin root 64 Apr 4 11:07 3 -> /dev/nvram
lrwx------ 1 admin root 64 Apr 4 11:07 4 -> socket:[457]
lrwx------ 1 admin root 64 Apr 4 11:07 5 -> socket:[459]
lrwx------ 1 admin root 64 Apr 4 11:07 6 -> socket:[460]

It seems that the PIPE is replaced with reading /dev/nvram. I guess that is what was causing the problem?

[Oleg]

The system has now been up 16 hours, my lease time is 12 hours. So far everything looks great. With the 1.9.2.7-9 firmware I would have seen udhcpc consuming all resources by now.

We need to continue testing, as I need this new functionality, which is removed now. I would prepare new version later, so please test it again.

[Oleg]

This is what I get. Should I wait more time or paste something else? I interrupted it after minute.

No, it's enough. It seems to be spinning inside the udhcpc itself.

I would prepare newer test version.

[wiz]

Oleg, do you want me to test with cr9 again or do you want to wait until the above is done?

cheers,

Wiz

[Oleg]

Well, test 9.2.1 version: I need be sure, that it's working for you too and this is actually the same problem. Later I would upload 9.2.2 with some newer functionality enabled.

[sesamebike]

We need to continue testing, as I need this new functionality, which is removed now. I would prepare new version later, so please test it again.

I'd be honoured to continue helping with the testing. Awaiting further instructions.

[wiz]

Well, test 9.2.1 version: I need be sure, that it's working for you too and this is actually the same problem. Later I would upload 9.2.2 with some newer functionality enabled.

Ok, it is running here now, 1.9.2.7-9.2.1 is in. I have moved the messages as I run logrotate, so we should have a clean messages file.

Will update in a couple of hours to see if renewalls take place.

cheers,

Wiz

[Oleg]

Ok, try 9.2.2 and 9.2.3. Start with 9.2.3 and if it works, then there is no need to check 9.2.2.

[dholliday]

I'm also running 9.2.1. Sftp is not making troubles with udhcpc. I can't tell you more:


Fri, 04 Apr 2008 18:35:35 +0100(28 minutes, 15 seconds since boot)

Let's wait and see what will hapen. :)

BTW: what has been changed in 1.9.2.7-9 firmware, that Asus utility Device Discovery don’t see my router, but it sees my friend 500gp? Or I just have some wrong settings? Not that I need this utility, I’m just curious. :D

EDIT: Oh, I'm behind a time, I'll try 9.2.3...

[wiz]

Ok, try 9.2.2 and 9.2.3. Start with 9.2.3 and if it works, then there is no need to check 9.2.2.


the 1 does the job, roughly 2 hours ago was the last boot:


Apr 4 21:14:57 udhcpc[131]: Lease of <MYADDRESS> obtained, lease time 14400

So that one works. Will test the others throughout this weekend Oleg.

Thanks anyway for all the extra effort you put in!

cheers,

Wiz

[sesamebike]

ok, here we go


[admin@wl500g root]$ nvram get boot_local
1.9.2.7-9.2.3


[admin@wl500g root]$ ls -la /proc/`pidof udhcpc`/fd
lrwx------ 1 admin root 64 Apr 4 22:01 0 -> /dev/null
lrwx------ 1 admin root 64 Apr 4 22:01 1 -> /dev/null
lrwx------ 1 admin root 64 Apr 4 22:01 2 -> /dev/null
lrwx------ 1 admin root 64 Apr 4 22:01 3 -> /dev/nvram
lrwx------ 1 admin root 64 Apr 4 22:01 4 -> socket:[484]
lrwx------ 1 admin root 64 Apr 4 22:01 5 -> socket:[486]
lrwx------ 1 admin root 64 Apr 4 22:01 6 -> socket:[487]


[admin@wl500g root]$ uptime
22:02:28 up 7 min, load average: 0.00, 0.04, 0.02

I'll leave it running for a while now.

[wiz]

Ok, try 9.2.2 and 9.2.3. Start with 9.2.3 and if it works, then there is no need to check 9.2.2.

Right, version 1.9.2.7-9.2.3 is in at the moment, will evaluate this today to see what happens.

cheers,

Wiz

[dholliday]

Release 9.2.3 works OK for now. udhcpc does not take all CPU


[dholliday@mig root]$ uptime
13:45:03 up 17:20, load average: 0.02, 0.01, 0.00

[wiz]

well, not if you use automatic IP. I am half way past the leasetime, so it is time for renewalls.

this is what I see:

http://www.geocities.com/the_wizard_oz/files/snapshot3.png

I'll proceed in putting the 9.2.2 version in to see if that works.

regards,

wiz

[sesamebike]

1.9.2.7-9.2.3 doesn't work for me either.


Mem: 13696K used, 268K free, 0K shrd, 2088K buff, 5648K cached
CPU: 98% usr 1% sys 0% nice 0% idle 0% io 0% irq 0% softirq
Load average: 1.46 1.19 1.07
PID PPID USER STAT VSZ %MEM %CPU COMMAND
176 1 admin R 2712 19% 98% udhcpc -i eth1 -p /var/run/udhcpc0.pi
3342 3339 admin R 1792 13% 1% top


[admin@wl500g root]$ uptime
18:45:36 up 20:49, load average: 1.08, 1.13, 1.06

I'll load 9.2.2 now.

[wiz]

9.2.2 does exactly the same here.

So far the only one that worked was 9.2.1.

I'll put that one back in in a minute. So 9.2.2 does clog the cpu when it is renewall time too..

[Oleg]

Uploaded 9.2.4, try it too.

[wiz]

Uploaded 9.2.4, try it too.

ok, will put that one in.

cheers,

wiz

[wiz]

9.2.4 works for me!


Apr 5 23:30:39 udhcpc[143]: Lease of myIPaddress obtained, lease time 14400
Apr 6 01:30:42 udhcpc[143]: Lease of myIPaddress obtained, lease time 14400
Apr 6 03:30:44 udhcpc[143]: Lease of myIPaddress obtained, lease time 14400
Apr 6 05:30:47 udhcpc[143]: Lease of myIPaddress obtained, lease time 14400
Apr 6 07:30:49 udhcpc[143]: Lease of myIPaddress obtained, lease time 14400


cheers,

Wiz

[sesamebike]

Wiz is one step ahead of me. I can confirm that 9.2.2 doesn't work for me either. I'll load 9.2.4 now.

[Oleg]

Ok, try 9.2.5 now. :)

[wiz]

will do that tomorrow. If that one does not work I don't have time to fix it until I get back from work, so tomorrow afternoon that one will go in.

Will keep you posted Oleg.

cheers,

Wiz

[sesamebike]

9.2.4 seems to work for me as well. Been running it for 23 hours now without any excessive cpu usage from udhcpc.

I'll load 9.2.5 now anyway. Anything in particular that I should look for?

[Oleg]

Just flash it. 9.2.5 seems to be the final in this saga.

[dholliday]

Afternoon I'll try 9.2.5, but I don't have problems even with 9.2.3. Anyway, I'll try it and if it'll work I'll keep 9.2.5 or which would be the final version in this super fast problem solving saga. I can't even keep up with all new releases. :o

Thank you very much, Oleg!
Thanks also to others who are testing new releases.
:)

[wiz]

9.2.5 is in at the moment. see what happens over the next couple of hours.

[sesamebike]

9.2.5 seems to be working here.


[admin@wl500g root]$ uptime
20:55:40 up 12:33, load average: 0.06, 0.01, 0.00
[admin@wl500g root]$ grep udhcp /tmp/syslog.log
Jan 1 01:00:12 udhcpc[114]: udhcpc (v0.9.9-pre) started
Jan 1 01:00:13 udhcpc[114]: Lease of 80.252.185.xxx obtained, lease time 43200
Apr 7 14:21:58 udhcpc[179]: Lease of 80.252.185.xxx obtained, lease time 43200
Apr 7 20:22:04 udhcpc[179]: Lease of 80.252.185.xxx obtained, lease time 43200

Well done Oleg! Thanks for all your work.

[wiz]

9.2.5 works like a charm here too:


Apr 7 18:31:00 udhcpc[135]: Lease of MyIP obtained, lease time 14400
Apr 7 20:31:03 udhcpc[135]: Lease of MyIP obtained, lease time 14400
Apr 7 22:31:06 udhcpc[135]: Lease of MyIp obtained, lease time 14400

cheers,

Wiz

[sesamebike]

Hi dholliday,

Please try to honour the one topic per thread rule in the forum. Better to consider this thread closed, marked as [solved] and instead create a new thread where you describe your upnp problem. No one benefits from a megalong thread covering a mishmash of problems with no resolution.

[cookabarra]

will this fix be available for WLHDD?