| 565 | 565 | | #[test] |
| 566 | 566 | | fn a_long_wait_says_so_in_the_log_as_it_goes() { |
| 567 | 567 | | let mut log = log(&[]); |
| 568 | + | // The work answers once the log has told of the wait twice, so the |
| 569 | + | // test does not hang on how fast the machine is; a minute at most. |
| 570 | + | let told_so_far = std::sync::Arc::new(std::sync::atomic::AtomicUsize::new(0)); |
| 571 | + | let seen = told_so_far.clone(); |
| 568 | 572 | | let started = Instant::now(); |
| 569 | | − | let answer = log.waiting(Duration::from_millis(50), |_| { |
| 570 | | − | std::thread::sleep(Duration::from_millis(180)); |
| 571 | | − | 42 |
| 572 | | − | }, |seconds| format!("still waiting ({seconds}s)")); |
| 573 | | − | // A busy machine sleeps longer than asked: one line per 50 ms the |
| 574 | | − | // wait really took, never more. |
| 573 | + | let answer = log.waiting( |
| 574 | + | Duration::from_millis(50), |
| 575 | + | move |_| { |
| 576 | + | let deadline = Instant::now() + Duration::from_secs(60); |
| 577 | + | while seen.load(std::sync::atomic::Ordering::SeqCst) < 2 && Instant::now() < deadline { |
| 578 | + | std::thread::sleep(Duration::from_millis(5)); |
| 579 | + | } |
| 580 | + | 42 |
| 581 | + | }, |
| 582 | + | move |seconds| { |
| 583 | + | told_so_far.fetch_add(1, std::sync::atomic::Ordering::SeqCst); |
| 584 | + | format!("still waiting ({seconds}s)") |
| 585 | + | }, |
| 586 | + | ); |
| 575 | 587 | | let took = started.elapsed().as_millis() as usize; |
| 576 | 588 | | assert_eq!(answer, 42); |
| 577 | 589 | | let lines = log.buffered(); |
| 578 | 590 | | let told = lines.lines().filter(|line| line.starts_with("still waiting (")).count(); |
| 591 | + | // At least the two it waited for, and never more than one per 50 ms |
| 592 | + | // the wait really took. |
| 579 | 593 | | assert!(told >= 2 && told <= took / 50, "a line each time the wait goes on ({took} ms): {lines:?}"); |
| 580 | 594 | | // A wait that ends at once writes nothing. |
| 581 | 595 | | let mut quick = super::tests::log(&[]); |
