Package: opensmtpd
Version: 6.0.2p1-2
When OpenSMTPD fails to parse a table passwd file it responds with a fatal
error:
This is done manually:
# smtpd -vvvd -f /etc/smtpd.conf
warn: table-passwd: invalid entry
warn: table-passwd: error parsing config file
warn: table-proc: imsg_read: Connection reset by peer
fatal: table-proc: exiting
warn: parent -> lka: pipe closed
If you try to start OpenSMTPD with SystemD, using the same configuration, it
starts and doesn't report any problems:
# systemctl start smtpd
# systemctl status opensmtpd
● opensmtpd.service - LSB: opensmtpd Mail Transport Agent
Loaded: loaded (/etc/init.d/opensmtpd; generated; vendor preset: enabled)
Active: active (exited) since Tue 2017-12-26 06:39:36 CET; 2s ago
Docs: man:systemd-sysv-generator(8)
Process: 2249 ExecStop=/etc/init.d/opensmtpd stop (code=exited,
status=0/SUCCESS)
Process: 2274 ExecStart=/etc/init.d/opensmtpd start (code=exited,
status=0/SUCCESS)
dec 26 06:39:37 serv1 smtpd[2281]: setup_done: pony[2285] done
dec 26 06:39:37 serv1 smtpd[2281]: setup_done: queue[2286] done
dec 26 06:39:37 serv1 smtpd[2286]: setup_proc: queue done
dec 26 06:39:37 serv1 smtpd[2285]: setup_proc: pony express done
dec 26 06:39:37 serv1 smtpd[2284]: setup_proc: lookup done
dec 26 06:39:37 serv1 smtpd[2281]: setup_done: scheduler[2287] done
dec 26 06:39:37 serv1 smtpd[2281]: smtpd: setup done
dec 26 06:39:37 serv1 smtpd[2287]: setup_proc: scheduler done
dec 26 06:39:37 serv1 smtpd[2283]: setup_proc: control done
dec 26 06:39:37 serv1 smtpd[2282]: setup_proc: klondike done
Hence, there is no reason to suspect any errors.
Using "ss" I discovered that OpenSMTPD wasn't listening on any ports and the
journal reveals the same problem as with starting OpenSMTPD manually in
debugging mode:
# journalctl -xe
-- Unit opensmtpd.service has finished shutting down.
dec 26 06:39:01 serv1 CRON[2265]: pam_unix(cron:session): session opened for
user vmail by (uid=0)
dec 26 06:39:01 serv1 CRON[2266]: (vmail) CMD ( $PYTHON $INSTANCE/manage.py
handle_mailbox_operations)
dec 26 06:39:01 serv1 cron[303]: cannot create temporary file
/var/spool/smtpd/offline/1514266741.XXXXDLjSdC: Permission denied
dec 26 06:39:01 serv1 CRON[2265]: (vmail) MAIL (mailed 3758 bytes of output but
got status 0x0045 from MTA
)
dec 26 06:39:01 serv1 CRON[2265]: pam_unix(cron:session): session closed for
user vmail
dec 26 06:39:36 serv1 systemd[1]: Starting LSB: opensmtpd Mail Transport
Agent...
-- Subject: Unit opensmtpd.service has begun start-up
-- Defined-By: systemd
-- Support: https://www.debian.org/support
--
-- Unit opensmtpd.service has begun starting up.
dec 26 06:39:36 serv1 smtpd[2280]: info: OpenSMTPD 6.0.2p1 starting
dec 26 06:39:36 serv1 opensmtpd[2274]: Starting MTA: opensmtpd.
dec 26 06:39:36 serv1 systemd[1]: Started LSB: opensmtpd Mail Transport Agent.
-- Subject: Unit opensmtpd.service has finished start-up
-- Defined-By: systemd
-- Support: https://www.debian.org/support
--
-- Unit opensmtpd.service has finished starting up.
--
-- The start-up result is done.
dec 26 06:39:36 serv1 smtpd[2287]: setup_peer: scheduler -> control[2283] fd=12
dec 26 06:39:37 serv1 smtpd[2285]: setup_peer: pony express -> control[2283]
fd=10
dec 26 06:39:37 serv1 smtpd[2284]: setup_peer: lookup -> control[2283] fd=9
dec 26 06:39:37 serv1 smtpd[2283]: setup_peer: control -> klondike[2282] fd=8
dec 26 06:39:37 serv1 smtpd[2282]: setup_peer: klondike -> control[2283] fd=7
dec 26 06:39:37 serv1 smtpd[2286]: setup_peer: queue -> control[2283] fd=11
dec 26 06:39:37 serv1 smtpd[2286]: setup_peer: queue -> pony express[2285] fd=12
dec 26 06:39:37 serv1 smtpd[2285]: setup_peer: pony express -> klondike[2282]
fd=11
dec 26 06:39:37 serv1 smtpd[2286]: setup_peer: queue -> lookup[2284] fd=13
dec 26 06:39:37 serv1 smtpd[2285]: setup_peer: pony express -> lookup[2284]
fd=12
dec 26 06:39:37 serv1 smtpd[2286]: setup_peer: queue -> scheduler[2287] fd=14
dec 26 06:39:37 serv1 smtpd[2284]: setup_peer: lookup -> pony express[2285]
fd=10
dec 26 06:39:37 serv1 smtpd[2285]: setup_peer: pony express -> queue[2286] fd=13
dec 26 06:39:37 serv1 smtpd[2284]: setup_peer: lookup -> queue[2286] fd=11
dec 26 06:39:37 serv1 smtpd[2287]: setup_peer: scheduler -> queue[2286] fd=13
dec 26 06:39:37 serv1 smtpd[2283]: setup_peer: control -> lookup[2284] fd=9
dec 26 06:39:37 serv1 smtpd[2283]: setup_peer: control -> pony express[2285]
fd=10
dec 26 06:39:37 serv1 smtpd[2283]: setup_peer: control -> queue[2286] fd=11
dec 26 06:39:37 serv1 smtpd[2283]: setup_peer: control -> scheduler[2287] fd=12
dec 26 06:39:37 serv1 smtpd[2282]: setup_peer: klondike -> pony express[2285]
fd=8
dec 26 06:39:37 serv1 smtpd[2281]: setup_done: ca[2282] done
dec 26 06:39:37 serv1 smtpd[2281]: setup_done: control[2283] done
dec 26 06:39:37 serv1 smtpd[2281]: setup_done: lka[2284] done
dec 26 06:39:37 serv1 smtpd[2281]: setup_done: pony[2285] done
dec 26 06:39:37 serv1 smtpd[2281]: setup_done: queue[2286] done
dec 26 06:39:37 serv1 smtpd[2286]: setup_proc: queue done
dec 26 06:39:37 serv1 smtpd[2285]: setup_proc: pony express done
dec 26 06:39:37 serv1 smtpd[2284]: setup_proc: lookup done
dec 26 06:39:37 serv1 smtpd[2281]: setup_done: scheduler[2287] done
dec 26 06:39:37 serv1 smtpd[2281]: smtpd: setup done
dec 26 06:39:37 serv1 smtpd[2287]: setup_proc: scheduler done
dec 26 06:39:37 serv1 smtpd[2283]: setup_proc: control done
dec 26 06:39:37 serv1 smtpd[2282]: setup_proc: klondike done
dec 26 06:39:37 serv1 smtpd[2284]: warn: table-proc: imsg_read: Connection
reset by peer
dec 26 06:39:37 serv1 smtpd[2284]: fatal: table-proc: exiting
dec 26 06:39:37 serv1 smtpd[2281]: warn: parent -> lka: pipe closed
dec 26 06:39:37 serv1 smtpd[2286]: warn: queue -> lookup: pipe closed
dec 26 06:39:37 serv1 smtpd[2287]: warn: scheduler -> queue: pipe closed
dec 26 06:39:37 serv1 smtpd[2285]: warn: pony -> lookup: pipe closed
dec 26 06:39:37 serv1 smtpd[2283]: warn: control -> lookup: pipe closed
dec 26 06:39:37 serv1 smtpd[2282]: warn: ca -> pony express: pipe closed
Please also notice the error message: cannot create temporary file
/var/spool/smtpd/offline/1514266741.XXXXDLjSdC: Permission denied
I then tried to change the file permission:
# chmod 777 /var/spool/smtpd/offline/
Restarting, got the following message from the journal:
dec 26 06:44:17 serv1 smtpd[2361]: /var/spool/smtpd/offline must be rwxrwx---
(770)
So changed it:
# chmod 770 /var/spool/smtpd/offline
In any ways, OpenSMTPD not working correctly with a "fatal: table-proc:
exiting", should make it halt, and SystemD should display this.
I have also filed a bug report (#885288) regarding the problems parsing the
passwd file (not the SystemD issue), but this is related to the
opensmtpmd-extras package I believe.
Kind regards,
Martin
