Wireless Access

System time on my controller seems totally synced to global time, and when I look at that time in various places like Show Version and in WebUI Infrastructure it shows an accurate time.

However when I do a 'show auth-tracebuf' command, it seems like all the entries are timestamps with a time that is 1 minute previous to the system time at which they occurred.

Can someone confirm this seems like a bug and not a user confusion issue?  Currently on version 8.5.0.0.

(Controller333) *[mynode] #show auth-tracebuf

Auth Trace Buffer
-----------------


Jul 22 13:40:10  wpa2-key4             ->  ^^:^^:^^:28:0b:25  f4:2e:7f:^^:^^:^^        -    95
Jul 22 13:40:10  station-up             *  ^^:^^:^^:28:02:3f  f4:2e:7f:^^:^^:^^        -    -    wpa2 psk aes
Jul 22 13:40:10  wpa2-key1             <-  ^^:^^:^^:28:02:3f  f4:2e:7f:^^:^^:^^        -    117
Jul 22 13:40:10  wpa2-key2             ->  ^^:^^:^^:28:02:3f  f4:2e:7f:^^:^^:^^        -    117
Jul 22 13:40:10  wpa2-key3             <-  ^^:^^:^^:28:02:3f  f4:2e:7f:^^:^^:^^        -    151
Jul 22 13:40:10  wpa2-key4             ->  ^^:^^:^^:28:02:3f  f4:2e:7f:^^:^^:^^        -    95
Jul 22 13:40:11  station-down           *  ^^:^^:^^:28:09:6f  f4:2e:7f:^^:^^:^^        -    -
Jul 22 13:40:11  station-up             *  ^^:^^:^^:28:0a:fc  f4:2e:7f:^^:^^:^^        -    -    wpa2 psk aes
Jul 22 13:40:11  wpa2-key1             <-  ^^:^^:^^:28:0a:fc  f4:2e:7f:^^:^^:^^        -    117
Jul 22 13:40:11  wpa2-key2             ->  ^^:^^:^^:28:0a:fc  f4:2e:7f:^^:^^:^^        -    117
Jul 22 13:40:11  wpa2-key3             <-  ^^:^^:^^:28:0a:fc  f4:2e:7f:^^:^^:^^        -    151
Jul 22 13:40:11  wpa2-key4             ->  ^^:^^:^^:28:0a:fc  f4:2e:7f:^^:^^:^^        -    95
Jul 22 13:40:13  station-down           *  ^^:^^:^^:28:0a:37  f4:2e:7f:^^:^^:^^        -    -
(Controller333) *[mynode] #  show clock

Mon Jul 22 13:41:23 CST 2019


(Controller333) *[mynode] #show ntp status

Authentication:         disabled
time since restart:     117467
time since reset:       117467
packets received:       184
packets processed:      180
current version:        180
previous version:       0
declined:               0
access denied:          0
bad length or format:   0
bad authentication:     0
rate exceeded:          0
system peer:          ns1.baxterit.net
system peer mode:     client
leap indicator:       00
stratum:              3
precision:            -18
root distance:        0.05148 s
root dispersion:      0.03819 s
reference ID:         [54.39.13.155]
reference time:       e0e08c0c.fe2ee997  Mon, Jul 22 2019 13:25:00.992
system flags:         auth monitor ntp kernel stats
jitter:               0.000000 s
stability:            0.062 ppm
broadcastdelay:       -0.049988 s
authdelay:            0.000000 s

(Controller333) *[mynode] #show ntp servers

NTP Server Table Entries
------------------------

Flags:     * Selected for synchronization
           + Included in the final selection set
           # Selected for synchronization but distance exceeds maximum
           - Discarded by the clustering algorithmn
           = mode is client

  remote                                  local                                    st   poll   reach    delay     offset      disp

=========================================================================================================================================

*ns1.baxterit.net                         10.x.y.z                                 2 1024     377    0.05080    -0.000368    0.13814

Upstream NTP Server(s) are reachable.
Time synchronization is with configured upstream NTP server.
(Controller333) *[mynode] #show ver
version                 Show System version

(Controller333) *[mynode] #show version

Aruba Operating System Software.
ArubaOS (MODEL: Aruba7024), Version 8.5.0.0
Website: http://www.arubanetworks.com
(c) Copyright 2019 Hewlett Packard Enterprise Development LP.
Compiled on 2019-04-26 at 22:27:39 UTC (build 70258) by p4build

ROM: System Bootstrap, Version CPBoot 1.0.0.0 (build 48228)
Built: 2015-01-22 04:55:27
Built by: p4build@re_client_48228


Switch uptime is 9 days 2 hours 48 minutes 56 seconds
Reboot Cause: User reboot (Intent:cause:register 78:86:0:2d)
Supervisor Card
Processor (XLP208 Rev B0 (Secure Boot) , 800 MHz) with 3797M bytes of memory.
32K bytes of non-volatile configuration memory.
3872M bytes of Supervisor Card system flash.
(Controller333) *[mynode] #

I did an experiment. I Forgot the wireless network on my phone. I re-entered the wireless network on my phone's config screen, with username trytryit (a username that had never been used before against this controller). On the controller CLI I typed in 'show clock', and I pressed enter on CLI and Accept on phone's wireless network config screen at the same time (within 1 second of each other).

As you can see from CLI output of the show clock and show auth-tracebuf, events that happened at the same time in the controller are logged with two different times. The show auth-tracebuf timestamps are incorrect, even against the controller's own internal time. "16:29:22" on 'show clock' is the same actual time as "16:28:23" on show auth-tracebuf.

(Controller333) *[mynode] #show clock

Mon Jul 22 16:29:22 CST 2019
(Controller333) *[mynode] #  show auth-tracebuf  | include  ^^:^^:^^:7b:36:6d
Jul 22 16:28:23  station-up             *  ^^:^^:^^:7b:36:6d  f4:2e:7f:^^:^^:^^        -    -    wpa2 aes
Jul 22 16:28:23  eap-id-req            <-  ^^:^^:^^:7b:36:6d  f4:2e:7f:^^:^^:^^        1    5
Jul 22 16:28:23  eap-id-resp           ->  ^^:^^:^^:7b:36:6d  f4:2e:7f:^^:^^:^^        1    13   trytryit
Jul 22 16:28:23  rad-req               ->  ^^:^^:^^:7b:36:6d  f4:2e:7f:^^:^^:^^        112  202  10.6.20.2
Jul 22 16:28:23  rad-reject            <-  ^^:^^:^^:7b:36:6d  f4:2e:7f:^^:^^:^^/NPS-1  112  44
Jul 22 16:28:23  eap-failure           <-  ^^:^^:^^:7b:36:6d  f4:2e:7f:^^:^^:^^        1    4    server rejected
Jul 22 16:28:23  station-down           *  ^^:^^:^^:7b:36:6d  f4:2e:7f:^^:^^:^^        -    -
Jul 22 16:28:24  station-up             *  ^^:^^:^^:7b:36:6d  f4:2e:7f:^^:^^:^^        -    -    wpa2 aes
Jul 22 16:28:24  eap-id-req            <-  ^^:^^:^^:7b:36:6d  f4:2e:7f:^^:^^:^^        1    5
Jul 22 16:28:24  eap-id-resp           ->  ^^:^^:^^:7b:36:6d  f4:2e:7f:^^:^^:^^        1    13   trytryit
Jul 22 16:28:24  rad-req               ->  ^^:^^:^^:7b:36:6d  f4:2e:7f:^^:^^:^^        113  202  10.6.20.2
Jul 22 16:28:24  station-down           *  ^^:^^:^^:7b:36:6d  f4:2e:7f:^^:^^:^^        -    -
Jul 22 16:28:24  rad-reject            <-  ^^:^^:^^:7b:36:6d  f4:2e:7f:^^:^^:^^/NPS-1  113  44
Jul 22 16:28:24  eap-failure           <-  ^^:^^:^^:7b:36:6d  f4:2e:7f:^^:^^:^^        1    4    server rejected
(Controller333) *[mynode] #

Please open a TAC case.  I don’t see that on my setup here.

Last night we upgraded to 8.5.0.1, and now when I do the same test the timestamp matches. So issue no longer present, and for that reason I won't open a case.