none
WMI reporting wrong time for event viewer tasks

    Question

  • I have a series of batch files I run on our main server every night, starting at 11:59:00 PM, Monday thru Friday. The first batch file is started via Task Scheduler. It copies some files and reboots the server.  Other batch files run when the server reboots, and at various times in the day.

    All these batch files use "EventCreate" to leave their progress and results in the Event Viewer. Then I use a VBS script with a WMI call to find the events and report them in a text file.

    The Event viewer records the time of the event properly, and up until a few days ago (around Daylight Savings Time kicking in) the VBS script reported everything correctly as to time. Now, the VBS script is moving the time of each recorded event up four hours. When I turned the DST switch in the clock off, the time shift from the VBS script was five hours. Now some of the recorded events, such as when I log in remotely, are reported by the VBS script as happening in the future. :( The time shift is happening to both the events made by my scripts and the events made by Microsoft Processes. The Event Viewer's times are good, the VBS script's times are not.

    Here's the script:

    Const ForReading = 1, ForWriting = 2, ForAppending = 8
    Set fso = CreateObject("Scripting.FileSystemObject")
    title="Send Notepad Message"
    outext=".msg"
    outnum=1
    tempext=".msg3"
    sender="VMhost"
    receiver="Scott"
    messagepath="\\server01\NotepadMessage"
    set logfile = fso.opentextfile("eventviewerlog.txt",forwriting,true)
    days2show = 1 'number of days' worth of VM events to show
    logfilestring = ""
    '****************************************
    ' WMI Event Viewer scanner 
    'objEvent.SourceName to capture, separated by spaces
    sourcenames="vmbackup.cmd vmstart.cmd CopyVMsRsync.cmd CopyVMs2AltRun.cmd CopyVMs2USBnet.cmd vmstuckhandle.cmd"
    daycount = 0
    strComputer = "."
    Set objWMIService = GetObject("winmgmts:" _
        & "{impersonationLevel=impersonate}!\\" _
        & strComputer & "\root\cimv2")
    Set colLoggedEvents = objWMIService.ExecQuery _
        ("Select * from Win32_NTLogEvent " _
            & "Where Logfile = 'Application'")
    For Each objEvent in colLoggedEvents
      if instr(sourcenames,objEvent.SourceName)<>0 then
        dt = left(objEvent.TimeWritten,14)
        datetime = mid(dt,5,2)&"-"&mid(dt,7,2)&"-"&left(dt,4)&" "&mid(dt,9,2)&":"&mid(dt,11,2)&":"&right(dt,2)
        logstring = datetime & "  " & objEvent.Type & "  " & objEvent.SourceName & "  " & objEvent.Message & "   (" & objEvent.TimeWritten & ")"
        logfile.writeline logstring
        logfilestring = logfilestring & logstring & vbcrlf
      end if
      if instr(objEvent.SourceName,"vmbackup.cmd")<>0 and instr(objEvent.Message,"starting vmbackup")<>0 then
        daycount = daycount + 1
        if daycount = days2show then exit for
      end if 
    Next 
    logfile.close
    '****************************************
    on error resume next
      set outfile=fso.opentextfile("msg34.txt",forwriting,true)
      outfile.writeline "From "&sender&vbcrlf&vbcrlf&logfilestring
      outfile.Close
      Do
        If Not fso.FileExists(messagepath&"\"&receiver&outext&Trim(CStr(outnum))) Then Exit Do
        outnum = outnum + 1
      Loop
      fso.movefile "msg34.txt",messagepath&"\"&receiver&outext&Trim(CStr(outnum))

    Here's the text file: 

    From VMhost
    03-16-2012 11:42:33  Information  CopyVMs2USBnet.cmd  copying E:\VMbackups\Server2003.vdi   (20120316114233.000000-000)
    03-16-2012 11:42:32  Information  CopyVMs2USBnet.cmd  Copy to external USB drive started   (20120316114232.000000-000)
    03-16-2012 07:53:50  Warning  CopyVMsRsync.cmd  No Rsync connection thru Hamachi available   (20120316075350.000000-000)
    03-16-2012 07:53:11  Information  vmstart.cmd  no external backup drive   (20120316075311.000000-000)
    03-16-2012 07:52:12  Information  vmstart.cmd  starting EmailTester   (20120316075212.000000-000)
    03-16-2012 07:51:09  Information  vmstart.cmd  starting CVserver   (20120316075109.000000-000)
    03-16-2012 07:49:45  Information  vmstart.cmd  starting Antispam   (20120316074945.000000-000)
    03-16-2012 07:47:07  Information  vmstart.cmd  starting Server2003   (20120316074707.000000-000)
    03-16-2012 07:46:07  Information  vmstart.cmd  Autostart VM script 60 second host-stabilize delay   (20120316074607.000000-000)
    03-16-2012 07:43:49  Information  vmbackup.cmd  VMhost reboot initiated   (20120316074349.000000-000)
    03-16-2012 07:43:49  Information  vmbackup.cmd  E:\VMbackups\Server2003data.vdi copied well   (20120316074349.000000-000)
    03-16-2012 05:40:39  Information  vmbackup.cmd  copying I:\Server2003data.vdi   (20120316054039.000000-000)
    03-16-2012 05:40:39  Information  vmbackup.cmd  E:\VMbackups\Server2003.vdi copied well   (20120316054039.000000-000)
    03-16-2012 05:09:32  Information  vmbackup.cmd  copying G:\Server2003.vdi   (20120316050932.000000-000)
    03-16-2012 05:09:32  Information  vmbackup.cmd  Moving older backups   (20120316050932.000000-000)
    03-16-2012 05:09:31  Information  vmbackup.cmd  Server2003 shutdown successful   (20120316050931.000000-000)
    03-16-2012 05:00:48  Information  vmbackup.cmd  Server2003 shutdown initiated   (20120316050048.000000-000)
    03-16-2012 05:00:48  Information  vmbackup.cmd  Antispam shutdown successful   (20120316050048.000000-000)
    03-16-2012 05:00:08  Information  vmbackup.cmd  Antispam shutdown initiated   (20120316050008.000000-000)
    03-16-2012 05:00:08  Information  vmbackup.cmd  CVserver shutdown successful   (20120316050008.000000-000)
    03-16-2012 04:59:40  Information  vmbackup.cmd  CVserver shutdown initiated   (20120316045940.000000-000)
    03-16-2012 04:59:40  Information  vmbackup.cmd  EmailTester shutdown successful   (20120316045940.000000-000)
    03-16-2012 04:59:04  Information  vmbackup.cmd  EmailTester shutdown initiated   (20120316045904.000000-000)
    03-16-2012 04:59:00  Information  vmbackup.cmd  backup drive found   (20120316045900.000000-000)
    03-16-2012 04:59:00  Information  vmbackup.cmd  starting vmbackup   (20120316045900.000000-000)

    The last event listed in the text file is really the first in the series. It really ran, and is reported correctly in Event Viewer, at 3/15/2012 11:59:00 PM. Note the last two events, happening at 3/16, 11:42 AM. I ran the script to make this text file at 3/16 7:50 AM.  According to the script they won't happen until lunch...

    As pointed out above, when I comment out the objevent.sourcename filter and get a full listing, the time is still off.

    I have seen this post:

    http://social.technet.microsoft.com/Forums/en/ITCG/thread/103a0f65-fb96-4c5d-81e8-cd42406e4b39

    But the problem is not just one hour off.

    WMI is retrieving the event time wrong. Any thoughts?


    • Modifié ScottGus1 vendredi 16 mars 2012 12:16 more info
    vendredi 16 mars 2012 12:11

Réponses

  • Windows stores dates in UTC (which used to be called GMT). You need to account for your local time zone bias. This is explained here:

    http://technet.microsoft.com/en-us/library/ee198928.aspx

    http://technet.microsoft.com/en-us/library/ee156576.aspx


    Richard Mueller - MVP Directory Services

    Richard- while the backgrounder is a good explanation, the need to convert in text was eliminated at about W2K SP2 by the inclusion of SWbemDataTime helper object that can convert dates to and from all formats.

    http://msdn.microsoft.com/en-us/library/windows/desktop/aa393687(v=vs.85).aspx

    This object is more convenient and eliminates errors or any need to adjust for time zone or DST.  It is the recommended method.

    There are still many scripts written for W3K pre-SP2 and many written because most admins did not realize that a helper tool was available.  I usually replace the dataetime math to reduce the amount of code and to take advantage of any fixes that might be added into the system,

    Set dtConverter = CreateObject("WbemScripting.SWbemDateTime")

    dtConverter.Value=objEvent.TimeWritten

    localedt = dtConverter.GetVarDate()

    The object has all of the bits needed to do any conversions including a GetFileTIme() method

    The object can also create WMI datetime interval strings needed for scheduled tasks.


    ¯\_(ツ)_/¯


    vendredi 16 mars 2012 15:10

Toutes les réponses

  • Are you on the East coast of the US?  This looks suspiciously like some sort of reversion to GMT, but that would only make sense if you were on the East coast of the US (or other location sharing the same GMT (or UTC if you prefer) offset.

    DAS

    vendredi 16 mars 2012 12:59
  • Windows stores dates in UTC (which used to be called GMT). You need to account for your local time zone bias. This is explained here:

    http://technet.microsoft.com/en-us/library/ee198928.aspx

    http://technet.microsoft.com/en-us/library/ee156576.aspx


    Richard Mueller - MVP Directory Services

    • Proposé comme réponse Bigteddy vendredi 16 mars 2012 13:57
    vendredi 16 mars 2012 13:51
  • Yes, we are on the East coast of US, Eastern Standard time. The first link (ee198928)  "Working with Dates and Times using WMI" shows that the last three digits in the time code (-000 in my text file) are the number of minutes offset from GMT/UTC time. Since mine are 000, it does seem to mean I've reverted to UTC time somehow. Good catch! (The taskbar clock is reading correctly, BTW, and the adjust-time window reports UTC-5:00 Eastern Standard Time, and DST is active.)

    I read on the posted links that thw WMI times should have been reporting UTC times with an offset-from-GMT all along. The times returned have been exactly correct for our Eastern Standard time without any need for correction for the offset-from-GMT. As in:

    If the event occurred at 11:59 PM, the time returned, pulled directly from the .TimeWritten data with Left(), Mid() and Right() as shown above, would be 11:59, no need to translate the time.

    It was working just fine a week or two ago (I don't remember the offset numbers from then, I hadn't been noting the unedited ".TimeWritten" info until trying to troubleshoot this today.) And the server was just set up a couple months ago, so last week was the first DST adjustment for it. The code above was what I'd been using since two months ago, except for adding the unedited .TimeWritten string for troubleshooting.

    I used the script in this page (http://technet.microsoft.com/en-us/library/ee156558.aspx) to get the offset from GMT, it returns -300.

    (Interestingly, I ran my logs-scanning script on another Windows 7 Professional PC - I should have pointed out earlier that the server is running Windows 7 Professional, too - and I get the same results: the text file output shows a UTC offset of 000 and times four hours later.)

    What would cause this time output to change, and Is there a way to get the WMI times to return correctly for our time like they used to?


    • Modifié ScottGus1 vendredi 16 mars 2012 15:04 clock info
    vendredi 16 mars 2012 15:01
  • Windows stores dates in UTC (which used to be called GMT). You need to account for your local time zone bias. This is explained here:

    http://technet.microsoft.com/en-us/library/ee198928.aspx

    http://technet.microsoft.com/en-us/library/ee156576.aspx


    Richard Mueller - MVP Directory Services

    Richard- while the backgrounder is a good explanation, the need to convert in text was eliminated at about W2K SP2 by the inclusion of SWbemDataTime helper object that can convert dates to and from all formats.

    http://msdn.microsoft.com/en-us/library/windows/desktop/aa393687(v=vs.85).aspx

    This object is more convenient and eliminates errors or any need to adjust for time zone or DST.  It is the recommended method.

    There are still many scripts written for W3K pre-SP2 and many written because most admins did not realize that a helper tool was available.  I usually replace the dataetime math to reduce the amount of code and to take advantage of any fixes that might be added into the system,

    Set dtConverter = CreateObject("WbemScripting.SWbemDateTime")

    dtConverter.Value=objEvent.TimeWritten

    localedt = dtConverter.GetVarDate()

    The object has all of the bits needed to do any conversions including a GetFileTIme() method

    The object can also create WMI datetime interval strings needed for scheduled tasks.


    ¯\_(ツ)_/¯


    vendredi 16 mars 2012 15:10
  • I tried including the lines fot the dtConverter in a test version of my VBS script:

    Set dtConverter = CreateObject("SWbemScripting.SWbemDateTime")
    sourcenames="vmstart.cmd"
    daycount = 0
    strComputer = "."
    Set objWMIService = GetObject("winmgmts:" _
        & "{impersonationLevel=impersonate}!\\" _
        & strComputer & "\root\cimv2")
    Set colLoggedEvents = objWMIService.ExecQuery _
        ("Select * from Win32_NTLogEvent " _
            & "Where Logfile = 'Application'")
    For Each objEvent in colLoggedEvents
      if instr(sourcenames,objEvent.SourceName)<>0 then
        dtConverter.Value=objEvent.TimeWritten 
        localedt = dtConverter.GetVarDate()
        dt = left(objEvent.TimeWritten,14)
        datetime = mid(dt,5,2)&"-"&mid(dt,7,2)&"-"&left(dt,4)&" "&mid(dt,9,2)&":"&mid(dt,11,2)&":"&right(dt,2)
        logstring = datetime & "  " & objEvent.Type & "  " & objEvent.SourceName & "  " & objEvent.Message & "   (" & objEvent.TimeWritten & ")"
    msgbox logstring & vbcrlf & localedt
      end if
      if instr(objEvent.SourceName,"vmbackup.cmd")<>0 and instr(objEvent.Message,"starting vmbackup")<>0 then
        daycount = daycount + 1
        if daycount = days2show then exit for
      end if 
    Next 

    I got an error: ActiveX component can't create object: 'SWbemScripting.SWbemDateTime'

    Is this an add-on I need to install?

    vendredi 16 mars 2012 15:21
  • Thanks jv, I was trying to find an example of the conversion code on my machine before I replied, but couldn't.


    Richard Mueller - MVP Directory Services

    vendredi 16 mars 2012 15:23
  • Sorry - I typed too many 'S's.

    Set dtConverter = CreateObject("WbemScripting.SWbemDateTime")

    There is no leading S in the name.

    I fixed the example too.

    That is what I get for testing with PowerShell then converting to VBScript.


    ¯\_(ツ)_/¯


    • Modifié jrv vendredi 16 mars 2012 15:35
    vendredi 16 mars 2012 15:33
  • Ok that worked fine! I plugged it into my scanning script and the times come out fine.

    Only question for now: What would've made the script times work right without the dtConverter up to a week ago?

    vendredi 16 mars 2012 15:51
  • Ok that worked fine! I plugged it into my scanning script and the times come out fine.

    Only question for now: What would've made the script times work right without the dtConverter up to a week ago?

     

    A week ago the TZ info was updated due t o changes in the time zone info.  These changes are compensated for correctly by the helper but may not be if you have hand coded the time info.  That is a big reason to allow Microsoft to do this in the converter.

    Another note for accuracy:

    UTC is call 'Universal Coordinated Time. in English.  In French it translates to "temps universel coordonné”  because Romance languages put the modifiers after noun. To confuse everyone equally the ITU chose UTC and not CUT or TUC.

    UTC is no GMT.  GMT iis Greenwich Mean Time which is similar to EST or PST. It is a very special time zone that exists only in Greenwich England and is where the marker is for the 0 longitude; the prime meridian.

    UTC is GMT+TZ+DST.  GMT never has a TZ. It is always related to the physical location of the earth in orbit.  TZ marks the relative offset from GMT in increments of 15 minutes but specified as a number of minutes offset from GMT.  DST is a locally established offset of one hour and is represented by a flag bit.  URC carries the DST setting as an offset to TZ.  TZ of -300 + DST is -240.  EST is currently -240 (we set DST on Sunday night in the US.

    http://www.nist.gov/pml/div688/utcnist.cfm


    ¯\_(ツ)_/¯

    vendredi 16 mars 2012 16:17
  • Right-O. Thanks for the help, everyone!, And to JRV for that converter info.

    vendredi 16 mars 2012 16:49