more call sites

15 minute timeout was used because it applied to the whole send()
operation. Now timeout applies to each I/O operation, such as read()
or write(), so it can be made much shorter. In particular, this timeout
applies to read() call right after connection to plain or STARTTLS server,
in which case it is not reasonable to wait 15 minutes to receive one
line of data.

The timeout is triggered only if no progress is made within 30 seconds. It
likely indicates a network failure anyway.

CHANGELOG.md

@@ -1,5 +1,11 @@
 # Changelog 
 
+## 1.0.0-beta.19
+
+- #1058 timeout smtp-send if it doesn't complete in 15 minutes 
+
+- #1059 trim down logging
+
 ## 1.0.0-beta.18
 
 - #1056 avoid panicking when we couldn't read imap-server's greeting

Cargo.lock

@@ -124,7 +124,7 @@ dependencies = [
 [[package]]
 name = "async-smtp"
 version = "0.1.0"
-source = "git+https://github.com/async-email/async-smtp#c26ce542e847c502654c471ebc50d6c996f86cee"
+source = "git+https://github.com/async-email/async-smtp#6a4830032953f06020edc09db8daa06193e2b93f"
 dependencies = [
  "async-native-tls 0.1.1 (registry+https://github.com/rust-lang/crates.io-index)",
  "async-std 1.2.0 (registry+https://github.com/rust-lang/crates.io-index)",
@@ -657,7 +657,7 @@ dependencies = [
 
 [[package]]
 name = "deltachat"
-version = "1.0.0-beta.18"
+version = "1.0.0-beta.19"
 dependencies = [
  "async-imap 0.1.1 (git+https://github.com/async-email/async-imap?branch=dcc-stable)",
  "async-native-tls 0.1.1 (registry+https://github.com/rust-lang/crates.io-index)",
@@ -734,9 +734,9 @@ dependencies = [
 
 [[package]]
 name = "deltachat_ffi"
-version = "1.0.0-beta.18"
+version = "1.0.0-beta.19"
 dependencies = [
- "deltachat 1.0.0-beta.18",
+ "deltachat 1.0.0-beta.19",
  "deltachat-provider-database 0.2.1 (registry+https://github.com/rust-lang/crates.io-index)",
  "failure 0.1.6 (registry+https://github.com/rust-lang/crates.io-index)",
  "human-panic 1.0.1 (registry+https://github.com/rust-lang/crates.io-index)",

Cargo.toml

@@ -1,6 +1,6 @@
 [package]
 name = "deltachat"
-version = "1.0.0-beta.18"
+version = "1.0.0-beta.19"
 authors = ["Delta Chat Developers (ML) <delta@codespeak.net>"]
 edition = "2018"
 license = "MPL"
@@ -17,7 +17,7 @@ smallvec = "1.0.0"
 reqwest = { version = "0.9.15" }
 num-derive = "0.3.0"
 num-traits = "0.2.6"
-async-smtp = { git = "https://github.com/async-email/async-smtp", branch = "master" }
+async-smtp = { git = "https://github.com/async-email/async-smtp" }
 email = { git = "https://github.com/deltachat/rust-email", branch = "master" }
 lettre_email = { git = "https://github.com/deltachat/lettre", branch = "native_tls" }
 

deltachat-ffi/Cargo.toml

@@ -1,6 +1,6 @@
 [package]
 name = "deltachat_ffi"
-version = "1.0.0-beta.18"
+version = "1.0.0-beta.19"
 description = "Deltachat FFI"
 authors = ["Delta Chat Developers (ML) <delta@codespeak.net>"]
 edition = "2018"

deltachat-ffi/src/lib.rs

@@ -509,7 +509,7 @@ pub unsafe extern "C" fn dc_interrupt_imap_idle(context: *mut dc_context_t) {
     }
     let ffi_context = &*context;
     ffi_context
-        .with_inner(|ctx| job::interrupt_inbox_idle(ctx, true))
+        .with_inner(|ctx| job::interrupt_inbox_idle(ctx))
         .unwrap_or(())
 }
 

examples/repl/cmdline.rs

@@ -491,7 +491,7 @@ pub fn dc_cmdline(context: &Context, line: &str) -> Result<(), failure::Error> {
             println!("{:#?}", context.get_info());
         }
         "interrupt" => {
-            interrupt_inbox_idle(context, true);
+            interrupt_inbox_idle(context);
         }
         "maybenetwork" => {
             maybe_network(context);

examples/repl/main.rs

@@ -202,7 +202,7 @@ fn stop_threads(context: &Context) {
         println!("Stopping threads");
         IS_RUNNING.store(false, Ordering::Relaxed);
 
-        interrupt_inbox_idle(context, true);
+        interrupt_inbox_idle(context);
         interrupt_mvbox_idle(context);
         interrupt_sentbox_idle(context);
         interrupt_smtp_idle(context);

examples/simple.rs

@@ -104,7 +104,7 @@ fn main() {
     println!("stopping threads");
 
     *running.write().unwrap() = false;
-    deltachat::job::interrupt_inbox_idle(&ctx, true);
+    deltachat::job::interrupt_inbox_idle(&ctx);
     deltachat::job::interrupt_smtp_idle(&ctx);
 
     println!("joining");

src/config.rs

@@ -144,7 +144,7 @@ impl Context {
             }
             Config::InboxWatch => {
                 let ret = self.sql.set_raw_config(self, key, value);
-                interrupt_inbox_idle(self, true);
+                interrupt_inbox_idle(self);
                 ret
             }
             Config::SentboxWatch => {

src/constants.rs

@@ -114,7 +114,7 @@ pub const DC_MSG_ID_LAST_SPECIAL: u32 = 9;
 /// approx. max. length returned by dc_msg_get_text()
 const DC_MAX_GET_TEXT_LEN: usize = 30000;
 /// approx. max. length returned by dc_get_msg_info()
-const DC_MAX_GET_INFO_LEN: usize = 100000;
+const DC_MAX_GET_INFO_LEN: usize = 100_000;
 
 pub const DC_CONTACT_ID_UNDEFINED: u32 = 0;
 pub const DC_CONTACT_ID_SELF: u32 = 1;

src/contact.rs

@@ -100,11 +100,11 @@ pub enum Origin {
     /// address is in our address book
     AdressBook = 0x80000,
     /// set on Alice's side for contacts like Bob that have scanned the QR code offered by her. Only means the contact has once been established using the "securejoin" procedure in the past, getting the current key verification status requires calling dc_contact_is_verified() !
-    SecurejoinInvited = 0x1000000,
+    SecurejoinInvited = 0x0100_0000,
     /// set on Bob's side for contacts scanned and verified from a QR code. Only means the contact has once been established using the "securejoin" procedure in the past, getting the current key verification status requires calling dc_contact_is_verified() !
-    SecurejoinJoined = 0x2000000,
+    SecurejoinJoined = 0x0200_0000,
     /// contact added mannually by dc_create_contact(), this should be the largets origin as otherwise the user cannot modify the names
-    ManuallyCreated = 0x4000000,
+    ManuallyCreated = 0x0400_0000,
 }
 
 impl Default for Origin {

src/dc_receive_imf.rs

@@ -1546,10 +1546,6 @@ fn dc_add_or_lookup_contacts_by_address_list(
         }
     };
 
-    info!(
-        context,
-        "dc_add_or_lookup_contacts_by_address raw={:?} addrs={:?}", addr_list_raw, addrs
-    );
     for addr in addrs.iter() {
         match addr {
             mailparse::MailAddr::Single(info) => {
@@ -1591,10 +1587,6 @@ fn add_or_lookup_contact_by_addr(
         .map(normalize_name)
         .unwrap_or_default();
 
-    info!(
-        context,
-        "looking up addr={:?} display_name={:?}", addr, display_name_normalized
-    );
     let (row_id, _modified) =
         Contact::add_or_lookup(context, display_name_normalized, addr, origin)?;
     ensure!(row_id > 0, "could not add contact: {:?}", addr);

src/dc_tools.rs

@@ -49,8 +49,8 @@ pub(crate) fn dc_truncate(buf: &str, approx_chars: usize, do_unwrap: bool) -> Co
 /// - harmonize together while being different enough
 /// (therefore, we cannot just use random rgb colors :)
 const COLORS: [u32; 16] = [
-    0xe56555, 0xf28c48, 0x8e85ee, 0x76c84d, 0x5bb6cc, 0x549cdd, 0xd25c99, 0xb37800, 0xf23030,
-    0x39b249, 0xbb243b, 0x964078, 0x66874f, 0x308ab9, 0x127ed0, 0xbe450c,
+    0xe5_65_55, 0xf2_8c_48, 0x8e_85_ee, 0x76_c8_4d, 0x5b_b6_cc, 0x54_9c_dd, 0xd2_5c_99, 0xb3_78_00,
+    0xf2_30_30, 0x39_b2_49, 0xbb_24_3b, 0x96_40_78, 0x66_87_4f, 0x30_8a_b9, 0x12_7e_d0, 0xbe_45_0c,
 ];
 
 pub(crate) fn dc_str_to_color(s: impl AsRef<str>) -> u32 {
@@ -59,7 +59,7 @@ pub(crate) fn dc_str_to_color(s: impl AsRef<str>) -> u32 {
     let bytes = str_lower.as_bytes();
     for (i, byte) in bytes.iter().enumerate() {
         checksum += (i + 1) * *byte as usize;
-        checksum %= 0xffffff;
+        checksum %= 0x00ff_ffff;
     }
     let color_index = checksum % COLORS.len();
 

src/dehtml.rs

@@ -139,13 +139,12 @@ fn dehtml_starttag_cb<B: std::io::BufRead>(
             dehtml.add_text = AddText::YesPreserveLineEnds;
         }
         "a" => {
-            if let Some(href) = event.html_attributes().find(|attr| {
-                attr.as_ref()
-                    .map(|a| String::from_utf8_lossy(a.key).trim().to_lowercase() == "href")
-                    .unwrap_or_default()
-            }) {
+            if let Some(href) = event
+                .html_attributes()
+                .filter_map(|attr| attr.ok())
+                .find(|attr| String::from_utf8_lossy(attr.key).trim().to_lowercase() == "href")
+            {
                 let href = href
-                    .unwrap()
                     .unescape_and_decode_value(reader)
                     .unwrap_or_default()
                     .to_lowercase();

src/job.rs

@@ -480,19 +480,19 @@ pub fn perform_sentbox_idle(context: &Context) {
         .idle(context, use_network);
 }
 
-pub fn interrupt_inbox_idle(context: &Context, block: bool) {
-    info!(context, "interrupt_inbox_idle called blocking={}", block);
-    if block {
-        context.inbox_thread.read().unwrap().interrupt_idle(context);
-    } else {
-        match context.inbox_thread.try_read() {
-            Ok(inbox_thread) => {
-                inbox_thread.interrupt_idle(context);
-            }
-            Err(err) => {
-                *context.perform_inbox_jobs_needed.write().unwrap() = true;
-                warn!(context, "could not interrupt idle: {}", err);
-            }
+pub fn interrupt_inbox_idle(context: &Context) {
+    info!(context, "interrupt_inbox_idle called");
+    // we do not block on trying to obtain the thread lock
+    // because we don't know in which state the thread is.
+    // If it's currently fetching then we can not get the lock
+    // but we flag it for checking jobs so that idle will be skipped.
+    match context.inbox_thread.try_read() {
+        Ok(inbox_thread) => {
+            inbox_thread.interrupt_idle(context);
+        }
+        Err(err) => {
+            *context.perform_inbox_jobs_needed.write().unwrap() = true;
+            warn!(context, "could not interrupt idle: {}", err);
         }
     }
 }
@@ -604,7 +604,7 @@ pub fn maybe_network(context: &Context) {
     }
 
     interrupt_smtp_idle(context);
-    interrupt_inbox_idle(context, true);
+    interrupt_inbox_idle(context);
     interrupt_mvbox_idle(context);
     interrupt_sentbox_idle(context);
 }
@@ -972,7 +972,7 @@ pub fn job_add(
     ).ok();
 
     match thread {
-        Thread::Imap => interrupt_inbox_idle(context, false),
+        Thread::Imap => interrupt_inbox_idle(context),
         Thread::Smtp => interrupt_smtp_idle(context),
         Thread::Unknown => {}
     }

src/lib.rs

@@ -1,7 +1,7 @@
 #![deny(clippy::correctness, missing_debug_implementations, clippy::all)]
 // for now we hide warnings to not clutter/hide errors during "cargo clippy"
 #![allow(clippy::cognitive_complexity, clippy::too_many_arguments)]
-#![allow(clippy::unreadable_literal, clippy::match_bool)]
+#![allow(clippy::match_bool)]
 #![feature(ptr_wrapping_offset_from)]
 #![feature(drain_filter)]
 

src/log.rs

@@ -8,9 +8,8 @@ macro_rules! info {
     ($ctx:expr, $msg:expr, $($args:expr),* $(,)?) => {{
         let formatted = format!($msg, $($args),*);
         let thread = ::std::thread::current();
-        let full = format!("{thid:?}/{thname} {file}:{line}: {msg}",
+        let full = format!("{thid:?} {file}:{line}: {msg}",
                            thid = thread.id(),
-                           thname = thread.name().unwrap_or("unnamed"),
                            file = file!(),
                            line = line!(),
                            msg = &formatted);
@@ -26,9 +25,8 @@ macro_rules! warn {
     ($ctx:expr, $msg:expr, $($args:expr),* $(,)?) => {{
         let formatted = format!($msg, $($args),*);
         let thread = ::std::thread::current();
-        let full = format!("{thid:?}/{thname} {file}:{line}: {msg}",
+        let full = format!("{thid:?} {file}:{line}: {msg}",
                            thid = thread.id(),
-                           thname = thread.name().unwrap_or("unnamed"),
                            file = file!(),
                            line = line!(),
                            msg = &formatted);

src/message.rs

@@ -720,7 +720,7 @@ pub fn get_msg_info(context: &Context, msg_id: MsgId) -> String {
         return ret;
     }
     let rawtxt = rawtxt.unwrap_or_default();
-    let rawtxt = dc_truncate(rawtxt.trim(), 100000, false);
+    let rawtxt = dc_truncate(rawtxt.trim(), 100_000, false);
 
     let fts = dc_timestamp_to_str(msg.get_timestamp());
     ret += &format!("Sent: {}", fts);

src/smtp/mod.rs

@@ -2,17 +2,20 @@
 
 pub mod send;
 
+use std::time::Duration;
+
 use async_smtp::smtp::client::net::*;
 use async_smtp::*;
 
-use async_std::task;
-
 use crate::constants::*;
 use crate::context::Context;
 use crate::events::Event;
 use crate::login_param::{dc_build_tls, LoginParam};
 use crate::oauth2::*;
 
+/// SMTP write and read timeout in seconds.
+const SMTP_TIMEOUT: u64 = 30;
+
 #[derive(Debug, Fail)]
 pub enum Error {
     #[fail(display = "Bad parameters")]
@@ -21,12 +24,12 @@ pub enum Error {
     InvalidLoginAddress {
         address: String,
         #[cause]
-        error: async_smtp::error::Error,
+        error: error::Error,
     },
     #[fail(display = "SMTP failed to connect: {:?}", _0)]
-    ConnectionFailure(#[cause] async_smtp::smtp::error::Error),
+    ConnectionFailure(#[cause] smtp::error::Error),
     #[fail(display = "SMTP: failed to setup connection {:?}", _0)]
-    ConnectionSetupFailure(#[cause] async_smtp::smtp::error::Error),
+    ConnectionSetupFailure(#[cause] smtp::error::Error),
     #[fail(display = "SMTP: oauth2 error {:?}", _0)]
     Oauth2Error { address: String },
     #[fail(display = "TLS error")]
@@ -44,7 +47,7 @@ pub type Result<T> = std::result::Result<T, Error>;
 #[derive(Default, DebugStub)]
 pub struct Smtp {
     #[debug_stub(some = "SmtpTransport")]
-    transport: Option<async_smtp::smtp::SmtpTransport>,
+    transport: Option<smtp::SmtpTransport>,
     /// Email address we are sending from.
     from: Option<EmailAddress>,
 }
@@ -57,18 +60,25 @@ impl Smtp {
 
     /// Disconnect the SMTP transport and drop it entirely.
     pub fn disconnect(&mut self) {
-        if let Some(ref mut transport) = self.transport.take() {
-            transport.close();
+        if let Some(mut transport) = self.transport.take() {
+            async_std::task::block_on(transport.close()).ok();
         }
     }
 
-    /// check whether we are connected
+    /// Check whether we are connected.
     pub fn is_connected(&self) -> bool {
-        self.transport.is_some()
+        self.transport
+            .as_ref()
+            .map(|t| t.is_connected())
+            .unwrap_or_default()
     }
 
-    /// Connect using the provided login params
+    /// Connect using the provided login params.
     pub fn connect(&mut self, context: &Context, lp: &LoginParam) -> Result<()> {
+        async_std::task::block_on(self.inner_connect(context, lp))
+    }
+
+    async fn inner_connect(&mut self, context: &Context, lp: &LoginParam) -> Result<()> {
         if self.is_connected() {
             warn!(context, "SMTP already connected.");
             return Ok(());
@@ -104,21 +114,21 @@ impl Smtp {
             }
             let user = &lp.send_user;
             (
-                async_smtp::smtp::authentication::Credentials::new(
+                smtp::authentication::Credentials::new(
                     user.to_string(),
                     access_token.unwrap_or_default(),
                 ),
-                vec![async_smtp::smtp::authentication::Mechanism::Xoauth2],
+                vec![smtp::authentication::Mechanism::Xoauth2],
             )
         } else {
             // plain
             let user = lp.send_user.clone();
             let pw = lp.send_pw.clone();
             (
-                async_smtp::smtp::authentication::Credentials::new(user, pw),
+                smtp::authentication::Credentials::new(user, pw),
                 vec![
-                    async_smtp::smtp::authentication::Mechanism::Plain,
-                    async_smtp::smtp::authentication::Mechanism::Login,
+                    smtp::authentication::Mechanism::Plain,
+                    smtp::authentication::Mechanism::Login,
                 ],
             )
         };
@@ -126,30 +136,31 @@ impl Smtp {
         let security = if 0
             != lp.server_flags & (DC_LP_SMTP_SOCKET_STARTTLS | DC_LP_SMTP_SOCKET_PLAIN) as i32
         {
-            async_smtp::smtp::ClientSecurity::Opportunistic(tls_parameters)
+            smtp::ClientSecurity::Opportunistic(tls_parameters)
         } else {
-            async_smtp::smtp::ClientSecurity::Wrapper(tls_parameters)
+            smtp::ClientSecurity::Wrapper(tls_parameters)
         };
 
-        let client = task::block_on(async_smtp::smtp::SmtpClient::with_security(
-            (domain.as_str(), port),
-            security,
-        ))
-        .map_err(Error::ConnectionSetupFailure)?;
+        let client = smtp::SmtpClient::with_security((domain.as_str(), port), security)
+            .await
+            .map_err(Error::ConnectionSetupFailure)?;
 
         let client = client
             .smtp_utf8(true)
             .credentials(creds)
             .authentication_mechanism(mechanism)
-            .connection_reuse(async_smtp::smtp::ConnectionReuseParameters::ReuseUnlimited);
+            .connection_reuse(smtp::ConnectionReuseParameters::ReuseUnlimited)
+            .timeout(Some(Duration::from_secs(SMTP_TIMEOUT)));
+
         let mut trans = client.into_transport();
-        task::block_on(trans.connect()).map_err(Error::ConnectionFailure)?;
+        trans.connect().await.map_err(Error::ConnectionFailure)?;
 
         self.transport = Some(trans);
         context.call_cb(Event::SmtpConnected(format!(
             "SMTP-LOGIN as {} ok",
             lp.send_user,
         )));
+
         Ok(())
     }
 }

src/smtp/send.rs

@@ -1,16 +1,11 @@
 //! # SMTP message sending
 
-use std::time::Duration;
-
 use super::Smtp;
 use async_smtp::*;
 
 use crate::context::Context;
 use crate::events::Event;
 
-/// SMTP send times out after 15 minutes
-const SEND_TIMEOUT: u64 = 15 * 60;
-
 pub type Result<T> = std::result::Result<T, Error>;
 
 #[derive(Debug, Fail)]
@@ -56,18 +51,15 @@ impl Smtp {
             format!("{}", job_id), // only used for internal logging
             message,
         );
-        if let Some(ref mut transport) = self.transport {
-            let res =
-                async_std::future::timeout(Duration::from_secs(SEND_TIMEOUT), transport.send(mail))
-                    .await?
-                    .map_err(Error::SendError);
 
-            res.map(|_response| {
-                context.call_cb(Event::SmtpMessageSent(format!(
-                    "Message len={} was smtp-sent to {}",
-                    message_len, recipients_display
-                )));
-            })
+        if let Some(ref mut transport) = self.transport {
+            transport.send(mail).await.map_err(Error::SendError)?;
+
+            context.call_cb(Event::SmtpMessageSent(format!(
+                "Message len={} was smtp-sent to {}",
+                message_len, recipients_display
+            )));
+            Ok(())
         } else {
             warn!(
                 context,