This discussion is archived
11 Replies Latest reply: Oct 18, 2012 1:06 PM by Levi-Pereira RSS

Oracle logs have wrong timestamp

Linux-RAC-Admin Newbie
Currently Being Moderated
My DBA is woking on a new install of EM12c on Oracle Grid Infrustructure on a Standalone server using ASM. She is experiencing issues with the Oracle Restart facility. This issue she is working through an Oracle SR.

Linux OS running OL6.2

I am the Linux Admin and while troubleshooting I found that the logs under $ORACLE_HOME/log appear to have incorrect time stamps within them.

For example -
#ls -la /oracle/OracleHomes/11.2/grid/log/bkvlnxgrid02/alertbkvlnxgrid02.log
-rw-rw---- 1 oracle oinstall 19915 Oct 16 09:12 /oracle/OracleHomes/11.2/grid/log/bkvlnxgrid02/alertbkvlnxgrid02.log

This is the correct system time.

But within the log the time is in the future by nine hours -

# tail /oracle/OracleHomes/11.2/grid/log/bkvlnxgrid02/alertbkvlnxgrid02.log
2012-10-16 18:12:19.918
[evmd(8286)]CRS-1401:EVMD started on node bkvlnxgrid02.

The /var/log/messages is correct, the Database system time is correct and /etc/sysconfig/clock timezone entry is correct.

Has anyone else noticed this issue?
  • 1. Re: Oracle logs have wrong timestamp
    Levi-Pereira Guru
    Currently Being Moderated
    My DBA is woking on a new install of EM12c on Oracle Grid Infrustructure on a Standalone server using ASM. She is experiencing issues with the Oracle Restart facility
    For example -
    #ls -la /oracle/OracleHomes/11.2/grid/log/bkvlnxgrid02/alertbkvlnxgrid02.log
    -rw-rw---- 1 oracle oinstall 19915 Oct 16 09:12 /oracle/OracleHomes/11.2/grid/log/bkvlnxgrid02/alertbkvlnxgrid02.log
    
    #### This is the correct system time. 
    
    ### But within the log the time is in the future by nine hours - 
    
    # tail /oracle/OracleHomes/11.2/grid/log/bkvlnxgrid02/alertbkvlnxgrid02.log
    2012-10-16 18:12:19.918
    [evmd(8286)]CRS-1401:EVMD started on node bkvlnxgrid02.
    You posted only a example, right? Because EVMD is a component of Oracle Clusterware only.

    Can you post here output of command below from your env which have the issue:
    $ date
    $ ls -la  <grid_home>/log/<hostname>/alert<hostname>.log
    $ tail -f   <grid_home>/log/<hostname>/alert<hostname>.log
    The GI take date/time/timezone from OS.

    So, What may have happened was:

    The OS date was configured to (e.g 19:00) and at this time the HAS (Oracle Restart) was up.

    Someone may have changed the date from 19:00 to 10:00.

    So, on logs you will see the previous date that was 19:00, if this log was modified by Oracle you will see current date from OS, if you stop and start HAS you will see the OS date/time on your logs.
  • 2. Re: Oracle logs have wrong timestamp
    Linux-RAC-Admin Newbie
    Currently Being Moderated
    Hello Levi,

    Yes, that was just an example.

    The os date would not be changed by anyone but myself. Also, this issue is persistent through every reboot.

    We are currently troubleshooting the Oracle Restart for another issue on this server. Do you think this time issue is related?

    Thanks for your help.
  • 3. Re: Oracle logs have wrong timestamp
    Levi-Pereira Guru
    Currently Being Moderated
    Linux-RAC-Admin wrote:
    Hello Levi,

    Yes, that was just an example.

    The os date would not be changed by anyone but myself. Also, this issue is persistent through every reboot.

    We are currently troubleshooting the Oracle Restart for another issue on this server. Do you think this time issue is related?
    Oracle GI does not have a internal clock or internal timezone he takes the date/time/timezone from Operating System. So, if the date and time is wrong in the logs of Oracle, the operating system date and time is wrong too. This OS is on Virtual Machine? (maybe this date/time come from a Physical Host from Virtual Machine )

    Far as I know, Oracle support different timezone at Database Level only.

    I recommend you do this and post here for further analysis.
    $ date
    $ ls -la  <grid_home>/log/<hostname>/alert<hostname>.log
    $ tail -f   <grid_home>/log/<hostname>/alert<hostname>.log
    
    $ crsctl stop has
    
    $ date
    $ crsctl start has
    
    $ ls -la  <grid_home>/log/<hostname>/alert<hostname>.log
    $ tail -f   <grid_home>/log/<hostname>/alert<hostname>.log
  • 4. Re: Oracle logs have wrong timestamp
    Linux-RAC-Admin Newbie
    Currently Being Moderated
    Just performed a reboot, here is the alertlog

    # date
    Tue Oct 16 15:15:15 EDT 2012

    # ls -la /oracle/OracleHomes/11.2/grid/log/<hostname>/alert<hostname>.log
    -rw-rw---- 1 oracle oinstall 24378 Oct 16 15:09 /oracle/OracleHomes/11.2/grid/log/<hostname>/alert<hostname>.log

    #tail /oracle/OracleHomes/11.2/grid/log/<hostname>/alert<hostname>.log
    2012-10-17 00:05:12.833
    [oracle/OracleHomes/11.2/grid/bin/oraagent.bin(7880)]CRS-5016:Process "/oracle/OracleHomes/11.2/grid/bin/lsnrctl" spawned by agent "/oracle/OracleHomes/11.2/grid/bin/oraagent.bin" for action "check" failed: details at "(:CLSN00010:)" in "/oracle/OracleHomes/11.2/grid/log/bkvlnxgrid02/agent/ohasd/oraagent_oracle/oraagent_oracle.log"
    2012-10-17 00:06:05.057
    [cssd(6957)]CRS-1603:CSSD on node bkvlnxgrid02 shutdown by user.
    2012-10-17 00:06:05.157
    [cssd(6957)]CRS-1660:The CSS daemon shutdown has completed
    2012-10-17 00:09:06.570
    [ohasd(4575)]CRS-2112:The OLR service started on node bkvlnxgrid02.
    2012-10-17 00:09:06.674
    [ohasd(4575)]CRS-1301:Oracle High Availability Service started on node bkvlnxgrid02.
    2012-10-17 00:09:07.856
    [oracle/OracleHomes/11.2/grid/bin/oraagent.bin(5510)]CRS-5016:Process "/oracle/OracleHomes/11.2/grid/bin/lsnrctl" spawned by agent "/oracle/OracleHomes/11.2/grid/bin/oraagent.bin" for action "check" failed: details at "(:CLSN00010:)" in "/oracle/OracleHomes/11.2/grid/log/bkvlnxgrid02/agent/ohasd/oraagent_oracle/oraagent_oracle.log"
    2012-10-17 00:09:37.637
    [oracle/OracleHomes/11.2/grid/bin/oraagent.bin(5510)]CRS-5818:Aborted command 'check' for resource 'ora.ASM_DATA.dg'. Details at (:CRSAGF00113:) {0:0:2} in /oracle/OracleHomes/11.2/grid/log/bkvlnxgrid02/agent/ohasd/oraagent_oracle/oraagent_oracle.log.
    2012-10-17 00:09:37.637
    [oracle/OracleHomes/11.2/grid/bin/oraagent.bin(5510)]CRS-5818:Aborted command 'check' for resource 'ora.ASM_FRA.dg'. Details at (:CRSAGF00113:) {0:0:2} in /oracle/OracleHomes/11.2/grid/log/bkvlnxgrid02/agent/ohasd/oraagent_oracle/oraagent_oracle.log.
    2012-10-17 00:09:42.961
    [cssd(6922)]CRS-1713:CSSD daemon is started in local-only mode
    2012-10-17 00:09:44.796
    [ohasd(4575)]CRS-2767:Resource state recovery not attempted for 'ora.diskmon' as its target state is OFFLINE
    2012-10-17 00:09:51.599
    [cssd(6922)]CRS-1601:CSSD Reconfiguration complete. Active nodes are bkvlnxgrid02 .
    2012-10-17 00:09:52.907

    Strange problem.
  • 5. Re: Oracle logs have wrong timestamp
    Levi-Pereira Guru
    Currently Being Moderated
    I had seen issue like that caused due problem on timezone of OS.

    Try change OS timezone to a different timezone (e.g UTC).

    UTC should have the same setting as it in the BIOS
    # cd /etc
    # mv localtime localtime.bak
    # ln -s /usr/share/zoneinfo/UTC /etc/localtime
    
    #### restart server to make change to take effect.
    
    # date -s "HH:MM:SS" 
    ### to setup time properly
    Check if problem was fixed.

    It's only a test.
  • 6. Re: Oracle logs have wrong timestamp
    Linux-RAC-Admin Newbie
    Currently Being Moderated
    Thank you for all your help.

    I did the following -

    # mv localtime localtime.bak
    #ln -s /usr/share/zoneinfo/UTC /etc/localtime
    # date
    Tue Oct 16 20:10:50 UTC 2012

    # ls -la localtime
    lrwxrwxrwx 1 root root 23 Oct 16 20:10 localtime -> /usr/share/zoneinfo/UTC
    #rm localtime
    rm: remove symbolic link `localtime'? y
    #mv localtime.bak localtime
    #date
    Tue Oct 16 16:12:18 EDT 2012

    I see how it effects the date on the os.
    Did you mean to restart the server to see if the logs pick up the UTC timestamp?
    I cannot restart right now, so I will have to continue tomorrow.
  • 7. Re: Oracle logs have wrong timestamp
    Levi-Pereira Guru
    Currently Being Moderated
    Tomorrow during this test don't revert the settings to EDT before to check if the problem was solved.
  • 8. Re: Oracle logs have wrong timestamp
    Linux-RAC-Admin Newbie
    Currently Being Moderated
    Good Morning,

    I tested with the change of the 'localtime' timezone. Although it did not fix the problem it shows something interesting.

    After setting localtime to UTC and rebooting, the grid logs now are only 5 hours ahead of localtime as compared to nine hours when using EDT. This seems to indicate that the time on the logs is not dependent on the system time. When EDT the logs were +9 hours and now with UTC they are +4 hours.

    Here is the output from my test -

    # cd /etc
    # mv localtime localtime.bak
    # ln -s /usr/share/zoneinfo/UTC localtime
    # date
    Wed Oct 17 13:25:11 UTC 2012
    # reboot

    # date
    Wed Oct 17 13:34:57 UTC 2012

    # tail alert<hostname>.log
    2012-10-17 18:25:46.735
    [oracle/OracleHomes/11.2/grid/bin/oraagent.bin(8515)]CRS-5016:Process "/oracle/OracleHomes/11.2/grid/bin/lsnrctl" spawned by agent "/oracle/OracleHomes/11.2/grid/bin/oraagent.bin" for action "check" failed: details at "(:CLSN00010:)" in "/oracle/OracleHomes/11.2/grid/log/<hostname>/agent/ohasd/oraagent_oracle/oraagent_oracle.log"
    2012-10-17 18:26:41.374
    [cssd(6966)]CRS-1603:CSSD on node <hostname> shutdown by user.
    2012-10-17 18:26:41.474
    [cssd(6966)]CRS-1660:The CSS daemon shutdown has completed
    2012-10-17 18:29:45.613
    [ohasd(4563)]CRS-2112:The OLR service started on node <hostname>.
    2012-10-17 18:29:45.706
    [ohasd(4563)]CRS-1301:Oracle High Availability Service started on node <hostname>.
    2012-10-17 18:29:47.016
    [oracle/OracleHomes/11.2/grid/bin/oraagent.bin(5495)]CRS-5016:Process "/oracle/OracleHomes/11.2/grid/bin/lsnrctl" spawned by agent "/oracle/OracleHomes/11.2/grid/bin/oraagent.bin" for action "check" failed: details at "(:CLSN00010:)" in "/oracle/OracleHomes/11.2/grid/log/<hostname>/agent/ohasd/oraagent_oracle/oraagent_oracle.log"
    2012-10-17 18:30:16.696
    [oracle/OracleHomes/11.2/grid/bin/oraagent.bin(5495)]CRS-5818:Aborted command 'check' for resource 'ora.ASM_DATA.dg'. Details at (:CRSAGF00113:) {0:0:2} in /oracle/OracleHomes/11.2/grid/log/<hostname>/agent/ohasd/oraagent_oracle/oraagent_oracle.log.
    2012-10-17 18:30:16.696
    [oracle/OracleHomes/11.2/grid/bin/oraagent.bin(5495)]CRS-5818:Aborted command 'check' for resource 'ora.ASM_FRA.dg'. Details at (:CRSAGF00113:) {0:0:2} in /oracle/OracleHomes/11.2/grid/log/<hostname>/agent/ohasd/oraagent_oracle/oraagent_oracle.log.
    2012-10-17 18:30:22.048
    [cssd(7783)]CRS-1713:CSSD daemon is started in local-only mode
    2012-10-17 18:30:23.888
    [ohasd(4563)]CRS-2767:Resource state recovery not attempted for 'ora.diskmon' as its target state is OFFLINE
    2012-10-17 18:30:30.633
    [cssd(7783)]CRS-1601:CSSD Reconfiguration complete. Active nodes are <hostname> .
    2012-10-17 18:30:32.003
    [evmd(9346)]CRS-1401:EVMD started on node <hostname>.
    2012-10-17 18:30:51.257
    [ohasd(4563)]CRS-2807:Resource 'ora.repo.db' failed to start automatically.

    I have reverted my localtime back -

    # rm localtime
    rm: remove symbolic link `localtime'? y
    # mv localtime.bak localtime
    # date
    Wed Oct 17 09:37:38 EDT 2012
  • 9. Re: Oracle logs have wrong timestamp
    Levi-Pereira Guru
    Currently Being Moderated
    Hi,

    This issue is about timezone. Oracle is using a different timezone should be set somewhere and need to find where.


    Check if on profile/current variables of oracle and root user for "TZ" Environment Variable.

    Put here output of :
    $ set |grep TZ
    Also you can try reconfigure your date and timezone.
    # system-config-date
    Try set TZ variable on Oracle your Environment Variables, then restart HAS with variable TZ configured:
  • 10. Re: Oracle logs have wrong timestamp
    Linux-RAC-Admin Newbie
    Currently Being Moderated
    Hi Levi,

    I opened an SR and fortunately received good help. The engineer refered me to the document How To Change Timezone for 11gR2 Grid Infrastructure (Doc ID 1209444.1).

    The TZ entry that is used by the Oracle logs is in $GRID_HOME/crs/install/s_crsconfig_<hostname>_env.txt
    I changed it to be (it needed the underscore) -
    TZ=America/New_York

    FYI, this matched the directory structure in /usr/share/zoneinfo/America/New_York and not the entry in /etc/sysconfig/clock.

    I restarted has and the log now matches the system date.

    Thank yo for all your help!
  • 11. Re: Oracle logs have wrong timestamp
    Levi-Pereira Guru
    Currently Being Moderated
    After this reply above, I need to review my concepts about how Oracle Grid Infrastructure handles with Timezone.

    So, Oracle Grid Infrastructure uses its own Timezone. (I did not find this information in the documentation, that is really bad :) )

    Thanks for sharing the solution.

Legend

  • Correct Answers - 10 points
  • Helpful Answers - 5 points