#224 OpenDKIM is silent if SQL datasets + systemd service dependencies = not starting on boot

[Steve Jenkins]

As reported by George Notaras @ RedHat Bugzilla, if configured to use SQL datasets, OpenDKIM won't start on boot and is awfully quiet about it:

https://bugzilla.redhat.com/show_bug.cgi?id=1209009

If would be nice to figure out a way for OpenDKIM to spit out some sort of warning message if it:

a) is configured to use SQL datasets, and
b) fails a start attempt

Of course, there might be no way to be certain that the SQL + service dependency issue is reason it's not starting, but it still might be nice to have some sort of failure warning (via whatever logging mechanism OpenDKIM is configured to use) that gives users a first place to start looking.

I'm not sure if this also affects other systemd distros, but on the Fedora package side I plan to include a note in the configuration file and the README.Fedora file. But I also wanted to file a ticket here so that upstream is aware of the current functionality.

[Murray S. Kucherawy]

I can't see how this wouldn't log something on a data set load failure.

When the application starts, it tries to open everything, and an error there will be printed to stderr and result in an exit status of EX_CONFIG (78). Otherwise, it then becomes the user requested in the "User" setting, and repeats that operation in the child process (if "Background" and/or "AutoRestart" are set).

Is it possible that as root, all of the database operations succeed, but after dropping privileges, it can no longer load its data sets? In that case something should still be logged via syslog() so long as "Log" is enabled.

[Steve Jenkins]

I tested this on an F21 system, with a fresh install of opendkim:

# opendkim -V
opendkim: OpenDKIM Filter v2.10.1
    Compiled with OpenSSL 1.0.1k-fips 8 Jan 2015
    SMFI_VERSION 0x1000001
    libmilter version 1.0.1
    Supported signing algorithms:
        rsa-sha1
        rsa-sha256
    Supported canonicalization algorithms:
        relaxed
        simple
    Active code options:
        USE_DB
        USE_ODBX
    libopendkim 2.10.1:

I generated a default set of keys, then put the following entry as the KeyTable in opendkim.conf, which I knew would fail:

KeyTable dsn:mysql://opendkim:test123@localhost/opendkim/table=keytable?keycol=keyname?datacol=domain,selector,keypath

Then I attempted startup via systemd:

# /bin/systemctl start opendkim.service
Job for opendkim.service failed. See "systemctl status opendkim.service" and "journalctl -xe" for details.

[root@fedora-jenkins-org keys]# systemctl status opendkim
● opendkim.service - DomainKeys Identified Mail (DKIM) Milter
   Loaded: loaded (/usr/lib/systemd/system/opendkim.service; enabled)
   Active: failed (Result: exit-code) since Wed 2015-04-29 11:21:03 PDT; 14s ago
     Docs: man:opendkim(8)
           man:opendkim.conf(5)
           man:opendkim-genkey(8)
           man:opendkim-genzone(8)
           man:opendkim-testadsp(8)
           man:opendkim-testkey
           http://www.opendkim.org/docs.html
  Process: 2924 ExecStart=/usr/sbin/opendkim $OPTIONS (code=exited, status=78)
 Main PID: 2880 (code=exited, status=0/SUCCESS)

Apr 29 11:21:03 fedora-jenkins-org opendkim[2924]: opendkim: /etc/opendkim.conf: dsn:mysql://opendkim:test123@localhost/opendkim/table=keytable?keycol=keyname?dat...irectory")
Apr 29 11:21:03 fedora-jenkins-org systemd[1]: opendkim.service: control process exited, code=exited status=78
Apr 29 11:21:03 fedora-jenkins-org systemd[1]: Failed to start DomainKeys Identified Mail (DKIM) Milter.
Apr 29 11:21:03 fedora-jenkins-org systemd[1]: Unit opendkim.service entered failed state.
Apr 29 11:21:03 fedora-jenkins-org systemd[1]: opendkim.service failed.
Hint: Some lines were ellipsized, use -l to show in full.

So I'm thinking something else might be silencing the error on the reporter's system. As expected, OpenDKIM chokes loudly when a DB issue causes it to fail startup.

[George Notaras]

Hello, I am the original reporter of this issue.

I confirm that opendkim prints proper error messages in /var/log/messages.

For some weird reason I hadn't noticed those messages while testing opendkim or I had been expecting an error message in /var/log/maillog.

As far as I'm concerned this is not an issue.

Steve & Murray, thanks for looking into this and I'm really sorry for the false alarm.

Kind Regards,
George

[George Notaras]

@Murray: Why not print an informational message in the maillog as well? From what I've seen other milters (eg opendmarc) print such messages in the maillog. It would make sense.

Kind Regards,
George

[George Notaras]

Hi,

It turns out that every piece of email related software I've tried (postfix, spamassassin, dovecot, proxsmtp, opendmarc, spf-policyd) prints at least a short error message in the maillog.

I was wondering on what convention is the current behavior based upon and the aforementioned error message is not sent to the 'mail' syslog facility. Even if there is such a convention, the fact that all other software print errors to the maillog, makes opendkim's behavior somewhat unexpected.

Also, the help text of the 'SyslogFacility' is not informative enough about this behavior leading the user into thinking that all messages regardless of severety should be expected to be recorded to the 'mail' facility.

Log via calls to syslog(3) using the named facility. The facility names are the same as the ones allowed in syslog.conf(5). The default is "mail".

I'd suggest you took a second look into this. If you need more feedback, please let me know.

Thanks for all your work. This software is great regardless of the above.

George

[Murray S. Kucherawy]

I'm confused a little here. Isn't maillog (by which I mean /var/log/maillog on most recent systems) managed by syslogd, and specifically configured to be the aggregation of messages sent to the "mail" facility of syslog?

That is, aren't you asking for exactly the behavior being described there?

[Murray S. Kucherawy]

Ah, I missed the "as well".

The active principle, if there is one, of the logging opendkim uses is to use stderr to report problems until it has turned into a daemon, at which point stderr is no longer available (it's either closed, or maps to /dev/null, or something) so using syslog(3) becomes the typical way to log things.