Opened 2 years ago

Closed 2 years ago

#14148 closed defect (fixed)

wxDateTime::UNow().Format() incorrect timezone?

Reported by: vm.dozor Owned by:
Priority: normal Milestone:
Component: base Version: 2.9.3
Keywords: Cc: vm.dozor@…, mutuka+wxwidgets@…
Blocked By: Blocking:
Patch: no

Description

I have problem with wxLog timestamp.
This code:

    logger->LogText(wxString::Format("Now is %s", wxDateTime::Now().Format("%Y-%m-%d %H:%M:%S %Z")));
    logger->LogText(wxString::Format("UNow is %s", wxDateTime::UNow().Format("%Y-%m-%d %H:%M:%S %Z")));

    wxString TestTime("TestTime:\n");
    TestTime << "wxUSE_LONGLONG = " << wxUSE_LONGLONG << '\n';
    TestTime << "wxGetLocalTimeMillis() = " << wxGetLocalTimeMillis() << '\n';
    TestTime << "wxGetTimeZone " << wxGetTimeZone() << '\n';
    TestTime << "wxGetUTCTimeMillis() = " << wxGetUTCTimeMillis() << '\n';

#if defined(__WXMSW__)
    TestTime << "defined __WXMSW__" << '\n';
#elif defined(HAVE_GETTIMEOFDAY)
    TestTime << "defined HAVE_GETTIMEOFDAY" << '\n';
#elif defined(HAVE_FTIME)
    TestTime << "defined HAVE_FTIME" << '\n';
#else // no gettimeofday() nor ftime()
    TestTime << "no gettimeofday() nor ftime()" << '\n';
#endif // time functions

    logger->LogText(TestTime);

gives the result:

  1. Linux 3.0.0-17-generic x86_64
<== *
* ==>

2012-03-29 03:09:04 VLAT: Program Dispatcher started. PID 2812.
Now is 2012-03-28 16:09:04 VLAT
UNow is 2012-03-29 03:09:04 VLAT
TestTime:
wxUSE_LONGLONG = 1
wxGetLocalTimeMillis() = 1332950944833
wxGetTimeZone -39600
wxGetUTCTimeMillis() = 1332911344833
defined HAVE_GETTIMEOFDAY
2012-03-29 03:09:25 VLAT: Program Dispatcher finished

</== *
* ==>
  1. WindowsXP SP 3

...
Now is 2012-03-28 16:06:47 Владивосток (зима)
UNow is 2012-03-29 03:06:47 Владивосток (зима)
...
defined WXMSW
...

Change History (11)

comment:1 Changed 2 years ago by vm.dozor

  • Cc vm.dozor@… added
  • Summary changed from wxDatatime::UNow().Format() incorrect timezone? to wxDateTime::UNow().Format() incorrect timezone?
  • Version set to 2.9.3

comment:2 Changed 2 years ago by vadz

  • Status changed from new to infoneeded_new

UNow() returns UTC time so it's normal that it's different from Now() which returns local time. And as wxDateTime objects don't store time zone (it's rather something that you can apply to them), it's also normal that you get the same time zone for both when you format them in Local time zone which is the default value of Format() tz argument.

OTOH I'm not sure why is the difference 13 hours and not 11 which should apparently be the case for VLAT time zone. Is this the bug that you're reporting? If not, I'm not sure what is it...

comment:3 Changed 2 years ago by vadz

P.S. I've documented UNow() returning UTC time in r71033.

comment:4 Changed 2 years ago by vm.dozor

  • Status changed from infoneeded_new to new

Sorry for the muddled issue.

I have problem with wxLog timestamp.

This code:

wxLog* logger = new wxLogStream(&m_LogStream);
wxLog::SetActiveTarget(logger);
logger->SetTimestamp("%Y-%m-%d %H:%M:%S %Z");
wxLogMessage(_("Program %s started. PID %ld."),
                 GetAppName(), wxGetProcessId());

gives the result:

2012-03-29 !03:09:04 VLAT: Program Dispatcher started. PID 2812.

BUT CORRECT TIME IS:  2012-03-28 !16:09:04 VLAT

comment:5 Changed 2 years ago by vadz

  • Status changed from new to infoneeded_new

Sorry, I have trouble reproducing this. I tested with this simple program

#include <wx/init.h>
#include <wx/log.h>

int main(int argc, char **argv)
{
    wxInitializer init;
    if ( !init.IsOk() ) {
        puts("Failed to initialize wxWidgets.");
        return 1;
    }

    wxLog::SetTimestamp("%Y-%m-%d %H:%M:%S %Z");
    wxLogMessage("Test");

    return 0;
}

Then:

% date
Thu Mar 29 14:03:31 CEST 2012
% g++ -g -Wall wxbt.cpp `~/build/wx-gtkud/wx-config --cxxflags --libs base` && ./a.out
2012-03-29 14:03:33 CEST: Test

I.e. everything looks correct to me. What does this program do for you? Can you (minimally) modify it to exhibit the wrong behaviour?

comment:6 Changed 2 years ago by vm.dozor

  • Status changed from infoneeded_new to new

In Europe everything is good :)

But in the Far East... :(

I didn't make changes to the program wxbt.cpp.

_build.sh:
g++ -g -Wall wxbt.cpp `wx-config --cxxflags --libs base` && ./a.out
date
dozor@dozor-2:~/Projects/wx.trac$ ./_build.sh

2012-03-30 20:26:54 VLAT: Test
Пт. марта 30 09:26:54 VLAT 2012

I removed one letter from a file log.cpp

void wxLog::TimeStamp(wxString *str)
{
#if wxUSE_DATETIME
  if ( !ms_timestamp.empty() ) {
//        *str = wxDateTime::UNow().Format(ms_timestamp);
// Change UNow to Now
  *str = wxDateTime::Now().Format(ms_timestamp);
  *str += wxS(": ");
}
#endif // wxUSE_DATETIME }

and rebuild wxWidgets

dozor@dozor-2:~/Projects/wx.trac$ ./_build.sh

2012-03-30 10:13:38 VLAT: Test
Пт. марта 30 10:13:38 VLAT 2012

Now we are no worse than in Europe. ;)

I looked at the link
http://www.cplusplus.com/reference/clibrary/ctime/strftime/
There's no milliseconds.

May be this way...

comment:7 Changed 2 years ago by vadz

There is something really strange going on here because looking carefully at your initial report I see that:

wxGetLocalTimeMillis() = 1332950944833
wxGetTimeZone -39600
wxGetUTCTimeMillis() = 1332911344833

which is absolutely correct: you're in UTC+11 TZ and this is the difference between the UTC and local times returned.

So I really don't see where could it have gone wrong as UNow() just assigns the time returned by wxGetUTCTimeMillis() to wxDateTime::m_time.

Right now I have no idea why does it behave differently for you and me. Could you please check what goes on inside Format() in the debugger?

comment:8 Changed 2 years ago by gnewt

I have similar issues with wxLogMessage here in Australia too.

    wxLog::SetTimestamp("%Y-%m-%d %H:%M:%S %Z");
    m_logOld = wxLog::SetActiveTarget( new wxLogTextCtrl( m_LogWindow ) );
    wxLogMessage( "Logging started. wxGetTimeZone (in hours) = [%d], wxNow = [%s], UNow() = [%s]", wxGetTimeZone()/3600, wxNow(), wxDateTime::UNow().FormatISOCombined() );

Produces this output in Melbourne (wxMSW, mingw32, win7 64 bit)

2012-04-17 20:24:08 AUS Eastern Standard Time: Logging started. wxGetTimeZone (in hours) = [-10], wxNow = [Tue Apr 17 10:24:08 2012], UNow() = [2012-04-17T02:24:08]

To me, it looks like the timezone offset is subtracted from local time, or subtracted twice from UTC?

Even better:

    wxLogMessage( "Logging started.");
    wxLogMessage("wxGetTimeZone (in hours) = [%d], wxNow = [%s], UNow() = [%s]", wxGetTimeZone()/3600, wxNow(), wxDateTime::UNow().FormatISOCombined() );

produces

2012-04-17 02:48:39 AUS Eastern Standard Time: Logging started.
2012-04-17 20:48:39 AUS Eastern Standard Time: wxGetTimeZone (in hours) = [-10], wxNow = [Tue Apr 17 10:48:39 2012], UNow() = [2012-04-17T20:48:39]

which is frankly bizarre!!!

wxNow() is correct in all instances.

comment:9 follow-up: Changed 2 years ago by vadz

Sorry, I didn't have time to debug this yet but I'd really like to ask people who can reproduce this bug to try to step inside the code and check what's going on here, it looks pretty bad but unfortunately I just don't see what is causing it.

Thanks in advance for any help!

comment:10 in reply to: ↑ 9 Changed 2 years ago by mutuka

  • Cc mutuka+wxwidgets@… added

Replying to vadz:

Sorry, I didn't have time to debug this yet but I'd really like to ask people who can reproduce this bug to try to step inside the code and check what's going on here, it looks pretty bad but unfortunately I just don't see what is causing it.

Thanks in advance for any help!

It seems this is fixed in trunk, as of [70418]. With that change, it works as expected for me.

Since wxLog::TimeStamp() calls wxDateTime::UNow().Format(ms_timestamp), and given that wxDateTime::UNow() was wrong in 2.9.3, the timezone offset was applied twice, yielding weird results.

comment:11 Changed 2 years ago by vadz

  • Resolution set to fixed
  • Status changed from new to closed

I assumed that the original reporter was testing it with the current svn for some reason but now I see that he probably indeed tested with 2.9.3 only. So I'm closing it for now, please reopen if you can still reproduce it with the current svn. Thanks!

Note: See TracTickets for help on using tickets.