Page MenuHomePhabricator

`arc land` shows only part of the error that causes the final squash to fail
Closed, InvalidPublic

Description

When running arc land and it needs to do a squash, the creation of the commit can be prevented by the pre-commit hook of the git repo. Arcanist shows only part of the stderr though, assuming a large number of stderr lines means there are more than one errors and there is no point in spamming the user with them, but this is not always the case. There can be a single error but with a lot of context info printed at the beginning, in which case it's difficult to figure out what's even happening, as the relevant part is hidden because it's at the end. When this happens, it's difficult to figure out how to recover. See below an example:

$ arc land --onto master --trace
 ARGV  '/usr/local/Cellar/arcanist/HEAD-3b6b523/libexec/bin/../scripts/arcanist.php' 'land' '--onto' 'master' '--trace'
 LOAD  Loaded "phutil" from "/usr/local/Cellar/arcanist/HEAD-3b6b523/libphutil/src".
 LOAD  Loaded "arcanist" from "/usr/local/Cellar/arcanist/HEAD-3b6b523/libexec/src".
[...]
>>> [15] <exec> $ git log --oneline 'origin/master'..'dd16d0bf4f7132b8629d381426bb085c671b069e' --
<<< [15] <exec> 27,888 us
These commits will be landed:

[... shows a bunch of commits]

>>> [16] <exec> $ git rev-parse HEAD
<<< [16] <exec> 11,081 us
>>> [17] <exec> $ git rev-parse --abbrev-ref HEAD
<<< [17] <exec> 10,257 us
>>> [18] <exec> $ git checkout 'synth' --
<<< [18] <exec> 50,535 us
>>> [19] <exec> $ git rev-parse 'HEAD'
<<< [19] <exec> 11,714 us
>>> [20] <exec> $ git merge-base 'origin/master' 'dd16d0bf4f7132b8629d381426bb085c671b069e'
<<< [20] <exec> 14,075 us
>>> [21] <exec> $ git log --first-parent --format=medium 'd0c5a4723eefd3a4f9c744c522f478ce641ee365'..'dd16d0bf4f7132b8629d381426bb085c671b069e'
<<< [21] <exec> 15,014 us
>>> [22] <conduit> differential.query() <bytes = 187>
>>> [23] <http> https://DOMAIN/api/differential.query
<<< [23] <http> 68,838 us
<<< [22] <conduit> 69,098 us
>>> [24] <conduit> differential.getcommitmessage() <bytes = 195>
>>> [25] <http> https://DOMAIN/api/differential.getcommitmessage
<<< [25] <http> 89,391 us
<<< [24] <conduit> 89,729 us
Landing revision 'D111: Run it 1000.4% faster...
>>> [26] <conduit> harbormaster.querybuildables() <bytes = 264>
>>> [27] <http> https://DOMAIN/api/harbormaster.querybuildables
<<< [27] <http> 57,796 us
<<< [26] <conduit> 58,135 us
 BUILDS PASSED  Harbormaster builds for the active diff completed successfully.
>>> [28] <exec> $ git checkout 'origin/master' --
<<< [28] <exec> 75,258 us
>>> [29] <exec> $ git log -n1 --format=%aD%n%an%n%ae 'dd16d0bf4f7132b8629d381426bb085c671b069e' --
<<< [29] <exec> 11,912 us
>>> [30] <exec> $ git merge --no-stat --no-commit --ff --squash -- 'dd16d0bf4f7132b8629d381426bb085c671b069e'
<<< [30] <exec> 79,614 us
>>> [31] <exec> $ git diff --no-ext-diff HEAD --
<<< [31] <exec> 32,181 us
>>> [32] <exec> $ git commit --author 'USER <EMAIL>' --date 'Mon, 22 May 2017 11:23:55 +0200' -F '/private/var/folders/j2/h20h8wdx0_zbsphlmbg5_wnc0000gn/T/3b8zwunfp4cgc8g8/75371-HVS8l4' --
<<< [32] <exec> 311,067 us
>>> [33] <exec> $ git checkout 'synth' --
<<< [33] <exec> 63,748 us
>>> [34] <exec> $ git reset --hard 'dd16d0bf4f7132b8629d381426bb085c671b069e' --
<<< [34] <exec> 43,083 us
>>> [35] <exec> $ git submodule update --init --recursive
<<< [35] <exec> 138,777 us

[2017-05-22 11:14:51] EXCEPTION: (CommandException) Command failed with error #1!
COMMAND
git commit --author 'USER <EMAIL>' --date 'Mon, 22 May 2017 11:23:55 +0200' -F '/private/var/folders/j2/h20h8wdx0_zbsphlmbg5_wnc0000gn/T/3b8zwunfp4cgc8g8/75371-HVS8l4' --

STDOUT
(empty)

STDERR
[... bunch of lines which show the error context]
2... (1,376 more bytes) ... at [<phutil>/src/future/exec/ExecFuture.php:369]
arcanist(), phutil()
  #0 ExecFuture::resolvex() called at [<arcanist>/src/repository/api/ArcanistRepositoryAPI.php:406]
  #1 ArcanistRepositoryAPI::execxLocal(string, string, string, TempFile) called at [<arcanist>/src/land/ArcanistGitLandEngine.php:202]
  #2 ArcanistGitLandEngine::updateWorkingCopy() called at [<arcanist>/src/land/ArcanistGitLandEngine.php:29]
  #3 ArcanistGitLandEngine::execute() called at [<arcanist>/src/workflow/ArcanistLandWorkflow.php:296]
  #4 ArcanistLandWorkflow::run() called at [<arcanist>/scripts/arcanist.php:394]

Event Timeline

What behavior would you expect arc to have if git commit ... produces 5GB of output (hypothetically, from a hook which prints 2.5GB of header and footer context and puts the important part in the middle)?

The same as what you do with any tool which produces 5GB of output: wonder what happened, then try again and redirect the output to a file and deal with it. Currently the user has to run manually the steps printed when using --trace, and then they will get to that 5GB output anyway.

Maybe --trace could also enable the show-entire-stderr behavior.

I don't think that's a very desirable behavior.

In any case, this isn't a bug: it's an explicit, intended behavior.

Feel free to fork arc if you'd prefer a different behavior.

Arcanist hides part of the stderr to prevent console spam. But what problem does this fix exactly? How is it a problem that 5GB of output are printed to stderr? The way I see it, if the tool called by arc prints a lot of info to stderr, it should be assumed it is printed for a good reason, be it 1KB or 5PB.

If you think the stdout-hiding is not a problem, it means we should stop using the pre-commit git hook? What should we use instead?

Please use Conpherence or Ponder if you have questions about Phabricator administration and options.

The error truncating behavior affects also Diffusion > R > Status, where only part of the stderr is shown, making it impossible to debug the problem without hacking Phabricator:

ab@phabricator-1-vm:/opt/bitnami$ diff apps/phabricator/libphutil/src/future/exec/CommandException.php.original apps/phabricator/libphutil/src/future/exec/CommandException.php
59c59
<     $limit = 1000;
---
>     $limit = 1000000000;

@aleb, if you like to continue discussion of this please use the appropriate channels, as @chad suggested above (at the time, they were Conpherence and Ponder, but the appropriate channel is now the community forum -- see: Discourse).