OpenWrt 21.02.3 Freezing up on GL AR-150

Installing and Using OpenWrt
#1

I've had a GL AR-150 seemingly stop responding a few times lately, so I put a cronjob on it to log uptime, procs, and mem usage every ten minutes.

It was good for 3 or so days and just acted up again:

2022-07-16T10:00:00-05:00 AP1 crond[2061]: USER root pid 8121 cmd logger -t UpAt $( date ) Uptime $( uptime ) Procs: $( ps | wc -l ) $( free -m | grep Mem )
2022-07-16T10:00:00-05:00 AP1 UpAt: Sat Jul 16 10:00:00 CDT 2022 Uptime 10:00:00 up 1 day, 20:04, load average: 0.00, 0.00, 0.00 Procs: 45 Mem: 58488 14572 29376 224 14540 24248
2022-07-16T10:10:00-05:00 AP1 crond[2061]: USER root pid 8137 cmd logger -t UpAt $( date ) Uptime $( uptime ) Procs: $( ps | wc -l ) $( free -m | grep Mem )
2022-07-16T10:10:00-05:00 AP1 UpAt: Sat Jul 16 10:10:00 CDT 2022 Uptime 10:10:00 up 1 day, 20:14, load average: 0.00, 0.00, 0.00 Procs: 45 Mem: 58488 14488 29460 224 14540 24332
2022-07-16T10:20:00-05:00 AP1 crond[2061]: USER root pid 8153 cmd logger -t UpAt $( date ) Uptime $( uptime ) Procs: $( ps | wc -l ) $( free -m | grep Mem )
2022-07-16T10:20:00-05:00 AP1 UpAt: Sat Jul 16 10:20:00 CDT 2022 Uptime 10:20:00 up 1 day, 20:24, load average: 0.00, 0.00, 0.00 Procs: 45 Mem: 58488 14924 29024 224 14540 23896
2022-07-16T10:30:00-05:00 AP1 crond[2061]: USER root pid 8169 cmd logger -t UpAt $( date ) Uptime $( uptime ) Procs: $( ps | wc -l ) $( free -m | grep Mem )
2022-07-16T10:30:00-05:00 AP1 UpAt: Sat Jul 16 10:30:00 CDT 2022 Uptime 10:30:00 up 1 day, 20:34, load average: 0.00, 0.00, 0.00 Procs: 45 Mem: 58488 17976 25972 224 14540 20844
2022-07-16T10:40:00-05:00 AP1 crond[2061]: USER root pid 8185 cmd logger -t UpAt $( date ) Uptime $( uptime ) Procs: $( ps | wc -l ) $( free -m | grep Mem )
2022-07-16T10:40:00-05:00 AP1 UpAt: Sat Jul 16 10:40:00 CDT 2022 Uptime 10:40:00 up 1 day, 20:44, load average: 0.00, 0.00, 0.00 Procs: 45 Mem: 58488 17676 26272 224 14540 21144

At about 11am I noticed trouble. I could not conect to wifi. Android and fedora laptop spun and then failed over to another network because they could not get an ip address. but I had to walk the dogs.

2022-07-16T11:12:16-05:00 AP1 hostapd: wlan0: AP-STA-DISCONNECTED 58:91:cf:1e:05:d7
2022-07-16T11:12:24-05:00 AP1 hostapd: wlan0: STA 58:91:cf:1e:05:d7 IEEE 802.11: authenticated
2022-07-16T11:12:24-05:00 AP1 hostapd: wlan0: STA 58:91:cf:1e:05:d7 IEEE 802.11: associated (aid 3)
2022-07-16T11:12:24-05:00 AP1 hostapd: wlan0: AP-STA-CONNECTED 58:91:cf:1e:05:d7
2022-07-16T11:12:24-05:00 AP1 hostapd: wlan0: STA 58:91:cf:1e:05:d7 WPA: pairwise key handshake completed (RSN)

At 11:16 I could not reach the openwrt from my wired lan. activity lights were blinking as norma and i had an led set to heartbeat and it looked normal too. I assumed the wired interface was not passing traffic (even though it is getting PoE via it)... I configured my wifi profile for that AP to be manually addressed, and connected to the AP in trouble and I logged in to luci and ssh to look for signs of problems.

2022-07-16T11:16:10-05:00 AP1 : luci: accepted login on / for root from 192.168.32.40
2022-07-16T11:17:11-05:00 AP1 hostapd: wlan0: STA 58:cb:52:01:c4:bc IEEE 802.11: authenticated
2022-07-16T11:17:11-05:00 AP1 hostapd: wlan0: STA 58:cb:52:01:c4:bc IEEE 802.11: associated (aid 5)
2022-07-16T11:17:12-05:00 AP1 hostapd: wlan0: AP-STA-CONNECTED 58:cb:52:01:c4:bc
2022-07-16T11:17:12-05:00 AP1 hostapd: wlan0: STA 58:cb:52:01:c4:bc WPA: pairwise key handshake completed (RSN)

this event looks like it rebooted. I see that when the thing boots up, but uptime shows over a day

2022-07-16T11:18:38-05:00 AP1 logread[932]: Logread connected to SysLog.internal.mydomain.com:514

root@AP1:/tmp/log# uptime
 11:39:41 up 1 day, 21:44,  load average: 0.00, 0.00, 0.00
root@AP1:/tmp/log# date
Sat Jul 16 11:39:48 CDT 2022
root@AP1:/tmp/log#

and sure enough, by 11:20 the logging was showing up again.

2022-07-16T11:20:00-05:00 AP1 crond[2061]: USER root pid 8633 cmd logger -t UpAt $( date ) Uptime $( uptime ) Procs: $( ps | wc -l ) $( free -m | grep Mem )
2022-07-16T11:20:00-05:00 AP1 UpAt: Sat Jul 16 11:20:00 CDT 2022 Uptime 11:20:00 up 1 day, 21:24, load average: 0.03, 0.03, 0.00 Procs: 48 Mem: 58488 20140 23752 224 14596 18652
2022-07-16T11:22:26-05:00 AP1 hostapd: wlan0: AP-STA-DISCONNECTED 58:91:cf:1e:05:d7
2022-07-16T11:28:31-05:00 AP1 crond[8684]: crond (busybox 1.33.2) started, log level 8
2022-07-16T11:28:47-05:00 AP1 crond[8741]: crond (busybox 1.33.2) started, log level 8

I have another 150 with no such problems.
What could be causing this?
I thought maybe STP, but i saw no stp log events from the AR-150, and then I realised, I was looking at a central syslog server (which would have been isolated during the problem). so I look in luci and I see:

Sat Jul 16 09:30:00 2022 cron.err crond[2061]: USER root pid 8080 cmd logger -t UpAt $( date ) Uptime $( uptime ) Procs: $( ps | wc -l ) $( free -m | grep Mem )
Sat Jul 16 09:30:00 2022 user.notice UpAt: Sat Jul 16 09:30:00 CDT 2022 Uptime 09:30:00 up 1 day, 19:34, load average: 0.02, 0.00, 0.00 Procs: 45 Mem: 58488 17656 26292 224 14540 21164
Sat Jul 16 09:40:00 2022 cron.err crond[2061]: USER root pid 8089 cmd logger -t UpAt $( date ) Uptime $( uptime ) Procs: $( ps | wc -l ) $( free -m | grep Mem )
Sat Jul 16 09:40:00 2022 user.notice UpAt: Sat Jul 16 09:40:00 CDT 2022 Uptime 09:40:00 up 1 day, 19:44, load average: 0.00, 0.00, 0.00 Procs: 45 Mem: 58488 17016 26932 224 14540 21804
Sat Jul 16 09:50:00 2022 cron.err crond[2061]: USER root pid 8105 cmd logger -t UpAt $( date ) Uptime $( uptime ) Procs: $( ps | wc -l ) $( free -m | grep Mem )
Sat Jul 16 09:50:00 2022 user.notice UpAt: Sat Jul 16 09:50:00 CDT 2022 Uptime 09:50:00 up 1 day, 19:54, load average: 0.00, 0.00, 0.00 Procs: 45 Mem: 58488 13880 30068 224 14540 24940
Sat Jul 16 10:00:00 2022 cron.err crond[2061]: USER root pid 8121 cmd logger -t UpAt $( date ) Uptime $( uptime ) Procs: $( ps | wc -l ) $( free -m | grep Mem )
Sat Jul 16 10:00:00 2022 user.notice UpAt: Sat Jul 16 10:00:00 CDT 2022 Uptime 10:00:00 up 1 day, 20:04, load average: 0.00, 0.00, 0.00 Procs: 45 Mem: 58488 14572 29376 224 14540 24248
Sat Jul 16 10:10:00 2022 cron.err crond[2061]: USER root pid 8137 cmd logger -t UpAt $( date ) Uptime $( uptime ) Procs: $( ps | wc -l ) $( free -m | grep Mem )
Sat Jul 16 10:10:00 2022 user.notice UpAt: Sat Jul 16 10:10:00 CDT 2022 Uptime 10:10:00 up 1 day, 20:14, load average: 0.00, 0.00, 0.00 Procs: 45 Mem: 58488 14488 29460 224 14540 24332
Sat Jul 16 10:20:00 2022 cron.err crond[2061]: USER root pid 8153 cmd logger -t UpAt $( date ) Uptime $( uptime ) Procs: $( ps | wc -l ) $( free -m | grep Mem )
Sat Jul 16 10:20:00 2022 user.notice UpAt: Sat Jul 16 10:20:00 CDT 2022 Uptime 10:20:00 up 1 day, 20:24, load average: 0.00, 0.00, 0.00 Procs: 45 Mem: 58488 14924 29024 224 14540 23896
Sat Jul 16 10:30:00 2022 cron.err crond[2061]: USER root pid 8169 cmd logger -t UpAt $( date ) Uptime $( uptime ) Procs: $( ps | wc -l ) $( free -m | grep Mem )
Sat Jul 16 10:30:00 2022 user.notice UpAt: Sat Jul 16 10:30:00 CDT 2022 Uptime 10:30:00 up 1 day, 20:34, load average: 0.00, 0.00, 0.00 Procs: 45 Mem: 58488 17976 25972 224 14540 20844
Sat Jul 16 10:40:00 2022 cron.err crond[2061]: USER root pid 8185 cmd logger -t UpAt $( date ) Uptime $( uptime ) Procs: $( ps | wc -l ) $( free -m | grep Mem )
Sat Jul 16 10:40:00 2022 user.notice UpAt: Sat Jul 16 10:40:00 CDT 2022 Uptime 10:40:00 up 1 day, 20:44, load average: 0.00, 0.00, 0.00 Procs: 45 Mem: 58488 17676 26272 224 14540 21144
Sat Jul 16 10:46:28 2022 kern.info kernel: [161476.812262] eth1: link down
Sat Jul 16 10:46:28 2022 kern.info kernel: [161476.814527] br-lan: port 2(eth1) entered disabled state
Sat Jul 16 10:46:28 2022 daemon.notice netifd: Network device 'eth1' link is down
Sat Jul 16 10:50:00 2022 cron.err crond[2061]: USER root pid 8201 cmd logger -t UpAt $( date ) Uptime $( uptime ) Procs: $( ps | wc -l ) $( free -m | grep Mem )
Sat Jul 16 10:50:00 2022 user.notice UpAt: Sat Jul 16 10:50:00 CDT 2022 Uptime 10:50:00 up 1 day, 20:54, load average: 0.00, 0.00, 0.00 Procs: 45 Mem: 58488 16280 27668 224 14540 22540
Sat Jul 16 11:00:00 2022 cron.err crond[2061]: USER root pid 8217 cmd logger -t UpAt $( date ) Uptime $( uptime ) Procs: $( ps | wc -l ) $( free -m | grep Mem )
Sat Jul 16 11:00:00 2022 user.notice UpAt: Sat Jul 16 11:00:00 CDT 2022 Uptime 11:00:00 up 1 day, 21:04, load average: 0.00, 0.00, 0.00 Procs: 45 Mem: 58488 16684 27264 224 14540 22136
Sat Jul 16 11:05:22 2022 daemon.info hostapd: wlan0: STA 58:91:cf:1e:05:d7 IEEE 802.11: authenticated
Sat Jul 16 11:05:22 2022 daemon.info hostapd: wlan0: STA 58:91:cf:1e:05:d7 IEEE 802.11: associated (aid 3)
Sat Jul 16 11:05:22 2022 daemon.notice hostapd: wlan0: AP-STA-CONNECTED 58:91:cf:1e:05:d7
Sat Jul 16 11:05:22 2022 daemon.info hostapd: wlan0: STA 58:91:cf:1e:05:d7 WPA: pairwise key handshake completed (RSN)
Sat Jul 16 11:05:35 2022 daemon.notice hostapd: wlan0: AP-STA-DISCONNECTED 58:91:cf:1e:05:d7
Sat Jul 16 11:05:49 2022 daemon.info hostapd: wlan0: STA 58:91:cf:1e:05:d7 IEEE 802.11: authenticated
Sat Jul 16 11:05:49 2022 daemon.info hostapd: wlan0: STA 58:91:cf:1e:05:d7 IEEE 802.11: associated (aid 3)
Sat Jul 16 11:05:49 2022 daemon.notice hostapd: wlan0: AP-STA-CONNECTED 58:91:cf:1e:05:d7
Sat Jul 16 11:05:49 2022 daemon.info hostapd: wlan0: STA 58:91:cf:1e:05:d7 WPA: pairwise key handshake completed (RSN)
Sat Jul 16 11:05:55 2022 kern.info kernel: [162644.168872] eth1: link up (100Mbps/Full duplex)
Sat Jul 16 11:05:55 2022 kern.info kernel: [162644.173482] br-lan: port 2(eth1) entered blocking state
Sat Jul 16 11:05:55 2022 kern.info kernel: [162644.177446] br-lan: port 2(eth1) entered forwarding state
Sat Jul 16 11:05:55 2022 daemon.notice netifd: Network device 'eth1' link is up
Sat Jul 16 11:05:58 2022 kern.info kernel: [162647.240113] eth1: link down
Sat Jul 16 11:05:58 2022 kern.info kernel: [162647.242382] br-lan: port 2(eth1) entered disabled state
Sat Jul 16 11:05:58 2022 daemon.notice netifd: Network device 'eth1' link is down
Sat Jul 16 11:06:02 2022 kern.info kernel: [162651.336903] eth1: link up (100Mbps/Full duplex)
Sat Jul 16 11:06:02 2022 kern.info kernel: [162651.341501] br-lan: port 2(eth1) entered blocking state
Sat Jul 16 11:06:02 2022 kern.info kernel: [162651.345472] br-lan: port 2(eth1) entered forwarding state
Sat Jul 16 11:06:02 2022 daemon.notice netifd: Network device 'eth1' link is up
Sat Jul 16 11:06:03 2022 kern.info kernel: [162652.359720] eth1: link down
Sat Jul 16 11:06:03 2022 kern.info kernel: [162652.361984] br-lan: port 2(eth1) entered disabled state
Sat Jul 16 11:06:03 2022 daemon.notice netifd: Network device 'eth1' link is down
Sat Jul 16 11:06:20 2022 daemon.notice hostapd: wlan0: AP-STA-DISCONNECTED 58:91:cf:1e:05:d7
Sat Jul 16 11:08:34 2022 kern.info kernel: [162802.888225] eth1: link up (100Mbps/Full duplex)
Sat Jul 16 11:08:34 2022 kern.info kernel: [162802.893072] br-lan: port 2(eth1) entered blocking state
Sat Jul 16 11:08:34 2022 kern.info kernel: [162802.897018] br-lan: port 2(eth1) entered forwarding state
Sat Jul 16 11:08:34 2022 daemon.notice netifd: Network device 'eth1' link is up
Sat Jul 16 11:08:36 2022 kern.info kernel: [162804.935102] eth1: link down
Sat Jul 16 11:08:36 2022 kern.info kernel: [162804.937368] br-lan: port 2(eth1) entered disabled state
Sat Jul 16 11:08:36 2022 daemon.notice netifd: Network device 'eth1' link is down
Sat Jul 16 11:10:00 2022 cron.err crond[2061]: USER root pid 8233 cmd logger -t UpAt $( date ) Uptime $( uptime ) Procs: $( ps | wc -l ) $( free -m | grep Mem )
Sat Jul 16 11:10:00 2022 user.notice UpAt: Sat Jul 16 11:10:00 CDT 2022 Uptime 11:10:00 up 1 day, 21:14, load average: 0.07, 0.01, 0.00 Procs: 45 Mem: 58488 16620 27316 224 14552 22192
Sat Jul 16 11:11:10 2022 kern.info kernel: [162958.535632] eth1: link up (100Mbps/Full duplex)
Sat Jul 16 11:11:10 2022 kern.info kernel: [162958.540292] br-lan: port 2(eth1) entered blocking state
Sat Jul 16 11:11:10 2022 kern.info kernel: [162958.544232] br-lan: port 2(eth1) entered forwarding state
Sat Jul 16 11:11:10 2022 daemon.notice netifd: Network device 'eth1' link is up
Sat Jul 16 11:11:11 2022 kern.info kernel: [162959.558468] eth1: link down
Sat Jul 16 11:11:11 2022 kern.info kernel: [162959.560733] br-lan: port 2(eth1) entered disabled state
Sat Jul 16 11:11:11 2022 daemon.notice netifd: Network device 'eth1' link is down
Sat Jul 16 11:11:18 2022 daemon.info hostapd: wlan0: STA 58:91:cf:1e:05:d7 IEEE 802.11: authenticated
Sat Jul 16 11:11:19 2022 daemon.info hostapd: wlan0: STA 58:91:cf:1e:05:d7 IEEE 802.11: authenticated
Sat Jul 16 11:11:20 2022 daemon.info hostapd: wlan0: STA 58:91:cf:1e:05:d7 IEEE 802.11: authenticated
Sat Jul 16 11:11:22 2022 daemon.info hostapd: wlan0: STA 58:91:cf:1e:05:d7 IEEE 802.11: authenticated
Sat Jul 16 11:11:31 2022 daemon.info hostapd: wlan0: STA 58:91:cf:1e:05:d7 IEEE 802.11: authenticated
Sat Jul 16 11:11:31 2022 daemon.info hostapd: wlan0: STA 58:91:cf:1e:05:d7 IEEE 802.11: associated (aid 3)
Sat Jul 16 11:11:31 2022 daemon.notice hostapd: wlan0: AP-STA-CONNECTED 58:91:cf:1e:05:d7
Sat Jul 16 11:11:31 2022 daemon.info hostapd: wlan0: STA 58:91:cf:1e:05:d7 WPA: pairwise key handshake completed (RSN)
Sat Jul 16 11:11:54 2022 kern.info kernel: [163002.567419] eth1: link up (100Mbps/Full duplex)
Sat Jul 16 11:11:54 2022 kern.info kernel: [163002.572035] br-lan: port 2(eth1) entered blocking state
Sat Jul 16 11:11:54 2022 kern.info kernel: [163002.575978] br-lan: port 2(eth1) entered forwarding state
Sat Jul 16 11:11:54 2022 daemon.notice netifd: Network device 'eth1' link is up
Sat Jul 16 11:12:16 2022 daemon.notice hostapd: wlan0: AP-STA-DISCONNECTED 58:91:cf:1e:05:d7
Sat Jul 16 11:12:24 2022 daemon.info hostapd: wlan0: STA 58:91:cf:1e:05:d7 IEEE 802.11: authenticated
Sat Jul 16 11:12:24 2022 daemon.info hostapd: wlan0: STA 58:91:cf:1e:05:d7 IEEE 802.11: associated (aid 3)
Sat Jul 16 11:12:24 2022 daemon.notice hostapd: wlan0: AP-STA-CONNECTED 58:91:cf:1e:05:d7
Sat Jul 16 11:12:24 2022 daemon.info hostapd: wlan0: STA 58:91:cf:1e:05:d7 WPA: pairwise key handshake completed (RSN)
Sat Jul 16 11:12:32 2022 kern.info kernel: [163040.453943] eth1: link down
Sat Jul 16 11:12:32 2022 kern.info kernel: [163040.456470] br-lan: port 2(eth1) entered disabled state
Sat Jul 16 11:12:32 2022 daemon.notice netifd: Network device 'eth1' link is down
Sat Jul 16 11:12:52 2022 authpriv.info dropbear[8242]: Child connection from 192.168.32.40:43490
Sat Jul 16 11:12:53 2022 authpriv.warn dropbear[8242]: Login attempt for nonexistent user
Sat Jul 16 11:12:55 2022 authpriv.info dropbear[8242]: Exit before auth from <192.168.32.40:43490>: Exited normally
Sat Jul 16 11:12:57 2022 authpriv.info dropbear[8243]: Child connection from 192.168.32.40:43494
Sat Jul 16 11:12:57 2022 authpriv.notice dropbear[8243]: Pubkey auth succeeded for 'root' with key sha1!! 1f:9e:a3:c2:2b:7c:c9:4c:f9:99:ff:b0:57:c2:34:c7:2a:5c:73:7f from 192.168.32.40:43494
Sat Jul 16 11:13:16 2022 user.notice root: mark
Sat Jul 16 11:15:38 2022 kern.info kernel: [163226.822609] eth1: link up (100Mbps/Full duplex)
Sat Jul 16 11:15:38 2022 kern.info kernel: [163226.833014] br-lan: port 2(eth1) entered blocking state
Sat Jul 16 11:15:38 2022 kern.info kernel: [163226.836927] br-lan: port 2(eth1) entered forwarding state
Sat Jul 16 11:15:38 2022 daemon.notice netifd: Network device 'eth1' link is up
Sat Jul 16 11:15:45 2022 user.info : luci: failed login on / for root from 192.168.32.40
Sat Jul 16 11:15:55 2022 user.info : luci: failed login on / for root from 192.168.32.40
Sat Jul 16 11:16:10 2022 user.info : luci: accepted login on / for root from 192.168.32.40
Sat Jul 16 11:17:11 2022 daemon.info hostapd: wlan0: STA 58:cb:52:01:c4:bc IEEE 802.11: authenticated
Sat Jul 16 11:17:11 2022 daemon.info hostapd: wlan0: STA 58:cb:52:01:c4:bc IEEE 802.11: associated (aid 5)
Sat Jul 16 11:17:12 2022 daemon.notice hostapd: wlan0: AP-STA-CONNECTED 58:cb:52:01:c4:bc
Sat Jul 16 11:17:12 2022 daemon.info hostapd: wlan0: STA 58:cb:52:01:c4:bc WPA: pairwise key handshake completed (RSN)
Sat Jul 16 11:18:13 2022 kern.info kernel: [163382.278866] br-lan: port 3(wlan0) entered disabled state
Sat Jul 16 11:18:13 2022 kern.info kernel: [163382.283070] br-lan: port 2(eth1) entered disabled state
Sat Jul 16 11:18:13 2022 kern.info kernel: [163382.288401] br-lan: port 1(eth0) entered disabled state
Sat Jul 16 11:18:13 2022 daemon.info logread[932]: failed to send log data to SysLog.internal.mydomain.com:514 via udp
Sat Jul 16 11:18:13 2022 kern.info kernel: [163382.328796] device eth0 left promiscuous mode
Sat Jul 16 11:18:13 2022 kern.info kernel: [163382.331966] br-lan: port 1(eth0) entered disabled state
Sat Jul 16 11:18:13 2022 kern.info kernel: [163382.361202] eth0: link down
Sat Jul 16 11:18:14 2022 kern.info kernel: [163382.376001] device eth1 left promiscuous mode
Sat Jul 16 11:18:14 2022 kern.info kernel: [163382.379270] br-lan: port 2(eth1) entered disabled state
Sat Jul 16 11:18:14 2022 kern.info kernel: [163382.402307] eth1: link down
Sat Jul 16 11:18:14 2022 kern.info kernel: [163382.416138] device wlan0 left promiscuous mode
Sat Jul 16 11:18:14 2022 kern.info kernel: [163382.419527] br-lan: port 3(wlan0) entered disabled state
Sat Jul 16 11:18:14 2022 kern.info kernel: [163382.470542] eth0: link up (1000Mbps/Full duplex)
Sat Jul 16 11:18:14 2022 kern.info kernel: [163382.474961] br-lan: port 1(eth0) entered blocking state
Sat Jul 16 11:18:14 2022 kern.info kernel: [163382.479287] br-lan: port 1(eth0) entered disabled state
Sat Jul 16 11:18:14 2022 kern.info kernel: [163382.484948] device eth0 entered promiscuous mode
Sat Jul 16 11:18:14 2022 kern.info kernel: [163382.532707] br-lan: port 2(eth1) entered blocking state
Sat Jul 16 11:18:14 2022 kern.info kernel: [163382.536687] br-lan: port 2(eth1) entered disabled state
Sat Jul 16 11:18:14 2022 kern.info kernel: [163382.568390] device eth1 entered promiscuous mode
Sat Jul 16 11:18:14 2022 kern.info kernel: [163382.582764] br-lan: port 3(wlan0) entered blocking state
Sat Jul 16 11:18:14 2022 kern.info kernel: [163382.586980] br-lan: port 3(wlan0) entered disabled state
Sat Jul 16 11:18:14 2022 kern.info kernel: [163382.624748] device wlan0 entered promiscuous mode
Sat Jul 16 11:18:14 2022 kern.info kernel: [163382.649051] br-lan: port 3(wlan0) entered blocking state
Sat Jul 16 11:18:14 2022 kern.info kernel: [163382.653086] br-lan: port 3(wlan0) entered forwarding state
Sat Jul 16 11:18:14 2022 kern.info kernel: [163382.658738] br-lan: port 2(eth1) entered blocking state
Sat Jul 16 11:18:14 2022 kern.info kernel: [163382.663894] br-lan: port 2(eth1) entered forwarding state
Sat Jul 16 11:18:14 2022 kern.info kernel: [163382.669412] br-lan: port 1(eth0) entered blocking state
Sat Jul 16 11:18:14 2022 kern.info kernel: [163382.674650] br-lan: port 1(eth0) entered forwarding state
Sat Jul 16 11:18:14 2022 daemon.notice netifd: Network device 'eth1' link is down
Sat Jul 16 11:18:14 2022 daemon.notice netifd: lan (3938): udhcpc: received SIGTERM
Sat Jul 16 11:18:14 2022 daemon.notice netifd: lan (3938): udhcpc: unicasting a release of 192.168.32.24 to 192.168.32.1
Sat Jul 16 11:18:14 2022 daemon.notice netifd: lan (3938): udhcpc: sending release
Sat Jul 16 11:18:14 2022 daemon.notice netifd: lan (3938): udhcpc: bind(UDP): Address not available
Sat Jul 16 11:18:14 2022 daemon.notice netifd: lan (3938): udhcpc: entering released state
Sat Jul 16 11:18:14 2022 daemon.notice netifd: lan (3938): Command failed: Permission denied
Sat Jul 16 11:18:14 2022 daemon.notice netifd: Interface 'lan' is now down
Sat Jul 16 11:18:14 2022 kern.info kernel: [163383.075361] br-lan: port 3(wlan0) entered disabled state
Sat Jul 16 11:18:14 2022 kern.info kernel: [163383.079545] br-lan: port 2(eth1) entered disabled state
Sat Jul 16 11:18:14 2022 kern.info kernel: [163383.084734] br-lan: port 1(eth0) entered disabled state
Sat Jul 16 11:18:14 2022 kern.info kernel: [163383.129612] device eth0 left promiscuous mode
Sat Jul 16 11:18:14 2022 kern.info kernel: [163383.132871] br-lan: port 1(eth0) entered disabled state
Sat Jul 16 11:18:14 2022 kern.info kernel: [163383.160518] eth0: link down
Sat Jul 16 11:18:14 2022 kern.info kernel: [163383.174212] device eth1 left promiscuous mode
Sat Jul 16 11:18:14 2022 kern.info kernel: [163383.177472] br-lan: port 2(eth1) entered disabled state
Sat Jul 16 11:18:14 2022 kern.info kernel: [163383.232668] device wlan0 left promiscuous mode
Sat Jul 16 11:18:14 2022 kern.info kernel: [163383.235919] br-lan: port 3(wlan0) entered disabled state
Sat Jul 16 11:18:14 2022 daemon.notice netifd: Interface 'lan' is disabled
Sat Jul 16 11:18:14 2022 kern.info kernel: [163383.290053] eth0: link up (1000Mbps/Full duplex)
Sat Jul 16 11:18:14 2022 kern.info kernel: [163383.308773] br-lan: port 1(eth0) entered blocking state
Sat Jul 16 11:18:14 2022 kern.info kernel: [163383.312901] br-lan: port 1(eth0) entered disabled state
Sat Jul 16 11:18:14 2022 kern.info kernel: [163383.318495] device eth0 entered promiscuous mode
Sat Jul 16 11:18:15 2022 kern.info kernel: [163383.385467] br-lan: port 2(eth1) entered blocking state
Sat Jul 16 11:18:15 2022 kern.info kernel: [163383.389430] br-lan: port 2(eth1) entered disabled state
Sat Jul 16 11:18:15 2022 kern.info kernel: [163383.435795] device eth1 entered promiscuous mode
Sat Jul 16 11:18:15 2022 kern.info kernel: [163383.460517] br-lan: port 3(wlan0) entered blocking state
Sat Jul 16 11:18:15 2022 kern.info kernel: [163383.464526] br-lan: port 3(wlan0) entered disabled state
Sat Jul 16 11:18:15 2022 kern.info kernel: [163383.513371] device wlan0 entered promiscuous mode
Sat Jul 16 11:18:15 2022 kern.info kernel: [163383.550478] br-lan: port 3(wlan0) entered blocking state
Sat Jul 16 11:18:15 2022 kern.info kernel: [163383.554547] br-lan: port 3(wlan0) entered forwarding state
Sat Jul 16 11:18:15 2022 kern.info kernel: [163383.560174] br-lan: port 1(eth0) entered blocking state
Sat Jul 16 11:18:15 2022 kern.info kernel: [163383.565319] br-lan: port 1(eth0) entered forwarding state
Sat Jul 16 11:18:15 2022 daemon.notice netifd: Interface 'lan' is enabled
Sat Jul 16 11:18:15 2022 daemon.notice netifd: Interface 'lan' is setting up now
Sat Jul 16 11:18:15 2022 daemon.notice netifd: lan (8451): udhcpc: started, v1.33.2
Sat Jul 16 11:18:16 2022 daemon.notice netifd: lan (8451): udhcpc: sending discover
Sat Jul 16 11:18:16 2022 daemon.notice netifd: lan (8451): udhcpc: performing DHCP renew
Sat Jul 16 11:18:16 2022 daemon.notice netifd: lan (8451): udhcpc: sending discover
Sat Jul 16 11:18:17 2022 kern.info kernel: [163385.413844] eth1: link up (100Mbps/Full duplex)
Sat Jul 16 11:18:17 2022 kern.info kernel: [163385.417530] br-lan: port 2(eth1) entered blocking state
Sat Jul 16 11:18:17 2022 kern.info kernel: [163385.422398] br-lan: port 2(eth1) entered forwarding state
Sat Jul 16 11:18:17 2022 daemon.notice netifd: Network device 'eth1' link is up
Sat Jul 16 11:18:18 2022 daemon.notice netifd: lan (8451): udhcpc: sending discover
Sat Jul 16 11:18:34 2022 daemon.notice netifd: lan (8451): udhcpc: sending select for 192.168.32.24
Sat Jul 16 11:18:34 2022 daemon.notice netifd: lan (8451): udhcpc: lease of 192.168.32.24 obtained, lease time 86400
Sat Jul 16 11:18:34 2022 daemon.notice netifd: Interface 'lan' is now up
Sat Jul 16 11:18:34 2022 user.notice firewall: Reloading firewall due to ifup of lan (br-lan)
Sat Jul 16 11:18:38 2022 daemon.info logread[932]: Logread connected to SysLog.internal.mydomain.com:514
Sat Jul 16 11:20:00 2022 cron.err crond[2061]: USER root pid 8633 cmd logger -t UpAt $( date ) Uptime $( uptime ) Procs: $( ps | wc -l ) $( free -m | grep Mem )
Sat Jul 16 11:20:00 2022 user.notice UpAt: Sat Jul 16 11:20:00 CDT 2022 Uptime 11:20:00 up 1 day, 21:24, load average: 0.03, 0.03, 0.00 Procs: 48 Mem: 58488 20140 23752 224 14596 18652
Sat Jul 16 11:22:26 2022 daemon.notice hostapd: wlan0: AP-STA-DISCONNECTED 58:91:cf:1e:05:d7

2022-07-16T10:46:27-05:00 switch.internal.mydomain.com STP: VLAN 10 Port 1/1/17 STP State -> FORWARDING (PortDown)
2022-07-16T10:46:27-05:00 switch.internal.mydomain.com STP: VLAN 10 Port 1/1/17 STP State -> DISABLED (PortDown)
2022-07-16T10:46:27-05:00 switch.internal.mydomain.com System: Interface ethernet 1/1/17, state down
2022-07-16T11:05:55-05:00 switch.internal.mydomain.com STP: VLAN 10 Port 1/1/17 STP State -> LISTENING (MakeFwding)
2022-07-16T11:05:55-05:00 switch.internal.mydomain.com System: Interface ethernet 1/1/17, state up
2022-07-16T11:05:57-05:00 switch.internal.mydomain.com STP: VLAN 10 Port 1/1/17 STP State -> LEARNING (FwdDlyExpiry)
2022-07-16T11:05:58-05:00 switch.internal.mydomain.com STP: VLAN 10 Port 1/1/17 STP State -> LEARNING (PortDown)
2022-07-16T11:05:58-05:00 switch.internal.mydomain.com STP: VLAN 10 Port 1/1/17 STP State -> DISABLED (PortDown)
2022-07-16T11:05:58-05:00 switch.internal.mydomain.com System: Interface ethernet 1/1/17, state down
2022-07-16T11:06:02-05:00 switch.internal.mydomain.com STP: VLAN 10 Port 1/1/17 STP State -> LISTENING (MakeFwding)
2022-07-16T11:06:02-05:00 switch.internal.mydomain.com System: Interface ethernet 1/1/17, state up
2022-07-16T11:06:03-05:00 switch.internal.mydomain.com STP: VLAN 10 Port 1/1/17 STP State -> LISTENING (PortDown)
2022-07-16T11:06:03-05:00 switch.internal.mydomain.com STP: VLAN 10 Port 1/1/17 STP State -> DISABLED (PortDown)
2022-07-16T11:06:03-05:00 switch.internal.mydomain.com System: Interface ethernet 1/1/17, state down
2022-07-16T11:06:57-05:00 switch.internal.mydomain.com STP: VLAN 10 Port 1/1/17 STP State -> LISTENING (MakeFwding)
2022-07-16T11:06:57-05:00 switch.internal.mydomain.com System: Interface ethernet 1/1/17, state up
2022-07-16T11:06:57-05:00 switch.internal.mydomain.com STP: VLAN 10 Port 1/1/17 STP State -> LISTENING (PortDown)
2022-07-16T11:06:57-05:00 switch.internal.mydomain.com STP: VLAN 10 Port 1/1/17 STP State -> DISABLED (PortDown)
2022-07-16T11:06:57-05:00 switch.internal.mydomain.com System: Interface ethernet 1/1/17, state down
2022-07-16T11:08:33-05:00 switch.internal.mydomain.com STP: VLAN 10 Port 1/1/17 STP State -> LISTENING (MakeFwding)
2022-07-16T11:08:33-05:00 switch.internal.mydomain.com System: Interface ethernet 1/1/17, state up

Both the switch and the AR-150 think the link went down at 10:46. But I'm the only one here and I wasn't unplugging anything, and if I had, it would have taken power with it wouldn't it being a PoE powered AP?

I went through and disabled all stp related stuff in luci and set

!
interface ethernet 1/1/17
 no spanning-tree
 inline power
!

on the switch. But I doubt stp is it. What else should I check?

#2

Presumably you have an inline usb to poe adaptor connected to the AR-150.
I have seen very similar with an MT300n-V2, it was the poe to usb power adaptor that was marginal, leading to random crashes/reboots. Worth checking particularly as you have another AR-150 that works ok, eliminating anything you are running.

#3

That presumption is false. My GL-AR150's have internal PoE support. There is no external poe to usb adapter in my setup.

The system uptime clock had not restarted either during this most recent interruption, which i think rules out a power disruption doesn't it?

I have used poe for a long time with many devices. I last changed my switch out from a cisco 24port poe switch to a brocade 48 port about 6 months ago and no other poe devices have problems with it.

#4

Just had another episode:

[163383.308773] br-lan: port 1(eth0) entered blocking state
[163383.312901] br-lan: port 1(eth0) entered disabled state
[163383.318495] device eth0 entered promiscuous mode
[163383.385467] br-lan: port 2(eth1) entered blocking state
[163383.389430] br-lan: port 2(eth1) entered disabled state
[163383.435795] device eth1 entered promiscuous mode
[163383.460517] br-lan: port 3(wlan0) entered blocking state
[163383.464526] br-lan: port 3(wlan0) entered disabled state
[163383.513371] device wlan0 entered promiscuous mode
[163383.550478] br-lan: port 3(wlan0) entered blocking state
[163383.554547] br-lan: port 3(wlan0) entered forwarding state
[163383.560174] br-lan: port 1(eth0) entered blocking state
[163383.565319] br-lan: port 1(eth0) entered forwarding state
[163385.413844] eth1: link up (100Mbps/Full duplex)
[163385.417530] br-lan: port 2(eth1) entered blocking state
[163385.422398] br-lan: port 2(eth1) entered forwarding state
[179186.724358] eth1: link down
[179186.726647] br-lan: port 2(eth1) entered disabled state
[185908.235352] eth1: link up (100Mbps/Full duplex)
[185908.240096] br-lan: port 2(eth1) entered blocking state
[185908.244060] br-lan: port 2(eth1) entered forwarding state
[185932.809890] eth1: link down
[185932.812182] br-lan: port 2(eth1) entered disabled state
[190420.985090] eth1: link up (100Mbps/Full duplex)
[190420.990062] br-lan: port 2(eth1) entered blocking state
[190420.993998] br-lan: port 2(eth1) entered forwarding state
root@AP1:~# cat /proc/uptime 
192204.31 189734.16
root@AP1:~# date
Sat Jul 16 19:18:59 CDT 2022

Nobody was touching the AP. all interfaces on it seemed to be touched. eth0, eth1, and wlan0. I think the bridge is acting up, just not sure how/why....

root@AP1:~# brctl show
bridge name     bridge id               STP enabled     interfaces
br-lan          7fff.e4956e408293       no              eth0
                                                        wlan0
                                                        eth1
root@AP1:~#
#5

This implies something is wrong with the misbehaving ar-150, its ethernet links to your switch, or the switch port.

Whether the PoE to 5volt power supply convertor is internal or external makes no difference if the ar-150 is not receiving the correct power.
The PoE internal version of the ar-150 was quite rare, the ar-150 is also becoming rare (as it is EOL), so an assumption you had an external adaptor, that turns out to be false, does not change my hypothesis that you are seeing all the symptoms of a bad power supply.

Try swapping the two ar-150s you have. If the problem stays in the same location then the problem is with the ethernet links or the switch port.
If the problem stays with the same ar-150, then it is a faulty unit.

#6

following up: I swapped the two with eachother and the problem stayed in the same room, not with the same unit. So I suspected a cabling issue. I ran a temporary cable from another ethernet drop in that room to the ar-150 experiencing the problem, and the problem went away.

So it appears there's a cabling problem in the wall between one a jack that's thoroughly a pain to get to (behind a bed), and that temporary cable just because a lot less temporary until I have the time to sort everything out to move the bed!

1 Like
#7

This topic was automatically closed 10 days after the last reply. New replies are no longer allowed.