Show elapsed time for build and publishing

[hugovk]

Helps #169.

The logs for a single language/version look like this:

logs

2024-08-14 14:01:15,870 INFO ja/3.12: Running.
2024-08-14 14:01:15,871 DEBUG ja/3.12: Run: 'git -C /srv/docsbuild/cpython show-ref -s origin/3.12'
2024-08-14 14:01:15,874 DEBUG ja/3.12: Run: 'git -C /srv/docsbuild/cpython reset --hard 344a7b535bb725a7ea144648a6a3bc3ce8485e2c --'
2024-08-14 14:01:15,905 DEBUG ja/3.12: Run: 'git -C /srv/docsbuild/cpython clean -dfqx'
2024-08-14 14:01:16,080 DEBUG ja/3.12: Run: 'git -C /srv/docsbuild/3.12/locale/ja/LC_MESSAGES fetch'
2024-08-14 14:01:16,345 DEBUG ja/3.12: Run: 'git -C /srv/docsbuild/3.12/locale/ja/LC_MESSAGES branch -r'
2024-08-14 14:01:16,349 DEBUG ja/3.12: Run: 'git -C /srv/docsbuild/3.12/locale/ja/LC_MESSAGES show-ref -s origin/3.11'
2024-08-14 14:01:16,352 DEBUG ja/3.12: Run: 'git -C /srv/docsbuild/3.12/locale/ja/LC_MESSAGES reset --hard 71404d22de96db3df16e11a1d92c39f58cb746f5 --'
2024-08-14 14:01:16,916 DEBUG ja/3.12: Run: 'git -C /srv/docsbuild/3.12/locale/ja/LC_MESSAGES clean -dfqx'
2024-08-14 14:01:17,039 DEBUG ja/3.12: Run: 'git -C /srv/docsbuild/cpython rev-parse HEAD'
2024-08-14 14:01:17,042 DEBUG ja/3.12: Run: 'git -C /srv/docsbuild/3.12/locale/ja/LC_MESSAGES rev-parse HEAD'
2024-08-14 14:01:17,044 INFO ja/3.12: Should rebuild: new translations (from 61bd824895952478350bad88edc205741af324e2 to 71404d22de96db3df16e11a1d92c39f58cb746f5)
2024-08-14 14:01:17,045 DEBUG ja/3.12: Run: '/srv/docsbuild/venv/bin/python -m venv /srv/docsbuild/venv-3.12'
2024-08-14 14:01:19,328 DEBUG ja/3.12: Run: '/srv/docsbuild/venv-3.12/bin/python -m pip install --upgrade python-docs-theme jieba -rrequirements.txt'
2024-08-14 14:01:20,398 DEBUG ja/3.12: Run: '/srv/docsbuild/venv-3.12/bin/python -m pip freeze --all'
2024-08-14 14:01:20,830 INFO ja/3.12: Build start.
2024-08-14 14:01:21,130 INFO ja/3.12: Running make autobuild-stable
2024-08-14 14:01:21,131 DEBUG ja/3.12: Run: "sed -i 's/ *-A switchers=1//' /srv/docsbuild/cpython/Doc/Makefile"
2024-08-14 14:01:21,137 DEBUG ja/3.12: Run: "make -C /srv/docsbuild/cpython/Doc PYTHON=/srv/docsbuild/venv-3.12/bin/python SPHINXBUILD=/srv/docsbuild/venv-3.12/bin/sphinx-build BLURB=/srv/docsbuild/venv-3.12/bin/blurb VENVDIR=/srv/docsbuild/venv-3.12 'SPHINXOPTS=-D latex_engine=lualatex -D latex_elements.inputenc= -D latex_elements.fontenc= -D latex_docclass.manual=ltjsbook -D latex_docclass.howto=ltjsarticle -D latex_elements.polyglossia= -D latex_elements.fontpkg= -D latex_elements.preamble=\\\\usepackage[noto-otf]{luatexja-preset}\\\\usepackage{newunicodechar}\\\\newunicodechar{^^^^212a}{K}\\\\makeatletter\\\\titleformat{\\\\subsubsection}{\\\\normalsize\\\\py@HeaderFamily}{\\\\py@TitleColor\\\\thesubsubsection}{0.5em}{\\\\py@TitleColor}\\\\titleformat{\\\\paragraph}{\\\\normalsize\\\\py@HeaderFamily}{\\\\py@TitleColor\\\\theparagraph}{0.5em}{\\\\py@TitleColor}\\\\titleformat{\\\\subparagraph}{\\\\normalsize\\\\py@HeaderFamily}{\\\\py@TitleColor\\\\thesubparagraph}{0.5em}{\\\\py@TitleColor}\\\\makeatother\\\\setlength{\\\\footskip}{16.4pt} -q -D locale_dirs=/srv/docsbuild/3.12/locale -D language=ja -D gettext_compact=0' SPHINXERRORHANDLING= autobuild-stable"
2024-08-14 14:07:01,512 INFO: Another builder is running... dying...
2024-08-14 15:07:02,088 INFO: Another builder is running... dying...
2024-08-14 15:33:21,379 DEBUG ja/3.12: Run: 'mkdir -p /var/log/docsbuild'
2024-08-14 15:33:21,382 DEBUG ja/3.12: Run: 'chgrp -R docs /var/log/docsbuild'
2024-08-14 15:33:23,090 INFO ja/3.12: Build done.
2024-08-14 15:33:23,091 INFO ja/3.12: Publishing start.
2024-08-14 15:33:23,091 DEBUG ja/3.12: Run: 'chgrp -R docs /srv/docs.python.org/ja'
2024-08-14 15:33:23,177 DEBUG ja/3.12: Run: 'chgrp -R docs /srv/docs.python.org/ja/3.12'
2024-08-14 15:33:24,480 INFO ja/3.12: Copying HTML files to /srv/docs.python.org/ja/3.12
2024-08-14 15:33:24,481 DEBUG ja/3.12: Run: 'chown -R :docs /srv/docsbuild/cpython/Doc/build/html'
2024-08-14 15:33:24,488 DEBUG ja/3.12: Run: 'chmod -R o+r /srv/docsbuild/cpython/Doc/build/html'
2024-08-14 15:33:24,498 DEBUG ja/3.12: Run: "find /srv/docsbuild/cpython/Doc/build/html -type d -exec chmod o+x '{}' ';'"
2024-08-14 15:33:24,547 DEBUG ja/3.12: Run: "rsync -a --delete-delay --filter 'P archives/' /srv/docsbuild/cpython/Doc/build/html/ /srv/docs.python.org/ja/3.12"
2024-08-14 15:33:24,965 DEBUG ja/3.12: Copying dist files.
2024-08-14 15:33:24,965 DEBUG ja/3.12: Run: 'chown -R :docs /srv/docsbuild/cpython/Doc/dist'
2024-08-14 15:33:24,967 DEBUG ja/3.12: Run: 'chmod -R o+r /srv/docsbuild/cpython/Doc/dist'
2024-08-14 15:33:24,969 DEBUG ja/3.12: Run: 'mkdir -m o+rx -p /srv/docs.python.org/ja/3.12/archives'
2024-08-14 15:33:24,971 DEBUG ja/3.12: Run: 'chown :docs /srv/docs.python.org/ja/3.12/archives'
2024-08-14 15:33:24,973 DEBUG ja/3.12: Run: 'cp -a /srv/docsbuild/cpython/Doc/dist/python-3.12.5-docs-text.zip /srv/docsbuild/cpython/Doc/dist/python-3.12.5-docs-texinfo.zip /srv/docsbuild/cpython/Doc/dist/python-3.12.5-docs-text.tar.bz2 /srv/docsbuild/cpython/Doc/dist/python-3.12.5-docs-texinfo.tar.bz2 /srv/docsbuild/cpython/Doc/dist/python-3.12.5-docs-pdf-a4.tar.bz2 /srv/docsbuild/cpython/Doc/dist/python-3.12.5-docs-html.zip /srv/docsbuild/cpython/Doc/dist/python-3.12.5-docs-html.tar.bz2 /srv/docsbuild/cpython/Doc/dist/python-3.12.5-docs-pdf-letter.zip /srv/docsbuild/cpython/Doc/dist/python-3.12.5-docs-pdf-a4.zip /srv/docsbuild/cpython/Doc/dist/python-3.12.5-docs.epub /srv/docsbuild/cpython/Doc/dist/python-3.12.5-docs-pdf-letter.tar.bz2 /srv/docs.python.org/ja/3.12/archives'
2024-08-14 15:33:25,214 INFO ja/3.12: 886 files changed
2024-08-14 15:33:25,214 DEBUG ja/3.12: Run: 'find -L /srv/docs.python.org -samefile /srv/docs.python.org/ja/3.12'
2024-08-14 15:33:27,813 DEBUG ja/3.12: Purging https://docs.python.org/ja/3/ from CDN
2024-08-14 15:33:27,814 DEBUG ja/3.12: Starting new HTTPS connection (1): docs.python.org:443
2024-08-14 15:33:27,858 DEBUG ja/3.12: https://docs.python.org:443 "PURGE /ja/3/ HTTP/1.1" 200 53
<snip 5316 lines>
2024-08-14 15:34:58,559 DEBUG ja/3.12: Purging https://docs.python.org/ja/3.12/archives/python-3.12.3-docs-pdf-a4.tar.bz2 from CDN
2024-08-14 15:34:58,560 DEBUG ja/3.12: Starting new HTTPS connection (1): docs.python.org:443
2024-08-14 15:34:58,615 DEBUG ja/3.12: https://docs.python.org:443 "PURGE /ja/3.12/archives/python-3.12.3-docs-pdf-a4.tar.bz2 HTTP/1.1" 200 52
2024-08-14 15:34:58,618 INFO ja/3.12: Publishing done
2024-08-14 15:34:58,766 DEBUG ja/3.12: Run: 'git -C /srv/docsbuild/cpython rev-parse HEAD'
2024-08-14 15:34:58,770 DEBUG ja/3.12: Run: 'git -C /srv/docsbuild/3.12/locale/ja/LC_MESSAGES rev-parse HEAD'

The longest "start"/"done" times are:

2024-08-14 14:01:20,830 INFO ja/3.12: Build start.
...
2024-08-14 15:33:23,090 INFO ja/3.12: Build done.

This is the longest part of the build, taking about 90 minutes here.

(The slowest command is the actual Sphinx/latex/PDF build: make -C /srv/docsbuild/cpython/Doc ...)

This PR adds a duration to the "done" line:

2024-08-14 15:33:23,090 INFO ja/3.12: Build done (1h 32m 3s).

We also have a "Publishing start"/"Publishing done" pair, which can take a couple of minutes (#184) so I added it there too.

This means we can easily see how long they take in the logs, which will help us analyse build times for #169.

---

I added tests for the new format_seconds function, plus added it to the CI with linting.

It uses the match statement, new in Python 3.10, so that's the minimum required. The docs server uses 3.10 (although 3.12 is also installed).

[hugovk]

Updated to wrap "Full build start." / "Full build done (%s)." around the main build_docs() called from main() that builds all the languages and versions combinations.

This allows us to easily grep the daily build logs to see how long the single full build from the cron takes.

[willingc]

Thanks @hugovk for adding this and some standard code quality tools that we use in the rest of the docs ecosystem.