Why does postgrey not launch correctly on boot with Ubuntu 16.04?

Question

I upgraded my Ubuntu 14.04 LTS to 16.04.1 LTS and now I have a problem with my postgrey installation. When I (re)boot the server, the postgrey startup script is apparently called but postgrey does not launch correctly. Only after manually restarting the service is postgrey working correctly.

In more detail: After reboot the following lines appear in my syslog:

Dec  1 19:22:14 systemd[1]: Starting LSB: Start/stop the postgrey daemon...
Dec  1 19:22:14 postgrey[998]:  * Starting postfix greylisting daemon postgrey
Dec  1 19:22:15 postgrey[1050]: Process Backgrounded
Dec  1 19:22:15 postgrey[1050]: 2016/12/01-19:22:15 postgrey (type Net::Server::Multiplex) starting! pid(1050)
Dec  1 19:22:15 postgrey[998]:    ...done.
Dec  1 19:22:15 systemd[1]: Started LSB: Start/stop the postgrey daemon.

When I then ps for postgrey, no process is found. However, a simple sudo systemctl restart postgrey makes it run properly. The launch is documented in syslog as follows:

Dec  1 19:25:54 systemd[1]: Stopping LSB: Start/stop the postgrey daemon...
Dec  1 19:25:54 postgrey[1878]:  * Stopping postfix greylisting daemon postgrey
Dec  1 19:25:54 systemd[1]: postgrey.service: Control process exited, code=exited status=1
Dec  1 19:25:54 systemd[1]: Stopped LSB: Start/stop the postgrey daemon.
Dec  1 19:25:54 systemd[1]: postgrey.service: Unit entered failed state.
Dec  1 19:25:54 systemd[1]: postgrey.service: Failed with result 'exit-code'.
Dec  1 19:25:54 systemd[1]: Starting LSB: Start/stop the postgrey daemon...
Dec  1 19:25:54 postgrey[1886]:  * Starting postfix greylisting daemon postgrey
Dec  1 19:25:54 postgrey[1886]: Pid_file "/var/run/postgrey.pid" already exists.  Overwriting!
Dec  1 19:25:54 postgrey[1893]: Process Backgrounded
Dec  1 19:25:54 postgrey[1893]: 2016/12/01-19:25:54 postgrey (type Net::Server::Multiplex) starting! pid(1893)
Dec  1 19:25:54 postgrey[1886]:    ...done.
Dec  1 19:25:54 systemd[1]: Started LSB: Start/stop the postgrey daemon.
Dec  1 19:25:54 postgrey[1893]: Resolved [localhost]:10023 to [::1]:10023, IPv6
Dec  1 19:25:54 postgrey[1893]: Resolved [localhost]:10023 to [127.0.0.1]:10023, IPv4
Dec  1 19:25:55 postgrey[1893]: Binding to TCP port 10023 on host ::1 with IPv6
Dec  1 19:25:55 postgrey[1893]: Binding to TCP port 10023 on host 127.0.0.1 with IPv4
Dec  1 19:25:55 postgrey[1893]: Setting gid to "120 120"
Dec  1 19:25:55 postgrey[1893]: Setting uid to "112"

As you can see, this time postgrey documents its binding to the correct port. When I look through my ps output now, I can see the working process there. My question is: Why does the process not launch correctly when it is called at boot time? How can I pinpoint the error? I could not find any hints on what causes the error, so any advise regarding that might help me, too. Since it used to work in 14.04 and stopped working in 16.04, maybe it is related to upstart vs. systemd?

score 4 · Answer 1 · answered Dec 02 '16 at 18:57

The postgrey project does not include in a systemd "service unit" file, nor does the Ubuntu package for it. The service is instead loaded by a shim that allows systemd to manage services that use the older sysv "init" scripts. This is supposed to work, but adds an extra layer of indirection and complication. I recommend you try putting the following in /etc/systemd/system/postgrey.service:

[Unit]
Description=Postfix Greylisting Service
Before=postfix.service

[Service]
Type=forking
ExecStartPre=-/bin/rm -f /var/run/postgrey.pid
PIDFile=/var/run/postgrey.pid
ExecStart=/usr/local/sbin/postgrey --inet=10025 -d --delay=150 --pidfile=/var/run/postgrey.pid
Restart=always
RestartSec=1

[Install]
WantedBy=multi-user.target

Then disable the sysv init versions from being run:

update-rc.d -f postgrey remove

You'll need to enable the new systemd service to start at boot:

 systemctl enable postgrey

Now try again to start the service using systemd:

 systemctl start postgrey

If it still fails to start. Check the specific log for this service, journalctl -u postgrey and also the general systemd journal: journalctl.

I also recommend submitting a patch to postgrey project to add a systemctl unit file to their contrib directory so in the future an official systemd service file will be used to start the service on systemd-based systems and a shim layer will not be required.

Thanks for this tutorial. I'll give it a try when I find time to dabble with your script a bit more. The init script of the postgrey package reads some settings from a file, which I would probably implement for the systemd script as well. — ilpssun, Dec 03 '16 at 13:22
The first rule for migrating to systemd applies here as well. A -d option is usually wrong, but note that postgrey's mis-handling of plain old logging to standard error is a now four year old bug. — JdeBP, Dec 09 '16 at 19:29

score 0 · Answer 2 · answered Dec 07 '18 at 02:21

I had a very similar issue on an IPV6 disabled Ubuntu 16 system, and it was related to postgrey's failed IPV6 binding on port 10025.

I fixed it by editing /etc/default/postgrey and changed the --inet parameter to:

--inet=127.0.0.1:10025

Of course a better solution would be to let systemd handle it like described in the first answer, and set the --inet parameter in the ExecStart= line to 127.0.0.1:10025

There was no trace in the logs, until I've run postgrey binary in console and saw the following:

ERROR: Can't connect to TCP port 10025 on ::1 [Cannot assign requested address] at /usr/sbin/postgrey line 776.

Why does postgrey not launch correctly on boot with Ubuntu 16.04?

2 Answers2