Wireless Access

Hello,

We recently upgraded our M3 controller to AOS 6.4.2.6 and I noticed that one AP is showing in the system logs with incrementing numbers:

Apr 23 10:09:24  KERNEL(AP_NAME@192.168.66.74): [67950.222672]
Apr 23 10:09:52  KERNEL(AP_NAME@192.168.66.74): [67977.569164]
Apr 23 10:10:06  KERNEL(AP_NAME@192.168.66.74): [67991.913480]
Apr 23 10:10:12  KERNEL(AP_NAME@192.168.66.74): [67998.456512]
Apr 23 10:10:21  KERNEL(AP_NAME@192.168.66.74): [68007.348325]
Apr 23 10:10:43  KERNEL(AP_NAME@192.168.66.74): [68028.815591]
Apr 23 10:10:45  KERNEL(AP_NAME@192.168.66.74): [68031.339407]
Apr 23 10:10:54  KERNEL(AP_NAME@192.168.66.74): [68040.482872]
Apr 23 10:12:46  KERNEL(AP_NAME@192.168.66.74): [68151.546531]
Apr 23 10:13:00  KERNEL(AP_NAME@192.168.66.74): [68165.974742]
Apr 23 10:13:31  KERNEL(AP_NAME@192.168.66.74): [68196.807312]
Apr 23 10:15:05  KERNEL(AP_NAME@192.168.66.74): [68290.963298]
Apr 23 10:15:33  KERNEL(AP_NAME@192.168.66.74): [68319.316412]
Apr 23 10:15:51  KERNEL(AP_NAME@192.168.66.74): [68336.596698]
Apr 23 10:15:53  KERNEL(AP_NAME@192.168.66.74): [68339.197131]
Apr 23 10:18:00  KERNEL(AP_NAME@192.168.66.74): [68466.282819]

As anybody seen this before?

show ap debug crash-info ap-name returns nothing and AP is live and working.

Thanks

Yann

I think you may have chopped the end of the message, the number that is incrementing is a timestamp - there should be stuff after it, example:

Apr 23 01:07:24  KERNEL(ap225-sales@10.74.32.131): [149815.906120] <64:76:ba:ae:2f:7e> [wlc_dotxstatus@40810]:sent data packet dcae8900, seqnum 0x568, pkttag->seq = 0x568, was_acked 1, supr_status 0
Apr 23 01:07:24  KERNEL(ap225-sales@10.74.32.131): [149816.061422] <64:76:ba:ae:2f:7e> [wlc_dotxstatus@40810]:sent data packet dcae8900, seqnum 0x568, pkttag->seq = 0x568, was_acked 1, supr_status 0
Apr 23 15:28:31  KERNEL(ap225-sales@10.74.32.131): [201483.270693] chan dur      ibss           obss           interf       time
Apr 23 15:28:31  KERNEL(ap225-sales@10.74.32.131): [201483.353060] 161 1002    4  0% Low     139 13% Medium 8305 828% High   201480
Apr 23 15:28:31  KERNEL(ap225-sales@10.74.32.131): [201483.438514] 161 1000    9  0% Low      55  5% Low      21  2% Low    201479
Apr 23 15:28:31  KERNEL(ap225-sales@10.74.32.131): [201483.522918] 161 1000    8  0% Low      80  8% Low      24  2% Low    201478

It appears R&D has decided to start sending the ap console log messages from the AP to the controller into the system log. I am trying to find out if this is really what they wanted to do as it's going to create consternation for customers and these messages come with zero information outside of R&D - will update when I learn something, hopefully in next 48 hours.

I should add - these messages are probably just informational, despite some often scary sounding language - please post a snapshot of them here so we can try to make a judgement if you need a TAC case too. You can also find these logs in "show ap debug log ap-name <>"

regards

-jeff

Hi jgoff,

I wish I could say that the messages have been truncated but what I've posted is exactly what I got except for the ap name. I did notice however that every once in a while  - 100/full would be added.

Apr 25 03:04:17  KERNEL(AP_NAME@192.168.66.74): [215242.192121]
Apr 25 03:07:27  KERNEL(AP_NAME@192.168.66.74): [215432.562999]  - 100/Full
Apr 25 03:08:14  KERNEL(AP_NAME@192.168.66.74): [215479.670385]
Apr 25 03:09:42  KERNEL(AP_NAME@192.168.66.74): [215567.162382]
Apr 25 03:09:52  KERNEL(AP_NAME@192.168.66.74): [215577.648007]
Apr 25 03:12:46  KERNEL(AP_NAME@192.168.66.74): [215751.289836]
Apr 25 03:12:53  KERNEL(AP_NAME@192.168.66.74): [215758.587833]
Apr 25 03:13:10  KERNEL(AP_NAME@192.168.66.74): [215774.795215]  - 100/Full
Apr 25 03:13:58  KERNEL(AP_NAME@192.168.66.74): [215822.843693]

Sometimes it's hours between those tidbits of information.

Thank you for looking into this.

hi Yann

you might be able to see the full message using "show ap debug log ap-name <>", can you try to see ? At least 2 new messages were added to 6.4.2.6 that seem to have an incorrect priority on them, hence they are being spammed to the system log - but your case may be different.

see if you can get the full output from the ap debug log, there may be something else at play here

regards

-jeff

Hi jgoff,

The only thing different in the ap debug log is two lines far apart :

Apr 27 05:58:40 sapd[2008]: <404069> <WARN> |AP AP_NAME@10.254.254.3 sapd|  ^[bssid 18:64:72:65:65:40] [min_amc_channel 11] [arm_nii_arm_nccii 112] [ap_amc_channel 1] [arm_nccii_arm_nii 142] [channel 11] [new_tx_power 7] [arm_tci 10]

Apr 27 08:50:10 sapd[2008]: <404075> <WARN> |AP AP_NAME@10.254.254.3 sapd|  ^[bssid 18:64:72:65:65:40] [arm_ci 11] [arm_nci 1] [current_tx_power 7] [current_channel 11] [current_tx_power_2 6]

Yann

Seems the IP you are checking is different now - not sure if that was intentional ? At any rate, the log may only exist for a short time, you also need to check "show ap debug driver-log ap-name<>" as well. Wait for the message to re-appear and recollect both as close as possible.

regards

-jeff

Hi jgoff,

The IP is different because that was the VPN IP, instead of the local IP

The driver log shows a lot more information and provides insight as to what is actually happening.

[411983.833079] PHY: eth0 (mdio@ffe24000:00) - Link is Up - 100/Full
[411983.941073] bonding: bond0: link status definitely up for interface eth0.
[411984.023459] bonding: bond0: making interface eth0 the new active one.
[411984.689091] PHY: eth0 (mdio@ffe24000:00) - Link is Down
[411984.901075] bonding: bond0: link status definitely down for interface eth0, disabling it
[411984.999076] bonding: bond0: making interface eth1 the new active one.
[411986.504834] PHY: eth0 (mdio@ffe24000:00) - Link is Up - 100/Full
[411986.677071] bonding: bond0: link status definitely up for interface eth0.
[411986.759414] bonding: bond0: making interface eth0 the new active one.
[411987.373425] PHY: eth0 (mdio@ffe24000:00) - Link is Down
[411987.637074] bonding: bond0: link status definitely down for interface eth0, disabling it
[411987.735047] bonding: bond0: making interface eth1 the new active one.
[411989.335953] PHY: eth0 (mdio@ffe24000:00) - Link is Up - 100/Full
[411989.413564] bonding: bond0: link status definitely up for interface eth0.
[411989.495912] bonding: bond0: making interface eth0 the new active one.
[411990.225496] PHY: eth0 (mdio@ffe24000:00) - Link is Down
[411990.373569] bonding: bond0: link status definitely down for interface eth0, disabling it
[411990.471550] bonding: bond0: making interface eth1 the new active one.
[411992.515716] PHY: eth0 (mdio@ffe24000:00) - Link is Up - 100/Full
[411992.589657] bonding: bond0: link status definitely up for interface eth0.
[411992.672030] bonding: bond0: making interface eth0 the new active one.
[411993.413119] PHY: eth0 (mdio@ffe24000:00) - Link is Down
[411993.549664] bonding: bond0: link status definitely down for interface eth0, disabling it
[411993.625107] stats > 100: ccastats_us: 2392497, acc->statss_ms: 2354
[411993.647741] bonding: bond0: making interface eth1 the new active one.