Skip to content

Delivery attempt failed, reason: "context deadline exceeded" #842

Open

Description

@cuu508

Describe the bug

I'm running maddy 0.9.4, and noticed that about 12 hours ago deliveries to @hotmail.com addresses started to fail with:

May 11 06:34:29 maddy[286019]: submission: RCPT ok        {"msg_id":"71eef592","rcpt":"[redacted]@hotmail.com"}
May 11 06:34:29 maddy[286019]: submission: accepted        {"msg_id":"71eef592"}
May 11 06:34:36 maddy[286019]: delivery attempt failed        {"msg_id":"71eef592","rcpt":"[redacted]@hotmail.com","reason":"context deadline exceeded"}
May 11 06:34:36 maddy[286019]: will retry        {"attempts_count":{"[redacted]@hotmail.com":1},"msg_id":"71eef592","next_try_delay":"14m59.99999862s","rcpts":["[redacted]@hotmail.com"]}
May 11 06:49:41 maddy[286019]: delivery attempt failed        {"msg_id":"71eef592","rcpt":"[redacted]@hotmail.com","reason":"context deadline exceeded"}
May 11 06:49:41 maddy[286019]: will retry        {"attempts_count":{"[redacted]@hotmail.com":2},"msg_id":"71eef592","next_try_delay":"14m59.999998479s","rcpts":["[redacted]@hotmail.com"]}
[...]

The mesage would go back in the queue, and subsequent attempts would fail as well. In the logs there were no other interesting bits, no error message from the remote mail server.

After restarting maddy, the "context deadline exceeded" errors ceased, and emails to @hotmail.com addresses started to go out again. This indicates to me that there's potentially something wrong on the maddy side – it somehow got itself in a bad state it could not recover from.

Unfortunately I do not have more specific details for now. I realize that from what I described it may be impossible to figure out what precisely went wrong. But I want to report what I have for now anyway, and I will update if I find out more. I've now enabled debug logging in maddy configuration, and will look out for any reoccurences of the "context deadline exceeded" error.

Steps to reproduce

Unfortunately I do not know yet. The server has been running fine for a long time, this is the first time I've noticed something like this. Perhaps there's some weirdness from hotmail.com mail servers that triggered a bug in maddy, but no idea what it is.

Log files

See above

Configuration file

$(public_ip) = 1.2.3.4

hostname mail.example.org

openmetrics tcp://127.0.0.1:9749 { }

tls {
    loader acme {
        hostname mail.example.org
        email contact@example.org
        agreed
        challenge dns-01
        dns cloudflare {
            api_token "secret"
        }
    }
}

msgpipeline webhook {
    default_destination {
        check {
            command /usr/bin/curl -fsS -o /dev/null --data-binary @- https://example.org/hanbdle_bounce/
            command /usr/bin/cp /dev/stdin bounces/{msg_id}.txt
        }

        deliver_to dummy
    }
}

smtp tcp://$(public_ip):25 {
    limits {
        # Up to 20 msgs/sec across max. 20 SMTP connections.
        all rate 20 1s
        all concurrency 20
    }

    destination mail.example.org {
        deliver_to &webhook
    }

    default_destination {
        reject 551 5.7.1 "Delivery not authorized, message refused"
    }
}

submission tls://$(public_ip):465 {
    limits {
        # Up to 50 msgs/sec across any amount of SMTP connections.
        all rate 50 1s
    }

    auth pass_table static {
        entry smtpuser "secret"
    }

    modify {
        # Bounces should be delivered to us, not the main MX 
        replace_sender regexp "(.+)@example.org" "$1@mail.example.org"
    }

    source mail.example.org {
        default_destination {
            modify {
                dkim {
                    domains example.org
                    selector mail
                    sign_subdomains yes
                }
            }
            deliver_to &remote_queue
        }
    }

    default_source {
        reject 551 5.7.1 "Bad from address, we only accept email from example.org"
    }
}

target.queue remote_queue {
    # debug true
    target &outbound_delivery
    # retry for ~32 hours:
    max_tries 17
    max_parallelism 100

    autogenerated_msg_domain mail.example.org
    bounce {
        deliver_to &webhook
    }
}

target.remote outbound_delivery {
    # debug true
    local_ip $(public_ip)
    force_ipv4 true
    connect_timeout 1m
    conn_max_idle_time 30
    limits {
        # Up to 20 msgs/sec across max. 20 SMTP connections for each recipient domain.
        destination rate 20 1s
        destination concurrency 20
    }
    mx_auth {
        dane
        mtasts
    }
}

Environment information

  • maddy version: 0.9.4 linux/amd64 go1.26.2

Activity

  1. self-assigned this
    on May 15, 2026
  2. foxcpp commented on May 15, 2026

    @foxcpp
    Owner

    0.9.4 fixed destination limits being no-op. Apparently, it is also broken in other ways. Looking into it.

  3. reopened this on May 15, 2026
  4. foxcpp commented on May 15, 2026

    @foxcpp
    Owner

    fd6d880 might fix this. Apparently, limiter semaphore is not released correctly if MAIL or RCPT errors is received.

  5. cuu508 commented on May 18, 2026

    @cuu508
    ContributorAuthor

    I'm currently still running 0.9.4, and had this happen again. An excerpt from logs, now with debug enabled:

    May 18 05:04:02 maddy[1207244]: submission: RCPT ok        {"msg_id":"3b24958c","rcpt":"redacted@hotmail.com"}
    May 18 05:04:02 maddy[1207244]: submission: accepted        {"msg_id":"3b24958c"}
    May 18 05:04:02 maddy[1207244]: [debug] target.queue: starting delivery for 3b24958c
    May 18 05:04:02 maddy[1207244]: [debug] target.queue: waiting on delivery semaphore for 3b24958c
    May 18 05:04:02 maddy[1207244]: [debug] target.queue: delivery semaphore acquired for 3b24958c
    May 18 05:04:02 maddy[1207244]: [debug] using message ID = 3b24958c-6a0a81a2        {"msg_id":"3b24958c"}
    May 18 05:04:02 maddy[1207244]: [debug] target.StartDelivery OK        {"msg_id":"3b24958c"}
    May 18 05:04:02 maddy[1207244]: [debug] opening new connection        {"cache_ignored":false,"domain":"hotmail.com","msg_id":"3b24958c-6a0a81a2"}
    May 18 05:04:02 maddy[1207244]: [debug] trying        {"domain":"hotmail.com","msg_id":"3b24958c-6a0a81a2","remote_server":"hotmail-com.olc.protection.outlook.com."}
    May 18 05:04:02 maddy[1207244]: [debug] connected        {"local_addr":"123.123.123.123:42599","msg_id":"3b24958c-6a0a81a2","remote_addr":"52.101.73.13:25","remote_server":"hotmail-com.olc.protection.outlook.com."}
    May 18 05:04:07 maddy[1207244]: [debug] delivery.AddRcpt redacted@hotmail.com failed: context deadline exceeded        {"msg_id":"3b24958c"}
    May 18 05:04:07 maddy[1207244]: [debug] delivery.Abort (no accepted recipients)        {"msg_id":"3b24958c"}
    May 18 05:04:07 maddy[1207244]: [debug] errors: map[redacted@hotmail.com:context deadline exceeded]        {"msg_id":"3b24958c"}
    May 18 05:04:07 maddy[1207244]: delivery attempt failed        {"msg_id":"3b24958c","rcpt":"redacted@hotmail.com","reason":"context deadline exceeded"}
    May 18 05:04:07 maddy[1207244]: [debug] delay: 15m0s * 1.25 ^ (1 - 1)        {"msg_id":"3b24958c"}
    May 18 05:04:07 maddy[1207244]: will retry        {"attempts_count":{"redacted@hotmail.com":1},"msg_id":"3b24958c","next_try_delay":"14m59.99997662s","rcpts":["redacted@hotmail.com"]}
    May 18 05:19:07 maddy[1207244]: [debug] target.queue: starting delivery for 3b24958c
    May 18 05:19:07 maddy[1207244]: [debug] target.queue: waiting on delivery semaphore for 3b24958c
    May 18 05:19:07 maddy[1207244]: [debug] target.queue: delivery semaphore acquired for 3b24958c
    May 18 05:19:07 maddy[1207244]: [debug] using message ID = 3b24958c-6a0a852b        {"msg_id":"3b24958c"}
    May 18 05:19:07 maddy[1207244]: [debug] target.StartDelivery OK        {"msg_id":"3b24958c"}
    May 18 05:19:07 maddy[1207244]: [debug] opening new connection        {"cache_ignored":false,"domain":"hotmail.com","msg_id":"3b24958c-6a0a852b"}
    May 18 05:19:07 maddy[1207244]: [debug] trying        {"domain":"hotmail.com","msg_id":"3b24958c-6a0a852b","remote_server":"hotmail-com.olc.protection.outlook.com."}
    May 18 05:19:07 maddy[1207244]: [debug] connected        {"local_addr":"123.123.123.123:48791","msg_id":"3b24958c-6a0a852b","remote_addr":"52.101.68.1:25","remote_server":"hotmail-com.olc.protection.outlook.com."}
    May 18 05:19:12 maddy[1207244]: [debug] delivery.AddRcpt redacted@hotmail.com failed: context deadline exceeded        {"msg_id":"3b24958c"}
    May 18 05:19:12 maddy[1207244]: [debug] delivery.Abort (no accepted recipients)        {"msg_id":"3b24958c"}
    May 18 05:19:12 maddy[1207244]: [debug] errors: map[redacted@hotmail.com:context deadline exceeded]        {"msg_id":"3b24958c"}
    May 18 05:19:12 maddy[1207244]: delivery attempt failed        {"msg_id":"3b24958c","rcpt":"redacted@hotmail.com","reason":"context deadline exceeded"}
    May 18 05:19:12 maddy[1207244]: [debug] delay: 15m0s * 1.25 ^ (2 - 1)        {"msg_id":"3b24958c"}
    May 18 05:19:12 maddy[1207244]: will retry        {"attempts_count":{"redacted@hotmail.com":2},"msg_id":"3b24958c","next_try_delay":"14m59.99997548s","rcpts":["redacted@hotmail.com"]}
    
    
  6. cuu508 commented on May 25, 2026

    @cuu508
    ContributorAuthor

    For the past ~12 days I've been running a nightly maddy build with fd6d880 as the last commit. Just checked logs and I now see a slightly different "context deadline exceeded" message:

    May 23 06:34:58 maddy[2079781]: submission: RCPT ok        {"msg_id":"dfd7d07f","rcpt":"redacted@example.org"}
    May 23 06:34:58 maddy[2079781]: submission: accepted        {"msg_id":"dfd7d07f"}
    May 23 06:34:58 maddy[2079781]: [debug] target.queue: starting delivery for dfd7d07f
    May 23 06:34:58 maddy[2079781]: [debug] target.queue: waiting on delivery semaphore for dfd7d07f
    May 23 06:35:01 maddy[2079781]: [debug] target.queue: delivery semaphore acquired for dfd7d07f
    May 23 06:35:01 maddy[2079781]: [debug] using message ID = dfd7d07f-6a112e75        {"msg_id":"dfd7d07f"}
    May 23 06:35:01 maddy[2079781]: [debug] target.StartDelivery OK        {"msg_id":"dfd7d07f"}
    May 23 06:35:01 maddy[2079781]: reusing cached connection        {"domain":"example.org","local_addr":"1.2.3.4:50503","msg_id":"dfd7d07f-6a112e75","remote_addr":"52.101.194.13:25","transactions_counter":1}
    May 23 06:35:06 maddy[2079781]: [debug] delivery.AddRcpt redacted@example.org failed: TakeDest: dest: context deadline exceeded        {"msg_id":"dfd7d07f"}
    May 23 06:35:06 maddy[2079781]: [debug] delivery.Abort (no accepted recipients)        {"msg_id":"dfd7d07f"}
    May 23 06:35:06 maddy[2079781]: [debug] errors: map[redacted@example.org:TakeDest: dest: context deadline exceeded]        {"msg_id":"dfd7d07f"}
    May 23 06:35:06 maddy[2079781]: delivery attempt failed        {"msg_id":"dfd7d07f","rcpt":"redacted@example.org","reason":"TakeDest: dest: context deadline exceeded"}
    May 23 06:35:06 maddy[2079781]: [debug] delay: 15m0s * 1.25 ^ (1 - 1)        {"msg_id":"dfd7d07f"}
    May 23 06:35:06 maddy[2079781]: will retry        {"attempts_count":{"redacted@example.org":1},"msg_id":"dfd7d07f","next_try_delay":"14m59.99998689s","rcpts":["redacted@example.org"]}
    May 23 06:50:06 maddy[2079781]: [debug] target.queue: starting delivery for dfd7d07f
    May 23 06:50:06 maddy[2079781]: [debug] target.queue: waiting on delivery semaphore for dfd7d07f
    May 23 06:50:06 maddy[2079781]: [debug] target.queue: delivery semaphore acquired for dfd7d07f
    May 23 06:50:06 maddy[2079781]: [debug] using message ID = dfd7d07f-6a1131fe        {"msg_id":"dfd7d07f"}
    May 23 06:50:06 maddy[2079781]: [debug] target.StartDelivery OK        {"msg_id":"dfd7d07f"}
    May 23 06:50:06 maddy[2079781]: reusing cached connection        {"domain":"example.org","local_addr":"1.2.3.4:50169","msg_id":"dfd7d07f-6a1131fe","remote_addr":"52.101.9.17:25","transactions_counter":1}
    May 23 06:50:06 maddy[2079781]: [debug] delivery.AddRcpt redacted@example.org OK        {"msg_id":"dfd7d07f"}
    May 23 06:50:06 maddy[2079781]: [debug] using delivery.BodyNonAtomic        {"msg_id":"dfd7d07f"}
    May 23 06:50:07 maddy[2079781]: [debug] returning connection 1.2.3.4:50169 for example-org.mail.protection.outlook.com. to pool        {"msg_id":"dfd7d07f-6a1131fe"}
    May 23 06:50:07 maddy[2079781]: [debug] delivery.Commit OK        {"msg_id":"dfd7d07f"}
    May 23 06:50:07 maddy[2079781]: [debug] errors: map[]        {"msg_id":"dfd7d07f"}
    May 23 06:50:07 maddy[2079781]: delivered        {"attempt":2,"msg_id":"dfd7d07f","rcpt":"redacted@example.org"}
    May 23 06:50:07 maddy[2079781]: [debug] removed message from disk        {"msg_id":"dfd7d07f"}
    
  7. foxcpp commented on Oct 3, 2026

    @foxcpp
    Owner

    0.9.6 might fix this one.

  8. moved this from Triage to TODO in Maddy Mail Server Task Trackeron Oct 29, 2026
  9. moved this from TODO to In Progress in Maddy Mail Server Task Trackeron Oct 29, 2026
  10. moved this from In Progress to Ready for Release in Maddy Mail Server Task Trackeron Oct 29, 2026
  11. foxcpp commented on Oct 29, 2026

    @foxcpp
    Owner

    Another fix for source limiter will be in 0.9.7 release, not pushed to master yet.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

bugSomething isn't working.

Projects

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions