Docker-mailserver: Postfix terminating on signal 15

[maxisme]

Context

Here are my logs:

May  7 11:54:07 mail postfix/postscreen[7813]: PASS NEW [31.216.147.136]:48772
May  7 11:54:07 mail postfix/postscreen[7813]: warning: cannot connect to service private/smtpd: Connection refused
May  7 11:54:07 mail postfix/postscreen[7813]: PASS OLD [31.216.147.136]:48772
May  7 11:54:07 mail postfix/postscreen[7813]: DISCONNECT [31.216.147.136]:48772
May  7 11:54:10 mail postfix/master[8459]: daemon started -- version 3.4.8, configuration /etc/postfix
May  7 11:54:23 mail postfix/postscreen[9090]: CONNECT from [31.216.147.134]:33740 to [172.18.0.3]:25
May  7 11:54:23 mail postfix/dnsblog[9094]: warning: dnsblog_query: lookup error for DNS query 134.147.216.31.list.dnswl.org: Host or domain name not found. Name service error for name=134.147.216.31.list.dnswl.org type=A: Host not found, try again
May  7 11:54:25 mail postfix/master[8459]: terminating on signal 15

Which seem to happen on repeat but intermittently. I believe this is stopping emails being received.

Expected Behavior

Postfix to not restart

Actual Behavior

Postfix keeps restarting

Steps to Reproduce

$ docker-compose up -d with the below yml

Your Environment

• Amount of RAM available: 2GB
• Mailserver version used: latest
• Docker version used: Docker version 19.03.8, build afacb8b7f0
• Environment settings relevant to the config:

  mail:
    image: tvial/docker-mailserver:latest
    hostname: mail
    domainname: ${DOMAINNAME:?err}
    container_name: mail
    ports:
      - "25:25"
      - "143:143"
      - "587:587"
      - "993:993"
    volumes:
      - maildata:/var/mail
      - mailstate:/var/mail-state
      - maillogs:/var/log/mail
      - ./config/:/tmp/docker-mailserver/
      - ./config/postfix-policyd-spf.conf:/etc/postfix-policyd-spf-python/policyd-spf.conf
    cap_add:
      - NET_ADMIN
      - SYS_PTRACE
    dns: 1.1.1.1
    restart: always

• Any relevant stack traces ("Full trace" preferred):
  See above

[youtous]

Hi,
Did you tried using the minimal config without custom things such as ./config/postfix-policyd-spf.conf:/etc/postfix-policyd-spf-python/policyd-spf.conf?

I would recommend enabling postfix debug mode for a more detailed output.

Maybe not related, but did you investigated May 7 11:54:07 mail postfix/postscreen[7813]: warning: cannot connect to service private/smtpd: Connection refused?

Please provide the full trace log + your full config, it's a good starting point for debugging. You can also set DMS_DEBUG=1.

[maxisme]

Great thank you for getting back to me. Sorry how do I turn postfix debug mode on for this project? i.e what is the best way to add the smtpd -v?

Maybe not related, but did you investigated May 7 11:54:07 mail postfix/postscreen[7813]: warning: cannot connect to service private/smtpd: Connection refused?

I have not debugged that - any tips on where to look?

[youtous]

how do I turn postfix debug mode on for this project?

/etc/postfix/master.cf:
    smtp      inet  n       -       n       -       -       smtpd -v

A quick (but dirty) way to debug could be docker exec -it mail bash
Then you will be able to debug inside the container:

1. apt-get update && apt-get vim
2. vim /etc/postfix/master.cf
3. postfix reload

Logs are located in /var/logs/supervisorctl/, perhaps /var/logs/supervisorctl/postfix.log contains the reason of the crash.

[maxisme]

ahh okay will try that... except with nano ;)

[maxisme]

are you sure the logs are located in /var/logs/supervisorctl/? :

root@mail:/# cd /var/logs/supervisorctl/
bash: cd: /var/logs/supervisorctl/: No such file or directory

[maxisme]

So a way I am testing is to tail -f /var/log/mail/mail.log and clear then send an email and sometimes it works and sometimes it just returns:

May  7 12:53:12 mail postfix/master[17984]: terminating on signal 15
May  7 12:53:15 mail postfix/master[19791]: daemon started -- version 3.4.8, configuration /etc/postfix

or:

May  7 12:55:59 mail postfix/postscreen[21467]: CONNECT from [31.216.147.135]:57832 to [172.18.0.3]:25
May  7 12:55:59 mail postfix/dnsblog[21468]: warning: dnsblog_query: lookup error for DNS query 135.147.216.31.list.dnswl.org: Host or domain name not found. Name service error for name=135.147.216.31.list.dnswl.org type=A: Host not found, try again
May  7 12:56:00 mail postfix/master[19791]: terminating on signal 15
May  7 12:56:04 mail postfix/master[22141]: daemon started -- version 3.4.8, configuration /etc/postfix

I think that it is perhaps just bad timing with the termination? I am also thinking that signal 15 is a SIGTERM right so that means something external is killing it?

[maxisme]

An example of an email being received succesfully is:

May  7 12:57:39 mail postfix/postscreen[26029]: CONNECT from [31.216.147.136]:56194 to [172.18.0.3]:25
May  7 12:57:39 mail postfix/postscreen[26029]: PASS OLD [31.216.147.136]:56194
May  7 12:57:39 mail postfix/smtpd[26006]: table hash:/etc/aliases(0,lock|fold_fix|utf8_request) has changed -- restarting
May  7 12:57:40 mail postfix/smtpd[27232]: connect from lu5.api.example.com[31.216.147.136]
May  7 12:57:40 mail postfix/smtpd[27232]: Anonymous TLS connection established from lu5.api.example.com[31.216.147.136]: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
May  7 12:57:40 mail policyd-spf[27233]: prepend X-Comment: SPF skipped for whitelisted relay domain - client-ip=31.216.147.136; helo=lu5.api.example.com; [email protected]; receiver=<UNKNOWN> 
May  7 12:57:41 mail postfix/smtpd[27232]: 1BBDF1DF952: client=lu5.api.example.com[31.216.147.136]
May  7 12:57:41 mail postfix/cleanup[26017]: 1BBDF1DF952: message-id=<[email protected]>
May  7 12:57:41 mail opendkim[1149]: 1BBDF1DF952: lu5.api.example.com [31.216.147.136] not internal
May  7 12:57:41 mail opendkim[1149]: 1BBDF1DF952: not authenticated
May  7 12:57:41 mail opendkim[1149]: 1BBDF1DF952: DKIM verification successful
May  7 12:57:41 mail opendkim[1149]: 1BBDF1DF952: s=201611 d=example.com SSL 
May  7 12:57:41 mail opendmarc[1155]: 1BBDF1DF952: example.com pass
May  7 12:57:41 mail postfix/qmgr[26002]: 1BBDF1DF952: from=<[email protected]>, size=14819, nrcpt=1 (queue active)
May  7 12:57:41 mail postfix/smtpd[27232]: disconnect from lu5.api.example.com[31.216.147.136] ehlo=2 starttls=1 mail=1 rcpt=1 data=1 quit=1 commands=7
May  7 12:57:41 mail amavis[1469]: (01469-08) ESMTP :10024 /var/lib/amavis/tmp/amavis-20200507T124458-01469-D9Czbxhw: <[email protected]> -> <[email protected]> SIZE=14819 Received: from mail.domain.com ([127.0.0.1]) by localhost (mail.domain.com [127.0.0.1]) (amavisd-new, port 10024) with ESMTP for <[email protected]>; Thu,  7 May 2020 12:57:41 +0000 (UTC)
May  7 12:57:41 mail amavis[1469]: (01469-08) Checking: 7fdTsyIo6mvr [31.216.147.136] <[email protected]> -> <[email protected]>
May  7 12:57:41 mail amavis[1469]: (01469-08) p007 1 Content-Type: multipart/related
May  7 12:57:41 mail amavis[1469]: (01469-08) p008 1/1 Content-Type: multipart/alternative
May  7 12:57:41 mail amavis[1469]: (01469-08) p001 1/1/1 Content-Type: text/plain, 7bit, size: 325, SHA1 digest: 7a9969ed3d77b027f3e14ab10940596f6287b561
May  7 12:57:41 mail amavis[1469]: (01469-08) p002 1/1/2 Content-Type: text/html, QP, size: 6184, SHA1 digest: 910c9b2ff07adedaaf393c63848972b0b632fdf6
May  7 12:57:41 mail amavis[1469]: (01469-08) p003 1/2 Content-Type: image/png, base64, size: 2498, SHA1 digest: c55476cd3ad5a86af78e5a92d7a7a3295f6a7d61
May  7 12:57:41 mail amavis[1469]: (01469-08) p004 1/3 Content-Type: image/png, base64, size: 460, SHA1 digest: 01f442e9eb093c102200986f309d91a880c568e1
May  7 12:57:41 mail amavis[1469]: (01469-08) p005 1/4 Content-Type: image/png, base64, size: 534, SHA1 digest: 2a10440f09200742f828d018dce6d319670871d7
May  7 12:57:41 mail amavis[1469]: (01469-08) p006 1/5 Content-Type: image/png, base64, size: 589, SHA1 digest: 5c49ce7a0bce4bd5279b001e3eaec3fde755726c
May  7 12:57:41 mail postfix/smtpd[26020]: connect from localhost[127.0.0.1]
May  7 12:57:41 mail postfix/smtpd[26020]: 860D81DF956: client=localhost[127.0.0.1]
May  7 12:57:41 mail postfix/cleanup[26017]: 860D81DF956: message-id=<[email protected]>
May  7 12:57:41 mail postfix/smtpd[26020]: disconnect from localhost[127.0.0.1] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
May  7 12:57:41 mail postfix/qmgr[26002]: 860D81DF956: from=<[email protected]>, size=15243, nrcpt=1 (queue active)
May  7 12:57:41 mail amavis[1469]: (01469-08) 7fdTsyIo6mvr FWD from <[email protected]> -> <[email protected]>,  250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 860D81DF956
May  7 12:57:41 mail dovecot: lmtp(26022): Connect from local
May  7 12:57:41 mail amavis[1469]: (01469-08) Passed CLEAN {RelayedInbound}, [31.216.147.136]:56194 [31.216.147.136] <[email protected]> -> <[email protected]>, Queue-ID: 1BBDF1DF952, Message-ID: <[email protected]>, mail_id: 7fdTsyIo6mvr, Hits: -, size: 15028, queued_as: 860D81DF956, 308 ms
May  7 12:57:41 mail dovecot: lmtp([email protected])<26022><qD23IcUFtF6mZQAAoh8UkQ>: msgid=<[email protected]>: saved mail to INBOX
May  7 12:57:41 mail postfix/smtp[26018]: 1BBDF1DF952: to=<[email protected]>, relay=127.0.0.1[127.0.0.1]:10024, delay=1, delays=0.68/0/0.02/0.3, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 860D81DF956)
May  7 12:57:41 mail postfix/qmgr[26002]: 1BBDF1DF952: removed
May  7 12:57:41 mail postfix/lmtp[26021]: 860D81DF956: to=<[email protected]>, relay=mail.domain.com[/var/run/dovecot/lmtp], delay=0.04, delays=0.01/0/0/0.02, dsn=2.0.0, status=sent (250 2.0.0 <[email protected]> qD23IcUFtF6mZQAAoh8UkQ Saved)
May  7 12:57:41 mail postfix/qmgr[26002]: 860D81DF956: removed
May  7 12:57:41 mail dovecot: lmtp(26022): Disconnect from local: Client has quit the connection (state=READY)
May  7 12:57:41 mail amavis[1469]: (01469-08) size: 15028, TIMING [total 323 ms] - SMTP greeting: 9 (3%)3, SMTP EHLO: 1.4 (0%)3, SMTP pre-MAIL: 0.7 (0%)3, SMTP MAIL: 2.7 (1%)4, SMTP pre-DATA-flush: 3.2 (1%)5, SMTP DATA: 42 (13%)18, check_init: 1.1 (0%)18, digest_hdr: 0.8 (0%)19, digest_body: 0.4 (0%)19, collect_info: 2.7 (1%)20, mime_decode: 68 (21%)41, get-file-type6: 104 (32%)73, parts_decode: 0.5 (0%)73, check_header: 0.8 (0%)73, decide_mail_destiny: 2.5 (1%)74, notif-quar: 0.5 (0%)74, fwd-connect: 29 (9%)83, fwd-mail-pip: 12 (4%)87, fwd-rcpt-pip: 0.3 (0%)87, fwd-data-chkpnt: 0.1 (0%)87, write-header: 0.6 (0%)87, fwd-data-contents: 0.3 (0%)88, fwd-end-chkpnt: 9 (3%)90, prepare-dsn: 1.2 (0%)91, report: 5 (2%)92, main_log_entry: 11 (3%)95, update_snmp: 4.3 (1%)97, SMTP pre-response: 0.5 (0%)97, SMTP response: 0.2 (0%)97, unlink-6-files: 8 (3%)100, rundown: 1.1 (0%)100
May  7 12:57:41 mail postfix/master[25999]: terminating on signal 15
May  7 12:57:44 mail postfix/master[27899]: daemon started -- version 3.4.8, configuration /etc/postfix

[youtous]

are you sure the logs are located in /var/logs/supervisorctl/? :

Ooops, /var/log/supervisor/postfix.log

I am also thinking that signal 15 is a SIGTERM right so that means something external is killing it?

Indeed, it could be https://github.com/tomav/docker-mailserver/blob/master/target/check-for-changes.sh or something else (plugin...)

[maxisme]

Oh! I am adding a new user before sending the email! Which causes a restart!! Sorry this was stupid of me! Thank you haha!

[casperklein]

@maxisme There is another issue:

May  7 11:54:23 mail postfix/dnsblog[9094]: warning: dnsblog_query: lookup error for DNS query 134.147.216.31.list.dnswl.org: Host or domain name not found. Name service error for name=134.147.216.31.list.dnswl.org type=A: Host not found, try again

Most DNS blacklist provider rate limit their service. When the limit is reached, they reply with a SRVFAIL:

dig 134.147.216.31.list.dnswl.org @1.1.1.1

; <<>> DiG 9.11.5-P4-5.1-Debian <<>> 134.147.216.31.list.dnswl.org @1.1.1.1
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: SERVFAIL, id: 25841
;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 1452
;; QUESTION SECTION:
;134.147.216.31.list.dnswl.org. IN      A

;; Query time: 2 msec
;; SERVER: 1.1.1.1#53(1.1.1.1)
;; WHEN: Thu May 07 21:22:39 CEST 2020
;; MSG SIZE  rcvd: 58

That's the reason for the DNS lookup error in your logs. To avoid that, you shouldn't use a public DNS (1.1.1.1) for DNS BL lookups.

[youtous]

Further reading https://github.com/tomav/docker-mailserver/issues/948

Seen docker is using Google DNS (8.8.8.8) by default when host dns are not available/or are local, we should document this. I'm suspecting a lot of users have the dnsblog_query failing without noticing.

EDIT: We could add it in docker-compose.yml.dist (like https://github.com/zokradonh/kopano-docker/commit/a52a4b9eaacd343669f791ba409a8f5a5b011d11). I'll add it in the wiki.