remove TODOs

Every `info!`, `warn!` and `error!` call expanded a complete
`tracing::event!` to mirror its message into `tracing` (#6919),
and that mirror made up most of core's macro output, now removed:
it's down from 219k to 54k lines using

    RUSTC_BOOTSTRAP=1 cargo rustc -p deltachat --lib \
        --profile check -- -Zmacro-stats

A warm build and `touch src/lib.rs` with rustc 1.99.0,

    CARGO_INCREMENTAL=0 RUSTC_WRAPPER= /usr/bin/time -v \
        cargo check -p deltachat

takes about a third less time and 0.37 GiB less peak memory,
`cargo build -p deltachat` about a tenth less time and 0.36 GiB less.
The release binary from `nix build .#deltachat-rpc-server-x86_64-linux`
gets 2.7% smaller.

If we want to use tracing events to integrate better with iroh-debugging,
for example when we move to iroh 1.X,
we could introduce some iroh-relevant tracing events in core.

.github/workflows/ci.yml

@@ -30,6 +30,9 @@ jobs:
     name: Lint Rust
     runs-on: ubuntu-latest
     timeout-minutes: 60
+    env:
+      # Tests always unwind: match it so dependencies are only checked once.
+      CARGO_PROFILE_DEV_PANIC: unwind
     steps:
       - uses: actions/checkout@v7
         with:
@@ -48,8 +51,6 @@ jobs:
         run: cargo fmt --all -- --check
       - name: Run clippy
         run: scripts/clippy.sh
-      - name: Check with all features
-        run: cargo check --workspace --all-targets --all-features
       - name: Check with only default features
         run: cargo check --all-targets
 
@@ -139,12 +140,12 @@ jobs:
       - name: Tests
         env:
           RUST_BACKTRACE: 1
-        run: cargo nextest run --workspace --locked
+        run: cargo nextest run --workspace --exclude deltachat-jsonrpc-bindings --locked
 
       - name: Doc-Tests
         env:
           RUST_BACKTRACE: 1
-        run: cargo test --workspace --locked --doc
+        run: cargo test --workspace --exclude deltachat-jsonrpc-bindings --locked --doc
 
       - name: Test cargo vendor
         run: cargo vendor

Cargo.lock

@@ -1406,7 +1406,6 @@ dependencies = [
  "tokio-stream",
  "tokio-util",
  "toml",
- "tracing",
  "url",
  "uuid",
  "walkdir",

Cargo.toml

@@ -104,7 +104,6 @@ astral-tokio-tar = { version = "0.7.0", default-features = false }
 tokio-util = { workspace = true }
 tokio = { workspace = true, features = ["fs", "rt-multi-thread", "macros"] }
 toml = "0.9"
-tracing = "0.1.41"
 url = "2"
 uuid = { version = "1", features = ["serde", "v4"] }
 walkdir = "2.5.0"

docs/schema.sql

@@ -456,6 +456,21 @@ CREATE TABLE smtp_status_updates (
     descr TEXT NOT NULL -- text to send along with the updates
 );
 
+-- Table to record the successful usage transports for sending.
+-- Sorting the table by rowid in descending order
+-- returns most recently successfully used transport first.
+CREATE TABLE smtp_success (
+    -- Sequentially increasing ID of the success.
+    -- Transport with the highest ID is to be used first.
+    id INTEGER PRIMARY KEY AUTOINCREMENT NOT NULL,
+
+    -- ID of the transport that was used to send a message.
+    transport_id INTEGER UNIQUE NOT NULL,
+
+    -- Delete `smtp_success` rows when the transport is deleted.
+    FOREIGN KEY(transport_id) REFERENCES transports(id) ON DELETE CASCADE
+) STRICT;
+
 -- Table of "sync items" to be grouped into sync messages
 -- and sent to own devices.
 CREATE TABLE multi_device_sync (

scripts/clippy.sh

@@ -6,4 +6,4 @@
 #
 # To automatically fix warnings, run
 #   scripts/clippy.sh --fix --allow-dirty
-cargo clippy --locked --workspace --all-targets --all-features "$@" -- -D warnings
+cargo clippy --locked --workspace --exclude deltachat-jsonrpc-bindings --all-targets --all-features "$@" -- -D warnings

src/accounts.rs

@@ -76,12 +76,8 @@ impl Accounts {
         Accounts::open(events, dir, writable).await
     }
 
-    /// Get the ID used to log events.
-    ///
-    /// Account manager logs events with ID 0
-    /// which is not used by any accounts.
-    fn get_id(&self) -> u32 {
-        0
+    fn log_info(&self, file: &str, line: u32, msg: String) {
+        self.emit_event(EventType::Info(format!("{file}:{line}: {msg}")));
     }
 
     /// Ensures the accounts directory and config file exist.
@@ -395,11 +391,6 @@ impl Accounts {
                 "Starting background fetch for {n_accounts} accounts."
             )),
         });
-        ::tracing::event!(
-            ::tracing::Level::INFO,
-            account_id = 0,
-            "Starting background fetch for {n_accounts} accounts."
-        );
         let mut set = JoinSet::new();
         for account in accounts {
             set.spawn(async move {
@@ -415,11 +406,6 @@ impl Accounts {
                 "Finished background fetch for {n_accounts} accounts."
             )),
         });
-        ::tracing::event!(
-            ::tracing::Level::INFO,
-            account_id = 0,
-            "Finished background fetch for {n_accounts} accounts."
-        );
     }
 
     /// Auxiliary function for [Accounts::background_fetch].
@@ -462,11 +448,6 @@ impl Accounts {
                 id: 0,
                 typ: EventType::Warning("Background fetch timed out.".to_string()),
             });
-            ::tracing::event!(
-                ::tracing::Level::WARN,
-                account_id = 0,
-                "Background fetch timed out."
-            );
         }
         events.emit(Event {
             id: 0,
@@ -549,7 +530,7 @@ impl Accounts {
         }
     }
 
-    /// Emits a single event.
+    /// Emits a single event with ID 0, which is not used by any accounts.
     pub fn emit_event(&self, event: EventType) {
         self.events.emit(Event { id: 0, typ: event })
     }

src/log.rs

@@ -3,6 +3,7 @@
 #![allow(missing_docs)]
 
 use crate::context::Context;
+use crate::events::EventType;
 
 mod stream;
 
@@ -12,15 +13,9 @@ macro_rules! info {
     ($ctx:expr,  $msg:expr) => {
         info!($ctx, $msg,)
     };
-    ($ctx:expr, $msg:expr, $($args:expr),* $(,)?) => {{
-        let formatted = format!($msg, $($args),*);
-        let full = format!("{file}:{line}: {msg}",
-                           file = file!(),
-                           line = line!(),
-                           msg = &formatted);
-        ::tracing::event!(::tracing::Level::INFO, account_id = $ctx.get_id(), "{}", &formatted);
-        $ctx.emit_event($crate::EventType::Info(full));
-    }};
+    ($ctx:expr, $msg:expr, $($args:expr),* $(,)?) => {
+        $ctx.log_info(file!(), line!(), format!($msg, $($args),*))
+    };
 }
 
 // Workaround for <https://github.com/rust-lang/rust/issues/133708>.
@@ -30,15 +25,9 @@ mod warn_macro_mod {
         ($ctx:expr, $msg:expr) => {
             warn_macro!($ctx, $msg,)
         };
-        ($ctx:expr, $msg:expr, $($args:expr),* $(,)?) => {{
-            let formatted = format!($msg, $($args),*);
-            let full = format!("{file}:{line}: {msg}",
-                               file = file!(),
-                               line = line!(),
-                               msg = &formatted);
-            ::tracing::event!(::tracing::Level::WARN, account_id = $ctx.get_id(), "{}", &formatted);
-            $ctx.emit_event($crate::EventType::Warning(full));
-        }};
+        ($ctx:expr, $msg:expr, $($args:expr),* $(,)?) => {
+            $ctx.log_warn(file!(), line!(), format!($msg, $($args),*))
+        };
     }
 
     pub(crate) use warn_macro;
@@ -50,15 +39,25 @@ macro_rules! error {
     ($ctx:expr, $msg:expr) => {
         error!($ctx, $msg,)
     };
-    ($ctx:expr, $msg:expr, $($args:expr),* $(,)?) => {{
-        let formatted = format!($msg, $($args),*);
-        ::tracing::event!(::tracing::Level::ERROR, account_id = $ctx.get_id(), "{}", &formatted);
-        $ctx.set_last_error(&formatted);
-        $ctx.emit_event($crate::EventType::Error(formatted));
-    }};
+    ($ctx:expr, $msg:expr, $($args:expr),* $(,)?) => {
+        $ctx.log_error(format!($msg, $($args),*))
+    };
 }
 
 impl Context {
+    pub(crate) fn log_info(&self, file: &str, line: u32, msg: String) {
+        self.emit_event(EventType::Info(format!("{file}:{line}: {msg}")));
+    }
+
+    pub(crate) fn log_warn(&self, file: &str, line: u32, msg: String) {
+        self.emit_event(EventType::Warning(format!("{file}:{line}: {msg}")));
+    }
+
+    pub(crate) fn log_error(&self, msg: String) {
+        self.set_last_error(&msg);
+        self.emit_event(EventType::Error(msg));
+    }
+
     /// Set last error string.
     /// Implemented as blocking as used from macros in different, not always async blocks.
     pub fn set_last_error(&self, error: &str) {
@@ -116,12 +115,6 @@ impl<T, E: std::fmt::Display> LogExt<T, E> for Result<T, E> {
             );
             // We can't use the warn!() macro here as the file!() and line!() macros
             // don't work with #[track_caller]
-            tracing::event!(
-                ::tracing::Level::WARN,
-                account_id = context.get_id(),
-                "{}",
-                &full
-            );
             context.emit_event(crate::EventType::Warning(full));
         };
         self

src/log/stream.rs

@@ -93,11 +93,6 @@ impl<S: SessionStream> AsyncRead for LoggingStream<S> {
                 "Read error on stream {peer_addr:?} after reading {} and writing {} bytes: {err}.",
                 this.metrics.total_read, this.metrics.total_written
             );
-            tracing::event!(
-                ::tracing::Level::WARN,
-                account_id = *this.account_id,
-                log_message
-            );
             this.events.emit(Event {
                 id: *this.account_id,
                 typ: EventType::Warning(log_message),

src/smtp.rs

@@ -54,6 +54,39 @@ pub(crate) struct Smtp {
     pub(crate) last_send_error: Option<String>,
 }
 
+/// Returns transports with their IDs in the order in which they should be tried.
+async fn sorted_transports(context: &Context) -> Result<Vec<(u32, ConfiguredLoginParam)>> {
+    context
+        .sql
+        .query_map_vec(
+            "SELECT transports.id, configured_param FROM transports
+             LEFT JOIN smtp_success ON smtp_success.transport_id=transports.id
+             ORDER BY IFNULL(smtp_success.id, 0) DESC, transports.id ASC",
+            (),
+            |row| {
+                let id: u32 = row.get(0)?;
+                let json: String = row.get(1)?;
+                let param = ConfiguredLoginParam::from_json(&json)?;
+                Ok((id, param))
+            },
+        )
+        .await
+}
+
+/// Records successful use of SMTP transport so it is tried first next time we connect to SMTP.
+async fn record_success(context: &Context, transport_id: u32) -> Result<()> {
+    // INSERT OR REPLACE essentially replaces rowid of the row
+    // if the row exists already, so it becomes the highest rowid in the table.
+    context
+        .sql
+        .execute(
+            "INSERT OR REPLACE INTO smtp_success (transport_id) VALUES (?)",
+            (transport_id,),
+        )
+        .await?;
+    Ok(())
+}
+
 impl Smtp {
     /// Create a new Smtp instances.
     pub fn new() -> Self {
@@ -101,13 +134,7 @@ impl Smtp {
 
         self.connectivity.set_connecting(context);
         let proxy_config = ProxyConfig::load(context).await?;
-        let transports = ConfiguredLoginParam::load_all(context).await?;
-
-        // Try to connect to the newest transport first. If sending is unreliable,
-        // user can configure a new transport and it will be the one used.
-        // Conversely, if user just added a new transport and sending got less reliable,
-        // user can restore old state by removing the just added transport.
-        for (transport_id, lp) in transports.into_iter().rev() {
+        for (transport_id, lp) in sorted_transports(context).await? {
             info!(context, "Trying to connect to transport {transport_id}.");
             match self
                 .connect(
@@ -327,6 +354,18 @@ pub(crate) async fn smtp_send(
         Ok(()) => SendResult::Success,
     };
 
+    if matches!(status, SendResult::Success) {
+        debug_assert!(smtp.transport_id.is_some());
+        if let Some(transport_id) = smtp.transport_id
+            && let Err(err) = record_success(context, transport_id).await
+        {
+            warn!(
+                context,
+                "Failed to record successful use of transport {transport_id} in smtp_success table: {err:#}."
+            );
+        }
+    }
+
     if let SendResult::Failure(err) = &status
         && let Some(msg_id) = msg_id
     {
@@ -858,3 +897,6 @@ pub(crate) async fn add_self_recipients(
 
     Ok(())
 }
+
+#[cfg(test)]
+mod smtp_tests;

src/smtp/smtp_tests.rs

@@ -0,0 +1,49 @@
+use anyhow::Result;
+
+use crate::test_utils::TestContextManager;
+use crate::transport;
+
+#[tokio::test(flavor = "multi_thread", worker_threads = 2)]
+async fn test_smtp_candidates() -> Result<()> {
+    let mut tcm = TestContextManager::new();
+    let t = &tcm.unconfigured().await;
+
+    transport::add_pseudo_transport(t, "foo@example.net").await?;
+    transport::add_pseudo_transport(t, "bar@example.net").await?;
+    transport::add_pseudo_transport(t, "baz@example.net").await?;
+
+    let transports = super::sorted_transports(t).await?;
+    let [
+        (transport_id1, ref transport1),
+        (transport_id2, ref transport2),
+        (transport_id3, ref transport3),
+    ] = transports[..]
+    else {
+        panic!("Unexpected number of transports");
+    };
+
+    // By default first added transport is used first.
+    assert_eq!(transport1.addr, "foo@example.net");
+    assert_eq!(transport2.addr, "bar@example.net");
+    assert_eq!(transport3.addr, "baz@example.net");
+
+    super::record_success(t, transport_id3).await?;
+    let transports2 = super::sorted_transports(t).await?;
+    assert_eq!(transports2[0].0, transport_id3);
+    assert_eq!(transports2[1].0, transport_id1);
+    assert_eq!(transports2[2].0, transport_id2);
+
+    super::record_success(t, transport_id2).await?;
+    let transports3 = super::sorted_transports(t).await?;
+    assert_eq!(transports3[0].0, transport_id2);
+    assert_eq!(transports3[1].0, transport_id3);
+    assert_eq!(transports3[2].0, transport_id1);
+
+    super::record_success(t, transport_id3).await?;
+    let transports4 = super::sorted_transports(t).await?;
+    assert_eq!(transports4[0].0, transport_id3);
+    assert_eq!(transports4[1].0, transport_id2);
+    assert_eq!(transports4[2].0, transport_id1);
+
+    Ok(())
+}

src/sql.rs

@@ -684,6 +684,17 @@ impl Sql {
     }
 }
 
+pub(crate) trait TransactionExt {
+    fn count(&self, query: &str, params: impl rusqlite::Params + Send) -> Result<usize>;
+}
+
+impl TransactionExt for rusqlite::Transaction<'_> {
+    fn count(&self, query: &str, params: impl rusqlite::Params + Send) -> Result<usize> {
+        let count: isize = self.query_row(query, params, |row| row.get(0))?;
+        Ok(usize::try_from(count)?)
+    }
+}
+
 /// Creates a new SQLite connection.
 ///
 /// `path` is the database path.

src/sql/migrations.rs

@@ -16,6 +16,7 @@ use crate::key::DcKey;
 use crate::log::warn;
 
 use crate::sql::Sql;
+use crate::sql::TransactionExt as _;
 use crate::tools::{self, Time, inc_and_check, time_elapsed};
 use crate::transport::ConfiguredLoginParam;
 
@@ -2672,6 +2673,34 @@ CREATE TABLE smtp2 (
             .await?;
     }
 
+    inc_and_check(&mut migration_version, 168)?;
+    if dbversion < migration_version {
+        sql.execute_migration(
+            "
+CREATE TABLE smtp_success (
+    id INTEGER PRIMARY KEY AUTOINCREMENT NOT NULL,
+    transport_id INTEGER UNIQUE NOT NULL,
+    FOREIGN KEY(transport_id) REFERENCES transports(id) ON DELETE CASCADE
+) STRICT;
+",
+            migration_version,
+        )
+        .await?;
+    }
+
+    inc_and_check(&mut migration_version, 169)?;
+    if dbversion < migration_version {
+        sql.execute_migration_transaction(
+            |transaction| {
+                unencrypted_chats_migration(context, transaction)?;
+
+                Ok(())
+            },
+            migration_version,
+        )
+        .await?;
+    }
+
     let new_version = sql
         .get_raw_config_int(VERSION_CFG)
         .await?
@@ -2689,5 +2718,82 @@ CREATE TABLE smtp2 (
     Ok(recode_avatar)
 }
 
+fn unencrypted_chats_migration(
+    context: &Context,
+    transaction: &mut rusqlite::Transaction<'_>,
+) -> Result<()> {
+    // Migrate:
+    // - all unencrypted (i.e. ad-hoc) groups into regular groups with 0 members.
+    // - all unencrypted 1:1 chats into a group with 0 members. (probably unnecessary, not implemented right now)
+    // - all chats of type Mailinglist into a group with 0 members.
+    transaction.execute_batch(
+        "
+-- Save the rewritten chats in a table in case the migration is faulty
+-- and we need to fix something later:
+CREATE TABLE legacy_unencrypted_chats(chat_id INTEGER PRIMARY KEY, type INTEGER) STRICT;
+
+INSERT INTO legacy_unencrypted_chats(chat_id, type)
+SELECT id, type FROM chats
+WHERE ((type=120 AND grpid='') OR type=140) -- Ad-hoc groups and mailinglists
+  AND id>9;
+
+DELETE FROM chats_contacts
+WHERE chat_id IN (SELECT chat_id FROM legacy_unencrypted_chats);
+
+UPDATE chats SET type=120
+WHERE id IN (SELECT chat_id FROM legacy_unencrypted_chats);
+",
+    )?;
+
+    // Rewrite all address-contacts into a key-contact with "Hidden" origin.
+    // We still need the contacts because we want to keep the messages, and every message needs a sender.
+    // Make sure that the address is available in the name, so that the user can still see it.
+    transaction.execute_batch(
+        "
+UPDATE contacts
+SET origin=8 -- Origin::Hidden
+WHERE fingerprint='' AND id>9;
+
+UPDATE contacts
+SET name=name || ' (' || addr || ')'
+WHERE fingerprint='' AND id>9 AND name!='';
+
+UPDATE contacts
+SET authname=authname || ' (' || addr || ')'
+WHERE fingerprint='' AND id>9 AND name='' AND authname!='';
+
+UPDATE contacts
+SET authname=addr
+WHERE fingerprint='' AND id>9 AND name='' AND authname=''
+",
+    )?;
+
+    // Set the gray letter avatar for all legacy chats:
+    let legacy_chats = transaction.count("SELECT COUNT(*) FROM legacy_unencrypted_chats", ())?;
+    let legacy_contacts = transaction.count(
+        "SELECT COUNT(*) FROM contacts WHERE fingerprint='' AND id>9",
+        (),
+    )?;
+    if legacy_chats > 0 || legacy_contacts > 0 {
+        let blob = crate::blob::BlobObject::create_and_deduplicate_from_bytes(
+            context,
+            include_bytes!("../../assets/icon-unencrypted.png"),
+            "icon-unencrypted.png",
+        )?;
+        let new_param = &format!("i={}", blob.as_name());
+        transaction.execute(
+            "UPDATE chats SET param=? WHERE id IN (SELECT chat_id FROM legacy_unencrypted_chats)",
+            (new_param,),
+        )?;
+
+        transaction.execute(
+            "UPDATE contacts SET param=? WHERE fingerprint='' AND id>9",
+            (new_param,),
+        )?;
+    }
+
+    Ok(())
+}
+
 #[cfg(test)]
 mod migrations_tests;

src/sql/migrations/migrations_tests.rs

@@ -145,7 +145,8 @@ async fn test_key_contacts_migration_email1() -> Result<()> {
         .unwrap();
     let email_bob = Contact::get_by_id(&t, email_bob_id).await?;
     assert_eq!(email_bob.is_key_contact(), false);
-    assert_eq!(email_bob.origin, Origin::OutgoingTo);
+    // All email address contacts are hidden now:
+    assert_eq!(email_bob.origin, Origin::Hidden);
     assert_eq!(email_bob.e2ee_avail(&t).await?, false);
     assert_eq!(email_bob.fingerprint(), None);
 
@@ -178,7 +179,8 @@ async fn test_key_contacts_migration_email2() -> Result<()> {
         .unwrap();
     let email_bob = Contact::get_by_id(&t, email_bob_id).await?;
     assert_eq!(email_bob.is_key_contact(), false);
-    assert_eq!(email_bob.origin, Origin::OutgoingTo);
+    // All email address contacts are hidden now:
+    assert_eq!(email_bob.origin, Origin::Hidden);
     assert_eq!(email_bob.e2ee_avail(&t).await?, false);
     assert_eq!(email_bob.fingerprint(), None);