Strainge DHCP behavior on Wan port

[wiz]

Ok, I don't have the Wan port Die issue.

My Asus is hooked up to a Zyxel adsl modem, and my ISP uses DHCP. So far so good, but every now and then my asus looses its lease and all connections are dropped.

I've asked my ISP if they could see anything strange, they said I was trying to renew my DHCP lease like a lunatic at some point in time. I also asked them to send me a piece of logfile stating this strange behavior but they weren't really keen on that idea.

In the firmware forum I started this issue, so I think it will be easier to follow up on things in a new thread, so thats why I opened up this thread.

Last night I Flashed my asus with Olegs 1.9.2.7-2 as it should produce more diagnostics for the dhcp on the wan.

so far I got this log:


Dec 28 23:18:50 ntp client: time is synchronized to ntp.demon.nl
Dec 28 23:48:35 udhcpc[92]: Sending renew...
renewal lines snipped
Dec 29 00:18:33 udhcpc[92]: Sending renew...
Dec 29 00:18:34 udhcpc[92]: Lease lost, entering init state
Dec 29 00:18:35 dnsmasq[51]: read /etc/hosts - 4 addresses
Dec 29 00:18:35 dnsmasq[51]: reading /tmp/resolv.conf
Dec 29 00:18:35 dnsmasq[51]: using nameserver 194.159.73.138#53
Dec 29 00:18:35 dhcp client: deconfig: lease is lost
Dec 29 00:18:35 udhcpc[92]: Sending discover...
Dec 29 00:18:35 udhcpc[92]: Sending select for mywanaddress...
Dec 29 00:18:35 udhcpc[92]: Lease of myip obtained, lease time 3600
Dec 29 00:18:35 dnsmasq[51]: read /etc/hosts - 4 addresses
Dec 29 00:18:35 dnsmasq[51]: reading /tmp/resolv.conf
Dec 29 00:18:35 dnsmasq[51]: using nameserver 194.159.73.136#53
Dec 29 00:18:35 dnsmasq[51]: using nameserver 194.159.73.138#53
Dec 29 00:18:35 dhcp client: bound IP : mywanaddress from 82.161.6.1
Dec 29 00:48:35 udhcpc[92]: Sending renew...
renewal lines snipped
Dec 29 01:18:33 udhcpc[92]: Sending renew...
Dec 29 01:18:34 udhcpc[92]: Lease lost, entering init state
Dec 29 01:18:34 dnsmasq[51]: read /etc/hosts - 4 addresses
Dec 29 01:18:34 dnsmasq[51]: reading /tmp/resolv.conf
Dec 29 01:18:34 dnsmasq[51]: using nameserver 194.159.73.138#53
Dec 29 01:18:34 dhcp client: deconfig: lease is lost
Dec 29 01:18:34 udhcpc[92]: Sending discover...
Dec 29 01:18:34 udhcpc[92]: Sending select for mywanaddress...
Dec 29 01:18:34 udhcpc[92]: Lease of mywanaddress obtained, lease time 3600
Dec 29 01:18:35 dnsmasq[51]: read /etc/hosts - 4 addresses
Dec 29 01:18:35 dnsmasq[51]: reading /tmp/resolv.conf
Dec 29 01:18:35 dnsmasq[51]: using nameserver 194.159.73.136#53
Dec 29 01:18:35 dnsmasq[51]: using nameserver 194.159.73.138#53
Dec 29 01:18:35 dhcp client: bound IP : mywanaddress from 82.161.6.1
Dec 29 01:18:50 ntp client: time is synchronized to ntp.demon.nl
Dec 29 01:48:36 udhcpc[92]: Sending renew...
renewal lines snipped
Dec 29 02:18:34 udhcpc[92]: Sending renew...
Dec 29 02:18:35 udhcpc[92]: Lease lost, entering init state
Dec 29 02:18:35 dnsmasq[51]: read /etc/hosts - 4 addresses
Dec 29 02:18:35 dnsmasq[51]: reading /tmp/resolv.conf
Dec 29 02:18:35 dnsmasq[51]: using nameserver 194.159.73.138#53
Dec 29 02:18:35 dhcp client: deconfig: lease is lost
Dec 29 02:18:35 udhcpc[92]: Sending discover...
Dec 29 02:18:35 udhcpc[92]: Sending select for mywanaddress...
Dec 29 02:18:35 udhcpc[92]: Lease of mywanaddress obtained, lease time 3600
Dec 29 02:18:35 dnsmasq[51]: read /etc/hosts - 4 addresses
Dec 29 02:18:35 dnsmasq[51]: reading /tmp/resolv.conf
Dec 29 02:18:35 dnsmasq[51]: using nameserver 194.159.73.136#53
Dec 29 02:18:35 dnsmasq[51]: using nameserver 194.159.73.138#53
Dec 29 02:18:36 dhcp client: bound IP : mywanaddress from 82.161.6.1
Dec 29 02:48:35 udhcpc[92]: Sending renew...
renewal lines snipped
Dec 29 03:18:33 udhcpc[92]: Sending renew...
Dec 29 03:18:34 udhcpc[92]: Lease lost, entering init state
Dec 29 03:18:34 dnsmasq[51]: read /etc/hosts - 4 addresses
Dec 29 03:18:34 dnsmasq[51]: reading /tmp/resolv.conf
Dec 29 03:18:34 dnsmasq[51]: using nameserver 194.159.73.138#53
Dec 29 03:18:34 dhcp client: deconfig: lease is lost
Dec 29 03:18:34 udhcpc[92]: Sending discover...
Dec 29 03:18:34 udhcpc[92]: Sending select for mywanaddress...
Dec 29 03:18:34 udhcpc[92]: Lease of mywanaddress obtained, lease time 3600
Dec 29 03:18:34 dnsmasq[51]: read /etc/hosts - 4 addresses
Dec 29 03:18:34 dnsmasq[51]: reading /tmp/resolv.conf
Dec 29 03:18:34 dnsmasq[51]: using nameserver 194.159.73.136#53
Dec 29 03:18:34 dnsmasq[51]: using nameserver 194.159.73.138#53
Dec 29 03:18:35 dhcp client: bound IP : mywanaddress from 82.161.6.1
Dec 29 03:18:52 ntp client: time is synchronized to ntp.demon.nl
Dec 29 03:48:36 udhcpc[92]: Sending renew...
renewal lines snipped
Dec 29 04:18:34 udhcpc[92]: Sending renew...
Dec 29 04:18:35 udhcpc[92]: Lease lost, entering init state
Dec 29 04:18:35 dnsmasq[51]: read /etc/hosts - 4 addresses
Dec 29 04:18:35 dnsmasq[51]: reading /tmp/resolv.conf
Dec 29 04:18:35 dnsmasq[51]: using nameserver 194.159.73.138#53
Dec 29 04:18:35 dhcp client: deconfig: lease is lost
Dec 29 04:18:35 udhcpc[92]: Sending discover...
Dec 29 04:18:35 udhcpc[92]: Sending select for mywanaddress...
Dec 29 04:18:35 udhcpc[92]: Lease of mywanaddress obtained, lease time 3600
Dec 29 04:18:35 dnsmasq[51]: read /etc/hosts - 4 addresses
Dec 29 04:18:35 dnsmasq[51]: reading /tmp/resolv.conf
Dec 29 04:18:35 dnsmasq[51]: using nameserver 194.159.73.136#53
Dec 29 04:18:35 dnsmasq[51]: using nameserver 194.159.73.138#53
Dec 29 04:18:35 dhcp client: bound IP : mywanaddress from 82.161.6.1
Dec 29 04:48:35 udhcpc[92]: Sending renew...
renewal snipped
Dec 29 05:18:33 udhcpc[92]: Sending renew...
Dec 29 05:18:34 udhcpc[92]: Lease lost, entering init state
Dec 29 05:18:35 dnsmasq[51]: read /etc/hosts - 4 addresses
Dec 29 05:18:35 dnsmasq[51]: reading /tmp/resolv.conf
Dec 29 05:18:35 dnsmasq[51]: using nameserver 194.159.73.138#53
Dec 29 05:18:35 dhcp client: deconfig: lease is lost
Dec 29 05:18:35 udhcpc[92]: Sending discover...
Dec 29 05:18:35 udhcpc[92]: Sending select for mywanaddress...
Dec 29 05:18:35 udhcpc[92]: Lease of mywanaddress obtained, lease time 3600
Dec 29 05:18:35 dnsmasq[51]: read /etc/hosts - 4 addresses
Dec 29 05:18:35 dnsmasq[51]: reading /tmp/resolv.conf
Dec 29 05:18:35 dnsmasq[51]: using nameserver 194.159.73.136#53
Dec 29 05:18:35 dnsmasq[51]: using nameserver 194.159.73.138#53
Dec 29 05:18:35 dhcp client: bound IP : mywanaddress from 82.161.6.1
Dec 29 05:18:54 ntp client: time is synchronized to ntp.demon.nl
Dec 29 05:48:37 udhcpc[92]: Sending renew...
renewal lines snipped
Dec 29 06:18:35 udhcpc[92]: Sending renew...
Dec 29 06:18:36 udhcpc[92]: Lease lost, entering init state
Dec 29 06:18:36 dnsmasq[51]: read /etc/hosts - 4 addresses
Dec 29 06:18:36 dnsmasq[51]: reading /tmp/resolv.conf
Dec 29 06:18:36 dnsmasq[51]: using nameserver 194.159.73.138#53
Dec 29 06:18:36 dhcp client: deconfig: lease is lost
Dec 29 06:18:36 udhcpc[92]: Sending discover...
Dec 29 06:18:37 udhcpc[92]: Sending select for mywanaddress...
Dec 29 06:18:37 udhcpc[92]: Lease of mywanaddress obtained, lease time 3600
Dec 29 06:18:37 dnsmasq[51]: read /etc/hosts - 4 addresses
Dec 29 06:18:37 dnsmasq[51]: reading /tmp/resolv.conf
Dec 29 06:18:37 dnsmasq[51]: using nameserver 194.159.73.136#53
Dec 29 06:18:37 dnsmasq[51]: using nameserver 194.159.73.138#53
Dec 29 06:18:37 dhcp client: bound IP : mywanaddress from 82.161.6.1
Dec 29 06:48:36 udhcpc[92]: Sending renew...
renewal lines snipped
Dec 29 07:18:34 udhcpc[92]: Sending renew...
Dec 29 07:18:35 udhcpc[92]: Lease lost, entering init state
Dec 29 07:18:35 dnsmasq[51]: read /etc/hosts - 4 addresses
Dec 29 07:18:35 dnsmasq[51]: reading /tmp/resolv.conf
Dec 29 07:18:35 dnsmasq[51]: using nameserver 194.159.73.138#53
Dec 29 07:18:35 dhcp client: deconfig: lease is lost
Dec 29 07:18:35 udhcpc[92]: Sending discover...
Dec 29 07:18:35 udhcpc[92]: Sending select for mywanaddress...
Dec 29 07:18:35 udhcpc[92]: Lease of mywanaddress obtained, lease time 3600
Dec 29 07:18:36 dnsmasq[51]: read /etc/hosts - 4 addresses
Dec 29 07:18:36 dnsmasq[51]: reading /tmp/resolv.conf
Dec 29 07:18:36 dnsmasq[51]: using nameserver 194.159.73.136#53
Dec 29 07:18:36 dnsmasq[51]: using nameserver 194.159.73.138#53
Dec 29 07:18:36 dhcp client: bound IP : mywanaddress from 82.161.6.1
Dec 29 07:18:56 ntp client: time is synchronized to ntp.demon.nl


Seems the renew request doesn't reach the dhcp server of my isp demon, so after an hour when the lease runs out it gets dropped. My asus will reinitialize and the whole thing starts again.

If there is a way to produce more information or diagnostics, please let me know.

[Oleg]

How often these sending renew lines (which you've snipped) are appearing in the log? Could you please post several snipped lines?

[wiz]

How often these sending renew lines (which you've snipped) are appearing in the log? Could you please post several snipped lines?

Off course, here is one:


Dec 29 10:49:39 dhcp client: deconfig: lease is lost
Dec 29 10:49:39 udhcpc[92]: Sending discover...
Dec 29 10:49:39 udhcpc[92]: Sending select for myip...
Dec 29 10:49:39 udhcpc[92]: Lease of myip obtained, lease time 3600
Dec 29 10:49:39 dnsmasq[51]: read /etc/hosts - 4 addresses
Dec 29 10:49:39 dnsmasq[51]: reading /tmp/resolv.conf
Dec 29 10:49:39 dnsmasq[51]: using nameserver 194.159.73.136#53
Dec 29 10:49:39 dnsmasq[51]: using nameserver 194.159.73.138#53
Dec 29 10:49:40 dhcp client: bound IP : myip from 82.161.6.1
Dec 29 11:19:39 udhcpc[92]: Sending renew...
Dec 29 11:30:54 udhcpc[92]: Sending renew...
Dec 29 11:36:31 udhcpc[92]: Sending renew...
Dec 29 11:39:20 udhcpc[92]: Sending renew...
Dec 29 11:40:44 udhcpc[92]: Sending renew...
Dec 29 11:41:26 udhcpc[92]: Sending renew...
Dec 29 11:41:47 udhcpc[92]: Sending renew...
Dec 29 11:41:58 udhcpc[92]: Sending renew...
Dec 29 11:42:03 udhcpc[92]: Sending renew...
Dec 29 11:42:06 udhcpc[92]: Sending renew...
Dec 29 11:42:07 udhcpc[92]: Sending renew...
Dec 29 11:42:09 udhcpc[92]: Sending renew...
Dec 29 11:45:54 udhcpc[92]: Sending renew...
Dec 29 11:47:46 udhcpc[92]: Sending renew...
Dec 29 11:48:42 udhcpc[92]: Sending renew...
Dec 29 11:49:10 udhcpc[92]: Sending renew...
Dec 29 11:49:24 udhcpc[92]: Sending renew...
Dec 29 11:49:31 udhcpc[92]: Sending renew...
Dec 29 11:49:35 udhcpc[92]: Sending renew...
Dec 29 11:49:37 udhcpc[92]: Sending renew...
Dec 29 11:49:38 udhcpc[92]: Lease lost, entering init state
Dec 29 11:49:38 dnsmasq[51]: read /etc/hosts - 4 addresses
Dec 29 11:49:38 dnsmasq[51]: reading /tmp/resolv.conf
Dec 29 11:49:38 dnsmasq[51]: using nameserver 194.159.73.138#53
Dec 29 11:49:38 dhcp client: deconfig: lease is lost
Dec 29 11:49:38 udhcpc[92]: Sending discover...
Dec 29 11:49:38 udhcpc[92]: Sending select for myip...
Dec 29 11:49:38 udhcpc[92]: Lease of myip obtained, lease time 3600


Seems this happens roughly every hour as leasetime is 3600.

[Marko]

I have experienced the same as wiz. My log is the exact same with the same persistent dhcp renewal requests, it always gets an ip after the lease is lost at which point connectivity often dies. My lease time is also 3600. I have a Navini wireless modem connected by ethernet 10base half via the WAN port

Sometimes the link stays working for many hours but every now and again always immediately following a automatic dhcp renewal I lose my connection. The WAN light is still on and flashes randomly as if there is traffic. I have experienced this with ASUS firmware 1.7.2.6 and with Olegs 1.7.5.9-5 and 1.9.2.7-2. Though 1.9.2.7-2 is much less prone to the problem it still occurs

Once the connection fails DNS fails and no traffic passes either way. If I issue the iptables -L -v command it prints outs


[admin@router /]$ iptables -L -v
Chain INPUT (policy ACCEPT 0 packets, 0 bytes)
pkts bytes target prot opt in out source destination
0 0 DROP all -- any any anywhere anywhere state INVALID
1511 119K ACCEPT all -- any any anywhere anywhere state RELATED,ESTABLISHED
90 5400 ACCEPT all -- lo any anywhere anywhere state NEW
170 22561 ACCEPT all -- br0 any anywhere anywhere state NEW

And stalls (pkts and bytes counts of course are different as you would expect each time)

If I click the connect button on the web interface through the status page and wait about 10 seconds connectivity returns and reissuing the iptables command results in a complete result

[Oleg]

Well, looks like it does not get reply from the ISP.
Anyway, I've uploaded tcpdump binary to http://wl500g.dyndns.org/tcpdump
Please wget it to your unit, chmod +x and then run as follows:


tcpdump -n -i eth1 port 67 or port 68 | tee /tmp/tcpdump.log

This should print and collect data to /tmp/tcpdump.log
I need this output and syslog to check for real network activity.

[wiz]

Tcpdump is running at the moment, will keep it running for a while.

In the mean time I have been searching for udhcpc and renew, seems I am not the only one on this planet that has this problem. I haven't found a solution yet either.

How long does it have to run?

[Oleg]

at least 2 hours, to gather all renew dances info...

[wiz]

How do I get the syslog and tcpdumplog to you Oleg?

[Oleg]

cp /tmp/tcpdump.log /tmp/harddisk

Browse your usb drive using ftp or samba then.

[wiz]

cp /tmp/tcpdump.log /tmp/harddisk

Browse your usb drive using ftp or samba then.

grin, that wasn't what I wanted to know :D

I meant I am not keen on putting my ip address here, and it doesn't really make sense to put fake addresses in, so I wondered how to get these files to you. Pulling em off the asus isn't a problem.

Can I send em to your email address?

[Oleg]

Can I send em to your email address?
:) Sure, send it to me.

[Antiloop]

it is also possible to attach it to your post..

[wiz]

I know I can attach it to a posting, but I don't want to broadcast my IP address .

Mail has been send !

[wiz]

Solved by Oleg (thanks Oleg!)

Turns out my ISP has a funny way of doing dhcp.

When I boot my asus, it gets a dhcp lease from 82.161.88.1. So far so good. About half way through the lease time (normal behavior) it starts requesting renewal of the lease. So my asus gets a reply to its request from 82.161.247.54. My asus expects a reply from the original dhcp server and drops the reply from 82.161.247.54. It then keeps on requesting renewal until the lease runs out and the lease expires.

Then my asus starts reinit process, gets a lease from 82.161.88.1 and the whole thing starts all over again. Wouldn't be too bad if leasetime wasn't 3600 (an hour).

My asus only accepts a reply from the originating dhcp server as it does statefull firewalling.

I've send them an email with a little piece of MY log as they weren't keen on sending theirs, and I ask them why they have it set up this way, but haven't got the answer yet. Don't think I will get a satisfying answer to this question but one can hope.

Solution:

put this in post-firewall
iptables -I INPUT -p udp --sport 67 --dport 68 -j ACCEPT

So anyone in the Netherlands hooking his or her asus up to a Zyxel with a demon adsl connection, you have been warned!

[Oleg]

And a workaround will appear in the 1.8.2.7-3.

[Styno]

So anyone in the Netherlands hooking his or her asus up to a Zyxel with a demon adsl connection, you have been warned!
Hmm, I have Demon Internet AND a Zyxel modem, but I haven't got problem with it at all....

[wiz]

Hmm, I have Demon Internet AND a Zyxel modem, but I haven't got problem with it at all....

Maybe you are lucky and I had bad luck to be on a subnet with a faulty dhcp config or something, or you don't use firewalling?

[Styno]

Maybe you are lucky and I had bad luck to be on a subnet with a faulty dhcp config or something, or you don't use firewalling?
Yes, I use the firewall. Weird.

[wiz]

well, if I look at the names of the systems I get the feeling it is a configuration error on the ISP site.

82.161.88.1 = bbned-vrf-04.router.nl.demon.net (also my default gateway)
82.161.247.54= bbned-pppoa-1.router.nl.demon.net.

So the original reply to the inital lease request ought to come from 82.161.247.54. My asus said it got is lease from my default gateway instead of the pppoa-1 router it is supposed to get it from.

[Styno]

I've just read the router HOWTO for the zyxel modem (http://www.zyxel.nl/p650/z009.html) because I want to setup NAT as an extra security for my parents - otherwise they must rely on Windows security :eek: - and I discovered that DEMON requires a port to be forwarded.

IP Address Assingment moet meestal op automatisch staan. De meeste ISP's geven altijd hetzelfde vaste IP-adres. Zorg er bij een Prestige 652 voor dat in de WAN-WAN regels UDP-poort 68 (Bootp/DHCP) naar binnen wordt doorgelaten.
This rule is allready in the router when you received it so maybe you got a router where they forgot to setup this rule or you accidently deleted the rule.

[Oleg]

Styno, wiz has different setup as seems. His zyxel works in bridged mode as seems, while you're running zyxel as router. So, actually your zyxel is managing ISP dhcp stuff, not wl500g.

[wiz]

Yeps, my zyxel is running in bridged mode.

[Styno]

Styno, wiz has different setup as seems. His zyxel works in bridged mode as seems, while you're running zyxel as router. So, actually your zyxel is managing ISP dhcp stuff, not wl500g.
Ok, you're right about that, but it confirms that the iptables rule wiz found out a few topics above is right. Demon requires that for proper functionality somehow. Weird anyway, I don't have that rule in my Asus router (Zyxel is in bridge mode)....

[wiz]

just proves my point that it is in fact a configuration error on the subnet where I am at.

Luckily the helpdesk isn't ignorant at all so they didn't even wanted to ask network maintenance to check if this is a configuration error.

It is non standard not supported hardware, and it is solved now according to HD.

oh well me and helpdesks :D

[max]

Hi,
I have a similar problem. Zyxel modem Bridged, Demon Internet, Asus Wl 500G and USR 8054 AP. Since Mid december my Internet was having strange behaviour. I thought it was my USR8054. So i bought a new AP the asus. It did not work straight away so put the USR back on. Now i noticed that when I swap the AP, internet works again. So Almost every day I need to swap the access points in order to have internet access.
I will contact the helpdesk of Demon to report of this strange behaviour, this week.
The funny thing is that I still seem to have a demon internet IP number when it happens. I looked at the log and it looks like the DHCP lease expires.
Note that I already have demon internet for more then 1.5 years.

[Styno]

Maybe you can check on the network status page if the router of you neighbourhood central modem configuration has changed since you have the problems...

http://www.demon.nl/cgi-bin/dslstatus/dslstatus.pl

[max]

You were right Styno thx.

If have found this email..

"
Dear customer,

On 15-12-2004 comprehensive maintenance will be performed on central
equipment in the DSL network of our DSL partner bbned.

The maintenance is planned between 00:01 CET and 06:00 CET. As a
result of this work you will lose connectivity one or more periods of
time between said times. During the maintenance period it is necessary
that you leave your DSL modem turned on. We kindly request you not to
contact the Support department with inquiries concerning this work.
Our Support Agents have no additional information.

Your connection will be automatically restored afterwards. If this is
not the case we request you contact the Support department as soon as
possible on our (toll free) number 0800 - 336 66 68. To reach the
support department from a mobile phone, dial 0900-0212 (EUR 0.10 per
minute plus the usage costs of your mobile phone).

This work is essential for the continuity of the service.
"

[wiz]

Max,

Maybe you have more luck with the helpdesk, as yours did work correctly and all over sudden it is not working anymore despite the fact you haven't changed your network config.

I did install my asus after this maintenance job from demon. As I bought it around december 20th.

is your default gateway 82.161.88.1 = bbned-vrf-04.router.nl.demon.net by any chance?

[max]

Wiz,

No, would be a coincidence ;-)
My default gateway is.. 212.238.156.1.

Max