EXOS switch creating dual EMS log entries in actual and lower case?

[Anonymous]

Hi,

Getting a really strange issue in EXOS version 31.5.1.6, Universal switch 5220.

Have this log entry historically showing in the logs:

04/27/2022 16:42:29.67 <Info:nl.ClientAuthenticated> Slot-1: Network Login MAC user 00107FF11266 logged in MAC 00:10:7F:F1:12:66 port 1:21 VLAN(s) "AVcon-VLAN" policy "avcon", authentication Radius

The specific attention being drawn to where is says policy "avcon"

If I disable to port then re-enable, I then get the following appear:

04/27/2022 17:22:17.81 <Info:nl.ClientAuthenticated> Slot-1: Network Login MAC user 00107FF11266 logged in MAC 00:10:7F:F1:12:66 port 1:21 VLAN(s) "AVcon-VLAN" policy "AVcon", authentication Radius
04/27/2022 17:22:19.86 <Info:nl.ClientAuthenticated> Slot-1: Network Login MAC user 00107FF11266 logged in MAC 00:10:7F:F1:12:66 port 1:21 VLAN(s) "AVcon-VLAN" policy "avcon", authentication Radius

You see there the first entry records policy as "AVcon", this is in fact the real policy name:

configure policy profile 7 name "AVcon" pvid-status "enable" pvid 1066 nsi 12041066

Then for some reason almost immediately after you get another entry like before but all lower case policy name "avcon"!?

This is an issue for me as I have a UPM that is triggering on the actual real policy name "AVcon", and do something else if there is no match. Since "avcon" is different to "AVcon", and that event "avcon" comes in last, it triggers my elseif statement straight after previously matching it. So effectively it is triggering both my if and elseif statements!

I could fix this by only using avcon, but the point is why is this happening, something does not seem to be right.

Anyone seen this before?

Many thanks,

Martin

[Anonymous]

Hi Chris,

Sorry for the delay. The reboot lost the SSH key, so couldn't get in for a while.

Unfortunately it did not straighten out the issue. So see messages below taken from the log:

05/03/2022 20:24:00.80 <Info:nl.ClientAuthenticated> Slot-1: Network Login MAC user 58FCDB434FED logged in MAC 58:FC:DB:43:4F:ED port 1:30 VLAN(s) "AVcol-VLAN" policy "avcol", authentication Radius
05/03/2022 20:23:59.40 <Info:nl.ClientAuthenticated> Slot-1: Network Login MAC user 58FCDB43593C logged in MAC 58:FC:DB:43:59:3C port 1:35 VLAN(s) "AVcol-VLAN" policy "avcol", authentication Radius
05/03/2022 20:23:59.24 <Info:nl.ClientAuthenticated> Slot-1: Network Login MAC user 58FCDB434FCA logged in MAC 58:FC:DB:43:4F:CA port 1:29 VLAN(s) "AVcol-VLAN" policy "avcol", authentication Radius
05/03/2022 20:23:58.29 <Info:nl.ClientAuthenticated> Slot-1: Network Login MAC user 58FCDB435782 logged in MAC 58:FC:DB:43:57:82 port 2:14 VLAN(s) "AVcol-VLAN" policy "avcol", authentication Radius
05/03/2022 20:23:40.10 <Info:nl.ClientAuthenticated> Slot-1: Network Login MAC user 58FCDB435008 logged in MAC 58:FC:DB:43:50:08 port 1:19 VLAN(s) "AVcol-VLAN" policy "avcol", authentication Radius
05/03/2022 20:23:38.60 <Info:nl.ClientAuthenticated> Slot-1: Network Login MAC user 58FCDB437F70 logged in MAC 58:FC:DB:43:7F:70 port 3:17 VLAN(s) "AVcol-VLAN" policy "avcol", authentication Radius
05/03/2022 20:23:19.73 <Info:nl.ClientAuthenticated> Slot-1: Network Login MAC user 58FCDB4394AE logged in MAC 58:FC:DB:43:94:AE port 2:31 VLAN(s) "AVcol-VLAN" policy "avcol", authentication Radius
05/03/2022 20:20:53.48 <Info:nl.ClientAuthenticated> Slot-1: Network Login MAC user 006074FD82AB logged in MAC 00:60:74:FD:82:AB port 2:30 VLAN(s) "AVip-VLAN" policy "avip", authentication Radius
05/03/2022 20:16:26.38 <Info:nl.ClientAuthenticated> Slot-1: Network Login MAC user 94DB56E381EA logged in MAC 94:DB:56:E3:81:EA port 1:14 VLAN(s) "AVcon-VLAN" policy "avcon", authentication Radius
05/03/2022 20:14:02.04 <Info:nl.ClientAuthenticated> Slot-1: Network Login MAC user BCF310E2BA80 logged in MAC BC:F3:10:E2:BA:80 port 1:48 VLAN(s) "WlanMgmt-VLAN" policy "access point", authentication Radius
05/03/2022 20:13:49.53 <Info:nl.ClientAuthenticated> Slot-1: Network Login MAC user 000A8305F3AB logged in MAC 00:0A:83:05:F3:AB port 3:2 VLAN(s) "Salto-VLAN" policy "salto", authentication Radius
05/03/2022 20:12:52.73 <Info:nl.ClientAuthenticated> Slot-1: Network Login MAC user 00107FF112E2 logged in MAC 00:10:7F:F1:12:E2 port 1:13 VLAN(s) "AVcon-VLAN" policy "avcon", authentication Radius
05/03/2022 20:12:52.08 <Info:nl.ClientAuthenticated> Slot-1: Network Login MAC user 00107FF11200 logged in MAC 00:10:7F:F1:12:00 port 2:13 VLAN(s) "AVcon-VLAN" policy "avcon", authentication Radius

It goes on like this, and everything looks OK. You see the policy name is always lowercase. These entries are all related to re-auth, rather then new devices connecting, or ports connecting and disconnecting as far as I can tell. Re-Auth is set to 3600s.

Now if I disable and enable the port for the first entry in that log, port 1:30, here is the log it generates:

05/03/2022 20:31:37.87 <Info:nl.ClientAuthenticated> Slot-1: Network Login MAC user 58FCDB434FED logged in MAC 58:FC:DB:43:4F:ED port 1:30 VLAN(s) "AVcol-VLAN" policy "AVcol", authentication Radius

You see the policy name is exactly how it should be with the case alignment. This is how the policy is configured in the switch, how it is configured in NAC, and how it is being sent in the attributes.

So the problem still exists, this seem buggy to you?

Thanks

[CThompsonEXOS]

Hi Martin,

Any good news after the reboot?


Thanks,
Chris Thompson

[Anonymous]

Hi Chris,

Thanks for posting back.

Not show how related the article is to the issue I have, in that the issue is that EXOS seems to be recording the same event twice, first referencing the policy as 'AVcon', which is correct, then again immediately after as 'avcon' which is incorrect. It is the fact it repeats with a policy name that the case of the policy wording is what is causing the issue. As the UPM is configured to use the correct case, but when another entry appears for the same thing, but lower case, there is no match, so then re-handles it correctly. There are probably ways in the UPM script to manage it, but it seems like incorrect behaviour is more the problem.

I don't know why it is doing that, since the policy is actually 'AVcon', and the attributes sent to EXOS via ExtremeControl is in the correct format, where and why is it repeating it in lower case again, is very strange. It is like it is doing it itself, as there no reference anywhere of the policy in all lowercase?

I've not been able to find anything else related to the article, and using ExtremeControl to answer your question directly.

So rather odd. 

One thing I am going to try is a reboot later this evening. Since it seems entries where all showing lowercase, but when disabling and enabling the port it is then after that both show. It is almost like there maybe a cache of the lowercase entry stored, that maybe rebooting will clear.

Will report back on results, unless any other ideas come to surface.

Many thanks,

Martin

[CThompsonEXOS]

Hi Marin,

I thought it was this issue but this is resolved in 31.5.

https://extremeportal.force.com/ExtrArticleDetail?an=000099829

Are you using the Clearpass agent or anything else that article mentions?

Thanks,
Chris Thompson