OpenDKIM が起動していなかったので、 systemd の設定を直した

何気なくサーバのログ眺めているときに、 /var/log/mail.info に気になるものを発見。

May  5 13:53:50 nexus01 postfix/smtpd[25332]: warning: connect to Milter service inet:[127.0.0.1]:54321: Connection refused
May  5 13:53:50 nexus01 postfix/smtpd[25332]: lost connection after CONNECT from nexus01.downtown.jp[127.0.0.1]
May  5 13:53:50 nexus01 postfix/smtpd[25332]: disconnect from nexus01.downtown.jp[127.0.0.1] commands=0/0

OpenDKIM が起動していなくて、メール処理時の DKIM による認証処理が、ここしばらくずっと止まっていた模様。(おそらく、数ヶ月単位で…。orz)

まずは切り分け

原因を突き止めねばらなんということで、まずは OpenDKIM の起動を試みるも、下のようなメッセージを吐くだけで、起動せず。

nexus01:~# service opendkim start
Job for opendkim.service failed because the control process exited with error code. See "systemctl status opendkim.service" and "journalctl -xe" for details.

メッセージ中にある通り、systemctl で OpenDKIM のステータスを見ると、 opendkim の起動がうまくいってないのが明らか。

nexus01:~# systemctl status opendkim.service | more
● opendkim.service - DomainKeys Identified Mail (DKIM) Milter
   Loaded: loaded (/lib/systemd/system/opendkim.service; enabled; vendor preset: enabled)
   Active: failed (Result: exit-code) since 木 2016-05-05 14:05:41 JST; 3s 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: 779 ExecStart=/usr/sbin/opendkim -x /etc/opendkim.conf -u opendkim -P /var/run/opendkim/opendkim.pid -p $SOCKET $DAEMON_OPTS (code=exited, status=64)
  Process: 776 ExecStartPre=/bin/chown opendkim.opendkim /var/run/opendkim (code=exited, status=0/SUCCESS)
  Process: 773 ExecStartPre=/bin/mkdir -p /var/run/opendkim (code=exited, status=0/SUCCESS)
 5月 05 14:05:41 nexus01 systemd[1]: Starting DomainKeys Identified Mail (DKIM) Milter...
 5月 05 14:05:41 nexus01 systemd[1]: opendkim.service: Control process exited, code=exited status=64
 5月 05 14:05:41 nexus01 systemd[1]: Failed to start DomainKeys Identified Mail (DKIM) Milter.
 5月 05 14:05:41 nexus01 systemd[1]: opendkim.service: Unit entered failed state.
 5月 05 14:05:41 nexus01 systemd[1]: opendkim.service: Failed with result 'exit-code'.

OpenDKIM 起動時に付与される $SOCKET や $DAEMON_OPTS は /etc/default/opendikim で定義されているので、

nexus01:~# grep -E "(DAEMON_OPTS|SOCKET)" /etc/default/opendkim
#DAEMON_OPTS=""
#SOCKET="local:/var/run/opendkim/opendkim.sock" # default
SOCKET="inet:54321" # listen on all interfaces on port 54321
#SOCKET="inet:12345@localhost" # listen on loopback on port 12345
#SOCKET="inet:12345@192.0.2.1" # listen on 192.0.2.1 on port 12345

その内容に従ってコマンドラインで直接起動すると

nexus01:~#/usr/sbin/opendkim -x /etc/opendkim.conf -u opendkim -P /var/run/opendkim/opendkim.pid -p inet:54321

問題なく起動することが確認できたので、OpenDKIM 自身の設定がおかしいということではなくて、systemd 周りに原因がありそうだ、と。


対処はある意味、力技?

では、どこをどう直すかということになるわけですが、"systemctl status opendkim.service" の内容から推測するに /etc/default/opendkim で設定されている SOCKET と DAEMON_OPTS の内容を正しく取得できていないことが、起動できない原因のようなので、そのあたりを修正すれば良いというのは判る。
手っ取り早く対処するとすれば、 systemd が OpenDKIM を起動するための設定ファイルを直接いじっちゃえばよいのだけど、そのためのファイルは /lib/systemd/system/opendkim.service/etc/init.d/opendkim.service の 2 つが存在している。
で、どっちを直せば正解かというと、 /lib/systemd/system/opendkim.service のほうが正解。(両方、試したので…。)

/lib/systemd/system/opendkim.service の "ExecStart=" の -p の後ろの $SOCKET を "inet:54321" に置き換えて、 $DAEMON_OPTS は削除したのが、以下のもの。

# If you are using OpenDKIM with SQL datasets it might be necessary to start OpenDKIM after the database servers.
# For example, if using both MariaDB and PostgreSQL, change "After=" in the "[Unit]" section to:
# After=network.target nss-lookup.target syslog.target mariadb.service postgresql.service
[Unit]
Description=DomainKeys Identified Mail (DKIM) Milter
Documentation=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
After=network.target nss-lookup.target

[Service] Type=forking EnvironmentFile=-/etc/default/opendkim PIDFile=/var/run/opendkim/opendkim.pid PermissionsStartOnly=true User=opendkim Group=opendkim ExecStartPre=-/bin/mkdir -p /var/run/opendkim ExecStartPre=-/bin/chown opendkim.opendkim /var/run/opendkim #ExecStart=/usr/sbin/opendkim -x /etc/opendkim.conf -u opendkim -P /var/run/opendkim/opendkim.pid -p $SOCKET $DAEMON_OPTS ExecStart=/usr/sbin/opendkim -x /etc/opendkim.conf -u opendkim -P /var/run/opendkim/opendkim.pid -p inet:54321 TimeoutStartSec=10 ExecReload=/bin/kill -USR1 $MAINPID
[Install] WantedBy=multi-user.target

18 行目が元々の設定をコメント化したもので、 19 行目が新たに書き足したもの。

これで起動して、"systemctl status opendkim.service" で状態を確認すると。

nexus01:~# service opendkim start
nexus01:~# systemctl status opendkim.service | more
● opendkim.service - DomainKeys Identified Mail (DKIM) Milter
   Loaded: loaded (/lib/systemd/system/opendkim.service; enabled; vendor preset: enabled)
   Active: failed (Result: exit-code) since 木 2016-05-05 14:14:15 JST; 16s 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: 4397 ExecStart=/usr/sbin/opendkim -x /etc/opendkim.conf -u opendkim -P /var/run/opendkim/opendkim.pid -p inet:54321 (code=exited, status=0/SUCCESS)
  Process: 4393 ExecStartPre=/bin/chown opendkim.opendkim /var/run/opendkim (code=exited, status=0/SUCCESS)
  Process: 4389 ExecStartPre=/bin/mkdir -p /var/run/opendkim (code=exited, status=0/SUCCESS)
 Main PID: 4401 (code=exited, status=69)
 5月 05 14:14:15 nexus01 systemd[1]: Starting DomainKeys Identified Mail (DKIM) Milter...
 5月 05 14:14:15 nexus01 systemd[1]: Started DomainKeys Identified Mail (DKIM) Milter.
 5月 05 14:14:15 nexus01 systemd[1]: opendkim.service: Main process exited, code=exited, status=69/n/a
 5月 05 14:14:15 nexus01 systemd[1]: opendkim.service: Unit entered failed state.
 5月 05 14:14:15 nexus01 systemd[1]: opendkim.service: Failed with result 'exit-code'.

opendkim 実行時のステータスが "SUCCESS" になり、ログにも正常起動したことを示す内容が記録されたので、対処完了。

May  5 14:14:15 nexus01 opendkim[4401]: OpenDKIM Filter: Unable to bind to port inet:54321: Address already in use
May  5 14:14:15 nexus01 opendkim[4401]: OpenDKIM Filter: Unable to create listening socket on conn inet:54321
May  5 14:14:15 nexus01 opendkim[4401]: smfi_opensocket() failed

本来ならば、/etc/default/opendikim の内容を systemd で正しくパースして反映されるように直すべきなのでしょうけど、今回は力技的な対処まで、ということで。
気分がノッたら、もう少し頑張って原因追求と対処をしてみます。

トラックバック(0)

コメントする