add logging

Cargo.lock

@@ -17,6 +17,15 @@ version = "1.0.2"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "f26201604c87b1e01bd3d98f8d5d9a8fcbb815e8cedb41ffccbeb4bf593a35fe"
 
+[[package]]
+name = "aho-corasick"
+version = "1.0.2"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "43f6cb1bf222025340178f382c426f13757b2960e89779dfcb319c32542a5a41"
+dependencies = [
+ "memchr",
+]
+
 [[package]]
 name = "async-trait"
 version = "0.1.71"
@@ -42,7 +51,7 @@ checksum = "f8175979259124331c1d7bf6586ee7e0da434155e4b2d48ec2c8386281d8df39"
 dependencies = [
  "async-trait",
  "axum-core",
- "bitflags",
+ "bitflags 1.3.2",
  "bytes",
  "futures-util",
  "http",
@@ -104,6 +113,12 @@ version = "1.3.2"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "bef38d45163c2f1dde094a7dfd33ccf595c92905c8f8f4fdc18d06fb1037718a"
 
+[[package]]
+name = "bitflags"
+version = "2.3.3"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "630be753d4e58660abd17930c71b647fe46c27ea6b63cc59e1e3851406972e42"
+
 [[package]]
 name = "bytes"
 version = "1.4.0"
@@ -115,7 +130,9 @@ name = "captcha"
 version = "0.1.0"
 dependencies = [
  "axum",
+ "env_logger",
  "lazy_static",
+ "log",
  "rand",
  "serde",
  "tokio",
@@ -133,6 +150,40 @@ version = "1.0.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "baf1de4339761588bc0619e3cbc0120ee582ebb74b53b4efbf79117bd2da40fd"
 
+[[package]]
+name = "env_logger"
+version = "0.10.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "85cdab6a89accf66733ad5a1693a4dcced6aeff64602b634530dd73c1f3ee9f0"
+dependencies = [
+ "humantime",
+ "is-terminal",
+ "log",
+ "regex",
+ "termcolor",
+]
+
+[[package]]
+name = "errno"
+version = "0.3.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "4bcfec3a70f97c962c307b2d2c56e358cf1d00b558d74262b5f929ee8cc7e73a"
+dependencies = [
+ "errno-dragonfly",
+ "libc",
+ "windows-sys",
+]
+
+[[package]]
+name = "errno-dragonfly"
+version = "0.1.2"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "aa68f1b12764fab894d2755d2518754e71b4fd80ecfb822714a1206c2aab39bf"
+dependencies = [
+ "cc",
+ "libc",
+]
+
 [[package]]
 name = "fnv"
 version = "1.0.7"
@@ -207,6 +258,12 @@ dependencies = [
  "libc",
 ]
 
+[[package]]
+name = "hermit-abi"
+version = "0.3.2"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "443144c8cdadd93ebf52ddb4056d257f5b52c04d3c804e657d19eb73fc33668b"
+
 [[package]]
 name = "http"
 version = "0.2.9"
@@ -241,6 +298,12 @@ version = "1.0.2"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "c4a1e36c821dbe04574f602848a19f742f4fb3c98d40449f11bcad18d6b17421"
 
+[[package]]
+name = "humantime"
+version = "2.1.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "9a3a5bfb195931eeb336b2a7b4d761daec841b97f947d34394601737a7bba5e4"
+
 [[package]]
 name = "hyper"
 version = "0.14.27"
@@ -264,6 +327,17 @@ dependencies = [
  "want",
 ]
 
+[[package]]
+name = "is-terminal"
+version = "0.4.9"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "cb0889898416213fab133e1d33a0e5858a48177452750691bde3666d0fdbaf8b"
+dependencies = [
+ "hermit-abi 0.3.2",
+ "rustix",
+ "windows-sys",
+]
+
 [[package]]
 name = "itoa"
 version = "1.0.8"
@@ -282,6 +356,18 @@ version = "0.2.147"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "b4668fb0ea861c1df094127ac5f1da3409a82116a4ba74fca2e58ef927159bb3"
 
+[[package]]
+name = "linux-raw-sys"
+version = "0.4.3"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "09fc20d2ca12cb9f044c93e3bd6d32d523e6e2ec3db4f7b2939cd99026ecd3f0"
+
+[[package]]
+name = "log"
+version = "0.4.19"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "b06a4cde4c0f271a446782e3eff8de789548ce57dbc8eca9292c27f4a42004b4"
+
 [[package]]
 name = "matchit"
 version = "0.7.0"
@@ -326,7 +412,7 @@ version = "1.15.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "0fac9e2da13b5eb447a6ce3d392f23a29d8694bff781bf03a16cd9ac8697593b"
 dependencies = [
- "hermit-abi",
+ "hermit-abi 0.2.6",
  "libc",
 ]
 
@@ -437,12 +523,54 @@ dependencies = [
  "getrandom",
 ]
 
+[[package]]
+name = "regex"
+version = "1.9.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "b2eae68fc220f7cf2532e4494aded17545fce192d59cd996e0fe7887f4ceb575"
+dependencies = [
+ "aho-corasick",
+ "memchr",
+ "regex-automata",
+ "regex-syntax",
+]
+
+[[package]]
+name = "regex-automata"
+version = "0.3.3"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "39354c10dd07468c2e73926b23bb9c2caca74c5501e38a35da70406f1d923310"
+dependencies = [
+ "aho-corasick",
+ "memchr",
+ "regex-syntax",
+]
+
+[[package]]
+name = "regex-syntax"
+version = "0.7.4"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "e5ea92a5b6195c6ef2a0295ea818b312502c6fc94dde986c5553242e18fd4ce2"
+
 [[package]]
 name = "rustc-demangle"
 version = "0.1.23"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "d626bb9dae77e28219937af045c257c28bfd3f69333c512553507f5f9798cb76"
 
+[[package]]
+name = "rustix"
+version = "0.38.4"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "0a962918ea88d644592894bc6dc55acc6c0956488adcebbfb6e273506b7fd6e5"
+dependencies = [
+ "bitflags 2.3.3",
+ "errno",
+ "libc",
+ "linux-raw-sys",
+ "windows-sys",
+]
+
 [[package]]
 name = "rustversion"
 version = "1.0.13"
@@ -544,6 +672,15 @@ version = "0.1.2"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "2047c6ded9c721764247e62cd3b03c09ffc529b2ba5b10ec482ae507a4a70160"
 
+[[package]]
+name = "termcolor"
+version = "1.2.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "be55cf8942feac5c765c2c993422806843c9a9a45d4d5c407ad6dd2ea95eb9b6"
+dependencies = [
+ "winapi-util",
+]
+
 [[package]]
 name = "tokio"
 version = "1.29.1"
@@ -664,6 +801,15 @@ version = "0.4.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "ac3b87c63620426dd9b991e5ce0329eff545bccbbb34f3be09ff6fb6ab51b7b6"
 
+[[package]]
+name = "winapi-util"
+version = "0.1.5"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "70ec6ce85bb158151cae5e5c87f95a8e97d2c0c4b001223f33a334e3ce5de178"
+dependencies = [
+ "winapi",
+]
+
 [[package]]
 name = "winapi-x86_64-pc-windows-gnu"
 version = "0.4.0"

Cargo.toml

@@ -11,3 +11,5 @@ serde = { version = "1.0", features = ["serde_derive"] }
 axum = { version = "0.6", features = ["tokio", "query", "form", "json", "http1"], default-features = false }
 rand = "0.8"
 lazy_static = "1.4"
+log = "0.4"
+env_logger = "0.10"

src/main.rs

@@ -5,6 +5,7 @@ use axum::{
 	response::{Html, IntoResponse, Response},
 	Router, extract::{Path, Query, State}, Form, http::{header, StatusCode}, Json,
 };
+use log::{info, debug};
 use rand::{seq::SliceRandom, Rng, distributions::{Alphanumeric, DistString}};
 use serde::{Deserialize, Serialize};
 use tokio::{sync::Mutex, process::Command};
@@ -60,6 +61,7 @@ async fn next_id(state: &AppState) -> u64 {
 	loop {
 		let id = rand::thread_rng().gen();
 		if !state.incomplete.lock().await.contains_key(&id) {
+			debug!("generated id {id}");
 			return id
 		}
 	}
@@ -139,6 +141,7 @@ struct IndexQuery {
 }
 
 async fn page_index(State(state): State<AState>, Query(query): Query<IndexQuery>) -> Html<String> {
+	debug!("loading index page, count {} userdata {:?}", query.count, query.userdata);
 	let id = next_id(&state).await;
 	let id_string = id.to_string();
 	let id_str: &str = id_string.as_ref();
@@ -167,12 +170,15 @@ async fn page_index(State(state): State<AState>, Query(query): Query<IndexQuery>
 }
 
 async fn page_image(State(state): State<AState>, Path(id): Path<u64>) -> Response {
+	debug!("loading image {id}");
 	let mut incomplete = state.incomplete.lock().await;
 	let Some(cap) = incomplete.get_mut(&id) else {
+		debug!("invalid image {id}");
 		return (StatusCode::BAD_REQUEST, "Invalid ID").into_response()
 	};
 
 	if cap.got_image {
+		debug!("image {id} already loaded");
 		return (StatusCode::BAD_REQUEST, "Image already viewed").into_response()
 	}
 	cap.got_image = true;
@@ -182,9 +188,15 @@ async fn page_image(State(state): State<AState>, Path(id): Path<u64>) -> Respons
 
 	tokio::time::sleep(Duration::from_millis(300)).await;
 
-	let Ok(img) = mk_captcha_img(&digits).await else {
+	debug!("generating image");
-		return (StatusCode::INTERNAL_SERVER_ERROR, "Internal server error").into_response()
+	let img = match mk_captcha_img(&digits).await {
+		Ok(img) => img,
+		Err(e) => {
+			debug!("image generation failed: {e}");
+			return (StatusCode::INTERNAL_SERVER_ERROR, "Internal server error").into_response()
+		}
 	};
+	debug!("image generated");
 
 	let mut res = img.into_response();
 	res.headers_mut().insert(
@@ -194,12 +206,15 @@ async fn page_image(State(state): State<AState>, Path(id): Path<u64>) -> Respons
 }
 
 async fn page_audio(State(state): State<AState>, Path(id): Path<u64>) -> Response {
+	debug!("loading audio {id}");
 	let mut incomplete = state.incomplete.lock().await;
 	let Some(cap) = incomplete.get_mut(&id) else {
+		debug!("invalid audio {id}");
 		return (StatusCode::BAD_REQUEST, "Invalid ID").into_response()
 	};
 
 	if cap.got_audio {
+		debug!("audio {id} already loaded");
 		return (StatusCode::BAD_REQUEST, "Audio already accessed").into_response()
 	}
 	cap.got_audio = true;
@@ -209,9 +224,15 @@ async fn page_audio(State(state): State<AState>, Path(id): Path<u64>) -> Respons
 
 	tokio::time::sleep(Duration::from_millis(300)).await;
 
-	let Ok(audio) = mk_captcha_audio(&digits).await else {
+	debug!("generating audio");
-		return (StatusCode::INTERNAL_SERVER_ERROR, "Internal server error").into_response()
+	let audio = match mk_captcha_audio(&digits).await {
+		Ok(audio) => audio,
+		Err(e) => {
+			debug!("audio generation failed: {e}");
+			return (StatusCode::INTERNAL_SERVER_ERROR, "Internal server error").into_response()
+		}
 	};
+	debug!("audio generated");
 
 	let mut res = audio.into_response();
 	res.headers_mut().insert(
@@ -227,21 +248,27 @@ struct SubmitForm {
 }
 
 async fn page_submit(State(state): State<AState>, Form(form): Form<SubmitForm>) -> impl IntoResponse {
+	debug!("submitting id {} digits {}", form.id, form.digits);
 	let Some(cap) = state.incomplete.lock().await.remove(&form.id) else {
+		debug!("id {} expired", form.id);
 		let body = SUBMIT_ERR.replace("{{msg}}", "CAPTCHA expired or ID invalid. Consider trying again.");
 		return Html(body)
 	};
 
 	if form.digits != cap.digits {
+		debug!("id {} failed: expected {}, got {}", form.id, cap.digits, form.digits);
 		let body = SUBMIT_ERR.replace("{{msg}}", "CAPTCHA failed. Consider trying again.");
 		return Html(body)
 	}
 
+
 	let token = Alphanumeric.sample_string(&mut rand::thread_rng(), 24);
 
 	let count = cap.digits.len();
 	let completed = SystemTime::now().duration_since(SystemTime::UNIX_EPOCH).unwrap().as_secs();
 
+	debug!("id {} succeeded, generated token {}", form.id, token);
+
 	let body = SUBMIT_OK.replace("{{token}}", &token);
 
 	state.complete.lock().await.insert(token, CompleteCaptcha { count, issued: cap.issued, completed, userdata: cap.userdata });
@@ -255,15 +282,20 @@ struct VerifyQuery {
 }
 
 async fn page_verify(State(state): State<AState>, Query(query): Query<VerifyQuery>) -> Response {
+	debug!("verifying token {}", query.token);
 	let Some(info) = state.complete.lock().await.remove(&query.token) else {
+		debug!("verification failed for {}", query.token);
 		return (StatusCode::BAD_REQUEST, "Invalid or expired token").into_response()
 	};
+	debug!("verification succeeded for {}", query.token);
 
 	Json(info).into_response()
 }
 
 #[tokio::main]
 async fn main() {
+	env_logger::init();
+
 	let addr = std::env::var("TCAP_ADDR")
 		.unwrap_or_else(|_| "localhost:8000".to_owned())
 		.to_socket_addrs().unwrap().next().unwrap();
@@ -282,7 +314,7 @@ async fn main() {
 		.with_state(state.clone());
 
 	let server = tokio::spawn(async move {
-		println!("Listening on http://{addr}");
+		info!("Listening on http://{addr}");
 		axum::Server::bind(&addr)
 			.serve(app.into_make_service())
 			.await
@@ -293,6 +325,7 @@ async fn main() {
         let mut interval = tokio::time::interval(Duration::from_secs(15));
         loop {
             interval.tick().await;
+			debug!("cleaning up");
 
 			let now = SystemTime::now().duration_since(SystemTime::UNIX_EPOCH).unwrap().as_secs();