Don't ask for verbose output from tar when installing packages

[qed777]

The sage-spkg script runs tar with the v option to extract spkgs. This significantly increases the size of many installation logs. Not adding the option would make the logs easier to navigate and search for errors and warnings, too.

I think Leif Leonhardy proposed this, somewhere.

CC: @nexttime

Component: build

Author: Leif Leonhardy

Reviewer: Mitesh Patel

Merged: sage-4.6.1.alpha1

Issue created by migration from https://trac.sagemath.org/ticket/10040

[qed777]

comment:1

Are there good reasons to keep the verbose non-error output?

Smaller logs would also help with #3524.

[sagetrac-drkirkby]

comment:2

I think Leif said the verbose output could be useful to find packages which have unnecessary files in them. But personally I think that issue should be resolved when packages are reviewed. I've not objections to adding an environment variable to control it, but it's more work than a one-character patch!

As you say, it would also help with buildbot too.

Dave

[nexttime]

comment:3

Replying to @sagetrac-drkirkby:

I think Leif said the verbose output could be useful to find packages which have unnecessary files in them.

That was meant a joke. (I don't expect people to read the full, nearly 300,000-lines install.log, but incidentally noticed the mentioned obsolete SageNB files when watching the build process.)

But personally I think that issue should be resolved when packages are reviewed.

Of course. Unfortunately it's unlikely people look into the Mercurial repository for deleted files. (Ok, you can see them when verbosely unpacking an spkg manually, or do du -sh on the spkg's directory, which a reviewer should perhaps also do.)

I've not objections to adding an environment variable to control it, but it's more work than a one-character patch!

Obviously, but shouldn't carry much more of a danger.

[nexttime]

comment:4

Perhaps (on another ticket) we should also address the almost useless "copying ..." messages that afaik originate from distutils. These make up another fair amount of the logs.

[sagetrac-drkirkby]

comment:5

Are you two happy with just removing the 'v', and not bothering with an environment variable? I certainly am. If so, let's create a patch.

Anything to cut down the log size is a good thing, so feel free to create a ticket for this other issue.

Dave

[nexttime]

Apply to Sage scripts repository. Based on Sage 4.6.rc0pre1.

[nexttime]

comment:6

Attachment: trac_10040-untar_non-verbosely_by_default-sage_scripts.patch.gz

I've attached a patch to sage-spkg that honors SAGE_SPKG_LIST_FILES=yes, and calls tar without "v" otherwise.

[nexttime]

Author: Leif Leonhardy

[nexttime]

comment:7

Btw, #9799 is also related (in case of build errors), since without that running make will also attempt to build the documentation regardless if the build succeeded or not, and obscure (and unnecessarily grow) the log or even "hide" the build error.

(Build errors do not always cause failures in building the documentation, so it might look as if the whole build succeeded, which probably William meant by "leading to all kinds of confusion".)

[nexttime]

comment:8

Replying to @nexttime:

Perhaps (on another ticket) we should also address the almost useless "copying ..." messages that afaik originate from distutils. These make up another fair amount of the logs.

leif@quadriga:~/Sage/sage-4.6.rc0pre1$ grep "^copying" install.log | wc -lc
  65512 11147892

(That's more than 34% of the log file size.)

Maybe it's setuptools, not distutils; I don't know yet.

[nexttime]

comment:9

More detailed:

leif@quadriga:~/Sage/sage-4.6.rc0pre1$ grep -c "^copying" spkg/logs/* | awk 'BEGIN { FS=":" } { if ($2!=0) printf "%5d  %s\n", $2, $1 }' | sort -rn
43543  spkg/logs/moin-1.9.1.p1.log
 8419  spkg/logs/sagenb-0.8.7.log
 2702  spkg/logs/sage-4.6.rc0pre1.log
 2142  spkg/logs/matplotlib-1.0.0.log
 1797  spkg/logs/twisted-9.0.p2.log
 1096  spkg/logs/scipy-0.7.p5.log
  773  spkg/logs/sympy-0.6.4.p0.log
  661  spkg/logs/ipython-0.9.1.p0.log
  620  spkg/logs/numpy-1.3.0.p4.log
  429  spkg/logs/zodb3-3.7.0.p4.log
  388  spkg/logs/mercurial-1.3.1.p2.log
  367  spkg/logs/scons-1.2.0.log
  363  spkg/logs/networkx-1.2.p1.log
  349  spkg/logs/cython-0.13.p1.log
  307  spkg/logs/sphinx-0.6.3.p4.log
  292  spkg/logs/weave-0.4.9.p0.log
  260  spkg/logs/docutils-0.5.p0.log
  183  spkg/logs/pycrypto-2.1.0.log
  169  spkg/logs/pil-1.1.6.p2.log
  157  spkg/logs/sqlalchemy-0.5.8.log
  154  spkg/logs/mpmath-0.15.log
  122  spkg/logs/pygments-0.11.1.p0.log
   76  spkg/logs/setuptools-0.6c9.p0.log
   69  spkg/logs/python-2.6.4.p9.log
   68  spkg/logs/rpy2-2.0.8.log
   68  spkg/logs/r-2.10.1.p4.log
   65  spkg/logs/jinja2-2.1.1.p0.log
   27  spkg/logs/python_gnutls-1.1.4.p7.log
   22  spkg/logs/scipy_sandbox-20071020.p7.log
   21  spkg/logs/cvxopt-0.9.p9.log
   15  spkg/logs/sagetex-2.2.5.log
    3  spkg/logs/gdmodule-0.56.p7.log
    2  spkg/logs/pexpect-2.0.p4.log
    1  spkg/logs/gsl-1.14.log

So it's perhaps more worth addressing that in those spkgs that produce a huge number of such lines. There's a "verbose" option to distutils' setup() which is enabled by default (and also a "quiet" one), but I think we only want to suppress the verbose copying, so we'd have to configure just that command.

[nexttime]

comment:10

Oh, the "copying ..." messages appear to be a distutils bug; distutils.file_util.copy_file() has a verbose (default: 0) parameter, but doesn't use it!

If I change it to the following:

    ...
    if verbose: # added just this line
        if os.path.basename(dst) == os.path.basename(src):
            log.info("%s %s -> %s", action, src, dir)
        else:
            log.info("%s %s -> %s", action, src, dst)
    ...

the "copying ..." messages vanish at least for mpmath (I only tried that so far).

Opinions? (before I open a ticket for that)

[nexttime]

comment:11

Replying to @nexttime:

If I change it [...] the "copying ..." messages vanish at least for mpmath (I only tried that so far).

Also works for the record holders MoinMoin and SageNB...

[jhpalmieri]

comment:12

Replying to @sagetrac-drkirkby:

Are you two happy with just removing the 'v', and not bothering with an environment variable? I certainly am. If so, let's create a patch.

Would it make sense to have a make target which produced verbose logs? Then you wouldn't have to explicitly set an environment variable. The same might go for parallel building, by the way.

[nexttime]

comment:13

Replying to @jhpalmieri:

Would it make sense to have a make target which produced verbose logs? Then you wouldn't have to explicitly set an environment variable.

No problem to add such.

The same might go for parallel building, by the way.

Not a bad idea. I vaguely remember what I had in mind for the "global" log and parallel builds: Since our "deps" Makefile does nothing but call sage-spkg, we can move the logging (i.e. the use of pipestatus) there, just passing in addition the name(s) of the logfile(s) in the Make rules.

sage-spkg can then take control of what (and how much) to log where (depending on command line options and/or environment variables), e.g. not teeing but just redirecting the output of spkg-install to the logfile, and printing short messages to stdout on parallel builds.

[nexttime]

comment:14

OT: A target for building the documentation (at least some parts) in parallel would be nice, too.

(We'd have to split the meaning of "all", which isn't defined by/in sage-sage but devel/sage/doc/common/builder.py in the Makefile. I'm not sure if we need that buggy Python script at all btw, which finally does an equivalent of os.system("sphinx ...") rather than importing it to build the docs...)

[sagetrac-drkirkby]

comment:15

This works fine for me on OpenSolaris, and I can't possibly see it would be platform dependent.

However, the meaning of SAGE_SPKG_LIST_FILES should be added to the installation guide, along with the other environment variables.

I think in many cases one might want to set SAGE_SPKG_LIST_FILES=yes when installing a particular package. i.e.

$  export SAGE_SPKG_LIST_FILES=yes
$ ./sage -f somepackage.spkg

or something like that. As such, I think SAGE_SPKG_LIST_FILES should be documented in the installation guide, which will need another patch.

[sagetrac-drkirkby]

Work Issues: Add a patch to document the new environment variable

[nexttime]

comment:17

Replying to @sagetrac-drkirkby:

However, the meaning of SAGE_SPKG_LIST_FILES should be added to the installation guide, along with the other environment variables.

Done.

I think in many cases one might want to set SAGE_SPKG_LIST_FILES=yes when installing a particular package.

You previously said you were happy with just removing the "v"... ;-)

---

Though the installation guide really needs work (it is fairly out-dated), I've in addition only reformatted one paragraph to (less than) 80 columns and moved the description of CFLAG64 up s.t. it's now immediately below that of SAGE64, where it IMHO belongs.

[nexttime]

Changed work issues from Add a patch to document the new environment variable to none

[jhpalmieri]

comment:19

I think "s.t." stands for "such that". Maybe that sentence could be rephrased as

Since some spkgs contain a huge number of files, the log files can 
get very large and hard to search (and listing the contained files is
usually not very valuable), so this is turned off by default.

[nexttime]

comment:20

Replying to @sagetrac-drkirkby:

What does the s.t. standard for, in the sentence Since some spkgs contain a huge number of files s.t. the log files get very large and harder to search (and listing the contained ?

It does not mean "sine tempore" (nor "subject to")...

Of course I can change that.

I was happy to just omit -v, but if we are going to have the option to configure it, we should document it. I would have been quite happy not to have the option myself.

I rather consider that a "developer's back door", which I would document in the Developer's Guide (if at all). ;-)

[nexttime]

Apply to Sage library. Based on Sage 4.6.rc0pre1. (Updated version s.t. more people can read it.)

[nexttime]

comment:21

Attachment: trac_10040-document_SAGE_SPKG_LIST_FILES-sage_library.patch.gz

Replying to @nexttime:

Of course I can change that.

Reluctantly did that.

[nexttime]

comment:22

ping (before it rottens) ;-)

I'm working on a lot of further changes to (not only) sage-spkg...

[qed777]

Reviewer: Mitesh Patel

[qed777]

comment:23

Suppressing the copying... messages sounds good to me. Should we have an option to enable them?

Should we use suppress "tarbosity" in sage-bdist, too?

[nexttime]

comment:24

Replying to @qed777:

Suppressing the copying... messages sounds good to me. Should we have an option to enable them?

I have a patched Python package here that currently only adds the if verbose:.

Unfortunately, setting distutils.log's verbosity level (before calling setup()) seems to not work for some reason. It's not clear what the verbose parameter is supposed to change, and apparently it isn't [always] passed to copy_file().

There's always DISTUTILS_DEBUG btw. ;-)

We could make use of Sage environment variables (e.g. SAGE_DEBUG_BUILD, or SAGE_DISTUTILS_VERBOSITY_LEVEL) directly there, enabling more output. But I think keeping the other messages of the same verbosity level (like "creating ..." etc.) is ok, I'm not sure about "moving ..." of which we also have a lot, but by far not that many.

Did I already tell the install.log size drops to less than the half with non-verbose untarring and "copying" messages suppressed? (Also quite significantly depends on the length of $SAGE_ROOT...)

Should we use suppress "tarbosity" in sage-bdist, too?

Less important, at least to me.

[nexttime]

comment:25

Replying to @nexttime:

Did I already tell the install.log size drops to less than the half with non-verbose untarring and "copying" messages suppressed? (Also quite significantly depends on the length of $SAGE_ROOT...)

$ wc -lc sage-4.6.rc0/install.log-rc0-orig sage-4.6.rc0-short-logs/install.log-rc0-short-logs 
  299773 31880226 sage-4.6.rc0/install.log-rc0-orig
  122924 15222503 sage-4.6.rc0-short-logs/install.log-rc0-short-logs
  422697 47102729 total
$ expr 15222503 - 11 \* `grep -c -- -short-logs sage-4.6.rc0-short-logs/install.log-rc0-short-logs`
14771536
$ echo "Total bytes saved: `expr 31880226 - 14771536`"
Total bytes saved: 17108690

(The above computation does not even take into account multiple occurrences of $SAGE_ROOT on a single line, which is also frequently the case, so we save more than 53.7%. :) )

[jdemeyer]

comment:26

Have you considered simply remove the v option to tar without environment variables? I don't really like adding another (pointless) environment variable.

[nexttime]

comment:27

Replying to @jdemeyer:

Have you considered simply remove the v option to tar without environment variables? I don't really like adding another (pointless) environment variable.

See comments above. It's always good to have a "back door", the others then wanted me to officially document it. (And Mitesh recently asked if I could provide some way to reenable the useless "copying ..." messages from distutils if I suppress them.)

I don't mind having dozens of environment variables that nobody uses, at least as far as their names do not pollute the environment. (And they're much easier to implement than command line options.) There are enough scripts that export(!) variables like OPT etc., often despite being only locally used. The package name variables set in spkg/install, used in deps, are bad enough.

But IMHO the opposite is the case: We have too many useful variables (some undocumented), many with odd names like SAGE64 (which always reminds me of F77, Window95 etc.).

[sagetrac-drkirkby]

comment:28

Replying to @jdemeyer:

Have you considered simply remove the v option to tar without environment variables? I don't really like adding another (pointless) environment variable.

As you will see above, my suggestion was to just remove the 'v' and leave it there.

But I admit being able to change this does have some small benefit, and since it's now working, I think it's best left as it is. It can do no harm, and its documented properly.

Dave

[jdemeyer]

comment:29

I get the following error which might be caused by this patch:

[...]
sage_scripts-4.6.1.alpha1/spkg-install
sage_scripts-4.6.1.alpha1/sage-rebase_sage.sh
sage_scripts-4.6.1.alpha1/sage-sbuildhack
sage_scripts-4.6.1.alpha1/sage-grep
sage_scripts-4.6.1.alpha1/ipy_profile_sage.py
sage_scripts-4.6.1.alpha1/sage-ipython
Finished extraction
****************************************************
Host system
uname -a:
Linux boxen 2.6.24-24-server #1 SMP Fri Sep 18 16:47:05 UTC 2009 x86_64 GNU/Linux
****************************************************
****************************************************
CC Version
gcc -v
Using built-in specs.
Target: x86_64-linux-gnu
Configured with: ../src/configure -v --enable-languages=c,c++,fortran,objc,obj-c++,treelang --prefix=/usr --enable-shared --with-system-zlib --libexecdir=/usr/lib --without-included-gettext --enable-threads=posix --enable-nls --with-gxx-include-dir=/usr/include/c++/4.2 --program-suffix=-4.2 --enable-clocale=gnu --enable-libstdcxx-debug --enable-objc-gc --enable-mpfr --enable-checking=release --build=x86_64-linux-gnu --host=x86_64-linux-gnu --target=x86_64-linux-gnu
Thread model: posix
gcc version 4.2.4 (Ubuntu 4.2.4-1ubuntu4)
****************************************************
cp: cannot stat `/scratch/jdemeyer/merger/sage-4.6.1.alpha1/sage-python': No such file or directory
cp: cannot stat `/scratch/jdemeyer/merger/sage-4.6.1.alpha1/ipython': No such file or directory

real	0m0.075s
user	0m0.000s
sys	0m0.060s
/scratch/jdemeyer/merger/sage-4.6.1.alpha1/local/bin/sage-spkg: line 426: syntax error near unexpected token `('
/scratch/jdemeyer/merger/sage-4.6.1.alpha1/local/bin/sage-spkg: line 426: `    echo "(cd '`pwd`' && '$SAGE_ROOT/sage' -sh)"'
make[1]: *** [installed/sage_scripts-4.6.1.alpha1] Error 2
make[1]: Leaving directory `/padic/scratch/jdemeyer/merger/sage-4.6.1.alpha1/spkg'

[nexttime]

comment:30

Replying to @jdemeyer:

I get the following error which might be caused by this patch:

How that? I see no relation to my patch, looks rather like the spkg-install does something weird, possibly corrupting (the running) sage-spkg?

[nexttime]

comment:31

Replying to @sagetrac-drkirkby:

I think it's best left as it is. It can do no harm, and its documented properly.

We need a special section for useless (or rarely used) variables, I think in the Developer's rather than the Installation Guide.

[nexttime]

comment:32

Replying to @nexttime:

Replying to @sagetrac-drkirkby:

I think it's best left as it is. It can do no harm, and its documented properly.

We need a special section for useless (or rarely used) variables, I think in the Developer's rather than the Installation Guide.

Like PIL_NOTK (I always read "Pill not K", like the famous nchoosek.)

[sagetrac-drkirkby]

comment:33

Replying to @nexttime:

We need a special section for useless (or rarely used) variables, I think in the Developer's rather than the Installation Guide.

Yes, perhaps some of these rarely used once should be in a section of their own. But that can be the subject of another ticket, and would not doubt need a lot of discussion about what is rarely used, what should be used more often.

IMHO, this ticket has positive review and should be merged unchanged.

[jhpalmieri]

comment:34

Replying to @jdemeyer:

I get the following error which might be caused by this patch:

Yes and no. I think it was caused by the patch, but because you made a small mistake in applying the patch: when patching the script sage-spkg for testing purposes, you need to apply the patch, but then also copy the new version of sage-spkg to SAGE_ROOT/spkg/base. (Or apply the patch and then run "sage -sdist" and build the new version from scratch.) Otherwise, if the files SAGE_ROOT/spkg/base/sage-spkg and sage-spkg in the sage_scripts spkg don't match, at some point one of them overwrites the other while it is being executed, and the shell gets confused.

At least, that's my guess about what happened.

[jdemeyer]

comment:35

Replying to @jhpalmieri:

Yes and no. I think it was caused by the patch, but because you made a small mistake in applying the patch: when patching the script sage-spkg for testing purposes, you need to apply the patch, but then also copy the new version of sage-spkg to SAGE_ROOT/spkg/base. (Or apply the patch and then run "sage -sdist" and build the new version from scratch.) Otherwise, if the files SAGE_ROOT/spkg/base/sage-spkg and sage-spkg in the sage_scripts spkg don't match, at some point one of them overwrites the other while it is being executed, and the shell gets confused.

That seems to be a likely explanation, I will test later. I suppose the same holds for sage-env and sage-make_relative, which are also in spkg/base?

[jdemeyer]

comment:36

Replying to @jhpalmieri:

Yes and no. I think it was caused by the patch, but because you made a small mistake in applying the patch: when patching the script sage-spkg for testing purposes, you need to apply the patch, but then also copy the new version of sage-spkg to SAGE_ROOT/spkg/base.

Thanks a lot for the tip, that's precisely what happened.

[jhpalmieri]

comment:37

Replying to @jdemeyer:

Thanks a lot for the tip, that's precisely what happened.

Well, the same thing happened to me a few days ago, so it was an educated guess.

[jdemeyer]

Merged: sage-4.6.1.alpha1