Versioned SAGE_ROOT/logs directory; append config.log

[mkoeppe]

The SAGE_ROOT/logs directory is never cleaned up and can grow very large over time.

We append the Sage version number to it, e.g., SAGE_ROOT/logs-9.6 (and create a symlink from SAGE_ROOT/logs for convenience). Upon first use, make moves the old logs directory out of the way so that the symlink can be created.

Users can then delete old log directories without having to worry that they lose information that is relevant for reporting bugs.

The location of the log file can also be overridden using an environment variable SAGE_ROOT_LOGS. This is useful for tox and devcontainer runs, whose logs are best kept separate from local direct builds.

Also, we change the handling of config.log, previously set up as a symlink into logs/pkgs/. We often get reports about build problems with a config.log attached that just shows "... already installed as an SPKG", so we cannot see what caused the SPKG to be installed in the first place. We fix this problem by appending the current contents of config.log (whenever it has changed) to logs/pkgs/config.log.

CC: @orlitzky @dimpase @jhpalmieri

Component: build: configure

Author: Matthias Koeppe

Branch/Commit: u/mkoeppe/append_config_log @ ab876cc

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

[mkoeppe]

Description changed:

--- 
+++ 
@@ -1,6 +1,10 @@
-The behavior of our `configure` script depends on what SPKGs are already installed.
+The `SAGE_ROOT/logs` directory is never cleaned up and can grow very large over time.

-We often get reports about build problems with a `config.log` attached that just shows "... already installed as an SPKG", so we cannot see what caused the SPKG to be installed in the first place.
+We append the Sage version number to it, e.g., `SAGE_ROOT/logs-9.6` (and create a symlink from `SAGE_ROOT/logs` for convenience). Upon first use, `make` moves the old `logs` directory out of the way so that the symlink can be created.

-So at the end of a `configure` run or perhaps as a step in `build`, we should append the current contents of `config.log` to some file in `logs/`
+Users can then delete old log directories without having to worry that they lose information that is relevant for reporting bugs.

+The location of the log file can also be overridden using an environment variable `SAGE_ROOT_LOGS`. This is useful for `tox` and devcontainer runs, whose logs are best kept separate from local direct builds.
+
+Also, we change the handling of `config.log`, previously set up as a symlink into `logs/pkgs/`. We often get reports about build problems with a `config.log` attached that just shows "... already installed as an SPKG", so we cannot see what caused the SPKG to be installed in the first place. We fix this problem by appending the current contents of `config.log` (whenever it has changed) to `logs/pkgs/config.log`.
+

[mkoeppe]

Branch: u/mkoeppe/append_config_log

[mkoeppe]

Author: Matthias Koeppe

[mkoeppe]

Commit: 7024f58

[mkoeppe]

New commits:

7024f58

Versioned SAGE_ROOT/logs directory; append config.log

[jhpalmieri]

comment:5

Should make misc-clean remove the new logs-... directories? make distclean certainly should.

[mkoeppe]

comment:6

Thanks, great point.

[7ed8c4ca-6d56-4ae9-953a-41e42b4ed313]

Changed commit from 7024f58 to cbfe328

[7ed8c4ca-6d56-4ae9-953a-41e42b4ed313]

Branch pushed to git repo; I updated commit sha1. New commits:

cbfe328

Makefile (misc-clean): Delete logs-* too

[jhpalmieri]

comment:9

I don't know if it's worth it, but it would keep the top-level directory cleaner if the action all happened inside the logs directory: either move old logs directories there or create versioned pkgs directories. I don't know if we need to have versioned and archived install.log or ptestlong.log files.

[mkoeppe]

comment:10

I don't think the separation of the *test*.log from the package logs is very useful, so I suppose we could get rid of pkgs and then put everything in a versioned logs/sage-X.Y directory?

[mkoeppe]

comment:11

In this case I could use a symlink logs/current that's pointing to the corresponding logs/sage-X.Y (or in the case of a tox build, to the tox log dir)

[jhpalmieri]

comment:12

That's an interesting idea. Is there a good way to highlight the non-pkg logs? Capitalize their names? Does it matter?

[mkoeppe]

comment:13

The idea behind the naming of the *test*.log files is not fully clear to me. Do people really need to distinguish between test.log and ptest.log?

[jhpalmieri]

comment:14

It's good to know if a test failure might be happening because it was running in parallel.

[mkoeppe]

comment:15

OK, then mixing in the logs from pkgs/ is probably not such a good idea

[jhpalmieri]

comment:16

I could open a separate ticket where we rename the test logs as test...log: instead of ptest.log, use testp.log (or testparallel.log or whatever). Our use of p as a prefix meaning "parallel" is not particularly standard, is it? We could even go so far as to change the make targets from ptest to testparallel or similar. I would even be tempted to try to set the -p flag for doctesting automatically, depending on MAKE, MAKEFLAGS, etc.

[jhpalmieri]

comment:17

By the way, what do you think of this change? (For a separate ticket, I think.)

diff --git a/Makefile b/Makefile
index a9290e54b7..6b4cdaaddb 100644
--- a/Makefile
+++ b/Makefile
@@ -223,8 +223,8 @@ fast-rebuild-clean: misc-clean
    # Remove leftovers from ancient branches
    rm -rf src/build

-TESTALL = ./sage -t --all
-PTESTALL = ./sage -t -p --all
+TESTALL = ./sage -t --all --logfile=logs/$@.log
+PTESTALL = $(TESTALL) -p

 # Flags for ./sage -t --all.
 # When the documentation is installed, "optional" also includes all tests marked 'sagemath_doc_html',
@@ -233,80 +233,80 @@ PTESTALL = ./sage -t -p --all
 TESTALL_FLAGS = --optional=sage,optional,external

 test: all
-   $(TESTALL) --logfile=logs/test.log
+   $(TESTALL)

 check: test

 testall: all
-   $(TESTALL) $(TESTALL_FLAGS) --logfile=logs/testall.log
+   $(TESTALL) $(TESTALL_FLAGS)

 testlong: all
-   $(TESTALL) --long --logfile=logs/testlong.log
+   $(TESTALL) --long

 testalllong: all
-   $(TESTALL) --long $(TESTALL_FLAGS) --logfile=logs/testalllong.log
+   $(TESTALL) --long $(TESTALL_FLAGS)

 ptest: all
-   $(PTESTALL) --logfile=logs/ptest.log
+   $(PTESTALL)

 ptestall: all
-   $(PTESTALL) $(TESTALL_FLAGS) --logfile=logs/ptestall.log
+   $(PTESTALL) $(TESTALL_FLAGS)

 ptestlong: all
-   $(PTESTALL) --long --logfile=logs/ptestlong.log
+   $(PTESTALL) --long

 ptestalllong: all
-   $(PTESTALL) --long $(TESTALL_FLAGS) --logfile=logs/ptestalllong.log
+   $(PTESTALL) --long $(TESTALL_FLAGS)

 testoptional: all
-   $(TESTALL) --logfile=logs/testoptional.log
+   $(TESTALL)

 testoptionallong: all
-   $(TESTALL) --long --logfile=logs/testoptionallong.log
+   $(TESTALL) --long

 ptestoptional: all
-   $(PTESTALL) --logfile=logs/ptestoptional.log
+   $(PTESTALL)

 ptestoptionallong: all
-   $(PTESTALL) --long --logfile=logs/ptestoptionallong.log
+   $(PTESTALL) --long

 test-nodoc: build
-   $(TESTALL) --logfile=logs/test.log
+   $(TESTALL)

 check-nodoc: test-nodoc

 testall-nodoc: build
-   $(TESTALL) $(TESTALL_FLAGS) --logfile=logs/testall.log
+   $(TESTALL) $(TESTALL_FLAGS)

 testlong-nodoc: build
-   $(TESTALL) --long --logfile=logs/testlong.log
+   $(TESTALL) --long

 testalllong-nodoc: build
-   $(TESTALL) --long $(TESTALL_FLAGS) --logfile=logs/testalllong.log
+   $(TESTALL) --long $(TESTALL_FLAGS)

 ptest-nodoc: build
-   $(PTESTALL) --logfile=logs/ptest.log
+   $(PTESTALL)

 ptestall-nodoc: build
-   $(PTESTALL) $(TESTALL_FLAGS) --logfile=logs/ptestall.log
+   $(PTESTALL) $(TESTALL_FLAGS)

 ptestlong-nodoc: build
-   $(PTESTALL) --long --logfile=logs/ptestlong.log
+   $(PTESTALL) --long

 ptestalllong-nodoc: build
-   $(PTESTALL) --long $(TESTALL_FLAGS) --logfile=logs/ptestalllong.log
+   $(PTESTALL) --long $(TESTALL_FLAGS)

 testoptional-nodoc: build
-   $(TESTALL) --logfile=logs/testoptional.log
+   $(TESTALL)

 testoptionallong-nodoc: build
-   $(TESTALL) --long --logfile=logs/testoptionallong.log
+   $(TESTALL) --long

 ptestoptional-nodoc: build
-   $(PTESTALL) --logfile=logs/ptestoptional.log
+   $(PTESTALL)

 ptestoptionallong-nodoc: build
-   $(PTESTALL) --long --logfile=logs/ptestoptionallong.log
+   $(PTESTALL) --long

 configure: bootstrap src/doc/bootstrap configure.ac src/bin/sage-version.sh m4/*.m4 build/pkgs/*/spkg-configure.m4 build/pkgs/*/type build/pkgs/*/install-requires.txt build/pkgs/*/package-version.txt build/pkgs/*/distros/*.txt
    ./bootstrap -d

I think the only difference in behavior is that -nodoc will be added to the corresponding log files.

[mkoeppe]

comment:18

Replying to @jhpalmieri:

It's good to know if a test failure might be happening because it was running in parallel.

This is a good point, but I think it is also clearly visible in the first lines of output in the log:

Running doctests with ID 2022-06-08-00-48-49-d7ceb8b6.
Git branch: t/33011/remove___init___py_files_for_packages_designated_to_be_namespace_packages
Using --optional=bliss,ccache,e_antic,homebrew,igraph,normaliz,perl_term_readline_gnu,pip,sage,sage_spkg
Features to be detected: 4ti2,benzene,bliss,buckygen,conway_polynomials,csdp,database_cremona_ellcurve,database_cremona_mini_ellcurve,database_jones_numfield,database_knotinfo,dvipng,gfan,graphviz,imagemagick,jupymake,kenzo,latte_int,lrslib,mcqd,meataxe,msolve,nauty,palp,pandoc,pdf2svg,pdftocairo,phitigra,plantri,polytopes_db,polytopes_db_4d,pynormaliz,python_igraph,rubiks,sage.combinat,sage.geometry.polyhedron,sage.graphs,sage.groups,sage.plot,sage.rings.number_field,sage.rings.padics,sage.rings.real_double,sage.symbolic,sage_numerical_backends_coin,sagemath_doc_html,sphinx,tdlib
Doctesting entire Sage library.
Doctesting all documentation sources.
Sorting sources by runtime so that slower doctests are run first....
Doctesting 4364 files using 8 threads.
sage -t --random-seed=200685860218284960962388612985087409788 src/sage/modules/free_module_element.pxd
    [0 tests, 0.00 s]

[jhpalmieri]

comment:19

So maybe it's fine to use the same log file for all testing if the relevant information is written to the log file: parallel, nodoc, optional, long, etc.

[mkoeppe]

comment:20

I don't think nodoc needs to be indicated in the logfile - this is only a shortcut for developers to avoid waiting for the docbuild

[jhpalmieri]

comment:21

I thought that nodoc meant that fewer doctests are run — the ones depending on the presence of the documentation in particular. Or they are run on an old version of the documentation which happens to be lying around. I think this is useful information.

[mkoeppe]

Dependencies: #33823

[mkoeppe]

comment:22

That's not the current behavior, but it's an interesting idea for an improvement. Easy to implement using #33823

[7ed8c4ca-6d56-4ae9-953a-41e42b4ed313]

Changed commit from cbfe328 to f129c74

[7ed8c4ca-6d56-4ae9-953a-41e42b4ed313]

Branch pushed to git repo; I updated commit sha1. New commits:

389ee10	Merge tag '9.7.beta2' into t/33262/append_config_log
b1ce8d6	sage -t: Handle --optional=!FEATURE
a670ae8	src/bin/sage-runtests: Update documentation of --optional
ba86146	src/bin/sage-runtests --help: Say that ! needs to be quoted
de421e4	Merge #33823
f129c74	Makefile (*test*-nodoc): Skip tests marked # optional - sagemath_doc_html or sagemath_doc_pdf

[7ed8c4ca-6d56-4ae9-953a-41e42b4ed313]

Changed commit from f129c74 to 8668dfe

[7ed8c4ca-6d56-4ae9-953a-41e42b4ed313]

Branch pushed to git repo; I updated commit sha1. New commits:

3b5b0f6	Makefile (*test*): Log to a common log file TEST.log
8668dfe	Makefile: testoptional is the same as test

[7ed8c4ca-6d56-4ae9-953a-41e42b4ed313]

Branch pushed to git repo; I updated commit sha1. New commits:

2e602d9

Makefile: Rewrite *test* targets using target-specific variables TEST_FLAGS, TEST_OPTIONAL

[7ed8c4ca-6d56-4ae9-953a-41e42b4ed313]

Changed commit from 8668dfe to 2e602d9

[mkoeppe]

Changed dependencies from #33823 to #33823, #33967

[7ed8c4ca-6d56-4ae9-953a-41e42b4ed313]

Branch pushed to git repo; I updated commit sha1. New commits:

4ae68cc	foo
d242f96	src/sage/doctest/control.py: Show also 'git describe --always --dirty'
f2468ab	src/sage/doctest/control.py: Show SAGE_LOCAL, SAGE_VENV
bad1af9	Merge #33967

[7ed8c4ca-6d56-4ae9-953a-41e42b4ed313]

Changed commit from 2e602d9 to bad1af9

[7ed8c4ca-6d56-4ae9-953a-41e42b4ed313]

Changed commit from bad1af9 to bc412b1

[7ed8c4ca-6d56-4ae9-953a-41e42b4ed313]

Branch pushed to git repo; I updated commit sha1. New commits:

bc412b1

Makefile (test): Back to using test.log (not TEST.log) for now

[jhpalmieri]

comment:29

Can we just delete the redundant make targets testoptional etc.? They do not seem to be documented anywhere.

[mkoeppe]

comment:30

These changes are now on #33995, where I added deprecation warnings for these targets.

[mkoeppe]

Work Issues: Rebase on #33995

[mkoeppe]

Changed dependencies from #33823, #33967 to #33823, #33967, #33995

[7ed8c4ca-6d56-4ae9-953a-41e42b4ed313]

Branch pushed to git repo; I updated commit sha1. This was a forced push. New commits:

bfa5db2	Versioned SAGE_ROOT/logs directory; append config.log
97c4cfc	Makefile (misc-clean): Delete logs-* too

[7ed8c4ca-6d56-4ae9-953a-41e42b4ed313]

Changed commit from bc412b1 to 97c4cfc

[mkoeppe]

Changed work issues from Rebase on #33995 to none

[mkoeppe]

Changed dependencies from #33823, #33967, #33995 to none

[7ed8c4ca-6d56-4ae9-953a-41e42b4ed313]

Branch pushed to git repo; I updated commit sha1. This was a forced push. New commits:

ab876cc

Versioned SAGE_ROOT/logs directory; append config.log

[7ed8c4ca-6d56-4ae9-953a-41e42b4ed313]

Changed commit from 97c4cfc to ab876cc