Device all of a sudden is assigning itself a 169.254 IP address when coming out of standby

[JTnola]

RT-AC86u • Merlin 386.12_4 • AMTM 4.1 • Diversion 5.0 • Skynet • ScMerlin

I’m having an issue with my Apple TV. It started sometime after installing 386.12_4 (but I can’t say for sure that the issue related to that, or merely coincidence. I don’t think it began immediately after that update—only that it began sometime in the 24-72hrs that followed).

My Apple TV is connected to the router by Ethernet cable. What happens is … I finish watching something on my Apple TV. I go away to do something else. The device goes into standby mode. Sometimes, when I come back to watch something else, all’s well. Other times—now occurring multiple times a day, though not every time the device is coming back from standby mode—I return to find that the Apple TV has assigned itself (?) an errant IP address, subnet, etc. 169.254.160.xx; (the Apple TV is normally issued a manually assigned IP address by the router’s dhcp server).

The following FAILS to remedy the problem:
• Rebooting the AppleTV
• Restarting the DHCP server on the router using scMerlin
• Trying to manually enter the correct IP address, etc. on the AppleTV (normally set to DHCP/DNS automatic on the AppleTV side)

I’ve also tried replacing the Ethernet cable & switching which Ethernet port it is plugged into on the router. No improvement.

The only way I’ve found to immediately remedy the problem is to reboot the router itself.

Any thoughts? Please see log below. (NB: the Apple TV is currently plugged into Ethernet port 3. There is another device plugged into Ethernet port 2 that continues to work *without* issue. There was no update or change to the Apple TV firmware/settings in the period before the problem appeared.)

THANK YOU!!

Jan 3 08:14:30 kernel: eth3 (Ext switch port: 2) (Logical Port: 10) Link DOWN.

Jan 3 08:14:30 kernel: br0: port 3(eth3) entered disabled state

Jan 3 08:14:33 kernel: eth3 (Ext switch port: 2) (Logical Port: 10) Link UP 1000 mbps full duplex

Jan 3 08:14:33 kernel: br0: port 3(eth3) entered forwarding state

Jan 3 08:14:33 kernel: br0: port 3(eth3) entered forwarding state

Jan 3 08:14:54 kernel: eth3 (Ext switch port: 2) (Logical Port: 10) Link DOWN.

Jan 3 08:14:54 kernel: br0: port 3(eth3) entered disabled state

Jan 3 08:14:56 kernel: eth3 (Ext switch port: 2) (Logical Port: 10) Link UP 100 mbps full duplex

Jan 3 08:14:56 kernel: br0: port 3(eth3) entered forwarding state

Jan 3 08:14:56 kernel: br0: port 3(eth3) entered forwarding state

Jan 3 08:15:36 kernel: asd[3115]: unhandled level 3 translation fault (11) at 0x00000168, esr 0x92000007

Jan 3 08:15:36 kernel: pgd = ffffffc00ac64000

Jan 3 08:15:36 kernel: [00000168] *pgd=0000000012a81003, *pud=0000000012a81003, *pmd=0000000013732003, *pte=0000000000000000

Jan 3 08:15:36 kernel: CPU: 0 PID: 3115 Comm: asd Tainted: P O 4.1.27 #2

Jan 3 08:15:36 kernel: Hardware name: Broadcom-v8A (DT)

Jan 3 08:15:36 kernel: task: ffffffc01918f5c0 ti: ffffffc0019f4000 task.ti: ffffffc0019f4000

Jan 3 08:15:36 kernel: PC is at 0xf702816e

Jan 3 08:15:36 kernel: LR is at 0xf6ff37fc

Jan 3 08:15:36 kernel: pc : [<00000000f702816e>] lr : [<00000000f6ff37fc>] pstate: 200f0030

Jan 3 08:15:36 kernel: sp : 00000000ff812da8

Jan 3 08:15:36 kernel: x12: 00000000ffffffff

Jan 3 08:15:36 kernel: x11: 00000000ff8132a4 x10: 000000000000001c

Jan 3 08:15:36 kernel: x9 : 00000000ffffffff x8 : 000000000000016d

Jan 3 08:15:36 kernel: x7 : 0000000000000000 x6 : 00000000ff8132b0

Jan 3 08:15:36 kernel: x5 : 0000000000000073 x4 : 0000000000000005

Jan 3 08:15:36 kernel: x3 : 0000000000000000 x2 : 0000000000000001

Jan 3 08:15:36 kernel: x1 : 0000000000000168 x0 : 000000000000016d

Jan 3 08:15:36 kernel: potentially unexpected fatal signal 11.

Jan 3 08:15:36 kernel: CPU: 0 PID: 3115 Comm: asd Tainted: P O 4.1.27 #2

Jan 3 08:15:36 kernel: Hardware name: Broadcom-v8A (DT)

Jan 3 08:15:36 kernel: task: ffffffc01918f5c0 ti: ffffffc0019f4000 task.ti: ffffffc0019f4000

Jan 3 08:15:36 kernel: PC is at 0xf702816e

Jan 3 08:15:36 kernel: LR is at 0xf6ff37fc

Jan 3 08:15:36 kernel: pc : [<00000000f702816e>] lr : [<00000000f6ff37fc>] pstate: 200f0030

Jan 3 08:15:36 kernel: sp : 00000000ff812da8

Jan 3 08:15:36 kernel: x12: 00000000ffffffff

Jan 3 08:15:36 kernel: x11: 00000000ff8132a4 x10: 000000000000001c

Jan 3 08:15:36 kernel: x9 : 00000000ffffffff x8 : 000000000000016d

Jan 3 08:15:36 kernel: x7 : 0000000000000000 x6 : 00000000ff8132b0

Jan 3 08:15:36 kernel: x5 : 0000000000000073 x4 : 0000000000000005

Jan 3 08:15:36 kernel: x3 : 0000000000000000 x2 : 0000000000000001

Jan 3 08:15:36 kernel: x1 : 0000000000000168 x0 : 000000000000016d

Jan 3 08:15:40 rc_service: service 9666:notify_rc restart_firewall

Jan 3 08:15:40 custom_script: Running /jffs/scripts/service-event (args: restart firewall)

Jan 3 08:15:40 custom_script: Running /jffs/scripts/firewall-start (args: eth0)

Jan 3 08:15:40 Skynet: [*] Killing Locked Processes (start skynetloc=/tmp/mnt/SmSng20-2nu/skynet) (pid=31496)

Jan 3 08:15:40 Skynet: [*] 31496 pterOthe 3940 S sh /jffs/scripts/firewall start skynetloc=/tmp/mnt/S

Jan 3 08:16:00 kernel: eth3 (Ext switch port: 2) (Logical Port: 10) Link DOWN.

Jan 3 08:16:00 kernel: br0: port 3(eth3) entered disabled state

Jan 3 08:16:02 kernel: eth3 (Ext switch port: 2) (Logical Port: 10) Link UP 1000 mbps full duplex

Jan 3 08:16:02 kernel: br0: port 3(eth3) entered forwarding state

Jan 3 08:16:02 kernel: br0: port 3(eth3) entered forwarding state

Jan 3 08:16:05 rc_service: service 10222:notify_rc restart_dnsmasq

Jan 3 08:16:05 custom_script: Running /jffs/scripts/service-event (args: restart dnsmasq)

Jan 3 08:16:05 dnsmasq[32132]: exiting on receipt of SIGTERM

Jan 3 08:16:05 custom_config: Appending content of /jffs/configs/dnsmasq.conf.add.

Jan 3 08:16:05 custom_script: Running /jffs/scripts/dnsmasq.postconf (args: /etc/dnsmasq.conf)

Jan 3 08:16:05 Diversion: created br0:ad_blocking_excl for 192.168.50.3

Jan 3 08:16:05 dnsmasq[10391]: started, version 2.89 cachesize 150

Jan 3 08:16:05 dnsmasq[10391]: read /etc/hosts - 22 names

Jan 3 08:16:05 dnsmasq[10391]: using nameserver 9.9.9.9#53

Jan 3 08:16:05 dnsmasq[10391]: using nameserver 149.112.112.112#53

Jan 3 08:16:05 dnsmasq[10391]: using nameserver 10.0.0.243#53

Jan 3 08:16:05 dnsmasq[10391]: using nameserver 127.0.1.1#53

Jan 3 08:16:05 dnsmasq[10391]: using nameserver 9.9.9.9#53

Jan 3 08:16:05 dnsmasq[10391]: using nameserver 149.112.112.112#53

Jan 3 08:16:05 dnsmasq[10391]: using nameserver 10.0.0.243#53

Jan 3 08:16:05 dnsmasq[10391]: using nameserver 127.0.1.1#53

Jan 3 08:16:05 Diversion: started separate Dnsmasq instance for ad-blocking exclusion on IP 192.168.50.3

Jan 3 08:16:05 Diversion: restarted Dnsmasq to apply settings

Jan 3 08:16:05 stubby[10396]: Stubby version: Stubby 0.4.2

Jan 3 08:16:23 kernel: eth3 (Ext switch port: 2) (Logical Port: 10) Link DOWN.

Jan 3 08:16:23 kernel: br0: port 3(eth3) entered disabled state

Jan 3 08:16:25 kernel: eth3 (Ext switch port: 2) (Logical Port: 10) Link UP 100 mbps full duplex

Jan 3 08:16:25 kernel: br0: port 3(eth3) entered forwarding state

Jan 3 08:16:25 kernel: br0: port 3(eth3) entered forwarding state

 

[ColinTaylor]

As per our previous discussion about this (link), if it isn't a cable fault then it could be a problem with the DHCP server being down.

I'm not sure what your log excerpt is meant to be showing us. Something is restarting the WAN connection and by association dnsmasq. As dnsmasq is the DHCP server that could be the problem. But without more context it's difficult to guess what's happening.

 

[Woody]

RT-AC86u • Merlin 386.12_4 • AMTM 4.1 • Diversion 5.0 • Skynet • ScMerlin

I’m having an issue with my Apple TV. It started sometime after installing 386.12_4 (but I can’t say for sure that the issue related to that, or merely coincidence. I don’t think it began immediately after that update—only that it began sometime in the 24-72hrs that followed).

My Apple TV is connected to the router by Ethernet cable. What happens is … I finish watching something on my Apple TV. I go away to do something else. The device goes into standby mode. Sometimes, when I come back to watch something else, all’s well. Other times—now occurring multiple times a day, though not every time the device is coming back from standby mode—I return to find that the Apple TV has assigned itself (?) an errant IP address, subnet, etc. 169.254.160.xx; (the Apple TV is normally issued a manually assigned IP address by the router’s dhcp server).

The following FAILS to remedy the problem:
• Rebooting the AppleTV
• Restarting the DHCP server on the router using scMerlin
• Trying to manually enter the correct IP address, etc. on the AppleTV (normally set to DHCP/DNS automatic on the AppleTV side)

I’ve also tried replacing the Ethernet cable & switching which Ethernet port it is plugged into on the router. No improvement.

The only way I’ve found to immediately remedy the problem is to reboot the router itself.

Any thoughts? Please see log below. (NB: the Apple TV is currently plugged into Ethernet port 3. There is another device plugged into Ethernet port 2 that continues to work *without* issue. There was no update or change to the Apple TV firmware/settings in the period before the problem appeared.)

THANK YOU!!

Are you running anything else in your environment that could be SSH accessing your router or similar (Network Management/Home Assistant or the like)?

It's just that the log looks more like the recovery from something crashing to me - but what do I know?

Your symptoms - DHCP apparently non-responsive - are the same that I was getting when you previously reported this here: https://www.snbforums.com/threads/asuswrt-merlin-386-12-is-now-available-for-ac-models.86647/ run through that discussion (a few pages before your report) and you'll see me pointing out a few memory issues.

See here: https://www.snbforums.com/threads/s...and-or-crashes-with-merlin-on-rt-ac86u.88298/ as to what was causing my problem - is there a connection?

 

[Morris]

Your Apple TV probably is failing to connect to the network on restart. Try assigning a static IP on the Apple TV.

 

[miazza]

I have a very similar behaviour on my network:
https://www.snbforums.com/threads/ac86u-dhcp-not-assigning-ip.88445/#post-885296

In my case a reboot is not sufficient and I need to power cycle the router.

In my case it is less annoying because it happens only if the devices are not connected to the DHCP for few days.

I have the feeling that this is somehow related to Diversion but this is only a feeling without any data in support.

It is something that starded only in the last few months may be starting with RT-AC86U_386.12_0

 

[Morris]

I have a very similar behaviour on my network:
https://www.snbforums.com/threads/ac86u-dhcp-not-assigning-ip.88445/#post-885296

In my case a reboot is not sufficient and I need to power cycle the router.

In my case it is less annoying because it happens only if the devices are not connected to the DHCP for few days.

I have the feeling that this is somehow related to Diversion but this is only a feeling without any data in support.

It is something that starded only in the last few months may be starting with RT-AC86U_386.12_0

This type of issue is usually a network issue resulting from lost packets. This results in the DHCP server not hearing renewal requests and/or the client not hearing the response. Take a look at your DHCP list, renewals should happen at 50% to 60% of the lease time. If you see leases longer than this you have a communications problem. Also look at client and server error counts. Do long packet pings of 100 or more. These things should out the issue and help you correct it. Also, if you are loading your router up with lots of tasks, then it might miss a DHCP renewal.

Morris

 

[miazza]

I have a reboot scheduled every 24 hours with the amtm script.
The lease time is also 24 hours so basically I never see a lease of the DHCP.
May me be this is the reason ?

And yes, the route is a bit loaded with DIversion, spdMerlin, wancheck but shoud not be sufficient to loose DHCP requests...

And also I do not understand why a reboot is not sufficient and only a power cycle unlock to situation... by the way every time I powercycle the router the entware usb disk becomes unavailable and I need to unplug/plug to have it back woring.

 

[Morris]

I have a reboot scheduled every 24 hours with the amtm script.
The lease time is also 24 hours so basically I never see a lease of the DHCP.
May me be this is the reason ?

And yes, the route is a bit loaded with DIversion, spdMerlin, wancheck but shoud not be sufficient to loose DHCP requests...

And also I do not understand why a reboot is not sufficient and only a power cycle unlock to situation... by the way every time I powercycle the router the entware usb disk becomes unavailable and I need to unplug/plug to have it back woring.

No, first DHCP renewal is at 60 percent of lease time to prevent problems like you are expecting. Read the RFC as there is more to it than I care to quote.

 

[ColinTaylor]

^ Typo. 60 50 percent.

 

[miazza]

Right now I have the issue on my Nas and on my Rasperry.
They are bot connecte by LAN Etnernet cable to the router with a DHCP reserved address:
- NAS at 192.168.1.5
- Pi at 192.168.1.248

The lease time for all the connected devices is not interesting the above two IP.

The wake-on lan on the NAS MAC is well working so the LAN is well detected (on Pi is is not working for HW limitation)
I tried to restart DNS/DHCP Server (dnsmasq) without any success.

On the Log side I cannot see anything strange.

Now I do not know what to do further other than power cycle the router.
This is an issue I have since Septembrer last year with 386.12.

Edit:
The command "service reboot" makes the trick.
It is not the same of a simple reboot.
Despite I have not understood why the DHCP get stuck and not assigning the IP to those devices that are not connected to the router during the last switch-on.

 

[Morris]

Right now I have the issue on my Nas and on my Rasperry.
They are bot connecte by LAN Etnernet cable to the router with a DHCP reserved address:
- NAS at 192.168.1.5
- Pi at 192.168.1.248

The lease time for all the connected devices is not interesting the above two IP.

The wake-on lan on the NAS MAC is well working so the LAN is well detected (on Pi is is not working for HW limitation)
I tried to restart DNS/DHCP Server (dnsmasq) without any success.

On the Log side I cannot see anything strange.

Now I do not know what to do further other than power cycle the router.
This is an issue I have since Septembrer last year with 386.12.

Edit:
The command "service reboot" makes the trick.
It is not the same of a simple reboot.
Despite I have not understood why the DHCP get stuck and not assigning the IP to those devices that are not connected to the router during the last switch-on.

Try configuring the IP for both the NAS and PI on those hosts.

 

[miazza]

Try configuring the IP for both the NAS and PI on those hosts.

What do you mean ? Shall I configure the NAS and Pi with the same host of the router ?

 

[Morris]

No. They each need there own IP, a DNS assignment and the default gateway.

You need to do a bunch of reading as you don't understand this basic information. While what I'm suggesting will fix your symptoms, it is a bandaid and not addressing the packet loss on your network.

 

[miazza]

Yes clear.
I do not like to fix the IP in the device : DHCP shall work with the MAC Address IP reservation (as for all the other wifi devices I have in the network) and I might consider the bandaid only as a temporary solution (by the way, even setting a fixed own IP and DNS on the NAS does not fix the symptomos).
It worked fine like that for years and something changed only in the last few months (even if apparently I did not change anything on the network infrastructure that is quite simple).
The my problem is anyhow confirmed only on the devices connected via LAN cable and this looks as a good starting point where to start to investigate the packet loss.

I have no idea if this is just a case but I made a full reinstall of the last Diversion 5.0 (from SSH UI) and, as suggested by post-update notes , I also removed pixelserv-tls; for this the IP 192.168.1.2 was reserved in the DHCP which was starting at IP .3 and now I reverted the DHCP to start from .2.
The fact that the last release Removes LAN blocking IP address feature, no longer needed, suggests that something has changed in the LAN IP blocking management that is exactly the problem I have (and also the timing looks compatible with my first problem with LAN devices).
After this I had no more problems ... I will keep it under monitoring for some time meanwhile I will investigate how to understand the packet loss just in case it will happen again.

 

[Morris]

Yes clear.
I do not like to fix the IP in the device : DHCP shall work with the MAC Address IP reservation (as for all the other wifi devices I have in the network) and I might consider the bandaid only as a temporary solution (by the way, even setting a fixed own IP and DNS on the NAS does not fix the symptomos).
It worked fine like that for years and something changed only in the last few months (even if apparently I did not change anything on the network infrastructure that is quite simple).
The my problem is anyhow confirmed only on the devices connected via LAN cable and this looks as a good starting point where to start to investigate the packet loss.

I have no idea if this is just a case but I made a full reinstall of the last Diversion 5.0 (from SSH UI) and, as suggested by post-update notes , I also removed pixelserv-tls; for this the IP 192.168.1.2 was reserved in the DHCP which was starting at IP .3 and now I reverted the DHCP to start from .2.
The fact that the last release Removes LAN blocking IP address feature, no longer needed, suggests that something has changed in the LAN IP blocking management that is exactly the problem I have (and also the timing looks compatible with my first problem with LAN devices).
After this I had no more problems ... I will keep it under monitoring for some time meanwhile I will investigate how to understand the packet loss just in case it will happen again.

To prove your theory that it's code, go back to a known working version. If that fixes it for at least 3 times as long as it takes for the problem, then go forward again and see if the problem comes back with the same frequency.

Good luck

 

[MarkNZ]

I have also been having the same problem with LAN ports on RT-86U if they are not used for a while, either the connected device has been powered off, or a device is plugged when the router has been booted for a while. The port shows as connected with a link speed in the web GUI, but it the is no communication on the port.

This manifests as 169.x addresses for DHCP clients, and packets simply not being sent or received for static IP devices. The only resolution is a power cycle of the router. This has been occuring on 2 separate routers I have at different locations both running 386.12_4, but it started a couple of months ago.

I have noticed that the port is listed as "disabled" when I do a "brctl showstp br0", which is odd. Although even if I disable spanning tree it doesn't change anything.

I have tried using ethctl to force speed and duplex, in case it's autonegotiating incorrectly but this also doesn't change anything.

I am running Diversion also, and did inline upgrade to version 5.0, so will do an uninstall/reinstall in the hopes this might help. I will restore config from backup, or is a complete remove and configure from scratch needed? But as it's a problem which only occurs after some time, it could be hours or days, I'm not really sure, it's a bit of a pain to troubleshoot.

 

[miazza]

I have also been having the same problem with LAN ports on RT-86U if they are not used for a while, either the connected device has been powered off, or a device is plugged when the router has been booted for a while. The port shows as connected with a link speed in the web GUI, but it the is no communication on the port.

This manifests as 169.x addresses for DHCP clients, and packets simply not being sent or received for static IP devices. The only resolution is a power cycle of the router. This has been occuring on 2 separate routers I have at different locations both running 386.12_4, but it started a couple of months ago.

I have noticed that the port is listed as "disabled" when I do a "brctl showstp br0", which is odd. Although even if I disable spanning tree it doesn't change anything.

I have tried using ethctl to force speed and duplex, in case it's autonegotiating incorrectly but this also doesn't change anything.

I am running Diversion also, and did inline upgrade to version 5.0, so will do an uninstall/reinstall in the hopes this might help. I will restore config from backup, or is a complete remove and configure from scratch needed? But as it's a problem which only occurs after some time, it could be hours or days, I'm not really sure, it's a bit of a pain to troubleshoot.

After having uninstalled and reinstalled Diversion from amtm the problem did not occur anymore.
It's about 10 days. I also reconfigured the DHCP to start IP allocation from 192.168.1.2 (before it was assigned to Diversion but now no more needed from 5.0).

Instead of powercycle you can reboot from amtm or run "service reboot" (simple reboot does not solve the issue).

It seems the packet loss is not the issue here even if I am still monitoring if the problem occurs.

Please advise if the Diversion uninstall/install solve the problem (in the Diversion page it is stated that the upgrade should be done from amtm and not from WebGUI); this might be the reason why I had problems; I see you did the same

 

[Morris]

I have also been having the same problem with LAN ports on RT-86U if they are not used for a while, either the connected device has been powered off, or a device is plugged when the router has been booted for a while. The port shows as connected with a link speed in the web GUI, but it the is no communication on the port.

This manifests as 169.x addresses for DHCP clients, and packets simply not being sent or received for static IP devices. The only resolution is a power cycle of the router. This has been occuring on 2 separate routers I have at different locations both running 386.12_4, but it started a couple of months ago.

I have noticed that the port is listed as "disabled" when I do a "brctl showstp br0", which is odd. Although even if I disable spanning tree it doesn't change anything.

I have tried using ethctl to force speed and duplex, in case it's autonegotiating incorrectly but this also doesn't change anything.

I am running Diversion also, and did inline upgrade to version 5.0, so will do an uninstall/reinstall in the hopes this might help. I will restore config from backup, or is a complete remove and configure from scratch needed? But as it's a problem which only occurs after some time, it could be hours or days, I'm not really sure, it's a bit of a pain to troubleshoot.

Try unplugging and replunging the port. Is there a switch between the host and the router? If you have spanning tree enabled, try keeping it disabled. If Asus dose not implement port fast then traffic will be blocked for 30 seconds when a port comes up and this can cause DHCP issues of the type you described.

 

[miazza]

Try unplugging and replunging the port.

In my case this was not changing the problem and my host is connected straight to the router with 50cm LAN cable (no switch in between).

 

[Morris]

In my case this was not changing the problem and my host is connected straight to the router with 50cm LAN cable (no switch in between).

What is not changing your problem? With no additional switches involved, there is no reason to have spanning tree enabled. Turn it off if it is on and see if that helps.