more debug logging

.github/workflows/upload-docs.yml

@@ -1,18 +1,16 @@
-name: Build & deploy documentation on rs.delta.chat, c.delta.chat, py.delta.chat and cffi.delta.chat
+name: Build & deploy documentation on rs.delta.chat, c.delta.chat, and py.delta.chat
 
 on:
   push:
     branches:
       - main
+      - build_jsonrpc_docs_ci
 
 permissions: {}
 
 jobs:
   build-rs:
     runs-on: ubuntu-latest
-    environment:
-      name: rs.delta.chat
-      url: https://rs.delta.chat/
 
     steps:
       - uses: actions/checkout@v6
@@ -25,15 +23,12 @@ jobs:
       - name: Upload to rs.delta.chat
         run: |
           mkdir -p "$HOME/.ssh"
-          echo "${{ secrets.RS_DOCS_SSH_KEY }}" > "$HOME/.ssh/key"
+          echo "${{ secrets.KEY }}" > "$HOME/.ssh/key"
           chmod 600 "$HOME/.ssh/key"
-          rsync -avzh -e "ssh -i $HOME/.ssh/key -o StrictHostKeyChecking=no" $GITHUB_WORKSPACE/target/doc "${{ secrets.RS_DOCS_SSH_USER }}@rs.delta.chat:/var/www/html/rs.delta.chat/"
+          rsync -avzh -e "ssh -i $HOME/.ssh/key -o StrictHostKeyChecking=no" $GITHUB_WORKSPACE/target/doc "${{ secrets.USERNAME }}@rs.delta.chat:/var/www/html/rs/"
 
   build-python:
     runs-on: ubuntu-latest
-    environment:
-      name: py.delta.chat
-      url: https://py.delta.chat/
 
     steps:
       - uses: actions/checkout@v6
@@ -47,15 +42,12 @@ jobs:
       - name: Upload to py.delta.chat
         run: |
           mkdir -p "$HOME/.ssh"
-          echo "${{ secrets.PY_DOCS_SSH_KEY }}" > "$HOME/.ssh/key"
+          echo "${{ secrets.CODESPEAK_KEY }}" > "$HOME/.ssh/key"
           chmod 600 "$HOME/.ssh/key"
-          rsync -avzh --delete -e "ssh -i $HOME/.ssh/key -o StrictHostKeyChecking=no" $GITHUB_WORKSPACE/result/html/ "${{ secrets.PY_DOCS_SSH_USER }}@py.delta.chat:/var/www/html/py.delta.chat"
+          rsync -avzh -e "ssh -i $HOME/.ssh/key -o StrictHostKeyChecking=no" $GITHUB_WORKSPACE/result/html/ "delta@py.delta.chat:/home/delta/build/master"
 
   build-c:
     runs-on: ubuntu-latest
-    environment:
-      name: c.delta.chat
-      url: https://c.delta.chat/
 
     steps:
       - uses: actions/checkout@v6
@@ -69,9 +61,9 @@ jobs:
       - name: Upload to c.delta.chat
         run: |
           mkdir -p "$HOME/.ssh"
-          echo "${{ secrets.C_DOCS_SSH_KEY }}" > "$HOME/.ssh/key"
+          echo "${{ secrets.CODESPEAK_KEY }}" > "$HOME/.ssh/key"
           chmod 600 "$HOME/.ssh/key"
-          rsync -avzh --delete -e "ssh -i $HOME/.ssh/key -o StrictHostKeyChecking=no" $GITHUB_WORKSPACE/result/html/ "${{ secrets.C_DOCS_SSH_USER }}@c.delta.chat:/var/www/html/c.delta.chat"
+          rsync -avzh -e "ssh -i $HOME/.ssh/key -o StrictHostKeyChecking=no" $GITHUB_WORKSPACE/result/html/ "delta@c.delta.chat:/home/delta/build-c/master"
 
   build-ts:
     runs-on: ubuntu-latest
@@ -101,24 +93,3 @@ jobs:
           echo "${{ secrets.KEY }}" > "$HOME/.ssh/key"
           chmod 600 "$HOME/.ssh/key"
           rsync -avzh -e "ssh -i $HOME/.ssh/key -o StrictHostKeyChecking=no" $GITHUB_WORKSPACE/deltachat-jsonrpc/typescript/docs/ "${{ secrets.USERNAME }}@js.jsonrpc.delta.chat:/var/www/html/js-jsonrpc/"
-
-  build-cffi:
-    runs-on: ubuntu-latest
-    environment:
-      name: cffi.delta.chat
-      url: https://cffi.delta.chat/
-
-    steps:
-      - uses: actions/checkout@v6
-        with:
-          show-progress: false
-          persist-credentials: false
-      - name: Build the documentation with cargo
-        run: |
-          cargo doc --package deltachat_ffi --no-deps
-      - name: Upload to cffi.delta.chat
-        run: |
-          mkdir -p "$HOME/.ssh"
-          echo "${{ secrets.CFFI_DOCS_SSH_KEY }}" > "$HOME/.ssh/key"
-          chmod 600 "$HOME/.ssh/key"
-          rsync -avzh --delete -e "ssh -i $HOME/.ssh/key -o StrictHostKeyChecking=no" $GITHUB_WORKSPACE/target/doc/ "${{ secrets.CFFI_DOCS_SSH_USER }}@delta.chat:/var/www/html/cffi.delta.chat/"

.github/workflows/upload-ffi-docs.yml

@@ -0,0 +1,31 @@
+# GitHub Actions workflow
+# to build `deltachat_ffi` crate documentation
+# and upload it to <https://cffi.delta.chat/>
+
+name: Build & Deploy Documentation on cffi.delta.chat
+
+on:
+  push:
+    branches:
+      - main
+
+permissions: {}
+
+jobs:
+  build:
+    runs-on: ubuntu-latest
+
+    steps:
+      - uses: actions/checkout@v6
+        with:
+          show-progress: false
+          persist-credentials: false
+      - name: Build the documentation with cargo
+        run: |
+          cargo doc --package deltachat_ffi --no-deps
+      - name: Upload to cffi.delta.chat
+        run: |
+          mkdir -p "$HOME/.ssh"
+          echo "${{ secrets.KEY }}" > "$HOME/.ssh/key"
+          chmod 600 "$HOME/.ssh/key"
+          rsync -avzh -e "ssh -i $HOME/.ssh/key -o StrictHostKeyChecking=no" $GITHUB_WORKSPACE/target/doc/ "${{ secrets.USERNAME }}@delta.chat:/var/www/html/cffi/"

src/configure.rs

@@ -243,6 +243,11 @@ impl Context {
                         Ok((id, add_timestamp))
                     },
                 )?;
+                transaction.execute("DELETE FROM imap WHERE transport_id=?", (transport_id,))?;
+                transaction.execute(
+                    "DELETE FROM imap_sync WHERE transport_id=?",
+                    (transport_id,),
+                )?;
 
                 // Removal timestamp should not be lower than addition timestamp
                 // to be accepted by other devices when synced.

src/imap.rs

@@ -323,7 +323,8 @@ impl Imap {
         if !ratelimit_duration.is_zero() {
             warn!(
                 context,
-                "IMAP got rate limited, waiting for {} until can connect.",
+                "Transport {}: IMAP got rate limited, waiting for {} until can connect.",
+                self.transport_id,
                 duration_to_str(ratelimit_duration),
             );
             let interrupted = async {
@@ -335,12 +336,16 @@ impl Imap {
             if interrupted {
                 info!(
                     context,
-                    "Connecting to IMAP without waiting for ratelimit due to interrupt."
+                    "Transport {}: Connecting to IMAP without waiting for ratelimit due to interrupt.",
+                    self.transport_id
                 );
             }
         }
 
-        info!(context, "Connecting to IMAP server.");
+        info!(
+            context,
+            "Transport {}: Connecting to IMAP server.", self.transport_id
+        );
         self.connectivity.set_connecting(context);
 
         self.conn_last_try = tools::Time::now();
@@ -355,7 +360,10 @@ impl Imap {
         let login_params = prioritize_server_login_params(&context.sql, &self.lp, "imap").await?;
         let mut first_error = None;
         for lp in login_params {
-            info!(context, "IMAP trying to connect to {}.", &lp.connection);
+            info!(
+                context,
+                "Transport {}: IMAP trying to connect to {}.", self.transport_id, &lp.connection
+            );
             let connection_candidate = lp.connection.clone();
             let client = match Client::connect(
                 context,
@@ -403,7 +411,10 @@ impl Imap {
                     let resync_request_sender = self.resync_request_sender.clone();
 
                     let session = if capabilities.can_compress {
-                        info!(context, "Enabling IMAP compression.");
+                        info!(
+                            context,
+                            "Transport {}: Enabling IMAP compression.", self.transport_id
+                        );
                         let compressed_session = session
                             .compress(|s| {
                                 let session_stream: Box<dyn SessionStream> = Box::new(s);
@@ -436,7 +447,10 @@ impl Imap {
                         lp.user
                     )));
                     self.connectivity.set_preparing(context);
-                    info!(context, "Successfully logged into IMAP server.");
+                    info!(
+                        context,
+                        "Transport {}: Successfully logged into IMAP server.", self.transport_id
+                    );
                     return Ok(session);
                 }
 
@@ -444,7 +458,10 @@ impl Imap {
                     let imap_user = lp.user.to_owned();
                     let message = stock_str::cannot_login(context, &imap_user);
 
-                    warn!(context, "IMAP failed to login: {err:#}.");
+                    warn!(
+                        context,
+                        "Transport {}: IMAP failed to login: {err:#}.", self.transport_id
+                    );
                     first_error.get_or_insert(format_err!("{message} ({err:#})"));
 
                     // If it looks like the password is wrong, send a notification:
@@ -463,7 +480,11 @@ impl Imap {
                             )
                             .await
                             {
-                                warn!(context, "Failed to add device message: {e:#}.");
+                                warn!(
+                                    context,
+                                    "Transport {}: Failed to add device message: {e:#}.",
+                                    self.transport_id
+                                );
                             } else {
                                 context
                                     .set_config_internal(Config::NotifyAboutWrongPw, None)
@@ -525,10 +546,21 @@ impl Imap {
             bail!("IMAP operation attempted while it is torn down");
         }
 
+        let transport_id = session.transport_id();
+        info!(
+            context,
+            "Transport {transport_id}: fetch_move_delete start."
+        );
+
         let msgs_fetched = self
             .fetch_new_messages(context, session, watch_folder, folder_meaning)
             .await
             .context("fetch_new_messages")?;
+
+        info!(
+            context,
+            "Transport {transport_id}: fetch_move_delete finished fetch_new_messages."
+        );
         if msgs_fetched && context.get_config_delete_device_after().await?.is_some() {
             // New messages were fetched and shall be deleted later, restart ephemeral loop.
             // Note that the `Config::DeleteDeviceAfter` timer starts as soon as the messages are
@@ -567,10 +599,18 @@ impl Imap {
             return Ok(false);
         }
 
+        info!(
+            context,
+            "Transport {transport_id}: fetch_new_messages selects folder {folder:?}."
+        );
         let folder_exists = session
             .select_with_uidvalidity(context, folder)
             .await
             .with_context(|| format!("Failed to select folder {folder:?}"))?;
+        info!(
+            context,
+            "Transport {transport_id}: fetch_new_messages selected folder {folder:?}."
+        );
 
         if !session.new_mail {
             info!(
@@ -1103,22 +1143,16 @@ impl Session {
             return Ok(());
         }
 
-        context
-            .sql
-            .execute(
-                "DELETE FROM imap_markseen WHERE id NOT IN (SELECT imap.id FROM imap)",
-                (),
-            )
-            .await?;
-
         let transport_id = self.transport_id();
-        let mut rows = context
+        info!(context, "Transport {transport_id}: Storing seen flags.");
+        let rows = context
             .sql
             .query_map_vec(
                 "SELECT imap.id, uid, folder FROM imap, imap_markseen
                  WHERE imap.id = imap_markseen.id
                  AND imap.transport_id=?
-                 AND target = folder",
+                 AND target = folder
+                 ORDER BY folder, uid",
                 (transport_id,),
                 |row| {
                     let rowid: i64 = row.get(0)?;
@@ -1129,16 +1163,6 @@ impl Session {
             )
             .await?;
 
-        // Number of SQL results is expected to be low as
-        // we usually don't have many messages to mark on IMAP at once.
-        // We are sorting outside of SQL to avoid SQLite constructing a query plan
-        // that scans the whole `imap` table. Scanning `imap_markseen` is fine
-        // as it should not have many items.
-        // If you change the SQL query, test it with `EXPLAIN QUERY PLAN`.
-        rows.sort_unstable_by(|(_rowid1, uid1, folder1), (_rowid2, uid2, folder2)| {
-            (folder1, uid1).cmp(&(folder2, uid2))
-        });
-
         for (folder, rowid_set, uid_set) in UidGrouper::from(rows) {
             let folder_exists = match self.select_with_uidvalidity(context, &folder).await {
                 Err(err) => {
@@ -1155,13 +1179,15 @@ impl Session {
             } else if let Err(err) = self.add_flag_finalized_with_set(&uid_set, "\\Seen").await {
                 warn!(
                     context,
-                    "Cannot mark messages {uid_set} in {folder} as seen, will retry later: {err:#}."
+                    "Transport {transport_id}: Cannot mark messages {uid_set} in {folder} as seen, will retry later: {err:#}."
                 );
                 continue;
             } else {
                 info!(
                     context,
-                    "Marked messages {} in folder {} as seen.", uid_set, folder
+                    "Transport {transport_id}: Marked messages {} in folder {} as seen.",
+                    uid_set,
+                    folder
                 );
             }
             context
@@ -1176,6 +1202,10 @@ impl Session {
                 .await
                 .context("Cannot remove messages marked as seen from imap_markseen table")?;
         }
+        info!(
+            context,
+            "Transport {transport_id}: Finished storing seen flags."
+        );
 
         Ok(())
     }
@@ -1516,9 +1546,10 @@ impl Session {
             return Ok(());
         }
 
+        let transport_id = self.transport_id();
         info!(
             context,
-            "Server supports metadata, retrieving server comment and admin contact."
+            "Transport {transport_id}: Server supports metadata, retrieving server comment and admin contact."
         );
 
         let mut comment = None;
@@ -1551,7 +1582,8 @@ impl Session {
                         } else {
                             warn!(
                                 context,
-                                "Got invalid URL from iroh relay metadata: {:?}.", value
+                                "Transport {transport_id}: Got invalid URL from iroh relay metadata: {:?}.",
+                                value
                             );
                         }
                     }
@@ -1580,6 +1612,7 @@ impl Session {
             create_fallback_ice_servers()
         };
 
+        info!(context, "Transport {transport_id}: Got IMAP metadata.");
         *lock = Some(ServerMetadata {
             comment,
             admin,

src/mimefactory.rs

@@ -852,13 +852,7 @@ impl MimeFactory {
 
         let rfc724_mid = match &self.loaded {
             Loaded::Message { msg, .. } => match &self.pre_message_mode {
-                PreMessageMode::Pre { .. } => {
-                    if msg.pre_rfc724_mid.is_empty() {
-                        create_outgoing_rfc724_mid()
-                    } else {
-                        msg.pre_rfc724_mid.clone()
-                    }
-                }
+                PreMessageMode::Pre { .. } => create_outgoing_rfc724_mid(),
                 _ => msg.rfc724_mid.clone(),
             },
             Loaded::Mdn { .. } => create_outgoing_rfc724_mid(),

src/pgp.rs

@@ -84,14 +84,12 @@ pub(crate) fn create_keypair(addr: EmailAddress) -> Result<SignedSecretKey> {
 /// Selects a subkey of the public key to use for encryption.
 ///
 /// Returns `None` if the public key cannot be used for encryption.
+///
+/// TODO: take key flags and expiration dates into account
 fn select_pk_for_encryption(key: &SignedPublicKey) -> Option<&SignedPublicSubKey> {
-    key.public_subkeys.iter().find(|subkey| {
-        subkey.algorithm().can_encrypt()
-            && subkey
-                .signatures
-                .iter()
-                .any(|signature| signature.key_flags().encrypt_comms())
-    })
+    key.public_subkeys
+        .iter()
+        .find(|subkey| subkey.algorithm().can_encrypt())
 }
 
 /// Version of SEIPD packet to use.

src/sql.rs

@@ -883,24 +883,6 @@ pub async fn housekeeping(context: &Context) -> Result<()> {
         .log_err(context)
         .ok();
 
-    // Cleanup `imap` and `imap_sync` entries for deleted transports.
-    //
-    // Transports may be deleted directly or via sync messages,
-    // so it is easier to cleanup orphaned entries in a single place.
-    context
-        .sql
-        .execute(
-            "DELETE FROM imap WHERE transport_id NOT IN (SELECT transports.id FROM transports)",
-            (),
-        )
-        .await
-        .log_err(context)
-        .ok();
-    context.sql.execute(
-        "DELETE FROM imap_sync WHERE transport_id NOT IN (SELECT transports.id FROM transports)",
-        (),
-    ).await.log_err(context).ok();
-
     // Delete POI locations
     // which don't have corresponding message.
     delete_orphaned_poi_locations(context)

src/stats.rs

@@ -554,6 +554,7 @@ async fn get_message_stats(context: &Context) -> Result<BTreeMap<Chattype, Messa
 }
 
 pub(crate) async fn update_message_stats(context: &Context) -> Result<()> {
+    info!(context, "Updating message statistics.");
     for chattype in [Chattype::Single, Chattype::Group, Chattype::OutBroadcast] {
         update_message_stats_inner(context, chattype).await?;
     }

src/test_utils.rs

@@ -715,8 +715,7 @@ impl TestContext {
     }
 
     pub async fn get_smtp_rows_for_msg<'a>(&'a self, msg_id: MsgId) -> Vec<SentMessage<'a>> {
-        let sent_msgs = self
-            .ctx
+        self.ctx
             .sql
             .query_map_vec(
                 "SELECT id, msg_id, mime, recipients FROM smtp WHERE msg_id=?",
@@ -738,23 +737,7 @@ impl TestContext {
                 sender_context: &self.ctx,
                 recipients,
             })
-            .collect();
-        self.ctx
-            .sql
-            .execute("DELETE FROM smtp WHERE msg_id=?", (msg_id,))
-            .await
-            .expect("Delete smtp jobs");
-        update_msg_state(&self.ctx, msg_id, MessageState::OutDelivered)
-            .await
-            .expect("Update message state");
-        self.sql
-            .execute(
-                "UPDATE msgs SET timestamp_sent=? WHERE id=?",
-                (time(), msg_id),
-            )
-            .await
-            .expect("Update timestamp_sent");
-        sent_msgs
+            .collect()
     }
 
     /// Parses a message.

src/tests/pre_messages/sending.rs

@@ -56,27 +56,23 @@ async fn test_sending_pre_message() -> Result<()> {
             .is_some()
     );
 
-    let post_rfc724_mid = post_message_parsed
-        .headers
-        .get_header_value(HeaderDef::MessageId);
     assert_eq!(
-        post_rfc724_mid,
+        post_message_parsed
+            .headers
+            .get_header_value(HeaderDef::MessageId),
         Some(format!("<{}>", msg.rfc724_mid)),
         "Post-Message should have the rfc message id of the database message"
     );
 
-    let pre_rfc724_mid = pre_message_parsed
-        .headers
-        .get_header_value(HeaderDef::MessageId);
     assert_ne!(
-        pre_rfc724_mid, post_rfc724_mid,
+        pre_message_parsed
+            .headers
+            .get_header_value(HeaderDef::MessageId),
+        post_message_parsed
+            .headers
+            .get_header_value(HeaderDef::MessageId),
         "message ids of Pre-Message and Post-Message should be different"
     );
-    assert_eq!(
-        pre_rfc724_mid,
-        Some(format!("<{}>", msg.pre_rfc724_mid)),
-        "Unexpected pre-message RFC 724 ID"
-    );
 
     let decrypted_post_message = bob.parse_msg(post_message).await;
     assert_eq!(decrypted_post_message.decrypting_failed, false);
@@ -90,7 +86,9 @@ async fn test_sending_pre_message() -> Result<()> {
         decrypted_pre_message
             .get_header(HeaderDef::ChatPostMessageId)
             .map(String::from),
-        post_rfc724_mid,
+        post_message_parsed
+            .headers
+            .get_header_value(HeaderDef::MessageId)
     );
     assert!(
         pre_message_parsed
@@ -100,25 +98,6 @@ async fn test_sending_pre_message() -> Result<()> {
         "no Chat-Post-Message-ID header in unprotected headers of Pre-Message"
     );
 
-    chat::resend_msgs(alice, &[msg_id]).await?;
-    let smtp_rows = alice.get_smtp_rows_for_msg(msg_id).await;
-    assert_eq!(smtp_rows.len(), 2);
-
-    let pre_message_parsed = mailparse::parse_mail(smtp_rows[0].payload.as_bytes())?;
-    assert_eq!(
-        pre_message_parsed
-            .headers
-            .get_header_value(HeaderDef::MessageId),
-        pre_rfc724_mid
-    );
-    let post_message_parsed = mailparse::parse_mail(smtp_rows[1].payload.as_bytes())?;
-    assert_eq!(
-        post_message_parsed
-            .headers
-            .get_header_value(HeaderDef::MessageId),
-        post_rfc724_mid
-    );
-
     Ok(())
 }
 

src/tools.rs

@@ -21,6 +21,7 @@ pub use std::time::SystemTime as Time;
 #[cfg(not(test))]
 pub use std::time::SystemTime;
 
+use crate::log::LogExt as _;
 use anyhow::{Context as _, Result, bail, ensure};
 use base64::Engine as _;
 use chrono::{Local, NaiveDateTime, NaiveTime, TimeZone};
@@ -248,6 +249,8 @@ async fn maybe_warn_on_bad_time(context: &Context, now: i64, known_past_timestam
                 true,
             )
             .await
+            .context("Failed to add bad time warning")
+            .log_err(context)
             .ok();
         } else {
             warn!(context, "Can't convert current timestamp");