don't warn on hello

Do not put log messages into format string
and enable INFO level when bot is started
via main() as it happens with systemd.

CHANGELOG.md

@@ -0,0 +1,22 @@
+# Changelog for chatmail deployment 
+
+## unreleased
+
+### Changes since March 15th, 2024
+
+- Fix various tests to pass again with "cmdeploy test". 
+  ([#245](https://github.com/deltachat/chatmail/pull/245),
+  [#242](https://github.com/deltachat/chatmail/pull/242)
+
+- Ensure lets-encrypt certificates are reloaded after renewal 
+  ([#244]) https://github.com/deltachat/chatmail/pull/244
+
+- Persist tokens to avoid iOS users loosing push-notifications when the
+  chatmail metadata service is restarted (happens regularly during deploys)
+  ([#238](https://github.com/deltachat/chatmail/pull/239)
+
+- Fix failing sieve-script compile errors on incoming messages
+  ([#237](https://github.com/deltachat/chatmail/pull/239)
+
+- Fix quota reporting after expunging of old mails
+  ([#233](https://github.com/deltachat/chatmail/pull/239)

chatmaild/src/chatmaild/chatmail-metadata.service.f

@@ -2,7 +2,7 @@
 Description=Chatmail dict proxy for IMAP METADATA
 
 [Service]
-ExecStart={execpath} /run/dovecot/metadata.socket vmail {config_path}
+ExecStart={execpath} /run/dovecot/metadata.socket vmail {config_path} /home/vmail/metadata
 Restart=always
 RestartSec=30
 

chatmaild/src/chatmaild/doveauth.py

@@ -17,6 +17,10 @@ from .config import read_config, Config
 NOCREATE_FILE = "/etc/chatmail-nocreate"
 
 
+class UnknownCommand(ValueError):
+    """dictproxy handler received an unkown command"""
+
+
 def encrypt_password(password: str):
     # https://doc.dovecot.org/configuration_manual/authentication/password_schemes/
     passhash = crypt.crypt(password, crypt.METHOD_SHA512)
@@ -127,8 +131,12 @@ def split_and_unescape(s):
 
 
 def handle_dovecot_request(msg, db, config: Config):
+    # see https://doc.dovecot.org/3.0/developer_manual/design/dict_protocol/
     short_command = msg[0]
-    if short_command == "L":  # LOOKUP
+    if short_command == "H":  # HELLO
+        # we don't do any checking on versions and just return
+        return
+    elif short_command == "L":  # LOOKUP
         parts = msg[1:].split("\t")
 
         # Dovecot <2.3.17 has only one part,
@@ -159,7 +167,7 @@ def handle_dovecot_request(msg, db, config: Config):
                     reply_command = "N"
         json_res = json.dumps(res) if res else ""
         return f"{reply_command}{json_res}\n"
-    return None
+    raise UnknownCommand(msg)
 
 
 def handle_dovecot_protocol(rfile, wfile, db: Database, config: Config):
@@ -167,12 +175,14 @@ def handle_dovecot_protocol(rfile, wfile, db: Database, config: Config):
         msg = rfile.readline().strip().decode()
         if not msg:
             break
-        res = handle_dovecot_request(msg, db, config)
-        if res:
-            wfile.write(res.encode("ascii"))
-            wfile.flush()
+        try:
+            res = handle_dovecot_request(msg, db, config)
+        except UnknownCommand:
+            logging.warning("unknown command: %r", msg)
         else:
-            logging.warning("request had no answer: %r", msg)
+            if res:
+                wfile.write(res.encode("ascii"))
+                wfile.flush()
 
 
 class ThreadedUnixStreamServer(ThreadingMixIn, UnixStreamServer):

chatmaild/src/chatmaild/echo.py

@@ -18,14 +18,14 @@ hooks = events.HookCollection()
 @hooks.on(events.RawEvent)
 def log_event(event):
     if event.kind == EventType.INFO:
-        logging.info(event.msg)
+        logging.info("%s", event.msg)
     elif event.kind == EventType.WARNING:
-        logging.warning(event.msg)
+        logging.warning("%s", event.msg)
 
 
 @hooks.on(events.RawEvent(EventType.ERROR))
 def log_error(event):
-    logging.error(event.msg)
+    logging.error("%s", event.msg)
 
 
 @hooks.on(events.MemberListChanged)
@@ -48,6 +48,9 @@ def on_group_name_changed(event):
 @hooks.on(events.NewMessage(func=lambda e: not e.command))
 def echo(event):
     snapshot = event.message_snapshot
+    if snapshot.is_info:
+        # Ignore info messages
+        return
     if snapshot.text or snapshot.file:
         snapshot.chat.send_message(text=snapshot.text, file=snapshot.file)
 
@@ -59,6 +62,7 @@ def help_command(event):
 
 
 def main():
+    logging.basicConfig(level=logging.INFO)
     path = os.environ.get("PATH")
     venv_path = sys.argv[0].strip("echobot")
     os.environ["PATH"] = path + ":" + venv_path
@@ -80,5 +84,4 @@ def main():
 
 
 if __name__ == "__main__":
-    logging.basicConfig(level=logging.INFO)
     main()

chatmaild/src/chatmaild/metadata.py

@@ -1,5 +1,6 @@
 import pwd
 
+import pathlib
 from queue import Queue
 from threading import Thread
 from socketserver import (
@@ -12,6 +13,7 @@ import sys
 import logging
 import os
 import requests
+import marshal
 
 
 DICTPROXY_LOOKUP_CHAR = "L"
@@ -23,12 +25,37 @@ DICTPROXY_TRANSACTION_CHARS = "SBC"
 
 
 class Notifier:
-    def __init__(self):
-        self.guid2token = {}
+    def __init__(self, metadata_dir):
+        self.metadata_dir = metadata_dir
         self.to_notify_queue = Queue()
 
+    def get_metadata(self, guid):
+        guid_path = self.metadata_dir.joinpath(guid)
+        if guid_path.exists():
+            with guid_path.open("rb") as f:
+                return marshal.load(f)
+        return {}
+
+    def set_metadata(self, guid, guid_data):
+        guid_path = self.metadata_dir.joinpath(guid)
+        write_path = guid_path.with_suffix(".tmp")
+        with write_path.open("wb") as f:
+            marshal.dump(guid_data, f)
+        os.rename(write_path, guid_path)
+
     def set_token(self, guid, token):
-        self.guid2token[guid] = token
+        guid_data = self.get_metadata(guid)
+        guid_data["token"] = token
+        self.set_metadata(guid, guid_data)
+
+    def del_token(self, guid):
+        guid_data = self.get_metadata(guid)
+        if "token" in guid_data:
+            del guid_data["token"]
+            self.set_metadata(guid, guid_data)
+
+    def get_token(self, guid):
+        return self.get_metadata(guid).get("token")
 
     def new_message_for_guid(self, guid):
         self.to_notify_queue.put(guid)
@@ -40,7 +67,7 @@ class Notifier:
 
     def thread_run_one(self, requests_session):
         guid = self.to_notify_queue.get()
-        token = self.guid2token.get(guid)
+        token = self.get_token(guid)
         if token:
             response = requests_session.post(
                 "https://notifications.delta.chat/notify",
@@ -50,7 +77,7 @@ class Notifier:
             if response.status_code == 410:
                 # 410 Gone status code
                 # means the token is no longer valid.
-                del self.guid2token[guid]
+                self.del_token(guid)
 
 
 def handle_dovecot_protocol(rfile, wfile, notifier):
@@ -119,12 +146,15 @@ class ThreadedUnixStreamServer(ThreadingMixIn, UnixStreamServer):
 
 
 def main():
-    socket, username, config = sys.argv[1:]
+    socket, username, config, metadata_dir = sys.argv[1:]
     passwd_entry = pwd.getpwnam(username)
 
     # XXX config is not currently used
     config = read_config(config)
-    notifier = Notifier()
+    metadata_dir = pathlib.Path(metadata_dir)
+    if not metadata_dir.exists():
+        metadata_dir.mkdir()
+    notifier = Notifier(metadata_dir)
 
     class Handler(StreamRequestHandler):
         def handle(self):

chatmaild/src/chatmaild/tests/test_doveauth.py

@@ -75,6 +75,14 @@ def test_handle_dovecot_request(db, example_config):
     assert userdata["password"].startswith("{SHA512-CRYPT}")
 
 
+def test_handle_dovecot_protocol_hello_is_skipped(db, example_config, caplog):
+    rfile = io.BytesIO(b"H3\t2\t0\t\tauth\n")
+    wfile = io.BytesIO()
+    handle_dovecot_protocol(rfile, wfile, db, example_config)
+    assert wfile.getvalue() == b""
+    assert not caplog.messages
+
+
 def test_handle_dovecot_protocol(db, example_config):
     rfile = io.BytesIO(
         b"H3\t2\t0\t\tauth\nLshared/userdb/foobar@chat.example.org\tfoobar@chat.example.org\n"

chatmaild/src/chatmaild/tests/test_metadata.py

@@ -1,4 +1,5 @@
 import io
+import pytest
 
 from chatmaild.metadata import (
     handle_dovecot_request,
@@ -7,40 +8,60 @@ from chatmaild.metadata import (
 )
 
 
-def test_handle_dovecot_request_lookup_fails():
-    notifier = Notifier()
+@pytest.fixture
+def notifier(tmp_path):
+    metadata_dir = tmp_path.joinpath("metadata")
+    metadata_dir.mkdir()
+    return Notifier(metadata_dir)
+
+
+def test_notifier_persistence(tmp_path):
+    metadata_dir = tmp_path.joinpath("metadata")
+    metadata_dir.mkdir()
+    notifier1 = Notifier(metadata_dir)
+    notifier2 = Notifier(metadata_dir)
+    assert notifier1.get_token(guid="guid00") is None
+    assert notifier2.get_token(guid="guid00") is None
+
+    notifier1.set_token("guid00", "01234")
+    notifier1.set_token("guid03", "456")
+    assert notifier2.get_token("guid00") == "01234"
+    assert notifier2.get_token("guid03") == "456"
+    notifier2.del_token("guid00")
+    assert notifier1.get_token("guid00") is None
+
+
+def test_handle_dovecot_request_lookup_fails(notifier):
     res = handle_dovecot_request("Lpriv/123/chatmail", {}, notifier)
     assert res == "N\n"
 
 
-def test_handle_dovecot_request_happy_path():
-    notifier = Notifier()
+def test_handle_dovecot_request_happy_path(notifier):
     transactions = {}
 
     # lookups return the same NOTFOUND result
     res = handle_dovecot_request("Lpriv/123/chatmail", transactions, notifier)
     assert res == "N\n"
-    assert not notifier.guid2token and not transactions
+    assert notifier.get_token("guid00") is None and not transactions
 
     # set device token in a transaction
     tx = "1111"
     msg = f"B{tx}\tuser"
     res = handle_dovecot_request(msg, transactions, notifier)
-    assert not res and not notifier.guid2token
+    assert not res and notifier.get_token("guid00") is None
     assert transactions == {tx: "O\n"}
 
     msg = f"S{tx}\tpriv/guid00/devicetoken\t01234"
     res = handle_dovecot_request(msg, transactions, notifier)
     assert not res
     assert len(transactions) == 1
-    assert len(notifier.guid2token) == 1
-    assert notifier.guid2token["guid00"] == "01234"
+    assert notifier.get_token("guid00") == "01234"
 
     msg = f"C{tx}"
     res = handle_dovecot_request(msg, transactions, notifier)
     assert res == "O\n"
     assert len(transactions) == 0
-    assert notifier.guid2token["guid00"] == "01234"
+    assert notifier.get_token("guid00") == "01234"
 
     # trigger notification for incoming message
     assert handle_dovecot_request(f"B{tx}\tuser", transactions, notifier) is None
@@ -52,7 +73,7 @@ def test_handle_dovecot_request_happy_path():
     assert not transactions
 
 
-def test_handle_dovecot_protocol_set_devicetoken():
+def test_handle_dovecot_protocol_set_devicetoken(notifier):
     rfile = io.BytesIO(
         b"\n".join(
             [
@@ -64,13 +85,12 @@ def test_handle_dovecot_protocol_set_devicetoken():
         )
     )
     wfile = io.BytesIO()
-    notifier = Notifier()
     handle_dovecot_protocol(rfile, wfile, notifier)
-    assert notifier.guid2token["guid00"] == "01234"
+    assert notifier.get_token("guid00") == "01234"
     assert wfile.getvalue() == b"O\n"
 
 
-def test_handle_dovecot_protocol_iterate():
+def test_handle_dovecot_protocol_iterate(notifier):
     rfile = io.BytesIO(
         b"\n".join(
             [
@@ -80,12 +100,11 @@ def test_handle_dovecot_protocol_iterate():
         )
     )
     wfile = io.BytesIO()
-    notifier = Notifier()
     handle_dovecot_protocol(rfile, wfile, notifier)
     assert wfile.getvalue() == b"\n"
 
 
-def test_handle_dovecot_protocol_messagenew():
+def test_handle_dovecot_protocol_messagenew(notifier):
     rfile = io.BytesIO(
         b"\n".join(
             [
@@ -97,14 +116,13 @@ def test_handle_dovecot_protocol_messagenew():
         )
     )
     wfile = io.BytesIO()
-    notifier = Notifier()
     handle_dovecot_protocol(rfile, wfile, notifier)
     assert wfile.getvalue() == b"O\n"
     assert notifier.to_notify_queue.get() == "guid00"
     assert notifier.to_notify_queue.qsize() == 0
 
 
-def test_notifier_thread_run():
+def test_notifier_thread_run(notifier):
     requests = []
 
     class ReqMock:
@@ -116,16 +134,15 @@ def test_notifier_thread_run():
 
             return Result()
 
-    notifier = Notifier()
     notifier.set_token("guid00", "01234")
     notifier.new_message_for_guid("guid00")
     notifier.thread_run_one(ReqMock())
     url, data, timeout = requests[0]
     assert data == "01234"
-    assert len(notifier.guid2token) == 1
+    assert notifier.get_token("guid00") == "01234"
 
 
-def test_notifier_thread_run_gone_removes_token():
+def test_notifier_thread_run_gone_removes_token(notifier):
     requests = []
 
     class ReqMock:
@@ -137,11 +154,10 @@ def test_notifier_thread_run_gone_removes_token():
 
             return Result()
 
-    notifier = Notifier()
     notifier.set_token("guid00", "01234")
     notifier.new_message_for_guid("guid00")
-    assert notifier.guid2token["guid00"] == "01234"
+    assert notifier.get_token("guid00") == "01234"
     notifier.thread_run_one(ReqMock())
     url, data, timeout = requests[0]
     assert data == "01234"
-    assert len(notifier.guid2token) == 0
+    assert notifier.get_token("guid00") is None

cmdeploy/src/cmdeploy/__init__.py

@@ -350,15 +350,18 @@ def _configure_dovecot(config: Config, debug: bool = False) -> bool:
     need_restart |= lua_push_notification_script.changed
 
     sieve_script = files.put(
-        src=importlib.resources.files(__package__).joinpath(
-            "dovecot/default.sieve"
-        ),
+        src=importlib.resources.files(__package__).joinpath("dovecot/default.sieve"),
         dest="/etc/dovecot/default.sieve",
         user="root",
         group="root",
         mode="644",
     )
     need_restart |= sieve_script.changed
+    if sieve_script.changed:
+        server.shell(
+            name="compile sieve script",
+            commands=["/usr/bin/sievec /etc/dovecot/default.sieve"],
+        )
 
     files.template(
         src=importlib.resources.files(__package__).joinpath("dovecot/expunge.cron.j2"),
@@ -450,7 +453,9 @@ def check_config(config):
         blocked_words = "merlinux schmieder testrun.org".split()
         for key in config.__dict__:
             value = config.__dict__[key]
-            if key.startswith("privacy") and any(x in str(value) for x in blocked_words):
+            if key.startswith("privacy") and any(
+                x in str(value) for x in blocked_words
+            ):
                 raise ValueError(
                     f"please set your own privacy contacts/addresses in {config._inipath}"
                 )

cmdeploy/src/cmdeploy/acmetool/acmetool.cron

@@ -1,4 +1,4 @@
 SHELL=/bin/sh
 PATH=/bin:/sbin:/usr/bin:/usr/sbin:/usr/local/bin:/usr/local/sbin
 MAILTO=root
-20 16 * * * root /usr/bin/acmetool --batch reconcile
+20 16 * * * root /usr/bin/acmetool --batch reconcile && systemctl reload dovecot && systemctl reload postfix

cmdeploy/src/cmdeploy/dns.py

@@ -5,8 +5,6 @@ import importlib
 import subprocess
 import datetime
 
-from typing import Optional
-
 
 class DNS:
     def __init__(self, out, mail_domain):

cmdeploy/src/cmdeploy/dovecot/default.sieve

@@ -1,5 +1,7 @@
 require ["imap4flags"];
 
+# flag the message so it doesn't cause a push notification
+
 if header :is ["Auto-Submitted"] ["auto-replied", "auto-generated"] {
 	addflag "$Auto";
 }

cmdeploy/src/cmdeploy/tests/online/test_2_deltachat.py

@@ -63,7 +63,7 @@ class TestEndToEndDeltaChat:
 
         addr = ac2.get_config("addr").lower()
         saved_ok = 0
-        for line in remote.iter_output("journalctl -f -u dovecot"):
+        for line in remote.iter_output("journalctl -n0 -f -u dovecot"):
             if addr not in line:
                 # print(line)
                 continue
@@ -75,7 +75,7 @@ class TestEndToEndDeltaChat:
                         )
                     lp.indent("good, message sending failed because quota was exceeded")
                     return
-            if "saved mail to inbox" in line:
+            if "stored mail into mailbox 'inbox'" in line or "saved mail to inbox" in line:
                 saved_ok += 1
                 print(f"{saved_ok}: {line}")
                 if saved_ok >= num_to_send:
@@ -112,7 +112,7 @@ class TestEndToEndDeltaChat:
         lp.sec("ac1 sends a message and ac2 marks it as seen")
         chat = ac1.create_chat(ac2)
         msg = chat.send_text("hi")
-        m = ac2.wait_next_incoming_message()
+        m = ac2._evtracker.wait_next_incoming_message()
         m.mark_seen()
         # we can only indirectly wait for mark-seen to cause an smtp-error
         lp.sec("try to wait for markseen to complete and check error states")
@@ -132,7 +132,7 @@ def test_hide_senders_ip_address(cmfactory):
     chat = cmfactory.get_accepted_chat(user1, user2)
 
     chat.send_text("testing submission header cleanup")
-    user2.wait_next_incoming_message()
+    user2._evtracker.wait_next_incoming_message()
     user2.direct_imap.select_folder("Inbox")
     msg = user2.direct_imap.get_all_messages()[0]
     assert public_ip not in msg.obj.as_string()
@@ -146,5 +146,5 @@ def test_echobot(cmfactory, chatmail_config, lp):
     text = "hi, I hope you text me back"
     chat.send_text(text)
     lp.sec("Wait for reply from echobot")
-    reply = ac.wait_next_incoming_message()
+    reply = ac._evtracker.wait_next_incoming_message()
     assert reply.text == text