replaced println's with tracing calls

This commit is contained in:
Shautvast 2026-02-25 09:04:11 +01:00
parent 2287b08cb5
commit a8ea1fb5bb
8 changed files with 66 additions and 63 deletions

1
Cargo.lock generated
View file

@ -2966,6 +2966,7 @@ dependencies = [
"sha2 0.10.9",
"tokio",
"toml",
"tracing",
]
[[package]]

View file

@ -21,3 +21,4 @@ env_logger = "0.11"
aes = "0.8"
cfb-mode = "0.8"
sha1 = "0.10"
tracing = "0.1.44"

View file

@ -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<Client, String> {
pub async fn authenticate(client: &Client, config: &ProtonConfig) -> Result<Session, String> {
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<Session, String
}
let has_full = auth.scope.split_whitespace().any(|s| s == "full");
println!("Auth scope tokens: {}", auth.scope);
info!("Auth scope tokens: {}", auth.scope);
if !has_full {
println!("Warning: token does not have 'full' scope — some endpoints may return 403.");
warn!("Token does not have 'full' scope — some endpoints may return 403.");
}
session.save()?;
println!("Authenticated as {}", config.username);
info!("Authenticated as {}", config.username);
Ok(session)
}
async fn submit_totp(client: &Client, session: &Session) -> 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())?;

View file

@ -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<St
i += 4;
}
eprintln!(" [bcrypt-js] effective salt bytes: {}",
info!(" [bcrypt-js] effective salt bytes: {}",
salt.iter().map(|b| format!("{b:02x}")).collect::<String>());
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<Str
.map_err(|e| format!("parse token: {e}"))?;
// Diagnostic: print key IDs, algorithms, and S2K params.
eprintln!(" [token diag] user primary key ID: {:?} algo={:?} sha1_cksum={}",
info!(" [token diag] user primary key ID: {:?} algo={:?} sha1_cksum={}",
user_key.inner.key_id(), user_key.inner.algorithm(),
user_key.inner.primary_key.has_sha1_checksum());
for sk in &user_key.inner.secret_subkeys {
eprintln!(" [token diag] user subkey ID: {:?} algo={:?} sha1_cksum={} s2k={:?}",
info!(" [token diag] user subkey ID: {:?} algo={:?} sha1_cksum={} s2k={:?}",
sk.key_id(), sk.algorithm(),
sk.key.has_sha1_checksum(),
sk.key.secret_params());
@ -276,7 +276,7 @@ pub fn decrypt_token(encrypted_token: &str, user_key: &PrivateKey) -> Result<Str
let kid = pkesk.id().map(|k| format!("{k:?}")).unwrap_or("(anon)".into());
let algo = pkesk.algorithm().map(|a| format!("{a:?}")).unwrap_or("?".into());
let ver = pkesk.version();
eprintln!(" [token diag] PKESK version={ver:?} algo={algo} recipient={kid}");
info!(" [token diag] PKESK version={ver:?} algo={algo} recipient={kid}");
}
}
}
@ -348,7 +348,7 @@ pub fn diagnose_subkey_passphrase(key: &PrivateKey, candidates: &[(&str, &str)])
}
for sk in &key.inner.secret_subkeys {
eprintln!(" [diag] subkey {:?}", sk.key_id());
info!(" [diag] subkey {:?}", sk.key_id());
match sk.key.secret_params() {
SecretParams::Plain(_) => 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::<String>()
);
eprintln!(
info!(
" [diag] iv: {}",
iv.iter().map(|b| format!("{b:02x}")).collect::<String>()
);
@ -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<String
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!(" [incoming-pkesk] version={ver:?} recipient={kid}");
info!(" [incoming-pkesk] version={ver:?} recipient={kid}");
}
}
}

View file

@ -7,7 +7,7 @@ use std::sync::Arc;
use tokio::io::{AsyncBufReadExt, AsyncWriteExt, BufReader};
use tokio::net::{TcpListener, TcpStream};
use tracing::{debug, error, info, warn};
use crate::api::{ApiClient, LABEL_INBOX};
use crate::{crypto, SharedState};
@ -15,7 +15,7 @@ use crate::{crypto, SharedState};
pub async fn run(state: SharedState, port: u16) -> Result<(), Box<dyn std::error::Error>> {
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}");
}
}

View file

@ -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))
}

View file

@ -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.");
}

View file

@ -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<dyn std::error::Error>> {
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}");
}
});
}