OpenDKIM fails to sign messages and crashes

[tyranron]

OpenDKIM verifies incoming message ok, but fails and crashes for outgoing (submission port).

Steps to reproduce

1. Pre-generate required credentials: make dkim-config && make ssl-cert
2. Start everything: docker-compose up
3. Open in browser mailserver-nginx container (127.0.0.1 or %dockermachine_ip% depending on your Docker installation) and log into Roundcube Webmail as test@domain.com user with qweqweqwe password.
4. Send any email message to somewhere.
5. Look at that message headers at receiver side. It does not contain any DKIM signatures.
6. Look at Docker logs of mailserver-opendkim container, you see something like Sep 30 08:36:27 b00868c2bab6 mail.notice opendkim[238]: terminated with signal 11, restarting

   OpenDKIM container logs

[s6-init] making user provided files available at /var/run/s6/etc...exited 0.
[s6-init] ensuring user provided files have correct perms...exited 0.
[fix-attrs.d] applying ownership & permissions fixes...
[fix-attrs.d] 01-cont-init-finish-jobs: applying... 
[fix-attrs.d] 01-cont-init-finish-jobs: exited 0.
[fix-attrs.d] done.
[cont-init.d] executing container initialization scripts...
[cont-init.d] 30-opendkim-data.sh: executing... 
[cont-init.d] 30-opendkim-data.sh: exited 0.
[cont-init.d] done.
[services.d] starting services
Sep 30 08:27:18 b00868c2bab6 syslog.info syslogd started: BusyBox v1.24.2
[services.d] done.
Sep 30 08:27:18 b00868c2bab6 mail.debug opendkim[240]: OpenDKIM Filter: Opening listen socket on conn inet:8891
Sep 30 08:27:18 b00868c2bab6 mail.info opendkim[240]: OpenDKIM Filter v2.10.3 starting (args: -f -x /etc/opendkim/opendkim.conf)
Sep 30 08:36:27 b00868c2bab6 mail.notice opendkim[238]: terminated with signal 11, restarting
Sep 30 08:36:27 b00868c2bab6 mail.debug opendkim[249]: OpenDKIM Filter: Opening listen socket on conn inet:8891
Sep 30 08:36:27 b00868c2bab6 mail.info opendkim[249]: OpenDKIM Filter v2.10.3 starting (args: -f -x /etc/opendkim/opendkim.conf)

Postfix container logs

...
Sep 30 08:36:27 mail mail.info postfix/submission/smtpd[278]: connect from mailserver-roundcube.dockermailserver_default[172.18.0.9]
Sep 30 08:36:27 mail mail.info postfix/submission/smtpd[278]: E741515B: client=mailserver-roundcube.dockermailserver_default[172.18.0.9], sasl_method=LOGIN, sasl_username=test@domain.com
Sep 30 08:36:27 mail mail.info postfix/cleanup[280]: E741515B: message-id=<7a6708f3fa262a8a99f90b72c6ed602c@domain.com>
Sep 30 08:36:27 mail mail.warn postfix/cleanup[280]: warning: milter inet:opendkim:8891: can't read SMFIC_EOH reply packet header: No error information
Sep 30 08:36:27 mail mail.info postfix/qmgr[260]: E741515B: from=<test@domain.com>, size=970, nrcpt=1 (queue active)
Sep 30 08:36:28 mail mail.info postfix/submission/smtpd[278]: disconnect from mailserver-roundcube.dockermailserver_default[172.18.0.9] ehlo=2 starttls=1 auth=1 mail=1 rcpt=1 data=1 quit=1 commands=8
Sep 30 08:36:28 mail mail.info postfix/smtpd[282]: connect from mailserver-amavis.dockermailserver_default[172.18.0.7]
Sep 30 08:36:28 mail mail.info postfix/smtpd[282]: DE8D515C: client=mailserver-amavis.dockermailserver_default[172.18.0.7]
Sep 30 08:36:28 mail mail.info postfix/cleanup[280]: DE8D515C: message-id=<7a6708f3fa262a8a99f90b72c6ed602c@domain.com>
Sep 30 08:36:28 mail mail.info postfix/qmgr[260]: DE8D515C: from=<test@domain.com>, size=1440, nrcpt=1 (queue active)
Sep 30 08:36:28 mail mail.info postfix/smtpd[282]: disconnect from mailserver-amavis.dockermailserver_default[172.18.0.7] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
Sep 30 08:36:28 mail mail.info postfix/smtp[281]: E741515B: to=<jobs.tyranron@gmail.com>, relay=amavis[172.18.0.7]:10024, delay=1, delays=0.05/0.02/0/0.93, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[postfix]:10025): 250 2.0.0 Ok: queued as DE8D515C)
Sep 30 08:36:28 mail mail.info postfix/qmgr[260]: E741515B: removed
Sep 30 08:36:29 mail mail.info postfix/smtp[283]: Trusted TLS connection established to gmail-smtp-in.l.google.com[74.125.133.27]:25: TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)
Sep 30 08:36:30 mail mail.info postfix/smtp[283]: DE8D515C: to=<jobs.tyranron@gmail.com>, relay=gmail-smtp-in.l.google.com[74.125.133.27]:25, delay=1.2, delays=0.01/0.02/0.89/0.33, dsn=2.0.0, status=sent (250 2.0.0 OK 1475224590 14si741653wje.234 - gsmtp)
Sep 30 08:36:30 mail mail.info postfix/qmgr[260]: DE8D515C: removed
...

OpenDKIM configuration

LogWhy                  Yes

Mode                    sv
Canonicalization        relaxed/simple
SignatureAlgorithm      rsa-sha256
RemoveOldSignatures     Yes
OversignHeaders         From

KeyTable                refile:/var/opendkim/KeyTable
SigningTable            refile:/var/opendkim/SigningTable
MTA                     ORIGINATING

# If remove, container will just stop on that crash
AutoRestart             Yes

# Enable all debuging
EnableCoredumps         Yes
KeepTemporaryFiles      Yes
MilterDebug             4
ResolverTracing         Yes
LogResults              Yes
SyslogSuccess           Yes

Conclusions

The problem is definitely in OpenDKIM. Verification goes fine without issues, but on signing it just crashes. The bad thing is that OpenDKIM is completely silent (with all debugging turned on) about crashing reason. Not even temporary files (option KeepTemporaryFiles) are created.

[tyranron]

Tried to rebuild image on top debian:stretch and everything works fine.

So moving OpenDKIM image to debian... 😢

[tyranron]

Need to post this issue somehow to Alpine packages bug tracker before closing it.

[tyranron]

Posted here

[tyranron]

The reason was in libmilter segfaults and was fixed with this commit. Now it works okay so we can revert OpenDKIM image back to Alpine.