Mysterious time warp on a DUT
Reported by
jrbarnette@chromium.org,
Apr 1 2017
|
||||
Issue description
During a test on chromeos2-row8-rack1-host1, time mysteriously
warped from 2017 to 2019, and then back again.
The time warp lasted through the end of one test, with the
result that the test logs reported completion in a future
that (as of this writing) is yet to arrive.
This is the test that saw the time warp:
http://cautotest/afe/#tab_id=view_job&object_id=106379106
Note that these logs has a version of /var/log/messages that
shows only the warp forward.
The best way to see the complete logs is with the test job
that followed:
http://cautotest/afe/#tab_id=view_job&object_id=106379107
Logs from job 106379107 contain a /var/log/messages that shows
both the warp forward in time and the warp back to the present.
First, the warp forward:
2017-03-13T08:45:01.977498+00:00 NOTICE ag[5838]: autotest server[stack::install_pkg|untar_pkg|_run_command] -> ssh_run(tar --no-same-owner -xjf /usr/local/autotest/packages/client-autotest.tar.bz2 -C /usr/local/autotest)
2017-03-13T08:45:03.680360+00:00 NOTICE ag[5850]: autotest server[stack::untar_pkg|compute_checksum|_run_command] -> ssh_run(md5sum /usr/local/autotest/packages/client-autotest.tar.bz2 )
2017-03-13T08:45:04.013598+00:00 NOTICE ag[5853]: autotest server[stack::install_pkg|untar_pkg|_run_command] -> ssh_run(echo "d4a5d63e262be87bf01062b5bcf2d278" > /usr/local/autotest/.checksum )
2019-05-17T21:49:25.177265+00:00 NOTICE ag[5860]: autotest server[stack::send_file|use_rsync|_check_rsync] -> ssh_run(rsync --version)
2019-05-17T21:49:25.895113+00:00 NOTICE ag[5865]: autotest server[stack::wait_up|is_up|ssh_ping] -> ssh_run(true)
2019-05-17T21:49:26.084794+00:00 NOTICE ag[5868]: autotest server[stack::run|_do_run|verify_machine] -> ssh_run(ls /usr/local/autotest/bin/autotest > /dev/null 2>&1)
Time went from 2017-03-13 to 2019-05-17.
A bit later, time jumped back:
2019-05-17T21:50:22.305142+00:00 NOTICE ag[7150]: autotest server[stack::install|_install|_install] -> ssh_run(mkdir -p /usr/local/autotest)
2019-05-17T21:50:22.481549+00:00 NOTICE ag[7153]: autotest server[stack::install|_install|_install] -> ssh_run(rm -rf /usr/local/autotest/results/*)
2019-05-17T21:50:23.230106+00:00 NOTICE ag[7159]: autotest server[stack::_install|_install|_install_using_packaging] -> ssh_run(cd /usr/local/autotest && ls | grep -v "^packages$" | xargs rm -rf && rm -rf .[!.]*)
2017-03-13T08:46:02.001064+00:00 NOTICE ag[7166]: autotest server[stack::_install_using_packaging|install_pkg|_run_command] -> ssh_run(mkdir -p /usr/local/autotest/packages)
2017-03-13T08:46:02.185310+00:00 NOTICE ag[7170]: autotest server[stack::fetch_pkg|exists|_run_command] -> ssh_run(test -d /usr/local/autotest/packages)
2017-03-13T08:46:02.360444+00:00 NOTICE ag[7173]: autotest server[stack::fetch_pkg|exists|_run_command] -> ssh_run(test -e /usr/local/autotest/packages/client-autotest.tar.bz2)
So, the logs claimed we spent 58 seconds in the future, and then
returned to the present 58 seconds after we left.
There's nothing in the logs to explain either time change. It's
plausible (but not proved) that the warp backward was caused by
tlsdate setting time from the network.
,
Apr 1 2017
Also in the logs for job 106379107 (the job that ran after the failure) you can find the complete tlsdate.log showing that tlsdate did in fact detect and correct the time warp. The best evidence from the logs so far is that the DUT clock spontaneously jumped forward; tlsdated then correctly detected and corrected the jump.
,
Apr 13 2017
Potentially related to Xixuan's work on https://bugs.chromium.org/p/chromium/issues/detail?id=702276 ?
,
Mar 14 2018
This bug is Untriaged and very old. Because it has an owner, the status will be set to assigned to avoid closing a bug someone is using. If this bug still needs triage, change it back to Untriaged.
,
Mar 19 2018
|
||||
►
Sign in to add a comment |
||||
Comment 1 by jrbarnette@chromium.org
, Apr 1 2017