feat: switch to another SMTP transport when current one returns an error

[link2xt]

Classic email servers sometimes start rejecting all messages and ask the user to solve web CAPTCHA, but still allow to connect.
In this case we want to switch to another SMTP server by moving the transport to the end of the list returned by smtp::sorted_transports.

We disconnect after any message sending failure, so next message or resent same message will be sent over another other transport.

Permanent SMTP error does not necessarily mean that switching to another server will help.
For example if the user tries to send a large message, any server will reject it, and it is not a failure of the server.
We do not try to distinguish between error messages, so it is expected that we may
sometimes switch to another server when it is unnecessary.

Follow-up to #8771

Closes #8804

[hpk42]

in python at least i am used to try to avoid shadowing names (here err shadows the err of the match arm it is in).

[Hocuri]

In general, in Rust, shadowing names is considered idiomatic in order to prevent accidentally using the outer or earlier variable, and to avoid needing to come up with new names. And I can't remember any problems in core that would have been avoided by avoiding shadowing; most of the related problems are avoided by the strict static analysis, anyway.

In this concrete example, either way of writing it seems fine to me.

[link2xt]

I tried enabling clippy::shadow_unrelated and started fixing some reported problems there, but there are a lot of them. Maybe will open a PR. Most of them I'd say are indeed idiomatic Rust, but some shadowing in huge functions in receive_imf looks suspicious.

Python is different because it does not create a new scope for loops and ifs, and does not have a separate syntax for bindings and assignment, so you risk assigning a variable from outer scope when you actually just wanted to have a temporary variable inside of an if or loop body.

clippy also has clippy::shadow_same and clippy::shadow_reuse, these look like separate lints moved out of clippy::shadow_unrelated for something that is even less likely to be a problem.

[hpk42]

So connect failures fail over to other transports.

But are you sure that send failures fall through to the next transport as well, in all cases?

As soon as a send failure does not effectively move smtp to the next transport, the loop can get stuck.

I'd rather err on moving to the next transport than repeating the last one.

[link2xt]

So connect failures fail over to other transports.

connect_configured fails over and ends up either connecting to something or failing to connect to any transport.

As soon as a send failure does not effectively move smtp to the next transport, the loop can get stuck.

Not sure which loop you talk about. There is a loop over all queued messages in send_smtp_messages and calls send_msg_to_smtp for each one. send_smtp_messages loop cannot get stuck because it selects all queued messages and tries them one after another, but only once. For example if it selects two messages, and first message fails with an error, it will remove success for the used transport, and then for the second message another transport will be used. First message will be sent later in another call to send_smtp_messages if the error was temporary.

SMTP loop in smtp_loop is infinite, but it is ratelimited and worst case even if you remove all ratelimits the messages will run out of retries.

[hpk42]

As soon as a send failure does not effectively move smtp to the next transport, the loop can get stuck.

Not sure which loop you talk about.

I should not have used the word loop here i guess. My point was more about the guaranteed advancing to the next transport on send failure of a message.

For example if it selects two messages, and first message fails with an error, it will remove success for the used transport, and then for the second message another transport will be used. First message will be sent later in another call to send_smtp_messages if the error was temporary.

I don't think this is true. Here is my understanding:

1. send_msg_to_smtp returns Err for both Retry and Failure, and send_smtp_messages exits the loop on it, smtp is disconnected. Let's assume it was a temporary error during send of a message, so next attempt will retry it (up to six attempts in total).

2. if there is no other transport with a success row, the next connect attempt falls back to the lowest transports.id: If that is the failed transport from step 1, the message is attempted for sending over it again.

It's also a problem in practice. Here is a bit of a hacky Python test (which nevertheless tests everything in context, which i think we must find ways of doing, because Rust unit or partial integration tests only go so far).

test_transient_trace.py

It sends a small pre-message (success), then a too-large full message with postfix configured to temp-fail instead of permanently fail. Here is a transcript of running that test against your branch (it takes a while because of retries: we need time-shifting in python), and note the -s to directly print output and not capture it.

(venv) hpk@gamma:~/chatmail/core (link2xt/smtp-permanent-error-failover)$ CHATMAIL_DOMAIN=_cm0.localchat pytest -s deltachat-rpc-client/tests/test_transient_trace.py 
============================================ test session starts ============================================
platform linux -- Python 3.12.12, pytest-9.1.1, pluggy-1.6.0
CHATMAIL_DOMAIN: _cm0.localchat
RPC-SERVER: /home/hpk/chatmail/core/venv/bin/deltachat-rpc-server [2.63.0-dev]
rootdir: /home/hpk/chatmail/core/deltachat-rpc-client
configfile: tox.ini
plugins: timeout-2.4.0, xdist-3.8.0, deltachat-rpc-client-2.63.0.dev0
timeout: 300.0s
timeout method: signal
timeout func_only: False
collected 1 item                                                                                            

deltachat-rpc-client/tests/test_transient_trace.py::test_transient_trace 
---------------------------------------------- live log setup -----------------------------------------------
INFO     root:rpc.py:144 RPC server ready. Core version: v2.63.0-dev

transports in id order: ['czq3r9qlr@_cm0.localchat', 'tsdpkzagu@_cm0.localchat']
big=Msg#14 two=Msg#15
   0.0s INFO src/smtp.rs:702: Selected rows from SMTP queue: [2, 3, 4].
   0.0s INFO src/smtp.rs:150: Trying to connect to transport 1.
   0.1s SMTP_CONNECTED SMTP-LOGIN as czq3r9qlr@_cm0.localchat ok
   0.1s INFO src/smtp.rs:547: Try number 1 to send message Msg#14 (entry 2) over SMTP.
   0.1s SMTP_MESSAGE_SENT Message len=3033 was SMTP-sent to 1 recipients.
   3.8s INFO src/smtp.rs:547: Try number 1 to send message Msg#14 (entry 3) over SMTP.
   4.1s INFO src/smtp.rs:281: SMTP failed to send: Transient(Response { code: Code { severity: TransientNegativeCompletion, category: MailSystem, detail: Two }, message: ["4.3.4 Error: message file too big"] }).
   4.1s INFO src/smtp.rs:354: Transient error Response { code: Code { severity: TransientNegativeCompletion, category: MailSystem, detail: Two }, message: ["4.3.4 Error: message file too big"] }, postponing retry for later.
   4.1s INFO src/smtp.rs:370: Failed to send message over SMTP, disconnecting.
   4.1s INFO src/scheduler.rs:676: SMTP has messages to retry, planning to retry 30 seconds later.
  34.1s INFO src/smtp.rs:702: Selected rows from SMTP queue: [3, 4].
  34.1s INFO src/smtp.rs:150: Trying to connect to transport 1.
  34.2s SMTP_CONNECTED SMTP-LOGIN as czq3r9qlr@_cm0.localchat ok
  38.2s INFO src/smtp.rs:547: Try number 2 to send message Msg#14 (entry 3) over SMTP.
  38.6s INFO src/smtp.rs:281: SMTP failed to send: Transient(Response { code: Code { severity: TransientNegativeCompletion, category: MailSystem, detail: Two }, message: ["4.3.4 Error: message file too big"] }).
  38.6s INFO src/smtp.rs:354: Transient error Response { code: Code { severity: TransientNegativeCompletion, category: MailSystem, detail: Two }, message: ["4.3.4 Error: message file too big"] }, postponing retry for later.
  38.6s INFO src/smtp.rs:370: Failed to send message over SMTP, disconnecting.
  38.6s INFO src/scheduler.rs:676: SMTP has messages to retry, planning to retry 49 seconds later.
  87.6s INFO src/smtp.rs:702: Selected rows from SMTP queue: [3, 4].
  87.6s INFO src/smtp.rs:150: Trying to connect to transport 1.
  87.6s SMTP_CONNECTED SMTP-LOGIN as czq3r9qlr@_cm0.localchat ok
  91.2s INFO src/smtp.rs:547: Try number 3 to send message Msg#14 (entry 3) over SMTP.
  91.5s INFO src/smtp.rs:281: SMTP failed to send: Transient(Response { code: Code { severity: TransientNegativeCompletion, category: MailSystem, detail: Two }, message: ["4.3.4 Error: message file too big"] }).
FAILED

================================================= FAILURES ==================================================
___________________________________________ test_transient_trace ____________________________________________

acf = <deltachat_rpc_client.pytestplugin.RPCAccountFactory object at 0x7b9fdf297da0>
tmp_path = PosixPath('/tmp/pytest-of-hpk/pytest-730/test_transient_trace0')

    @pytest.mark.usefixtures("soft_bounce")
    def test_transient_trace(acf, tmp_path):
        alice, bob = acf.get_online_accounts(2)
        alice.add_transport_from_qr(acf.get_account_qr())
        alice.bring_online()
        print("\ntransports in id order:", [t["addr"] for t in alice.list_transports()])
    
        bob.create_chat(alice)
        chat = alice.create_chat(bob)
        chat.send_text("one")
        while bob.wait_for_incoming_msg().get_snapshot().text != "one":
            pass
    
        # Queue pre/post messages while IO is stopped, so one send_smtp_messages() has both
        alice.stop_io()
        big = tmp_path / "big.bin"
        big.write_bytes(os.urandom(25 * 1024 * 1024))
        msg = chat.send_message(text="big", file=str(big))
        two = chat.send_text("two")
        print(f"big=Msg#{msg.id} two=Msg#{two.id}")
        alice.clear_all_events()
        start = time.monotonic()
        alice.start_io()
    
        tried_transports = []
        failures = 0
        while failures < 3:
            ev = alice.wait_for_event()
            t = time.monotonic() - start
            if ev.kind == EventType.INFO and any(k in ev.msg for k in KEYS):
                print(f"{t:6.1f}s INFO {ev.msg}")
                if m := re.search(r"Trying to connect to transport (\d+)\.", ev.msg):
                    tried_transports.append(int(m.group(1)))
                if "SMTP failed to send" in ev.msg:
                    failures += 1
            elif ev.kind == EventType.SMTP_CONNECTED:
                print(f"{t:6.1f}s SMTP_CONNECTED {ev.msg}")
            elif ev.kind == EventType.SMTP_MESSAGE_SENT:
                print(f"{t:6.1f}s SMTP_MESSAGE_SENT {ev.msg}")
            elif ev.kind == EventType.MSG_FAILED:
                print(f"{t:6.1f}s MSG_FAILED Msg#{ev.msg_id}")
                assert ev.msg_id != msg.id, "big failed permanently, soft_bounce not active"
>       assert len(set(tried_transports)) > 1, f"3 failed attempts, all on same transport {tried_transports[0]}"
E       AssertionError: 3 failed attempts, all on same transport 1
E       assert 1 > 1
E        +  where 1 = len({1})
E        +    where {1} = set([1, 1, 1])

deltachat-rpc-client/tests/test_transient_trace.py:77: AssertionError
-------------------------------------------- Captured log setup ---------------------------------------------
INFO     root:rpc.py:144 RPC server ready. Core version: v2.63.0-dev
========================================== short test summary info ==========================================
FAILED deltachat-rpc-client/tests/test_transient_trace.py::test_transient_trace - AssertionError: 3 failed attempts, all on same transport 1
======================================= 1 failed in 97.09s (0:01:37) =======================================

The full message is stuck with the first transport, and holds up all others (here: "two") 10+ minutes.
maybe_network interrupts may change that but that doesn't make the current handling correct.

Moreover, also with permanent errors there likely is a problem, see this Rust test:

/// Test that a transport that returned a permanent error
/// is not tried first again on the next connection.
#[tokio::test(flavor = "multi_thread", worker_threads = 2)]
async fn test_permanent_error_demotes_oldest_transport() -> Result<()> {
    let mut tcm = TestContextManager::new();
    let t = &tcm.unconfigured().await;

    transport::add_pseudo_transport(t, "classic@example.org").await?;
    transport::add_pseudo_transport(t, "relay@chatmail.example").await?;
    let transports = super::sorted_transports(t).await?;
    let classic_id = transports[0].0;
    let relay_id = transports[1].0;

    // Sending works over the classic transport, then it starts rejecting.
    super::record_success(t, classic_id).await?;
    super::remove_success(t, classic_id).await?;

    let transports = super::sorted_transports(t).await?;
    assert_eq!(transports[0].0, relay_id, "rejecting transport is tried first again");
    Ok(())
}

It fails on your branch as well. Now i am not claiming that my sketch tests are to be directly integrated. I just wanted to provide something reproducible, and to prove there are problems, and to make the point that we need to find ways to test things properly and in full context. It took me 3 hours now, but doing a release cycle and getting feedback from the wild, analyzing logfiles etc. and then doing another release is way more effort, and we would struggle to advance to next stages with smtp-sending code.

[link2xt]

I don't think this is true. Here is my understanding:

Yes, send_smtp_messages exits the loop on the first failure instead of sending the next message.

Anyway, since it is not about SMTP loops, but making sure that we eventually switch to the working relay, i pushed a commit that adds smtp_failure table similar to smtp_success and ordering the relays in this order:

1. Successful relays, most recently succeeded first.
2. Never tried relays, in the addition order
3. Failed relays, least recently failed first.

So now if all relays fail, we cycle through all of them and will eventually find the working one if there is any.

[Hocuri]

Nice to have more reliable transport selection

[Hocuri]

Right now, we record a failure only if the server returns an error code. There seem to be more errors that warrant switching relays, like timeouts because of a very slow connection or problems with parsing the response. What about recording a failure whenever send_result.is_err()? Then we will unnecessarily switch sending relays more often, but this seems fine.

Of course, it's hard to say what's really best here, since we don't know which real-world problems occur often.

[link2xt]

like timeouts because of a very slow connection or problems with parsing the response

In case of timeouts while connecting we will try second relay after timeout and record success for it, this is how it works already in 2.63.0 without this PR.

Misbehaving servers may be a problem (e.g. server dying each time after getting a message without returning any response, but this is theoretical). Most realistic problem is the servers which are timing out while receiving the message, e.g. because of middlebox blackholing the connection after a certain number of bytes is sent. Doing something about this scenario would be nice, but i don't think recording failure on timeout and moving the candidate to the end of the list on a single failure is a good idea because you will have false positives each time you switch the network or lose the connection while sending a message.

[Hocuri]

In general, in Rust, shadowing names is considered idiomatic in order to prevent accidentally using the outer or earlier variable, and to avoid needing to come up with new names. And I can't remember any problems in core that would have been avoided by avoiding shadowing; most of the related problems are avoided by the strict static analysis, anyway.

In this concrete example, either way of writing it seems fine to me.

[Hocuri]

Suggested change

	/// Removes last remembered success for SMTP transport so another transport is tried next time.
	/// Records a failure and removes last remembered success for
	/// SMTP transport so another transport is tried next time.

[Hocuri]

Suggested change

	// Remove recorded SMTP success on any error returned by the server, but not network errors.
	// Record failure on any error returned by the server, but not network errors.