New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.

Issue 671429 link

Starred by 4 users

Issue metadata

Status: Fixed
Owner:
Closed: Nov 2017
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Linux , iOS
Pri: 3
Type: Bug



Sign in to add a comment

base_unittests TimeFormatting* tests flaky; off by 1-hour

Project Member Reported by mbjorge@google.com, Dec 6 2016

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)
 

Comment 1 by mbjorge@google.com, Dec 8 2016

Cc: js...@chromium.org
jshin@ any ideas where a good place to start poking might be?

Comment 2 by js...@chromium.org, 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? 


Comment 3 by mbjorge@google.com, 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.

Comment 4 by mbjorge@google.com, 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)
friendly ping here; did you get a chance to investigate this yet?
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.

Is it necessary to generate |time| via Time::FromLocaleExploded, or could the test use Time::FromUTCExploded instead to generate |time|?
Status: Assigned (was: Untriaged)
Another friendly ping. Is there any sort of logging or such I could capture that might be useful?
Project Member

Comment 9 by bugdroid1@chromium.org, 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

Comment 10 by js...@chromium.org, 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.  

Comment 11 by js...@chromium.org, Oct 17 2017

Labels: OS-iOS
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. 
Components: Tests>Flaky

Comment 13 by js...@chromium.org, Oct 30 2017

 Issue 778629  has been merged into this issue.

Comment 14 by js...@chromium.org, Oct 30 2017

 Issue 778835  has been merged into this issue.
Status: Started (was: Assigned)
https://chromium-review.googlesource.com/c/chromium/src/+/748220 is a CL. 

Project Member

Comment 16 by bugdroid1@chromium.org, 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

Status: Fixed (was: Started)

Sign in to add a comment