udhcpc taking 100% CPU in 1.9.2.7-9

udhcpc taking 100% CPU in 1.9.2.7-9 [solved]

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.. :(

Quote:

Originally Posted by sesamebike

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.

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?

BTW, could you please type this:

nvram show|grep ^wanx_

and post results?

Also, I need a process list, type

/bin/ps w

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:

Code:

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

Code:

[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 [bdflush] 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:

Code:

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 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.

Quote:

Originally Posted by 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?

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

Quote:

Originally Posted by sesamebike

Code:

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 ?

Hi Oleg,

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

Code:

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:

Code:

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.

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

Code:

[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?

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.

Code:

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

Code:

[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.

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.

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.

Hi Oleg,

Thanks again for your time.

Code:

[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

Code:

[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:

Code:

[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.

Nope, today the same thing happened.

Code:

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

Code:

[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

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

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

Quote:

Originally Posted by 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.. :(

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):

Code:

[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.

Code:

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

Code:

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

Code:

[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

Code:

[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

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...

Quote:

Originally Posted by 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...

Hi

Code:

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…)

Status update:

Code:

[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:

Code:

[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:

Code:

[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?

Quote:

Originally Posted by sesamebike

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.

Quote:

Originally Posted by dholliday

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.

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

cheers,

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.

Quote:

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.

Quote:

Originally Posted by 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.

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

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.

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

Code:

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...

Quote:

Originally Posted by 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.

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

Code:

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

ok, here we go

Code:

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

Code:

[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]

Code:

[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.

Quote:

Originally Posted by 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.

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

cheers,

Wiz

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

Code:

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

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_.../snapshot3.png

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

regards,

wiz

1.9.2.7-9.2.3 doesn't work for me either.

Code:

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

Code:

[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.

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..

Uploaded 9.2.4, try it too.

Quote:

Originally Posted by Oleg

Uploaded 9.2.4, try it too.

ok, will put that one in.

cheers,

wiz

9.2.4 works for me!

Code:

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

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.

Ok, try 9.2.5 now. :)