Abnormal log messages and SM dropping regularly each evening

Hi all,

We’ve had one customer on an F300 that is dropping every day, accompanied by some interesting log events that we have not seen before. The SM is running on 4.6.2STA, using an STA frequency. Spectrum analyzer doesn’t show anything else on that frequency at either the AP or SM end. The ICMP monitoring for this device shows that in the evening, the latency spikes real high and eventually the SM drops completely. Usually the consistent latency issues in the evenings would indicate the connection or the AP itself is being maxed out, but the AP seems to be running at less than 75% capacity at peak, and the customer rarely comes close to maxing out her own connection. Congestion also wouldn’t explain why it loses the wireless link at this time. Here are the messages in the log (it pretty much looks the same every day, sanitized for security):

Aug 31 23:06:54 Cust-Radio kernel: [34331.670147] SM associated with AP[xx:xx:xx:xx:xx:xx]
Aug 31 23:06:21 Cust-Radio kernel: [34298.558941] SM cannot be associated on AP[xx:xx:xx:xx:xx:xx] F=5860 11acvht40plus. Reason: 16 (INA RETRIES EXHAUSTED)
Aug 31 23:06:21 Cust-Radio kernel: [34298.558094] SM cannot be associated on AP[xx:xx:xx:xx:xx:xx] F=5860 11acvht40plus. Reason: 24 (LOST INAR)
Aug 31 23:05:56 Cust-Radio kernel: [34274.324181] SM disassociated from AP[xx:xx:xx:xx:xx:xx] F=5860 11acvht40plus. Reason: 49 (INVALID SECURITY KEY)
Aug 31 23:05:52 Cust-Radio kernel: [34269.532980] SM associated with AP[xx:xx:xx:xx:xx:xx]
Aug 31 23:04:47 Cust-Radio kernel: [34204.719992] SM disassociated from AP[xx:xx:xx:xx:xx:xx] F=5860 11acvht40plus. Reason: 32 (NO ALLOCATION ON AP)
Aug 31 23:03:44 Cust-Radio kernel: [34142.121591] SM associated with AP[xx:xx:xx:xx:xx:xx]
Aug 31 23:02:43 Cust-Radio kernel: [34080.638087] SM cannot be associated on AP[xx:xx:xx:xx:xx:xx] F=5860 11acvht40plus. Reason: 19 (LOST AID)
Aug 31 23:01:03 Cust-Radio kernel: [33980.812496] SM disassociated from AP[xx:xx:xx:xx:xx:xx] F=5860 11acvht40plus. Reason: 32 (NO ALLOCATION ON AP)
Aug 31 22:55:36 Cust-Radio kernel: [33654.413124] SM associated with AP[xx:xx:xx:xx:xx:xx]
Aug 31 22:54:29 Cust-Radio kernel: [33586.988983] SM cannot be associated on AP[xx:xx:xx:xx:xx:xx] F=5860 11acvht40plus. Reason: 16 (INA RETRIES EXHAUSTED)
Aug 31 22:54:29 Cust-Radio kernel: [33586.988087] SM cannot be associated on AP[xx:xx:xx:xx:xx:xx] F=5860 11acvht40plus. Reason: 24 (LOST INAR)
Aug 31 22:52:38 Cust-Radio kernel: [33475.623377] SM disassociated from AP[xx:xx:xx:xx:xx:xx] F=5860 11acvht40plus. Reason: 32 (NO ALLOCATION ON AP)
Aug 31 14:06:06 Cust-Radio kernel: [ 1883.618218] SM associated with AP[xx:xx:xx:xx:xx:xx]
Aug 31 14:05:27 Cust-Radio kernel: [ 1845.143094] SM disassociated from AP[xx:xx:xx:xx:xx:xx] F=5860 11acvht40plus. Reason: 32 (NO ALLOCATION ON AP)

about to open a support ticket, but thought we would ask around here to see if anybody else has had this combination of log events before.

The Invalid Security Key log event usually indicates interference if the key is actually set properly in the SM, so that may just be what we are dealing with here, but whatever it is doesn’t seem to show up on spectrum, at least not during office hours.

This is not true. It could be a problem with signal quality. Check Line of Sight and RSSI.

It has been in our experience. We’ve had high levels of interference cause SMs to fail to connect with the Invalid Security Key message in the logs. The line of sight and signal quality are quite good, -60 RSSI.

Did u test other channel ?

I have forwarded this to our support team.
Ray

Hello @SBBinc,

did you have a chance to raise a support ticket? If yes, PM me the number please!

Which exactly F300 is it?
Why don’t you upgrade to 4.7.0.1?

It can be a bad signal or just failed radio. Will it be the same if you swap the radio?

Is 4.7.0.1 the recommended version? I thought that it was 4.6.2 or 4.7.1 and to avoid 4.7.0.1 (I thought?). I was told that 4.7.1 fixed all the issues with 4.7.0.1?

Anyway, I don’t have anything useful to add to this thread… just surprised at that advice :slight_smile:

Hello,
Were you able to ever satisfactorily resolve this trouble? We have a similar issue on 4.7.0.1STA with force 300-25’s on 2000 APs. One is a lite but it has its capacity license on and is carrying well over 10 SUs. It seemed to start when we put on the STA firmware, but that could be a red herring as perhaps its just the log clearing due to the reboot and us just paying attention after the firmware update and noticing the drops. We hadn’t heard from these folks and they have all reported the trouble started around that time. I opened an inquiry with cambium support, but will open a new one in the AM with specific data based on seeing this post and also request we roll back an AP to non STA firmware just to see if that clears up the issues. I think the issue is likely tied to noise- RSSI is excellent based on our experience and we’ve checked the install, but the drops coincide with drops in SNR. We also don’t see congestion being a likely issue based on our stats. the following logs are from two SMs on different APs.

Sep 2 05:01:34 Radio 1 kernel: [88062.022569] SM disassociated from AP[00:04:56:d4:6d:84] F=5200 11acvht20. Reason: 32 (NO ALLOCATION ON AP)
Sep 2 04:52:29 Radio1 kernel: [87516.892511] SM associated with AP[00:04:56:d4:6d:84]
Sep 2 04:48:52 Radio 1 kernel: [87300.182257] SM disassociated from AP[00:04:56:d4:6d:84] F=5200 11acvht20. Reason: 32 (NO ALLOCATION ON AP)

or

Sep 23 23:37:22 Radio 2 kernel: [181344.333326] SM associated with AP[00:04:56:d6:df:1c]
Sep 23 23:36:53 Radio 2 kernel: [181315.574307] SM disassociated from AP[00:04:56:d6:df:1c] F=5755 11acvht20. Reason: 33 (GPFs MISS)
Sep 23 23:35:54 Radio 2 kernel: [181256.381183] SM associated with AP[00:04:56:d6:df:1c]
Sep 24 00:32:40 Radio 2 kernel: [184662.155356] SM cannot be associated on AP[00:04:56:d6:df:1c] F=5755 11acvht20. Reason: 24 (LOST INAR)
Sep 24 00:32:13 Radio 2kernel: [184635.055448] SM cannot be associated on AP[00:04:56:d6:df:1c] F=5755 11acvht20. Reason: 24 (LOST INAR)
ep 23 23:56:05 radio 2 kernel: [182467.512617] SM disassociated from AP[00:04:56:d6:df:1c] F=5755 11acvht20. Reason: 32 (NO ALLOCATION ON AP)
Sep 23 23:55:15 radio 2 kernel: [182417.280547] SM associated with AP[00:04:56:d6:df:1c]
Sep 23 23:54:15 radio 2 kernel: [182357.213763] SM disassociated from AP[00:04:56:d6:df:1c] F=5755 11acvht20. Reason: 32 (NO ALLOCATION ON AP)

Hello @Natalia_Cortez-Barb,

if those messages are not legitimate and there is no interference we have to investigate it case by case.
Taking in account such considerations:

  1. STA FW does not really differ from a normal one. It just unlocks frequencies locked by FCC or ETSI radio market lock.
  2. N and AC APs most probably will not have common bugs because they are different platforms, have different SW images and share code base only partially.

We saw a bug on AC, ePMP3000L to be precise, with NO ALLOCATION ON AP. It was fixed in 4.7.0. And was not reported on 4.7.1-RC13 after continuous monitoring.

So if you see listed logs frequently, please, raise a support ticket. A button In the right top of this page.
Attach techsupport file from AP when the issue is in progress. Recover the sector in case it is possible.
Download techsupport files from AP and SM which was not able to connect before.
4.7.0.1 is an official stable. But it is highly desirable to try on the latest beta 4.7.1-RC18. It has multiple stability improvements. You have to join Beta program do be able to download the image.

In our case, it did appear to be interference from a competitor on 5GHz. It was tricky to identify as it seemed to be intermittent and no SSID was getting picked up on the spectrum analyzer. We ended up moving them to LTE, and they have not had any issues since.

1 Like

Thank you, I am almost certain our issues stem from noise as well. I am trying hard setting the modulations a bit lower in the radios though to see if that stabilizes things.