diff --git a/Cargo.lock b/Cargo.lock index 80425b4..eff78a1 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2966,6 +2966,7 @@ dependencies = [ "sha2 0.10.9", "tokio", "toml", + "tracing", ] [[package]] diff --git a/proton-bridge/Cargo.toml b/proton-bridge/Cargo.toml index deafe9e..5485b52 100644 --- a/proton-bridge/Cargo.toml +++ b/proton-bridge/Cargo.toml @@ -21,3 +21,4 @@ env_logger = "0.11" aes = "0.8" cfb-mode = "0.8" sha1 = "0.10" +tracing = "0.1.44" \ No newline at end of file diff --git a/proton-bridge/src/auth.rs b/proton-bridge/src/auth.rs index deabdba..ad6c971 100644 --- a/proton-bridge/src/auth.rs +++ b/proton-bridge/src/auth.rs @@ -3,7 +3,7 @@ use serde::{Deserialize, Serialize}; use std::fs; use std::io::{self, Write}; use std::time::{SystemTime, UNIX_EPOCH}; - +use tracing::{error, info, warn}; use crate::config::ProtonConfig; use crate::srp; @@ -173,25 +173,25 @@ pub fn build_client() -> Result { pub async fn authenticate(client: &Client, config: &ProtonConfig) -> Result { if let Some(session) = Session::load() { if !session.has_locked_scope() { - println!("Cached session missing 'locked' scope — re-authenticating…"); + error!("Cached session missing 'locked' scope — re-authenticating…"); } else if !session.is_expired() { - println!("Using cached session for {}", config.username); + info!("Using cached session for {}", config.username); return Ok(session); } else { - println!("Access token expired, refreshing…"); + info!("Access token expired, refreshing…"); match refresh(client, &session).await { Ok(refreshed) => { // Refreshed tokens don't carry the locked scope; save the // new tokens but only use this session if it has the scope. if refreshed.has_locked_scope() { refreshed.save()?; - println!("Session refreshed for {}", config.username); + info!("Session refreshed for {}", config.username); return Ok(refreshed); } - println!("Refreshed token lacks 'locked' scope — falling back to full login"); + warn!("Refreshed token lacks 'locked' scope — falling back to full login"); } Err(e) => { - println!("Refresh failed ({}), falling back to full login", e); + error!("Refresh failed ({}), falling back to full login", e); } } } @@ -294,18 +294,18 @@ async fn login(client: &Client, config: &ProtonConfig) -> Result Result<(), String> { - print!("TOTP code: "); + info!("TOTP code: "); io::stdout().flush().unwrap(); let mut code = String::new(); io::stdin().read_line(&mut code).map_err(|e| e.to_string())?; diff --git a/proton-bridge/src/crypto.rs b/proton-bridge/src/crypto.rs index dedd64b..5c4cc35 100644 --- a/proton-bridge/src/crypto.rs +++ b/proton-bridge/src/crypto.rs @@ -25,7 +25,7 @@ use pgp::packet::{SignatureConfig, SignatureType, Subpacket, SubpacketData, SymE use pgp::ser::Serialize; use pgp::types::{KeyVersion, PublicKeyTrait}; use pgp::{Deserializable, Message, SignedPublicKey, SignedSecretKey}; - +use tracing::{error, info, warn}; use crate::srp::bcrypt_base64_encode; // ── Key passphrase derivation ───────────────────────────────────────────────── @@ -111,7 +111,7 @@ pub fn derive_key_passphrase_js(password: &str, key_salt_b64: &str) -> Result()); let parts = bcrypt::hash_with_salt(password, 10, salt) @@ -202,7 +202,7 @@ impl PrivateKey { /// Print the key IDs of every key in the pool for diagnostics. pub fn dump_key_pool(pool: &[PrivateKey]) { for (i, k) in pool.iter().enumerate() { - eprintln!(" [pool] key[{i}]: {:?} (pp: ...{})", + info!(" [pool] key[{i}]: {:?} (pp: ...{})", k.key_ids(), k.passphrase_suffix()); } } @@ -213,16 +213,16 @@ pub fn log_public_key_ids(pub_key_armored: &str, label: &str) { let Ok((pk, _)) = SignedPublicKey::from_armor_single(Cursor::new(pub_key_armored.as_bytes())) else { - eprintln!(" [key-ids] {label}: failed to parse public key"); + error!(" [key-ids] {label}: failed to parse public key"); return; }; - eprintln!( + info!( " [key-ids] {label} primary: id={:?} algo={:?}", pk.key_id(), pk.algorithm() ); for (i, sk) in pk.public_subkeys.iter().enumerate() { - eprintln!( + info!( " [key-ids] {label} subkey[{i}]: id={:?} algo={:?}", sk.key_id(), sk.algorithm() @@ -233,7 +233,7 @@ pub fn log_public_key_ids(pub_key_armored: &str, label: &str) { /// Print the PKESK recipient key IDs of a PGP-armored message. pub fn dump_message_pkesk(armored: &str) { let Ok((msg, _)) = Message::from_armor_single(Cursor::new(armored.as_bytes())) else { - eprintln!(" [body-diag] failed to parse message armor"); + warn!(" [body-diag] failed to parse message armor"); return; }; if let pgp::Message::Encrypted { esk, .. } = &msg { @@ -241,11 +241,11 @@ pub fn dump_message_pkesk(armored: &str) { if let pgp::composed::message::Esk::PublicKeyEncryptedSessionKey(pkesk) = e { let kid = pkesk.id().map(|k| format!("{k:?}")).unwrap_or("(anon)".into()); let ver = pkesk.version(); - eprintln!(" [body-diag] PKESK version={ver:?} recipient={kid}"); + info!(" [body-diag] PKESK version={ver:?} recipient={kid}"); } } } else { - eprintln!(" [body-diag] message is not Encrypted variant"); + error!(" [body-diag] message is not Encrypted variant"); } } @@ -261,11 +261,11 @@ pub fn decrypt_token(encrypted_token: &str, user_key: &PrivateKey) -> Result Result eprintln!(" [diag] subkey is unencrypted"), SecretParams::Encrypted(enc) => { @@ -357,12 +357,12 @@ pub fn diagnose_subkey_passphrase(key: &PrivateKey, candidates: &[(&str, &str)]) if let S2kParams::Cfb { sym_alg, s2k, iv } = s2k_params { let key_size = sym_alg.key_size(); - eprintln!( + info!( " [diag] enc_data ({} bytes): {}", enc_data.len(), enc_data.iter().map(|b| format!("{b:02x}")).collect::() ); - eprintln!( + info!( " [diag] iv: {}", iv.iter().map(|b| format!("{b:02x}")).collect::() ); @@ -383,7 +383,7 @@ pub fn diagnose_subkey_passphrase(key: &PrivateKey, candidates: &[(&str, &str)]) (ok, preview, k4) } Err(e) => { - eprintln!(" [diag] {label} → S2K error: {e}"); + info!(" [diag] {label} → S2K error: {e}"); continue; } }; @@ -405,22 +405,22 @@ pub fn diagnose_subkey_passphrase(key: &PrivateKey, candidates: &[(&str, &str)]) let keys_agree = rpgp_key4 == k4_dec; let sha1_str = if rpgp_ok { "OK ✓" } else { "FAIL" }; - eprintln!( + info!( " [diag] {label} → SHA-1 {sha1_str} (pt:{rpgp_preview}) \ rpgp={rpgp_key4} man65k={k4_dec}(ok:{ok_dec}) \ man96={k4_raw}(ok:{ok_raw}) agree:{keys_agree}" ); if rpgp_ok || ok_dec || ok_raw { - eprintln!(" [diag] *** CORRECT PASSPHRASE: {label} ***"); + info!(" [diag] *** CORRECT PASSPHRASE: {label} ***"); } } else { let sha1_str = if rpgp_ok { "OK ✓" } else { "FAIL" }; - eprintln!(" [diag] {label} → SHA-1 {sha1_str} (pt:{rpgp_preview})"); - if rpgp_ok { eprintln!(" [diag] *** CORRECT PASSPHRASE: {label} ***"); } + info!(" [diag] {label} → SHA-1 {sha1_str} (pt:{rpgp_preview})"); + if rpgp_ok { info!(" [diag] *** CORRECT PASSPHRASE: {label} ***"); } } } } else { - eprintln!(" [diag] non-CFB S2K params: {s2k_params:?}"); + info!(" [diag] non-CFB S2K params: {s2k_params:?}"); } } } @@ -607,7 +607,7 @@ pub fn encrypt_sign_body_for_external_send( .to_writer(&mut seipd_bytes) .map_err(|e| format!("serialize seipd: {e}"))?; - eprintln!( + info!( " [send] signed+encrypted SEIPD: {} bytes, session_key {} bytes", seipd_bytes.len(), session_key.len() @@ -717,7 +717,7 @@ pub fn build_pgp_mime_for_external_send( .to_writer(&mut seipd_bytes) .map_err(|e| format!("serialize seipd: {e}"))?; - eprintln!( + info!( " [send] PGP/MIME SEIPD: {} bytes, session_key {} bytes, boundary={boundary}", seipd_bytes.len(), session_key.len() @@ -747,7 +747,7 @@ pub fn decrypt_body(encrypted_body: &str, keys: &[&PrivateKey]) -> Result Result<(), Box> { let listener = TcpListener::bind(format!("0.0.0.0:{port}")).await?; - println!("IMAP listening on port {port}"); + info!("IMAP listening on port {port}"); run_with_listener(state, listener).await } @@ -30,7 +30,7 @@ pub async fn run_with_listener( let state = Arc::clone(&state); tokio::spawn(async move { if let Err(e) = handle_connection(socket, state).await { - eprintln!("IMAP connection error: {e}"); + error!("IMAP connection error: {e}"); } }); } @@ -66,9 +66,9 @@ async fn handle_connection( let response = dispatch(&tag, &cmd, &rest, &state, &mut authenticated).await; - // for log_line in response.lines() { - // eprintln!("IMAP > {log_line}"); - // } + for log_line in response.lines() { + debug!("IMAP > {log_line}"); + } writer.write_all(response.as_bytes()).await?; if logout { break; @@ -135,7 +135,7 @@ async fn cmd_select(tag: &str, state: &SharedState) -> String { let messages = match api.list_messages(LABEL_INBOX, 0, 50).await { Ok((msgs, _)) => msgs, Err(e) => { - eprintln!("SELECT list_messages failed: {e}"); + warn!("SELECT list_messages failed: {e}"); return format!("{tag} NO SELECT failed\r\n"); } }; @@ -246,7 +246,7 @@ async fn fetch_body(tag: &str, seq_set: &str, state: &SharedState) -> String { let full_msg = match api.get_message(&proton_id).await { Ok(m) => m, Err(e) => { - eprintln!("FETCH get_message failed: {e}"); + error!("FETCH get_message failed: {e}"); return format!("{tag} NO fetch failed\r\n"); } }; @@ -258,7 +258,7 @@ async fn fetch_body(tag: &str, seq_set: &str, state: &SharedState) -> String { match crypto::decrypt_body(&full_msg.body, &keys) { Ok(p) => p, Err(e) => { - eprintln!("FETCH decrypt_body failed: {e}"); + error!("FETCH decrypt_body failed: {e}"); return format!("{tag} NO decrypt failed\r\n"); } } @@ -340,7 +340,7 @@ async fn cmd_expunge(tag: &str, state: &SharedState) -> String { if !proton_ids.is_empty() { let api = ApiClient::new(&http_client, &session); if let Err(e) = api.delete_messages(&proton_ids).await { - eprintln!("EXPUNGE delete_messages failed: {e}"); + error!("EXPUNGE delete_messages failed: {e}"); } } diff --git a/proton-bridge/src/lib.rs b/proton-bridge/src/lib.rs index d0b5960..03e52e6 100644 --- a/proton-bridge/src/lib.rs +++ b/proton-bridge/src/lib.rs @@ -14,7 +14,7 @@ use api::{ApiClient, LABEL_INBOX}; use store::MessageStore; use tokio::net::TcpListener; use tokio::sync::Mutex; - +use tracing::{error, info}; // ── Shared bridge state ─────────────────────────────────────────────────────── /// State shared between the IMAP and SMTP server tasks. @@ -71,13 +71,13 @@ async fn run(config: config::Config) -> Result<(), String> { let session = auth::authenticate(&client, &config.proton) .await .map_err(|e| format!("Authentication failed: {e}"))?; - eprintln!("Authenticated as {}", config.proton.username); + info!("Authenticated as {}", config.proton.username); let api = ApiClient::new(&client, &session); let (key_pool, sender_addresses, own_public_keys, sender_key_indices) = unlock_key_pool(&api, &config).await?; - eprintln!("{} key(s) in pool", key_pool.len()); + info!("{} key(s) in pool", key_pool.len()); crypto::dump_key_pool(&key_pool); let (messages, total) = api @@ -86,7 +86,7 @@ async fn run(config: config::Config) -> Result<(), String> { .map_err(|e| format!("list_messages: {e}"))?; let mut store = MessageStore::new(); store.load_all(messages); - eprintln!("Inbox: {} messages ({total} total)", store.count()); + info!("Inbox: {} messages ({total} total)", store.count()); // Bind ports before spawning tasks — ports are occupied when start() returns. let imap_listener = TcpListener::bind(("127.0.0.1", config.bridge.imap_port)) @@ -115,7 +115,7 @@ async fn run(config: config::Config) -> Result<(), String> { }); tokio::spawn(async move { if let Err(e) = smtp_server::run_with_listener(state, smtp_listener).await { - eprintln!("SMTP server error: {e}"); + error!("SMTP server error: {e}"); } }); @@ -189,10 +189,10 @@ async fn unlock_key_pool( .unwrap_or_else(|_| password.to_string()); match crypto::PrivateKey::unlock(&uk.private_key, &pp) { Ok(k) => { - println!("user key {} unlocked", &uk.id[..8.min(uk.id.len())]); + info!("user key {} unlocked", &uk.id[..8.min(uk.id.len())]); user_private_keys.push(k); } - Err(e) => eprintln!("user key {} FAILED: {e}", &uk.id[..8.min(uk.id.len())]), + Err(e) => error!("user key {} FAILED: {e}", &uk.id[..8.min(uk.id.len())]), } } @@ -219,7 +219,7 @@ async fn unlock_key_pool( }; match crypto::PrivateKey::unlock(&ak.private_key, &pp) { Ok(k) => { - println!( + info!( "address key {} ({}) unlocked primary={}", &ak.id[..8.min(ak.id.len())], addr.email, @@ -228,20 +228,20 @@ async fn unlock_key_pool( if !first_active_key_done { match k.public_key_armored() { Ok(pk) => { - eprintln!( + info!( " [own-key] {} → first-active key primary={}", addr.email, ak.primary ); own_public_keys.insert(addr.email.clone(), pk); sender_key_indices.insert(addr.email.clone(), key_pool.len()); } - Err(e) => eprintln!("extract pub key for {}: {e}", addr.email), + Err(e) => info!("extract pub key for {}: {e}", addr.email), } first_active_key_done = true; } key_pool.push(k); } - Err(e) => eprintln!( + Err(e) => error!( "address key {} ({}): {e}", &ak.id[..8.min(ak.id.len())], addr.email @@ -257,6 +257,6 @@ async fn unlock_key_pool( .map(|a| (a.id.clone(), a.email.clone())) .collect(); - println!("{} own public key(s) from address keys", own_public_keys.len()); + info!("{} own public key(s) from address keys", own_public_keys.len()); Ok((key_pool, sender_addresses, own_public_keys, sender_key_indices)) } diff --git a/proton-bridge/src/main.rs b/proton-bridge/src/main.rs index e6d8604..b23776f 100644 --- a/proton-bridge/src/main.rs +++ b/proton-bridge/src/main.rs @@ -1,4 +1,5 @@ use std::fs; +use tracing::info; fn main() { env_logger::init(); @@ -15,12 +16,12 @@ fn main() { let imap_port = config.bridge.imap_port; let smtp_port = config.bridge.smtp_port; - eprint!("Starting ProtonMail bridge..."); + info!("Starting ProtonMail bridge..."); proton_bridge::start(config).unwrap_or_else(|e| { eprintln!("\nBridge failed to start: {e}"); std::process::exit(1); }); - eprintln!(" ready. IMAP :{imap_port} SMTP :{smtp_port} (Ctrl-C to stop)"); + info!(" ready. IMAP :{imap_port} SMTP :{smtp_port} (Ctrl-C to stop)"); // Block until Ctrl-C (the servers run in a background thread). let rt = tokio::runtime::Builder::new_current_thread() @@ -28,5 +29,5 @@ fn main() { .build() .expect("tokio runtime"); rt.block_on(tokio::signal::ctrl_c()).ok(); - println!("Shutting down."); + info!("Shutting down."); } diff --git a/proton-bridge/src/smtp_server.rs b/proton-bridge/src/smtp_server.rs index 50f45c9..2077a7e 100644 --- a/proton-bridge/src/smtp_server.rs +++ b/proton-bridge/src/smtp_server.rs @@ -9,7 +9,7 @@ use base64::engine::general_purpose::STANDARD as B64; use base64::Engine; use tokio::io::{AsyncBufReadExt, AsyncWriteExt, BufReader}; use tokio::net::{TcpListener, TcpStream}; - +use tracing::{error, info}; use crate::api::ApiClient; use crate::{crypto, SharedState}; @@ -17,7 +17,7 @@ use crate::{crypto, SharedState}; pub async fn run(state: SharedState, port: u16) -> Result<(), Box> { let listener = TcpListener::bind(format!("0.0.0.0:{port}")).await?; - println!("SMTP listening on port {port}"); + info!("SMTP listening on port {port}"); run_with_listener(state, listener).await } @@ -32,7 +32,7 @@ pub async fn run_with_listener( let state = Arc::clone(&state); tokio::spawn(async move { if let Err(e) = handle_connection(socket, state).await { - eprintln!("SMTP connection error: {e}"); + error!("SMTP connection error: {e}"); } }); }