New issue
Advanced search Search tips
Starred by 1 user
Status: Untriaged
Owner: ----
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 1
Type: Bug



Sign in to add a comment
-release: UnitTest/Archive steps race: WARNING: CreateTarball: tar: source modification time changed
Project Member Reported by drinkcat@chromium.org, Nov 28 Back to list
https://luci-milo.appspot.com/buildbot/chromeos/betty-arc64-release/310

In the Archive step (https://logs.chromium.org/v/?s=chromeos%2Fbb%2Fchromeos%2Fbetty-arc64-release%2F310%2F%2B%2Frecipes%2Fsteps%2FArchive%2F0%2Fstdout), I see:

13:11:35: INFO: Archiving full autotest tarball locally ...
13:11:35: INFO: RunCommand: tar --sparse -I /b/c/cbuild/repository/chroot/usr/bin/pbzip2 -cf /b/c/cbuild/repository/src/build/images/betty-arc64/latest-cbuildbot/autotest.tar.bz2 autotest in /b/c/cbuild/repository/chroot/build/betty-arc64/usr/local/build
tar: autotest/frontend: file changed as we read it
13:13:12: WARNING: CreateTarball: tar: source modification time changed (see crbug.com/547055), retrying once
13:13:12: INFO: RunCommand: tar --sparse -I /b/c/cbuild/repository/chroot/usr/bin/pbzip2 -cf /b/c/cbuild/repository/src/build/images/betty-arc64/latest-cbuildbot/autotest.tar.bz2 autotest in /b/c/cbuild/repository/chroot/build/betty-arc64/usr/local/build
tar: autotest/site_utils: file changed as we read it
tar: autotest: file changed as we read it

I think the problem here is that UnitTest runs at the same time, and rebuilds autotest while packaging is underway: https://logs.chromium.org/v/?s=chromeos%2Fbb%2Fchromeos%2Fbetty-arc64-release%2F310%2F%2B%2Frecipes%2Fsteps%2FUnitTest%2F0%2Fstdout

Pending 4/61, Building 2/2, [Time 13:11:31 | Elapsed 17m35.6s | Load 46.58 81.87 67.65]
Completed chromeos-base/chromeos-login-0.0.2-r3371 (in 1m18.5s)
Still building autotest-0.0.2-r8884 (16m33.0s). Logs in /tmp/autotest-0.0.2-r8884-Ndjy8b
Started chromeos-base/chromeos-init-0.0.25-r3374 (logged in /tmp/chromeos-init-0.0.25-r3374-_zEBs7)
Started chromeos-base/debugd-0.0.1-r2289 (logged in /tmp/debugd-0.0.1-r2289-YEzTqP)
Completed chromeos-base/debugd-0.0.1-r2289 (in 0m37.2s)
Pending 2/61, Building 2/2, [Time 13:13:01 | Elapsed 19m5.0s | Load 61.06 77.5 67.41]
Completed chromeos-base/chromeos-init-0.0.25-r3374 (in 0m39.6s)
Pending 0/61, Building 3/3, [Time 13:13:03 | Elapsed 19m7.4s | Load 61.06 77.5 67.41]
Started chromeos-base/chromeos-trim-0.0.1-r1168 (logged in /tmp/chromeos-trim-0.0.1-r1168-0v81hm)
Started chromeos-base/factory_installer-0.0.1-r43 (logged in /tmp/factory_installer-0.0.1-r43-X4Jy3n)
13:13:20: INFO: Refreshing due to a 401 (attempt 1/2)
13:13:20: INFO: Refreshing access_token
Completed chromeos-base/autotest-0.0.2-r8884 (in 17m32.1s) <<<<==== Probably modifying autotest directory
Pending 0/61, Building 2/2, [Time 13:13:23 | Elapsed 19m26.9s | Load 62.32 76.77 67.39]
Completed chromeos-base/factory_installer-0.0.1-r43 (in 0m24.2s)
Pending 0/61, Building 1/1, [Time 13:13:27 | Elapsed 19m31.6s | Load 59.33 75.91 67.16]
Completed chromeos-base/chromeos-trim-0.0.1-r1168 (in 0m28.4s)
Pending 0/61, [Time 13:13:31 | Elapsed 19m35.8s | Load 57.94 75.35 67.03]

Note that this is also happening on successful builds, e.g.
https://luci-milo.appspot.com/buildbot/chromeos/betty-arc64-release/308

Archive:
21:17:44: INFO: Archiving full autotest tarball locally ...
21:17:44: INFO: RunCommand: tar --sparse -I /b/c/cbuild/repository/chroot/usr/bin/pbzip2 -cf /b/c/cbuild/repository/src/build/images/betty-arc64/latest-cbuildbot/autotest.tar.bz2 autotest in /b/c/cbuild/repository/chroot/build/betty-arc64/usr/local/build
tar: autotest/packages: file changed as we read it
tar: autotest: file changed as we read it
21:19:17: WARNING: CreateTarball: tar: source modification time changed (see crbug.com/547055), retrying once

UnitTest:
Pending 0/60, Building 3/3, [Time 21:17:37 | Elapsed 17m56.6s | Load 38.29 80.58 67.37]
Started chromeos-base/chromeos-trim-0.0.1-r1167 (logged in /tmp/chromeos-trim-0.0.1-r1167-Q9M3nm)
Started chromeos-base/factory_installer-0.0.1-r43 (logged in /tmp/factory_installer-0.0.1-r43-JVGryj)
Completed chromeos-base/factory_installer-0.0.1-r43 (in 0m18.8s)
Pending 0/60, Building 2/2, [Time 21:17:56 | Elapsed 18m15.3s | Load 40.45 78.22 66.87]
Completed chromeos-base/chromeos-trim-0.0.1-r1167 (in 0m23.8s)
Pending 0/60, Building 1/1, [Time 21:18:01 | Elapsed 18m20.4s | Load 42.81 78.08 66.89]
Completed chromeos-base/autotest-0.0.2-r8882 (in 18m54.3s)
Pending 0/60, [Time 21:19:01 | Elapsed 19m20.1s | Load 49.14 73.42 65.98]
Merge complete

Except that the timing is just a little better and the tar operation succeeds on retry.

(looks related to https://bugs.chromium.org/p/chromium/issues/detail?id=547055, I preferred not re-opening)
 
Summary: -release: UnitTest/Archive steps race: WARNING: CreateTarball: tar: source modification time changed (was: betty-arc64-release: WARNING: CreateTarball: tar: source modification time changed)
Seen on swanky-release too:
https://luci-milo.appspot.com/buildbot/chromeos/swanky-release/1715

12:45:20: INFO: RunCommand: tar --sparse -I /b/c/cbuild/repository/chroot/usr/bin/pbzip2 -cf /b/c/cbuild/repository/src/build/images/swanky/latest-cbuildbot/autotest.tar.bz2 autotest in /b/c/cbuild/repository/chroot/build/swanky/usr/local/build
tar: autotest/client/deps: file changed as we read it
tar: autotest/client: file changed as we read it
tar: autotest: file changed as we read it
12:45:43: WARNING: CreateTarball: tar: source modification time changed (see crbug.com/547055), retrying once

Pending 4/55, Building 4/4, [Time 12:45:44 | Elapsed 13m57.8s | Load 35.11 59.14 46.38]
Completed chromeos-base/autotest-0.0.2-r8884 (in 12m27.1s)

Also:
https://luci-milo.appspot.com/buildbot/chromeos/swanky-release/1705

Cc: vapier@chromium.org
Components: Infra>Client>ChromeOS
Please also see https://bugs.chromium.org/p/chromium/issues/detail?id=789085, I think these have a similar root cause.

I wonder if we should wait for Unittest to complete before starting Archive stage?
this probably broke due to this CL:
  https://chromium-review.googlesource.com/698948

i don't think we can easily do surgery on builders/simple_builders.py:_RunBackgroundStagesForBoard which does (effectively):
    # All of these are run in parallel together.
    stage_list = [
        [test_stages.UnitTestStage, board],
        [chrome_stages.SimpleChromeArtifactsStage, board],
        [release_stages.SignerTestStage, board, archive_stage],  
        [release_stages.SigningStage, board],
        [release_stages.PaygenStage, board],
        [test_stages.ImageTestStage, board],
        [artifact_stages.UploadPrebuiltsStage, board],
        [artifact_stages.DevInstallerPrebuiltsStage, board],
        [artifact_stages.CPEExportStage, board],
        [artifact_stages.UploadTestArtifactsStage, board],
    ]
    parallel.RunParallelSteps([
        lambda: self._RunParallelStages(stage_objs + [archive_stage]),
        lambda: self._RunHWTests(builder_run, board),
        lambda: self._RunVMTests(builder_run, board),
        lambda: self._RunDebugSymbolStages(builder_run, board),
    ])

so we're running a lot of tests in parallel that are supposed to largely not modify things.  but after  issue 740549 , that's no longer the case with the unittest stage.

sucking UnitTest out by itself and running it alone would probably impact the builders -- the stage takes ~20 min, but it's amortized by running the same time as vm/hw tests.

we could introduce a signal whereby the archive stage would hold off until the test artifacts are available.  see how we handle debug_tarball_generated today via the cbuildbot run attrs.
Cc: semenzato@chromium.org
 Issue 789085  has been merged into this issue.
Labels: -Pri-2 Pri-1
Another 2 here:
https://luci-milo.appspot.com/buildbot/chromeos/clapper-release/2136
https://luci-milo.appspot.com/buildbot/chromeos/whirlwind-release/2444

But this time I think it's UnitTest and DebugSymbols clashing:
DebugSymbols:
11:51:36: INFO: RunCommand: sudo -n 'CROS_CACHEDIR=/b/c/cbuild/repository/.cache' 'CROS_SUDO_KEEP_ALIVE=unknown' -- tar --exclude debug/usr/local/build/autotest --exclude debug/tests --sparse -I /usr/bin/pigz -cf /b/c/cbuild/repository/buildbot_archive/clapper-release/R64-10168.0.0/debug.tgz debug in /b/c/cbuild/repository/chroot/build/clapper/usr/lib
tar: debug/usr/bin: file changed as we read it
11:52:23: WARNING: CreateTarball: tar: source modification time changed (see crbug.com/547055), retrying once
11:52:23: INFO: RunCommand: sudo -n 'CROS_CACHEDIR=/b/c/cbuild/repository/.cache' 'CROS_SUDO_KEEP_ALIVE=unknown' -- tar --exclude debug/usr/local/build/autotest --exclude debug/tests --sparse -I /usr/bin/pigz -cf /b/c/cbuild/repository/buildbot_archive/clapper-release/R64-10168.0.0/debug.tgz debug in /b/c/cbuild/repository/chroot/build/clapper/usr/lib
tar: debug/usr/bin: file changed as we read it

UnitTest:
Pending 30/55, Building 10/17, [Time 11:51:48 | Elapsed 6m34.0s | Load 88.28 76.86 46.79]
...
Completed chromeos-base/google-breakpad-2017.11.14.143122-r133 (in 6m7.4s)
Pending 29/55, Building 10/16, [Time 11:51:49 | Elapsed 6m34.7s | Load 88.28 76.86 46.79]
Started chromeos-base/chromeos-installer-0.0.2-r2916 (logged in /tmp/chromeos-installer-0.0.2-r2916-aa1koT)
Completed chromeos-base/chromeos-config-tools-0.0.2-r787 (in 0m40.5s)
Pending 28/55, Building 10/16, [Time 11:52:29 | Elapsed 7m14.5s | Load 65.7 72.66 46.66]
Owner: ----
Status: Untriaged
This shouldn't be a semenzato problem.

Dropping it into our triage queue.
Sign in to add a comment