diff --git a/.github/workflows/e2e.yml b/.github/workflows/e2e.yml index 0899ccd9..bd28c5ac 100644 --- a/.github/workflows/e2e.yml +++ b/.github/workflows/e2e.yml @@ -79,7 +79,7 @@ on: type: boolean default: false save_images: - description: 'e2e: save the image cache from this branch too (only main saves by default)' + description: 'e2e: save the image and data caches from this branch too (only main saves by default)' type: boolean default: false trace: @@ -395,6 +395,13 @@ jobs: sudo mkdir -p "$work" && sudo chown "$(id -u):$(id -g)" "$work" fi echo "E2E_WORK=${work}" >> "$GITHUB_ENV" + # One fixed path: actions/cache counts the path in an entry's + # version, so a path that followed the work area would miss on a + # runner that picked the other disk. e2e-run.sh hard-links the + # cached downloads into the work area, or copies them when the + # work area is on /mnt. + mkdir -p "${RUNNER_TEMP}/e2e-data" + echo "E2E_DATA_CACHE=${RUNNER_TEMP}/e2e-data" >> "$GITHUB_ENV" - uses: actions/setup-java@b843ebf9b913146b38da2eaa7aeddf76074ae1ad # v6.1.0 with: @@ -493,6 +500,8 @@ jobs: echo "$(wc -l < "$list") cases: $(paste -sd' ' "$list")" grep -qx nextflow-from-fastq-2-nextflow "$list" && echo "parity_fastq=true" >> "$GITHUB_OUTPUT" grep -qx nextflow-hardening-2-nf "$list" && echo "parity_hardening=true" >> "$GITHUB_OUTPUT" + grep -qx mocha-1 "$list" && echo "data_mocha=true" >> "$GITHUB_OUTPUT" + grep -qx archaic-ancestry-1 "$list" && echo "data_archaic=true" >> "$GITHUB_OUTPUT" echo "list=${list}" >> "$GITHUB_OUTPUT" # Before the base outputs: the base leg pulled the same images. @@ -535,6 +544,38 @@ jobs: echo "::error::Could not fetch e2e-base in 5 tries." exit 1 + # The two largest downloads of the cases, from EBI's 1000 Genomes + # server, which is slow and stalls at times: MoChA's chr20 panel and + # its manifest (mocha-1, 0.64 GB), keyed on the manifest's pin and the + # chromosome (the whole raw chr20 panel, which no fixture changes), and the 1000 + # Genomes sites VCF (archaic-ancestry-1, 1.36 GB), keyed on its md5. + # e2e-run.sh hands them to the two cases ("Downloads kept between + # runs" there) and downloads what a miss leaves out. Saved like the + # images: on main, or a run by hand with save_images, on a miss. Only + # the leg whose cases include the case restores and saves its entry. + - name: Data cache keys + id: data-keys + run: | + . versions.env + echo "mocha=e2e-data-mocha-${MOCHA_PANEL_MANIFEST_SHA256:0:16}-chr20" | tee -a "$GITHUB_OUTPUT" + echo "archaic=e2e-data-1kg-sites-${ARCHAIC_1KG_SITES_MD5}" | tee -a "$GITHUB_OUTPUT" + + - name: Restore cached data, MoChA panel + id: data-mocha + if: steps.cases-list.outputs.data_mocha == 'true' + uses: actions/cache/restore@55cc8345863c7cc4c66a329aec7e433d2d1c52a9 # v6.1.0 + with: + path: ${{ env.E2E_DATA_CACHE }}/mocha + key: ${{ steps.data-keys.outputs.mocha }} + + - name: Restore cached data, 1000 Genomes sites + id: data-archaic + if: steps.cases-list.outputs.data_archaic == 'true' + uses: actions/cache/restore@55cc8345863c7cc4c66a329aec7e433d2d1c52a9 # v6.1.0 + with: + path: ${{ env.E2E_DATA_CACHE }}/archaic + key: ${{ steps.data-keys.outputs.archaic }} + - name: Run the e2e cases id: cases env: @@ -544,7 +585,50 @@ jobs: E2E_TRACE: ${{ needs.e2e-plan.outputs.trace }} E2E_BASE_OUT: ${{ matrix.job == 'base' && format('{0}/base.tar.zst', runner.temp) || '' }} E2E_BASE_IN: ${{ matrix.job != 'base' && format('{0}/e2e-base/base.tar.zst', runner.temp) || '' }} - run: scripts/ci/e2e-run.sh + # Keep the downloads to the end of the job only when a save step uses them. + E2E_DATA_KEEP: ${{ (github.ref == 'refs/heads/main' || inputs.save_images) && ((steps.cases-list.outputs.data_mocha == 'true' && steps.data-mocha.outputs.cache-hit != 'true') || (steps.cases-list.outputs.data_archaic == 'true' && steps.data-archaic.outputs.cache-hit != 'true')) && 'true' || 'false' }} + HIT_MOCHA: ${{ steps.data-mocha.outputs.cache-hit || 'false' }} + HIT_ARCHAIC: ${{ steps.data-archaic.outputs.cache-hit || 'false' }} + DATA_MOCHA: ${{ steps.cases-list.outputs.data_mocha || 'false' }} + DATA_ARCHAIC: ${{ steps.cases-list.outputs.data_archaic || 'false' }} + run: | + if [ "$DATA_MOCHA" = true ] || [ "$DATA_ARCHAIC" = true ]; then + echo "Data cache (${JOB}): exact key hit, MoChA panel ${HIT_MOCHA}, 1000 Genomes sites ${HIT_ARCHAIC}" | tee -a "$GITHUB_STEP_SUMMARY" + fi + scripts/ci/e2e-run.sh + + # A miss saves what e2e-run.sh downloaded, checked against its pin + # (data_fetch there), when every file of the entry is in place. + - name: Data cache, what to save + id: data-save + if: >- + always() && steps.cases.outcome != 'skipped' && + (github.ref == 'refs/heads/main' || inputs.save_images) + env: + HIT_MOCHA: ${{ steps.data-mocha.outputs.cache-hit }} + HIT_ARCHAIC: ${{ steps.data-archaic.outputs.cache-hit }} + run: | + d=$E2E_DATA_CACHE + if [ "$HIT_MOCHA" != true ] && [ -s "${d}/mocha/manifest.txt" ] \ + && [ "$(find "${d}/mocha/raw" -type f ! -name '*.part' 2> /dev/null | wc -l)" -eq 2 ]; then + echo "mocha=true" >> "$GITHUB_OUTPUT" + fi + if [ "$HIT_ARCHAIC" != true ] && [ -s "${d}/archaic/1kg_sites.vcf.gz" ]; then + echo "archaic=true" >> "$GITHUB_OUTPUT" + fi + du -sh "${d}"/* 2> /dev/null || echo "Data cache: nothing downloaded" + + - uses: actions/cache/save@55cc8345863c7cc4c66a329aec7e433d2d1c52a9 # v6.1.0 + if: always() && steps.data-save.outputs.mocha == 'true' + with: + path: ${{ env.E2E_DATA_CACHE }}/mocha + key: ${{ steps.data-keys.outputs.mocha }} + + - uses: actions/cache/save@55cc8345863c7cc4c66a329aec7e433d2d1c52a9 # v6.1.0 + if: always() && steps.data-save.outputs.archaic == 'true' + with: + path: ${{ env.E2E_DATA_CACHE }}/archaic + key: ${{ steps.data-keys.outputs.archaic }} - name: Upload the base outputs if: matrix.job == 'base' @@ -617,9 +701,10 @@ jobs: # readable by that pull request alone, and every entry counts against # the repository's 10 GB, so it would only push main's entries out. # Each group keeps its smallest images up to GROUP_BUDGET_MB of zstd - # output; the rest are pulled on every run. Four groups of 1900 MB are - # 7.4 GB, and while main replaces one group the old and the new entry - # both count: 9.3 GB, under the 10 GB limit. An image pinned by digest + # output; the rest are pulled on every run. Four groups of 1500 MB are + # 5.9 GB, and while main replaces one group the old and the new entry + # both count: 7.3 GB. With the two data entries above (2.0 GB) that is + # 9.3 GB, under the 10 GB limit. An image pinned by digest # is never saved: docker load gives it back without its digest, so # e2e-run.sh would pull it again anyway. - name: Image sizes, and save images for the next run @@ -627,7 +712,7 @@ jobs: if: always() && matrix.job == 'base' && steps.keys.outcome == 'success' env: SAVE: ${{ (github.ref == 'refs/heads/main' || inputs.save_images) && 'true' || 'false' }} - GROUP_BUDGET_MB: 1900 + GROUP_BUDGET_MB: 1500 HIT0: ${{ steps.images0.outputs.cache-hit }} HIT1: ${{ steps.images1.outputs.cache-hit }} HIT2: ${{ steps.images2.outputs.cache-hit }} diff --git a/.github/workflows/repeat-test.yml b/.github/workflows/repeat-test.yml new file mode 100644 index 00000000..33addbd1 --- /dev/null +++ b/.github/workflows/repeat-test.yml @@ -0,0 +1,130 @@ +name: Repeat a test + +# Runs one test many times, each run in a fresh job on its own runner, to +# tell a flaky test from a broken one: a flake fails a few runs out of many, +# a broken test fails them all. Start it from the Actions tab with the test's +# path and the number of runs. It also runs on a pull request that changes +# this file, with the defaults, so a change to it is seen working. +# +# One extra run, "control", runs a test that always fails. The summary +# counts the failed runs and fails when any did, or when the control did +# not fail, so a count of zero failures is never a count that could not +# see one. +on: + workflow_dispatch: + inputs: + test: + description: "Test to repeat (a tests/test_*.sh or tests/test_*.py)" + default: tests/test_annotsv_benign_mane.sh + runs: + description: "How many runs (1 to 60)" + default: "30" + pull_request: + branches: [main] + paths: [.github/workflows/repeat-test.yml] + +permissions: + contents: read + +concurrency: + group: ${{ github.workflow }}-${{ github.ref }} + cancel-in-progress: true + +env: + TEST: ${{ inputs.test || 'tests/test_annotsv_benign_mane.sh' }} + RUNS: ${{ inputs.runs || '30' }} + +jobs: + plan: + runs-on: ubuntu-latest + timeout-minutes: 5 + outputs: + runs: ${{ steps.plan.outputs.runs }} + steps: + - uses: actions/checkout@3d3c42e5aac5ba805825da76410c181273ba90b1 # v7.0.1 + + - name: Check the inputs and list the runs + id: plan + run: | + case "$TEST" in + tests/test_*.sh|tests/test_*.py) ;; + *) echo "ERROR: '${TEST}' is not a tests/test_*.sh or tests/test_*.py"; exit 1 ;; + esac + [ -f "$TEST" ] || { echo "ERROR: ${TEST} does not exist"; exit 1; } + case "$RUNS" in ''|*[!0-9]*) echo "ERROR: runs must be a whole number, got '${RUNS}'"; exit 1 ;; esac + n=$((10#$RUNS)) + [ "$n" -ge 1 ] && [ "$n" -le 60 ] || { echo "ERROR: runs must be 1 to 60, got ${n}"; exit 1; } + echo "runs=$( (seq 1 "$n"; echo control) | jq -R . | jq -sc .)" >> "$GITHUB_OUTPUT" + echo "${TEST}: ${n} runs and the control" + + run: + needs: plan + name: run ${{ matrix.run }} + runs-on: ubuntu-latest + timeout-minutes: 30 + strategy: + fail-fast: false + # GitHub runs at most 20 jobs at once on this account; leave room for + # the other workflows. + max-parallel: 6 + matrix: + run: ${{ fromJSON(needs.plan.outputs.runs) }} + steps: + - uses: actions/checkout@3d3c42e5aac5ba805825da76410c181273ba90b1 # v7.0.1 + + # The step records the test's exit code in the name of a small + # artifact and passes, so a failed test leaves the job green and the + # summary below is the one place that counts. + - name: Run the test + env: + RUN: ${{ matrix.run }} + run: | + t=$TEST + if [ "$RUN" = control ]; then + t="${RUNNER_TEMP}/test_planted.sh" + echo 'echo "planted failure"; exit 1' > "$t" + fi + rc=0 + case "$t" in + *.py) python3 "$t" || rc=$? ;; + *) bash "$t" || rc=$? ;; + esac + echo "run ${RUN}: exit ${rc}" + echo "$rc" > "${RUNNER_TEMP}/rc" + echo "RC=${rc}" >> "$GITHUB_ENV" + + - uses: actions/upload-artifact@cf430e030ddbb5b0abf93d22962f4752f3646cd9 # v7.0.2 + with: + name: result-${{ matrix.run }}-exit-${{ env.RC }} + path: ${{ runner.temp }}/rc + # A rerun of a job may write the same name again. + overwrite: true + retention-days: 1 + + summary: + needs: [plan, run] + if: always() && needs.plan.result == 'success' + runs-on: ubuntu-latest + timeout-minutes: 5 + permissions: + actions: read + steps: + - name: Count the failed runs + env: + GH_TOKEN: ${{ github.token }} + run: | + gh api --paginate "repos/${GITHUB_REPOSITORY}/actions/runs/${GITHUB_RUN_ID}/artifacts" \ + -q '.artifacts[] | select(.name | startswith("result-")) | "\(.created_at)\t\(.id)\t\(.name)"' \ + | sort -t$'\t' -k1,1 -k2,2n \ + | sed -n 's/^.*\tresult-\(.*\)-exit-\([0-9]*\)$/\1\t\2/p' \ + | awk -F'\t' '{ last[$1] = $2 } END { for (s in last) print s "\t" last[s] }' > results.tsv + # A rerun leaves the old attempt's artifact beside the new one; + # the newest result of each run counts. + sort -V results.tsv + ctl=$(awk -F'\t' '$1 == "control" {print $2}' results.tsv) + [ -n "$ctl" ] && [ "$ctl" -ne 0 ] || { echo "FAIL: the control run should fail, its exit is '${ctl:-missing}'"; exit 1; } + n=$(awk -F'\t' '$1 != "control"' results.tsv | wc -l) + bad=$(awk -F'\t' '$1 != "control" && $2 != 0' results.tsv | wc -l) + echo "${TEST}: ${bad} of ${n} runs failed (the control failed, as it should)." | tee -a "$GITHUB_STEP_SUMMARY" + [ "$n" -eq "$((10#$RUNS))" ] || { echo "FAIL: ${n} results found, ${RUNS} runs planned"; exit 1; } + [ "$bad" -eq 0 ] || { echo "FAIL: runs that failed: $(awk -F'\t' '$1 != "control" && $2 != 0 {print $1}' results.tsv | paste -sd' ' -)"; exit 1; } diff --git a/docs/lessons-learned.md b/docs/lessons-learned.md index c115df03..b121b943 100644 --- a/docs/lessons-learned.md +++ b/docs/lessons-learned.md @@ -616,3 +616,15 @@ Most bioinformatics containers run as non-root users. If writing to bind-mounted - **Failed:** `setup.sh --archaic` stopped on a wrong md5 for the 1000 Genomes phase 3 sites VCF (about 1.5 GB) in the e2e case `archaic-ancestry-1`. Other runs on the same day downloaded the same file with the right md5. - **Why:** `fetch` tried a download again only when the transfer itself failed. A transfer that finished with the wrong bytes failed its check, and `fetch` deleted it and returned 1 at once, so one bad transfer ended the run. - **Fix:** a download that fails its checksum, `gzip -t` or non-empty check is deleted and downloaded again from the start, up to `FETCH_TRIES` tries `FETCH_WAIT` apart, the same budget as a broken transfer. A broken transfer still keeps its `.part` and the next try resumes it. `tests/test_fetch_retry.sh` serves a bad file once and then the right one, and a bad file every time, and checks both against a mutant that returns at the first failed check. + +## CI flakes (2026-11) + +### AnnotSV's merge run in `setup.sh` failed in two seconds +- **Failed:** `tests/test_annotsv_benign_mane.sh` failed now and then with `setup.sh --annotsv-data` exiting 1, and the rerun passed. Its log showed AnnotSV's merge run ending with exit 125 two seconds after it started, and the gnomAD-SV file left unmerged. +- **Why:** the merge run was the first use of the AnnotSV image on the runner, so `docker run` pulled it. One pull broke off (`short read: expected 603618355 bytes but got 8388608: unexpected EOF`), and `docker run` does not try a pull again: it exits 125 before AnnotSV starts. +- **Fix:** `annotsv_merge_benign` pulls the image first with `pull_image`, which tries `FETCH_TRIES` times. The **Repeat a test** workflow (`.github/workflows/repeat-test.yml`) runs the test 30 times on fresh runners to show it no longer flakes. + +### A slow download used up an e2e case's hour +- **Failed:** `archaic-ancestry-1` ran into the 3600-second case timeout on one e2e run (run 40933547961, attempt 1) and pushed the job past its own limit; the rerun passed. +- **Why:** `setup.sh --archaic` downloads the 1000 Genomes phase 3 sites VCF (1.36 GB) from EBI. On that run EBI sent it at about 440 KB/s, and the download alone took 53 minutes, so the case's Nextflow half started with minutes left. The download never stopped: it was slow, not stalled. MoChA's chr20 panel in `mocha-1` comes from the same server. +- **Fix:** the e2e job caches both files (keyed on their pins) and `scripts/ci/e2e-run.sh` hands them to the two cases, so a run with a cache hit downloads neither. Separately, `_get` now bounds a real stall, which nothing did before: `curl` gets `--connect-timeout 30 --speed-limit 1024 --speed-time ${FETCH_STALL:-120}`, so a transfer under 1 KB/s for two minutes fails and `fetch` tries again, resuming the `.part`. `wget` gets `--connect-timeout=30 --read-timeout=${FETCH_STALL:-120}`, which fails only when no data arrives for that long. A slow but moving transfer like the one above is left alone. diff --git a/docs/testing.md b/docs/testing.md index 081508b5..d5897e63 100644 --- a/docs/testing.md +++ b/docs/testing.md @@ -86,7 +86,9 @@ To measure the table again, run the E2E workflow by hand with `job: e2e` and `tr Every pull request starts the workflow. Its `e2e-scope` job checks whether the pull request touches `scripts/`, `modules/`, `workflows/`, `bin/`, `conf/`, `assets/`, `tests/e2e/`, `tests/fixtures/VERSION`, `main.nf`, `nextflow.config`, `versions.env` or the workflow itself. When it touches none of them the plan and the legs are skipped and the job `e2e` passes without running anything, so main can require the e2e check without blocking a docs-only change. The e2e job also runs once a month and by hand (`job: e2e`). It also runs on main after every merge that touches those paths, because main does not require a branch to be up to date before it merges: two pull requests that land close together each passed alone, and only the run on main tests them together. A docs-only merge starts no run. A run on main is never cancelled half way. A merge that lands while one runs waits, and GitHub keeps one waiting run, so a newer merge replaces the waiting one and the next run tests every merge since the last run. A red run on main names its commit, the newest merge it tested; the merges between the last green run on main and that commit are the suspects. The push paths in `e2e.yml` and the `E2E_SCOPE_DIRS` and `E2E_SCOPE_FILES` lists that `e2e-scope` reads are the same scope written twice, and the first step of `e2e-plan` fails when they differ. A push to any other branch starts no run: its pull request runs e2e, and an `e2e` check from a push run would sit on the same commit as the pull request's required `e2e` check. The DeepVariant case passes the fixture slices as `INTERVALS`, so DeepVariant calls only those slices instead of walking all 1.8 Gb of the reference, which alone took 27 to 48 minutes. It uses a standard GitHub-hosted runner (4 CPUs, 16 GB of RAM) after deleting preinstalled toolchains it does not use (Android, .NET, Haskell, CodeQL, Boost) to make disk room. -The images the cases use are cached in four GitHub Actions cache entries, one per group. `scripts/ci/e2e-run.sh --image-groups` names each image's group, taken from its repository name without the tag, so a version bump changes the key of one group only; a group whose key missed restores the newest older entry of that group and pulls only what changed. A group keeps its smallest images up to 1900 MB of zstd output, and the larger ones are pulled on every run. Four groups of 1900 MB stay under the repository's 10 GB cache limit even while main replaces one of them. Images pinned by digest are not cached, because `docker load` gives them back without the digest, and they are left out of the group's key, so a digest bump misses no entry. Only the base leg saves, and only on main (or in a run by hand with `save_images`, on any branch), after it pulled every image the cases use and got through its cases, and only the groups whose key missed: a cache saved by a pull request can be read by that pull request alone and would only push main's entries out. The job summary lists every image with its size and what the cache did with it: restored on an exact key hit, restored from an older entry, saved, or pulled. Every merge in the e2e scope starts a run on main, so the cache follows main's images. GitHub drops an entry no run has read for 7 days, so after a quiet week the next run on main fills the cache again. Until this layout the cache was one entry, and by October 2026 it had grown to about 11 GB, over the limit, so every run missed it. +The images the cases use are cached in four GitHub Actions cache entries, one per group. `scripts/ci/e2e-run.sh --image-groups` names each image's group, taken from its repository name without the tag, so a version bump changes the key of one group only; a group whose key missed restores the newest older entry of that group and pulls only what changed. A group keeps its smallest images up to 1500 MB of zstd output, and the larger ones are pulled on every run. Four groups of 1500 MB and the two data entries below stay under the repository's 10 GB cache limit even while main replaces one group: 5.9 GB of images, 1.5 GB more for the group being replaced, and 2.0 GB of data. Images pinned by digest are not cached, because `docker load` gives them back without the digest, and they are left out of the group's key, so a digest bump misses no entry. Only the base leg saves, and only on main (or in a run by hand with `save_images`, on any branch), after it pulled every image the cases use and got through its cases, and only the groups whose key missed: a cache saved by a pull request can be read by that pull request alone and would only push main's entries out. The job summary lists every image with its size and what the cache did with it: restored on an exact key hit, restored from an older entry, saved, or pulled. Every merge in the e2e scope starts a run on main, so the cache follows main's images. GitHub drops an entry no run has read for 7 days, so after a quiet week the next run on main fills the cache again. Until this layout the cache was one entry, and by October 2026 it had grown to about 11 GB, over the limit, so every run missed it. + +Two downloads are cached the same way, because they come from EBI's 1000 Genomes server, which is slow and at times stalls: MoChA's chr20 panel with its manifest (0.64 GB, case `mocha-1`), keyed on `MOCHA_PANEL_MANIFEST_SHA256` and the chromosome, and the 1000 Genomes phase 3 sites VCF (1.36 GB, case `archaic-ancestry-1`), keyed on `ARCHAIC_1KG_SITES_MD5`. `scripts/ci/e2e-run.sh` hands each case its files just before it runs, at the paths `setup.sh` reads them from, so `setup.sh` downloads nothing; on a miss it downloads them first, checked against their pins. Only the leg whose cases include the case restores and saves its entry, and it saves only on main or in a run by hand with `save_images`, as with the images. The job summary says whether each key hit, and the case's log says where its files came from. Every download, there and in `setup.sh`, gives up on a transfer that stalls (`FETCH_STALL`, see `fetch` in `scripts/lib/common.sh`), and the next try resumes it. How long it took in one job, before the split: a passing e2e job took about 105 to 205 minutes with 84 cases, and 230 minutes of cases with 130 (run 41390434697, 2026-11-02). The runner decides much of it, not the cache: the same CPU model took 106 minutes in one run and 166 in another. In October 2026, with 84 cases, the same code took 106 and 166 minutes on an AMD EPYC 9V45 (runs 39197502832 and 39075176392, the second of which also saved the cache), 112 minutes on an Intel Xeon 6973P (run 39088086725), 156 and 191 minutes on an AMD EPYC 7763 (runs 39075764278 and 39075201465) and 205 minutes on an AMD EPYC 9V74 (run 39197512594, which saved three groups). The image cache saves about 7 minutes of that: pulling every image took 9 minutes, restoring and loading the four groups took 2.5 (run 39075201465 restored 39 images in 118 seconds), and saving them all took 12. Each leg has a limit of 240 minutes (355 for a traced shard leg); the base leg waits up to 75 minutes for a fixture a pull request bumps. Each leg's first steps print the runner's CPU model and CPU count to the log and the job summary, so a later timing can name the hardware. @@ -189,3 +191,7 @@ It writes DEMO-001 from a fixed seed (`tests/demo/make_demo_sample.py`; no real The **Demo pictures** workflow ([`.github/workflows/demo-pictures.yml`](https://github.com/GeiserX/Personal-Genome-Pipeline/blob/main/.github/workflows/demo-pictures.yml)) retakes them on `ubuntu-latest`, by hand or on a pull request that changes `tests/demo/` or the workflow. It sets `PLAYWRIGHT_WITH_DEPS=1`, so Playwright installs Chromium's system libraries itself, and returns the pictures as the `demo-pictures` artifact. On Linux the check reads the PNG chunks only, because the OCR half needs macOS: run `tests/demo/check_pictures.py --ocr` on a Mac before you commit pictures from the artifact. The workflow writes nothing to the repository. Look at the pictures, copy them into `docs/images/`, and update the alt text where the cards changed. A new report card that the generator does not feed yet stops the script with its name; add its input file to `make_demo_sample.py`. + +## Telling a flaky test from a broken one + +The **Repeat a test** workflow (`.github/workflows/repeat-test.yml`) runs one `tests/test_*.sh` or `tests/test_*.py` many times, each run in a fresh job on its own `ubuntu-latest` runner, six at a time. Start it from the Actions tab with the test's path and the number of runs (1 to 60, default 30); it also runs, with its defaults (`tests/test_annotsv_benign_mane.sh`, 30 runs), on a pull request that changes the workflow. A flaky test fails a few runs out of many; a broken one fails them all. Each run records its exit code, and the summary job lists every run and fails when any failed. One more run, `control`, runs a test that always fails, and the summary fails when the control passed, so "0 of 30 failed" is never a count that could not see a failure. diff --git a/scripts/ci/e2e-run.sh b/scripts/ci/e2e-run.sh index 12027f40..375e50ee 100755 --- a/scripts/ci/e2e-run.sh +++ b/scripts/ci/e2e-run.sh @@ -28,6 +28,8 @@ # earlier case wrote each file it read (atime and ctime, with # the file systems remounted strictatime; needs sudo), in # $E2E_WORK/report/trace.tsv for `e2e-shards.sh times` +# E2E_DATA_CACHE a folder of downloads kept between runs (see "Downloads +# kept between runs" below); E2E_DATA_KEEP=true keeps it whole # # Every run writes $E2E_WORK/report/results.tsv ("CASE RESULT SECONDS JOB", # tab-separated) and report/extra.md (failed checks and notes), which the @@ -319,6 +321,86 @@ else echo "=== Partial run ('${PATTERN}'): no pre-pull, each case pulls what it uses ===" fi +# --- Downloads kept between runs ---------------------------------------------- +# The two largest downloads of the cases come from EBI's 1000 Genomes server, +# which is slow and stalls at times: MoChA's chr20 panel (mocha-1, about +# 655 MB, with its manifest) and the 1000 Genomes phase 3 sites VCF +# (archaic-ancestry-1, about 1.5 GB). With E2E_DATA_CACHE set (the e2e +# workflow restores it from the Actions cache), the runner gives each of +# these cases its files before it starts, at the paths setup.sh reads them +# from, so setup.sh finds them and downloads nothing. A file missing from +# E2E_DATA_CACHE is downloaded there first, checked against its pin. The +# files are hard links where they can be (setup.sh deletes its copy, the +# cache keeps its own). Without E2E_DATA_KEEP=true (the workflow sets it on +# a run that saves the cache) a case's cached files are deleted after it, +# to give the disk back. +DATA_CACHE=${E2E_DATA_CACHE:-} +# data_fetch NAME: fills E2E_DATA_CACHE/NAME with what is missing, in a +# subshell that sources scripts/lib/common.sh for fetch and the pins. +data_fetch() ( + d="${DATA_CACHE}/$1" + # shellcheck source=../lib/common.sh + . "${REPO}/scripts/lib/common.sh" || exit 1 + case "$1" in + mocha) + m="${d}/manifest.txt" + { [ -s "$m" ] && [ "$(_digest sha256 "$m")" = "$MOCHA_PANEL_MANIFEST_SHA256" ]; } \ + || fetch "${MOCHA_PANEL_URL}/20220804_manifest.txt" "$m" sha256 "$MOCHA_PANEL_MANIFEST_SHA256" || exit 1 + # mocha-1 cuts the panel to the fixture's chr20 slice. + f=1kGP_high_coverage_Illumina.chr20.filtered.SNV_INDEL_SV_phased_panel.vcf.gz + for e in "" .tbi; do + md5=$(awk -v n="${f}${e}" '$1 == n {print $2}' "$m") + [ -n "$md5" ] || { echo "ERROR: ${f}${e} is not in the panel manifest" >&2; exit 1; } + [ -s "${d}/raw/${f}${e}" ] && [ "$(_digest md5 "${d}/raw/${f}${e}")" = "$md5" ] && continue + fetch "${MOCHA_PANEL_URL}/${f}${e}" "${d}/raw/${f}${e}" md5 "$md5" || exit 1 + done ;; + archaic) + url=$(sed -n 's/^ARCHAIC_1KG_SITES_URL=//p' "${REPO}/scripts/setup.sh") + [ -n "$url" ] || { echo "ERROR: no ARCHAIC_1KG_SITES_URL line in scripts/setup.sh" >&2; exit 1; } + s="${d}/1kg_sites.vcf.gz" + [ -s "$s" ] && [ "$(_digest md5 "$s")" = "$ARCHAIC_1KG_SITES_MD5" ] && exit 0 + fetch "$url" "$s" md5 "$ARCHAIC_1KG_SITES_MD5" || exit 1 ;; + *) echo "ERROR: no data cache entry ${1}" >&2; exit 1 ;; + esac +) +# data_name CASE: the E2E_DATA_CACHE entry CASE reads, and where setup.sh wants it. +data_name() { + # shellcheck source=../../versions.env + case "$1" in + mocha-1.sh) echo "mocha ${GENOME_DIR}/reference/mocha-$(. "${REPO}/versions.env" && echo "$MOCHA_PANEL_VERSION")" ;; + archaic-ancestry-1.sh) echo "archaic ${GENOME_DIR}/reference/archaic/$(. "${REPO}/versions.env" && echo "$ARCHAIC_DATA_VERSION")/download" ;; + esac +} +# data_seed CASE: before CASE, its files from E2E_DATA_CACHE. A failure here +# only warns and costs the download: setup.sh in the case fetches what is +# not there. +data_seed() { + local n dest f t + [ -n "$DATA_CACHE" ] || return 0 + read -r n dest <<< "$(data_name "$1")" + [ -n "$n" ] || return 0 + if [ -n "$(find "${DATA_CACHE}/${n}" -type f ! -name '*.part' 2> /dev/null | head -n 1)" ]; then + echo "Data cache: ${n} restored from the Actions cache" + else + echo "Data cache: ${n} not in the Actions cache; downloading it" + fi + data_fetch "$n" || { echo "::warning::Data cache: could not fill ${n}; ${1%.sh} downloads it itself"; return 0; } + while IFS= read -r f; do + t="${dest}/${f#./}" + mkdir -p "${t%/*}" \ + && { ln -f "${DATA_CACHE}/${n}/${f#./}" "$t" 2> /dev/null || cp -f "${DATA_CACHE}/${n}/${f#./}" "$t"; } \ + || echo "::warning::Data cache: could not place ${f#./}; ${1%.sh} downloads it itself" + done < <(cd "${DATA_CACHE}/${n}" && find . -type f ! -name '*.part') + echo "Data cache: ${n}: $(cd "${DATA_CACHE}/${n}" && find . -type f ! -name '*.part' | wc -l | tr -d ' ') files in ${dest}" +} +# data_drop CASE: after CASE, its cache files go, unless this run saves them. +data_drop() { + local n dest + [ -n "$DATA_CACHE" ] && [ "${E2E_DATA_KEEP:-false}" != true ] || return 0 + read -r n dest <<< "$(data_name "$1")" + [ -z "$n" ] || rm -rf "${DATA_CACHE:?}/${n}" +} + # --- Trace ------------------------------------------------------------------- # With E2E_TRACE=true each case's reads are told apart by atime, which only # moves on every read under strictatime, and its writes by ctime, which no @@ -388,10 +470,12 @@ for c in "${CASES[@]}"; do start=$(date +%s) tstart=$(date +%s.%N) echo "::group::${name}" + data_seed "$c" set +e timeout -k 30 "$CASE_TIMEOUT" bash "${REPO}/tests/e2e/${c}" 2>&1 | tee "$log" rc=${PIPESTATUS[0]} set -e + data_drop "$c" echo "::endgroup::" case "$rc" in 0) result=pass ;; diff --git a/scripts/lib/common.sh b/scripts/lib/common.sh index 10e15c7f..836ccbac 100644 --- a/scripts/lib/common.sh +++ b/scripts/lib/common.sh @@ -346,22 +346,35 @@ consumer_sites_digest() { # _get URL OUT: download URL to OUT (resuming a partial OUT), curl first and # wget when curl is missing. OUT "-" writes to stdout. A server that cannot # resume (curl exit 33) gets the partial OUT dropped and one fresh download. +# +# A stalled transfer fails instead of hanging: curl gives up on a connection +# that takes over 30 s, or a transfer slower than 1 KB/s for FETCH_STALL +# seconds (default 120); wget on a connection over 30 s, or no data for +# FETCH_STALL seconds, with no retry of its own. fetch then tries again, +# resuming the partial OUT. _get() { - local rc=0 + local rc=0 stall=${FETCH_STALL:-120} + # 10# so 00, 08 and 09 read as decimal; curl and wget take 0 as no bound. + case "$stall" in ''|*[!0-9]*) stall=0 ;; esac + [ "$((10#$stall))" -gt 0 ] || { echo "ERROR: FETCH_STALL must be a whole number of seconds above 0, got '${FETCH_STALL}'" >&2; return 1; } + # The URL stays the last argument (scripts/ci/fake-docker/curl takes it from there). + local cbound=(--connect-timeout 30 --speed-limit 1024 --speed-time "$stall") if command -v curl >/dev/null 2>&1; then if [ "$2" = "-" ]; then - curl -fsSL "$1" + curl -fsSL "${cbound[@]}" "$1" else - curl -fL -C - -o "$2" "$1" || rc=$? + curl -fL "${cbound[@]}" -C - -o "$2" "$1" || rc=$? if [ "$rc" -eq 33 ]; then rm -f "$2" - curl -fL -o "$2" "$1" + curl -fL "${cbound[@]}" -o "$2" "$1" else return "$rc" fi fi elif command -v wget >/dev/null 2>&1; then - if [ "$2" = "-" ]; then wget -q -O - "$1"; else wget -c -O "$2" "$1"; fi + # --tries=1: fetch does the retries, as it does for curl. + local wbound=(--connect-timeout=30 "--read-timeout=${stall}" --tries=1) + if [ "$2" = "-" ]; then wget -q "${wbound[@]}" -O - "$1"; else wget -c "${wbound[@]}" -O "$2" "$1"; fi else echo "ERROR: neither curl nor wget is installed." >&2 return 1 diff --git a/scripts/setup.sh b/scripts/setup.sh index 42ca1c4a..78265b5f 100755 --- a/scripts/setup.sh +++ b/scripts/setup.sh @@ -1424,6 +1424,14 @@ annotsv_merge_benign() { '##FORMAT=' > "${probe}/probe.vcf" printf '#CHROM\tPOS\tID\tREF\tALT\tQUAL\tFILTER\tINFO\tFORMAT\tprobe\n' >> "${probe}/probe.vcf" printf 'chr20\t1000001\tsetup_probe\tN\t\t100\tPASS\tEND=1001000;SVTYPE=DEL;SVLEN=-1000\tGT\t0/1\n' >> "${probe}/probe.vcf" + # The image first, with pull_image's retries: left to `docker run`, one + # broken pull (a short read from the registry) failed the merge in two + # seconds with exit 125. + if ! "$CONTAINER_ENGINE" image inspect "$ANNOTSV_IMAGE" &>/dev/null && ! pull_image "$ANNOTSV_IMAGE"; then + echo "[WARN] Could not pull ${ANNOTSV_IMAGE} for AnnotSV's merge run; Docker's message is above." + rm -rf "$probe" + return 1 + fi echo " AnnotSV merges the records into its benign set (one run, a few minutes)..." # The annotations directory is writable: AnnotSV rewrites its benign files there. run_in --rw "$ANNOTSV_DIR" --cpus 2 --memory 8g "$ANNOTSV_IMAGE" \ @@ -1571,7 +1579,9 @@ install_archaic() { for c in $chroms; do [ -s "${dir}/chr${c}.tsv.gz" ] && [ "$(cat "${dir}/chr${c}.stamp" 2>/dev/null)" = "$stamp" ] && continue if [ ! -s "${sites}.tbi" ]; then - fetch "$ARCHAIC_1KG_SITES_URL" "$sites" md5 "$ARCHAIC_1KG_SITES_MD5" \ + # A whole copy already there (an earlier run that stopped at the index) is kept. + { [ -s "$sites" ] && [ "$(_digest md5 "$sites")" = "$ARCHAIC_1KG_SITES_MD5" ]; } \ + || fetch "$ARCHAIC_1KG_SITES_URL" "$sites" md5 "$ARCHAIC_1KG_SITES_MD5" \ || { echo "[WARN] Could not download the 1000 Genomes sites file; run: $0 --archaic ${GENOME_DIR}"; return 1; } run_in --rw "$dir" "$BCFTOOLS_IMAGE" bcftools index -t -f "$(cpath "$sites")" \ || { echo "[WARN] Could not index ${sites}"; return 1; } diff --git a/tests/e2e/family-joint-1.sh b/tests/e2e/family-joint-1.sh index a21bf51a..85ffe4ba 100755 --- a/tests/e2e/family-joint-1.sh +++ b/tests/e2e/family-joint-1.sh @@ -272,8 +272,20 @@ check "the pipeline published somalier's tables under family/somalier" test -s " nf_family swapped "${F}/pedigree_swapped.tsv" check "pipeline, HG002 and HG003 swapped: the run stops (exit ${RC})" test "$RC" -ne 0 -check "the message names a pair that disagrees" has 'HG003 and HG004: declared parent-child \(first degree\), but somalier measures (unrelated|third degree)' "$(cat "$LOG")" check "FAMILY_CHECK is the task that failed" has "FAMILY:FAMILY_CHECK" "$(cat "$LOG")" +# The pair message, read from the failed FAMILY_CHECK task's own .command.err. +# The console's copy of it is not reliable: in one run the task's stdout lines +# overwrote the start of its stderr there, and the ERROR lines were gone. +FC_ERR="" +for d in "${F}"/nfwork/*/*/; do + grep -q 'family_report.py check' "${d}.command.sh" 2>/dev/null || continue + [ "$(cat "${d}.exitcode" 2>/dev/null)" = 0 ] && continue + FC_ERR="${d}.command.err" +done +check "a failed FAMILY_CHECK task was found" test -n "$FC_ERR" +PAIR_MSG='HG003 and HG004: declared parent-child \(first degree\), but somalier measures (unrelated|third degree)' +check "the failed FAMILY_CHECK task's error names a pair that disagrees (${FC_ERR:-no failed task found})" \ + has "$PAIR_MSG" "$(cat "$FC_ERR" 2>/dev/null)" check "no report and no phasing after the stop" test ! -e "${OUT}/family/family_report.md" -a ! -e "${OUT}/family/family.phased.vcf.gz" # A planted de novo: a site HG002 inherited from HG004 (HG002 0/1, HG003 0/0, diff --git a/tests/test_fetch_retry.sh b/tests/test_fetch_retry.sh old mode 100755 new mode 100644 index 49cb6daa..46692af2 --- a/tests/test_fetch_retry.sh +++ b/tests/test_fetch_retry.sh @@ -9,11 +9,22 @@ # Two planted mutants show the test can fail: one returns at the first failed # check, the behaviour before this test, and one drops the .part of a broken # transfer instead of resuming it. +# +# Stalls: _get, which fetch calls for each try, gives up on a transfer that +# stops sending data, so fetch can try again and resume the .part. A local +# HTTP server sends the start of a file and then nothing, holding the +# connection open. With FETCH_STALL=2, fetch with curl and fetch with wget +# (curl hidden from PATH) each fail within seconds, keep the .part, and try +# FETCH_TRIES times; the same server's whole file downloads under the same +# bounds (at most 20 s). Two planted mutants, curl and wget without the +# bounds, still hang at 25 s, when this test stops them: the behaviour before +# the bounds. set -euo pipefail REPO=$(cd "$(dirname "$0")/.." && pwd) WORK=$(mktemp -d) -trap 'rm -rf "$WORK"' EXIT +SRV="" +trap '[ -z "$SRV" ] || kill "$SRV" 2>/dev/null; rm -rf "$WORK"' EXIT export FETCH_WAIT=0 # The served file, a real gzip so the gzip -t check has something to pass. @@ -123,4 +134,94 @@ else echo "FAIL: control: the no-resume mutant passed; the test cannot see a dropped .part"; FAILS=$((FAILS + 1)) fi -[ "$FAILS" -eq 0 ] +# --- Stalls ------------------------------------------------------------------- +fail() { echo "FAIL: $*"; FAILS=$((FAILS + 1)); } +pass() { echo "ok: $*"; } +command -v curl >/dev/null || { echo "FAIL: curl is needed to run this test"; exit 1; } +command -v wget >/dev/null || { echo "FAIL: wget is needed to run this test"; exit 1; } + +# The server: /stall.bin sends a 100000-byte Content-Length, 1000 bytes, then +# holds the connection for 60 s; /whole.bin sends the whole file. +cat > "${WORK}/server.py" <<'PY' +import http.server, sys, time +class H(http.server.BaseHTTPRequestHandler): + def log_message(self, *a): pass + def do_GET(self): + self.send_response(200) + self.send_header("Content-Length", "100000") + self.end_headers() + if self.path == "/stall.bin": + self.wfile.write(b"x" * 1000); self.wfile.flush(); time.sleep(60) + else: + self.wfile.write(b"x" * 100000) +s = http.server.ThreadingHTTPServer(("127.0.0.1", 0), H) +open(sys.argv[1], "w").write(str(s.server_address[1])) +s.serve_forever() +PY +python3 "${WORK}/server.py" "${WORK}/port" & SRV=$! +for _ in $(seq 1 50); do [ -s "${WORK}/port" ] && break; sleep 0.1; done +[ -s "${WORK}/port" ] || { echo "FAIL: the test server did not start"; exit 1; } +URL="http://127.0.0.1:$(cat "${WORK}/port")" + +# A PATH without curl, so _get takes its wget branch. +mkdir -p "${WORK}/nocurl" +for c in bash wget awk sed mv rm mkdir cat sleep basename dirname gzip md5sum sha256sum wc head tail tr cut date env \ + grep sort stat readlink uname id timeout nproc getconf printf; do + p=$(command -v "$c") && ln -sf "$p" "${WORK}/nocurl/$c" +done + +# stall_mutant NAME SED: a copy of the library with SED applied, at +# ${WORK}/NAME/scripts/lib/common.sh; stops when SED changes nothing. +stall_mutant() { + mkdir -p "${WORK}/$1/scripts/lib" + cp "${REPO}/versions.env" "${WORK}/$1/" + sed "$2" "${REPO}/scripts/lib/common.sh" > "${WORK}/$1/scripts/lib/common.sh" + if cmp -s "${REPO}/scripts/lib/common.sh" "${WORK}/$1/scripts/lib/common.sh"; then + echo "FAIL: mutant $1 is the same as common.sh; its sed no longer matches _get" + exit 1 + fi +} +# shellcheck disable=SC2016 # the $ and braces are sed's, not the shell's +stall_mutant curl-unbounded 's/ "\${cbound\[@\]}"//g' +# shellcheck disable=SC2016 +stall_mutant wget-unbounded 's/ "\${wbound\[@\]}"//g' + +# fetch_in LIB PATH NAME FILE [LIMIT]: fetch URL/FILE with LIB, PATH and +# FETCH_STALL=2, two tries, under a LIMIT-second timeout (default 30). +# Prints "rc= secs= part=". +fetch_in() { + local start rc=0 dest="${WORK}/$3/$4" + start=$(date +%s) + # shellcheck disable=SC2016 # $1 to $3 belong to the inner bash + PATH="$2" FETCH_STALL=2 FETCH_TRIES=2 FETCH_WAIT=0 timeout -k 2 "${5:-30}" bash -c '. "$1" && fetch "$2" "$3"' \ + _ "$1" "${URL}/$4" "$dest" > "${WORK}/$3.log" 2>&1 || rc=$? + echo "rc=${rc} secs=$(( $(date +%s) - start )) part=$( { wc -c < "${dest}.part" || echo 0; } 2>/dev/null | tr -d ' ')" +} +# expect_re DESC GOT WANT [LOG]: GOT matches the extended regex WANT. +expect_re() { + if [[ "$2" =~ $3 ]]; then pass "$1 ($2)"; else fail "$1: got '$2', want /$3/"; sed 's/^/ /' "${WORK}/${4:-none}.log" 2>/dev/null | tail -n 5; fi +} + +expect_re "curl: a stalled transfer fails both tries in seconds and keeps the .part" \ + "$(fetch_in "$LIB" "$PATH" curl-stall stall.bin)" '^rc=1 secs=([0-9]|1[0-9]|20) part=1000$' curl-stall +expect_re "curl: a whole file downloads under the same bounds" \ + "$(fetch_in "$LIB" "$PATH" curl-whole whole.bin)" '^rc=0 ' curl-whole +expect_re "wget: a stalled transfer fails both tries in seconds and keeps the .part" \ + "$(fetch_in "$LIB" "${WORK}/nocurl" wget-stall stall.bin)" '^rc=1 secs=([0-9]|1[0-9]|20) part=1000$' wget-stall +expect_re "wget: a whole file downloads under the same bounds" \ + "$(fetch_in "$LIB" "${WORK}/nocurl" wget-whole whole.bin)" '^rc=0 ' wget-whole +expect_re "control: curl without the bounds hangs until the timeout" \ + "$(fetch_in "${WORK}/curl-unbounded/scripts/lib/common.sh" "$PATH" curl-mutant stall.bin 25)" '^rc=124 ' curl-mutant +expect_re "control: wget without the bounds hangs until the timeout" \ + "$(fetch_in "${WORK}/wget-unbounded/scripts/lib/common.sh" "${WORK}/nocurl" wget-mutant stall.bin 25)" '^rc=124 ' wget-mutant +for z in 0 00 x; do + # shellcheck disable=SC2016 # $1 to $3 belong to the inner bash + if FETCH_STALL=$z bash -c '. "$1" && _get "$2" "$3"' _ "$LIB" "${URL}/whole.bin" "${WORK}/zero" > "${WORK}/zero.log" 2>&1; then + fail "FETCH_STALL=${z} was accepted" + else + expect_re "FETCH_STALL=${z} is refused" "$(cat "${WORK}/zero.log")" 'FETCH_STALL must be' + fi +done + +if [ "$FAILS" -gt 0 ]; then echo "${FAILS} check(s) failed"; exit 1; fi +echo "All fetch checks passed."