Bouncing radios

[jtara]

RT-AC88U with firmware 382.1.2.

The radios are constantly bouncing, CPU on core 1 and core 2 alternately go to 100%. I do not see the SSID on my iPhone, iPad, etc.

It was working fine, but I decided to try Enable Smart Connect. It was a mistake to mess with it...

After that, no wireless connectivity.

I noticed then when you enable smart connect, it sets both radios to the same network name. It choose the network name I was using for 5gHz... I decided to set things back the way they were - I turned off Smart Connect, and back to separate network names.

Ever since then, bouncing radios....

Now, I'm not absolutely certain that the radios were working before, as I was getting very poor speed tests on iPhone/iPad for the past couple days, and I am guessing now they failed back to cellular and I just wasn't paying attention.

I am guessing that flipping the switch to turn on Smart Connect got some settings screwed up and now I have to reset some settings. Nothing looks wrong to me, though.

Oh, I also had turned off WPS. I can't imagine that would create this problem?

Here are some log entries:

Feb 10 18:55:10 rc_service: watchdog 357:notify_rc stop_httpd
Feb 10 18:55:10 rc_service: waitting "restart_wireless" via httpd ...
Feb 10 18:55:25 rc_service: skip the event: stop_httpd.
Feb 10 18:55:25 rc_service: watchdog 357:notify_rc start_httpd
Feb 10 18:55:25 rc_service: waitting "restart_wireless" via httpd ...
Feb 10 18:55:40 rc_service: skip the event: start_httpd.
Feb 10 18:56:09 watchdog: restart httpd
Feb 10 18:56:09 rc_service: watchdog 357:notify_rc stop_httpd
Feb 10 18:56:09 rc_service: waitting "restart_wireless" via httpd ...
Feb 10 18:56:24 rc_service: skip the event: stop_httpd.
Feb 10 18:56:24 rc_service: watchdog 357:notify_rc start_httpd
Feb 10 18:56:24 rc_service: waitting "restart_wireless" via httpd ...
Feb 10 18:56:39 rc_service: skip the event: start_httpd.
Feb 10 18:57:08 watchdog: restart httpd
Feb 10 18:57:08 rc_service: watchdog 357:notify_rc stop_httpd
Feb 10 18:57:08 rc_service: waitting "restart_wireless" via httpd ...
Feb 10 18:57:23 rc_service: skip the event: stop_httpd.
Feb 10 18:57:23 rc_service: watchdog 357:notify_rc start_httpd
Feb 10 18:57:23 rc_service: waitting "restart_wireless" via httpd ...
Feb 10 18:57:38 rc_service: skip the event: start_httpd.
Feb 10 18:58:07 watchdog: restart httpd
Feb 10 18:58:07 rc_service: watchdog 357:notify_rc stop_httpd
Feb 10 18:58:07 rc_service: waitting "restart_wireless" via httpd ...
Feb 10 18:58:22 rc_service: skip the event: stop_httpd.
Feb 10 18:58:22 rc_service: watchdog 357:notify_rc start_httpd
Feb 10 18:58:22 rc_service: waitting "restart_wireless" via httpd ...
Feb 10 18:58:37 rc_service: skip the event: start_httpd.
Feb 10 18:59:06 watchdog: restart httpd
Feb 10 18:59:06 rc_service: watchdog 357:notify_rc stop_httpd
Feb 10 18:59:06 rc_service: waitting "restart_wireless" via httpd ...
Feb 10 18:59:21 rc_service: skip the event: stop_httpd.
Feb 10 18:59:21 rc_service: watchdog 357:notify_rc start_httpd
Feb 10 18:59:21 rc_service: waitting "restart_wireless" via httpd ...
Feb 10 18:59:36 rc_service: skip the event: start_httpd.
Feb 10 19:00:05 watchdog: restart httpd
Feb 10 19:00:05 rc_service: watchdog 357:notify_rc stop_httpd
Feb 10 19:00:05 rc_service: waitting "restart_wireless" via httpd ...
Feb 10 19:00:20 rc_service: skip the event: stop_httpd.
Feb 10 19:00:20 rc_service: watchdog 357:notify_rc start_httpd
Feb 10 19:00:20 rc_service: waitting "restart_wireless" via httpd ...
Feb 10 19:00:35 rc_service: skip the event: start_httpd.
Feb 10 19:01:04 watchdog: restart httpd
Feb 10 19:01:04 rc_service: watchdog 357:notify_rc stop_httpd
Feb 10 19:01:04 rc_service: waitting "restart_wireless" via httpd ...
Feb 10 19:01:19 rc_service: skip the event: stop_httpd.
Feb 10 19:01:19 rc_service: watchdog 357:notify_rc start_httpd
Feb 10 19:01:19 rc_service: waitting "restart_wireless" via httpd ...
Feb 10 19:01:34 rc_service: skip the event: start_httpd.

 

[jtara]

The radios stopped bouncing when I powered down/back up after having trouble with changing uername/password/https/port.

What is strange is that I powered down/up several times prior and it did NOT fix the radio problem.

I can now connect to the wifi, and it also solved my WiFi speed problem I'd been having for the past couple of days.

I was not able to turn the radios off manually, because I did not have Telnet or SSH set-up. I've fixed that!

 

[jtara]

Bouncing again, though this time without the 100% CPU, and with different log messages. Haven't tried another reboot yet. Lots of error messages in the log.

Anybody understand anything in these log entries. Hopefully I've captured enough to make sense to somebody.

Throughput is obviously horrible on WiFi (though I do get some.)

Feb 11 19:39:12 kernel: CONSOLE: 113768.223 wl0: Proxy STA d0:4f:7e:75:29:ce ignoring bsscfg_free while in PS
Feb 11 19:39:12 kernel: CONSOLE: 113768.223 wl0: Proxy STA d0:4f:7e:75:29:ce link is already gone !!??
Feb 11 19:40:58 kernel: CONSOLE: 113873.974 bcm_pack_xtlv_entry: no space tlv_buf: requested:260, available:236
Feb 11 19:40:58 kernel: CONSOLE: 113944.712 bcm_pack_xtlv_entry: no space tlv_buf: requested:260, available:236
Feb 11 19:41:13 kernel: CONSOLE: 113889.042 wl0: turn sta MFP setting on with sha1
Feb 11 19:41:13 kernel: CONSOLE: 113889.046 flow_create : bitmap_size=512 maxitems=512
Feb 11 19:41:26 kernel: dhd_flow_rings_delete_for_peer: ifindex 0
Feb 11 19:41:26 kernel: CONSOLE: 113902.092 wl0: Proxy STA 40:98:ad:26:39:3d link is already gone !!??
Feb 11 19:41:34 kernel: CONSOLE: 113910.049 wl0: wlc_lq_chanim_update: WLC_CHANIM upd blocked scan/detect
Feb 11 19:41:34 kernel: CONSOLE: 113910.049 wl0: wlc_watchdog: WLC_CHANIM upd fail -25
Feb 11 19:42:38 kernel: CONSOLE: 113973.654 wl0: turn sta MFP setting on with sha1
Feb 11 19:42:38 kernel: CONSOLE: 113973.654 wl0: wlc_ht_send_action_obss_coex: Not STA
Feb 11 19:42:38 kernel: CONSOLE: 113973.657 flow_create : bitmap_size=512 maxitems=512
Feb 11 19:42:43 kernel: CONSOLE: 113979.466 wl0.0: non-802.1X frame to unauthorized station d0:4f:7e:75:29:ce
Feb 11 19:42:49 kernel: dhd_flow_rings_delete_for_peer: ifindex 0
Feb 11 19:42:49 kernel: CONSOLE: 113985.082 wl0: Proxy STA d0:4f:7e:75:29:ce link is already gone !!??
Feb 11 19:43:08 kernel: CONSOLE: 114003.696 wl0: turn sta MFP setting on with sha1
Feb 11 19:43:08 kernel: CONSOLE: 114003.696 wl0: wlc_ht_send_action_obss_coex: Not STA
Feb 11 19:43:08 kernel: CONSOLE: 114003.699 flow_create : bitmap_size=512 maxitems=512
Feb 11 19:43:17 kernel: CONSOLE: 114012.580 wl0: turn sta MFP setting on with sha1
Feb 11 19:43:17 kernel: dhd_wait_pend8021x: TIMEOUT
Feb 11 19:43:17 kernel: CONSOLE: 114012.820 flow_create : bitmap_size=512 maxitems=512
Feb 11 19:43:19 kernel: CONSOLE: 114015.198 wl0: Proxy STA d0:4f:7e:75:29:ce ignoring bsscfg_free while in PS
Feb 11 19:43:20 kernel: dhd_flow_rings_delete_for_peer: ifindex 0
Feb 11 19:43:20 kernel: CONSOLE: 114015.946 wl0: Proxy STA d0:4f:7e:75:29:ce link is already gone !!??
Feb 11 19:43:28 kernel: CONSOLE: 114024.076 wl0: Proxy STA 40:98:ad:26:39:3d link is already gone !!??
Feb 11 19:43:29 kernel: dhd_flow_rings_delete_for_peer: ifindex 0
Feb 11 19:43:29 kernel: CONSOLE: 114025.071 wl0: Proxy STA 40:98:ad:26:39:3d link is already gone !!??
Feb 11 19:43:34 kernel: CONSOLE: 114029.744 wl0: turn sta MFP setting on with sha1
Feb 11 19:43:34 kernel: CONSOLE: 114029.744 wl0: wlc_ht_send_action_obss_coex: Not STA
Feb 11 19:43:34 kernel: CONSOLE: 114029.747 flow_create : bitmap_size=512 maxitems=512
Feb 11 19:43:34 kernel: CONSOLE: 114030.058 wl0: turn sta MFP setting on with sha1
Feb 11 19:43:34 kernel: CONSOLE: 114030.061 flow_create : bitmap_size=512 maxitems=512
Feb 11 19:43:34 kernel: CONSOLE: 114030.355 wl0.0: non-802.1X frame to unauthorized station d0:4f:7e:75:29:ce
Feb 11 19:43:34 kernel: CONSOLE: 114030.355 wl0.0: non-802.1X frame to unauthorized station 40:98:ad:26:39:3d
Feb 11 19:43:43 kernel: CONSOLE: 114039.198 wl0.0: non-802.1X frame to unauthorized station 40:98:ad:26:39:3d
Feb 11 19:43:45 kernel: CONSOLE: 114040.933 wl0: Proxy STA d0:4f:7e:75:29:ce ignoring bsscfg_free while in PS
Feb 11 19:43:46 kernel: dhd_flow_rings_delete_for_peer: ifindex 0

 

[jtara]

Also, I notice I had a LOT of these earlier:
Feb 11 15:45:11 dnsmasq[351]: failed to send packet: Operation not permitted
Feb 11 15:45:11 dnsmasq[351]: failed to send packet: Operation not permitted
Feb 11 15:45:11 dnsmasq[351]: failed to send packet: Operation not permitted
Feb 11 15:45:11 dnsmasq[351]: failed to send packet: Operation not permitted
Feb 11 15:45:11 dnsmasq[351]: failed to send packet: Operation not permitted
Feb 11 15:45:11 dnsmasq[351]: failed to send packet: Operation not permitted
Feb 11 15:45:11 dnsmasq[351]: failed to send packet: Operation not permitted
Feb 11 15:45:11 dnsmasq[351]: failed to send packet: Operation not permitted

Some kind of memory exhaustion?

Feb 11 15:40:57 kernel: CONSOLE: 099500.026 bcm_pack_xtlv_entry: no space tlv_buf: requested:260, available:236
Feb 11 15:40:58 kernel: CONSOLE: 099559.670 bcm_pack_xtlv_entry: no space tlv_buf: requested:260, available:236
Feb 11 15:43:06 dnsmasq[351]: failed to send packet: Operation not permitted

 

[jtara]

A reboot cured for now. I've set up a nightly reboot.

It's either something with 382.1.2 or else I messed things up GOOD by trying Smart Connect.

 

[jtara]

Alas, the nightly reboot isn't enough. Not sure if it failed since 4:00AM this morning, or if it has to be a power-down reboot (which seemed to be the case previously).

I was asked to capture "top" - it seems unremarkable. But I will post here in case somebody notices something. It is NOT using 100% CPU, though, or anything close.

I can only post 10,000 characters, so will just post the first part.

Mem: 195896K used, 319408K free, 1920K shrd, 848K buff, 12712K cached
CPU: 0.0% usr 0.0% sys 0.0% nic 95.0% idle 0.0% io 0.0% irq 5.0% sirq
Load average: 0.20 0.18 0.15 1/114 7722
PID PPID USER STAT VSZ %VSZ CPU %CPU COMMAND
7722 7225 jtara R 1456 0.2 0 5.0 top -b
319 1 jtara S 8776 1.7 1 0.0 nt_center
324 319 jtara S 8776 1.7 0 0.0 nt_center
325 324 jtara S 8776 1.7 1 0.0 nt_center
380 1 jtara S 6236 1.2 1 0.0 mastiff
377 1 jtara S 6236 1.2 1 0.0 networkmap --bootwait
1758 399 jtara S 6236 1.2 0 0.0 mastiff
399 380 jtara S 6236 1.2 1 0.0 mastiff
400 399 jtara S 6236 1.2 1 0.0 mastiff
410 1 jtara S 6072 1.1 1 0.0 /usr/sbin/smbd -D -s /etc/smb.conf
411 1 jtara S 5912 1.1 1 0.0 nmbd -D -s /etc/smb.conf
412 411 jtara S 5592 1.0 0 0.0 nmbd -D -s /etc/smb.conf
356 1 jtara S 5560 1.0 1 0.0 httpds -s -p 8443 -i br0
340 316 jtara S 5144 1.0 1 0.0 nt_monitor
317 316 jtara S 5144 1.0 0 0.0 nt_monitor
301 1 jtara S 5144 1.0 1 0.0 nt_monitor
316 301 jtara S 5144 1.0 1 0.0 nt_monitor
360 1 jtara S 4912 0.9 0 0.0 watchdog
303 1 jtara S 4900 0.9 1 0.0 /sbin/netool
310 303 jtara S 4900 0.9 1 0.0 /sbin/netool
311 310 jtara S 4900 0.9 0 0.0 /sbin/netool
1 0 jtara S 4896 0.9 1 0.0 /sbin/preinit
293 1 jtara S 4884 0.9 1 0.0 /sbin/wanduck
361 1 jtara S 4880 0.9 1 0.0 sw_devled
764 1 jtara S 4880 0.9 0 0.0 bwdpi_wred_alive
413 1 jtara S 4880 0.9 0 0.0 erp_monitor
610 1 jtara S 4880 0.9 1 0.0 ntp
631 1 jtara S 4880 0.9 0 0.0 disk_monitor
551 1 jtara S 4880 0.9 1 0.0 usbled
365 360 jtara S 4880 0.9 1 0.0 ots
382 1 jtara S 4880 0.9 0 0.0 hour_monitor
381 1 jtara S 4880 0.9 0 0.0 bwdpi_check
328 1 jtara S 4880 0.9 0 0.0 wpsaide
141 1 jtara S 4876 0.9 1 0.0 console
366 1 jtara S 2884 0.5 1 0.0 rstats
670 669 jtara S 2808 0.5 0 0.0 wred -B
667 1 jtara S 2808 0.5 1 0.0 wred -B
679 669 jtara S 2808 0.5 1 0.0 wred -B
669 667 jtara S 2808 0.5 1 0.0 wred -B
674 669 jtara S 2808 0.5 1 0.0 wred -B
673 669 jtara S 2808 0.5 0 0.0 wred -B
677 669 jtara S 2808 0.5 0 0.0 wred -B
678 669 jtara S 2808 0.5 1 0.0 wred -B
676 669 jtara S 2808 0.5 1 0.0 wred -B
675 669 jtara S 2808 0.5 1 0.0 wred -B
672 669 jtara S 2808 0.5 0 0.0 wred -B
552 1 jtara S 2352 0.4 1 0.0 u2ec
555 552 jtara S 2352 0.4 0 0.0 u2ec
556 555 jtara S 2352 0.4 1 0.0 u2ec
339 1 jtara S 2240 0.4 0 0.0 /usr/sbin/wlceventd
353 1 jtara S 2208 0.4 0 0.0 avahi-daemon: running [RT-AC88U-8610.local]
329 1 jtara S 2208 0.4 1 0.0 /usr/sbin/wlc_nt
302 1 jtara S 2072 0.4 0 0.0 protect_srv
315 314 jtara S 2072 0.4 0 0.0 protect_srv
314 302 jtara S 2072 0.4 1 0.0 protect_srv
332 1 jtara S 2056 0.4 0 0.0 nas
660 1 jtara S 1872 0.3 0 0.0 dcd -i 3600 -p 43200 -b -d /tmp/bwdpi/
666 661 jtara S 1872 0.3 0 0.0 dcd -i 3600 -p 43200 -b -d /tmp/bwdpi/
663 661 jtara S 1872 0.3 0 0.0 dcd -i 3600 -p 43200 -b -d /tmp/bwdpi/
4699 661 jtara S 1872 0.3 0 0.0 dcd -i 3600 -p 43200 -b -d /tmp/bwdpi/
661 660 jtara S 1872 0.3 0 0.0 dcd -i 3600 -p 43200 -b -d /tmp/bwdpi/
662 661 jtara S 1872 0.3 1 0.0 dcd -i 3600 -p 43200 -b -d /tmp/bwdpi/
664 661 jtara S 1872 0.3 0 0.0 dcd -i 3600 -p 43200 -b -d /tmp/bwdpi/

 

[jtara]

I thought there was some way to filter log entries, but apparently not? It seems you can only control what is LOGGED, not what is shown?

Anyway, some more suspicious log entries:

eb 13 07:37:37 kernel: CONSOLE: 039660.306 wl1.0: wlc_send_bar: seq 0x7b1 tid 0
Feb 13 07:37:37 kernel: CONSOLE: 039660.309 wl1.0: wlc_send_bar: seq 0x7b1 tid 0
Feb 13 07:37:37 kernel: CONSOLE: 039660.313 wl1.0: wlc_send_bar: seq 0x7b1 tid 0
Feb 13 07:37:38 kernel: CONSOLE: 039661.157 wl1: wlc_ampdu_tx_send_delba: tid 0 initiator 1 reason 39
Feb 13 07:37:42 kernel: CONSOLE: 039665.516 wl1: turn sta MFP setting on with sha1
Feb 13 07:37:45 kernel: CONSOLE: 039667.696 wl1: Proxy STA d0:4f:7e:75:29:ce link is already gone !!??
Feb 13 07:37:48 kernel: CONSOLE: 039656.555 wl0: turn sta MFP setting on with sha1
Feb 13 07:37:48 kernel: CONSOLE: 039656.555 wl0: wlc_ht_send_action_obss_coex: Not STA
Feb 13 07:37:49 kernel: dhd_wait_pend8021x: TIMEOUT
Feb 13 07:37:49 kernel: CONSOLE: 039657.566 flow_create : bitmap_size=512 maxitems=512
Feb 13 07:37:50 kernel: CONSOLE: 039658.548 wl0.0: wlc_send_bar: seq 0x3 tid 0
Feb 13 07:37:57 kernel: CONSOLE: 039679.946 wl1.0: wlc_send_bar: seq 0x18 tid 0
Feb 13 07:38:03 kernel: CONSOLE: 039671.654 wl0.0: wlc_send_bar: seq 0x1e8 tid 0
Feb 13 07:38:04 kernel: CONSOLE: 039672.663 flow_create : bitmap_size=512 maxitems=512
Feb 13 07:38:06 kernel: CONSOLE: 039674.820 wl0.0: wlc_send_bar: seq 0x4 tid 6
Feb 13 07:38:17 kernel: CONSOLE: 039685.883 Ring: d2hc Local ring bufs not available
Feb 13 07:38:17 kernel: CONSOLE: 039685.884 Ring: d2hc Local ring bufs not available
Feb 13 07:38:24 kernel: CONSOLE: 039692.299 wl0.0: wlc_send_bar: seq 0xae9 tid 0
Feb 13 07:38:30 kernel: CONSOLE: 039698.540 Ring: d2hc Local ring bufs not available
Feb 13 07:38:30 kernel: CONSOLE: 039698.540 Ring: d2hc Local ring bufs not available
Feb 13 07:38:30 kernel: CONSOLE: 039698.540 Ring: d2hc Local ring bufs not available
Feb 13 07:38:35 kernel: CONSOLE: 039703.586 Ring: d2hc Local ring bufs not available
Feb 13 07:38:35 kernel: CONSOLE: 039703.586 Ring: d2hc Local ring bufs not available
Feb 13 07:38:35 kernel: CONSOLE: 039703.586 Ring: d2hc Local ring bufs not available
Feb 13 07:38:43 kernel: CONSOLE: 039711.583 Ring: d2hc Local ring bufs not available
Feb 13 07:38:43 kernel: CONSOLE: 039711.583 Ring: d2hc Local ring bufs not available
Feb 13 07:38:43 kernel: CONSOLE: 039711.583 Ring: d2hc Local ring bufs not available

And this:

Feb 13 06:47:11 kernel: CONSOLE: 036626.832 bcm_pack_xtlv_entry: no space tlv_buf: requested:260, available:236
Feb 13 06:47:12 kernel: CONSOLE: 036638.450 bcm_pack_xtlv_entry: no space tlv_buf: requested:260, available:236
Feb 13 06:58:20 kernel: CONSOLE: 037294.504 wl0: wlc_lq_chanim_update: WLC_CHANIM upd blocked scan/detect
Feb 13 06:58:20 kernel: CONSOLE: 037294.504 wl0: wlc_watchdog: WLC_CHANIM upd fail -25
Feb 13 07:02:10 kernel: dhd_flow_rings_delete_for_peer: ifindex 0
Feb 13 07:02:10 kernel: dhd_flow_rings_delete_for_peer: ifindex 0
Feb 13 07:02:10 kernel: CONSOLE: 037535.383 wl1: Proxy STA 00:23:6c:83:da:47 link is already gone !!??
Feb 13 07:02:11 kernel: CONSOLE: 037524.538 bcm_pack_xtlv_entry: no space tlv_buf: requested:260, available:236
Feb 13 07:02:12 kernel: CONSOLE: 037537.325 bcm_pack_xtlv_entry: no space tlv_buf: requested:260, available:236
Feb 13 07:02:13 kernel: dhd_wait_pend8021x: TIMEOUT
Feb 13 07:03:44 watchdog: Hostname/IP mapping error! Restart ddns.
Feb 13 07:03:44 rc_service: watchdog 360:notify_rc start_ddns
Feb 13 07:03:44 start_ddns: update WWW.DYNDNS.ORG dyndns, wan_unit 0
Feb 13 07:03:44 ddns_update: ez-ipupdate: starting...
Feb 13 07:03:44 ddns_update: connected to members.dyndns.org (162.88.175.12) on port 80.
Feb 13 07:03:44 ddns_update: members.dyndns.org says that your IP address has not changed since the last update
Feb 13 07:03:44 ddns_update: asusddns_update: 0
Feb 13 07:03:45 ddns: ddns update ok

 

[jtara]

After a reboot, the radios are fine.

Not really sure I'm seeing the same problem as when it was "bouncing".

Symptom is very poor throughput on WiFi, but throughput unaffected on wired network. By "very poor", I mean I normally get 300-350mbps down on speedtest, but once it goes wonky I might get 10-20 mbps.

I am using Speedtest, which I know is not the best for diagnosing WiFi problems. Next time I will remember to use WiFi Sweetspots, which tests WiFi throughput to the router. (Uses iPerf? Or something else? They don't say.)

 

[jtara]

Once again this morning I had to reboot. Same symptom - crappy/jerky WiFi performance, but find wired. But no repeat of the 100% CPU, so I guess a different issue.

This time, nothing suspicious in the log, but really I don't know what I'd be looking for.

I'm afraid I will either need to drop back to a previous version (on 382.1.2) or else start clean with 382.1.2 and set everything up from scratch.

This started happening either with 382.1.2 or with my ill-fated experiment with Enable Smart Connect.

I've disabled all QOS, Traffic Analyzer, etc. in case they might be interfering. Will see if this happens again tomorrow, if so I'll have to bite the bullet and just start over.

It had been stable and never required reboots before the update to 382.1.2.