ci: add duration timestamps on all test jobs

ci/shell.nix

@@ -66,6 +66,7 @@ stdenv.mkDerivation ({
     rustStable
     wget
     zlib
+    moreutils
   ] ++ lib.optionals (!stdenv.isDarwin) [
     procps
     valgrind

ci/test-hw.yml

@@ -29,8 +29,8 @@ hardware core regular device test:
     - source hardware.cfg
     - set +a
     - nix-shell --run "cd ../.. && poetry install"
-    - nix-shell --run "poetry run python bootstrap.py tt ../../trezor-*.bin"
-    - nix-shell --run "poetry run pytest -m 'altcoin and not sd_card' $TESTS_SKIP ../../tests/device_tests"
+    - nix-shell --run "poetry run python bootstrap.py tt ../../trezor-*.bin | ts -s"
+    - nix-shell --run "poetry run pytest -m 'altcoin and not sd_card' $TESTS_SKIP ../../tests/device_tests | ts -s"
   timeout: 4h
   artifacts:
     name: "$CI_JOB_NAME-$CI_COMMIT_SHORT_SHA"
@@ -59,8 +59,8 @@ hardware core btconly device test:
     - source hardware.cfg
     - set +a
     - nix-shell --run "cd ../.. && poetry install"
-    - nix-shell --run "poetry run python bootstrap.py tt ../../trezor-*.bin"
-    - nix-shell --run "poetry run pytest -m 'not sd_card' $TESTS_SKIP ../../tests/device_tests"
+    - nix-shell --run "poetry run python bootstrap.py tt ../../trezor-*.bin | ts -s"
+    - nix-shell --run "poetry run pytest -m 'not sd_card' $TESTS_SKIP ../../tests/device_tests | ts -s"
   timeout: 4h
   artifacts:
     name: "$CI_JOB_NAME-$CI_COMMIT_SHORT_SHA"
@@ -86,8 +86,8 @@ hardware core monero test:
     - source hardware.cfg
     - set +a
     - nix-shell --run "cd ../.. && poetry install"
-    - nix-shell --run "poetry run python bootstrap.py tt ../../trezor-*.bin"
-    - nix-shell --arg fullDeps true --run "cd ../../core/tests && ./run_tests_device_emu_monero.sh $TESTOPTS"
+    - nix-shell --run "poetry run python bootstrap.py tt ../../trezor-*.bin | ts -s"
+    - nix-shell --arg fullDeps true --run "cd ../../core/tests && ./run_tests_device_emu_monero.sh $TESTOPTS | ts -s"
   timeout: 1h
   artifacts:
     name: "$CI_JOB_NAME-$CI_COMMIT_SHORT_SHA"
@@ -108,7 +108,7 @@ hardware legacy regular device test:
     - legacy fw regular debug build
   script:
     - cd ci/hardware_tests
-    - nix-shell --run "./t1_hw_test.sh"
+    - nix-shell --run "./t1_hw_test.sh | ts -s"
   timeout: 1h10m
   artifacts:
     name: "$CI_JOB_NAME-$CI_COMMIT_SHORT_SHA"
@@ -133,7 +133,7 @@ hardware legacy btconly device test:
     - legacy fw btconly debug build
   script:
     - cd ci/hardware_tests
-    - nix-shell --run "./t1_hw_test.sh"
+    - nix-shell --run "./t1_hw_test.sh | ts -s"
   artifacts:
     name: "$CI_JOB_NAME-$CI_COMMIT_SHORT_SHA"
     paths:

ci/test.yml

@@ -7,17 +7,17 @@ core unit test:
   needs:
     - core unix regular build
   script:
-    - nix-shell --run "poetry run make -C core test"
+    - nix-shell --run "poetry run make -C core test | ts -s"
 
 core device ui test:
   stage: test
   needs:
     - core unix frozen debug build
   script:
-    - nix-shell --run "poetry run make -C core test_emu_ui"
+    - nix-shell --run "poetry run make -C core test_emu_ui | ts -s"
   after_script:
     - mv tests/ui_tests/reporting/reports/test/ test_ui_report
-    - nix-shell --run "poetry run python ci/prepare_ui_artifacts.py"
+    - nix-shell --run "poetry run python ci/prepare_ui_artifacts.py | ts -s"
     - diff tests/ui_tests/fixtures.json tests/ui_tests/fixtures.suggestion.json
   artifacts:
     name: "$CI_JOB_NAME-$CI_COMMIT_SHORT_SHA"
@@ -40,7 +40,7 @@ core device test:
   variables:
     TREZOR_PROFILING: 1
   script:
-    - nix-shell --run "poetry run make -C core test_emu"
+    - nix-shell --run "poetry run make -C core test_emu | ts -s"
     - mv core/src/.coverage core/.coverage.test_emu
   artifacts:
     name: "$CI_JOB_NAME-$CI_COMMIT_SHORT_SHA"
@@ -61,7 +61,7 @@ core btconly device test:
     MICROPYTHON: "build/unix/trezor-emu-core-bitcoinonly"
     TREZOR_PYTEST_SKIP_ALTCOINS: 1
   script:
-    - nix-shell --run "poetry run make -C core test_emu"
+    - nix-shell --run "poetry run make -C core test_emu | ts -s"
   artifacts:
     name: "$CI_JOB_NAME-$CI_COMMIT_SHORT_SHA"
     paths:
@@ -79,7 +79,7 @@ core monero test:
   variables:
     TREZOR_PROFILING: 1
   script:
-    - nix-shell --arg fullDeps true --run "poetry run make -C core test_emu_monero"
+    - nix-shell --arg fullDeps true --run "poetry run make -C core test_emu_monero | ts -s"
     - mv core/src/.coverage core/.coverage.test_emu_monero
   artifacts:
     name: "$CI_JOB_NAME-$CI_COMMIT_SHORT_SHA"
@@ -97,8 +97,8 @@ core u2f test:
   variables:
     TREZOR_PROFILING: 1
   script:
-    - nix-shell --run "poetry run make -C tests/fido_tests/u2f-tests-hid"
-    - nix-shell --run "poetry run make -C core test_emu_u2f"
+    - nix-shell --run "poetry run make -C tests/fido_tests/u2f-tests-hid | ts -s"
+    - nix-shell --run "poetry run make -C core test_emu_u2f | ts -s"
     - mv core/src/.coverage core/.coverage.test_emu_u2f
   artifacts:
     name: "$CI_JOB_NAME-$CI_COMMIT_SHORT_SHA"
@@ -116,7 +116,7 @@ core fido2 test:
     TREZOR_PROFILING: 1
   script:
     - pgrep trezor-emu-core || true
-    - nix-shell --run "poetry run make -C core test_emu_fido2"
+    - nix-shell --run "poetry run make -C core test_emu_fido2 | ts -s"
     - pgrep trezor-emu-core || true
     - mv core/src/.coverage core/.coverage.test_emu_fido2
   artifacts:
@@ -135,7 +135,7 @@ core click test:
   needs:
     - core unix frozen debug build
   script:
-    - nix-shell --run "poetry run make -C core test_emu_click"
+    - nix-shell --run "poetry run make -C core test_emu_click | ts -s"
   artifacts:
     name: "$CI_JOB_NAME-$CI_COMMIT_SHORT_SHA"
     paths:
@@ -154,7 +154,7 @@ core upgrade test:
     TREZOR_UPGRADE_TEST: "core"
   script:
     - nix-shell --run "tests/download_emulators.sh"
-    - nix-shell --run "poetry run pytest --junitxml=tests/junit.xml tests/upgrade_tests"
+    - nix-shell --run "poetry run pytest --junitxml=tests/junit.xml tests/upgrade_tests | ts -s"
   artifacts:
     name: "$CI_JOB_NAME-$CI_COMMIT_SHORT_SHA"
     paths:
@@ -169,7 +169,7 @@ core persistence test:
   needs:
     - core unix frozen debug build
   script:
-    - nix-shell --run "poetry run pytest --junitxml=tests/junit.xml tests/persistence_tests"
+    - nix-shell --run "poetry run pytest --junitxml=tests/junit.xml tests/persistence_tests | ts -s"
   artifacts:
     name: "$CI_JOB_NAME-$CI_COMMIT_SHORT_SHA"
     paths:
@@ -195,8 +195,8 @@ crypto test:
     - ./crypto/tests/aestst
     - ./crypto/tests/test_check
     - ./crypto/tests/test_openssl 1000
-    - nix-shell --run "cd crypto && ITERS=10 poetry run pytest --junitxml=tests/junit.xml tests"
-    - nix-shell --run "CK_TIMEOUT_MULTIPLIER=20 valgrind -q --error-exitcode=1 ./crypto/tests/test_check"
+    - nix-shell --run "cd crypto && ITERS=10 poetry run pytest --junitxml=tests/junit.xml tests | ts -s"
+    - nix-shell --run "CK_TIMEOUT_MULTIPLIER=20 valgrind -q --error-exitcode=1 ./crypto/tests/test_check | ts -s"
   artifacts:
     name: "$CI_JOB_NAME-$CI_COMMIT_SHORT_SHA"
     paths:
@@ -216,7 +216,7 @@ legacy test:
   variables:
     EMULATOR: "1"
   script:
-    - nix-shell --run "poetry run legacy/script/test"
+    - nix-shell --run "poetry run legacy/script/test | ts -s"
   artifacts:
     name: "$CI_JOB_NAME-$CI_COMMIT_SHORT_SHA"
     paths:
@@ -235,7 +235,7 @@ legacy btconly test:
     EMULATOR_BINARY: "firmware/trezor-bitcoinonly.elf"
     TREZOR_PYTEST_SKIP_ALTCOINS: 1
   script:
-    - nix-shell --run "poetry run legacy/script/test"
+    - nix-shell --run "poetry run legacy/script/test | ts -s"
   artifacts:
     name: "$CI_JOB_NAME-$CI_COMMIT_SHORT_SHA"
     paths:
@@ -254,7 +254,7 @@ legacy upgrade test:
     TREZOR_UPGRADE_TEST: "legacy"
   script:
     - nix-shell --run "tests/download_emulators.sh"
-    - nix-shell --run "poetry run pytest --junitxml=tests/junit.xml tests/upgrade_tests"
+    - nix-shell --run "poetry run pytest --junitxml=tests/junit.xml tests/upgrade_tests | ts -s"
   artifacts:
     name: "$CI_JOB_NAME-$CI_COMMIT_SHORT_SHA"
     paths:
@@ -290,7 +290,7 @@ python test:
     # See also:
     # https://github.com/NixOS/nixpkgs/blob/b00c7c2d1d905eb63c81a0917f1a94b763a7843b/pkgs/development/interpreters/python/cpython/default.nix#L103
     # https://github.com/NixOS/nixpkgs/pull/98915
-    - nix-shell --arg fullDeps true --run "unset _PYTHON_SYSCONFIGDATA_NAME && cd python && poetry run tox"
+    - nix-shell --arg fullDeps true --run "unset _PYTHON_SYSCONFIGDATA_NAME && cd python && poetry run tox | ts -s"
 
 
 # Storage
@@ -304,8 +304,8 @@ storage test:
       - storage/**/*
   needs: []
   script:
-    - nix-shell --run "poetry run make -C storage/tests build"
-    - nix-shell --run "poetry run make -C storage/tests tests_all"
+    - nix-shell --run "poetry run make -C storage/tests build | ts -s"
+    - nix-shell --run "poetry run make -C storage/tests tests_all | ts -s"
   artifacts:
     name: "$CI_JOB_NAME-$CI_COMMIT_SHORT_SHA"
     paths:
@@ -326,8 +326,8 @@ core unix memory profiler:
     TREZOR_MEMPERF: "1"
     PYTEST_TIMEOUT: "900"
   script:
-    - nix-shell --run "poetry run make -C core build_unix_frozen"
-    - nix-shell --run "poetry run make -C core test_emu"
+    - nix-shell --run "poetry run make -C core build_unix_frozen | ts -s"
+    - nix-shell --run "poetry run make -C core test_emu | ts -s"
     - nix-shell --run "mkdir core/prof/memperf-html"
     - nix-shell --run "poetry run core/tools/alloc.py --alloc-data=core/src/alloc_data.txt html core/prof/memperf-html"
   artifacts: