Problems with Emailserver update (rspamd)

pa3hfj · October 6, 2018, 2:33pm

NethServer Version: 7.5.1804 (final)
Module: mail

Hello to all,

Today I executed the pending updates on my Nethserver installation, it had mostly to do with the emailserver. During the update there were several errors in the messages logfile concerning the rspamd service mainly “fragment generated warnings”. Also, in the filter tab of the email configuration the three checkboxes are not selected and if I do and activate the same fragment warnings appear in the log and the checkboxes are deselected again.

afbeelding

Sorry for the Dutch interface language above

Below I included the loglines from the initial update. What went wrong here and how can I solve it?

Greetings, Wijnand.

Oct  6 15:40:27 server1 yum[1003]: Updated: nethserver-mail-common-2.3.0-1.ns7.noarch
Oct  6 15:40:29 server1 yum[1003]: Installed: nethserver-mail-filter-2.3.0-1.ns7.noarch
Oct  6 15:40:31 server1 yum[1003]: Updated: nethserver-sssd-1.4.2-1.ns7.noarch
Oct  6 15:40:33 server1 yum[1003]: Updated: nethserver-mail-server-2.3.0-1.ns7.noarch
Oct  6 15:40:35 server1 yum[1003]: Installed: nethserver-mail-getmail-2.3.0-1.ns7.noarch
Oct  6 15:40:36 server1 yum[1003]: Updated: nethserver-dc-1.5.6-1.ns7.x86_64
Oct  6 15:40:38 server1 yum[1003]: Installed: nethserver-mail-p3scan-2.3.0-1.ns7.noarch
Oct  6 15:40:38 server1 yum[1003]: Updated: nethserver-mail-disclaimer-2.3.0-1.ns7.noarch
Oct  6 15:40:39 server1 yum[1003]: Updated: php-kolab-net-ldap3-1.0.7-2.el7.noarch
Oct  6 15:40:40 server1 yum[1003]: Updated: nethserver-lang-en-1.2.15-1.ns7.noarch
Oct  6 15:40:41 server1 yum[1003]: Updated: nethserver-mail-smarthost-2.3.0-1.ns7.noarch
Oct  6 15:40:45 server1 yum[1003]: Updated: nethserver-lang-nl-1.2.15-1.ns7.noarch
Oct  6 15:40:45 server1 yum[1003]: Erased: nethserver-getmail-1.0.4-1.ns7.noarch
Oct  6 15:40:47 server1 yum[1003]: Erased: nethserver-p3scan-1.1.3-1.ns7.noarch
Oct  6 15:40:49 server1 systemd: Reloading.
Oct  6 15:40:55 server1 yum[1003]: Erased: nethserver-spamd-1.0.1-1.ns7.noarch
Oct  6 15:45:01 server1 systemd: Started Session 15521 of user root.
Oct  6 15:45:01 server1 systemd: Starting Session 15521 of user root.
Oct  6 15:45:01 server1 systemd: Started Session 15520 of user root.
Oct  6 15:45:01 server1 systemd: Starting Session 15520 of user root.
Oct  6 15:45:01 server1 systemd: Started Session 15522 of user root.
Oct  6 15:45:01 server1 systemd: Starting Session 15522 of user root.
Oct  6 15:45:01 server1 systemd: Started Session 15519 of user root.
Oct  6 15:45:01 server1 systemd: Starting Session 15519 of user root.
Oct  6 15:45:01 server1 systemd: Started Session 15523 of user root.
Oct  6 15:45:01 server1 systemd: Starting Session 15523 of user root.
Oct  6 15:45:01 server1 systemd: Started Session 15524 of user root.
Oct  6 15:45:01 server1 systemd: Starting Session 15524 of user root.
Oct  6 15:45:01 server1 systemd: Started Session 15525 of user root.
Oct  6 15:45:01 server1 systemd: Starting Session 15525 of user root.
Oct  6 15:45:01 server1 systemd: Started Session 15527 of user root.
Oct  6 15:45:01 server1 systemd: Starting Session 15527 of user root.
Oct  6 15:45:01 server1 systemd: Started Session 15526 of user root.
Oct  6 15:45:01 server1 systemd: Starting Session 15526 of user root.
Oct  6 15:45:02 server1 esmith::event[1932]: Event: nethserver-mail-filter-save
Oct  6 15:45:02 server1 esmith::event[1932]: expanding /var/lib/nethserver/sieve-scripts/before.sieve
Oct  6 15:45:02 server1 dbus[894]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service'
Oct  6 15:45:02 server1 systemd: Starting Time &amp; Date Service...
Oct  6 15:45:02 server1 dbus[894]: [system] Successfully activated service 'org.freedesktop.timedate1'
Oct  6 15:45:03 server1 systemd: Started Time &amp; Date Service.
Oct  6 15:45:03 server1 esmith::event[1932]: expanding /etc/dnsmasq.conf
Oct  6 15:45:03 server1 esmith::event[1932]: expanding /etc/rspamd/whitelist_to_domains.map
Oct  6 15:45:03 server1 esmith::event[1932]: expanding /etc/rspamd/whitelist_from.map
Oct  6 15:45:03 server1 esmith::event[1932]: expanding /etc/rspamd/rspamd.conf
Oct  6 15:45:03 server1 esmith::event[1932]: WARNING in /etc/e-smith/templates//etc/rspamd/rspamd.conf/20Options: Use of uninitialized value $esmith::__TEMPLATE__::5::rspamd{"SpamCheckStatus"} in string eq at /etc/e-smith/templates//etc/rspamd/rspamd.conf/20Options line 10.
Oct  6 15:45:03 server1 esmith::event[1932]: WARNING: Template processing succeeded for //etc/rspamd/rspamd.conf: 1 fragment generated warnings
Oct  6 15:45:03 server1 esmith::event[1932]: at /etc/e-smith/events/actions/generic_template_expand line 64.
Oct  6 15:45:03 server1 esmith::event[1932]: expanding /etc/rspamd/whitelist_to.map
Oct  6 15:45:03 server1 esmith::event[1932]: expanding /etc/rspamd/blacklist_from_domains.map
Oct  6 15:45:03 server1 esmith::event[1932]: expanding /etc/rspamd/whitelist_from_domains.map
Oct  6 15:45:03 server1 esmith::event[1932]: expanding /etc/rspamd/forbidden_file_extension.map
Oct  6 15:45:03 server1 esmith::event[1932]: WARNING in /etc/e-smith/templates//etc/rspamd/forbidden_file_extension.map/10base: Use of uninitialized value $esmith::__TEMPLATE__::9::rspamd{"BlockAttachmentStatus"} in string eq at /etc/e-smith/templates//etc/rspamd/forbidden_file_extension.map/10base line 5.
Oct  6 15:45:03 server1 esmith::event[1932]: WARNING: Template processing succeeded for //etc/rspamd/forbidden_file_extension.map: 1 fragment generated warnings
Oct  6 15:45:03 server1 esmith::event[1932]: at /etc/e-smith/events/actions/generic_template_expand line 64.
Oct  6 15:45:03 server1 esmith::event[1932]: expanding /etc/rspamd/blacklist_from.map
Oct  6 15:45:03 server1 esmith::event[1932]: expanding /etc/rspamd/rspamd.conf.override
Oct  6 15:45:04 server1 esmith::event[1932]: expanding /etc/rspamd/override.d/metrics.conf
Oct  6 15:45:04 server1 esmith::event[1932]: expanding /etc/rspamd/local.d/greylist.conf
Oct  6 15:45:04 server1 esmith::event[1932]: expanding /etc/rspamd/local.d/multimap.conf
Oct  6 15:45:04 server1 esmith::event[1932]: WARNING in /etc/e-smith/templates//etc/rspamd/local.d/multimap.conf/10base: Use of uninitialized value $esmith::__TEMPLATE__::13::rspamd{"SpamCheckStatus"} in string eq at /etc/e-smith/templates//etc/rspamd/local.d/multimap.conf/10base line 4.
Oct  6 15:45:04 server1 esmith::event[1932]: WARNING in /etc/e-smith/templates//etc/rspamd/local.d/multimap.conf/10base: Use of uninitialized value $esmith::__TEMPLATE__::13::rspamd{"BlockAttachmentStatus"} in string eq at /etc/e-smith/templates//etc/rspamd/local.d/multimap.conf/10base line 88.
Oct  6 15:45:04 server1 esmith::event[1932]: WARNING: Template processing succeeded for //etc/rspamd/local.d/multimap.conf: 2 fragments generated warnings
Oct  6 15:45:04 server1 esmith::event[1932]: at /etc/e-smith/events/actions/generic_template_expand line 64.
Oct  6 15:45:04 server1 esmith::event[1932]: expanding /etc/rspamd/local.d/antivirus.conf
Oct  6 15:45:04 server1 esmith::event[1932]: expanding /etc/rspamd/local.d/actions.conf
Oct  6 15:45:04 server1 esmith::event[1932]: WARNING in /etc/e-smith/templates//etc/rspamd/local.d/actions.conf/10base: Use of uninitialized value $esmith::__TEMPLATE__::15::rspamd{"SpamSubjectPrefixString"} in concatenation (.) or string at /etc/e-smith/templates//etc/rspamd/local.d/actions.conf/10base line 13.
Oct  6 15:45:04 server1 esmith::event[1932]: WARNING: Template processing succeeded for //etc/rspamd/local.d/actions.conf: 1 fragment generated warnings
Oct  6 15:45:04 server1 esmith::event[1932]: at /etc/e-smith/events/actions/generic_template_expand line 64.
Oct  6 15:45:04 server1 esmith::event[1932]: expanding /etc/postfix/main.cf
Oct  6 15:45:04 server1 esmith::event[1932]: WARNING in /etc/e-smith/templates//etc/postfix/main.cf/01dkim_milter: Use of uninitialized value $esmith::__TEMPLATE__::16::opendkim{"status"} in string eq at /etc/e-smith/templates//etc/postfix/main.cf/01dkim_milter line 6.
Oct  6 15:45:04 server1 esmith::event[1932]: WARNING in /etc/e-smith/templates//etc/postfix/main.cf/01template_vars_milter_mail_macros_rspamd: Use of uninitialized value $esmith::__TEMPLATE__::16::rspamd{"status"} in string eq at /etc/e-smith/templates//etc/postfix/main.cf/01template_vars_milter_mail_macros_rspamd line 4.
Oct  6 15:45:04 server1 esmith::event[1932]: WARNING in /etc/e-smith/templates//etc/postfix/main.cf/01template_vars_rspamd: Use of uninitialized value $esmith::__TEMPLATE__::16::rspamd{"status"} in string eq at /etc/e-smith/templates//etc/postfix/main.cf/01template_vars_rspamd line 5.
Oct  6 15:45:04 server1 esmith::event[1932]: WARNING: Template processing succeeded for //etc/postfix/main.cf: 3 fragments generated warnings
Oct  6 15:45:04 server1 esmith::event[1932]: at /etc/e-smith/events/actions/generic_template_expand line 64.
Oct  6 15:45:04 server1 esmith::event[1932]: expanding /etc/postfix/sender_access
Oct  6 15:45:04 server1 esmith::event[1932]: WARNING in /etc/e-smith/templates//etc/postfix/sender_access/10sender_wbl: Use of uninitialized value in split at /etc/e-smith/templates//etc/postfix/sender_access/10sender_wbl line 7.
Oct  6 15:45:04 server1 esmith::event[1932]: WARNING in /etc/e-smith/templates//etc/postfix/sender_access/10sender_wbl: Use of uninitialized value in split at /etc/e-smith/templates//etc/postfix/sender_access/10sender_wbl line 8.
Oct  6 15:45:04 server1 esmith::event[1932]: WARNING: Template processing succeeded for //etc/postfix/sender_access: 2 fragments generated warnings
Oct  6 15:45:04 server1 esmith::event[1932]: at /etc/e-smith/events/actions/generic_template_expand line 64.
Oct  6 15:45:04 server1 esmith::event[1932]: expanding /etc/pam.d/rspamd
Oct  6 15:45:04 server1 esmith::event[1932]: Action: /etc/e-smith/events/actions/generic_template_expand SUCCESS [1.598786]
Oct  6 15:45:08 server1 esmith::event[1932]: Action: /etc/e-smith/events/nethserver-mail-filter-save/S10nethserver-mail-postmap-update SUCCESS [4.009232]
Oct  6 15:45:08 server1 esmith::event[1932]: [INFO] service rspamd is not configured: skipped
Oct  6 15:45:08 server1 systemd: Reloading.
Oct  6 15:45:08 server1 esmith::event[1932]: [INFO] service postfix reload
Oct  6 15:45:09 server1 postfix: /usr/sbin/postconf: warning: /etc/postfix/main.cf: unused parameter: submission_smtpd_milters=
Oct  6 15:45:11 server1 systemd: Reloaded Postfix Mail Transport Agent.
Oct  6 15:45:11 server1 systemd: Reloading.
Oct  6 15:45:11 server1 esmith::event[1932]: [INFO] service httpd-admin reload
Oct  6 15:45:13 server1 systemd: Reloaded Server Manager UI httpd instance.
Oct  6 15:45:13 server1 esmith::event[1932]: Action: /etc/e-smith/events/actions/adjust-services SUCCESS [5.345969]
Oct  6 15:45:13 server1 esmith::event[1932]: Event: nethserver-mail-filter-save SUCCESS

mrmarkuz · October 6, 2018, 10:23pm

Does config show rspamd give back a result? Maybe some properties are missing like SpamCheckStatus or BlockAttachmentStatus or the values are wrong…

Does it occur again when you update the configuration with signal-event nethserver-mail2-update ?

I could not reproduce, expanding the templates gives no error on my side.

pa3hfj · October 7, 2018, 9:54am

Hello Markus,

This command gave a completely empty result.

This command doesn’t exist but the returned error made me look in the directory /etc/e-smith/events. There I executed all nethserver-mail-*-update events (* = common, disclaimer, filter, getmail, p3scan, server and smarthost)

After this the settings in the Filter tab appeared again and are changeable. Also the config show rspamd gave back results. The rspamd “webservice” did not work, only a menubar appeared on top of the page but in the services page on the Nethserver GUI I saw the p3scan service was not running. After a start info appeared on the rspamd page. How can I make sure it is restarted after a reboot?

But there still is one major problem, mail is not sent out by postfix, see the corresponding error messages out of maillog:

Oct  7 11:44:10 server1 postfix/pickup[16619]: 823831280B52: uid=8 from=&lt;pa3hfj@vrza.nl&gt;
Oct  7 11:44:10 server1 postfix/cleanup[19995]: warning: connect to Milter service unix:/var/run/opendkim/milter: Permission denied
Oct  7 11:44:10 server1 postfix/cleanup[19995]: 823831280B52: milter-reject: CONNECT from localhost[127.0.0.1]: 4.7.1 Service unavailable - try again later; from=&lt;pa3hfj@vrza.nl&gt;
Oct  7 11:44:10 server1 postfix/pickup[16619]: 826281280B52: uid=990 from=&lt;root@server1.pa3hfj.nl&gt;
Oct  7 11:44:10 server1 postfix/cleanup[19995]: warning: connect to Milter service unix:/var/run/opendkim/milter: Permission denied
Oct  7 11:44:10 server1 postfix/cleanup[19995]: 826281280B52: milter-reject: CONNECT from localhost[127.0.0.1]: 4.7.1 Service unavailable - try again later; from=&lt;root@server1.pa3hfj.nl&gt;
Oct  7 11:44:10 server1 postfix/pickup[16619]: 829C71280B52: uid=0 from=&lt;no-reply@server1.pa3hfj.nl&gt;
Oct  7 11:44:10 server1 postfix/cleanup[19995]: warning: connect to Milter service unix:/var/run/opendkim/milter: Permission denied
Oct  7 11:44:10 server1 postfix/cleanup[19995]: 829C71280B52: milter-reject: CONNECT from localhost[127.0.0.1]: 4.7.1 Service unavailable - try again later; from=&lt;no-reply@server1.pa3hfj.nl&gt;
Oct  7 11:44:10 server1 postfix/pickup[16619]: 82D281280B52: uid=0 from=&lt;no-reply@server1.pa3hfj.nl&gt;
Oct  7 11:44:10 server1 postfix/cleanup[19995]: warning: connect to Milter service unix:/var/run/opendkim/milter: Permission denied
Oct  7 11:44:10 server1 postfix/cleanup[19995]: 82D281280B52: milter-reject: CONNECT from localhost[127.0.0.1]: 4.7.1 Service unavailable - try again later; from=&lt;no-reply@server1.pa3hfj.nl&gt;
Oct  7 11:44:10 server1 postfix/pickup[16619]: 82F081280B52: uid=0 from=&lt;root&gt;
Oct  7 11:44:10 server1 postfix/cleanup[19995]: warning: connect to Milter service unix:/var/run/opendkim/milter: Permission denied
Oct  7 11:44:10 server1 postfix/cleanup[19995]: 82F081280B52: milter-reject: CONNECT from localhost[127.0.0.1]: 4.7.1 Service unavailable - try again later; from=&lt;root@server1.pa3hfj.nl&gt;
Oct  7 11:44:10 server1 postfix/pickup[16619]: 831381280B52: uid=8 from=&lt;pa3hfj@vrza.nl&gt;
Oct  7 11:44:10 server1 postfix/cleanup[19995]: warning: connect to Milter service unix:/var/run/opendkim/milter: Permission denied
Oct  7 11:44:10 server1 postfix/cleanup[19995]: 831381280B52: milter-reject: CONNECT from localhost[127.0.0.1]: 4.7.1 Service unavailable - try again later; from=&lt;pa3hfj@vrza.nl&gt;
Oct  7 11:44:10 server1 postfix/pickup[16619]: 8333B1280B52: uid=0 from=&lt;no-reply@server1.pa3hfj.nl&gt;
Oct  7 11:44:10 server1 postfix/cleanup[19995]: warning: connect to Milter service unix:/var/run/opendkim/milter: Permission denied
Oct  7 11:44:10 server1 postfix/cleanup[19995]: 8333B1280B52: milter-reject: CONNECT from localhost[127.0.0.1]: 4.7.1 Service unavailable - try again later; from=&lt;no-reply@server1.pa3hfj.nl&gt;

Incoming mail (lifted with getmail from the internetproviders emailserver) seems to be handled OK.

giacomo · October 7, 2018, 10:27am

It seems that something didn’t start correctly, but I can’t say what failed without seeing the logs.
To fix the permission problem, just execute:

   chown opendkim:mail /var/run/opendkim/milter
   systemctl restart rspamd

davidep · October 7, 2018, 10:35am

I think there are multiple symptoms of a (past?) failed package update

pa3hfj · October 7, 2018, 12:11pm

Resulting to:

 [root@server1 ~]# chown opendkim:mail /var/run/opendkim/milter
    chown: cannot access ‘/var/run/opendkim/milter’: No such file or directory

It seems something is not there…

davidep · October 7, 2018, 12:52pm

iIRC it is a socket file. The path components are created by systemd-tmpfs (kinda…) at boot or when the service unit is started. I cannot give more info by now, I hope it helps anyway…

pa3hfj · October 7, 2018, 2:25pm

Well guys, thanks for your tips and pointers so far, trying to narrowing down the problem:

Zooming in on opendkim; the service is not running and cannot be started:

[root@server1 ~]# systemctl start opendkim
Job for opendkim.service failed because the control process exited with error code. See "systemctl status opendkim.service" and "journalctl -xe" for details.
[root@server1 ~]# systemctl status opendkim.service
● opendkim.service - DomainKeys Identified Mail (DKIM) Milter
   Loaded: loaded (/usr/lib/systemd/system/opendkim.service; disabled; vendor preset: disabled)
  Drop-In: /etc/systemd/system/opendkim.service.d
           └─nethserver.conf
   Active: failed (Result: exit-code) since Sun 2018-10-07 15:22:35 CEST; 9s 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: 25053 ExecStart=/usr/sbin/opendkim $OPTIONS (code=exited, status=78)

Oct 07 15:22:35 server1.pa3hfj.nl systemd[1]: Starting DomainKeys Identified Mail (DKIM) Milter...
Oct 07 15:22:35 server1.pa3hfj.nl opendkim[25053]: /etc/opendkim/keys/default.private: open(): No such file or directory
Oct 07 15:22:35 server1.pa3hfj.nl systemd[1]: opendkim.service: control process exited, code=exited status=78
Oct 07 15:22:35 server1.pa3hfj.nl systemd[1]: Failed to start DomainKeys Identified Mail (DKIM) Milter.
Oct 07 15:22:35 server1.pa3hfj.nl systemd[1]: Unit opendkim.service entered failed state.
Oct 07 15:22:35 server1.pa3hfj.nl systemd[1]: opendkim.service failed.

Then I decided to make an adjustment in one off the emaildomains by enabling the maildisclaimer and inserting a text. On activation the opendkim service came to live!

Oct  7 15:53:05 server1 httpd: [WARNING] NethServer\Module\Mail\Domain\Modify: file_get_contents(/var/lib/nethserver/mail-disclaimers/taalapart.nl.raw): failed to open stream: No such file or directory
Oct  7 15:53:05 server1 httpd: [WARNING] NethServer\Module\Mail\Domain\Modify: file_get_contents(/etc/opendkim/default.txt): failed to open stream: No such file or directory
Oct  7 15:53:05 server1 httpd: [WARNING] NethServer\Module\Mail\Domain\Modify: file_get_contents(/etc/opendkim/default.txt): failed to open stream: No such file or directory
Oct  7 15:53:18 server1 httpd: [WARNING] NethServer\Module\Mail\Domain\Modify: file_get_contents(/var/lib/nethserver/mail-disclaimers/taalapart.nl.raw): failed to open stream: No such file or directory
Oct  7 15:53:19 server1 /sbin/e-smith/db[30851]: /var/lib/nethserver/db/domains: OLD taalapart.nl=domain|AlwaysBccStatus|disabled|Description|Taal Apart|DisclaimerStatus|disabled|TransportType|LocalDelivery|UnknownRecipientsActionType|bounce
Oct  7 15:53:19 server1 /sbin/e-smith/db[30851]: /var/lib/nethserver/db/domains: NEW taalapart.nl=domain|AlwaysBccStatus|disabled|Description|Taal Apart|DisclaimerStatus|enabled|TransportType|LocalDelivery|UnknownRecipientsActionType|bounce
Oct  7 15:53:19 server1 /sbin/e-smith/db[30851]: /var/lib/nethserver/db/domains: OLD taalapart.nl=domain|AlwaysBccStatus|disabled|Description|Taal Apart|DisclaimerStatus|enabled|TransportType|LocalDelivery|UnknownRecipientsActionType|bounce
Oct  7 15:53:19 server1 /sbin/e-smith/db[30851]: /var/lib/nethserver/db/domains: NEW taalapart.nl=domain|AlwaysBccStatus|disabled|Description|Taal Apart|DisclaimerStatus|enabled|OpenDkimStatus|disabled|TransportType|LocalDelivery|UnknownRecipientsActionType|bounce
Oct  7 15:53:19 server1 httpd: [WARNING] NethServer\Module\Mail\Domain\Modify: file_get_contents(/etc/opendkim/default.txt): failed to open stream: No such file or directory
Oct  7 15:53:19 server1 httpd: [WARNING] NethServer\Module\Mail\Domain\Modify: file_get_contents(/etc/opendkim/default.txt): failed to open stream: No such file or directory
Oct  7 15:53:20 server1 esmith::event[30865]: Event: domain-modify taalapart.nl
Oct  7 15:53:20 server1 esmith::event[30865]: expanding /var/lib/nethserver/sieve-scripts/unknown.sieve
Oct  7 15:53:20 server1 dbus[894]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service'
Oct  7 15:53:20 server1 systemd: Starting Time &amp; Date Service...
Oct  7 15:53:20 server1 dbus[894]: [system] Successfully activated service 'org.freedesktop.timedate1'
Oct  7 15:53:20 server1 systemd: Started Time &amp; Date Service.
Oct  7 15:53:20 server1 esmith::event[30865]: expanding /etc/opendkim.conf
Oct  7 15:53:20 server1 esmith::event[30865]: expanding /etc/opendkim/SigningTable
Oct  7 15:53:20 server1 esmith::event[30865]: expanding /etc/opendkim/KeyTable
Oct  7 15:53:20 server1 esmith::event[30865]: expanding /etc/opendkim/TrustedHosts
Oct  7 15:53:20 server1 esmith::event[30865]: expanding /etc/postfix/virtual
Oct  7 15:53:20 server1 esmith::event[30865]: expanding /etc/postfix/master.cf
Oct  7 15:53:21 server1 esmith::event[30865]: expanding /etc/postfix/internal_access
Oct  7 15:53:21 server1 esmith::event[30865]: expanding /etc/postfix/main.cf
Oct  7 15:53:21 server1 esmith::event[30865]: expanding /etc/postfix/transport
Oct  7 15:53:21 server1 esmith::event[30865]: expanding /etc/postfix/disclaimer
Oct  7 15:53:21 server1 esmith::event[30865]: expanding /etc/postfix/recipient_bcc
Oct  7 15:53:21 server1 esmith::event[30865]: expanding /etc/dovecot/dovecot.conf
Oct  7 15:53:21 server1 esmith::event[30865]: Action: /etc/e-smith/events/actions/generic_template_expand SUCCESS [1.346568]
Oct  7 15:53:23 server1 esmith::event[30865]: Action: /etc/e-smith/events/domain-modify/S30nethserver-mail-postmap-update SUCCESS [1.805474]
Oct  7 15:53:23 server1 systemd: Reloading.
Oct  7 15:53:25 server1 systemd: Starting DomainKeys Identified Mail (DKIM) Milter...
Oct  7 15:53:25 server1 systemd: Started DomainKeys Identified Mail (DKIM) Milter.
Oct  7 15:53:25 server1 esmith::event[30865]: [INFO] opendkim has been started
Oct  7 15:53:25 server1 systemd: Reloading.
Oct  7 15:53:25 server1 esmith::event[30865]: [INFO] service postfix restart
Oct  7 15:53:25 server1 systemd: Stopping Postfix Mail Transport Agent...
Oct  7 15:53:25 server1 systemd: Starting Postfix Mail Transport Agent...
Oct  7 15:53:26 server1 systemd: Started Postfix Mail Transport Agent.
Oct  7 15:53:26 server1 systemd: Reloading.
Oct  7 15:53:26 server1 esmith::event[30865]: [INFO] service dovecot reload
Oct  7 15:53:26 server1 systemd: Reloaded Dovecot IMAP/POP3 email server.
Oct  7 15:53:26 server1 esmith::event[30865]: Action: /etc/e-smith/events/actions/adjust-services SUCCESS [3.470779]
Oct  7 15:53:26 server1 esmith::event[30865]: Event: domain-modify SUCCESS

So one step further, i feel were getting close! But, still no joy at sending mail:

Oct  7 16:15:27 server1 postfix/pickup[31029]: D545912801E8: uid=0 from=&lt;no-reply@server1.pa3hfj.nl&gt;
Oct  7 16:15:27 server1 postfix/cleanup[32408]: warning: connect to Milter service unix:/var/run/opendkim/milter: Permission denied
Oct  7 16:15:27 server1 postfix/cleanup[32408]: D545912801E8: milter-reject: CONNECT from localhost[127.0.0.1]: 4.7.1 Service unavailable - try again later; from=&lt;no-reply@server1.pa3hfj.nl&gt;

The same permission denied messages on /var/run/opendkim/milter are in the log. The difference is that milter exists now, with opendkim:mail permissions:

[root@server1 opendkim]# ll
total 4
srwxrwx--- 1 opendkim mail 0 Oct  7 15:53 milter
-rw-r--r-- 1 opendkim mail 6 Oct  7 15:53 opendkim.pid

Is it worth a try to do a complete reboot to get things on its place?

davidep · October 7, 2018, 2:34pm

It could fix the socket path permissions… Let’s give it a try…

pa3hfj · October 7, 2018, 3:02pm

Well, the reboot gave the final kick, so to speak. The mailqueue is empty now, all mail delivered. I will closely monitor the maillog and messageslog the coming days, but it looks like the problem is solved!

Once again a big thank you is in order for the amazing supportteam of the Nethserver Community, where would we be without you guys?

alefattorini · October 11, 2018, 4:14pm

We can’t say “thank you” enough.