From 4e551cc89d383dfcd1cc25421d09ec0da88fdd4f Mon Sep 17 00:00:00 2001 From: almac2022 Date: Fri, 2 Oct 2026 06:45:23 -0700 Subject: [PATCH 1/4] Initialize PWF baseline for #87 Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01PRhUJsuKABLfpBGktPoiBN --- planning/active/findings.md | 92 ++++++++++++++++++++++++++++++++++++ planning/active/progress.md | 8 ++++ planning/active/task_plan.md | 62 ++++++++++++++++++++++++ 3 files changed, 162 insertions(+) create mode 100644 planning/active/findings.md create mode 100644 planning/active/progress.md create mode 100644 planning/active/task_plan.md diff --git a/planning/active/findings.md b/planning/active/findings.md new file mode 100644 index 0000000..17eed9c --- /dev/null +++ b/planning/active/findings.md @@ -0,0 +1,92 @@ +# Findings — Failed gdalcubes chunk reads are silent: a partial cube passes the empty check and is cached (#87) + +## Issue context + +## Problem + +When gdalcubes cannot read some chunks of a cube (an expired signed URL, a refused or throttled request), it does **not** raise an R warning or error. It prints `[WARNING] n out of m chunks have repoprted errors / incompleteness` and writes the cube with those chunks NA. drift then: + +- passes `cube_check_nonempty()` whenever any chunk succeeded; +- **caches the partial cube as complete**, and serves it forever under `force = FALSE`. + +This affects `dft_stac_cube()` and `dft_stac_composite()` (shared `stac_cube_assemble()`), and probably `dft_stac_fetch()` (same gdalcubes write). + +## How it was found (drift#79, 2026-09-28) + +A floodplain-wide composite over BULK (`tile_size = 20000`, 30 tiles) ran for 54 min. Planetary Computer SAS tokens last about 45 min, and every asset had been signed once at query time. **15 of 30 tiles** reported "9 out of 9 chunks" failed. The run died later on an unrelated COG write; otherwise the holed composite would have been cached. + +#79 fixes the cause it hit: features are re-signed before each read extent. With corrupted tokens, re-signing read 102,364 cells, against 0 without. **Detection is still missing.** A single extent that outlives a token, or a throttled request, still yields silent NA. + +## Why the obvious guard does not work + +Capturing stderr around `write_ncdf()` (`capture.output(type = "message")`) and aborting on the report line was tried and measured on the packaged AOI with corrupted tokens: + +| gdalcubes `parallel` | image mask | report captured | cells read | +|---|---|---|---| +| 1 | no | 0 (1 in an earlier run of the same probe) | 0 | +| 1 | SCL | 2 | 0 | +| 4 | no | 0 | 0 | +| 4 | SCL | 0 | 0 | + +With worker processes (drift's default is `min(4, cores - 1)`) the report never reaches R. A guard that fires sometimes reads as protection it does not give, so #79 did not ship it. + +## Options + +- Ask gdalcubes for a programmatic error count after compute (look for a debug/log option in 0.7.5). If none exists, propose one upstream: draft it here first, and do not post upstream without approval. +- Pre-flight each extent: `HEAD` one asset URL per item just before the read, and abort on 403 or 404. That catches expired tokens but not mid-read throttling. +- Post-check against an independent expectation: for each item footprint that intersects the extent, require some non-NA cells unless the SCL for that item is fully masked. Expensive, but it discriminates. + +## Acceptance + +- A read with corrupted tokens, at the default `parallel`, aborts and caches nothing. +- The same holds for a tiled read. +- A normal read is unaffected, and so is the cube cache key. + +Relates: drift#79, drift#83 + + +## Plan-mode exploration (2026-10-02) + +### chunk_status + +When gdalcubes cannot read chunks (expired SAS token, throttling) it prints a +`[WARNING] n out of m chunks …` line and writes NA. drift passes the empty check +whenever any chunk succeeded and caches the holed cube forever. Capturing stderr +was measured unreliable at `parallel > 1` (#79). The issue proposed three options: +ask upstream, HEAD pre-flight, or an independent pixel post-check. + +**Exploration found a fourth option, already in gdalcubes 0.7.5.** `write_ncdf()` +writes a per-chunk `chunk_status` int variable into every output file +(`cube.cpp:785/969`; enum `OK=0, ERROR=1, INCOMPLETE=2, UNKNOWN=128`; chunks +never visited stay at NC_INT fill `-2147483647`). In multiprocess mode the status +travels from worker to master inside the chunk file (`cube.cpp:1833/1866`). +Probed offline (local fixture, one image deleted after collection creation): + +| parallel | stderr `[WARNING]` | `chunk_status` failures | notNA cells | +|---|---|---|---| +| 1, clean | — | 0 | 3200 | +| 4, clean | — | 0 | 3200 | +| 1, broken | printed | 9 × `2` | 1600 | +| 4, broken | **not printed** | 9 × `2` | 1600 | +| 4, broken, monthly median | not printed | 1 × `2` | **1600 of 1600** | + +The last row is the discriminating one: a median over two images where one +failed fills every cell from the survivor, so *no* pixel-based check (including +the issue's option 3) can see it. `chunk_status` does. No upstream ask is needed. + +Reader: `ncdf4` (`nc_open` + `ncvar_get`). gdalcubes Imports ncdf4, so it is +present whenever these paths can run; terra/GDAL ignore the 1-D variable as a +subdataset (`rast(f, subds=)` errors) and the `NETCDF:` path form prints a stray +`R_nc4_open` error line. Add `ncdf4` to Suggests. + +Write sites (only two): `stac_cube_assemble()`'s `build_stack()` +(`R/dft_stac_cube.R:642`, shared by `dft_stac_cube()` and `dft_stac_composite()`, +tiled and untiled) and `fetch_extent_to()` (`R/dft_stac_fetch.R:632`, both +`dft_stac_fetch()` paths). Both run before any cache publish: +`cache_write_atomic()` removes its temp on error, and the tiled paths abort before +the mosaic. Cache key untouched (no new argument). + +## Errors Encountered + +| Error | Resolution | +|-------|------------| diff --git a/planning/active/progress.md b/planning/active/progress.md new file mode 100644 index 0000000..2cfeeb5 --- /dev/null +++ b/planning/active/progress.md @@ -0,0 +1,8 @@ +# Progress — Failed gdalcubes chunk reads are silent: a partial cube passes the empty check and is cached (#87) + +## Session 2026-10-02 + +- Plan-mode exploration — phases approved by user +- Created branch `87-failed-gdalcubes-chunk-reads-are-silent` off main +- Scaffolded PWF baseline from issue #87 with approved phases +- Next: start Phase 1 diff --git a/planning/active/task_plan.md b/planning/active/task_plan.md new file mode 100644 index 0000000..6a67c5c --- /dev/null +++ b/planning/active/task_plan.md @@ -0,0 +1,62 @@ +# Task: Failed gdalcubes chunk reads are silent: a partial cube passes the empty check and is cached (#87) + +## Problem + +When gdalcubes cannot read some chunks of a cube (an expired signed URL, a refused or throttled request), it does **not** raise an R warning or error. It prints `[WARNING] n out of m chunks have repoprted errors / incompleteness` and writes the cube with those chunks NA. drift then: + +- passes `cube_check_nonempty()` whenever any chunk succeeded; +- **caches the partial cube as complete**, and serves it forever under `force = FALSE`. + +This affects `dft_stac_cube()` and `dft_stac_composite()` (shared `stac_cube_assemble()`), and probably `dft_stac_fetch()` (same gdalcubes write). + +## Phase 1: Chunk-status guard + unit tests +- [ ] `tests/testthat/helper-gdalcubes.R`: offline fixture builder (local B04 + SCL + tifs, `create_image_collection()`), with an option to delete one image after + the collection is built +- [ ] Failing tests for `cube_check_chunks(nc_file)`: clean file passes at + `parallel = 1` and `4`; broken file aborts (class `drift_incomplete_cube`) at + both; the monthly-median case with every cell non-NA still aborts; a NetCDF + with no `chunk_status` variable aborts (fail toward abort, not pass) +- [ ] Implement `cube_check_chunks()` in `R/dft_stac_cube.R`: failure = any value + not in `{0, NC_INT fill}` (so a future status code fails toward abort); + message names n of m chunks, the likely causes (expired token, throttling), + and that nothing was cached +- [ ] `ncdf4` → Suggests; restore the bug (no-op the check) and confirm the + tests go red + +## Phase 2: Wire into both write sites +- [ ] Call `cube_check_chunks(tmp)` in `build_stack()` after `write_ncdf()` +- [ ] Call it in `fetch_extent_to()` after `write_ncdf()` +- [ ] Integration tests (offline; `stac_image_collection` mocked to return the + broken fixture collection, STAC query helpers stubbed): `dft_stac_composite()` + untiled and tiled, and `dft_stac_fetch()` untiled and tiled, each abort with + `drift_incomplete_cube` and leave the cache directory empty; the clean fixture + still returns a raster and caches it +- [ ] Existing cache-key frozen tests still pass unchanged (key not affected) + +## Phase 3: Live check, docs, notes +- [ ] Live probe (opt-in, `DRIFT_TEST_NETWORK=true`): packaged AOI, corrupted `sig` + on every asset, re-signing stubbed out, default `parallel` → aborts, nothing + cached; same call with valid tokens succeeds +- [ ] Short-run timing per CLAUDE.md (`/usr/bin/time -l`) on a clean packaged-AOI + read before/after: the check reads one int vector, so expect no change; record + numbers for the PR body +- [ ] Update the `stac_features_resign()` roxygen (it says chunk failures cannot be + reliably captured) and `inst/notes/gdalcubes-pc-gotchas.md` with the + `chunk_status` finding and the probe table +- [ ] Edit the #87 issue body: the fourth option and why options 1–3 were not taken +- [ ] `devtools::document()`, `devtools::test()`, `lintr::lint_package()` + +## Not in scope (say so in the PR) +- Retrying a failed extent (re-sign + one retry) — would rescue a long tiled run + instead of discarding it, but is new behaviour; file as a follow-up if wanted. +- Re-signing per tile in `dft_stac_fetch()` (it signs once, like #79's cube path + did) — detection now catches it; the fix is a separate change. +- soul `code-check-spatial.md` says "gdalcubes reports failed chunk reads only on + stderr" — now wrong; flag in the report (soul edits go through an issue). + +## Validation +- [ ] Tests pass +- [ ] `/code-check` clean on each commit +- [ ] PWF checkboxes match landed work +- [ ] `/planning-archive` on completion From 36f2a6fcc2e3d9d1f239ca6524572cf9a48f88a5 Mon Sep 17 00:00:00 2001 From: almac2022 Date: Fri, 2 Oct 2026 07:31:42 -0700 Subject: [PATCH 2/4] Abort on failed gdalcubes chunk reads before caching (#87) gdalcubes writes a per-chunk chunk_status into every write_ncdf() output, carried from worker processes, so a band image that fails to open (an expired or refused signed URL) is visible at any parallel where the stderr line was not. cube_write_ncdf() is now drift's single write_ncdf() call, in stac_cube_assemble() and fetch_extent_to(): it aborts (drift_incomplete_cube) on a non-OK status and on gdalcubes' "could not be added to output" merge warning, after the write returns, before anything is cached. - offset split builds both sides before terra::cover(), whose S4 dispatch re-raised the abort without its class - untiled fetch .nc caches recording failed chunks are a miss and re-fetch - GDAL HTTP retries in the cube session and every dft_stac_fetch() - tiled fetch registers tile cleanup before the reads - ncdf4 to Suggests (gdalcubes imports it) Offline fixture tests, red before the wiring and after un-wiring; live probe 8 of 8 (data-raw/probe_chunk_status_live.R). Failures gdalcubes does not record (read after open, mask failures, worker files, crashes) are documented and moved to #99. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01PRhUJsuKABLfpBGktPoiBN --- DESCRIPTION | 1 + R/dft_stac_cube.R | 165 ++++++++++++- R/dft_stac_fetch.R | 44 +++- .../20261002T140832Z.txt | 18 ++ data-raw/probe_chunk_status_live.R | 109 +++++++++ inst/notes/gdalcubes-pc-gotchas.md | 28 ++- planning/active/findings.md | 54 +++++ planning/active/progress.md | 11 + planning/active/review-plan.md | 25 ++ planning/active/review-round1.md | 68 ++++++ planning/active/review-round2.md | 142 +++++++++++ planning/active/review-round3.md | 223 ++++++++++++++++++ planning/active/task_plan.md | 75 +++--- tests/testthat/helper-gdalcubes.R | 67 ++++++ tests/testthat/test-dft_stac_composite.R | 93 ++++++++ tests/testthat/test-dft_stac_cube.R | 150 ++++++++++++ tests/testthat/test-dft_stac_fetch.R | 83 +++++++ 17 files changed, 1310 insertions(+), 46 deletions(-) create mode 100644 data-raw/logs/probe_chunk_status_live/20261002T140832Z.txt create mode 100644 data-raw/probe_chunk_status_live.R create mode 100644 planning/active/review-plan.md create mode 100644 planning/active/review-round1.md create mode 100644 planning/active/review-round2.md create mode 100644 planning/active/review-round3.md create mode 100644 tests/testthat/helper-gdalcubes.R diff --git a/DESCRIPTION b/DESCRIPTION index 9f9de12..148e39f 100644 --- a/DESCRIPTION +++ b/DESCRIPTION @@ -47,6 +47,7 @@ Suggests: leaflet, leaflet.extras, mapgl, + ncdf4, rmarkdown, testthat (>= 3.2.0), withr, diff --git a/R/dft_stac_cube.R b/R/dft_stac_cube.R index 7063af7..c72c84c 100644 --- a/R/dft_stac_cube.R +++ b/R/dft_stac_cube.R @@ -401,7 +401,9 @@ cube_view_choice_check <- function(x, arg, allowed, fallback, class, #' parallel = 1 measured finer chunks 45% SLOWER. #' #' GDAL cloud-read tuning for /vsicurl COG streaming (biggest win: -#' DISABLE_READDIR_ON_OPEN avoids a remote directory listing on every open). +#' DISABLE_READDIR_ON_OPEN avoids a remote directory listing on every open), and +#' HTTP retries (#87). Environment variables, so gdalcubes' worker processes +#' inherit them. #' @noRd stac_cube_session <- function(parallel) { old_parallel <- gdalcubes::gdalcubes_options()$parallel @@ -413,7 +415,11 @@ stac_cube_session <- function(parallel) { GDAL_HTTP_MULTIPLEX = "YES", GDAL_HTTP_VERSION = "2", VSI_CACHE = "TRUE", - CPL_VSIL_CURL_ALLOWED_EXTENSIONS = ".tif" + CPL_VSIL_CURL_ALLOWED_EXTENSIONS = ".tif", + # A transient 429 or 5xx now aborts a whole read (#87), and one that strikes + # after an image has opened is a hole nothing can detect, so retry them. + GDAL_HTTP_MAX_RETRY = "3", + GDAL_HTTP_RETRY_DELAY = "5" ) old_cfg <- Sys.getenv(names(gdal_cfg), unset = NA) do.call(Sys.setenv, as.list(gdal_cfg)) @@ -549,10 +555,9 @@ stac_cube_items <- function(cfg, aoi_wgs84, datetime, cloud_cover_max, months, #' expired token and replaces the `sig` parameter of an already-signed href, so #' re-signing before each extent keeps every read inside a live token (verified #' live: features with a corrupted `sig` read 102,364 cells after re-signing, 0 -#' without). A single extent whose read outlives one token is still exposed, and -#' gdalcubes reports a failed chunk only on the worker's stderr, which R cannot -#' reliably capture (#87). A `fetched` without `sign_fn` (a test stub) passes -#' through unchanged. +#' without). A single extent whose read outlives one token is still exposed; an +#' image that then fails to open aborts the read through cube_write_ncdf() (#87). +#' A `fetched` without `sign_fn` (a test stub) passes through unchanged. #' @noRd stac_features_resign <- function(fetched, feats) { if (is.null(fetched$sign_fn) || is.null(fetched$items) || !length(feats)) { @@ -639,7 +644,8 @@ stac_cube_assemble <- function(fetched, cfg, aoi_target, target_crs, t0, t1, ) out <- pixel_fn(cube, offset_use) tmp <- tempfile(fileext = ".nc") - gdalcubes::write_ncdf(out, tmp, overwrite = TRUE) + # aborts on a failed chunk read, before any caller caches the result (#87) + cube_write_ncdf(out, tmp) terra::rast(tmp) } @@ -661,10 +667,12 @@ stac_cube_assemble <- function(fetched, cfg, aoi_target, target_crs, t0, t1, # re-sign here, per extent, so no read outlives its token feats <- stac_features_resign(fetched, features) if (any(is_pre) && !all(is_pre)) { - terra::cover( - build_stack(feats[is_pre], offset_before, v), - build_stack(feats[!is_pre], offset, v) - ) + # Both sides built BEFORE terra::cover(): built as its arguments, they are + # evaluated inside S4 method selection, which re-raises an abort as a plain + # "error in evaluating the argument" and drops its class (#87). + pre <- build_stack(feats[is_pre], offset_before, v) + post <- build_stack(feats[!is_pre], offset, v) + terra::cover(pre, post) } else { build_stack(feats, if (all(is_pre)) offset_before else offset, v) } @@ -720,6 +728,141 @@ cube_check_nonempty <- function(stk, collection, datetime, cached) { } +#' Write a gdalcubes cube to NetCDF, aborting if any chunk failed to read +#' +#' The one place drift calls [gdalcubes::write_ncdf()], shared by +#' stac_cube_assemble() (so [dft_stac_cube()] and [dft_stac_composite()]) and +#' fetch_extent_to() ([dft_stac_fetch()]). Both call it before anything derived +#' from the file is cached, so a failed read aborts with nothing cached. +#' +#' gdalcubes signals a failed chunk in two ways, and this watches both: +#' * a chunk whose merge into the output throws raises an R warning, `Chunk N +#' could not be added to output`, and the write carries on (gdalcubes 0.7.5, +#' `src/multiprocess.cpp`). That chunk holds no status at all, so +#' cube_check_chunks() alone would pass it. +#' * a chunk whose image would not open is recorded in the file; see +#' cube_check_chunks(). +#' +#' The warning is only NOTED in the handler, and the abort comes after +#' `write_ncdf()` returns. gdalcubes raises it with `Rcpp::warning()`, so an +#' abort from inside the handler would longjmp through its C++ frames and skip +#' their destructors: the worker shutdown, the work directory, the output +#' file's close (Rcpp's own header warns of exactly this). Other gdalcubes +#' warnings pass through untouched. +#' +#' Not every failed merge reaches either signal: a worker chunk file the main +#' process cannot open is skipped with status OK and no warning, a C++ stderr +#' line only (round-2 review of #87; drift#99). +#' @noRd +cube_write_ncdf <- function(cube, out) { + unmerged <- character(0) + withCallingHandlers( + gdalcubes::write_ncdf(cube, out, overwrite = TRUE), + warning = function(w) { + if (grepl("could not be added to output", conditionMessage(w), + fixed = TRUE)) { + unmerged <<- c(unmerged, conditionMessage(w)) + invokeRestart("muffleWarning") + } + } + ) + if (length(unmerged)) { + cli::cli_abort(class = "drift_incomplete_cube", c( + "gdalcubes could not merge {length(unmerged)} chunk{?s} into its output.", + "x" = "{unmerged[[1]]}", + "i" = "Nothing was cached." + )) + } + cube_check_chunks(out) +} + + +#' Abort on a gdalcubes NetCDF whose chunk reads failed +#' +#' gdalcubes does not raise when it cannot read a chunk. It prints `[WARNING] n +#' out of m chunks have repoprted errors / incompleteness` from C++ stdio and +#' writes the chunk as `NA`. That line never reaches R from a worker process, and +#' only sometimes from the main one, so capturing it was measured unreliable +#' (#79, #87). +#' +#' What gdalcubes does write, at every worker count, is a `chunk_status` variable +#' in the output NetCDF, one integer per chunk: `0` OK, `1` ERROR, `2` +#' INCOMPLETE, `128` UNKNOWN (gdalcubes 0.7.5, `src/gdalcubes/src/cube.cpp`). A +#' worker carries the status to the main process inside its chunk file. +#' +#' **What it records is narrower than "the read failed".** Measured offline +#' (#87): a band image that fails to OPEN marks its chunks INCOMPLETE, which is +#' the expired or refused signed URL. A band image that opens and then fails +#' mid-read (a corrupted tile here; a throttled range request on the network) +#' leaves the status OK, and so does a mask (SCL) image that fails to open, which +#' silently drops that scene. A mask image that opens and then fails mid-read is +#' worse: the scene is used unmasked. gdalcubes sets the status only when a band +#' image will not open; every other I/O step drops its return code, so none of +#' these is visible to this check or to anything else R can see (drift#99; +#' inst/notes/gdalcubes-pc-gotchas.md). +#' +#' **The netCDF integer fill value means no status was written for that id**, +#' not that the chunk was empty: a worker skips writing a chunk that is OK and +#' all-`NA` (no image, or fully masked), and a chunk whose merge threw keeps fill +#' too. That second case raises an R warning, which cube_write_ncdf() turns into +#' an abort, so fill is read as OK here. A worker chunk file the main process +#' cannot open is recorded as OK, with neither signal (drift#99). Anything that is neither OK nor fill fails, so a +#' status code a later gdalcubes adds aborts rather than passes. +#' +#' For an open failure, this is the only check that sees it. A median over two +#' scenes where one failed fills every cell from the survivor (measured: 1600 of +#' 1600 cells set), so no test on the pixels, cube_check_nonempty() included, can +#' tell that cube from a complete one. +#' +#' A file with no `chunk_status` variable also aborts: a guard that cannot find +#' its evidence must not report the read clean. +#' +#' Read with ncdf4, which gdalcubes imports: GDAL does not list the +#' one-dimensional variable as a subdataset, so terra cannot open it by name. +#' @noRd +cube_check_chunks <- function(nc_file) { + failed <- chunk_status_failed(nc_file) + if (is.na(failed[["failed"]])) { + cli::cli_abort(class = "drift_incomplete_cube", c( + "The gdalcubes output has no {.field chunk_status}, so its chunk reads \\ + cannot be checked.", + "i" = "Nothing was cached. drift needs a gdalcubes that records per-chunk \\ + status in {.fn gdalcubes::write_ncdf} output (0.7.5 does)." + )) + } + if (failed[["failed"]] == 0L) return(invisible(nc_file)) + cli::cli_abort(class = "drift_incomplete_cube", c( + "gdalcubes could not read {failed[['failed']]} of {failed[['chunks']]} \\ + chunk{?s}: an image would not open.", + "x" = "Those cells are {.val NA}, or computed from only the scenes that \\ + did open.", + "i" = "Usually an expired or refused signed URL. Nothing was cached.", + "i" = "Re-running signs the request again. If the same read fails every \\ + time, an asset may be missing from the catalogue." + )) +} + + +#' Count the failed chunks recorded in a gdalcubes NetCDF +#' +#' The reader behind cube_check_chunks() and the cache gate. Returns integers +#' `failed` and `chunks`, with `failed` `NA` when the file has no +#' `chunk_status` variable. Status `0` and the netCDF integer fill +#' (`NC_FILL_INT`, no chunk merged for that id) count as OK; see +#' cube_check_chunks(). +#' @noRd +chunk_status_failed <- function(nc_file) { + nc <- ncdf4::nc_open(nc_file) + on.exit(ncdf4::nc_close(nc), add = TRUE) + if (!"chunk_status" %in% names(nc$var)) { + return(c(failed = NA_integer_, chunks = NA_integer_)) + } + status <- as.vector(ncdf4::ncvar_get(nc, "chunk_status", raw_datavals = TRUE)) + failed <- !is.na(status) & status != 0L & status != -2147483647L + c(failed = sum(failed), chunks = length(status)) +} + + #' Resolve the gdalcubes worker count for a cube read #' #' `NULL` means auto: `min(4, cores - 1)`, capped at 4 rather than the full core diff --git a/R/dft_stac_fetch.R b/R/dft_stac_fetch.R index f4797de..91946e7 100644 --- a/R/dft_stac_fetch.R +++ b/R/dft_stac_fetch.R @@ -110,6 +110,18 @@ dft_stac_fetch <- function(aoi, aggregation <- aggregation_check(aggregation) resampling <- resampling_check(resampling) + # Retry a transient 429 or 5xx rather than abort the read on it: a failed + # open now aborts (#87). Tiled or not, restored on exit. + gdal_retry <- c(GDAL_HTTP_MAX_RETRY = "3", GDAL_HTTP_RETRY_DELAY = "5") + old_retry <- Sys.getenv(names(gdal_retry), unset = NA) + do.call(Sys.setenv, as.list(gdal_retry)) + on.exit({ + set_again <- old_retry[!is.na(old_retry)] + if (length(set_again)) do.call(Sys.setenv, as.list(set_again)) + unset <- names(old_retry)[is.na(old_retry)] + if (length(unset)) Sys.unsetenv(unset) + }, add = TRUE) + # Normalize tile_size ONCE so the path gate (is.null) and the cache key derive # from the same snapped scalar. When tiling, tune GDAL for the many extra # per-item COG opens (restored on exit so the caller's session is untouched). @@ -226,14 +238,17 @@ dft_stac_fetch <- function(aoi, }) } else { message(" ", yr, ": fetching ", length(tiles), " tile(s)...") + # Named and registered for removal BEFORE any read: on.exit, not a + # trailing unlink(), because a failed tile (#87) or a mosaic_tiles() error + # would otherwise strand every tile already written. tile_files <- vapply(seq_along(tiles), function(i) { - fetch_extent_to(col, tiles[[i]], t0, t1, target_crs, res, dt, - aggregation, resampling, - tempfile(sprintf("drift_tile%d_", i), fileext = ".nc")) + tempfile(sprintf("drift_tile%d_", i), fileext = ".nc") }, character(1)) - # on.exit, not a trailing unlink(): a mosaic_tiles() error would otherwise - # strand every tile file for the life of the session. on.exit(unlink(tile_files), add = TRUE) + for (i in seq_along(tiles)) { + fetch_extent_to(col, tiles[[i]], t0, t1, target_crs, res, dt, + aggregation, resampling, tile_files[[i]]) + } cache_write_atomic(cache_file, function(out) mosaic_tiles(tile_files, out)) } @@ -629,7 +644,9 @@ fetch_extent_to <- function(col, ext, t0, t1, target_crs, res, dt, aggregation = aggregation, resampling = resampling ) cube <- gdalcubes::raster_cube(col, v) - gdalcubes::write_ncdf(cube, out_nc, overwrite = TRUE) + # aborts on a failed chunk read: inside cache_write_atomic() untiled, before + # the mosaic tiled, so nothing is cached (#87) + cube_write_ncdf(cube, out_nc) out_nc } @@ -802,6 +819,21 @@ cache_invalid_reason <- function(path, probe = cache_probe_last_row) { } ) if (!ok) return("its pixel data could not be read cleanly") + + # An untiled dft_stac_fetch() cache IS the gdalcubes NetCDF, so it still holds + # the chunk_status it was written with, and one cached before #87 can record an + # image that never opened. A miss re-fetches it. A .nc with no chunk_status + # (written by something other than gdalcubes) has nothing to say and passes: + # the read arms above already vouched for it. + if (identical(tolower(tools::file_ext(path)), "nc") && + requireNamespace("ncdf4", quietly = TRUE)) { + failed <- tryCatch(chunk_status_failed(path)[["failed"]], + error = function(e) NA_integer_) + if (!is.na(failed) && failed > 0L) { + return(paste0("records ", failed, " chunk read(s) that failed when it ", + "was fetched")) + } + } NA_character_ } diff --git a/data-raw/logs/probe_chunk_status_live/20261002T140832Z.txt b/data-raw/logs/probe_chunk_status_live/20261002T140832Z.txt new file mode 100644 index 0000000..c515670 --- /dev/null +++ b/data-raw/logs/probe_chunk_status_live/20261002T140832Z.txt @@ -0,0 +1,18 @@ +14:08:32Z drift 0.21.0 (source tree), gdalcubes 0.7.5, cores 10, auto parallel 4 +14:08:37Z PASS | composite untiled, bad tokens | expect drift_incomplete_cube | got drift_incomplete_cube | cache files 0 | 5 s | gdalcubes parallel after 1 +14:08:37Z gdalcubes could not read 9 of 9 chunks: an image would not open. ✖ Those cells are "NA", or computed from only the scenes that did open. ℹ Usually an expired or refused signed URL. Nothing was cached. ℹ Re-running signs the request again. If the same read fails every time, an asset may be missing fr +14:08:41Z PASS | composite tiled 1000 m, bad tokens | expect drift_incomplete_cube | got drift_incomplete_cube | cache files 0 | 4 s | gdalcubes parallel after 1 +14:08:41Z gdalcubes could not read 4 of 4 chunks: an image would not open. ✖ Those cells are "NA", or computed from only the scenes that did open. ℹ Usually an expired or refused signed URL. Nothing was cached. ℹ Re-running signs the request again. If the same read fails every time, an asset may be missing fr +14:08:52Z PASS | cube untiled, bad tokens | expect drift_incomplete_cube | got drift_incomplete_cube | cache files 0 | 10 s | gdalcubes parallel after 1 +14:08:52Z gdalcubes could not read 9 of 9 chunks: an image would not open. ✖ Those cells are "NA", or computed from only the scenes that did open. ℹ Usually an expired or refused signed URL. Nothing was cached. ℹ Re-running signs the request again. If the same read fails every time, an asset may be missing fr +14:08:54Z PASS | fetch untiled, bad tokens, session parallel | expect drift_incomplete_cube | got drift_incomplete_cube | cache files 0 | 2 s | gdalcubes parallel after 1 +14:08:54Z gdalcubes could not read 4 of 4 chunks: an image would not open. ✖ Those cells are "NA", or computed from only the scenes that did open. ℹ Usually an expired or refused signed URL. Nothing was cached. ℹ Re-running signs the request again. If the same read fails every time, an asset may be missing fr +14:08:56Z PASS | fetch tiled 1000 m, bad tokens, session parallel | expect drift_incomplete_cube | got drift_incomplete_cube | cache files 0 | 2 s | gdalcubes parallel after 1 +14:08:56Z gdalcubes could not read 1 of 1 chunk: an image would not open. ✖ Those cells are "NA", or computed from only the scenes that did open. ℹ Usually an expired or refused signed URL. Nothing was cached. ℹ Re-running signs the request again. If the same read fails every time, an asset may be missing fro +14:13:22Z PASS | control: cube months 6:9, 2023, parallel 4 | expect returned | got returned | cache files 1 | 266 s | gdalcubes parallel after 1 +14:13:22Z SpatRaster +14:15:45Z PASS | control: composite 2023 July, tiled 1000 m, parallel 4 | expect returned | got returned | cache files 1 | 142 s | gdalcubes parallel after 1 +14:15:45Z list +14:15:52Z PASS | control: fetch 2023 untiled | expect returned | got returned | cache files 1 | 8 s | gdalcubes parallel after 1 +14:15:52Z list +14:15:52Z 8 of 8 as expected diff --git a/data-raw/probe_chunk_status_live.R b/data-raw/probe_chunk_status_live.R new file mode 100644 index 0000000..9b71f92 --- /dev/null +++ b/data-raw/probe_chunk_status_live.R @@ -0,0 +1,109 @@ +# Live acceptance for drift#87: a read whose signed URLs are bad aborts and +# caches nothing, and a normal read is unaffected. +# +# Every asset is signed and then has its SAS `sig` replaced, through a `sign_fn` +# that wraps rstac's Planetary Computer signer. stac_features_resign() calls the +# same `sign_fn` before each extent, so re-signing cannot repair the token: the +# image fails to open, as it does when a token has expired. This is the #79 +# failure (every chunk of 15 of 30 tiles), which drift used to cache. +# +# Rscript data-raw/probe_chunk_status_live.R +# +# Writes data-raw/logs/probe_chunk_status_live/.txt (committed: .log +# is gitignored under data-raw/logs). Packaged AOI, +# a few minutes of network reads. + +# Load the SOURCE tree, never the installed package (code-check-r.md). +pkgload::load_all(quiet = TRUE) + +out_dir <- file.path("data-raw", "logs", "probe_chunk_status_live") +dir.create(out_dir, recursive = TRUE, showWarnings = FALSE) +log_file <- file.path(out_dir, paste0(format(Sys.time(), "%Y%m%dT%H%M%SZ", + tz = "UTC"), ".txt")) +say <- function(...) { + line <- paste0(format(Sys.time(), "%H:%M:%SZ", tz = "UTC"), " ", ...) + cat(line, "\n") + cat(line, "\n", file = log_file, append = TRUE) +} + +aoi <- sf::st_read(system.file("extdata", "example_aoi.gpkg", package = "drift"), + quiet = TRUE) + +# Sign, then spoil the token, on every call: query time and every re-sign. +pc <- rstac::sign_planetary_computer() +sign_bad <- function(item) { + item <- pc(item) + item$assets <- lapply(item$assets, function(a) { + a$href <- sub("sig=[^&]+", "sig=AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA", + a$href) + a + }) + item +} + +# Run one call; record the outcome class, the cache files left and the time. +probe <- function(label, expect, fn) { + cache <- tempfile("drift87_") + t0 <- Sys.time() + res <- tryCatch( + { + out <- suppressMessages(fn(cache)) + list(outcome = "returned", detail = class(out)[1]) + }, + drift_incomplete_cube = function(e) { + list(outcome = "drift_incomplete_cube", + detail = gsub("\\s+", " ", conditionMessage(e))) + }, + error = function(e) { + list(outcome = paste0("error:", class(e)[1]), + detail = gsub("\\s+", " ", conditionMessage(e))) + } + ) + files <- list.files(cache, recursive = TRUE) + secs <- round(as.numeric(difftime(Sys.time(), t0, units = "secs"))) + ok <- identical(res$outcome, expect) && + (expect == "returned" || length(files) == 0L) + say(sprintf("%s | %s | expect %s | got %s | cache files %d | %d s | gdalcubes parallel after %s", + if (ok) "PASS" else "FAIL", label, expect, res$outcome, + length(files), secs, gdalcubes::gdalcubes_options()$parallel)) + say(" ", substr(res$detail, 1, 300)) + unlink(cache, recursive = TRUE) + ok +} + +say("drift ", as.character(utils::packageVersion("drift")), " (source tree), gdalcubes ", + as.character(utils::packageVersion("gdalcubes")), ", cores ", + parallel::detectCores(), ", auto parallel ", drift:::cube_parallel_check(NULL)) + +results <- c( + # composite: parallel = NULL, the auto default + probe("composite untiled, bad tokens", "drift_incomplete_cube", function(cache) + dft_stac_composite(aoi, years = 2023, months = 7, bands = "red", + cache_dir = cache, sign_fn = sign_bad)), + probe("composite tiled 1000 m, bad tokens", "drift_incomplete_cube", function(cache) + dft_stac_composite(aoi, years = 2023, months = 7, bands = "red", + tile_size = 1000, cache_dir = cache, sign_fn = sign_bad)), + probe("cube untiled, bad tokens", "drift_incomplete_cube", function(cache) + dft_stac_cube(aoi, index = "ndvi", datetime = "2023-07-01/2023-07-31", + cache_dir = cache, sign_fn = sign_bad)), + # fetch reads at the session worker count, which gdalcubes ships as 1 + probe("fetch untiled, bad tokens, session parallel", "drift_incomplete_cube", + function(cache) + dft_stac_fetch(aoi, years = 2023, cache_dir = cache, sign_fn = sign_bad)), + probe("fetch tiled 1000 m, bad tokens, session parallel", "drift_incomplete_cube", + function(cache) + dft_stac_fetch(aoi, years = 2023, tile_size = 1000, cache_dir = cache, + sign_fn = sign_bad)), + # false-abort controls with good tokens: empty months and cloud-masked chunks + # are the normal reads that leave chunks unvisited + probe("control: cube months 6:9, 2023, parallel 4", "returned", function(cache) + dft_stac_cube(aoi, index = "ndvi", datetime = "2023-01-01/2023-12-31", + months = 6:9, parallel = 4, cache_dir = cache)), + probe("control: composite 2023 July, tiled 1000 m, parallel 4", "returned", + function(cache) + dft_stac_composite(aoi, years = 2023, months = 7, bands = "red", + tile_size = 1000, parallel = 4, cache_dir = cache)), + probe("control: fetch 2023 untiled", "returned", function(cache) + dft_stac_fetch(aoi, years = 2023, cache_dir = cache)) +) +say(sum(results), " of ", length(results), " as expected") diff --git a/inst/notes/gdalcubes-pc-gotchas.md b/inst/notes/gdalcubes-pc-gotchas.md index bdecf87..748dba1 100644 --- a/inst/notes/gdalcubes-pc-gotchas.md +++ b/inst/notes/gdalcubes-pc-gotchas.md @@ -205,7 +205,7 @@ Measured on gdalcubes 0.7.5, rstac 1.0.1 and terra 1.9.50, with the BULK floodpl - Verified live: corrupted tokens read 102,364 cells after re-signing, 0 without. With re-signing, a full 3 h 16 min BULK read had no failed tiles. - **gdalcubes reports failed chunks only on stderr**, as `[WARNING] n out of m chunks have repoprted errors / incompleteness`. It is not an R warning. The cube is written with those chunks NA and passes an any-data check. - `capture.output(type = "message")` caught the line in 1 of 4 configurations, and never with `parallel > 1`, where workers write to the process's stderr directly. - - Do not build a guard on it. Detection is #87. + - Do not build a guard on it. The output file records the same failure reliably; see the #87 section below. - **terra reads a multi-variable gdalcubes NetCDF with its variables in ALPHABETICAL order.** A true-colour `apply_pixel(names = c("red","green","blue"))` reads back as `blue, green, red`, so select layers by name, never by position. The composite does this in `composite_layers_order()`. - The layers also arrive carrying a time (step `yearmonths`). - Writing that to a COG makes terra emit a `.aux.json` sidecar. So do units, varnames, longnames, metags and scoff; names alone do not. @@ -228,3 +228,29 @@ Measured on gdalcubes 0.7.5, rstac 1.0.1 and terra 1.9.50, with the BULK floodpl - `count_zero_na()` maps 0 to NA, after which the chunkings agree. - NA rather than 0, because a failed chunk read is NaN too. - **`create_image_collection(one_band_per_file = FALSE)` on two-band GeoTIFFs segfaulted a worker** (0.7.5). Separate files per band with a format JSON work. The #92 test fixture uses them. + +## Detecting failed chunk reads (#87, 2026-10-02) + +Measured on gdalcubes 0.7.5 (`appelmar/gdalcubes@ed68331`) with a local collection whose image is deleted after the collection is built, which fails the read the way an expired signed URL does. Fixture: `chunk_fixture()` in `tests/testthat/helper-gdalcubes.R`. + +- **`write_ncdf()` records every chunk's status in the output file**, as an integer variable `chunk_status` with one value per chunk: `0` OK, `1` ERROR, `2` INCOMPLETE, `128` UNKNOWN (`src/gdalcubes/src/cube.cpp`, `cube.h`). A chunk with no status written keeps the netCDF integer fill, `-2147483647`: a worker skips writing a chunk that is OK and all-NA (no image, or fully masked), and a chunk whose merge threw keeps it too. A worker carries the status to the main process inside its chunk file, so the record does not depend on `parallel`: + + | parallel | stderr line | `chunk_status` non-OK | non-NA cells | + |---|---|---|---| + | 1, clean (daily, 2 scenes) | none | 0 | 3200 | + | 4, clean | none | 0 | 3200 | + | 1, one image gone | printed | 9 of 279 (`2`) | 1600 | + | 4, one image gone | **not printed** | 9 of 279 (`2`) | 1600 | + | 4, one image gone, monthly median | not printed | 1 of 1 (`2`) | **1600 of 1600, every cell** | + +- **The last row is why a pixel check cannot do this.** A median over two scenes where one failed fills every cell from the survivor, so the holed cube has no NA at all. The issue's third option (require data under every item footprint) would have passed it. +- **Read it with ncdf4, not terra.** GDAL does not list a one-dimensional variable as a subdataset, so `terra::rast(f, subds = "chunk_status")` errors; the `NETCDF:"f":chunk_status` form opens but prints a stray `R_nc4_open` error line. ncdf4 is a gdalcubes import. +- **The `[WARNING]` line is C++ stdio**, so neither an R handler nor `capture.output()` silences it, even at `parallel = 1`. +- **Only one failure is recorded: a band image that fails to open.** gdalcubes sets `chunk_status` in six places, all in `image_collection_cube::read_chunk()`, and only band `GDALOpen` returning NULL can fire in practice; every other I/O step between `GDALOpen` and the final `nc_close` drops its return code or warns and continues. A code-check enumeration of the write pipeline (#87, round 3, `planning/archive/2026-10-issue-87-silent-chunk-read-failures/review-round3.md`) found 38 failure paths: 25 detected by drift (13 through `chunk_status` or the merge warning, 12 as an R error before anything is cached), 13 not. The ones that matter: + - a band image that opens then fails mid-read: status OK, cells filled from the scenes that read; + - **a mask (SCL) image that opens then fails mid-read: the scene is used UNMASKED** — cloud values in the median, not NA (measured: an all-cloud scene gave 1600 of 1600 cells, status OK); + - a mask image that fails to open, or a scene with no mask asset: dropped, or used unmasked; + - a worker that writes no chunk file, or a partial or unreadable one: status OK or fill, no R warning; + - a worker killed by a signal: `write_ncdf()` hangs. + These are drift#99. A chunk whose merge throws keeps fill and raises an R warning (`Chunk N could not be added to output`), which drift does catch. +- `cube_write_ncdf()` is drift's one `write_ncdf()` call, in `stac_cube_assemble()` and `fetch_extent_to()`. It notes the merge warning, lets gdalcubes return (aborting from inside an `Rcpp::warning()` handler would skip its C++ cleanup), then aborts on it or on `chunk_status`, so a failed read aborts before anything is cached. Before it, the offline fixture showed both `dft_stac_composite()` and `dft_stac_fetch()` caching the holed result, tiled and untiled. diff --git a/planning/active/findings.md b/planning/active/findings.md index 17eed9c..1c866af 100644 --- a/planning/active/findings.md +++ b/planning/active/findings.md @@ -90,3 +90,57 @@ the mosaic. Cache key untouched (no new argument). | Error | Resolution | |-------|------------| + +## Plan review triage (2026-10-02) + +Full summary in `review-plan.md`. Probed offline before acting (scratchpad `probe3.R`, +local fixture, `select_bands(B04)`, monthly median, 9 chunks of 16x16, p = 1 and 4): + +| case | p=1 status | p=4 status | non-NA cells | +|---|---|---|---| +| clean, SCL mask | 0x9 | 0x9 | 1600 | +| B04 deleted (open fails) | 2x9 | 2x9 | 1600 | +| B04 truncated (open fails) | 2x9 | — | 1600 | +| **B04 opens, tile data corrupt (read fails)** | **0x9** | **0x9** | 1600 | +| **SCL deleted, SCL mask** | **0x9** | **0x9** | 1600 | + +- **Reviewer right on its high-severity claim.** `chunk_status` records only a band + asset that fails to OPEN. A read that fails after a good open, and a mask asset that + fails to open, leave status 0 and every cell filled from the surviving scene. + (A corrupted tile with the IFD intact: `terra::values()` errors, gdalcubes reports OK.) +- `gdalcubes_options(log_file =, debug = TRUE)` writes 11 identical lines for clean and + failing reads alike, at p = 1 and 4: not a detector either. +- What the guard does cover: an expired or corrupted SAS token, a 403/404 at open — the + #79 failure (every chunk of 15 tiles failed) and the issue's acceptance test. +- Reviewer's "fill appears only with workers" is wrong: probe 1 showed fill at p = 1 + too. Harmless — the tests run p = 4 regardless. + +Plan changes (in the mandate; none touches stored data): +- message drops "throttled"; says a persistent failure is not fixed by re-running +- integration tests at `parallel = 4`; two-year composite (incomplete not swallowed as a + skip); offset-split assemble with the broken read on the post side; un-wire → red +- tiled fetch: tile cleanup registered before the reads +- GDAL HTTP retries in both session/config blocks, since a transient open failure now + aborts the run (and retries also shrink the undetectable mid-read class) +- untiled fetch caches are the gdalcubes `.nc`: check `chunk_status` on cache hit and + treat a failed one as a miss, so holed caches from earlier versions re-fetch +- follow-up issue: read-after-open and mask-open failures are undetected; draft an + upstream gdalcubes proposal there (set INCOMPLETE on warp/RasterIO and mask-open + failure) — not posted +- not taken: build_stack's tempfile never unlinked (pre-existing); log_file route (dead) + +## Code-check rounds (2026-10-02) + +| Round | Findings | Fixed | Accepted / moved | Inside previous fix? | +|---|---|---|---|---| +| 1 | 1 (fill also = unmerged chunk) | 1 (`cube_write_ncdf()` merge warning) | worker-signal hang → #99 | — | +| 2 | 3 | 2 (abort after write returns; retries on every fetch) | unreadable worker chunk file → #99 | **yes**: aborting inside the `Rcpp::warning` handler skipped C++ cleanup | +| 3 | 3 + 4 low, + enumeration | test ordering; notes/roxygen | 9 gdalcubes paths → #99 by class | **yes**: round 2's merge test could not fail (mutant green) | + +Ended by enumeration (round 3, `review-round3.md`): 38 failure paths in gdalcubes' +write pipeline — 25 detected by drift, 4 already in #99, 9 added to #99. The +mechanism: gdalcubes sets `chunk_status` only on band `GDALOpen` failure; every other +I/O step drops its return code. Nothing on the list is fixable in drift. + +Worst undetected case (measured, round 3): a mask image that opens then fails +mid-read leaves the scene UNMASKED — cloud values in the result, status OK. diff --git a/planning/active/progress.md b/planning/active/progress.md index 2cfeeb5..5954e75 100644 --- a/planning/active/progress.md +++ b/planning/active/progress.md @@ -6,3 +6,14 @@ - Created branch `87-failed-gdalcubes-chunk-reads-are-silent` off main - Scaffolded PWF baseline from issue #87 with approved phases - Next: start Phase 1 +- Phase 1: `cube_check_chunks()` + offline fixture; red-then-green; no-op mutation red +- Plan review: chunk_status records band OPEN failures only (probed: read-after-open + and SCL-open failures stay OK; log_file no help). Scope narrowed; drift#99 filed +- Phase 2: `cube_write_ncdf()` wired into both write sites; integration tests red + before wiring and after un-wiring; offset-split S4 class loss found and fixed; + cache-gate arm; retries; tile cleanup +- code-check round 1 (fill = unmerged chunk), round 2 (abort inside Rcpp warning + handler — a defect inside round 1's fix; unreadable worker chunk file; untiled + retries) fixed; round 3 asked for an enumeration of gdalcubes failure paths +- Live probe 8 of 8 (`data-raw/logs/probe_chunk_status_live/20261002T140832Z.txt`) +- Full suite: FAIL 0 | PASS 1548 diff --git a/planning/active/review-plan.md b/planning/active/review-plan.md new file mode 100644 index 0000000..3e52685 --- /dev/null +++ b/planning/active/review-plan.md @@ -0,0 +1,25 @@ +# Plan review (Plan agent, 2026-10-02) — summary + +No blocker. Claims to verify before acting: + +1. Assumption (high): chunk_status flags only open failures. Reads that fail after + GDALOpen succeeds (throttling, a token expiring mid-extent) leave NaN with status OK + (image_collection_cube.cpp:424-437, warp.cpp:256/650-654). Probe: truncate a TIFF. +2. Gap: a failed mask (SCL) open `continue`s the image loop with no set_status + (image_collection_cube.cpp:569-579) — silent thinner composite. Probe: delete SCL only. +3. Gap: fill appears only with workers (claim) — integration tests should run at parallel 4. +4. Gap: master merge failure leaves fill + an Rcpp::warning("Chunk N could not be added"). +5. Assumption: transient 5xx/429 at open now aborts a long run; add GDAL_HTTP_MAX_RETRY / + RETRY_DELAY; a persistent 404 aborts every run, so "re-run" wording misleads. +6. Gap: composite year loop catches drift_no_items / drift_empty_cube — test that + drift_incomplete_cube is not swallowed (two-year test). +7. Gap: dft_stac_cube offset-split path (two build_stack + cover) and count path untested. +8. Ordering: integration tests before wiring + un-wire to confirm red; tiled fetch tile + files unlinked only after the vapply; build_stack tempfile never unlinked (pre-existing). +9. Scope: holed caches written before the fix stay served; untiled fetch caches are the + .nc and could be checked in cache_hit_ok(); NEWS should advise force = TRUE. +10. Acceptance: live probe should name cube/composite and fetch, tiled and untiled, the + parallel used, and include a live false-abort control (months = 6:9 at parallel 4). +11. ncdf4 in Suggests is fine (gdalcubes import(ncdf4)). + +Triage: see findings.md "Plan review triage". diff --git a/planning/active/review-round1.md b/planning/active/review-round1.md new file mode 100644 index 0000000..373b29b --- /dev/null +++ b/planning/active/review-round1.md @@ -0,0 +1,68 @@ +# Code review — round 1, #87 Phase 1 (`cube_check_chunks()` + tests) + +Reviewed the staged diff (DESCRIPTION, R/dft_stac_cube.R, tests/testthat/helper-gdalcubes.R, +tests/testthat/test-dft_stac_cube.R, planning/active/task_plan.md). I worked in a copy +(scratchpad/drift_r1, with unstaged Phase-2 edits reverted to the index) and against gdalcubes +0.7.5 source at the installed SHA ed68331 (cube.cpp, cube.h, and src/multiprocess.cpp, fetched for this review). + +## Findings + +- **[fragile]** R/dft_stac_cube.R:776 (`failed <- ... & status != -2147483647L`), with the + roxygen claim at :733-736 — **reading the fill value as "fine" lets an unmerged chunk pass.** + The docstring says fill marks chunks "gdalcubes never visits, because no image intersects + them". The source says otherwise. R's gdalcubes always runs `chunk_processor_multiprocess` + (`gc_set_process_execution`, even at `parallel = 1`). A worker skips writing any chunk whose + status is OK and whose data is all-NaN (`chunk_data::write_ncdf`, cube.cpp:1808-1811). The main + process writes `chunk_status` only from inside `f()`, which it calls after a successful + `read_ncdf()` of a worker's chunk file (multiprocess.cpp:126-142). So fill means **"no chunk was + merged for this id"**, which covers two cases: + (a) a worker skipped writing an OK all-NaN chunk. This is legitimate and includes chunks whose + scenes were fully cloud-masked, not only chunks no image intersects. + (b) the main process never merged a chunk. One way is a merge exception. That path only calls + `Rcpp::warning("Chunk N could not be added to output.")` and `continue`s + (multiprocess.cpp:133-141), so it is an R **warning**, not an error. Another way is a worker that + exits 0 without writing its chunks. + Measured (b) in the copy: I swapped the worker script for one where worker 1 exits 0 before + `gc_exec_worker()`. `write_ncdf()` returned normally, `chunk_status` was 265 fill / 14 OK, + notNA was 4864 of 6400, and **`cube_check_chunks()` passed**. So the guard is sound for chunks + that were merged with a non-OK status. Nothing in `chunk_status` separates (a) from (b), + though. When this is wired in (Phase 2), the write sites should also turn gdalcubes' + `"could not be added to output"` R warning into an abort, e.g. with `withCallingHandlers()` + around `write_ncdf()`. The docstring's description of fill should also be corrected, so the + next reader does not take fill to mean "provably empty". Severity is fragile, not bug: the + realistic trigger is a merge exception (e.g. `bad_alloc` while reading a chunk file back), + not the common expired-token case, which this commit does catch. + +## Verified clean (checked, no action) + +- The tests pass in the copy (5 blocks, 0 failures, about 9 s). The guard is proven to fire. + When I no-op the abort (`return` before `any(failed)`), tests 2, 3 and 4 go red. When I treat + fill as failure, test 1 goes red. Both directions are pinned. +- The broken fixture writes status `2` (INCOMPLETE) for 9 chunks and `0` for 9, with 261 fill, + at both `parallel = 1` and `4`. "9 of 279" matches. With and without `raw_datavals`, ncdf4 + returns the fill as `-2147483647L`, not `NA`: no `_FillValue` attribute is written and + `missval` is `NA`. So the `!is.na()` term never masks a real value. +- The no-variable branch aborts with the right class (test 45). The message renders. The only + blemish is a double space where a single `\` continuation meets the next line. That is + cosmetic and not reported. +- `ncdf4::` from R/ code with ncdf4 in Suggests is not flagged by `R CMD check`. ncdf4 is a hard + Import of gdalcubes, so it is present whenever the check can be reached. +- The helper's `gdalcubes_options(parallel=)` save/restore uses `on.exit`. Its tempfiles and + tempdir are scoped to the calling test through `envir = parent.frame()`. It has no top-level + side effects. + +## Out of scope, but you should know (upstream gdalcubes, not this diff) + +- When a worker is killed by a signal (SIGKILL as from the OOM killer, or signal 11), the main + `write_ncdf()` **hangs**. In clean sequential re-runs, both SIGKILL and signal 11 were still + hung at the 150 s timeout. An earlier SIGKILL run sat for 5 min until I killed it. While it + hangs it neither raises nor returns, so no chunk-status check is ever reached. The main process + printed `[ERROR] worker process #1 returned 9` only once it was sent SIGTERM. A worker that + exits with status 1 (an R error) does raise promptly ("returned 1"). My first "SIGSEGV" probe + was in fact an R error, because `tools::SIGSEGV` does not exist. The signal-11 result comes + from the corrected re-run. This + matters for the floodplain-scale runs CLAUDE.md asks for, and #92 records a real worker + segfault. I have not diagnosed the mechanism. It may deserve its own issue. Nothing was posted + upstream. + +Probe scripts: scratchpad/r1_probe.R, r1_kill.R, worker_{exit0,segv,kill9}.R, r1_run.R. diff --git a/planning/active/review-round2.md b/planning/active/review-round2.md new file mode 100644 index 0000000..b92f389 --- /dev/null +++ b/planning/active/review-round2.md @@ -0,0 +1,142 @@ +# Code review: round 2, #87 Phase 1 + 2 (staged diff) + +I worked in a copy (`scratchpad/drift_r2`) and checked against the gdalcubes source at the +installed SHA ed68331. I fetched `multiprocess.cpp`, `image_collection_cube.cpp`, +`reduce_time.cpp`, `apply_pixel.cpp`, `select_bands.cpp`, `aggregate_time.cpp`, +`filter_pixel.cpp` and `filesystem.cpp` for this review. +All #87 test blocks pass in the copy. Counts are expectations (nb) per block: + +| file | blocks | nb per block | failures | +|---|---|---|---| +| cube | 8 | 2, 4, 2, 3, 1, 2, 1, 2 | 0 | +| composite | 4 | 2, 2, 6, 2 | 0 | +| fetch | 4 | 2, 2, 4, 3 | 0 | + +Every probe ran under `timeout`, and none was left running (checked with `ps`). + +## Findings + +- **[fragile]** R/dft_stac_cube.R:745-756 (`cube_write_ncdf()`, the `cli_abort()` inside the + `withCallingHandlers(warning = )` handler). **The abort longjmps through gdalcubes' C++ frames.** + - **How it happens.** gdalcubes raises the warning with `Rcpp::warning("Chunk" + id + " could + not be added to output.")` (multiprocess.cpp:139/143). That call takes the + `std::string` overload, which is a bare `::Rf_warning("%s", ...)` (Rcpp 1.1.2 + `include/Rcpp/exceptions.h:115-117`). An R calling handler runs synchronously inside + `Rf_warning`, and a handler that aborts makes a non-local exit across C++. Rcpp's own header + says so, at :190-194: "Rf_warning() may longjmp out of this frame ... A longjmp skips C++ + destructors". + - **What it skips.** The call sits inside a `catch` block in + `chunk_processor_multiprocess::apply()`. The jump therefore skips: + - the worker-process teardown. The `TinyProcessLib::Process` objects are never destroyed, + killed or waited on, so the workers keep reading images (network, CPU, memory) after R + has reported the abort. They then linger as zombies. + - `filesystem::remove(work_dir)` + - `nc_close(ncout)` on the output file in `cube::write_ncdf()` + - `__cxa_end_catch` for the caught exception + - **Why it matters.** The abort message tells the user to re-run. Re-running starts a fresh + set of workers alongside the orphans. + - **Reachability.** At this SHA it is low. `chunk_data::read_ncdf()` never throws, so the + warning fires only when an exception escapes `f()`, such as a `bad_alloc`. I could not + trigger it without patching gdalcubes, so the consequence is read from source, not + measured. + - **Fix.** Record a flag in the handler and abort after `gdalcubes::write_ncdf()` returns: + + ```r + unmerged <- character(0) + withCallingHandlers(gdalcubes::write_ncdf(cube, out, overwrite = TRUE), + warning = function(w) { + if (grepl("could not be added to output", conditionMessage(w), fixed = TRUE)) + unmerged <<- c(unmerged, conditionMessage(w)) + }) + if (length(unmerged)) cli::cli_abort(class = "drift_incomplete_cube", ...) + ``` + + This keeps the same guarantee that nothing is cached, and gdalcubes gets to finish its own + cleanup. The existing mocked test is unaffected, since its warning is raised at R level + either way. + +- **[fragile]** R/dft_stac_cube.R:738-743 and :760-781, and inst/notes "#87" section. + **The reachable merge failure is recorded as OK and raises no warning, so it passes both + guards.** + - **The documentation's claim.** The roxygen says "a chunk the main process could not merge + back from its worker raises an R warning" and "a chunk whose merge failed also keeps fill". + Both statements are wrong for the most likely merge failure: a worker chunk file that the + main process cannot open. + - **Why upstream records it as OK.** `chunk_data::read_ncdf()` (cube.cpp:1862-1867) does a + bare `return` when `nc_open()` fails. It never calls `set_status()`, and the + `chunk_data` default is `OK` (cube.h:276). So `f()` writes `chunk_status = 0` with no data, + and nothing throws, so the "could not be added" warning never fires. + - **How a worker produces such a file.** The worker writes the chunk with unchecked + `nc_create`/`nc_put_vara` return codes (cube.cpp:1815-1857), then renames it into place + regardless. A tempdir that fills mid-run (floodplain-scale reads are GB-scale) can + therefore leave a truncated `N.nc` for the main process to read. + - **Measured** (`scratchpad/worker_garbage.R` + `r2_garbage.R`). Worker 1 drops an + unreadable `N.nc` for each chunk it owns (70 of 279) and exits 0. The result: + - `cube_write_ncdf()` **PASSED** + - **0 R warnings** + - `chunk_status` was 195 fill / **84 OK** + - notNA 4864 of a clean 6400, so 1536 cells silently NA + - the only signal was `[ERROR] Failed to open netCDF file ... nc_open() returned -51` + on C++ stderr + - **Recommendation.** Nothing drift can read separates this case from a complete cube. Fold it + into the follow-up issue alongside read-after-open and mask-open failures; the upstream + fix is `set_status(ERROR)` on read_ncdf's failure returns. Also correct both roxygen blocks + and the inst/notes bullet, so the warning arm is not credited with covering merge failures. + In practice it covers almost nothing at this SHA. + +- **[fragile, low]** R/dft_stac_fetch.R:117-137. **The new HTTP retries reach only the tiled + fetch.** + - The `gdal_cfg` block sits inside `if (!is.null(tile_size))`. The default untiled + `dft_stac_fetch()` therefore gets no `GDAL_HTTP_MAX_RETRY` / `GDAL_HTTP_RETRY_DELAY`. + - The rationale written into the diff applies there too ("a transient 429 or 5xx now aborts + a whole read"). Before this diff, an untiled fetch that hit one transient 503 at open + silently cached a holed year. With it, the fetch aborts with no retry. + - That is the correct direction, but the stated intent ("retries in both blocks") does not + cover the default path. Setting the two retry variables unconditionally (restored on exit) + would close it. The other tuning variables can stay tile-only. + +## Verified clean (checked, no action) + +- **Abort inside `cache_write_atomic()`.** For the untiled fetch, `cube_write_ncdf()` runs + inside `write_fn(tmp)`, so the `on.exit(unlink(c(tmp, tmp_side)))` removes the temp. A file + netCDF still holds open after the longjmp case is unlinked too (POSIX). +- **Cube and composite.** The abort fires in `stac_cube_assemble()` before any + `cache_write_atomic()`. The tests confirm an empty cache dir for untiled and tiled reads, and + that year 1 stays cached when year 2 fails. +- **ncdf4 handles.** `chunk_status_failed()` closes through `on.exit(nc_close)` on every path, + including an `ncvar_get` error. Opening with ncdf4 while terra's `r` still references the + file works; the cache-gate test exercises exactly that and passes. +- **Status propagation through `pixel_fn`.** apply_pixel, select_bands and filter_pixel copy + the input status. reduce_time and aggregate_time escalate INCOMPLETE/ERROR, including on the + all-empty return. So the check placed after `pixel_fn` sees the source status for the + index, true-colour and count paths. In image_collection_cube, the healthy reads (GDALOpen, + warp and RasterIO all succeed) never set a non-OK status. +- **Cache-gate arm false refusals.** + - It is gated on the `.nc` extension, so cube and composite (`.tif`) and the tiled fetch + (`.tif`) never reach it. + - A terra-written `.nc` has no `chunk_status` and passes (tested). + - Chunks with no image keep fill, and fill counts as OK at parallel 1 and 4 (R gdalcubes + always runs the multiprocess executor). + - Any non-OK status in a gdalcubes `.nc` is a genuine open failure, so refusing it is + intended. + - On a fresh untiled write it re-checks what `cube_write_ncdf()` already checked. That is + redundant but harmless. +- **Building pre/post before `terra::cover()`.** The rasters are file-backed, and the argument + order is unchanged, so results are unchanged. The only difference is that the post side is + now built even when the pre side would abort. The order is pre then post, so a pre abort + still short-circuits. +- **Tiled fetch `on.exit`.** It is registered inside the `function(yr)` closure, so it fires + once per year when that call exits, with `add = TRUE`. `unlink()` of tiles not yet written + is a no-op. A partially written tile is removed. +- **GDAL environment variables.** + - Neither gdalcubes' `.onLoad` nor terra presets `GDAL_HTTP_MAX_RETRY` or + `GDAL_HTTP_RETRY_DELAY` as config options, which would outrank the environment. So + `CPLGetConfigOption` falls back to `getenv` and sees them. + - TinyProcessLib launches workers with no env override, so they inherit the parent's + environment, the same mechanism the existing tuning variables already rely on. + - Both blocks restore every name in `gdal_cfg` (re-set or unset) on exit. + - No test asserts the set of environment variables (grep of `tests/` for + `GDAL_HTTP|VSI_CACHE|CPL_VSIL|READDIR|getenv`). +- **The real warning text.** gdalcubes writes "Chunk3 could not be added to output." with no + space after "Chunk". The `fixed = TRUE` substring still matches it; the test mock's "Chunk 3" + differs only there. diff --git a/planning/active/review-round3.md b/planning/active/review-round3.md new file mode 100644 index 0000000..8bf6016 --- /dev/null +++ b/planning/active/review-round3.md @@ -0,0 +1,223 @@ +# Code review: round 3, #87 (staged diff), enumeration of gdalcubes failure paths + +Worked in a copy (`scratchpad/drift_r3`) against the gdalcubes source at the installed SHA +`ed683314` (0.7.5), fetched for this review: `src/multiprocess.cpp`, `src/gdalcubes.cpp`, +`src/gdalcubes/src/{cube.cpp,cube.h,image_collection_cube.cpp,image_collection_cube.h, +image_collection.cpp,warp.cpp,apply_pixel.cpp,apply_pixel.h,select_bands.cpp,reduce_time.cpp, +filesystem.cpp}`, `R/{cube.R,zzz.R,config.R,plot.R}`, `inst/scripts/worker.R`. Probes ran under +`timeout`; no worker process was left running (checked with `ps`). + +## Mechanism + +The assumption the earlier instances share is that every failure on the path from an image to +the output NetCDF either sets a non-OK `chunk_status` or raises in R. The source shows the +opposite design. gdalcubes sets a status in exactly six places, all in +`image_collection_cube::read_chunk()`: band open, band warp returns nullptr, band RasterIO, mask +warp returns nullptr, mask RasterIO, and all images failed. Every other failure is one of two +things. Either it is a dropped return code (`ChunkAndWarpImage`, every netCDF call on the +worker-to-master hand-off, `CPLMoveFile`, `sqlite3_step`), or it is a `GCBS_WARN` plus `continue` +that leaves the status OK. **Status is set at those six points. Nothing propagates it from the +I/O layers underneath them.** The six points are reachable in practice only through `GDALOpen` +returning NULL: the RasterIO calls read a MEM dataset, and `warp()` never returns nullptr after +`Create()` succeeds. + +So the set drift#99 needs to cover is "every unchecked I/O return between `GDALOpen` and +`nc_close`", not a list of instances. The enumeration below finds five instances that are +neither detected nor in #99. Two are measured. + +## Findings + +- **[fragile]** gdalcubes `image_collection_cube.cpp:620-656` with `warp.cpp:650-654`; drift + `R/dft_stac_cube.R` roxygen of `cube_check_chunks()` and `inst/notes/gdalcubes-pc-gotchas.md:450`. + **A mask (SCL) image that opens and then fails mid-read unmasks the whole scene, with status + OK.** + - **Mechanism.** The mask is warped into a MEM dataset pre-filled with NaN. A failed + `ChunkAndWarpImage` is unchecked, so `mask_buf` holds NaN. `value_mask::apply` + (`image_collection_cube.h:55`) masks a pixel only when `_mask_values.count(v) == 1`, and NaN + never matches. Every pixel is therefore kept. + - **Measured** (`scratchpad/r3_maskread.R`). One scene with B04 = 500 and SCL = 9 (cloud) + everywhere, `image_mask("SCL", values = c(8, 9))`, monthly median, 9 chunks: + + | SCL file | p=1 non-NA | p=4 non-NA | `chunk_status` | + |---|---|---|---| + | readable | 0 of 1600 | 0 of 1600 | fill x9 | + | opens, DEFLATE tile corrupt (`ZIPDecode` error on read) | **1600 of 1600** | **1600 of 1600** | **0 x9** | + + - **Why it is not a duplicate of #99.** #99 row 1 (band mid-read) loses data from the median, + which leaves fewer scenes. Row 2 (mask open fails) drops the scene. This one admits cloud and + shadow **values** into the composite and the index trajectory: wrong numbers, not missing + ones. No pixel check can see it, and nothing else does either. Retries reduce the risk; the + upstream fix in #99's draft (failed warp sets INCOMPLETE) would close it only if it also + covers the mask's warp. #99, its draft and the notes bullet at `gdalcubes-pc-gotchas.md:450` + should name this case. + +- **[fragile]** gdalcubes `src/multiprocess.cpp:241-244`, `cube.cpp:1801-1820`, + `filesystem.cpp:193-195`. **A worker that produces no chunk file at all passes both guards.** + - **Trigger.** `chunk_data::write_ncdf()` ignores `nc_create`'s return code. `exec()` then + moves the file only `if (filesystem::exists(outfile_temp))`, and `CPLMoveFile`'s return is + discarded. A worker that cannot create or rename its chunk file therefore skips the chunk + silently and exits 0. Causes: `EACCES`, `ENOSPC`/quota at create, a failed rename-copy + fallback. + - **Consequence.** The master never merges the chunk. It keeps fill (read as OK), and no R + warning is raised. + - **Measured in round 1** (a worker exiting 0 without writing): 265 fill / 14 OK, 4864 of + 6400 cells, and `cube_check_chunks()` passed. The behaviour is source-read in this round; + the consequence was measured then. + - **Not in #99.** #99 row 3 is a file that *exists* and fails `nc_open`. This case is the + same disk-full family with no file at all. + +- **[fragile]** `tests/testthat/test-dft_stac_cube.R`, "a chunk gdalcubes could not merge + aborts the write (#87)". **The assertion that pins round 2's fix cannot fail under the defect + it names.** + - The mock `file.copy()`s the clean file **before** `warning()`. With an abort from inside the + handler (the round-2 defect), `out` already exists, so `expect_true(file.exists(out) && + file.size(out) > 0)` holds either way. + - **Measured by mutation in the copy.** Replacing the handler body with + `cli::cli_abort(class = "drift_incomplete_cube", ...)`, i.e. an abort inside the handler, + leaves the block green: 3 expectations, 0 failed. + - **Fix, also measured.** Swap the mock's two lines, so it raises `warning(...)` first and runs + `file.copy(...)` after it. The mutant then fails 1 of 3, and the real `cube_write_ncdf()` + passes 3 of 3. + +- **[fragile, doc]** `inst/notes/gdalcubes-pc-gotchas.md:437`. **The notes still carry the + claim round 1 refuted:** "A chunk that no image intersects is never visited and keeps the + netCDF integer fill." + - Fill means that no chunk was merged for that id. That covers an OK all-NaN chunk, which a + worker visits and then skips writing (`cube.cpp:1808-1811`); fully cloud-masked chunks are + included. It also covers an unmerged chunk. + - The roxygen was corrected and this copy was not. A reader of the notes would take fill to + mean "provably empty", which is the premise the round-1 fix exists to reject. + - Related staleness, outside the diff: #99's "Mitigation already in drift" says the retries + are on "the cube/composite session and the tiled fetch". This diff now sets them on every + fetch. + +- **[fragile, low]** gdalcubes `cube.cpp:1883-1901` and `:1919`. **A worker chunk file that + opens but is partial is merged as OK, and the data-read case merges uninitialized memory.** + - The status comes from the global attribute, which is read first. If the `x/y/t/b` + dimensions or the `value` variable are missing, `read_ncdf()` returns empty with that status + (OK), so those cells are NA. + - If they are present and `nc_get_var_double` fails, its return is unchecked. The buffer was + `std::malloc`ed and never filled, so **arbitrary values** are merged under status OK. These + are not NA, so a pixel check passes them. + - Not measured; it needs a crafted HDF5 file whose header is intact over unreadable data. + #99 row 3 names only the `nc_open` failure. It should name the hand-off as a class. + +- **[fragile, low]** gdalcubes `image_collection_cube.cpp:565-566`. **A scene with no mask + asset is used unmasked, with status OK and only a stderr `[WARNING]`.** + - **Measured** (`scratchpad/r3_nomask.R`). Scene 1 is B04 = 500 with SCL = 9. Scene 2 is + B04 = 700 with no SCL file in the collection. The median is 700 in all 1600 of 1600 cells, + status 0 x9, at p = 1 and 4. + - **Reachability.** It needs a STAC item returned without its mask asset, which is rare on + Planetary Computer S2 L2A. The same code shape also skips an image whose *band* asset is + absent while its mask is present (`:411-412`, `image_datasets.empty()`). + +- **[fragile, low]** gdalcubes `image_collection.cpp:~1429` + (`while (sqlite3_step(stmt) == SQLITE_ROW)`). **A step error truncates a chunk's image list + silently.** `SQLITE_BUSY`, `IOERR` or `FULL` mid-query ends the loop as if the rows had run out. + The chunk is then computed from fewer images, or none, and the status is OK; an empty result + returns early at `image_collection_cube.cpp:329` as OK. Low reachability: workers only read + the collection DB, so a concurrent writer cannot cause it. It takes an I/O error, or a full + temp dir during the ORDER BY sorter's spill. Source-read only. + +### Round-2 fixes: checked, no defect + +- **Muffling inside a C-raised warning is safe.** `Rf_warning` reaches R through + `.signalSimpleWarning`, which establishes `muffleWarning` with `withRestarts()` in an R frame + *below* the gdalcubes C++ frames. `invokeRestart()` therefore unwinds only R frames created + after the C++ call and skips no destructor. Muffling hides nothing, because the abort that + follows carries the count and the first message. +- **Bonus, measured.** Under `options(warn = 2)` the handler muffles before `.dfltWarn` can + convert the warning to an error, so the wrapper also prevents the longjmp that `warn = 2` + would otherwise cause. The run returned `drift_incomplete_cube` as intended. +- **`{unmerged[[1]]}` in cli is safe.** cli substitutes values without re-parsing them. A probe + message containing `Chunk{x} ... {.val y} }{` rendered literally, and the class stayed + `drift_incomplete_cube`. gdalcubes' real text is `"Chunk could not be added to output."` + (`multiprocess.cpp:139/143`), which contains no braces. +- **Unconditional retry block in `dft_stac_fetch()`.** Its names + (`GDAL_HTTP_MAX_RETRY/RETRY_DELAY`) are disjoint from the tiled block's `gdal_cfg`. So the + FIFO order of the two `on.exit(add = TRUE)` handlers cannot re-set a value the other + restored. It is registered before every abort point that follows, including + `tile_size_check()` and the config resolution. +- **Doc claims checked against source.** + - **True:** the enum values (`cube.h:266-271`), "a chunk whose merge threw keeps fill" + (`read_ncdf` throws before `f()` writes the status), "always multiprocess", "worker carries + status in its chunk file" (`cube.cpp:1832-1833`, `:1866-1871`), and a missing attribute + reads as UNKNOWN 128. + - **Incomplete:** the notes bullet at `:450` ("Not every failure is recorded") omits findings + 1, 2, 5 and 6 above. + +## Enumeration + +(a) = detected: a non-OK `chunk_status` caught by `cube_check_chunks()`, the merge warning +caught by `cube_write_ncdf()`, or an R error that propagates out of `write_ncdf()` before +anything is cached (noted "err"). (b) = listed in drift#99. (c) = neither. + +| # | where (gdalcubes @ed68331) | trigger | status / signal | class | +|---|---|---|---|---| +| 1 | R `cube.R:886-890` | not a cube; file exists without overwrite | R `stop()` | a (err), unreachable: drift passes `overwrite = TRUE` | +| 2 | R `cube.R:910-915` | cube-cache hit copies an earlier file | silent `file.copy` | n/a: the cache is populated only by `plot.R:109-118/345-354`; drift never plots its internal cubes, and a per-call collection path makes the hash unique | +| 3 | `gdalcubes.cpp:1339-1374` | `std::string` thrown anywhere in `write_netcdf_file` | `Rcpp::stop` | a (err) | +| 4 | `cube.cpp:621-634` | output is a dir / irregular space | throw → `Rcpp::stop` | a (err) | +| 5 | `cube.cpp:752-754` | output `nc_create` fails | unchecked; write returns | a (err): `ncdf4::nc_open` in `cube_check_chunks()` errors on the missing file; drift's outputs are fresh tempfiles, so no stale file can stand in | +| 6 | `cube.cpp:969,1094,1103` | output `nc_put_var1_int`/`nc_put_vara`/`nc_close` fail (output disk full) | unchecked | c, low: undetected only if the file still opens; otherwise `ncdf4`/terra raise (not a finding by itself; grouped with the hand-off class) | +| 7 | `multiprocess.cpp:22-25` | work dir already exists | throw → `Rcpp::stop` | a (err) | +| 8 | `multiprocess.cpp:90-102,178-189,227-228` | a worker exits > 0 (R error in a worker, incl. any C++ throw in `read_chunk`) | `Rcpp::stop` | a (err) | +| 9 | `multiprocess.cpp:149-160,223-225` | user interrupt | `Rcpp::stop` | a (err) | +| 10 | `multiprocess.cpp:137-145` | exception merging a chunk (`read_ncdf`/`f()` throws) | `Rcpp::warning("Chunk could not be added")`, fill | a (`cube_write_ncdf`) | +| 11 | `multiprocess.cpp:84-102` + TinyProcessLib | worker killed by a signal | `write_ncdf()` hangs | b | +| 12 | `multiprocess.cpp:241` | `read_chunk` throws inside a worker (`exec` has no handler) | worker R error, exit 1 → row 8 | a (err) | +| 13 | `multiprocess.cpp:241-244`, `cube.cpp:1815-1820`, `filesystem.cpp:193` | worker `nc_create` or `CPLMoveFile` fails, so no chunk file | fill, no warning | **c** (finding 2) | +| 14 | `cube.cpp:1801-1804` | worker temp file already exists | `GCBS_ERROR`, no file | n/a: unique job dir | +| 15 | `cube.cpp:1808-1811` | OK and all-NaN chunk (no image, fully masked, all values NaN) | not written, fill | a (legitimate; fill read as OK by design) | +| 16 | `cube.cpp:1859-1862` | worker chunk file fails `nc_open` | OK, empty | b | +| 17 | `cube.cpp:1866-1871` | chunk file without the status attribute | UNKNOWN (128) | a | +| 18 | `cube.cpp:1883-1901` | chunk file lacks dims or `value` var | status from attribute (OK), empty | **c** (finding 5) | +| 19 | `cube.cpp:1919` | `nc_get_var_double` fails | unchecked; uninitialized buffer merged, OK | **c** (finding 5) | +| 20 | `image_collection_cube.cpp:317-321` | chunk id out of range | empty OK | n/a | +| 21 | `image_collection.cpp:1426` | query prepare fails | throw → row 8/12 | a (err) | +| 22 | `image_collection.cpp:~1429` | `sqlite3_step` error mid-query | truncated image list, OK | **c** (finding 7) | +| 23 | `image_collection_cube.cpp:329-331` | no image intersects | empty OK | a (legitimate) | +| 24 | `image_collection_cube.cpp:411-412` | image has no requested band (band asset absent) | skipped, OK | **c**, low (finding 6) | +| 25 | `image_collection_cube.cpp:414-416` | image outside the chunk's time range | skipped | n/a (legitimate) | +| 26 | `image_collection_cube.cpp:425-438` | band `GDALOpen` fails (strict: ERROR; drift is non-strict: INCOMPLETE) | 2 | a | +| 27 | `image_collection_cube.cpp:440-443` | dataset opens with 0 raster bands | skipped, OK | c, negligible: not reachable for COG assets; counted, not reported | +| 28 | `image_collection_cube.cpp:462-463,597-598` | `GDALTranslateOptionsNew` fails | throw → row 12 | a (err) | +| 29 | `warp.cpp:92-93,280,287,455-456,496-498` | MEM driver missing / transform cannot be inverted | throw → row 12 | a (err) | +| 30 | `warp.cpp:253-256,646-654` (band) | warp `Initialize` or `ChunkAndWarpImage` fails after a good open (range-request 429/5xx after retries, token expiry mid-extent, corrupt tile) | NaN, OK | b (row 1 of #99; `Initialize` failure falls through the same unchecked path) | +| 31 | `image_collection_cube.cpp:509-522` | band warp returns nullptr | 2 | a (unreachable: `warp()` returns its MEM dataset) | +| 32 | `image_collection_cube.cpp:538-551` | band RasterIO fails | 2 | a (unreachable: reads a MEM dataset) | +| 33 | `image_collection_cube.cpp:565-566` | image has no mask band | `GCBS_WARN`, used **unmasked**, OK | **c** (finding 6, measured) | +| 34 | `image_collection_cube.cpp:570-579` | mask `GDALOpen` fails | scene dropped, OK (strict: empty OK) | b | +| 35 | `image_collection_cube.cpp:620-633` | mask warp returns nullptr | 2 | a (unreachable, as row 31) | +| 36 | `warp.cpp:646-654` via mask path | mask opens, then the read fails | mask NaN → **nothing masked**, OK | **c** (finding 1, measured) | +| 37 | `image_collection_cube.cpp:636-649` | mask RasterIO fails | 2 | a (unreachable, MEM) | +| 38 | `image_collection_cube.cpp:663-665` | every image failed | ERROR (1) | a | +| 39 | `image_collection_cube.cpp:674-678` | all-NaN result keeps its status | INCOMPLETE/ERROR written by the worker | a | +| 40 | `apply_pixel.cpp:40-45` | input status / empty input | propagated | a | +| 41 | `apply_pixel.cpp:75-84` | `te_compile` fails in `read_chunk` | empty, input status | n/a: same expressions are validated in the constructor (`apply_pixel.h:106-111`, throws) | +| 42 | `select_bands.cpp:36,44-46` | passthrough / propagation | propagated | a | +| 43 | `reduce_time.cpp:533-535` | `size_t == 1` passthrough | input chunk as-is | a | +| 44 | `reduce_time.cpp:573` | unknown reducer | throw → row 12 | a (err) | +| 45 | `reduce_time.cpp:584-591,604-608` | input ERROR/INCOMPLETE, incl. the all-empty return | escalated | a | +| 46 | `cube.cpp:1108-1112` | `chunk_error_count > 0` | `GCBS_WARN` on C++ stdio only | not a signal; `chunk_status` carries it (a) | + +Not used by drift, so not enumerated: `aggregate_time`, `filter_pixel`, `filter_geom`, `ncdf_cube`, +`write_chunks_netcdf` (`chunked = TRUE`), packing. + +**Counts** (rows that are failure paths; n/a and legitimate-empty rows excluded): + +- **(a) 25.** 13 via `chunk_status` or the merge warning: rows 10, 17, 26, 31, 32, 35, 37, + 38, 39, 40, 42, 43, 45 (46 shares 26's status). 12 via an R error propagating out of + `write_ncdf()`: rows 1, 3, 4, 5, 7, 8, 9, 12, 21, 28, 29, 44. Rows 15, 23 and 25 are + legitimate empties; rows 2, 14, 20 and 41 are unreachable from drift. +- **(b) 4:** rows 11, 16, 30, 34. +- **(c) 9:** rows 6, 13, 18, 19, 22, 24, 27, 33, 36. + - **Reported as findings:** 13, 33 and 36 (two measured), and 18/19 and 22 (low, from + source). + - **Low:** 24 (finding 6, with 33). + - **Not reported on its own:** 6 (output-side unchecked writes, low) and 27 (negligible). + +The (c) rows share one mechanism with #99's rows 1 and 3: dropped I/O return codes under a +status that is set only at `GDALOpen`. Of the nine (c) rows, the one that changes values +rather than removing them is 36, which leaves clouds unmasked. That is the one to lead with in +#99 and the upstream draft. diff --git a/planning/active/task_plan.md b/planning/active/task_plan.md index 6a67c5c..bb9ae3f 100644 --- a/planning/active/task_plan.md +++ b/planning/active/task_plan.md @@ -10,53 +10,72 @@ When gdalcubes cannot read some chunks of a cube (an expired signed URL, a refus This affects `dft_stac_cube()` and `dft_stac_composite()` (shared `stac_cube_assemble()`), and probably `dft_stac_fetch()` (same gdalcubes write). ## Phase 1: Chunk-status guard + unit tests -- [ ] `tests/testthat/helper-gdalcubes.R`: offline fixture builder (local B04 + SCL +- [x] `tests/testthat/helper-gdalcubes.R`: offline fixture builder (local B04 + SCL tifs, `create_image_collection()`), with an option to delete one image after the collection is built -- [ ] Failing tests for `cube_check_chunks(nc_file)`: clean file passes at +- [x] Failing tests for `cube_check_chunks(nc_file)`: clean file passes at `parallel = 1` and `4`; broken file aborts (class `drift_incomplete_cube`) at both; the monthly-median case with every cell non-NA still aborts; a NetCDF with no `chunk_status` variable aborts (fail toward abort, not pass) -- [ ] Implement `cube_check_chunks()` in `R/dft_stac_cube.R`: failure = any value +- [x] Implement `cube_check_chunks()` in `R/dft_stac_cube.R`: failure = any value not in `{0, NC_INT fill}` (so a future status code fails toward abort); - message names n of m chunks, the likely causes (expired token, throttling), - and that nothing was cached -- [ ] `ncdf4` → Suggests; restore the bug (no-op the check) and confirm the + message names n of m chunks, the likely cause (an image that would not + open: expired or refused URL — "throttling" dropped, see findings) and that + nothing was cached +- [x] `ncdf4` → Suggests; restore the bug (no-op the check) and confirm the tests go red ## Phase 2: Wire into both write sites -- [ ] Call `cube_check_chunks(tmp)` in `build_stack()` after `write_ncdf()` -- [ ] Call it in `fetch_extent_to()` after `write_ncdf()` -- [ ] Integration tests (offline; `stac_image_collection` mocked to return the - broken fixture collection, STAC query helpers stubbed): `dft_stac_composite()` - untiled and tiled, and `dft_stac_fetch()` untiled and tiled, each abort with - `drift_incomplete_cube` and leave the cache directory empty; the clean fixture - still returns a raster and caches it -- [ ] Existing cache-key frozen tests still pass unchanged (key not affected) +Amended after the plan review and code-check rounds 1-2 (findings.md, "Plan review +triage"; review-round1.md, review-round2.md). +- [x] `cube_write_ncdf()`: drift's one `write_ncdf()` call — notes gdalcubes' + "could not be added to output" merge warning, aborts on it AFTER the write + returns (round 2: aborting inside the `Rcpp::warning` handler skips C++ + cleanup), then `cube_check_chunks()` +- [x] Call it in `build_stack()` and `fetch_extent_to()` +- [x] Offset split: build both sides before `terra::cover()` (S4 dispatch was + re-raising the abort without its class — found by the new test) +- [x] Integration tests at `parallel = 4`, written before the wiring and red + against it: `dft_stac_composite()` and `dft_stac_fetch()` untiled and tiled + abort and cache nothing; clean fixture still cached; a two-year composite + aborts rather than skipping the holed year; offset split with the broken + read on the post side +- [x] Un-wire (wrapper reduced to a bare `write_ncdf()`) → every wiring test red +- [x] Tiled fetch registers tile cleanup before the reads +- [x] `GDAL_HTTP_MAX_RETRY`/`RETRY_DELAY` in the cube session and (every path) in + `dft_stac_fetch()`, restored on exit +- [x] Cache gate: an untiled fetch `.nc` whose `chunk_status` records failures is a + miss and re-fetches (caches from before #87) +- [x] Existing cache-key frozen tests pass unchanged (key not affected) ## Phase 3: Live check, docs, notes -- [ ] Live probe (opt-in, `DRIFT_TEST_NETWORK=true`): packaged AOI, corrupted `sig` - on every asset, re-signing stubbed out, default `parallel` → aborts, nothing - cached; same call with valid tokens succeeds -- [ ] Short-run timing per CLAUDE.md (`/usr/bin/time -l`) on a clean packaged-AOI - read before/after: the check reads one int vector, so expect no change; record - numbers for the PR body -- [ ] Update the `stac_features_resign()` roxygen (it says chunk failures cannot be - reliably captured) and `inst/notes/gdalcubes-pc-gotchas.md` with the - `chunk_status` finding and the probe table -- [ ] Edit the #87 issue body: the fourth option and why options 1–3 were not taken -- [ ] `devtools::document()`, `devtools::test()`, `lintr::lint_package()` +- [x] Live probe `data-raw/probe_chunk_status_live.R` (not a test: run by hand): + bad tokens on every asset via a spoiling `sign_fn` → composite untiled + + tiled, cube, fetch untiled + tiled all abort with 0 cache files; good-token + controls (cube months 6:9 at parallel 4, tiled composite, fetch) return and + cache. 8 of 8, `data-raw/logs/probe_chunk_status_live/20261002T140832Z.txt` +- [x] Cost instead of a BULK RSS run: `cube_check_chunks()` reads one int per + chunk, no pixels — 2.3 ms on a 2000 x 2000 cube of 7,936 chunks (one BULK + tile at `tile_size = 20000`) +- [x] `stac_features_resign()` roxygen; `inst/notes/gdalcubes-pc-gotchas.md` + "Detecting failed chunk reads (#87)" with the probe table and what is NOT + recorded +- [x] File drift#99: read-after-open, mask-open, unreadable worker chunk file and + worker-crash failures stay silent; upstream gdalcubes draft (not posted) +- [x] Edit the #87 issue body: what was found, what is covered, what moved to #99 +- [x] `devtools::document()`, `devtools::test()` (1548 pass), lint ## Not in scope (say so in the PR) - Retrying a failed extent (re-sign + one retry) — would rescue a long tiled run instead of discarding it, but is new behaviour; file as a follow-up if wanted. - Re-signing per tile in `dft_stac_fetch()` (it signs once, like #79's cube path did) — detection now catches it; the fix is a separate change. +- Failures `chunk_status` cannot see — drift#99. - soul `code-check-spatial.md` says "gdalcubes reports failed chunk reads only on stderr" — now wrong; flag in the report (soul edits go through an issue). ## Validation -- [ ] Tests pass -- [ ] `/code-check` clean on each commit -- [ ] PWF checkboxes match landed work +- [x] Tests pass +- [x] `/code-check`: three rounds, ended by enumeration (findings.md) +- [x] PWF checkboxes match landed work - [ ] `/planning-archive` on completion diff --git a/tests/testthat/helper-gdalcubes.R b/tests/testthat/helper-gdalcubes.R new file mode 100644 index 0000000..6ea5977 --- /dev/null +++ b/tests/testthat/helper-gdalcubes.R @@ -0,0 +1,67 @@ +# A local, dated gdalcubes collection for the #87 chunk-status tests: one GeoTIFF +# per band per item, in EPSG:32609, over `ext` (xmin, xmax, ymin, ymax) at `res`. +# B04 is a constant reflectance, SCL is 4 (vegetation, never masked). `dates` are +# ISO dates, one item each. +# +# `break_dates` names items whose files are DELETED after the collection is +# built, so gdalcubes knows the image but cannot open it: the same chunk-read +# failure as an expired signed URL or a refused request, without a network. +# +# Separate files per band: two-band files with one_band_per_file = FALSE +# segfaulted a gdalcubes 0.7.5 worker (#92). +chunk_fixture <- function(dates, ext = c(0, 400, 0, 400), res = 10, + break_dates = character(0), + envir = parent.frame()) { + d <- withr::local_tempdir(.local_envir = envir) + r <- terra::rast(xmin = ext[1], xmax = ext[2], ymin = ext[3], ymax = ext[4], + resolution = res, crs = "EPSG:32609") + paths <- character(0) + for (dt in dates) { + stem <- file.path(d, paste0(format(as.Date(dt), "%Y%m%d"), "_a")) + b <- terra::init(r, 500) + s <- terra::init(r, 4) + terra::writeRaster(b, paste0(stem, "_B04.tif"), datatype = "INT2U") + terra::writeRaster(s, paste0(stem, "_SCL.tif"), datatype = "INT1U") + paths <- c(paths, paste0(stem, c("_B04.tif", "_SCL.tif"))) + } + fmt_file <- file.path(d, "format.json") + writeLines(c( + '{"description": "drift #87 fixture", "tags": ["test"],', + ' "pattern": ".*\\\\.tif",', + ' "images": {"pattern": ".*/([0-9]{8}_[a-z]+)_.*"},', + ' "datetime": {"pattern": ".*/([0-9]{8})_.*", "format": "%Y%m%d"},', + ' "bands": {"B04": {"pattern": ".*_B04\\\\.tif", "nodata": 0},', + ' "SCL": {"pattern": ".*_SCL\\\\.tif"}}}' + ), fmt_file) + col <- gdalcubes::create_image_collection( + paths, format = fmt_file, out_file = file.path(d, "col.db") + ) + for (dt in break_dates) { + unlink(file.path(d, paste0(format(as.Date(dt), "%Y%m%d"), "_a_B04.tif"))) + } + col +} + +# Write a cube over a chunk_fixture() collection with gdalcubes itself, at a given +# worker count, and return the NetCDF path. `chunking` small enough that a +# fixture spans several chunks. +chunk_fixture_write <- function(col, ext = c(0, 400, 0, 400), res = 10, + t0 = "2021-07-01", t1 = "2021-07-31", + dt = "P1D", aggregation = "first", + parallel = 1, chunking = c(1, 16, 16), + envir = parent.frame()) { + old <- gdalcubes::gdalcubes_options()$parallel + gdalcubes::gdalcubes_options(parallel = parallel) + on.exit(gdalcubes::gdalcubes_options(parallel = old), add = TRUE) + v <- gdalcubes::cube_view( + srs = "EPSG:32609", + extent = list(left = ext[1], right = ext[2], bottom = ext[3], top = ext[4], + t0 = t0, t1 = t1), + dx = res, dy = res, dt = dt, aggregation = aggregation, resampling = "near" + ) + out <- withr::local_tempfile(fileext = ".nc", .local_envir = envir) + # A broken fixture prints gdalcubes' "[WARNING] n out of m chunks" line from + # C++ stdio, which no R handler or capture.output() can silence (#87). + gdalcubes::write_ncdf(gdalcubes::raster_cube(col, v, chunking = chunking), out) + out +} diff --git a/tests/testthat/test-dft_stac_composite.R b/tests/testthat/test-dft_stac_composite.R index cd1b5fd..25995cc 100644 --- a/tests/testthat/test-dft_stac_composite.R +++ b/tests/testthat/test-dft_stac_composite.R @@ -663,3 +663,96 @@ test_that("a count is matched without case and keys as 'count' (#92)", { expect_length(files, 1L) expect_match(files, "^count_") }) + + +# --- #87: a failed chunk read aborts and caches nothing ---------------------- +# +# The real gdalcubes writer over a local collection (chunk_fixture(), in +# helper-gdalcubes.R) whose 2021-07-13 image is deleted after the collection is +# built: the read fails the way an expired signed URL does. Only the STAC query +# and the collection constructor are stubbed, so stac_cube_assemble(), the +# write, the guard and the cache publish all run as in production. At +# parallel = 4, because the default resolves to 1 on a two-core runner, and the +# fill value an unvisited chunk keeps (which the guard must read as OK) is the +# worker path's. + +# The fixture's extent: the packaged AOI's bbox in its UTM zone, widened to whole +# cells and a margin so every cube_view drift builds over it lies inside. +aoi_fixture_ext <- function(aoi) { + bb <- sf::st_bbox(sf::st_transform(aoi, 32609)) + c(floor(bb[["xmin"]] / 10) * 10 - 20, ceiling(bb[["xmax"]] / 10) * 10 + 20, + floor(bb[["ymin"]] / 10) * 10 - 20, ceiling(bb[["ymax"]] / 10) * 10 + 20) +} + +# `break_dates` holds one entry per year: the dates to break in that year's +# collection. Years are 2021, 2022, ...; each has scenes on 07-03 and 07-13. +composite_on_fixture <- function(break_dates, tile_size = NULL, cache, + env = parent.frame()) { + aoi <- aoi_pkg() + years <- 2020 + seq_along(break_dates) + cols <- lapply(seq_along(years), function(i) { + chunk_fixture(paste0(years[i], c("-07-03", "-07-13")), + ext = aoi_fixture_ext(aoi), break_dates = break_dates[[i]], + envir = env) + }) + year_now <- 0L + testthat::local_mocked_bindings( + stac_cube_items = function(...) { + year_now <<- year_now + 1L + list(features = list(list(id = "a"), list(id = "b")), + is_pre = rep(years[year_now] < 2022, 2)) + }, + .env = env + ) + testthat::local_mocked_bindings( + stac_image_collection = function(...) cols[[year_now]], + .package = "gdalcubes", .env = env + ) + suppressMessages(dft_stac_composite(aoi, years = years, months = 7, + bands = "red", tile_size = tile_size, + parallel = 4, cache_dir = cache)) +} + +test_that("a composite whose chunk reads failed aborts and caches nothing (#87)", { + skip_if_not_installed("gdalcubes") + cache <- withr::local_tempdir() + expect_error(composite_on_fixture(list("2021-07-13"), cache = cache), + class = "drift_incomplete_cube") + expect_length(list.files(cache, recursive = TRUE, all.files = TRUE), 0L) +}) + +test_that("a tiled composite whose chunk reads failed aborts and caches nothing (#87)", { + skip_if_not_installed("gdalcubes") + cache <- withr::local_tempdir() + expect_error(composite_on_fixture(list("2021-07-13"), tile_size = 1000, + cache = cache), + class = "drift_incomplete_cube") + expect_length(list.files(cache, recursive = TRUE, all.files = TRUE), 0L) +}) + +test_that("a composite over a readable collection is built and cached as before (#87)", { + # False-refusal control: the guard must not fire on a clean read, tiled or not. + skip_if_not_installed("gdalcubes") + for (ts in list(NULL, 1000)) { + cache <- withr::local_tempdir() + out <- composite_on_fixture(list(character(0)), tile_size = ts, + cache = cache) + expect_s4_class(out[[1]], "SpatRaster") + expect_gt(sum(terra::global(out[[1]], "notNA")$notNA), 0) + expect_length(list.files(cache, pattern = "\\.tif$", recursive = TRUE), 1L) + } +}) + +test_that("a failed year is an abort, not a skipped year (#87)", { + # The year loop turns drift_no_items and drift_empty_cube into a warning and a + # dropped year. A holed read must not take that exit: it would return the + # other years as though the window simply had no scenes. + skip_if_not_installed("gdalcubes") + cache <- withr::local_tempdir() + expect_error( + composite_on_fixture(list(character(0), "2022-07-13"), cache = cache), + class = "drift_incomplete_cube" + ) + # year 1 was built before year 2 failed, and stays cached; year 2 does not + expect_length(list.files(cache, pattern = "\\.tif$", recursive = TRUE), 1L) +}) diff --git a/tests/testthat/test-dft_stac_cube.R b/tests/testthat/test-dft_stac_cube.R index 5921b7d..dfb5d1c 100644 --- a/tests/testthat/test-dft_stac_cube.R +++ b/tests/testthat/test-dft_stac_cube.R @@ -967,3 +967,153 @@ test_that("fetch, cube and composite hash the caller's aggregation as given (#92 expect_identical(hashed, list(fetch = "Median", cube = "Median", composite = "Median")) }) + + +# --- #87: failed chunk reads ------------------------------------------------ +# +# gdalcubes prints "n out of m chunks have repoprted errors" and writes the +# failed chunks as NA, raising nothing in R; with worker processes the line never +# reaches R at all. What it does write, at every worker count, is a per-chunk +# `chunk_status` variable in the output NetCDF. These tests delete an image after +# the collection is built, which fails the read the way an expired signed URL +# does, and drive the real gdalcubes writer. + +test_that("a clean gdalcubes write passes the chunk check at 1 and 4 workers (#87)", { + skip_if_not_installed("gdalcubes") + col <- chunk_fixture(c("2021-07-03", "2021-07-13")) + for (p in c(1, 4)) { + nc <- chunk_fixture_write(col, parallel = p) + expect_silent(drift:::cube_check_chunks(nc)) + } +}) + +test_that("a failed image read aborts the chunk check at 1 and 4 workers (#87)", { + skip_if_not_installed("gdalcubes") + col <- chunk_fixture(c("2021-07-03", "2021-07-13"), break_dates = "2021-07-13") + for (p in c(1, 4)) { + nc <- chunk_fixture_write(col, parallel = p) + # PREMISE: the fixture really holes the cube, so a pass here would be the + # guard failing and not the fixture being clean + expect_lt(sum(terra::global(terra::rast(nc), "notNA")$notNA), + terra::ncell(terra::rast(nc)) * terra::nlyr(terra::rast(nc))) + expect_error(drift:::cube_check_chunks(nc), class = "drift_incomplete_cube") + } +}) + +test_that("a failed read the pixels cannot show still aborts (#87)", { + # A monthly median over two scenes where one failed fills every cell from the + # survivor: no NA anywhere, so no check on the pixels can see it. This is the + # case that makes chunk_status the only discriminating evidence. + skip_if_not_installed("gdalcubes") + col <- chunk_fixture(c("2021-07-03", "2021-07-13"), break_dates = "2021-07-13") + nc <- chunk_fixture_write(col, dt = "P1M", aggregation = "median", parallel = 4) + r <- terra::rast(nc) + expect_equal(sum(terra::global(r, "notNA")$notNA), + terra::ncell(r) * terra::nlyr(r)) + expect_error(drift:::cube_check_chunks(nc), class = "drift_incomplete_cube") +}) + +test_that("the chunk-check abort says how many chunks failed and that nothing was cached (#87)", { + skip_if_not_installed("gdalcubes") + col <- chunk_fixture(c("2021-07-03", "2021-07-13"), break_dates = "2021-07-13") + nc <- chunk_fixture_write(col, parallel = 1) + e <- expect_error(drift:::cube_check_chunks(nc), class = "drift_incomplete_cube") + msg <- conditionMessage(e) + expect_match(msg, "9 of 279", fixed = TRUE) + expect_match(msg, "Nothing was cached", fixed = TRUE) +}) + +test_that("a NetCDF with no chunk_status aborts rather than passing (#87)", { + # A guard that cannot find its evidence must not report the read clean. + skip_if_not_installed("gdalcubes") + r <- terra::rast(nrows = 4, ncols = 4, xmin = 0, xmax = 40, ymin = 0, + ymax = 40, crs = "EPSG:32609", vals = 1) + nc <- withr::local_tempfile(fileext = ".nc") + terra::writeCDF(r, nc, varname = "B04") + expect_error(drift:::cube_check_chunks(nc), class = "drift_incomplete_cube") +}) + +test_that("a chunk gdalcubes could not merge aborts the write (#87)", { + # A chunk whose worker output could not be merged keeps the fill value, which + # cube_check_chunks() must read as OK because a skipped empty chunk keeps it + # too. gdalcubes' only signal is an R warning, so the wrapper turns that into + # an abort. Simulated: the write lands a clean file and then warns as + # multiprocess.cpp does. + skip_if_not_installed("gdalcubes") + col <- chunk_fixture(c("2021-07-03", "2021-07-13")) + clean <- chunk_fixture_write(col, parallel = 4) + out <- withr::local_tempfile(fileext = ".nc") + testthat::local_mocked_bindings( + # warn FIRST, then land the file: an abort raised inside the handler + # unwinds before the copy, so `out` is missing exactly when the abort did + # not wait for the write (the order is what makes the last assertion bite) + write_ncdf = function(x, fname, ...) { + warning("Chunk 3 could not be added to output") + file.copy(clean, fname, overwrite = TRUE) + invisible(fname) + }, + .package = "gdalcubes" + ) + # PREMISE: the file it lands passes the status check on its own + expect_silent(drift:::cube_check_chunks(clean)) + expect_error(drift:::cube_write_ncdf(NULL, out), class = "drift_incomplete_cube") + # the abort waited for the write to return rather than unwinding through it: + # gdalcubes' C++ frames run their cleanup only if the write completes + expect_true(file.exists(out) && file.size(out) > 0) +}) + +test_that("an unrelated gdalcubes warning passes through the write (#87)", { + skip_if_not_installed("gdalcubes") + col <- chunk_fixture(c("2021-07-03", "2021-07-13")) + clean <- chunk_fixture_write(col, parallel = 4) + out <- withr::local_tempfile(fileext = ".nc") + testthat::local_mocked_bindings( + write_ncdf = function(x, fname, ...) { + file.copy(clean, fname, overwrite = TRUE) + warning("something else gdalcubes says") + invisible(fname) + }, + .package = "gdalcubes" + ) + expect_warning(drift:::cube_write_ncdf(NULL, out), "something else") +}) + +test_that("a failed read on the post-boundary side of an offset split aborts (#87)", { + # stac_cube_assemble() builds two cubes over one view when the items straddle + # the offset boundary and coalesces them with terra::cover(). Each write is + # checked: a holed post side must not be hidden by a complete pre side. + skip_if_not_installed("gdalcubes") + aoi <- sf::st_read(system.file("extdata", "example_aoi.gpkg", package = "drift"), + quiet = TRUE) + aoi_t <- sf::st_transform(aoi, 32609) + bb <- sf::st_bbox(aoi_t) + ext <- c(floor(bb[["xmin"]] / 10) * 10 - 20, ceiling(bb[["xmax"]] / 10) * 10 + 20, + floor(bb[["ymin"]] / 10) * 10 - 20, ceiling(bb[["ymax"]] / 10) * 10 + 20) + pre <- chunk_fixture(c("2021-07-03", "2021-07-13"), ext = ext) + post <- chunk_fixture(c("2022-07-03", "2022-07-13"), ext = ext, + break_dates = "2022-07-13") + calls <- 0L + testthat::local_mocked_bindings( + stac_image_collection = function(...) { + calls <<- calls + 1L + if (calls == 1L) pre else post + }, + .package = "gdalcubes" + ) + restore <- drift:::stac_cube_session(4) + withr::defer(restore()) + run <- function() { + drift:::stac_cube_assemble( + list(features = list(list(id = "a"), list(id = "b")), + is_pre = c(TRUE, FALSE)), + dft_stac_config("sentinel-2-l2a"), aoi_t, "EPSG:32609", + t0 = "2021-07-01", t1 = "2022-07-31", res = 10, dt = "P1Y", + aggregation = "median", resampling = "near", band_assets = "B04", + mask_values = c(8, 9), offset = 0, offset_before = 0, + pixel_fn = function(cube, offset_use) gdalcubes::select_bands(cube, "B04") + ) + } + expect_error(run(), class = "drift_incomplete_cube") + # both sides were built: the abort is the post side's, not a short-circuit + expect_equal(calls, 2L) +}) diff --git a/tests/testthat/test-dft_stac_fetch.R b/tests/testthat/test-dft_stac_fetch.R index 0454a6f..779f788 100644 --- a/tests/testthat/test-dft_stac_fetch.R +++ b/tests/testthat/test-dft_stac_fetch.R @@ -1243,3 +1243,86 @@ test_that("the key does not move when rlang's hash does", { expect_identical(cache_key(), before) expect_identical(cache_key(), "8b02f87e393e7f9a") }) + + +# --------------------------------------------------------------------------- +# #87 — a failed chunk read aborts and caches nothing +# --------------------------------------------------------------------------- +# +# The real gdalcubes writer over a local collection (chunk_fixture(), in +# helper-gdalcubes.R) whose 2020-07-13 image is deleted after the collection is +# built, so the read fails the way an expired signed URL does. Only the STAC +# query and the collection constructor are stubbed. + +fetch_on_fixture <- function(break_dates, tile_size = NULL, cache, + env = parent.frame()) { + aoi <- read_aoi() + bb <- sf::st_bbox(sf::st_transform(aoi, 32609)) + ext <- c(floor(bb[["xmin"]] / 10) * 10 - 20, ceiling(bb[["xmax"]] / 10) * 10 + 20, + floor(bb[["ymin"]] / 10) * 10 - 20, ceiling(bb[["ymax"]] / 10) * 10 + 20) + col <- chunk_fixture(c("2020-07-03", "2020-07-13"), ext = ext, + break_dates = break_dates, envir = env) + testthat::local_mocked_bindings( + stac_items_paged = function(...) fake_items("a", next_link = FALSE), + .env = env + ) + testthat::local_mocked_bindings( + stac_image_collection = function(...) col, .package = "gdalcubes", .env = env + ) + # dft_stac_fetch() reads at the session's gdalcubes worker count, which ships + # as 1; run the worker path, where an unvisited chunk keeps the fill value + old <- gdalcubes::gdalcubes_options()$parallel + gdalcubes::gdalcubes_options(parallel = 4) + withr::defer(gdalcubes::gdalcubes_options(parallel = old)) + suppressMessages(dft_stac_fetch(aoi, source = "io-lulc", years = 2020, + tile_size = tile_size, cache_dir = cache)) +} + +test_that("a fetch whose chunk reads failed aborts and caches nothing (#87)", { + skip_if_not_installed("gdalcubes") + cache <- withr::local_tempdir() + expect_error(fetch_on_fixture("2020-07-13", cache = cache), + class = "drift_incomplete_cube") + expect_length(list.files(cache, recursive = TRUE, all.files = TRUE), 0L) +}) + +test_that("a tiled fetch whose chunk reads failed aborts and caches nothing (#87)", { + # Its own test: the untiled case also trips the cache gate's chunk_status arm + # at publish, so a shared loop would stop there and never reach this path. + skip_if_not_installed("gdalcubes") + cache <- withr::local_tempdir() + expect_error(fetch_on_fixture("2020-07-13", tile_size = 1000, cache = cache), + class = "drift_incomplete_cube") + expect_length(list.files(cache, recursive = TRUE, all.files = TRUE), 0L) +}) + +test_that("a fetch over a readable collection is fetched and cached as before (#87)", { + skip_if_not_installed("gdalcubes") + for (ts in list(NULL, 1000)) { + cache <- withr::local_tempdir() + out <- fetch_on_fixture(character(0), tile_size = ts, cache = cache) + expect_gt(sum(terra::global(out[["2020"]], "notNA")$notNA), 0) + expect_length(list.files(cache, pattern = "^2020_", recursive = TRUE), 1L) + } +}) + +test_that("an untiled fetch cache that records failed chunks is re-fetched (#87)", { + # Caches written before #87 could hold a failed read, and the key did not + # change, so the gate has to look. The untiled cache is the gdalcubes NetCDF + # itself, which keeps its chunk_status. + skip_if_not_installed("gdalcubes") + holed <- chunk_fixture_write( + chunk_fixture(c("2021-07-03", "2021-07-13"), break_dates = "2021-07-13"), + parallel = 4 + ) + clean <- chunk_fixture_write(chunk_fixture(c("2021-07-03", "2021-07-13")), + parallel = 4) + expect_match(drift:::cache_invalid_reason(holed), "failed when it was fetched") + expect_true(is.na(drift:::cache_invalid_reason(clean))) + # a .nc that is not a gdalcubes output has no chunk_status and is not refused + r <- terra::rast(nrows = 4, ncols = 4, xmin = 0, xmax = 40, ymin = 0, + ymax = 40, crs = "EPSG:32609", vals = 1) + other <- withr::local_tempfile(fileext = ".nc") + suppressWarnings(terra::writeCDF(r, other, varname = "B04")) + expect_true(is.na(drift:::cache_invalid_reason(other))) +}) From 473d7e53f63052658bb8d1e8f779c339602be685 Mon Sep 17 00:00:00 2001 From: almac2022 Date: Fri, 2 Oct 2026 07:32:47 -0700 Subject: [PATCH 3/4] Archive planning files for issue #87 Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01PRhUJsuKABLfpBGktPoiBN --- .../README.md | 30 +++++++++++++++++++ .../findings.md | 0 .../progress.md | 0 .../review-plan.md | 0 .../review-round1.md | 0 .../review-round2.md | 0 .../review-round3.md | 0 .../task_plan.md | 0 8 files changed, 30 insertions(+) create mode 100644 planning/archive/2026-10-issue-87-silent-chunk-read-failures/README.md rename planning/{active => archive/2026-10-issue-87-silent-chunk-read-failures}/findings.md (100%) rename planning/{active => archive/2026-10-issue-87-silent-chunk-read-failures}/progress.md (100%) rename planning/{active => archive/2026-10-issue-87-silent-chunk-read-failures}/review-plan.md (100%) rename planning/{active => archive/2026-10-issue-87-silent-chunk-read-failures}/review-round1.md (100%) rename planning/{active => archive/2026-10-issue-87-silent-chunk-read-failures}/review-round2.md (100%) rename planning/{active => archive/2026-10-issue-87-silent-chunk-read-failures}/review-round3.md (100%) rename planning/{active => archive/2026-10-issue-87-silent-chunk-read-failures}/task_plan.md (100%) diff --git a/planning/archive/2026-10-issue-87-silent-chunk-read-failures/README.md b/planning/archive/2026-10-issue-87-silent-chunk-read-failures/README.md new file mode 100644 index 0000000..c802f6a --- /dev/null +++ b/planning/archive/2026-10-issue-87-silent-chunk-read-failures/README.md @@ -0,0 +1,30 @@ +## Outcome + +drift now aborts (`drift_incomplete_cube`) with nothing cached when gdalcubes fails to open a band image. That is the expired or refused signed URL that holed 15 of 30 tiles in #79. `cube_write_ncdf()` is drift's single `write_ncdf()` call, used by the cube, composite and fetch paths. It reads the per-chunk `chunk_status` gdalcubes writes into every output and aborts on gdalcubes' merge-failure warning after the write returns. None of the issue's three options was needed. The record already existed in the file, and a pixel post-check could never have seen a median filled from the surviving scene. + +The work then found that this is the *only* failure gdalcubes records. Every other I/O step drops its return code. A band or mask image that opens and then fails mid-read leaves status OK, and a failed mask read leaves the scene unmasked. Those moved to #99, with an upstream draft (not posted); GDAL HTTP retries were added as mitigation. + +Along the way the new tests found two defects: +- `terra::cover()`'s S4 dispatch stripped the abort class on the offset-split path; +- aborting inside an `Rcpp::warning` handler skips C++ cleanup (code-check round 2). + +## Measurement + +- **Offline fixture (local GeoTIFFs, one image deleted after the collection is built).** `chunk_status` held 9 × `2` (INCOMPLETE) of 279 chunks at `parallel` 1 **and** 4. The stderr `[WARNING]` line appeared only at 1. A monthly median with one of two scenes failed still had 1600 of 1600 cells set. +- **What is not recorded.** A band file with corrupted tiles but an intact IFD (it opens, then the read fails) gave status 0 × 9, all cells set. A deleted SCL gave 0 × 9. `gdalcubes_options(log_file =, debug = TRUE)` wrote 11 identical lines in clean and failing runs alike. This retracted the plan's claim that the guard covers throttling. +- **Before the fix,** the offline integration tests showed `dft_stac_composite()` and `dft_stac_fetch()` caching the holed result, tiled and untiled. +- **Live acceptance, 8 of 8.** + - Bad tokens on every asset: composite untiled and tiled, cube, and fetch untiled and tiled all aborted with 0 cache files in 2–10 s. + - Good-token controls returned and cached: cube over months 6:9 at parallel 4 (266 s), tiled composite (142 s), untiled fetch (8 s). +- **Cost of the check.** 2.3 ms on a 2000 × 2000 cube of 7,936 chunks, the size of one BULK tile at `tile_size = 20000`. It reads one integer per chunk and no pixels, which stood in for a BULK RSS run. +- **Code-check.** Three rounds, ended by enumeration. Round 3 counted 38 failure paths in gdalcubes' write pipeline: 25 detected by drift, 13 not (#99). Rounds 2 and 3 each found a defect inside the previous round's fix: aborting inside the warning handler, then a merge test whose mutant stayed green. + +## Evidence + +- `data-raw/logs/probe_chunk_status_live/20261002T14*`, made by `data-raw/probe_chunk_status_live.R`. +- The offline fixture is `chunk_fixture()` in `tests/testthat/helper-gdalcubes.R`. +- Review rounds: `review-plan.md`, `review-round[123].md` in this directory. +- Durable notes: `inst/notes/gdalcubes-pc-gotchas.md`, "Detecting failed chunk reads (#87)". +- Follow-ups: drift#99, soul#316. + +Closed by: commit 36f2a6f / PR (see `gh pr list --search 87`) diff --git a/planning/active/findings.md b/planning/archive/2026-10-issue-87-silent-chunk-read-failures/findings.md similarity index 100% rename from planning/active/findings.md rename to planning/archive/2026-10-issue-87-silent-chunk-read-failures/findings.md diff --git a/planning/active/progress.md b/planning/archive/2026-10-issue-87-silent-chunk-read-failures/progress.md similarity index 100% rename from planning/active/progress.md rename to planning/archive/2026-10-issue-87-silent-chunk-read-failures/progress.md diff --git a/planning/active/review-plan.md b/planning/archive/2026-10-issue-87-silent-chunk-read-failures/review-plan.md similarity index 100% rename from planning/active/review-plan.md rename to planning/archive/2026-10-issue-87-silent-chunk-read-failures/review-plan.md diff --git a/planning/active/review-round1.md b/planning/archive/2026-10-issue-87-silent-chunk-read-failures/review-round1.md similarity index 100% rename from planning/active/review-round1.md rename to planning/archive/2026-10-issue-87-silent-chunk-read-failures/review-round1.md diff --git a/planning/active/review-round2.md b/planning/archive/2026-10-issue-87-silent-chunk-read-failures/review-round2.md similarity index 100% rename from planning/active/review-round2.md rename to planning/archive/2026-10-issue-87-silent-chunk-read-failures/review-round2.md diff --git a/planning/active/review-round3.md b/planning/archive/2026-10-issue-87-silent-chunk-read-failures/review-round3.md similarity index 100% rename from planning/active/review-round3.md rename to planning/archive/2026-10-issue-87-silent-chunk-read-failures/review-round3.md diff --git a/planning/active/task_plan.md b/planning/archive/2026-10-issue-87-silent-chunk-read-failures/task_plan.md similarity index 100% rename from planning/active/task_plan.md rename to planning/archive/2026-10-issue-87-silent-chunk-read-failures/task_plan.md From caa5624312c25165dcd702dc00f465c51089a0a2 Mon Sep 17 00:00:00 2001 From: almac2022 Date: Fri, 2 Oct 2026 07:32:47 -0700 Subject: [PATCH 4/4] CLAUDE.md: point the gdalcubes notes at chunk_status (#87) Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01PRhUJsuKABLfpBGktPoiBN --- CLAUDE.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/CLAUDE.md b/CLAUDE.md index 2613b15..ad403f5 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -167,7 +167,7 @@ Tag PR bodies with `Relates to NewGraphEnvironment/sred-2025-2026#16` (the issue sliver-settles-less result in 6 of 8 bands. Neither geometric leg generalises. - [`inst/notes/temporal-qa-groups.md`](inst/notes/temporal-qa-groups.md) — `dft_rast_break_class()` across the four published seven-year groups (#62): sustained-break share 20-31% of 2017-2023 change, flicker 40-49%, 2017 the odd endpoint everywhere; the shape proxies and why the per-stream segment layer was rejected. Q6 (#73) adds distance from permanent water: the gradient is real, the null does not separate it from any other class boundary, the near-band `stable` share is biased down by construction because the reference excises the permanent-water pixels, and `break_year` runs the opposite way to a migrating bank. Read before quoting a `transition_2017_2023` hectare as change. - [`inst/notes/temporal-qa-disturbance.md`](inst/notes/temporal-qa-disturbance.md) — does dated fire/harvest corroborate the temporal QA (#67): the published `transition_vector.gpkg` is drift's own change layer after a 1 ha class-agnostic sieve and a sub-basin clip, reproduced exactly in all four groups (0 of 53/44/41/46 classes differ), which closes the two-totals problem; `break_year` lands at lag 0 or +1 for 86% of discriminating fire patches that broke and 72% of harvest (70.7% / 58.4% of all tagged), mode +1; flicker is LOWER in disturbed patches, so it does not read as succession. Read before treating drift's patch count and the published one as the same population. -- [`inst/notes/gdalcubes-pc-gotchas.md`](inst/notes/gdalcubes-pc-gotchas.md) — non-obvious gdalcubes 0.7.3 + Planetary Computer Sentinel-2 gotchas (filter_geom segfault, reduce_time worker closures, terra↔gdalcubes NetCDF round-trip, the S2 +1000 DN offset boundary at 2022-01-25, PC pagination). Read before touching the continuous pipeline. +- [`inst/notes/gdalcubes-pc-gotchas.md`](inst/notes/gdalcubes-pc-gotchas.md) — non-obvious gdalcubes 0.7.3 + Planetary Computer Sentinel-2 gotchas (filter_geom segfault, reduce_time worker closures, terra↔gdalcubes NetCDF round-trip, the S2 +1000 DN offset boundary at 2022-01-25, PC pagination, and what `chunk_status` does and does not record about a failed read, #87/#99). Read before touching the continuous pipeline.