+skitt cc FYI.. "interesting" problem here... curious if you're seeing this on your test server env?

> date/time displayed in karaf.log seems to be using some timezone info 

ODL Karaf appears to log using not "some" but the hosts current local TZ - and I would argue that's "correct".  At least e.g. on my local dev system (laptop), a "timedatectl" confirms I'm on CEST, +0200, and so karaf.log shows timestamp in local TZ, which is what one would want, I think? So, unless proven otherwise, I don't think we're looking at an ODL/Karaf "bug", here.  (Now we probably COULD look into changing ODL's logging to somehow log always in UTC instead of local TZ - if that's we want, but I doubt we do?)

> and it does not match with the time in Neutron/system

Who can we ask to learn whether Neutron logs in the system's local timezone or always in UTC?

> the date/time displayed in karaf.log seems to be using some timezone info 
> and it does not match with the time in Neutron/system.

Yeah. The most likely explanation at this point is "just" that, for some reason, ODL runs another TZ than Neutron. So the goal of this bug will be to find out which side of the side is on what TZ why:

Could I ask you to run a "timedatectl" both on where Neutron runs/logs, and where the Karaf ODL runs? When running timedatectl, make sure that you are the Linux UID user that the respective process runs - because: There is a System Timezone (ls -l /etc/localtime) and an, optional, user time zone (echo $TZ), and then the JVM has it's own -Duser.timezone, and then there is Karaf's etc/system.properties to override karaf.override.user.timezone=aTZ (see KARAF-3208) ... one of them must have been set to something else for ODL than for Neutron.

BTW: Beware of funky stuff like https://unix.stackexchange.com/a/117887/103272 - you haven't done anything like that, have you, to forward your local TZ into SSH sesssions of the QA env server, have you?! ;) I'm sure you haven't...

This is probably less of a real "ODL" as in Karaf/OSGi/Log4j/Java type issue, and more of a "system" problem.  I would welcome help from others more familiar with such things to figure out what's going on here.

PS: With bug 1475951 this problem will disappear, because it won't log the timestamp into journal as String anymore.

PPS: https://stackoverflow.com/questions/14480008/pax-logging-specifying-which-timezone-to-use-for-logs may be useful, later.

PPPS: This http://karaf.922171.n3.nabble.com/Karaf-doesn-t-use-proper-Time-Zone-td4047314.html claims a Karaf bug, but is too vague (and not confirmed by a quick test in my own local Karaf; as above, is does seem to respect TZ).

For this kind of reason, I always set servers up to use UTC as their local timezone ;-).

> I always set servers up to use UTC as their local timezone ;-)

The "interesting" part here is that Sridhar (claims) that "Date output: (..) UTC"

Could you please do a "dev:dump-create" in the (opendaylight-user@root> CLI) and attach the environment.txt you'll find contain in the resulting *.zip here?  

That will let us see the the "Dump timestamp" and actual system:property user.timezone (plus, possibly, karaf.override.user.timezone) of the JVM...

Also, looking more closely at the actual TS above, NB that ODL's 14:19:22 for UTC 18:20:02 is basically EDT (not EST) - which is... Raleigh time! Does that happen to be where this environment is? ;) Seems to confirm that this isn't some sort of "arbitrary TZ skew", but ODL logging in "local" TZ, somehow.

Jamo has noted that on upstream CSIT at LF there's a similar "skew" - but 2h there.

(In reply to Michael Vorburger from comment #3)
> > I always set servers up to use UTC as their local timezone ;-)
> 
> The "interesting" part here is that Sridhar (claims) that "Date output: (..)
> UTC"

Yes Michael, the date output I shared was UTC.

Created attachment 1323781 [details]
ODL environment file

environment.txt from dev:dump-create command on Controller-0

(In reply to Michael Vorburger from comment #4)
> Could you please do a "dev:dump-create" in the (opendaylight-user@root> CLI)
> and attach the environment.txt you'll find contain in the resulting *.zip
> here?  
> 
PFA the environment.txt file.

> That will let us see the the "Dump timestamp" and actual system:property
> user.timezone (plus, possibly, karaf.override.user.timezone) of the JVM...
> 
> Also, looking more closely at the actual TS above, NB that ODL's 14:19:22
> for UTC 18:20:02 is basically EDT (not EST) - which is... Raleigh time! Does
> that happen to be where this environment is? ;) Seems to confirm that this
> isn't some sort of "arbitrary TZ skew", but ODL logging in "local" TZ,
> somehow.
> 
You are right, the environment.txt indeed has EDT. 

Dump timestamp  : Friday, September 8, 2017 11:54:28 AM EDT 
<SNIP>

Instance name   : 18095@overcloud-controller-0.localdomain
Start time      : Friday, September 8, 2017 6:38:15 AM EDT 
Uptime  : 5 hours 16 minutes

Also, I just checked with @Sai regarding the location of Servers, he confirmed that they are in Raleigh!!

> Jamo has noted that on upstream CSIT at LF there's a similar "skew" - but 2h
> there.

@Michael, another interesting observation that I noticed was that after leaving the setup for sometime, the timestamp in ODL Karaf logs was matching the system date/time. I dont know the exact time after which it started using UTC.

The current setup is a fresh deployment, so after running it for sometime, when we start seeing that it matches with system-time/UTC, I'll capture the "dev:dump-create" output again and will update you.

> You are right, the environment.txt indeed has EDT.

and specifically it has these two interesting entries:

    user.name	  : odl
    user.timezone : America/New_York

so basically resolving this issue "just" boils down to figuring out why the ODL uid (as in the system Linux OS level user "odl") has its TZ set to EDT, despite (according to the "date" output you provided above) the host being set to UTC. Could you try to like a "su - odl" and then "timedatectl" kind of thing?

(In reply to Michael Vorburger from comment #9)
> > You are right, the environment.txt indeed has EDT.
> 
> and specifically it has these two interesting entries:
> 
>     user.name	  : odl
>     user.timezone : America/New_York
> 
> so basically resolving this issue "just" boils down to figuring out why the
> ODL uid (as in the system Linux OS level user "odl") has its TZ set to EDT,
> despite (according to the "date" output you provided above) the host being
> set to UTC. Could you try to like a "su - odl" and then "timedatectl" kind
> of thing?

[root@overcloud-controller-0 neutron]# tail -f /opt/opendaylight/data/log/karaf.log 
2017-09-11 10:13:51,398 | INFO  | Pool-1-worker-10 | LockManager                      | 345 - org.opendaylight.genius.lockmanager-impl - 0.2.2.SNAPSHOT | Waiting for the lock interfacestun182279e7201 is timed out. retrying again
2017-09-11 10:13:51,398 | INFO  | Pool-1-worker-11 | LockManager                      | 345 - org.opendaylight.genius.lockmanager-impl - 0.2.2.SNAPSHOT | Waiting for the lock interfacestun7fdd97de5e0 is timed out. retrying again
2017-09-11 10:13:52,393 | INFO  | Pool-1-worker-60 | LockManager                      | 345 - org.opendaylight.genius.lockmanager-impl - 0.2.2.SNAPSHOT | Waiting for the lock interfacestuneeb6fae6b72 is timed out. retrying again


[root@overcloud-controller-0 neutron]# su - odl
Last login: Mon Sep 11 14:12:48 UTC 2017 on pts/1
-bash-4.2$ timedatectl 
      Local time: Mon 2017-09-11 14:14:21 UTC
  Universal time: Mon 2017-09-11 14:14:21 UTC
        RTC time: Mon 2017-09-11 14:14:21
       Time zone: UTC (UTC, +0000)
     NTP enabled: no
NTP synchronized: yes
 RTC in local TZ: no
      DST active: n/a
-bash-4.2$ date
Mon Sep 11 14:14:22 UTC 2017
-bash-4.2$ whoami
odl
-bash-4.2$ 
-bash-4.2$ exit
logout
[root@overcloud-controller-0 neutron]# whoami
root
[root@overcloud-controller-0 neutron]# timedatectl 
      Local time: Mon 2017-09-11 14:15:29 UTC
  Universal time: Mon 2017-09-11 14:15:29 UTC
        RTC time: Mon 2017-09-11 14:15:29
       Time zone: UTC (UTC, +0000)
     NTP enabled: no
NTP synchronized: yes
 RTC in local TZ: no
      DST active: n/a
[root@overcloud-controller-0 neutron]#

Created attachment 1324522 [details]
DebugBug1488097 debug utility class

> @Michael, another interesting observation that I noticed was that after leaving the setup for sometime, the timestamp in ODL Karaf logs was matching the system date/time. I dont know the exact time after which it started using UTC.

Huh, are you sure? That's even more strange... ;-) I'll just ignore this for the time being.  But if you see this again, if you could do another "dev:dump-create", it would be fascinating to see if something (?) suddenly changed  e.g. user.timezone while it was running?!?

> resolving this issue "just" boils down to figuring out why the ODL uid has its TZ set to EDT

No, because the new output above seems to indicate that ODL uid does have UTC TZ.  I'm now starting to think that perhaps this is some funky problem / mismatch in the way that the JVM determines its TZ... Researching further into this kind of direction hits some "interesting" (scary?) things such as e.g. these:

* http://bugs.java.com/view_bug.do?bug_id=6456628
* https://stackoverflow.com/questions/7066075/jvm-and-timezones
* http://grokbase.com/t/tomcat/users/051m0s38p2/how-to-change-the-timezone-for-tomcat#20050120zlgufj6cgdsma7i2olrgcpwia4
* https://distracted-it.blogspot.ch/2014/09/dont-let-java-on-linux-determine-its.html

To simplify further analysis of this weird issue, I would like to suggest that we forget about ODL & Karaf and take that out of the picture, just for a moment.  For this I've written the attached DebugBug1488097 class.  Could I ask that you DL it, and then on the RHEL server where you're seeing this (remember we're not able to reproduce this on our Fedora 24+ laptops), su'd as the "odl" UID who has timedatectl/date as UTC you're showing above, do: "javac DebugBug1488097.java; java DebugBug1488097" and provide its output here?

(In reply to Michael Vorburger from comment #12)
> > @Michael, another interesting observation that I noticed was that after leaving the setup for sometime, the timestamp in ODL Karaf logs was matching the system date/time. I dont know the exact time after which it started using UTC.
> 
> Huh, are you sure? That's even more strange... ;-) I'll just ignore this for
> the time being.  But if you see this again, if you could do another
> "dev:dump-create", it would be fascinating to see if something (?) suddenly
> changed  e.g. user.timezone while it was running?!?
> 
Yes Michael, I did notice this twice so far. I'll keep a watch on it and will update the BZ if I notice it again.

> > resolving this issue "just" boils down to figuring out why the ODL uid has its TZ set to EDT
> 
> No, because the new output above seems to indicate that ODL uid does have
> UTC TZ.  I'm now starting to think that perhaps this is some funky problem /
> mismatch in the way that the JVM determines its TZ... Researching further
> into this kind of direction hits some "interesting" (scary?) things such as
> e.g. these:
> 
> * http://bugs.java.com/view_bug.do?bug_id=6456628
> * https://stackoverflow.com/questions/7066075/jvm-and-timezones
> *
> http://grokbase.com/t/tomcat/users/051m0s38p2/how-to-change-the-timezone-for-
> tomcat#20050120zlgufj6cgdsma7i2olrgcpwia4
> *
> https://distracted-it.blogspot.ch/2014/09/dont-let-java-on-linux-determine-
> its.html
> 
> To simplify further analysis of this weird issue, I would like to suggest
> that we forget about ODL & Karaf and take that out of the picture, just for
> a moment.  For this I've written the attached DebugBug1488097 class.  Could
> I ask that you DL it, and then on the RHEL server where you're seeing this
> (remember we're not able to reproduce this on our Fedora 24+ laptops), su'd
> as the "odl" UID who has timedatectl/date as UTC you're showing above, do:
> "javac DebugBug1488097.java; java DebugBug1488097" and provide its output
> here?

Sure, PSB the output.
-bash-4.2$ javac DebugBug1488097.java; java DebugBug1488097
new Date()                          : Mon Sep 11 17:55:45 UTC 2017
TimeZone.getDefault()               : sun.util.calendar.ZoneInfo[id="UTC",offset=0,dstSavings=0,useDaylight=false,transitions=0,lastRule=null]
System.getProperty("user.timezone") : UTC
System.getenv("TZ")                 : null


/etc/localtime exists
/etc/localtime -> /usr/share/zoneinfo/UTC

/etc/sysconfig/clock does not exist

-bash-4.2$ whoami
odl
-bash-4.2$ timedatectl
      Local time: Mon 2017-09-11 17:55:54 UTC
  Universal time: Mon 2017-09-11 17:55:54 UTC
        RTC time: Mon 2017-09-11 17:55:54
       Time zone: UTC (UTC, +0000)
     NTP enabled: no
NTP synchronized: yes
 RTC in local TZ: no
      DST active: n/a
-bash-4.2$ 
-bash-4.2$ exit
logout


[root@overcloud-controller-0 heat-admin]# whoami
root
[root@overcloud-controller-0 heat-admin]# timedatectl
      Local time: Mon 2017-09-11 17:56:07 UTC
  Universal time: Mon 2017-09-11 17:56:07 UTC
        RTC time: Mon 2017-09-11 17:56:07
       Time zone: UTC (UTC, +0000)
     NTP enabled: no
NTP synchronized: yes
 RTC in local TZ: no
      DST active: n/a
[root@overcloud-controller-0 heat-admin]# tail -f /opt/opendaylight/data/log/karaf.log 
2017-09-11 13:56:18,429 | INFO  | Pool-1-worker-53 | LockManager                      | 345 - org.opendaylight.genius.lockmanager-impl - 0.2.2.SNAPSHOT | Waiting for the lock interfacestun4db2c3a7504 is timed out. retrying again
2017-09-11 13:56:18,429 | INFO  | Pool-1-worker-10 | LockManager                      | 345 - org.opendaylight.genius.lockmanager-impl - 0.2.2.SNAPSHOT | Waiting for the lock interfacestun182279e7201 is timed out. retrying again

The test above shows that a normal test JVM class has the expected TZ (UTC).  Therefore, it does seem to be something from the configuration of or code running in ODL Karaf, after all.

Note that the environment.txt clearly shows that there is no -D for user.timezone passed to Karaf, but that the property is set to EDT when you do "dev:dump-create".

Your observation that "after leaving the setup for sometime, the timestamp in ODL Karaf logs was matching the system date/time" would make one think that perhaps at runtime some (bad! ugly!) piece of code somewhere may do a System.setProperty("user.timezone", ...) kind of thing ... only problem is that a grep over ODL's source code I've just done doesn't hit anything obvious doing anything like that! :(  

But such a problem could be in any JAR of course (non-ODL src) - only, how would one find that?!  AspectJ with Java Agent?  Custom SecurityManager?

Before even thinking further about anything like that (complicated), could I ask for another simple test, whenever you can (don't stress): If the idea that some (very) "bad" 3rd party code somewhere screws this up at some point is correct, then on a complete fresh new ODL just started, the first few lines of log, BEFORE any of our code runs, before ODL features are installed, should still have the correct TS .. can you have a look at / attach the "early startup" beginning of Karaf log, BEFORE you run any tests? Do you see a sudden "bump" in the hours of the TS in the log, at some point during start up?

PS: If above is inclusive, it could may be "too late" already (?); perhaps too much ODL related code already ran even if you didn't "do anything" yet - maybe an attempt with a fresh Apache.org Karaf (same version as the one used by ODL, so 3.0.8 for carbon; 4.x for later) and see if that has the same problem would be a useful step after above... is that something that could be tried out on this environment?

(In reply to Michael Vorburger from comment #14)
> The test above shows that a normal test JVM class has the expected TZ (UTC).
> Therefore, it does seem to be something from the configuration of or code
> running in ODL Karaf, after all.
> 
> Note that the environment.txt clearly shows that there is no -D for
> user.timezone passed to Karaf, but that the property is set to EDT when you
> do "dev:dump-create".

Ok.

> 
> Your observation that "after leaving the setup for sometime, the timestamp
> in ODL Karaf logs was matching the system date/time" would make one think
> that perhaps at runtime some (bad! ugly!) piece of code somewhere may do a
> System.setProperty("user.timezone", ...) kind of thing ... only problem is
> that a grep over ODL's source code I've just done doesn't hit anything
> obvious doing anything like that! :(  

I had a look at two deployments (one that was left over the weekend and was run for close to 70 hours and the other that was deployed yesterday and was run for 4 hours) but I'm seeing that the time is still inconsistent (i.e., ODL uses EDT 
 and not UTC). One difference though is that its a new rpm. 
 
> 
> But such a problem could be in any JAR of course (non-ODL src) - only, how
> would one find that?!  AspectJ with Java Agent?  Custom SecurityManager?
> 
> Before even thinking further about anything like that (complicated), could I
> ask for another simple test, whenever you can (don't stress): If the idea
> that some (very) "bad" 3rd party code somewhere screws this up at some point
> is correct, then on a complete fresh new ODL just started, the first few
> lines of log, BEFORE any of our code runs, before ODL features are
> installed, should still have the correct TS .. can you have a look at /
> attach the "early startup" beginning of Karaf log, BEFORE you run any tests?
> Do you see a sudden "bump" in the hours of the TS in the log, at some point
> during start up?
> 

Sure, I'll capture the logs and update you.

> PS: If above is inclusive, it could may be "too late" already (?); perhaps
> too much ODL related code already ran even if you didn't "do anything" yet -
> maybe an attempt with a fresh Apache.org Karaf (same version as the one used
> by ODL, so 3.0.8 for carbon; 4.x for later) and see if that has the same
> problem would be a useful step after above... is that something that could
> be tried out on this environment?

I would probably need your help for this. I'll sync up with you regarding this.

Please reopen if this is still happening and attach the requested logs.