base_unittests TimeFormatting* tests flaky; off by 1-hour |
||||||
Issue description
Chromecast team runs the base_unittests on our devices. We find that ~20% of the time, we will get the failures for:
TimeFormattingTest.TimeFormatDateUS
TimeFormattingTest.TimeFormatTimeOfDayJP
TimeFormattingTest.TimeFormatDateGB
TimeFormattingTest.TimeFormatTimeOfDayDefault12h
TimeFormattingTest.TimeFormatTimeOfDayDefault24h
When the failures happen, it happens for all 5 test cases, and the "actual" time formatted is always 1 hour before the "expected" time (e.g. actual=2:42, expected=3:42).
My first guess is that perhaps due to test ordering, there is another test that is setting/unsetting a timezone or daily savings global setting somewhere, which causes a race condition here.
I also do not see any of thes failures on our single-core devices ; only on the multi-core devices.
[ RUN ] TimeFormattingTest.TimeFormatTimeOfDayDefault12h
../../base/i18n/time_formatting_unittest.cc:63: Failure
Value of: TimeFormatTimeOfDay(time)
Actual: 2:42 PM
Expected: clock12h_pm
Which is: 3:42 PM
../../base/i18n/time_formatting_unittest.cc:64: Failure
Value of: TimeFormatTimeOfDayWithMilliseconds(time)
Actual: 14:42:07.000
Expected: clock24h_millis
Which is: 15:42:07.000
../../base/i18n/time_formatting_unittest.cc:70: Failure
Value of: TimeFormatTimeOfDayWithHourClockType(time, k24HourClock, kKeepAmPm)
Actual: 14:42
Expected: clock24h
Which is: 15:42
../../base/i18n/time_formatting_unittest.cc:74: Failure
Value of: TimeFormatTimeOfDayWithHourClockType(time, k24HourClock, kDropAmPm)
Actual: 14:42
Expected: clock24h
Which is: 15:42
../../base/i18n/time_formatting_unittest.cc:79: Failure
Value of: TimeFormatTimeOfDayWithHourClockType(time, k12HourClock, kKeepAmPm)
Actual: 2:42 PM
Expected: clock12h_pm
Which is: 3:42 PM
../../base/i18n/time_formatting_unittest.cc:83: Failure
Value of: TimeFormatTimeOfDayWithHourClockType(time, k12HourClock, kDropAmPm)
Actual: 2:42
Expected: clock12h
Which is: 3:42
[ FAILED ] TimeFormattingTest.TimeFormatTimeOfDayDefault12h (12 ms)
[ RUN ] TimeFormattingTest.TimeFormatTimeOfDayDefault24h
../../base/i18n/time_formatting_unittest.cc:106: Failure
Value of: TimeFormatTimeOfDay(time)
Actual: 14:42
Expected: clock24h
Which is: 15:42
../../base/i18n/time_formatting_unittest.cc:107: Failure
Value of: TimeFormatTimeOfDayWithMilliseconds(time)
Actual: 14:42:07.000
Expected: clock24h_millis
Which is: 15:42:07.000
../../base/i18n/time_formatting_unittest.cc:113: Failure
Value of: TimeFormatTimeOfDayWithHourClockType(time, k24HourClock, kKeepAmPm)
Actual: 14:42
Expected: clock24h
Which is: 15:42
../../base/i18n/time_formatting_unittest.cc:117: Failure
Value of: TimeFormatTimeOfDayWithHourClockType(time, k24HourClock, kDropAmPm)
Actual: 14:42
Expected: clock24h
Which is: 15:42
../../base/i18n/time_formatting_unittest.cc:122: Failure
Value of: TimeFormatTimeOfDayWithHourClockType(time, k12HourClock, kKeepAmPm)
Actual: 2:42 pm
Expected: clock12h_pm
Which is: 3:42 pm
../../base/i18n/time_formatting_unittest.cc:126: Failure
Value of: TimeFormatTimeOfDayWithHourClockType(time, k12HourClock, kDropAmPm)
Actual: 2:42
Expected: clock12h
Which is: 3:42
[ FAILED ] TimeFormattingTest.TimeFormatTimeOfDayDefault24h (10 ms)
[ RUN ] TimeFormattingTest.TimeFormatTimeOfDayJP
../../base/i18n/time_formatting_unittest.cc:147: Failure
Value of: TimeFormatTimeOfDay(time)
Actual: 14:42
Expected: clock24h
Which is: 15:42
../../base/i18n/time_formatting_unittest.cc:153: Failure
Value of: TimeFormatTimeOfDayWithHourClockType(time, k24HourClock, kKeepAmPm)
Actual: 14:42
Expected: clock24h
Which is: 15:42
../../base/i18n/time_formatting_unittest.cc:157: Failure
Value of: TimeFormatTimeOfDayWithHourClockType(time, k24HourClock, kDropAmPm)
Actual: 14:42
Expected: clock24h
Which is: 15:42
../../base/i18n/time_formatting_unittest.cc:162: Failure
Value of: TimeFormatTimeOfDayWithHourClockType(time, k12HourClock, kKeepAmPm)
Actual: åˆå¾Œ2:42
Expected: clock12h_pm
Which is: åˆå¾Œ3:42
../../base/i18n/time_formatting_unittest.cc:166: Failure
Value of: TimeFormatTimeOfDayWithHourClockType(time, k12HourClock, kDropAmPm)
Actual: 2:42
Expected: clock12h
Which is: 3:42
[ FAILED ] TimeFormattingTest.TimeFormatTimeOfDayJP (7 ms)
[ RUN ] TimeFormattingTest.TimeFormatDateUS
../../base/i18n/time_formatting_unittest.cc:187: Failure
Value of: TimeFormatShortDateAndTime(time)
Actual: 4/30/11, 2:42:07 PM
Expected: ASCIIToUTF16("4/30/11, 3:42:07 PM")
Which is: 4/30/11, 3:42:07 PM
../../base/i18n/time_formatting_unittest.cc:189: Failure
Value of: TimeFormatShortDateAndTimeWithTimeZone(time)
Actual: 4/30/11, 2:42:07 PM GMT+3:30
Expected: ASCIIToUTF16("4/30/11, 3:42:07 PM ") + GetShortTimeZone(time)
Which is: 4/30/11, 3:42:07 PM GMT+3:30
../../base/i18n/time_formatting_unittest.cc:192: Failure
Value of: TimeFormatFriendlyDateAndTime(time)
Actual: Saturday, April 30, 2011 at 2:42:07 PM
Expected: ASCIIToUTF16("Saturday, April 30, 2011 at 3:42:07 PM")
Which is: Saturday, April 30, 2011 at 3:42:07 PM
[ FAILED ] TimeFormattingTest.TimeFormatDateUS (33 ms)
[ RUN ] TimeFormattingTest.TimeFormatDateGB
../../base/i18n/time_formatting_unittest.cc:215: Failure
Value of: TimeFormatShortDateAndTime(time)
Actual: 30/04/2011, 14:42:07
Expected: ASCIIToUTF16("30/04/2011, 15:42:07")
Which is: 30/04/2011, 15:42:07
../../base/i18n/time_formatting_unittest.cc:217: Failure
Value of: TimeFormatShortDateAndTimeWithTimeZone(time)
Actual: 30/04/2011, 14:42:07 GMT+3:30
Expected: ASCIIToUTF16("30/04/2011, 15:42:07 ") + GetShortTimeZone(time)
Which is: 30/04/2011, 15:42:07 GMT+3:30
../../base/i18n/time_formatting_unittest.cc:219: Failure
Value of: TimeFormatFriendlyDateAndTime(time)
Actual: Saturday, 30 April 2011 at 14:42:07
Expected: ASCIIToUTF16("Saturday, 30 April 2011 at 15:42:07")
Which is: Saturday, 30 April 2011 at 15:42:07
[ FAILED ] TimeFormattingTest.TimeFormatDateGB (3 ms)
,
Dec 14 2016
Let me take a look. mbjorge@, just in case, does this happen always on a specific bot or just happen occasionally on any bot? Has this been observed only on Linux or other platforms?
,
Dec 14 2016
Thanks! This does not always happen on any specific device type. It happens occasionally (around ~15% of runs) across all devices (except for our single core devices). We are not seeing this on our android builds, only our linux builds.
,
Dec 14 2016
Oh, just checked and for the first time I actually saw this failure on the single core device also. Except it was off by one our in the other direction:
[ RUN ] TimeFormattingTest.TimeFormatTimeOfDayDefault12h
../../base/i18n/time_formatting_unittest.cc:63: Failure
Value of: TimeFormatTimeOfDay(time)
Actual: 4:42 PM
Expected: clock12h_pm
Which is: 3:42 PM
../../base/i18n/time_formatting_unittest.cc:64: Failure
Value of: TimeFormatTimeOfDayWithMilliseconds(time)
Actual: 16:42:07.000
Expected: clock24h_millis
Which is: 15:42:07.000
../../base/i18n/time_formatting_unittest.cc:70: Failure
Value of: TimeFormatTimeOfDayWithHourClockType(time, k24HourClock, kKeepAmPm)
Actual: 16:42
Expected: clock24h
Which is: 15:42
../../base/i18n/time_formatting_unittest.cc:74: Failure
Value of: TimeFormatTimeOfDayWithHourClockType(time, k24HourClock, kDropAmPm)
Actual: 16:42
Expected: clock24h
Which is: 15:42
../../base/i18n/time_formatting_unittest.cc:79: Failure
Value of: TimeFormatTimeOfDayWithHourClockType(time, k12HourClock, kKeepAmPm)
Actual: 4:42 PM
Expected: clock12h_pm
Which is: 3:42 PM
../../base/i18n/time_formatting_unittest.cc:83: Failure
Value of: TimeFormatTimeOfDayWithHourClockType(time, k12HourClock, kDropAmPm)
Actual: 4:42
Expected: clock12h
Which is: 3:42
[ FAILED ] TimeFormattingTest.TimeFormatTimeOfDayDefault12h (39 ms)
[524/2212] TimeFormattingTest.TimeFormatTimeOfDayDefault12h (39 ms)
[ RUN ] TimeFormattingTest.TimeFormatTimeOfDayDefault24h
../../base/i18n/time_formatting_unittest.cc:106: Failure
Value of: TimeFormatTimeOfDay(time)
Actual: 16:42
Expected: clock24h
Which is: 15:42
../../base/i18n/time_formatting_unittest.cc:107: Failure
Value of: TimeFormatTimeOfDayWithMilliseconds(time)
Actual: 16:42:07.000
Expected: clock24h_millis
Which is: 15:42:07.000
../../base/i18n/time_formatting_unittest.cc:113: Failure
Value of: TimeFormatTimeOfDayWithHourClockType(time, k24HourClock, kKeepAmPm)
Actual: 16:42
Expected: clock24h
Which is: 15:42
../../base/i18n/time_formatting_unittest.cc:117: Failure
Value of: TimeFormatTimeOfDayWithHourClockType(time, k24HourClock, kDropAmPm)
Actual: 16:42
Expected: clock24h
Which is: 15:42
../../base/i18n/time_formatting_unittest.cc:122: Failure
Value of: TimeFormatTimeOfDayWithHourClockType(time, k12HourClock, kKeepAmPm)
Actual: 4:42 pm
Expected: clock12h_pm
Which is: 3:42 pm
../../base/i18n/time_formatting_unittest.cc:126: Failure
Value of: TimeFormatTimeOfDayWithHourClockType(time, k12HourClock, kDropAmPm)
Actual: 4:42
Expected: clock12h
Which is: 3:42
[ FAILED ] TimeFormattingTest.TimeFormatTimeOfDayDefault24h (24 ms)
[525/2212] TimeFormattingTest.TimeFormatTimeOfDayDefault24h (24 ms)
[ RUN ] TimeFormattingTest.TimeFormatTimeOfDayJP
../../base/i18n/time_formatting_unittest.cc:147: Failure
Value of: TimeFormatTimeOfDay(time)
Actual: 16:42
Expected: clock24h
Which is: 15:42
../../base/i18n/time_formatting_unittest.cc:153: Failure
Value of: TimeFormatTimeOfDayWithHourClockType(time, k24HourClock, kKeepAmPm)
Actual: 16:42
Expected: clock24h
Which is: 15:42
../../base/i18n/time_formatting_unittest.cc:157: Failure
Value of: TimeFormatTimeOfDayWithHourClockType(time, k24HourClock, kDropAmPm)
Actual: 16:42
Expected: clock24h
Which is: 15:42
../../base/i18n/time_formatting_unittest.cc:162: Failure
Value of: TimeFormatTimeOfDayWithHourClockType(time, k12HourClock, kKeepAmPm)
Actual: åˆå¾Œ4:42
Expected: clock12h_pm
Which is: åˆå¾Œ3:42
../../base/i18n/time_formatting_unittest.cc:166: Failure
Value of: TimeFormatTimeOfDayWithHourClockType(time, k12HourClock, kDropAmPm)
Actual: 4:42
Expected: clock12h
Which is: 3:42
[ FAILED ] TimeFormattingTest.TimeFormatTimeOfDayJP (18 ms)
[526/2212] TimeFormattingTest.TimeFormatTimeOfDayJP (18 ms)
[ RUN ] TimeFormattingTest.TimeFormatDateUS
../../base/i18n/time_formatting_unittest.cc:187: Failure
Value of: TimeFormatShortDateAndTime(time)
Actual: 4/30/11, 4:42:07 PM
Expected: ASCIIToUTF16("4/30/11, 3:42:07 PM")
Which is: 4/30/11, 3:42:07 PM
../../base/i18n/time_formatting_unittest.cc:189: Failure
Value of: TimeFormatShortDateAndTimeWithTimeZone(time)
Actual: 4/30/11, 4:42:07 PM CDT
Expected: ASCIIToUTF16("4/30/11, 3:42:07 PM ") + GetShortTimeZone(time)
Which is: 4/30/11, 3:42:07 PM CDT
../../base/i18n/time_formatting_unittest.cc:192: Failure
Value of: TimeFormatFriendlyDateAndTime(time)
Actual: Saturday, April 30, 2011 at 4:42:07 PM
Expected: ASCIIToUTF16("Saturday, April 30, 2011 at 3:42:07 PM")
Which is: Saturday, April 30, 2011 at 3:42:07 PM
[ FAILED ] TimeFormattingTest.TimeFormatDateUS (38 ms)
[527/2212] TimeFormattingTest.TimeFormatDateUS (38 ms)
[ RUN ] TimeFormattingTest.TimeFormatDateGB
../../base/i18n/time_formatting_unittest.cc:215: Failure
Value of: TimeFormatShortDateAndTime(time)
Actual: 30/04/2011, 16:42:07
Expected: ASCIIToUTF16("30/04/2011, 15:42:07")
Which is: 30/04/2011, 15:42:07
../../base/i18n/time_formatting_unittest.cc:217: Failure
Value of: TimeFormatShortDateAndTimeWithTimeZone(time)
Actual: 30/04/2011, 16:42:07 GMT-5
Expected: ASCIIToUTF16("30/04/2011, 15:42:07 ") + GetShortTimeZone(time)
Which is: 30/04/2011, 15:42:07 GMT-5
../../base/i18n/time_formatting_unittest.cc:219: Failure
Value of: TimeFormatFriendlyDateAndTime(time)
Actual: Saturday, 30 April 2011 at 16:42:07
Expected: ASCIIToUTF16("Saturday, 30 April 2011 at 15:42:07")
Which is: Saturday, 30 April 2011 at 15:42:07
[ FAILED ] TimeFormattingTest.TimeFormatDateGB (4 ms)
,
Jan 9 2017
friendly ping here; did you get a chance to investigate this yet?
,
Jan 20 2017
I added a log statement that prints out the value of |time| after it is created by Time::FromLocalExploded(kTestDateTimeExploded, &time).
When the test passes on my desktop I see:[111760:111760:0119/180856.394722:3315122322753:INFO:time_formatting_unittest.cc(58)] |time| is: 2011-04-30 22:42:07.000 UTC
When the test failed on a device, I see:
[ RUN ] TimeFormattingTest.TimeFormatDateUS
[3933:3933:0119/194205.027564:2472506892:INFO:time_formatting_unittest.cc(195)] |time| is: 2011-04-30 21:42:07.000 UTC
../../base/i18n/time_formatting_unittest.cc:201: Failure
Value of: TimeFormatShortDateAndTime(time)
Actual: 4/30/11, 4:42:07 PM
Expected: ASCIIToUTF16("4/30/11, 3:42:07 PM")
Which is: 4/30/11, 3:42:07 PM
I also added in 3 calls to EXPECT_EQ(i18n::GetConfiguredLocale(), "en-US") (adjusted for the correct Locale per test) in each test (right after the local is set, in the middle of the tests, and at the very end), and those never print any failures in the logs.
,
Jan 20 2017
Is it necessary to generate |time| via Time::FromLocaleExploded, or could the test use Time::FromUTCExploded instead to generate |time|?
,
Feb 1 2017
Another friendly ping. Is there any sort of logging or such I could capture that might be useful?
,
Feb 14 2017
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/b51704ea96054edb2dba5a4e42359afe2c07c93d commit b51704ea96054edb2dba5a4e42359afe2c07c93d Author: mbjorge <mbjorge@chromium.org> Date: Tue Feb 14 01:11:25 2017 [Chromecast] Disable TimeFormattingTest.TimeFormat* tests. These tests are flaky on devices and the only failing test on many platforms. In an effort to stabilize the tests, disable these until a path forward is figured out. BUG= 671429 Review-Url: https://codereview.chromium.org/2687013004 Cr-Commit-Position: refs/heads/master@{#450181} [modify] https://crrev.com/b51704ea96054edb2dba5a4e42359afe2c07c93d/chromecast/BUILD.gn
,
Oct 17 2017
Sorry for the terribly late reply. There's a similar bug for iOS. It's also due to FromLocalExploded(). > Is it necessary to generate |time| via Time::FromLocaleExploded, or could the test use Time::FromUTCExploded instead to generate |time|? Yes, I suspect FromLocalExploded() is problematic. I don't know why it drifts onl y on some occasions. In that case, the actual result will depend on the device timezone. To make this test *independent* of FromLocalExploded's behavior, what we can do is 1) Use FromUTCExploded() or just a pre-calculated time value 2) Fix the ICU timezone manually to America/Los_Angeles (we can restore it at the end of the test). > When the test passes on my desktop I see:[111760:111760:0119/180856.394722:3315122322753:INFO:time_formatting_unittest.cc(58)] |time| is: 2011-04-30 22:42:07.000 UTC That corresponds to 2011-04-30T15:42:07 Pacific Daylight Saving Time I think when the test fails, that log will have '2011-04-30 21:42:07 UTC' or '2011-04-30 23:42:07 UTC' instead of 2011-04-30 22:42:07 UTC.
,
Oct 17 2017
bug 774111 is an iOS bug similar to this. Again, it's FromLocalExploded(). What I wrote in comment 10 should work for both Linux and iOS.
,
Oct 19 2017
,
Oct 30 2017
Issue 778629 has been merged into this issue.
,
Oct 30 2017
Issue 778835 has been merged into this issue.
,
Nov 1 2017
https://chromium-review.googlesource.com/c/chromium/src/+/748220 is a CL.
,
Nov 1 2017
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/d82b2911c9a112e822fddb479b244313472cc95c commit d82b2911c9a112e822fddb479b244313472cc95c Author: Jungshik Shin <jshin@chromium.org> Date: Wed Nov 01 18:57:46 2017 Fix TimeFormat tests and enable them on Android The test is flaky/failing apparently because FromLocalExplode is flaky. Use FromUTCExplode and the fixed timezone (America/Los_Angeles) instead of the default timezone of wherever the test runs. Bug: 671429 , 582915 Test: base_unittests --gtest_filter=TimeFormat* Change-Id: Ia7bd77dca5ef3712cc2516e59387f80899820dab Reviewed-on: https://chromium-review.googlesource.com/748220 Commit-Queue: Jungshik Shin <jshin@chromium.org> Reviewed-by: Mark Mentovai <mark@chromium.org> Cr-Commit-Position: refs/heads/master@{#513201} [modify] https://crrev.com/d82b2911c9a112e822fddb479b244313472cc95c/base/i18n/time_formatting_unittest.cc
,
Nov 1 2017
|
||||||
►
Sign in to add a comment |
||||||
Comment 1 by mbjorge@google.com
, Dec 8 2016