max / synckit
- Co-Authored-By
- Claude Opus 5 (1M context) <noreply@anthropic.com>
- Claude-Session
- https://claude.ai/code/session_01MptwXZ8k65v19rFmdGAyki
6 files changed,
+276 insertions,
-200 deletions
| @@ -80,6 +80,9 @@ | |||
| 80 | 80 | pub mod store; | |
| 81 | 81 | pub mod types; | |
| 82 | 82 | ||
| 83 | + | #[cfg(test)] | |
| 84 | + | mod test_support; | |
| 85 | + | ||
| 83 | 86 | // Re-exports for convenience | |
| 84 | 87 | pub use client::subscription::{ | |
| 85 | 88 | AccountInfo, AppPricing, BillingInterval, Cents, CheckoutResponse, PriceQuote, |
| @@ -1047,6 +1047,120 @@ | |||
| 1047 | 1047 | ); | |
| 1048 | 1048 | } | |
| 1049 | 1049 | ||
| 1050 | + | #[test] | |
| 1051 | + | fn a_store_failure_is_reported_and_swallowed() { | |
| 1052 | + | // `best_effort` is the whole of the rule that nothing about the | |
| 1053 | + | // resume store may fail an upload: it takes the error, says so, and | |
| 1054 | + | // returns. Both halves matter and neither is a return value, so a | |
| 1055 | + | // body replaced by `()` would behave identically to any caller. The | |
| 1056 | + | // log is where the difference lives. | |
| 1057 | + | let noisy = crate::test_support::events_from(|| { | |
| 1058 | + | best_effort( | |
| 1059 | + | "record_part", | |
| 1060 | + | Err(SyncKitError::Internal("disk full".into())), | |
| 1061 | + | ); | |
| 1062 | + | }); | |
| 1063 | + | let line = noisy | |
| 1064 | + | .iter() | |
| 1065 | + | .find(|e| { | |
| 1066 | + | e.message | |
| 1067 | + | .as_deref() | |
| 1068 | + | .is_some_and(|m| m.contains("record_part") && m.contains("disk full")) | |
| 1069 | + | }) | |
| 1070 | + | .expect("a store failure must name the operation and the cause"); | |
| 1071 | + | assert!( | |
| 1072 | + | line.message | |
| 1073 | + | .as_deref() | |
| 1074 | + | .is_some_and(|m| m.contains("will not resume")), | |
| 1075 | + | "the line must say what the failure costs, which is a restart from zero" | |
| 1076 | + | ); | |
| 1077 | + | ||
| 1078 | + | let quiet = crate::test_support::events_from(|| { | |
| 1079 | + | best_effort("record_part", Ok(())); | |
| 1080 | + | }); | |
| 1081 | + | assert!( | |
| 1082 | + | quiet.is_empty(), | |
| 1083 | + | "a store that worked has nothing to report" | |
| 1084 | + | ); | |
| 1085 | + | } | |
| 1086 | + | ||
| 1087 | + | /// Half the server's 24h orphan-reaper window, in seconds, written out | |
| 1088 | + | /// rather than read from [`RESUME_MAX_AGE_SECS`]. The point of the two | |
| 1089 | + | /// tests below is to pin that constant's value as well as the | |
| 1090 | + | /// comparison against it, and taking the number from the code under | |
| 1091 | + | /// test would make them agree with whatever it happened to hold. | |
| 1092 | + | const TWELVE_HOURS: i64 = 43_200; | |
| 1093 | + | ||
| 1094 | + | #[test] | |
| 1095 | + | fn a_record_on_the_twelve_hour_boundary_is_still_usable() { | |
| 1096 | + | // The comparison is `>`, not `>=`: the window is chosen to leave a | |
| 1097 | + | // slow transfer room to finish inside it, and a record that has just | |
| 1098 | + | // reached the boundary still names a session the server holds. | |
| 1099 | + | let store = fake(TWELVE_HOURS); | |
| 1100 | + | assert!( | |
| 1101 | + | SyncKitClient::load_resume(&store, "h", 24).is_some(), | |
| 1102 | + | "a record exactly at the limit is inside the window, not past it" | |
| 1103 | + | ); | |
| 1104 | + | assert!(!*store.cleared.lock().unwrap()); | |
| 1105 | + | } | |
| 1106 | + | ||
| 1107 | + | #[test] | |
| 1108 | + | fn a_record_one_second_past_twelve_hours_is_dropped() { | |
| 1109 | + | let store = fake(TWELVE_HOURS + 1); | |
| 1110 | + | assert!(SyncKitClient::load_resume(&store, "h", 24).is_none()); | |
| 1111 | + | assert!(*store.cleared.lock().unwrap()); | |
| 1112 | + | } | |
| 1113 | + | ||
| 1114 | + | /// The line `load_resume` writes when it throws a record away. | |
| 1115 | + | const DISCARD_LINE: &str = "discarding an unusable blob resume record"; | |
| 1116 | + | ||
| 1117 | + | #[test] | |
| 1118 | + | fn only_a_faulty_record_is_reported_as_discarded() { | |
| 1119 | + | // The three ways a record is dropped are not one event. A stale | |
| 1120 | + | // session and a plan that does not tile the blob are faults, and an | |
| 1121 | + | // operator wondering why an upload restarted wants to see them. A | |
| 1122 | + | // record with no completed parts is the ordinary case of a run that | |
| 1123 | + | // died before its first part landed; logging that would put a line | |
| 1124 | + | // in front of somebody on every such retry, and it says nothing. | |
| 1125 | + | // | |
| 1126 | + | // The guard that draws that distinction returns nothing and changes | |
| 1127 | + | // nothing, so the log is the only place it is observable at all. | |
| 1128 | + | ||
| 1129 | + | let empty = fake(60); | |
| 1130 | + | empty.record.lock().unwrap().as_mut().unwrap().parts.clear(); | |
| 1131 | + | let quiet = crate::test_support::events_from(|| { | |
| 1132 | + | assert!(SyncKitClient::load_resume(&empty, "h", 24).is_none()); | |
| 1133 | + | }); | |
| 1134 | + | assert!( | |
| 1135 | + | quiet | |
| 1136 | + | .iter() | |
| 1137 | + | .all(|e| e.message.as_deref() != Some(DISCARD_LINE)), | |
| 1138 | + | "a record that simply has nothing to save is not a fault to report" | |
| 1139 | + | ); | |
| 1140 | + | ||
| 1141 | + | let stale = fake(TWELVE_HOURS + 1); | |
| 1142 | + | let logged = crate::test_support::events_from(|| { | |
| 1143 | + | assert!(SyncKitClient::load_resume(&stale, "h", 24).is_none()); | |
| 1144 | + | }); | |
| 1145 | + | let line = logged | |
| 1146 | + | .iter() | |
| 1147 | + | .find(|e| e.message.as_deref() == Some(DISCARD_LINE)) | |
| 1148 | + | .expect("a stale session is a fault and must be reported"); | |
| 1149 | + | assert_eq!(line.field("stale"), Some("true")); | |
| 1150 | + | assert_eq!(line.field("fits"), Some("true"), "it fits, it is just dead"); | |
| 1151 | + | ||
| 1152 | + | let misfit = fake(60); | |
| 1153 | + | let logged = crate::test_support::events_from(|| { | |
| 1154 | + | assert!(SyncKitClient::load_resume(&misfit, "h", 999).is_none()); | |
| 1155 | + | }); | |
| 1156 | + | let line = logged | |
| 1157 | + | .iter() | |
| 1158 | + | .find(|e| e.message.as_deref() == Some(DISCARD_LINE)) | |
| 1159 | + | .expect("a record that cannot describe this upload must be reported"); | |
| 1160 | + | assert_eq!(line.field("stale"), Some("false")); | |
| 1161 | + | assert_eq!(line.field("fits"), Some("false")); | |
| 1162 | + | } | |
| 1163 | + | ||
| 1050 | 1164 | #[test] | |
| 1051 | 1165 | fn a_record_for_a_different_length_is_dropped() { | |
| 1052 | 1166 | // Same content hash, different ciphertext length is a contradiction: |
| @@ -452,78 +452,15 @@ | |||
| 452 | 452 | // operator learns the server has started sending an interval this client | |
| 453 | 453 | // does not know, and the guard is what keeps the two expected cases quiet | |
| 454 | 454 | // rather than logging on every ordinary monthly subscription. | |
| 455 | - | // | |
| 456 | - | // A recording subscriber is what makes it observable. `with_default` scopes | |
| 457 | - | // it to this thread, so nothing global is installed, and the subscriber is | |
| 458 | - | // twenty lines rather than a `tracing-subscriber` dev-dependency. | |
| 459 | - | ||
| 460 | - | /// Pull the `tag` field off an event, whichever way it was recorded. | |
| 461 | - | /// `tag = %other` arrives through `record_debug` as a `format_args`, so the | |
| 462 | - | /// `Debug` rendering is the raw string with no quotes around it. | |
| 463 | - | #[derive(Default)] | |
| 464 | - | struct TagVisitor(Option<String>); | |
| 465 | - | ||
| 466 | - | impl tracing::field::Visit for TagVisitor { | |
| 467 | - | fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) { | |
| 468 | - | if field.name() == "tag" { | |
| 469 | - | self.0 = Some(format!("{value:?}")); | |
| 470 | - | } | |
| 471 | - | } | |
| 472 | - | ||
| 473 | - | fn record_str(&mut self, field: &tracing::field::Field, value: &str) { | |
| 474 | - | if field.name() == "tag" { | |
| 475 | - | self.0 = Some(value.to_string()); | |
| 476 | - | } | |
| 477 | - | } | |
| 478 | - | } | |
| 479 | - | ||
| 480 | - | /// Records the `tag` of every event emitted while it is the thread default. | |
| 481 | - | struct TagRecorder(std::sync::Arc<std::sync::Mutex<Vec<Option<String>>>>); | |
| 482 | - | ||
| 483 | - | impl tracing::Subscriber for TagRecorder { | |
| 484 | - | fn register_callsite( | |
| 485 | - | &self, | |
| 486 | - | _: &'static tracing::Metadata<'static>, | |
| 487 | - | ) -> tracing::subscriber::Interest { | |
| 488 | - | // `sometimes`, not the default `always`/`never` verdict: interest is | |
| 489 | - | // cached per callsite for the life of the process, so a verdict | |
| 490 | - | // recorded here would outlive the guard below and decide the answer | |
| 491 | - | // for every later caller in this test binary. | |
| 492 | - | tracing::subscriber::Interest::sometimes() | |
| 493 | - | } | |
| 494 | - | ||
| 495 | - | fn enabled(&self, _: &tracing::Metadata<'_>) -> bool { | |
| 496 | - | true | |
| 497 | - | } | |
| 498 | - | ||
| 499 | - | fn new_span(&self, _: &tracing::span::Attributes<'_>) -> tracing::span::Id { | |
| 500 | - | tracing::span::Id::from_u64(1) | |
| 501 | - | } | |
| 502 | - | ||
| 503 | - | fn record(&self, _: &tracing::span::Id, _: &tracing::span::Record<'_>) {} | |
| 504 | - | ||
| 505 | - | fn record_follows_from(&self, _: &tracing::span::Id, _: &tracing::span::Id) {} | |
| 506 | - | ||
| 507 | - | fn event(&self, event: &tracing::Event<'_>) { | |
| 508 | - | let mut visitor = TagVisitor::default(); | |
| 509 | - | event.record(&mut visitor); | |
| 510 | - | self.0.lock().expect("the recorder mutex").push(visitor.0); | |
| 511 | - | } | |
| 512 | - | ||
| 513 | - | fn enter(&self, _: &tracing::span::Id) {} | |
| 514 | - | ||
| 515 | - | fn exit(&self, _: &tracing::span::Id) {} | |
| 516 | - | } | |
| 517 | 455 | ||
| 518 | 456 | /// The tags `from_wire` logged while parsing `wire`, in order. | |
| 519 | 457 | fn tags_logged_parsing(wire: &str) -> Vec<Option<String>> { | |
| 520 | - | let events = std::sync::Arc::new(std::sync::Mutex::new(Vec::new())); | |
| 521 | - | let recorder = TagRecorder(std::sync::Arc::clone(&events)); | |
| 522 | - | tracing::subscriber::with_default(recorder, || { | |
| 458 | + | crate::test_support::events_from(|| { | |
| 523 | 459 | let _ = BillingInterval::from_wire(wire); | |
| 524 | - | }); | |
| 525 | - | let events = events.lock().expect("the recorder mutex"); | |
| 526 | - | events.clone() | |
| 460 | + | }) | |
| 461 | + | .iter() | |
| 462 | + | .map(|e| e.field("tag").map(str::to_string)) | |
| 463 | + | .collect() | |
| 527 | 464 | } | |
| 528 | 465 | ||
| 529 | 466 | #[test] |
| @@ -149,6 +149,44 @@ | |||
| 149 | 149 | kit.authed().blob_confirm("sha256-abc", 1024).await.unwrap(); | |
| 150 | 150 | } | |
| 151 | 151 | ||
| 152 | + | /// The size guard on `blob_confirm` admits an empty blob and refuses a negative | |
| 153 | + | /// length. | |
| 154 | + | /// | |
| 155 | + | /// Zero is a real size: `streaming_upload_handles_an_empty_file` uploads one, so | |
| 156 | + | /// a guard that rejected it would make the empty blob unconfirmable and leave it | |
| 157 | + | /// unrecorded server-side. Negative is the only value that is not a length at | |
| 158 | + | /// all, and catching it here is what keeps it out of the request body. | |
| 159 | + | /// | |
| 160 | + | /// Both cases are needed. The `< 0` that separates them is one character from | |
| 161 | + | /// `<= 0`, which loses the empty blob, and from `== 0`, which loses the empty | |
| 162 | + | /// blob and lets a negative length through. | |
| 163 | + | #[tokio::test] | |
| 164 | + | async fn blob_confirm_admits_an_empty_blob_and_refuses_a_negative_size() { | |
| 165 | + | let kit = MockKit::start().await; | |
| 166 | + | kit.post(CONFIRM_PATH).empty().await; | |
| 167 | + | ||
| 168 | + | kit.authed() | |
| 169 | + | .blob_confirm("sha256-empty", 0) | |
| 170 | + | .await | |
| 171 | + | .expect("an empty blob has a size, and it is zero"); | |
| 172 | + | assert_eq!(kit.hits(CONFIRM_PATH).await, 1); | |
| 173 | + | ||
| 174 | + | let err = kit | |
| 175 | + | .authed() | |
| 176 | + | .blob_confirm("sha256-negative", -1) | |
| 177 | + | .await | |
| 178 | + | .unwrap_err(); | |
| 179 | + | assert!( | |
| 180 | + | matches!(err, SyncKitError::InvalidArgument(_)), | |
| 181 | + | "a negative length must be refused before it reaches the wire, got {err:?}" | |
| 182 | + | ); | |
| 183 | + | assert_eq!( | |
| 184 | + | kit.hits(CONFIRM_PATH).await, | |
| 185 | + | 1, | |
| 186 | + | "the refused call must not have been sent" | |
| 187 | + | ); | |
| 188 | + | } | |
| 189 | + | ||
| 152 | 190 | // ── Blob download URL ── | |
| 153 | 191 | ||
| 154 | 192 | #[tokio::test] |
| @@ -800,138 +800,6 @@ | |||
| 800 | 800 | std::fs::remove_file(&file).ok(); | |
| 801 | 801 | } | |
| 802 | 802 | ||
| 803 | - | // ── How old a resume record may be ── | |
| 804 | - | // | |
| 805 | - | // `load_resume` drops a record older than half the server's 24h orphan-reaper | |
| 806 | - | // window, because past it the `upload_id` is gone and resuming costs a doomed | |
| 807 | - | // round trip. Nothing observed the boundary: every other test here builds its | |
| 808 | - | // record seconds ago, so the comparison and the constant behind it were free to | |
| 809 | - | // be anything. | |
| 810 | - | // | |
| 811 | - | // A store of the test's own is what makes the age settable. `age_secs` is a | |
| 812 | - | // field on the record the store hands back, so a double can hand back any age | |
| 813 | - | // it likes without a clock seam in the client. | |
| 814 | - | ||
| 815 | - | /// A resume store that answers with one record the test chose, and counts the | |
| 816 | - | /// `clear` calls that say the client rejected it. | |
| 817 | - | struct SeededResume { | |
| 818 | - | record: std::sync::Mutex<Option<synckit_client::client::resume::ResumeRecord>>, | |
| 819 | - | } | |
| 820 | - | ||
| 821 | - | impl BlobResumeStore for SeededResume { | |
| 822 | - | fn load( | |
| 823 | - | &self, | |
| 824 | - | _hash: &str, | |
| 825 | - | ) -> synckit_client::Result<Option<synckit_client::client::resume::ResumeRecord>> { | |
| 826 | - | Ok(self.record.lock().unwrap().clone()) | |
| 827 | - | } | |
| 828 | - | ||
| 829 | - | fn begin( | |
| 830 | - | &self, | |
| 831 | - | _hash: &str, | |
| 832 | - | _session: &synckit_client::client::resume::ResumeSession, | |
| 833 | - | ) -> synckit_client::Result<()> { | |
| 834 | - | Ok(()) | |
| 835 | - | } | |
| 836 | - | ||
| 837 | - | fn record_part( | |
| 838 | - | &self, | |
| 839 | - | _hash: &str, | |
| 840 | - | _part: &synckit_client::client::resume::ResumePart, | |
| 841 | - | _chunks: &[synckit_client::client::resume::ResumeChunk], | |
| 842 | - | ) -> synckit_client::Result<()> { | |
| 843 | - | Ok(()) | |
| 844 | - | } | |
| 845 | - | ||
| 846 | - | fn clear(&self, _hash: &str) -> synckit_client::Result<()> { | |
| 847 | - | *self.record.lock().unwrap() = None; | |
| 848 | - | Ok(()) | |
| 849 | - | } | |
| 850 | - | } | |
| 851 | - | ||
| 852 | - | /// Run an upload against a resume record of the given age that names every | |
| 853 | - | /// part, and report how many parts went over the wire. | |
| 854 | - | /// | |
| 855 | - | /// A record the client keeps costs zero PUTs: it already names every part, so | |
| 856 | - | /// there is nothing left to send and only `complete` runs. A record the client | |
| 857 | - | /// rejects costs the whole blob. The two answers are as far apart as the | |
| 858 | - | /// question allows, which is what makes this a usable oracle for one `>`. | |
| 859 | - | async fn parts_sent_resuming_a_record_aged(age_secs: i64) -> (usize, usize) { | |
| 860 | - | let kit = MockKit::start().await; | |
| 861 | - | let key = synckit_client::crypto::generate_master_key(); | |
| 862 | - | ||
| 863 | - | let plaintext: Vec<u8> = (0..(synckit_client::crypto::BLOB_CHUNK_SIZE * 2 + 11)) | |
| 864 | - | .map(|i| i as u8) | |
| 865 | - | .collect(); | |
| 866 | - | let hash = hex::encode(sha2::Sha256::digest(&plaintext)); | |
| 867 | - | let file = temp_blob("aged.bin", &plaintext); | |
| 868 | - | let cipher_len = synckit_client::crypto::blob_encrypted_len(plaintext.len()); | |
| 869 | - | let part_size = 700 * 1024; | |
| 870 | - | let part_count = cipher_len.div_ceil(part_size); | |
| 871 | - | ||
| 872 | - | // A record that fits the file exactly and names every part, so keeping it | |
| 873 | - | // means sending nothing. No chunk records are needed: with every part | |
| 874 | - | // already up, the resume boundary lands past the last chunk and no chunk is | |
| 875 | - | // ever re-sealed. | |
| 876 | - | let record = synckit_client::client::resume::ResumeRecord { | |
| 877 | - | session: synckit_client::client::resume::ResumeSession { | |
| 878 | - | upload_id: "test-upload-id".into(), | |
| 879 | - | part_size: part_size as u64, | |
| 880 | - | part_count: part_count as u32, | |
| 881 | - | size_bytes: cipher_len as u64, | |
| 882 | - | }, | |
| 883 | - | age_secs, | |
| 884 | - | parts: (1..=part_count) | |
| 885 | - | .map(|n| synckit_client::client::resume::ResumePart { | |
| 886 | - | part_number: n as u32, | |
| 887 | - | etag: format!("\"etag-{n}\""), | |
| 888 | - | }) | |
| 889 | - | .collect(), | |
| 890 | - | chunks: Vec::new(), | |
| 891 | - | }; | |
| 892 | - | let store: Arc<dyn BlobResumeStore> = Arc::new(SeededResume { | |
| 893 | - | record: std::sync::Mutex::new(Some(record)), | |
| 894 | - | }); | |
| 895 | - | ||
| 896 | - | mount_session(&kit, cipher_len, part_size).await; | |
| 897 | - | kit.post(ABORT_PATH).code(204).empty().await; | |
| 898 | - | ||
| 899 | - | let client = kit.authed(); | |
| 900 | - | client.set_master_key_raw(key); | |
| 901 | - | client.set_resume_store(store); | |
| 902 | - | client.blob_upload_streaming(&hash, &file).await.unwrap(); | |
| 903 | - | ||
| 904 | - | let sent = put_bodies(&kit).await.len(); | |
| 905 | - | std::fs::remove_file(&file).ok(); | |
| 906 | - | (sent, part_count) | |
| 907 | - | } | |
| 908 | - | ||
| 909 | - | /// The record survives to exactly twelve hours and no further. | |
| 910 | - | /// | |
| 911 | - | /// Both halves are needed and they pin different things. The `at` case pins the | |
| 912 | - | /// comparison (`>` rather than `>=`, so a record on the boundary is still | |
| 913 | - | /// usable) and the constant behind it: a `RESUME_MAX_AGE_SECS` that arithmetic | |
| 914 | - | /// had made smaller would discard this record too. The `past` case is what | |
| 915 | - | /// stops the whole guard from being deleted. | |
| 916 | - | #[tokio::test] | |
| 917 | - | async fn a_resume_record_survives_to_twelve_hours_and_not_past_it() { | |
| 918 | - | /// `RESUME_MAX_AGE_SECS` from `src/client/blob.rs`, private there. Half the | |
| 919 | - | /// server's 24h orphan-reaper window. | |
| 920 | - | const RESUME_MAX_AGE_SECS: i64 = 12 * 60 * 60; | |
| 921 | - | ||
| 922 | - | let (at_the_limit, part_count) = parts_sent_resuming_a_record_aged(RESUME_MAX_AGE_SECS).await; | |
| 923 | - | assert_eq!( | |
| 924 | - | at_the_limit, 0, | |
| 925 | - | "a record exactly at the age limit is still usable: it names every part, so a resume sends nothing" | |
| 926 | - | ); | |
| 927 | - | ||
| 928 | - | let (past_the_limit, _) = parts_sent_resuming_a_record_aged(RESUME_MAX_AGE_SECS + 1).await; | |
| 929 | - | assert_eq!( | |
| 930 | - | past_the_limit, part_count, | |
| 931 | - | "a record one second past the limit must be discarded and the blob sent from part one" | |
| 932 | - | ); | |
| 933 | - | } | |
| 934 | - | ||
| 935 | 803 | // ── Part-boundary arithmetic ── | |
| 936 | 804 | // | |
| 937 | 805 | // The part plan is arithmetic on the ciphertext length, and the cases that break |
| @@ -1,0 +1,116 @@ | |||
| 1 | + | //! Test-only helpers shared across the crate's unit tests. | |
| 2 | + | //! | |
| 3 | + | //! Compiled only under `cfg(test)`, so nothing here reaches a consumer. | |
| 4 | + | ||
| 5 | + | /// One `tracing` event a [`events_from`] run saw. | |
| 6 | + | pub(crate) struct CapturedEvent { | |
| 7 | + | /// The event's message, which `tracing` carries as a field named `message`. | |
| 8 | + | pub(crate) message: Option<String>, | |
| 9 | + | /// Every other field, in the order they were recorded. | |
| 10 | + | pub(crate) fields: Vec<(String, String)>, | |
| 11 | + | } | |
| 12 | + | ||
| 13 | + | impl CapturedEvent { | |
| 14 | + | /// The value recorded for `name`, if the event carried it. | |
| 15 | + | pub(crate) fn field(&self, name: &str) -> Option<&str> { | |
| 16 | + | self.fields | |
| 17 | + | .iter() | |
| 18 | + | .find(|(k, _)| k == name) | |
| 19 | + | .map(|(_, v)| v.as_str()) | |
| 20 | + | } | |
| 21 | + | } | |
| 22 | + | ||
| 23 | + | /// Collects every field of one event. | |
| 24 | + | /// | |
| 25 | + | /// A `%value` field arrives through `record_debug` as a `format_args`, whose | |
| 26 | + | /// `Debug` rendering is the displayed text with no quotes around it, so both | |
| 27 | + | /// recorders below produce the bare string. | |
| 28 | + | #[derive(Default)] | |
| 29 | + | struct EventVisitor { | |
| 30 | + | message: Option<String>, | |
| 31 | + | fields: Vec<(String, String)>, | |
| 32 | + | } | |
| 33 | + | ||
| 34 | + | impl EventVisitor { | |
| 35 | + | fn put(&mut self, name: &str, value: String) { | |
| 36 | + | if name == "message" { | |
| 37 | + | self.message = Some(value); | |
| 38 | + | } else { | |
| 39 | + | self.fields.push((name.to_string(), value)); | |
| 40 | + | } | |
| 41 | + | } | |
| 42 | + | } | |
| 43 | + | ||
| 44 | + | impl tracing::field::Visit for EventVisitor { | |
| 45 | + | fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) { | |
| 46 | + | self.put(field.name(), format!("{value:?}")); | |
| 47 | + | } | |
| 48 | + | ||
| 49 | + | fn record_str(&mut self, field: &tracing::field::Field, value: &str) { | |
| 50 | + | self.put(field.name(), value.to_string()); | |
| 51 | + | } | |
| 52 | + | ||
| 53 | + | fn record_bool(&mut self, field: &tracing::field::Field, value: bool) { | |
| 54 | + | self.put(field.name(), value.to_string()); | |
| 55 | + | } | |
| 56 | + | } | |
| 57 | + | ||
| 58 | + | /// Records every event emitted while it is the thread's default subscriber. | |
| 59 | + | struct Recorder(std::sync::Arc<std::sync::Mutex<Vec<CapturedEvent>>>); | |
| 60 | + | ||
| 61 | + | impl tracing::Subscriber for Recorder { | |
| 62 | + | fn register_callsite( | |
| 63 | + | &self, | |
| 64 | + | _: &'static tracing::Metadata<'static>, | |
| 65 | + | ) -> tracing::subscriber::Interest { | |
| 66 | + | // `sometimes`, not the default `always`/`never` verdict: interest is | |
| 67 | + | // cached per callsite for the life of the process, so a verdict recorded | |
| 68 | + | // here would outlive the guard and decide the answer for every later | |
| 69 | + | // caller in this test binary. | |
| 70 | + | tracing::subscriber::Interest::sometimes() | |
| 71 | + | } | |
| 72 | + | ||
| 73 | + | fn enabled(&self, _: &tracing::Metadata<'_>) -> bool { | |
| 74 | + | true | |
| 75 | + | } | |
| 76 | + | ||
| 77 | + | fn new_span(&self, _: &tracing::span::Attributes<'_>) -> tracing::span::Id { | |
| 78 | + | tracing::span::Id::from_u64(1) | |
| 79 | + | } | |
| 80 | + | ||
| 81 | + | fn record(&self, _: &tracing::span::Id, _: &tracing::span::Record<'_>) {} | |
| 82 | + | ||
| 83 | + | fn record_follows_from(&self, _: &tracing::span::Id, _: &tracing::span::Id) {} | |
| 84 | + | ||
| 85 | + | fn event(&self, event: &tracing::Event<'_>) { | |
| 86 | + | let mut visitor = EventVisitor::default(); | |
| 87 | + | event.record(&mut visitor); | |
| 88 | + | self.0 | |
| 89 | + | .lock() | |
| 90 | + | .expect("the recorder mutex") | |
| 91 | + | .push(CapturedEvent { | |
| 92 | + | message: visitor.message, | |
| 93 | + | fields: visitor.fields, | |
| 94 | + | }); | |
| 95 | + | } | |
| 96 | + | ||
| 97 | + | fn enter(&self, _: &tracing::span::Id) {} | |
| 98 | + | ||
| 99 | + | fn exit(&self, _: &tracing::span::Id) {} | |
| 100 | + | } | |
| 101 | + | ||
| 102 | + | /// Every `tracing` event `f` emitted, in order. | |
| 103 | + | /// | |
| 104 | + | /// The subscriber is the thread's default for the duration of `f` only, so | |
| 105 | + | /// nothing global is installed and tests stay independent of each other. What | |
| 106 | + | /// it is for: a branch whose only effect is a log line, which no assertion on a | |
| 107 | + | /// return value can reach. | |
| 108 | + | pub(crate) fn events_from(f: impl FnOnce()) -> Vec<CapturedEvent> { | |
| 109 | + | let events = std::sync::Arc::new(std::sync::Mutex::new(Vec::new())); | |
| 110 | + | let recorder = Recorder(std::sync::Arc::clone(&events)); | |
| 111 | + | tracing::subscriber::with_default(recorder, f); | |
| 112 | + | std::sync::Arc::into_inner(events) | |
| 113 | + | .expect("the recorder is dropped with the subscriber") | |
| 114 | + | .into_inner() | |
| 115 | + | .expect("the recorder mutex") | |
| 116 | + | } |