Tests: XFA calculation tests no longer fail when the machine is busy (#4535)

Five XFA tests failed at random on a busy machine. The scripts of an
opening or a change share a 3 s wall-clock budget (a click's share 5 s),
each script has 1 s or 3 s, and the engine has 10 s to start; under load
the tests went past one of them, and the scripts they check were skipped
or did not start.

Session::with_xfa_time_scale (and Automation::with_xfa_time_scale)
multiplies each of these limits for a test; the default stays 1. The
script session counts the engine threads it starts on the calling thread
(xfa_session::engines_started).

The hundreds-of-calculations tests run with the limits raised, and the
engine's test now checks that opening starts one engine and a change one
more. A new test sets the factor to 0 and checks that the budget skips
all 210 calculations and says so. Three more tests that failed the same
way under load run with the limits raised.
This commit is contained in:
.CooCoo authored and GitHub committed 2026-10-25 10:02:00 -04:00
1 parent f0eccde407
commit 0db7d57619
6 files changed
+133 -26

No files matched your search

+6
View File
@@ -174,6 +174,12 @@ impl Automation {
self
}
/// Multiply the time XFA form scripts may take (tests). See [`Session::with_xfa_time_scale`].
pub fn with_xfa_time_scale(mut self, factor: u32) -> Self {
self.session = std::mem::take(&mut self.session).with_xfa_time_scale(factor);
self
}
/// The clock and time zone of a host without its own. See [`Session::with_wall_clock`].
pub fn with_wall_clock(mut self, clock: fn() -> i64, utc_offset: fn() -> i64) -> Self {
self.session = std::mem::take(&mut self.session).with_wall_clock(clock, utc_offset);
+9 -4
View File
@@ -6876,12 +6876,15 @@ BT /F1 11 Tf 20 20 Td (Total due: 150.00) Tj ET";
assert!(rendered.iter().any(|c| matches!(c, Content::Png { .. })));
}
/// Hundreds of calculations run on opening and again after a change through the tools. The
/// time limits are raised so that a busy machine does not stop them (the engine's tests check
/// that the limits stop them).
#[test]
fn hundreds_of_xfa_calculations_open_and_recalculate_within_their_budgets() {
fn hundreds_of_xfa_calculations_open_and_recalculate_through_tools() {
let dir = workdir("xfa-many");
let (sections, rows) = (10, 20);
std::fs::write(dir.join("many.pdf"), pdfcraft_xfa::fixtures::shell(&pdfcraft_xfa::fixtures::many_calculations_template(sections, rows))).unwrap();
let mut a = auto(&dir);
let mut a = auto(&dir).with_xfa_time_scale(100);
let started = std::time::Instant::now();
let opened = ok(&mut a, "doc_open", json!({ "path": "many.pdf" }));
let open_took = started.elapsed();
@@ -7304,7 +7307,8 @@ fn repeated_xfa_print_buttons_work_through_tools_and_after_reopen() {
let dir = workdir("xfa-print-buttons");
let template = pdfcraft_xfa::fixtures::repeated_print_button_template();
std::fs::write(dir.join("print.pdf"), pdfcraft_xfa::fixtures::shell(&template)).unwrap();
let mut a = auto(&dir);
// Raised time limits: a busy machine does not stop the click scripts this checks.
let mut a = auto(&dir).with_xfa_time_scale(100);
let doc = ok(&mut a, "doc_open", json!({ "path": "print.pdf" }))["doc"].as_u64().unwrap();
let check = |a: &mut Automation, doc| {
let fields = ok(a, "form_fields", json!({ "doc": doc }));
@@ -7329,7 +7333,8 @@ fn repeated_xfa_print_buttons_work_through_tools_and_after_reopen() {
fn xfa_scripts_run_for_buttons_and_field_changes_through_tools() {
let dir = workdir("xfa-scripts");
std::fs::write(dir.join("scripted.pdf"), pdfcraft_xfa::fixtures::shell(&pdfcraft_xfa::fixtures::scripted_template())).unwrap();
let mut a = auto(&dir);
// Raised time limits: a busy machine does not stop the scripts this checks.
let mut a = auto(&dir).with_xfa_time_scale(100);
let doc = ok(&mut a, "doc_open", json!({ "path": "scripted.pdf" }))["doc"].as_u64().unwrap();
let field = |a: &mut Automation, n: &str| {
let f = ok(a, "form_fields", json!({ "doc": doc }));
+39 -5
View File
@@ -2461,6 +2461,8 @@ struct EditCtx {
xfa_datasets: Option<pdfcraft_cos::ObjRef>,
/// A form script ran too long and was abandoned: the document's scripts go off.
xfa_ran_away: bool,
/// What the XFA scripts' time limits are multiplied by ([`Session::with_xfa_time_scale`]).
xfa_time_scale: u32,
/// The edit took the XFA out of the form: what went with it, for the document's warnings.
xfa_removed: Vec<String>,
/// Pages in the document, for `xfa.layout.pageCount()`.
@@ -2495,6 +2497,7 @@ impl EditCtx {
xfa_out: Default::default(),
xfa_datasets: None,
xfa_ran_away: false,
xfa_time_scale: 1,
xfa_removed: Vec::new(),
pages: 0,
date: now.map(pdfcraft_cos::pdf_date),
@@ -2677,7 +2680,8 @@ fn run_edit(doc: &mut pdfcraft_cos::Document, edit: &Edit, cx: &mut EditCtx) ->
},
Edit::XfaEvent { som, activity } => {
let tpl = cx.xfa.clone().ok_or_else(|| EditError::Invalid("this is not a laid-out XFA form, or JavaScript is off".into()))?;
let mut run = xfa::XfaRun { page_count: cx.pages, out: &mut cx.xfa_out, datasets: cx.xfa_datasets, ran_away: false };
let mut run =
xfa::XfaRun { page_count: cx.pages, out: &mut cx.xfa_out, datasets: cx.xfa_datasets, ran_away: false, time_scale: cx.xfa_time_scale };
let ran = xfa::on_event(doc, &tpl, som, activity, &mut run);
cx.xfa_datasets = run.datasets;
cx.xfa_ran_away |= run.ran_away;
@@ -3237,6 +3241,9 @@ pub struct Session {
date_format: Option<String>,
/// Preferences ▸ Date format ▸ Language, when not following the interface language.
date_language: Option<String>,
/// What the XFA scripts' time limits are multiplied by (`None`: 1); see
/// [`Session::with_xfa_time_scale`].
xfa_time_scale: Option<u32>,
}
/// Immutable session state needed while a document is prepared away from its owning thread.
@@ -3245,6 +3252,7 @@ pub struct OpenContext {
now: Option<i64>,
js_off: bool,
trust: Arc<TrustStore>,
xfa_time_scale: u32,
}
/// A fully prepared document that has not yet been registered in a session.
@@ -3481,7 +3489,8 @@ fn image_content_type(bytes: &[u8]) -> Option<&'static str> {
/// fields take the data's values.
fn xfa_after_data_change(doc: &mut pdfcraft_cos::Document, cx: &mut EditCtx, calculate: bool) -> Result<(), EditError> {
if let Some(tpl) = cx.xfa.clone() {
let mut run = xfa::XfaRun { page_count: cx.pages, out: &mut cx.xfa_out, datasets: cx.xfa_datasets, ran_away: false };
let mut run =
xfa::XfaRun { page_count: cx.pages, out: &mut cx.xfa_out, datasets: cx.xfa_datasets, ran_away: false, time_scale: cx.xfa_time_scale };
let r = guard(|| xfa::on_data_replaced(doc, &tpl, calculate, &mut run))
.unwrap_or_else(|m| Err(format!("laying the form out again failed unexpectedly ({m})")));
cx.xfa_datasets = run.datasets;
@@ -3569,6 +3578,17 @@ impl Session {
self
}
/// Multiply the time an XFA form's scripts may take by `factor` (tests): the 3 s the
/// scripts of an opening or a change share, the 5 s of a click's, the 10 s the script
/// engine has to start, and each script's own 1 s or 3 s. A test that checks what the
/// scripts do passes a large factor, so that a busy machine does not stop them. On native
/// builds, 0 stops every script before it starts; the wasm build has no wall clock, so
/// there the factor has no effect.
pub fn with_xfa_time_scale(mut self, factor: u32) -> Self {
self.xfa_time_scale = Some(factor);
self
}
/// A real clock for a host that has neither a clock nor a time zone of its own (a
/// `wasm32-unknown-unknown` build: `now()` would be empty and `local_utc_offset()` is 0, so
/// Fill & Sign stamps 1 Jan 1970 and `/ModDate` is never written). `clock` is the UTC time in
@@ -3641,7 +3661,7 @@ impl Session {
/// Snapshot the session state that affects open-time scripts, dates and signature trust.
pub fn open_context(&self) -> OpenContext {
OpenContext { now: self.now(), js_off: self.js_off, trust: self.trust.clone() }
OpenContext { now: self.now(), js_off: self.js_off, trust: self.trust.clone(), xfa_time_scale: self.xfa_time_scale.unwrap_or(1) }
}
/// Prepare a document without adding it to this session.
@@ -3770,7 +3790,13 @@ impl Session {
let mut work = cos.clone();
let pages = info.pages.len();
let ran = guard(|| {
let mut run = xfa::XfaRun { page_count: pages, out: &mut script_output, datasets: None, ran_away: false };
let mut run = xfa::XfaRun {
page_count: pages,
out: &mut script_output,
datasets: None,
ran_away: false,
time_scale: context.xfa_time_scale,
};
let changes = xfa::on_open(&mut work, &tpl, &mut run);
if run.ran_away {
ran_away = true;
@@ -3954,6 +3980,7 @@ impl Session {
let now = self.now();
let today = self.today();
let js_off = self.js_off;
let xfa_time_scale = self.xfa_time_scale.unwrap_or(1);
let doc = self.doc_mut(id)?;
doc.edit_notices.clear();
let name = doc.name.clone();
@@ -3963,6 +3990,7 @@ impl Session {
if !js_off {
cx.xfa = doc.xfa_template.clone();
}
cx.xfa_time_scale = xfa_time_scale;
cx.pages = doc.info.pages.len();
cx.today = today;
let reason = doc.read_only_reason.clone().unwrap_or_default();
@@ -4060,7 +4088,13 @@ impl Session {
let mut reset = false;
collect(&edit, &mut changed, &mut reset);
if !changed.is_empty() || reset {
let mut run = xfa::XfaRun { page_count: cx.pages, out: &mut cx.xfa_out, datasets: cx.xfa_datasets, ran_away: false };
let mut run = xfa::XfaRun {
page_count: cx.pages,
out: &mut cx.xfa_out,
datasets: cx.xfa_datasets,
ran_away: false,
time_scale: cx.xfa_time_scale,
};
// Every changed field's scripts, then the calculations once (after a reset,
// only those).
let ran = guard(|| xfa::on_changes(&mut next, &tpl, &changed, &mut run))
+33 -6
View File
@@ -5847,7 +5847,8 @@ fn xfa_data_import_on_a_static_form_replaces_every_value_and_pictures_reach_its_
#[test]
fn xfa_data_import_adds_and_removes_rows_of_a_dynamic_form() {
let bytes = Arc::new(pdfcraft_xfa::fixtures::shell(&pdfcraft_xfa::fixtures::scripted_template()));
let mut s = Session::new().with_clock(|| 1_700_000_000);
// Raised time limits: a busy machine does not stop the calculations this checks.
let mut s = Session::new().with_clock(|| 1_700_000_000).with_xfa_time_scale(100);
let id = s.open("rows.pdf", None, bytes, None).expect("opens");
let names = |s: &Session| s.get(id).unwrap().form.iter().map(|f| f.name.clone()).collect::<Vec<_>>();
let value = |s: &Session, n: &str| s.get(id).unwrap().form.iter().find(|f| f.name == n).map(|f| f.value.clone()).unwrap_or_default();
@@ -5876,16 +5877,19 @@ fn xfa_data_import_adds_and_removes_rows_of_a_dynamic_form() {
assert!(String::from_utf8_lossy(&out).contains("<item>only</item>"));
}
/// Hundreds of calculations, in JavaScript and FormCalc, run on opening in one engine within
/// the opening's budget, and a change recalculates them within the event's.
/// Hundreds of calculations, in JavaScript and FormCalc, run on opening in one engine, and a
/// change recalculates them in one more. The time limits are raised so that a busy machine
/// does not stop them; the next test checks that the limits stop them.
#[test]
fn hundreds_of_xfa_calculations_run_in_one_engine_within_the_open_budget() {
fn hundreds_of_xfa_calculations_run_in_one_engine() {
let (sections, rows) = (10, 20);
let bytes = Arc::new(pdfcraft_xfa::fixtures::shell(&pdfcraft_xfa::fixtures::many_calculations_template(sections, rows)));
let mut s = Session::new().with_clock(|| 1_700_000_000);
let mut s = Session::new().with_clock(|| 1_700_000_000).with_xfa_time_scale(100);
let engines = pdfcraft_js::xfa_session::engines_started();
let started = std::time::Instant::now();
let id = s.open("many.pdf", None, bytes, None).expect("opens");
let elapsed = started.elapsed();
assert_eq!(pdfcraft_js::xfa_session::engines_started() - engines, 1, "the scripts of the opening share one engine");
let out = s.take_js_output(id);
assert!(!out.errors.iter().any(|e| e.contains("were skipped") || e.contains("stopped")), "{:?}", out.errors);
let form = &s.get(id).unwrap().form;
@@ -5898,9 +5902,10 @@ fn hundreds_of_xfa_calculations_run_in_one_engine_within_the_open_budget() {
let expect = (rows * (rows + 1)).to_string();
assert!(sums.iter().all(|f| f.value == vec![expect.clone()]), "{:?}", sums.iter().map(|f| f.value.clone()).collect::<Vec<_>>());
eprintln!("{} calculate scripts on open in {elapsed:?}", sections * rows + sections);
// A change recalculates them all again, well within the event budget.
// A change recalculates them all again, in one more engine.
let started = std::time::Instant::now();
s.apply(id, Edit::SetFieldValue { name: "qty".into(), value: FieldValue::Text("100".into()) }).unwrap();
assert_eq!(pdfcraft_js::xfa_session::engines_started() - engines, 2, "the scripts of the change share one engine");
let out = s.take_js_output(id);
assert!(!out.errors.iter().any(|e| e.contains("were skipped")), "{:?}", out.errors);
assert_eq!(s.get(id).unwrap().form.iter().find(|f| f.name == "total").unwrap().value, vec!["200".to_string()]);
@@ -5908,6 +5913,28 @@ fn hundreds_of_xfa_calculations_run_in_one_engine_within_the_open_budget() {
eprintln!("recalculated after a change in {:?}", started.elapsed());
}
/// The time the scripts of an opening share stops the calculations it has no time for, and
/// says how many were skipped; a change's scripts are stopped the same way.
#[test]
fn the_xfa_open_budget_stops_the_calculations_it_has_no_time_for() {
let (sections, rows) = (10, 20);
let bytes = Arc::new(pdfcraft_xfa::fixtures::shell(&pdfcraft_xfa::fixtures::many_calculations_template(sections, rows)));
// A time scale of 0 leaves no time at all: every script is skipped before it starts.
let mut s = Session::new().with_clock(|| 1_700_000_000).with_xfa_time_scale(0);
let engines = pdfcraft_js::xfa_session::engines_started();
let id = s.open("many.pdf", None, bytes, None).expect("opens");
let skipped = sections * rows + sections;
let stopped = format!("The form's scripts were stopped: the scripts took more than 0 seconds; {skipped} more were skipped");
assert_eq!(s.take_js_output(id).errors, vec![stopped.clone()]);
let totals = |s: &Session| s.get(id).unwrap().form.iter().filter(|f| f.name.starts_with("total")).map(|f| f.value.clone()).collect::<Vec<_>>();
assert_eq!(totals(&s).len(), sections * rows);
assert!(totals(&s).iter().all(Vec::is_empty), "no total was calculated: {:?}", totals(&s));
s.apply(id, Edit::SetFieldValue { name: "qty".into(), value: FieldValue::Text("100".into()) }).unwrap();
assert!(s.take_js_output(id).errors.iter().any(|e| e.starts_with("The form's scripts were stopped: the scripts took more than 0 seconds")));
assert!(totals(&s).iter().all(Vec::is_empty), "no total was calculated: {:?}", totals(&s));
assert_eq!(pdfcraft_js::xfa_session::engines_started(), engines, "no script ran, so no engine started");
}
/// The scripts of one event share the form as the engine holds it: a failed script's
/// half-done writes reach nobody, and a script reads the saved value a choice list was given
/// by its shown text.
+9 -3
View File
@@ -128,6 +128,10 @@ pub(crate) struct XfaRun<'a> {
pub datasets: Option<pdfcraft_cos::ObjRef>,
/// A script ran past its time limit and was abandoned: the form's scripts should stay off.
pub ran_away: bool,
/// What every time limit of the scripts is multiplied by (the event's budget, the engine's
/// start and each script's own): 1, unless the session was given another
/// ([`crate::Session::with_xfa_time_scale`]).
pub time_scale: u32,
}
/// The live form node `n`, with its descendants, as the script engine's snapshot of it.
@@ -277,6 +281,7 @@ impl<'a, 'b> Runner<'a, 'b> {
fn new(doc: &'a mut pdfcraft_cos::Document, tpl: &'a Template, run: &'a mut XfaRun<'b>, budget_ms: u64) -> Self {
let data = pdfcraft_xfa::data_of(doc);
let ov = pdfcraft_xfa::overrides(doc);
let budget_ms = budget_ms.saturating_mul(u64::from(run.time_scale));
Runner {
doc,
tpl,
@@ -311,7 +316,8 @@ impl<'a, 'b> Runner<'a, 'b> {
/// The script engine for this event.
fn session(&mut self) -> &mut XfaSession {
let doc_info = XfaDoc { file_name: String::new(), page: 0, page_count: self.run.page_count };
self.session.get_or_insert_with(|| XfaSession::new(doc_info))
let scale = self.run.time_scale;
self.session.get_or_insert_with(|| XfaSession::new(doc_info).with_time_scale(scale))
}
/// Give the object at `som` the value `text` in the data and in the live form (refreshed
@@ -661,7 +667,7 @@ impl<'a, 'b> Runner<'a, 'b> {
event,
root,
limits: limits_for(&ev.activity),
timeout: timeout_for(&ev.activity),
timeout: timeout_for(&ev.activity).saturating_mul(self.run.time_scale),
};
let o = self.session().run(script);
if o.abandoned {
@@ -893,7 +899,7 @@ pub(crate) fn on_event(doc: &mut pdfcraft_cos::Document, tpl: &Template, som: &s
r.run(&ev, "")?;
}
// The calculations that follow get a budget of their own.
r.clock = Clock::start(OPEN_BUDGET_MS);
r.clock = Clock::start(OPEN_BUDGET_MS.saturating_mul(u64::from(r.run.time_scale)));
r.calculates()?;
r.finish().map(|_| ())
}
+37 -8
View File
@@ -18,6 +18,18 @@ use crate::xfa::{XfaDoc, XfaEvent, XfaNode, XfaOutcome};
#[cfg(test)]
pub(crate) static START_DELAY_MS: std::sync::atomic::AtomicU64 = std::sync::atomic::AtomicU64::new(0);
std::thread_local! {
static ENGINES_STARTED: std::cell::Cell<u64> = const { std::cell::Cell::new(0) };
}
/// How many script engine threads the sessions made on this thread have started, for
/// diagnostics and tests: an event's scripts share one, so opening a form with hundreds of
/// calculations starts one. Per thread, so a caller counting its own events is not disturbed
/// by forms on other threads. Always 0 on wasm, where the scripts run on the caller's thread.
pub fn engines_started() -> u64 {
ENGINES_STARTED.with(std::cell::Cell::get)
}
/// What one script run needs.
#[derive(Clone, Debug)]
pub struct Script {
@@ -58,7 +70,7 @@ fn run_script(s: Script, doc: &XfaDoc, started: &dyn Fn()) -> XfaOutcome {
#[cfg(not(target_arch = "wasm32"))]
mod native {
use std::sync::mpsc::{Receiver, RecvTimeoutError, Sender, channel};
use std::time::Instant;
use std::time::{Duration, Instant};
use super::{Script, run_script};
use crate::xfa::{ENGINE_START_LIMIT, XfaDoc, XfaOutcome};
@@ -83,11 +95,20 @@ mod native {
worker: Option<Worker>,
/// A script ran past its limit: its thread is left to it and nothing more runs.
dead: Option<String>,
/// How long the engine has to be ready for a script ([`ENGINE_START_LIMIT`] by default).
start_limit: Duration,
}
impl XfaSession {
pub fn new(doc: XfaDoc) -> XfaSession {
XfaSession { doc, worker: None, dead: None }
XfaSession { doc, worker: None, dead: None, start_limit: ENGINE_START_LIMIT }
}
/// Multiply the time the engine has to be ready for a script by `factor` (a script's
/// own time is [`Script::timeout`]).
pub fn with_time_scale(mut self, factor: u32) -> XfaSession {
self.start_limit = ENGINE_START_LIMIT.saturating_mul(factor);
self
}
/// Why nothing more runs, once a script was abandoned.
@@ -115,11 +136,12 @@ mod native {
}
});
spawned.map_err(|e| format!("the script engine could not start: {e}"))?;
match from.recv_timeout(ENGINE_START_LIMIT) {
super::ENGINES_STARTED.with(|n| n.set(n.get().saturating_add(1)));
match from.recv_timeout(self.start_limit) {
Ok(Reply::Ready) => {}
Ok(_) => return Err("the script engine answered out of turn".into()),
Err(RecvTimeoutError::Timeout) => {
return Err(format!("the script engine took longer than {:.0} s to start", ENGINE_START_LIMIT.as_secs_f64()));
return Err(format!("the script engine took longer than {:.0} s to start", self.start_limit.as_secs_f64()));
}
Err(RecvTimeoutError::Disconnected) => return Err("the script engine stopped with an internal error".into()),
}
@@ -129,8 +151,9 @@ mod native {
}
/// Run one script, waiting at most its `timeout` from when the engine is ready for it
/// (the engine itself gets [`ENGINE_START_LIMIT`] to be ready); past that it is
/// abandoned on its thread and the session is dead.
/// (the engine itself gets [`ENGINE_START_LIMIT`] to be ready, unless
/// [`XfaSession::with_time_scale`] changed it); past that it is abandoned on its thread
/// and the session is dead.
pub fn run(&mut self, script: Script) -> XfaOutcome {
let abandoned = |why: String| XfaOutcome { error: Some(why), abandoned: true, ..Default::default() };
let failed = |why: String| XfaOutcome { error: Some(why), ..Default::default() };
@@ -138,6 +161,7 @@ mod native {
return abandoned(why.clone());
}
let timeout = script.timeout;
let start_limit = self.start_limit;
let worker = match self.worker() {
Ok(w) => w,
Err(why) => return failed(why),
@@ -148,7 +172,7 @@ mod native {
return failed("the script engine stopped with an internal error".into());
}
// The engine's start, then the script's own time.
let (mut running, mut limit) = (false, ENGINE_START_LIMIT);
let (mut running, mut limit) = (false, start_limit);
let mut deadline = Instant::now().checked_add(limit);
loop {
let left = deadline.map_or(limit, |d| d.saturating_duration_since(Instant::now()));
@@ -167,7 +191,7 @@ mod native {
let why = if running {
format!("the script ran longer than {:.1} s and was abandoned", timeout.as_secs_f64())
} else {
format!("the script engine took longer than {:.0} s to start", ENGINE_START_LIMIT.as_secs_f64())
format!("the script engine took longer than {:.0} s to start", start_limit.as_secs_f64())
};
self.dead = Some(why.clone());
// Dropping the sender ends the thread's loop once the script is done.
@@ -199,6 +223,11 @@ mod native {
XfaSession { doc }
}
/// No engine to start on wasm: nothing to scale.
pub fn with_time_scale(self, _factor: u32) -> XfaSession {
self
}
pub fn dead(&self) -> Option<&str> {
None
}