Cisco ASR1001-X - "show logging" timestamps

[kasunrajapakse]

Hi Team, 

Any reason why the show logging timestamps are not on the order? 
The timings of the logs are not in order. These logs were captured at 16:21, but why do 15:21 appear on the logs? 

Sep 30 16:21:33.967 BST: %LINEPROTO-5-UPDOWN: Line protocol on Interface Tunnel7, changed state to up
Sep 30 15:21:33.967: ipnat_backup_primary idb Tunnel7 state 4
Sep 30 15:21:33.968: NAT: Process interface UP event for Tunnel7
Sep 30 16:21:56.817 BST: %LINEPROTO-5-UPDOWN: Line protocol on Interface Tunnel7, changed state to down
Sep 30 15:21:56.817: ipnat_backup_primary idb Tunnel7 state 4
Sep 30 16:22:03.779 BST: %SYS-6-LOGOUT: User kasunrajapakse has exited tty session 5(10.113.3.9)
Sep 30 16:22:34.390 BST: %LINEPROTO-5-UPDOWN: Line protocol on Interface Tunnel7, changed state to up
Sep 30 15:22:34.390: ipnat_backup_primary idb Tunnel7 state 4
Sep 30 15:22:34.391: NAT: Process interface UP event for Tunnel7
Sep 30 16:22:57.240 BST: %LINEPROTO-5-UPDOWN: Line protocol on Interface Tunnel7, changed state to down
Sep 30 15:22:57.240: ipnat_backup_primary idb Tunnel7 state 4
Sep 30 16:23:34.815 BST: %LINEPROTO-5-UPDOWN: Line protocol on Interface Tunnel7, changed state to up
Sep 30 15:23:34.815: ipnat_backup_primary idb Tunnel7 state 4
Sep 30 15:23:34.817: NAT: Process interface UP event for Tunnel7
Sep 30 16:23:57.654 BST: %LINEPROTO-5-UPDOWN: Line protocol on Interface Tunnel7, changed state to down
Sep 30 15:23:57.655: ipnat_backup_primary idb Tunnel7 state 4
Sep 30 16:24:35.240 BST: %LINEPROTO-5-UPDOWN: Line protocol on Interface Tunnel7, changed state to up
Sep 30 15:24:35.240: ipnat_backup_primary idb Tunnel7 state 4

Sep 30 15:24:35.241: NAT: Process interface UP event for Tunnel7
Sep 30 16:24:58.094 BST: %LINEPROTO-5-UPDOWN: Line protocol on Interface Tunnel7, changed state to down
Sep 30 15:24:58.094: ipnat_backup_primary idb Tunnel7 state 4
Sep 30 16:25:35.675 BST: %LINEPROTO-5-UPDOWN: Line protocol on Interface Tunnel7, changed state to up
Sep 30 15:25:35.675: ipnat_backup_primary idb Tunnel7 state 4
Sep 30 15:25:35.676: NAT: Process interface UP event for Tunnel7
Sep 30 16:25:58.534 BST: %LINEPROTO-5-UPDOWN: Line protocol on Interface Tunnel7, changed state to down
Sep 30 15:25:58.534: ipnat_backup_primary idb Tunnel7 state 4
Sep 30 16:26:36.097 BST: %LINEPROTO-5-UPDOWN: Line protocol on Interface Tunnel7, changed state to up
Sep 30 15:26:36.097: ipnat_backup_primary idb Tunnel7 state 4
Sep 30 15:26:36.098: NAT: Process interface UP event for Tunnel7

ASR1001-X#show clock
16:28:17.844 BST Thu Sep 30 2021
ASR1001-X#

ASR1001-X#show run | inc ntp
ntp authentication-key 5 md5 ********** 7
ntp authenticate
ntp trusted-key 5
ntp source GigabitEthernet0
ntp server vrf Mgmt-intf 1.1.3.2 prefer
ntp server vrf Mgmt-intf 1.1.7.2
ntp server 1.1.3.2 prefer source GigabitEthernet0
ntp server 1.1.7.2 source GigabitEthernet0
ASR1001-X#

[Georg Pauwen]

Hello,

it looks like some entries are off by one hour ? Could be related to configure timezone. Try and configure:

service timestamps log datetime localtime

This should keep the timestamps in sync with whatever time your device is on locally...

[Pierce Vasale · Accepted solution]

It appears to be two different logging events. One is set for timezone, and the other is not.

First is "service timestamps log datetime localtime msec show-timezone year" turns on just about everything and it looks like you have everything but "year" in your lines.

Then there is "service timestamps debug datetime localtime msec show-timezone year" which I think may be your other entries that are off by an hour and not showing time-zone.

[balaji.bandi]

Sure Agreed with @Georg Pauwen 

service timestamps log datetime localtime  - this should fix your issue

[paul driver]

Hello
Do you have any daylight saving time applied?

If you not then its possible either your ntp peer or your rtr  isnt configured to adjust to DST changes.

example DST for UK
clock summer-time BST recurring last MAR 2:00 last OCT 2:00 offset 60 

(offset = time to adjust to - default to 60mins

[Richard Burts]

I believe that @Pierce Vasale has correctly identified the issue (and +5 for that). These messages suggest that this device is running debug for nat

Sep 30 15:23:34.815: ipnat_backup_primary idb Tunnel7 state 4
Sep 30 15:23:34.817: NAT: Process interface UP event for Tunnel7

and using the service timestamps debug should resolve the issue.