I think this is the result of https://chromium-review.googlesource.com/c/581494/ , which looks like it doesn't do what I had hoped it would do.

I'm reverting this for now. 

https://chromium-review.googlesource.com/c/585581 might be an okay way forward, possibly if we modify that to log something if the setup fails.

QQ: Why do we care that "git cl upload" includes this? Is the objection that it's ugly?

Suppressing what a system is doing is a great way to have obscure failures. If the system needs to bootstrap its CIPD packages (BTW, the *first* time it's run), it should display what it's doing so that if something goes wrong, we can observe what the failure was and its context.

This should only be displayed the first time the repository is sync'd. If it's happening every time you call "git cl upload", that's a bug. Is this the case?

If not, I think it's perfectly reasonable to display this output. So long as "depot_tools" is expected to take the initiative and self-update, tool invocations may/will include self updates.

I'd also like to know why this is a "pretty bad regression". Regression to what? Why the "serious" severity? Is displaying operational output something that we strive to avoid doing? Is this impacting something such as a build system or developer productivity?

If the problem is unsolicited logs, we can trivially include a message: "your toolchain is out of date, updating...". It seems like we want implicit bootstraps for arbitrary tooling that automatically update when run, work on every OS, are safe to run in parallel, and only display logs on errors, but can display all back context logs on error. This will take a lot of engineering hours to achieve and possibly some breakages since it affects really core infrastructure scripts.

Alternatively, we can tolerate the once-in-a-while blob of messages and spend time on things that are more impactful.

I believe Nico strongly holds the opinion that tools should be silent by default when everything runs successfully, and I also strongly hold this opinion).

So, yes, I think we should strive to avoid operational/informational output.

I think Ninja is the model citizen in this regard. When run interactively, it produces essentially no output unless something fails. (And, I actually do prefer the "repeatedly updated one line of output" model to the "nothing at all" model for anything that takes a non-zero amount of time.)

This is particularly important when there might be output that you *do* need to see, like warnings or errors, that would otherwise be interspersed with output that you normally *don't* need to see (like unrelated debugging information).

I do certainly think that we should log things when failures do happen, and I do think it makes sense to have different verbose/debugging modes to get the output when you want it.

In fact, I think pretty much my first significant task on the team long, long ago was to rewrite Chromium's run-webkit-tests harness so that it stopped logging so much stuff by default, because it was impossible to actually tell what was going on or debug problems, and this was a stark contrast to WebKit's version, which logged a single "." per test, python unittest-style (though even that became quickly unwieldly).

I do also think this is an important enough issue that it does require careful consideration both of when we want things to update themselves *and* when we want things to log. I would tend to think, for example, that we don't want every vpython or cipd invocation to auto-update all of depot tools. And, there are certainly environments where we probably don't want vpython or cipd to even auto-update themselves (e.g., when vpython or cipd was checked out as part of a pinned revision).

For the record, I also think that both git-cl and particularly gclient *also* log too much by default and we should improve them. I also think that the gtest-based test harnesses are at least as bad in this regard, and I think the way we run run-webkit-tests on the bots (with debug logging on) is equally horrendous.

I think having good output for command line tools is actually quite important and impactful. I know the way ninja works output-wise is at least as delightful as its speed to me. You can compare that to something like make or xcodebuild which just spews out pages of output only to do nothing in the end. It's certainly possible that some (or many) people don't care about this as much as Nico and I do, though.

I have no objection to more meaningful logging. I think framing a preference as a P1 severe regression isn't helpful, though - in this case, we committed a change (revert) that touched scripts with the potential to bring our entire BuildBot fleet offline as a response, when (IMO) the right thing to do here is tweak the UX to be satisfactory in a more targeted and less risky follow-up.

I do apologize for over-reacting. When I landed this change, I coordinated with troopers and monitored BuildBot for a few hours to ensure that it didn't have that sort of impact. It's harrowing to touch these files, and I'd like to do it as infrequently as possible. This sort of thing eats up hours.

After some thought, I think that the right way forward here is:
1) Implement "-log-level" in CIPD so we can tell it to only log problems: https://codereview.chromium.org/2987893002/
2) Update our "depot_tools" usages of CIPD client to specify "-log-level warning", causing them to only log when something has gone bad / wrong.

All of the logs that thakis@ posted in #0 were info-level (I) logs, so (2) will cause them to not display. This prevents the need to dump logs somewhere and simplifies the use of CIPD in these critical scripts without needing to increase their complexity. WDYT?

The following revision refers to this bug:
  https://chromium.googlesource.com/external/github.com/luci/luci-go.git/+/8ccb74d02ea1ac77c1bff3a6230d7e8dd2280817

commit 8ccb74d02ea1ac77c1bff3a6230d7e8dd2280817
Author: dnj <dnj@chromium.org>
Date: Wed Jul 26 19:50:00 2017

[cipd] Enable specific log level.

Add a flag to CIPD client subcommand invocations that explicitly sets
the logging level. This is more precise than "-verbose", and can be used
to suppress INFO-level logs in situations where users don't want to see
them.

BUG= chromium:748651 
TEST=local
R=dpranke@chromium.org, vadimsh@chromium.org

Review-Url: https://codereview.chromium.org/2987893002

[modify] https://crrev.com/8ccb74d02ea1ac77c1bff3a6230d7e8dd2280817/cipd/client/cli/main.go

The following revision refers to this bug:
  https://chromium.googlesource.com/infra/infra/+/cfa0b2b09b504d1626b01c9317e6ad3bf4067b03

commit cfa0b2b09b504d1626b01c9317e6ad3bf4067b03
Author: Dan Jacques <dnj@google.com>
Date: Wed Jul 26 20:07:33 2017

[luci-go] Roll.

infra/go/src/github.com/luci/luci-go:
8ccb74d0 [cipd] Enable specific log level.
f4e9bd5a isolate: Finalize the isolate in UploadTracker
4f004b9a isolate: move creation of isolate into UploadTracker
a5a0dde2 isolate: Move uploadTracker into its own file
36932d3d isolate: Split UploadDeps into smaller chunks
36482f34 isolate: create a struct to hold upload state
ed1cc5c5 Milo: Fix console table alignment
9bc2ed3a isolate: pull uploading of deps out of exparchive main.
7a7fc567 Plumb through blacklist flag in exparchive.
6d809e0e Reuse blacklisting code in exp_archive.
02528b08 Add gitiles OWNERS.
40d91be4 gitiles: add Refs API.
c4abe79e Improve gitiles.Log.
8ffe319b isolate: (refactor) extract blacklisting into common package
3cafc370 Milo: Change console commit text format
16c2c39b Milo console importer: fix small bug
f754e176 [milo] get console in working shape.
c4c760ed Make gitiles calls as Self instead of Anon
09620964 Milo: Store console defs as their own entities
52e6f769 [milo] Add an (uncached) method to get console rows.
12910406 scheduler: Move IsJobOwner to acl package.
4b08c484 Add manifest links and hack to index on revision.
746d72c6 Milo: Fix ?limit= param
c73a0179 isolate: clean up some path handling in directory walking code.
b6f50320 [milo] initial call to get git history
33f9af61 Milo pubsub: Don't decode properties out of parameters
1ecc1348 milo: Add warmup paths
e3f06de0 Milo: Fix project importer so it doesn't error out on a bad config
6b67e981 Milo: Create build summaries for buildbot in the pubsub pipeline
2cc44f95 Fix copyright header presubmit
28c33775 [milo] add milo version to page base
5f9d6a65 [milo] remove remote_api
dabbfe02 [milo] add switch and switch-dev commands.
a3c9edc7 [milo] add warmup service to modules
3fa2a52a [milo] Refactor all html knowledge out of backends.
4bfe11eb Milo: Move buildbucket pubsub sub from buildbucket project to milo project
915ce57f Move gitiles module from milo to common/api.
b783a30c Gitiles: commit's author and committer are the same structures.
01276bd0 [milo] make logs uploadable and also remove it from up-dev.
2d017314 Update apache2 license header to newer format.
bad1bfc9 [milo] remove linkBase and calculate links directly.
6553a52a Flesh out the mmutex binary wrapper and test for existence of
lockfile

TBR=vadimsh@chromium.org
BUG= chromium:748651 
TEST=None

Change-Id: Ie386c2139289e64f50e7029ceb704cd0d21719ce
Reviewed-on: https://chromium-review.googlesource.com/587567
Reviewed-by: Daniel Jacques <dnj@chromium.org>
Commit-Queue: Daniel Jacques <dnj@chromium.org>

[modify] https://crrev.com/cfa0b2b09b504d1626b01c9317e6ad3bf4067b03/DEPS

I think switching to -warning sounds fine. I'm going to reassign this to you; I'd guess we still have to push a new cipd binary and adjust the scripts?

That is correct. I'll get on that right now.

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/tools/build/+/ccf1d9201787a2282a54eb2b3c128b303e15939c

commit ccf1d9201787a2282a54eb2b3c128b303e15939c
Author: Dan Jacques <dnj@google.com>
Date: Thu Jul 27 08:57:12 2017

[cipd_bootstrap_v2] Bump staging CIPD version.

Bump the staging CIPD version to
e2a98b41adb3403b5b7771c4101b42a55dc2dd9e.

BUG= chromium:748651 
TEST=None
R=iannucci@chromium.org

Change-Id: I400274e892720904335fc3b4712d3d7334275f23
Reviewed-on: https://chromium-review.googlesource.com/589008
Reviewed-by: Robbie Iannucci <iannucci@chromium.org>
Commit-Queue: Daniel Jacques <dnj@chromium.org>

[modify] https://crrev.com/ccf1d9201787a2282a54eb2b3c128b303e15939c/scripts/slave/cipd_bootstrap_v2.py

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/tools/build/+/318fb5cb80725e503472d74b35c9ff178b645d2b

commit 318fb5cb80725e503472d74b35c9ff178b645d2b
Author: Dan Jacques <dnj@google.com>
Date: Thu Jul 27 12:56:39 2017

[cipd_bootstrap_v2] Bump prod CIPD version.

Bump production CIPD version to:
e2a98b41adb3403b5b7771c4101b42a55dc2dd9e.

BUG= chromium:748651 
TEST=canary

Change-Id: I5cd224ff3124ea7dee6084b4d9f0fe20f0464862
Reviewed-on: https://chromium-review.googlesource.com/589009
Commit-Queue: Daniel Jacques <dnj@chromium.org>
Reviewed-by: Robbie Iannucci <iannucci@chromium.org>

[modify] https://crrev.com/318fb5cb80725e503472d74b35c9ff178b645d2b/scripts/slave/cipd_bootstrap_v2.py

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/tools/depot_tools/+/18aa2d93ed97e61163fb5795cd3e695f4a73d7c8

commit 18aa2d93ed97e61163fb5795cd3e695f4a73d7c8
Author: Dan Jacques <dnj@google.com>
Date: Thu Jul 27 14:10:33 2017

[cipd] Bump version, log at warning.

Bump the CIPD client version to
e2a98b41adb3403b5b7771c4101b42a55dc2dd9e. This version inculdes support
for the "-log-level" flag.

Update CIPD bootstrap scripts and tool installation scripts to log at
warning level, so that standard operation doesn't produce any logs.

BUG= chromium:748651 
TEST=canary
  - Tested this CIPD version on canary waterfall successfully.
  - Tested "gclient" bootstrap and "vpython" / "led" on Windows system,
    no output and works.
  - Tested "vpython" / "led" on OSX system, no output and works.

Change-Id: Iae316908283c43c504f293aafdf897df83dccf8d
Reviewed-on: https://chromium-review.googlesource.com/588889
Reviewed-by: Robbie Iannucci <iannucci@chromium.org>
Commit-Queue: Daniel Jacques <dnj@chromium.org>

[modify] https://crrev.com/18aa2d93ed97e61163fb5795cd3e695f4a73d7c8/cipd_client_version
[modify] https://crrev.com/18aa2d93ed97e61163fb5795cd3e695f4a73d7c8/bootstrap/win/win_tools.bat
[modify] https://crrev.com/18aa2d93ed97e61163fb5795cd3e695f4a73d7c8/cipd.bat
[modify] https://crrev.com/18aa2d93ed97e61163fb5795cd3e695f4a73d7c8/cipd
[modify] https://crrev.com/18aa2d93ed97e61163fb5795cd3e695f4a73d7c8/cipd_bin_setup.bat
[modify] https://crrev.com/18aa2d93ed97e61163fb5795cd3e695f4a73d7c8/cipd.ps1
[modify] https://crrev.com/18aa2d93ed97e61163fb5795cd3e695f4a73d7c8/cipd_bin_setup.sh

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/tools/depot_tools/+/9f9d82ac944eb5146230dc9ca43a05608148f7d9

commit 9f9d82ac944eb5146230dc9ca43a05608148f7d9
Author: Daniel Jacques <dnj@chromium.org>
Date: Thu Jul 27 14:21:45 2017

Revert "[cipd] Bump version, log at warning."

This reverts commit 18aa2d93ed97e61163fb5795cd3e695f4a73d7c8.

Reason for revert: <INSERT REASONING HERE>

Original change's description:
> [cipd] Bump version, log at warning.
> 
> Bump the CIPD client version to
> e2a98b41adb3403b5b7771c4101b42a55dc2dd9e. This version inculdes support
> for the "-log-level" flag.
> 
> Update CIPD bootstrap scripts and tool installation scripts to log at
> warning level, so that standard operation doesn't produce any logs.
> 
> BUG= chromium:748651 
> TEST=canary
>   - Tested this CIPD version on canary waterfall successfully.
>   - Tested "gclient" bootstrap and "vpython" / "led" on Windows system,
>     no output and works.
>   - Tested "vpython" / "led" on OSX system, no output and works.
> 
> Change-Id: Iae316908283c43c504f293aafdf897df83dccf8d
> Reviewed-on: https://chromium-review.googlesource.com/588889
> Reviewed-by: Robbie Iannucci <iannucci@chromium.org>
> Commit-Queue: Daniel Jacques <dnj@chromium.org>

TBR=iannucci@chromium.org,dnj@chromium.org

Change-Id: Ia611c1aeb204c609ff3469076b8256c54e702230
No-Presubmit: true
No-Tree-Checks: true
No-Try: true
Bug:  chromium:748651 
Reviewed-on: https://chromium-review.googlesource.com/589527
Reviewed-by: Daniel Jacques <dnj@chromium.org>
Commit-Queue: Daniel Jacques <dnj@chromium.org>

[modify] https://crrev.com/9f9d82ac944eb5146230dc9ca43a05608148f7d9/cipd_client_version
[modify] https://crrev.com/9f9d82ac944eb5146230dc9ca43a05608148f7d9/bootstrap/win/win_tools.bat
[modify] https://crrev.com/9f9d82ac944eb5146230dc9ca43a05608148f7d9/cipd.bat
[modify] https://crrev.com/9f9d82ac944eb5146230dc9ca43a05608148f7d9/cipd
[modify] https://crrev.com/9f9d82ac944eb5146230dc9ca43a05608148f7d9/cipd_bin_setup.bat
[modify] https://crrev.com/9f9d82ac944eb5146230dc9ca43a05608148f7d9/cipd.ps1
[modify] https://crrev.com/9f9d82ac944eb5146230dc9ca43a05608148f7d9/cipd_bin_setup.sh

The following revision refers to this bug:
  https://chromium.googlesource.com/external/github.com/luci/luci-go.git/+/88d9e961390254aa5a732d56f83eef40e25db59e

commit 88d9e961390254aa5a732d56f83eef40e25db59e
Author: dnj <dnj@chromium.org>
Date: Thu Jul 27 14:43:58 2017

[cipd] "selfupdate" command logs at Warning.

Make the "selfupdate" command log at "Warning" level by default.

BUG= chromium:748651 
TEST=local
  - Ran locally, did not show any logs on success.

R=iannucci@chromium.org, vadimsh@chromium.org

Review-Url: https://codereview.chromium.org/2986963002

[modify] https://crrev.com/88d9e961390254aa5a732d56f83eef40e25db59e/cipd/client/cli/main.go

The following revision refers to this bug:
  https://chromium.googlesource.com/infra/infra/+/739b269fcb685920924571a7668ab517ae562ed6

commit 739b269fcb685920924571a7668ab517ae562ed6
Author: Robert Iannucci <iannucci@chromium.org>
Date: Thu Jul 27 16:46:25 2017

Roll luci-go

infra/go/src/github.com/luci/luci-go:
88d9e961 [cipd] "selfupdate" command logs at Warning.
b8f38ac1 gitiles: go back to QueryEscape because url.PathEscape is not in Go1.6.
29440f13 isolate: Move json dumping back into exparchive main
1bb9e0cd isolate: Pull isolated file handling into its own type.
7869f7eb Pass a Writer to Finalize for JSON dumping.
b1e3f585 Milo: Show accurate pending build numbers for builder view.
d3bd4203 Make mmutex actually acquire and release file locks

R=dnj@chromium.org

Bug:  748651 
Change-Id: I5e7a645a8b53ea737301a59534fe105d2a6202ae
Reviewed-on: https://chromium-review.googlesource.com/589430
Commit-Queue: Daniel Jacques <dnj@chromium.org>
Reviewed-by: Daniel Jacques <dnj@chromium.org>

[modify] https://crrev.com/739b269fcb685920924571a7668ab517ae562ed6/DEPS

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/tools/build/+/533f4c5b550baddc23be31c4d5af346e94a1b613

commit 533f4c5b550baddc23be31c4d5af346e94a1b613
Author: Dan Jacques <dnj@google.com>
Date: Fri Jul 28 08:56:30 2017

[cipd_bootstrap_v2] Bump staging CIPD version.

Bump staging CIPD version to:
b482bfa19d3fa79b4b40dd5ac7a34479052e3df1

TBR=iannucci@chromium.org
BUG= chromium:748651 
TEST=None

Add ChromeOS amd64 Chromium Goma Canary.

Bug: 746810
Change-Id: I38a05bcd636a06c0c515312cccb8a9f57e659308
Reviewed-on: https://chromium-review.googlesource.com/584559
Reviewed-by: Shinya Kawanaka <shinyak@chromium.org>
Reviewed-by: Takuto Ikuta <tikuta@google.com>
Reviewed-by: Dirk Pranke <dpranke@chromium.org>
Commit-Queue: Yoshisato Yanagisawa <yyanagisawa@chromium.org>
Reviewed-on: https://chromium-review.googlesource.com/590450
Reviewed-by: Daniel Jacques <dnj@chromium.org>
Reviewed-by: Robbie Iannucci <iannucci@chromium.org>
Commit-Queue: Daniel Jacques <dnj@chromium.org>

[modify] https://crrev.com/533f4c5b550baddc23be31c4d5af346e94a1b613/scripts/slave/cipd_bootstrap_v2.py

The following revision refers to this bug:
  https://chrome-internal.googlesource.com/infra/puppet/+/47aab09ee3399cc0071ad6f5ba33a4b791b9e1d6

commit 47aab09ee3399cc0071ad6f5ba33a4b791b9e1d6
Author: Dan Jacques <dnj@google.com>
Date: Fri Jul 28 09:21:48 2017

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/tools/build/+/e0454629a4286d803c93a71b56aa1a988e25944a

commit e0454629a4286d803c93a71b56aa1a988e25944a
Author: Dan Jacques <dnj@google.com>
Date: Fri Jul 28 09:26:10 2017

[cipd_bootstrap_v2] Bump CIPD stable.

Bump CIPD stable to staging version:
b482bfa19d3fa79b4b40dd5ac7a34479052e3df1

TBR=iannucci@chromium.org
BUG= chromium:748651 
TEST=None

Change-Id: I007cee9bd1fd42f81388967133b5fe423edaca00
Reviewed-on: https://chromium-review.googlesource.com/590248
Reviewed-by: Daniel Jacques <dnj@chromium.org>
Reviewed-by: Robbie Iannucci <iannucci@chromium.org>
Commit-Queue: Daniel Jacques <dnj@chromium.org>

[modify] https://crrev.com/e0454629a4286d803c93a71b56aa1a988e25944a/scripts/slave/cipd_bootstrap_v2.py

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/tools/depot_tools/+/eb1feb9090baab435e8243ee04d28cb36325e7fc

commit eb1feb9090baab435e8243ee04d28cb36325e7fc
Author: Dan Jacques <dnj@google.com>
Date: Fri Jul 28 11:09:35 2017

[cipd] Bump version, log at warning (#2).

Bump the CIPD client version to
b482bfa19d3fa79b4b40dd5ac7a34479052e3df1. This version inculdes support
for the "-log-level" flag.

Update CIPD bootstrap scripts and tool installation scripts to log at
warning level, so that standard operation doesn't produce any logs.

This version differs from the previous CL in that the "selfupdate"
command no longer uses "-log-level". This fixes an issue where the
current CIPD, which doesn't support "-log-level", is given the flag
prior to actually updating to a version that does.

BUG= chromium:748651 
TEST=canary
  - Tested this CIPD version on canary waterfall successfully.

Change-Id: I69dfe522d890eb307214f18d0467ce921a766446
Reviewed-on: https://chromium-review.googlesource.com/589568
Commit-Queue: Daniel Jacques <dnj@chromium.org>
Reviewed-by: Robbie Iannucci <iannucci@chromium.org>

[modify] https://crrev.com/eb1feb9090baab435e8243ee04d28cb36325e7fc/cipd_client_version
[modify] https://crrev.com/eb1feb9090baab435e8243ee04d28cb36325e7fc/bootstrap/win/win_tools.bat
[modify] https://crrev.com/eb1feb9090baab435e8243ee04d28cb36325e7fc/cipd
[modify] https://crrev.com/eb1feb9090baab435e8243ee04d28cb36325e7fc/cipd_bin_setup.bat
[modify] https://crrev.com/eb1feb9090baab435e8243ee04d28cb36325e7fc/cipd.ps1
[modify] https://crrev.com/eb1feb9090baab435e8243ee04d28cb36325e7fc/cipd_bin_setup.sh

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/tools/depot_tools/+/5aeeb72c3343c0a9a95efa4c4dc7564ba3462a6a

commit 5aeeb72c3343c0a9a95efa4c4dc7564ba3462a6a
Author: Dan Jacques <dnj@google.com>
Date: Fri Jul 28 13:33:40 2017

[bootstraps] Sync at gclient, suppress output (#2)

Have the "update_depot_tools" script also do a CIPD tool sync. This will
ensure that users and systems have access to tooling at sync-time rather
than just-in-time loading them at execution time.

Update the tool boostraps to suppress any sort of syncing logs, if it
does happen. This will ensure that users who execute the tools don't see
unexpected output.

BUG= chromium:748651 
TEST=local
  - Tested on Mac and Windows.

Change-Id: I1aad897d885a07beeac40a372a658681720efd2a
Reviewed-on: https://chromium-review.googlesource.com/591229
Commit-Queue: Daniel Jacques <dnj@chromium.org>
Reviewed-by: Robbie Iannucci <iannucci@chromium.org>

[modify] https://crrev.com/5aeeb72c3343c0a9a95efa4c4dc7564ba3462a6a/update_depot_tools
[modify] https://crrev.com/5aeeb72c3343c0a9a95efa4c4dc7564ba3462a6a/led.bat
[modify] https://crrev.com/5aeeb72c3343c0a9a95efa4c4dc7564ba3462a6a/led
[modify] https://crrev.com/5aeeb72c3343c0a9a95efa4c4dc7564ba3462a6a/vpython.bat
[modify] https://crrev.com/5aeeb72c3343c0a9a95efa4c4dc7564ba3462a6a/vpython
[modify] https://crrev.com/5aeeb72c3343c0a9a95efa4c4dc7564ba3462a6a/tests/gclient_smoketest.py
[modify] https://crrev.com/5aeeb72c3343c0a9a95efa4c4dc7564ba3462a6a/update_depot_tools.bat
[modify] https://crrev.com/5aeeb72c3343c0a9a95efa4c4dc7564ba3462a6a/.gitattributes

This should be (finally) resolved now.

Looks like this is still broken:

C:\src\chrome\src>gclient sync
Bootstrapping cipd client for windows-amd64...
From https://chrome-infra-packages.appspot.com/client?platform=windows-amd64&version=git_revision:5cf65fdf804a9b3f3023f7
9d5b3cab2a88ccd09e
[P16552 09:38:50.274 client.go:907 I] cipd: updating client to infra/tools/cipd/windows-amd64:f889fa330df082ccd5f0ac7f4c
becc7fbbd3ef20 (git_revision:5cf65fdf804a9b3f3023f79d5b3cab2a88ccd09e)
[P8072 09:38:51.008 client.go:270 I] In subdir "git":
[P8072 09:38:51.009 client.go:274 I]   to install:
[P8072 09:38:51.009 client.go:276 I]     infra/git/windows-amd64:4d247679c8d981e360f4932d806bbeeabd1792e7
[P8072 09:38:51.009 client.go:270 I] In subdir "python":
[P8072 09:38:51.009 client.go:274 I]   to install:
[P8072 09:38:51.009 client.go:276 I]     infra/python/cpython/windows-386:ad63cbd3e9fcc5f30e4657a95bd99000ff1716ef
[P8072 09:38:51.013 client.go:1243 I] cipd: resolving fetch URL for infra/git/windows-amd64:4d247679c8d981e360f4932d806b
beeabd1792e7
[P8072 09:38:51.124 storage.go:248 I] cipd: initiating the fetch
[P8072 09:38:51.524 storage.go:215 I] cipd: about to fetch 86.2 Mb
[P8072 09:38:51.524 storage.go:206 I] cipd: fetching - 0%C:\src\chrome\src>gclient sync
Bootstrapping cipd client for windows-amd64...
From https://chrome-infra-packages.appspot.com/client?platform=windows-amd64&version=git_revision:5cf65fdf804a9b3f3023f7
9d5b3cab2a88ccd09e
[P16552 09:38:50.274 client.go:907 I] cipd: updating client to infra/tools/cipd/windows-amd64:f889fa330df082ccd5f0ac7f4c
becc7fbbd3ef20 (git_revision:5cf65fdf804a9b3f3023f79d5b3cab2a88ccd09e)
[P8072 09:38:51.008 client.go:270 I] In subdir "git":
[P8072 09:38:51.009 client.go:274 I]   to install:
[P8072 09:38:51.009 client.go:276 I]     infra/git/windows-amd64:4d247679c8d981e360f4932d806bbeeabd1792e7
[P8072 09:38:51.009 client.go:270 I] In subdir "python":
[P8072 09:38:51.009 client.go:274 I]   to install:
[P8072 09:38:51.009 client.go:276 I]     infra/python/cpython/windows-386:ad63cbd3e9fcc5f30e4657a95bd99000ff1716ef
[P8072 09:38:51.013 client.go:1243 I] cipd: resolving fetch URL for infra/git/windows-amd64:4d247679c8d981e360f4932d806b
beeabd1792e7
[P8072 09:38:51.124 storage.go:248 I] cipd: initiating the fetch
[P8072 09:38:51.524 storage.go:215 I] cipd: about to fetch 86.2 Mb
[P8072 09:38:51.524 storage.go:206 I] cipd: fetching - 0%
[P8072 09:38:53.255 storage.go:206 I] cipd: fetching - 100%
[P8072 09:38:53.255 storage.go:206 I] cipd: fetching - 100%
[P8072 09:38:53.255 client.go:1239 I] cipd: successfully fetched infra/git/windows-amd64:4d247679c8d981e360f4932d806bbee
abd1792e7
[P8072 09:38:53.260 deployer.go:156 I] Deploying infra/git/windows-amd64:4d247679c8d981e360f4932d806bbeeabd1792e7 into c
:\src\depot_tools\win_tools-2_7_6_bin(/git)
[P8072 09:38:53.384 reader.go:289 I] cipd: about to extract 206.7 Mb (5321 files)
[P8072 09:38:53.386 reader.go:326 I] cipd: extracting - 0%
[P8072 09:38:55.387 reader.go:326 I] cipd: extracting - 15%
[P8072 09:38:57.389 reader.go:326 I] cipd: extracting - 34%
[P8072 09:38:59.391 reader.go:326 I] cipd: extracting - 55%
[P8072 09:39:01.400 reader.go:326 I] cipd: extracting - 79%
[P8072 09:39:03.403 reader.go:326 I] cipd: extracting - 82%
[P8072 09:39:05.405 reader.go:326 I] cipd: extracting - 87%
[P8072 09:39:07.406 reader.go:326 I] cipd: extracting - 92%
[P8072 09:39:09.408 reader.go:326 I] cipd: extracting - 97%
[P8072 09:39:10.073 reader.go:326 I] cipd: extracting - 100%

[P8072 09:38:53.255 storage.go:206 I] cipd: fetching - 100%
[P8072 09:38:53.255 storage.go:206 I] cipd: fetching - 100%
[P8072 09:38:53.255 client.go:1239 I] cipd: successfully fetched infra/git/windows-amd64:4d247679c8d981e360f4932d806bbee
abd1792e7
[P8072 09:38:53.260 deployer.go:156 I] Deploying infra/git/windows-amd64:4d247679c8d981e360f4932d806bbeeabd1792e7 into c
:\src\depot_tools\win_tools-2_7_6_bin(/git)
[P8072 09:38:53.384 reader.go:289 I] cipd: about to extract 206.7 Mb (5321 files)
[P8072 09:38:53.386 reader.go:326 I] cipd: extracting - 0%
[P8072 09:38:55.387 reader.go:326 I] cipd: extracting - 15%
[P8072 09:38:57.389 reader.go:326 I] cipd: extracting - 34%
[P8072 09:38:59.391 reader.go:326 I] cipd: extracting - 55%
[P8072 09:39:01.400 reader.go:326 I] cipd: extracting - 79%
[P8072 09:39:03.403 reader.go:326 I] cipd: extracting - 82%
[P8072 09:39:05.405 reader.go:326 I] cipd: extracting - 87%
[P8072 09:39:07.406 reader.go:326 I] cipd: extracting - 92%
[P8072 09:39:09.408 reader.go:326 I] cipd: extracting - 97%
[P8072 09:39:10.073 reader.go:326 I] cipd: extracting - 100%

(This is on a Windows box that I last synced early-ish last week, so if the fix requires me to be synced up, it's likely fixed after all, in that case please close again.)


Re comment 4 / 5: I'd like to say a few more words on "why care". I don't think this is "Nico thinks".

Chromium's core principles are listed here, and are a core tenet of what "chrome" believes: https://www.chromium.org/developers/core-principles Among those is "simplicity", which contains things like "We try not to interrupt users with questions they are not prepared to answer, or get in their way with cumbersome modal dialog boxes that they didn't ask for." This sense of aesthetic does also extend to chrome's tooling for developers. We treat the attention of developers with respect and strive to not print things that are useless most of the time. (It's fine to add logging temporarily while you debug something.) This too isn't something that "Nico thinks" but also something that's codified in the style guide: https://chromium.googlesource.com/chromium/src/+/master/styleguide/c++/c++.md#Logging (And no, that section wasn't written by me).

As Dirk says, the build is one example of this: Ninja's output is a single line as long as no build step produces output. No build step is allowed to produce output per policy -- that's also one of the reasons why we build with warnings-as-errors: If a warning is important, it should be a hard blocker; if it isn't, it shouldn't produce ultimately meaningless output. It's not just the build, but also e.g. the test running which replaces gtest's noisy default output with one line per test (and more information if it fails), gn follows that philosophy, etc.

And these ideas aren't new-with-chrome either, the Unix Philosophy contains some of the same: http://www.faqs.org/docs/artu/ch01s06.html("rule of silence")


dpranke's comment 5 is right on, but I wanted to stress that this isn't just me (and him) having this opinion, it's really something that many people on the team believe, and have believed since chrome's early days.

One sync is required to bring the scripts and CIPD up to date. Future invocations will pick up the change and no longer show the output.

We have plans for good tooling and well-designed deployment that meets the standards of Chrome, and I fully subscribe to those standards. Right now, depot_tools is not (nor has ever been) sufficient at any of these. "depot_tools" is a technical debt goldmine that users, bots, systems, developers, and build processes have bought heavily into, and we can't move past that until we've unravelled that mess. Chipping away at depot_tools is really expensive, both in terms of time and risk.

#23 is a good illustration of this challenge: now that you have become aware of the output, you re-opened this bug in response to seeing the basic Git/Python bootstrap logging. However, at no point in time did the Windows Git/Python bootstrapping process *not* show a lot of verbose output. Prior to a patch that I landed last month, an equivalent number of lines were shown downloading and unpacking a ZIP file during bootstrapping. Now those lines show CIPD doing something similar. They are both equivalently verbose, but now there is a P1 demand to resolve it despite 6+ years of the previous verbose output being the status quo.

The reason for this problem is well understood: we're patching over a bad system, depot_tools, which embodies a risky and cumbersome tool deployment model. Nobody is arguing that "depot_tools" is good tooling, or that its deployment mechanisms are well-designed. This entire dialogue started because dpranke@ wanted logging at sync time rather than tool invocation time, and I offered to help. The change that I introduced caused this issue, too much logging at sync time, and extended to a rework of how CIPD logging is done in depot_tools.

IMO this is a cost/benefit problem. This cost me a lot of hours to resolve this, over a series of days, comments, and several risky patches. At the end of the day, we have a slightly nicer user experience (once ever ~month, fewer logs) and are barely any closer to fixing depot_tools. If these small regressions are unacceptable, perhaps I just don't have enough capital to pay off this sort of technical debt.

I'm still seeing this on the same windows box mentioned above, after having synced last time:

C:\src\chrome\src>gclient sync
[P30448 16:45:53.495 client.go:907 I] cipd: updating client to infra/tools/cipd/windows-amd64:9ab9e54d047cfb93ed67da3e29
916de589e422d6 (git_revision:b482bfa19d3fa79b4b40dd5ac7a34479052e3df1)
[P30448 16:45:53.616 storage.go:248 I] cipd: initiating the fetch
[P30448 16:45:54.014 storage.go:215 I] cipd: about to fetch 10.3 Mb
[P30448 16:45:54.014 storage.go:206 I] cipd: fetching - 0%
[P30448 16:45:54.252 storage.go:206 I] cipd: fetching - 100%
[P30448 16:45:54.253 storage.go:206 I] cipd: fetching - 100%
[P30448 16:45:54.338 fs.go:411 W] fs: failed to cleanup trashed file - remove c:\src\depot_tools\.cipd_client_cache\tras
h\BFTmpclV0DDD: Access is denied.
[P30448 16:45:54.555 fs.go:364 I] fs: cleaning up trash (1 items)...
[P30448 16:45:54.556 fs.go:411 W] fs: failed to cleanup trashed file - remove c:\src\depot_tools\.cipd_client_cache\tras

Maybe this is still not fixed on Windows?

Some of what you're seeing actual warnings, which is good. The rest suggests that you're using an old CIPD client, as the one pinned in "depot_tools" defaults to warning-level logs. Maybe it's not updating properly?

> Some of what you're seeing actual warnings, which is good.

No, see above. Things are either important, then they should be errors, or they aren't, then they shouldn't be printed ;-)

> depot_tools out of date

My non-src-pinned depot tools is at

commit 932ee3f5b74d7cfabfcfee22c6efc86f3b7b3886
Author: recipe-roller <recipe-roller@chromium.org>
Date:   Wed Aug 9 12:59:50 2017 -0700