New issue
Advanced search Search tips

Issue 707526 link

Starred by 2 users

Issue metadata

Status: Duplicate
Owner:
Closed: Mar 2018
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: ----
Pri: 3
Type: Bug



Sign in to add a comment

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.

 
More about the consequences of the time warp can be seen in
bug 702276.

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.
tlsdate.log
11.1 KB View Download

Comment 3 by aut...@google.com, Apr 13 2017

Owner: xixuan@chromium.org
Potentially related to Xixuan's work on https://bugs.chromium.org/p/chromium/issues/detail?id=702276 ? 
Status: Assigned (was: Untriaged)
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.

Comment 5 by xixuan@chromium.org, Mar 19 2018

Mergedinto: 702276
Status: Duplicate (was: Assigned)

Sign in to add a comment