Re: [PATCH] travis-ci: build Git during the 'script' phase

[Jeff King]

On Sun, Jan 14, 2018 at 11:43:05AM +0100, SZEDER Gábor wrote:

> On Sat, Jan 13, 2018 at 11:54 AM, Jeff King  wrote:
> > I think there's also a similar feature to include timings for each fold,
> > which might be worth pursuing.
> 
> If you look for 'travis_time' in the raw log, you'll find lines like
> these:
> 
>   travis_time:start:01ccbe40
>   $ some-command
>   ... and its output ...
>   
> travis_time:end:01ccbe40:start=1515840453305552968,finish=1515840471960386859,duration=18654833891
> 
> So it seems doable, but we'll have to do the timekeeping ourselves.
> Running 'time $cmd' is much easier, but that time won't be displayed
> next to the folds, of course.
> Do we really care that much?

I don't care that much (and I wasn't actually planning to push the fold
stuff into a patch, but would instead leave it to you people who were
already working on improving the ci script output ;) ).

Apparently there are exportable bash functions for all of this:

  http://www.garbers.co.za/2017/11/01/code-folding-and-timing-in-travis-ci/

but they're not part of the official API. So relying on them may be even
more questionable than relying on the travis_fold syntax.

-Peff

Re: [PATCH] travis-ci: build Git during the 'script' phase

[Jeff King]

On Sun, Jan 14, 2018 at 11:37:07AM +0100, SZEDER Gábor wrote:

> > +fold_cmd () {
> > +   local name=$1; shift
> > +   fold "$name"
> > +   "$@"
> > +   local ret=$?
> > +   unfold "$name"
> > +   return $ret
> > +}
> 
> We don't have to fiddle with the return value, because we run (almost
> all of) our build scripts with 'set -e', i.e. if the command fails then
> the script will exit immediately.

Yeah, that's probably enough for our simple scripts, though I have been
bit by "set -e" vagaries before (e.g., calling the function inside a
conditional block).

-Peff

Re: [PATCH] travis-ci: build Git during the 'script' phase

[SZEDER Gábor]

On Sat, Jan 13, 2018 at 11:54 AM, Jeff King  wrote:
> I think there's also a similar feature to include timings for each fold,
> which might be worth pursuing.

If you look for 'travis_time' in the raw log, you'll find lines like
these:

  travis_time:start:01ccbe40
  $ some-command
  ... and its output ...
  
travis_time:end:01ccbe40:start=1515840453305552968,finish=1515840471960386859,duration=18654833891

So it seems doable, but we'll have to do the timekeeping ourselves.
Running 'time $cmd' is much easier, but that time won't be displayed
next to the folds, of course.
Do we really care that much?


Gábor

Re: [PATCH] travis-ci: build Git during the 'script' phase

[SZEDER Gábor]

On Sat, Jan 13, 2018 at 11:32 AM, Jeff King  wrote:
> On Fri, Jan 12, 2018 at 02:32:54PM +0100, SZEDER Gábor wrote:
>
>> That's the just beginning of a looong list of executed test scripts in
>> seemingly pseudo-random order.  IMHO that's very rarely the interesting
>> part; I, for one, am only interested in that list in exceptional cases,
>> e.g. while tweaking the build dependencies or the 'prove --state=...'
>> options.
>
> Aren't folds supposed to do this? I.e., record all the output but only
> show it to the user if the command exited non-zero.
>
> According to:
>
>   https://blog.travis-ci.com/2013-05-22-improving-build-visibility-log-folds
>
> they auto-fold individual commands _except_ the ones in the script
> section. Is there a way to manually mark folds in the output?
>
> Hmph. I could not find an answer from travis, but googling seems to turn
> up that something like this would work:

Oh.  I did look for something like this in the Travis CI docs, found
nothing and then didn't bother with Google.  Rookie mistake, I know :)

But indeed, have a look at the raw trace log at:

  https://api.travis-ci.org/v3/job/328418291/log.txt

It starts with that "travis_fold:start:..." thing right away.

> diff --git a/ci/lib-travisci.sh b/ci/lib-travisci.sh
> index 07f27c7270..8c830aa3c0 100755
> --- a/ci/lib-travisci.sh
> +++ b/ci/lib-travisci.sh
> @@ -77,6 +77,23 @@ check_unignored_build_artifacts ()
> }
>  }
>
> +fold () {
> +   printf 'travis_fold:start:%s\r' "$1"
> +}
> +
> +unfold () {
> +   printf 'travis_fold:end:%s\r' "$1"
> +}
> +
> +fold_cmd () {
> +   local name=$1; shift
> +   fold "$name"
> +   "$@"
> +   local ret=$?
> +   unfold "$name"
> +   return $ret
> +}

We don't have to fiddle with the return value, because we run (almost
all of) our build scripts with 'set -e', i.e. if the command fails then
the script will exit immediately.

> +
>  # Set 'exit on error' for all CI scripts to let the caller know that
>  # something went wrong.
>  # Set tracing executed commands, primarily setting environment variables
> diff --git a/ci/run-build-and-tests.sh b/ci/run-build-and-tests.sh
> index d3a094603f..12b2590230 100755
> --- a/ci/run-build-and-tests.sh
> +++ b/ci/run-build-and-tests.sh
> @@ -7,8 +7,8 @@
>
>  ln -s $HOME/travis-cache/.prove t/.prove
>
> -make --jobs=2
> -make --quiet test
> +fold_cmd compile make --jobs=2
> +fold_cmd test make --quiet test
>
>  check_unignored_build_artifacts
>
>
> I've queued a CI job to see if this actually works. :)
>
> -Peff

Re: [PATCH] travis-ci: build Git during the 'script' phase

[Jeff King]

On Sat, Jan 13, 2018 at 05:32:56AM -0500, Jeff King wrote:

> According to:
> 
>   https://blog.travis-ci.com/2013-05-22-improving-build-visibility-log-folds
> 
> they auto-fold individual commands _except_ the ones in the script
> section. Is there a way to manually mark folds in the output?
> 
> Hmph. I could not find an answer from travis, but googling seems to turn
> up that something like this would work:
> [...]
> I've queued a CI job to see if this actually works. :)

Indeed it does work:

  https://travis-ci.org/peff/git/jobs/328418291

The rest of the crufty output looks like "set -x" stuff. It might be
worth being less aggressive there.

I think there's also a similar feature to include timings for each fold,
which might be worth pursuing.

-Peff

Re: [PATCH] travis-ci: build Git during the 'script' phase

[Jeff King]

On Fri, Jan 12, 2018 at 02:32:54PM +0100, SZEDER Gábor wrote:

> That's the just beginning of a looong list of executed test scripts in
> seemingly pseudo-random order.  IMHO that's very rarely the interesting
> part; I, for one, am only interested in that list in exceptional cases,
> e.g. while tweaking the build dependencies or the 'prove --state=...'
> options.

Aren't folds supposed to do this? I.e., record all the output but only
show it to the user if the command exited non-zero.

According to:

  https://blog.travis-ci.com/2013-05-22-improving-build-visibility-log-folds

they auto-fold individual commands _except_ the ones in the script
section. Is there a way to manually mark folds in the output?

Hmph. I could not find an answer from travis, but googling seems to turn
up that something like this would work:

diff --git a/ci/lib-travisci.sh b/ci/lib-travisci.sh
index 07f27c7270..8c830aa3c0 100755
--- a/ci/lib-travisci.sh
+++ b/ci/lib-travisci.sh
@@ -77,6 +77,23 @@ check_unignored_build_artifacts ()
}
 }
 
+fold () {
+   printf 'travis_fold:start:%s\r' "$1"
+}
+
+unfold () {
+   printf 'travis_fold:end:%s\r' "$1"
+}
+
+fold_cmd () {
+   local name=$1; shift
+   fold "$name"
+   "$@"
+   local ret=$?
+   unfold "$name"
+   return $ret
+}
+
 # Set 'exit on error' for all CI scripts to let the caller know that
 # something went wrong.
 # Set tracing executed commands, primarily setting environment variables
diff --git a/ci/run-build-and-tests.sh b/ci/run-build-and-tests.sh
index d3a094603f..12b2590230 100755
--- a/ci/run-build-and-tests.sh
+++ b/ci/run-build-and-tests.sh
@@ -7,8 +7,8 @@
 
 ln -s $HOME/travis-cache/.prove t/.prove
 
-make --jobs=2
-make --quiet test
+fold_cmd compile make --jobs=2
+fold_cmd test make --quiet test
 
 check_unignored_build_artifacts
 

I've queued a CI job to see if this actually works. :)

-Peff

Re: [PATCH] travis-ci: build Git during the 'script' phase

[SZEDER Gábor]

On Mon, Jan 8, 2018 at 11:38 PM, Lars Schneider
 wrote:
>
>> On 08 Jan 2018, at 23:07, Junio C Hamano  wrote:
>>
>> SZEDER Gábor  writes:
>>
>>> The reason why Travis CI does it this way and why it's a better
>>> approach than ours lies in how unsuccessful build jobs are
>>> categorized.  ...
>>> ...
>>> This makes it easier, both for humans looking at the Travis CI web
>>> interface and for automated tools querying the Travis CI API,...
>>> ...
>>> A verbose commit message for such a change... but I don't know why we
>>> started with building Git in the 'before_script' phase.
>>
>> Thanks for writing it up clearly.  TBH, I didn't even realize that
>> there were meaningful distinctions between the two cases after
>> seeing that sometimes our tests were failing and sometimes erroring
>> ;-)
>
> I understand the reasons for the proposed patch. However, I did this
> intentionally back then. Here is my reason:
>
> If `make` is successful, then I am not interested in its output.

If 'prove' is successful, then I'm not interested in its output ;)

> Look at this run: https://travis-ci.org/szeder/git/jobs/324271623
>
> You have to scroll down 1,406 lines to get to the test result
> output (this is usually the interesting part).

That's the just beginning of a looong list of executed test scripts in
seemingly pseudo-random order.  IMHO that's very rarely the interesting
part; I, for one, am only interested in that list in exceptional cases,
e.g. while tweaking the build dependencies or the 'prove --state=...'
options.

These are the really interesting parts of the build job's output, the
parts that do matter most of the time:

  # compiler error
  https://travis-ci.org/git/git/jobs/325252417#L1766
  # which tests failed
  https://travis-ci.org/git/git/jobs/315658238#L2247
  # stray build artifacts
  https://travis-ci.org/szeder/git/jobs/323531220#L2236
  # (no example logs for erroring while installing dependencies, OSX
  # timeout, etc.)

Note that these are all at the very end of the trace log, i.e. they are
easily accessible by one or two keystrokes (depending on whether the
keyboard has a dedicated 'End' key or requires an Fn combo), a vigorous
drag of the scrollbar, or a click on the "Scroll to end of log" circle
in the top right corner.

> If this is a valid argument for you,

I'm unconvinced :)

> would it be an option to
> pipe the verbose `make` output to a file and only print it in case
> of error (we do something similar for the tests already).

It's risky, because the build process would be completely silent for the
duration of building Git.  Travis CI considers a build 'errored' if it
doesn't produce any output for 10 minutes.  While building Git usually
takes much less time, transient slowdowns apparently do occur.

Gábor

Re: [PATCH] travis-ci: build Git during the 'script' phase

[Lars Schneider]

> On 08 Jan 2018, at 23:07, Junio C Hamano  wrote:
> 
> SZEDER Gábor  writes:
> 
>> The reason why Travis CI does it this way and why it's a better
>> approach than ours lies in how unsuccessful build jobs are
>> categorized.  ...
>> ...
>> This makes it easier, both for humans looking at the Travis CI web
>> interface and for automated tools querying the Travis CI API,...
>> ...
>> A verbose commit message for such a change... but I don't know why we
>> started with building Git in the 'before_script' phase.
> 
> Thanks for writing it up clearly.  TBH, I didn't even realize that
> there were meaningful distinctions between the two cases after
> seeing that sometimes our tests were failing and sometimes erroring
> ;-)

I understand the reasons for the proposed patch. However, I did this 
intentionally back then. Here is my reason:

If `make` is successful, then I am not interested in its output.
Look at this run: https://travis-ci.org/szeder/git/jobs/324271623

You have to scroll down 1,406 lines to get to the test result 
output (this is usually the interesting part).

If this is a valid argument for you, would it be an option to
pipe the verbose `make` output to a file and only print it in case
of error (we do something similar for the tests already).

- Lars

Re: [PATCH] travis-ci: build Git during the 'script' phase

[Junio C Hamano]

SZEDER Gábor  writes:

> The reason why Travis CI does it this way and why it's a better
> approach than ours lies in how unsuccessful build jobs are
> categorized.  ...
> ...
> This makes it easier, both for humans looking at the Travis CI web
> interface and for automated tools querying the Travis CI API,...
> ...
> A verbose commit message for such a change... but I don't know why we
> started with building Git in the 'before_script' phase.

Thanks for writing it up clearly.  TBH, I didn't even realize that
there were meaningful distinctions between the two cases after
seeing that sometimes our tests were failing and sometimes erroring
;-)

> Should go on top of 'sg/travis-check-untracked' in 'next'.