NDK test (gtest.gtest_unittest, FormatEpochTimeInMillisAsIso8601) fails on KitKat devices #1604

rprichard · 2021-11-13T08:09:07Z

Some FormatEpochTimeInMillisAsIso8601 tests in gtest.gtest_unittest are failing for me on KitKat devices:

[----------] 5 tests from FormatEpochTimeInMillisAsIso8601Test
[ RUN      ] FormatEpochTimeInMillisAsIso8601Test.PrintsTwoDigitSegments
[       OK ] FormatEpochTimeInMillisAsIso8601Test.PrintsTwoDigitSegments (6 ms)
[ RUN      ] FormatEpochTimeInMillisAsIso8601Test.IncludesMillisecondsAfterDot
/x/ndk/out/linux/android-ndk-r24-canary/sources/third_party/googletest/test/gtest_unittest.cc:496: Failure
Expected equality of these values:
  "2011-10-31T18:52:42.234"
  FormatEpochTimeInMillisAsIso8601(1320087162 * kMillisPerSec + 234)
    Which is: "2011-10-31T10:52:42.234"
[  FAILED  ] FormatEpochTimeInMillisAsIso8601Test.IncludesMillisecondsAfterDot (6 ms)
[ RUN      ] FormatEpochTimeInMillisAsIso8601Test.PrintsLeadingZeroes
/x/ndk/out/linux/android-ndk-r24-canary/sources/third_party/googletest/test/gtest_unittest.cc:501: Failure
Expected equality of these values:
  "2011-09-03T05:07:02.000"
  FormatEpochTimeInMillisAsIso8601(1315026422 * kMillisPerSec)
    Which is: "2011-09-02T21:07:02.000"
[  FAILED  ] FormatEpochTimeInMillisAsIso8601Test.PrintsLeadingZeroes (6 ms)
[ RUN      ] FormatEpochTimeInMillisAsIso8601Test.Prints24HourTime
/x/ndk/out/linux/android-ndk-r24-canary/sources/third_party/googletest/test/gtest_unittest.cc:506: Failure
Expected equality of these values:
  "2011-09-28T17:08:22.000"
  FormatEpochTimeInMillisAsIso8601(1317229702 * kMillisPerSec)
    Which is: "2011-09-28T09:08:22.000"
[  FAILED  ] FormatEpochTimeInMillisAsIso8601Test.Prints24HourTime (6 ms)
[ RUN      ] FormatEpochTimeInMillisAsIso8601Test.PrintsEpochStart
/x/ndk/out/linux/android-ndk-r24-canary/sources/third_party/googletest/test/gtest_unittest.cc:510: Failure
Expected equality of these values:
  "1970-01-01T00:00:00.000"
  FormatEpochTimeInMillisAsIso8601(0)
    Which is: "1969-12-31T16:00:00.000"
[  FAILED  ] FormatEpochTimeInMillisAsIso8601Test.PrintsEpochStart (6 ms)
[----------] 5 tests from FormatEpochTimeInMillisAsIso8601Test (33 ms total)

It seems there was a regression in KitKat involving timezone configuration. If the current timezone was configured using (a) an unset TZ variable or (b) a name like America/Los_Angeles, then trying to reconfigure the timezone using a string like UTC+nn has no effect. If there is an intermediate timezone configuration using an unrecognized string, then it can be finally configured using UTC+nn.

AFAICT, it's fixed in Lollipop.

Test program:

#include <time.h>
#include <stdio.h>
#include <stdlib.h>
void test(const char* time_zone) {
  setenv("TZ", time_zone, 1);
  tzset();
  time_t time_val = 0;
  struct tm result = { 0 };
  struct tm* p = localtime_r(&time_val, &result);
  printf("%16s: %04d-%02d-%02d %02d:%02d:%02d\n", time_zone, p->tm_year + 1900,
         p->tm_mon + 1, p->tm_mday, p->tm_hour, p->tm_min, p->tm_sec);
}
int main(int argc, char **argv) {
  test("America/Chicago");
  test("UTC+00");
  test("UTC-01");
  test("UTC-02");
  test("UTC-03");
  test("America/Chicago");
  test("--no-time-zone--");
  test("UTC+00");
  test("UTC-01");
  test("UTC-02");
  test("UTC-03");
  return 0;
}

JellyBean (generic_x86/sdk_x86/generic_x86:4.1.2/MASTER/eng.wdu.20191218.182616:eng/test-keys):

 America/Chicago: 1969-12-31 18:00:00
          UTC+00: 1970-01-01 00:00:00
          UTC-01: 1970-01-01 01:00:00
          UTC-02: 1970-01-01 02:00:00
          UTC-03: 1970-01-01 03:00:00
 America/Chicago: 1969-12-31 18:00:00
--no-time-zone--: 1970-01-01 00:00:00
          UTC+00: 1970-01-01 00:00:00
          UTC-01: 1970-01-01 01:00:00
          UTC-02: 1970-01-01 02:00:00
          UTC-03: 1970-01-01 03:00:00

KitKat (generic_x86/sdk_x86/generic_x86:4.4.2/KK/4174703:eng/test-keys, google/razor/flo:4.4.4/KTU84P/1227136:user/release-keys):

 America/Chicago: 1969-12-31 18:00:00
          UTC+00: 1969-12-31 18:00:00
          UTC-01: 1969-12-31 18:00:00
          UTC-02: 1969-12-31 18:00:00
          UTC-03: 1969-12-31 18:00:00
 America/Chicago: 1969-12-31 18:00:00
--no-time-zone--: 1970-01-01 00:00:00
          UTC+00: 1970-01-01 00:00:00
          UTC-01: 1970-01-01 01:00:00
          UTC-02: 1970-01-01 02:00:00
          UTC-03: 1970-01-01 03:00:00

Lollipop (generic_x86_64/sdk_phone_x86_64/generic_x86_64:5.0.2/LSY66K/4174711:eng/test-keys):

 America/Chicago: 1969-12-31 18:00:00
          UTC+00: 1970-01-01 00:00:00
          UTC-01: 1970-01-01 01:00:00
          UTC-02: 1970-01-01 02:00:00
          UTC-03: 1970-01-01 03:00:00
 America/Chicago: 1969-12-31 18:00:00
--no-time-zone--: 1970-01-01 00:00:00
          UTC+00: 1970-01-01 00:00:00
          UTC-01: 1970-01-01 01:00:00
          UTC-02: 1970-01-01 02:00:00
          UTC-03: 1970-01-01 03:00:00

I did a brief look through the history of bionic/libc/tzcode through JB..KitKat..L but nothing popped out to me.

Before I tried --no-time-zone--, I tried UTC, which also had the effect of making localtime use UTC time zone, but I don't know if that's because UTC is special or whether it's just another unrecognized string.

The text was updated successfully, but these errors were encountered:

rprichard · 2021-11-13T08:14:50Z

gtest sets the time zone here:

https://android.googlesource.com/platform/external/googletest/+/refs/tags/ndk-r24-beta1/googletest/test/gtest_unittest.cc#451

It calls localtime here:

https://android.googlesource.com/platform/external/googletest/+/refs/tags/ndk-r24-beta1/googletest/src/gtest.cc#4559

I wondered why it didn't use gmtime, but I think the idea is that FormatEpochTimeInMillisAsRFC3339 should report time strings in the local time zone, but when gtest is testing FormatEpochTimeInMillisAsRFC3339 itself, it needs to fix the time zone first so the result is consistent.

enh-google · 2021-11-16T02:21:21Z

i'm not sure i knew it was a regression at the time, but i do remember fixing a bug in that time period that's likely relevant ... there was a period where you needed to call tzset() if you changed the TZ environment variable. since then, we've automatically acted as if you called tzset(). so maybe that was true before then too? iirc it wasn't reported as a regression, but may have been?

rprichard · 2021-11-16T03:00:04Z

I don't think that's it?

localtime_r calls tzset_unlocked in all of: jb-dev, kitkat-dev, lollipop-dev.
Both googletest and my test case call tzset after [un]setenv.

rprichard · 2021-11-16T05:24:08Z

I debugged it on KitKat, and I think the problem is that tzload (used for UTC, GMT, America/Chicago) initializes lclmem.defaulttype, but tzparse (used for UTC+nn) doesn't.

tzload handles America/Chicago by setting lclmem.defaulttype to 1, whereas tzload of UTC or GMT sets it to 0. For a string like UTC+00, though, tzload fails, and the time is instead parsed with tzparse, which needs to clear defaulttype but doesn't.

For an arbitrary non-timezone random string, tzset_locked's tzload and tzparse calls fail, so tzset_locked calls gmtload, which calls tzload("GMT", ...). tzload sets defaulttype to 0.

I did attempt to bisect the changes to localtime.c, but left ALL_STATE undefined and used KitKat's timezone database.

The first CL with the bug was https://android-review.googlesource.com/c/platform/bionic/+/62125/, which introduced the defaulttype field.
The bug was fixed with https://android-review.googlesource.com/c/platform/bionic/+/98649/, which adds code to tzparse to clear defaulttype.

I think the upshot is that, on KitKat, to set the timezone to "UTC+nn", a program needs to first set the timezone to plain "UTC" or "GMT" then call tzset, so that lclmem.defaulttype is cleared. I'm wondering if I should make the obvious patch to googletest's SetTimeZone function. That function isn't used by users of googletest -- it's only used to test googletest itself.

rprichard · 2021-11-16T06:08:43Z

Either of these workarounds works:

enh-google · 2021-11-16T16:47:24Z

go with the NDK workaround for now, but send the gtest fix upstream, and cherrypick it if they accept it?

rprichard · 2021-11-20T01:49:26Z

It looks like upstream is happy with the workaround at http://cl/410688733 (though the automated tests seem to be failing).

On KitKat, calling tzset with UTC+nn doesn't initialize all the timezone state. If the previous timezone was something like America/Chicago, then changing it to UTC+nn might have no effect. Setting the timezone to an intermediate value like "UTC" avoids the problem. Works around android/ndk#1604. PiperOrigin-RevId: 413050236 Change-Id: I99b2d3330ae68f1d58cd2ca278d3eaae30bd1e83

DanAlbert · 2022-10-19T22:23:32Z

Was fixed in Lollipop, and we don't support kitkat any more.

rprichard added the bug label Nov 13, 2021

DanAlbert assigned rprichard and unassigned rprichard Oct 19, 2022

DanAlbert closed this as not planned Won't fix, can't repro, duplicate, stale Oct 19, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

NDK test (gtest.gtest_unittest, FormatEpochTimeInMillisAsIso8601) fails on KitKat devices #1604

NDK test (gtest.gtest_unittest, FormatEpochTimeInMillisAsIso8601) fails on KitKat devices #1604

rprichard commented Nov 13, 2021 •

edited

Loading

rprichard commented Nov 13, 2021

enh-google commented Nov 16, 2021

rprichard commented Nov 16, 2021

rprichard commented Nov 16, 2021

rprichard commented Nov 16, 2021

enh-google commented Nov 16, 2021

rprichard commented Nov 20, 2021

DanAlbert commented Oct 19, 2022

NDK test (gtest.gtest_unittest, FormatEpochTimeInMillisAsIso8601) fails on KitKat devices #1604

NDK test (gtest.gtest_unittest, FormatEpochTimeInMillisAsIso8601) fails on KitKat devices #1604

Comments

rprichard commented Nov 13, 2021 • edited Loading

rprichard commented Nov 13, 2021

enh-google commented Nov 16, 2021

rprichard commented Nov 16, 2021

rprichard commented Nov 16, 2021

rprichard commented Nov 16, 2021

enh-google commented Nov 16, 2021

rprichard commented Nov 20, 2021

DanAlbert commented Oct 19, 2022

rprichard commented Nov 13, 2021 •

edited

Loading