CRITICAL: postfix fails to start after upgrade to 2.03 release [solved]

marcelloc

This option.

postfix_enable.png_thumb

hcoin

It was unchecked, though Postfix along with the rest of the box was running without change for a year, to include power cycles every few months. It was certainly trading email just fine. All worked normally preupgrade so the enable box must have been checked then. Maybe the auto-upgrade of pfsense to the next pfsense release turned it off? I wonder why the upgrade GUI hung on postfix?

I've done a reboot to see if the box stays checked… and.... box stays checked.

Anyhow, Thanks! Seems to be working now. Never would I have thought to see if upgrading disabled configured packages short of your hint!

hcoin

The aforementioned box (now working) was a backup in a primary / secondary system. I've now done the 'upgrade' operation in the primary and the 'reinstall gui' is once again hung complaining of 'reinstalling packages in the background'. Here's some data:

…
63159 ?? Ss 0:00.10 /usr/local/sbin/dhcpd -user dhcpd -group _dhcp -chroo
25 v0 Is+ 0:00.04 sh /etc/rc autoboot
257 v0 I+ 1:37.98 /usr/local/bin/php -f /etc/rc.bootup
14085 v0 IN+ 0:00.32 /bin/sh /var/db/rrd/updaterrd.sh
20322 v0 I+ 0:00.01 /bin/sh ./+INSTALL postfix-2.8.7,1 POST-INSTALL
28607 v0 S+ 0:00.05 /usr/sbin/tcpdump -s 256 -v -S -l -n -e -ttt -i pflog
28821 v0 S+ 0:00.05 logger -t pf -p local0.info
35930 v0 I+ 0:00.15 /usr/sbin/pkg_add -fv /tmp/apkg_postfix-2.8.7,1.tbz
41620 v0 I+ 0:00.00 /bin/sh ./+INSTALL postfix-2.8.7,1 POST-INSTALL
44770 v0 IN+ 0:00.00 sleep 60

...

hcoin

And a few minutes later:

…
159 ?? S 0:00.24 /usr/local/sbin/dnsmasq --local-ttl 1 --all-servers -
252 ?? INs 0:25.10 /usr/local/sbin/check_reload_status
254 ?? IN 0:00.00 check_reload_status: Monitoring daemon of check_reloa
264 ?? Is 0:00.02 /sbin/devd
431 ?? SNs 0:00.19 /usr/local/bin/ntpd -g -c /var/etc/ntpd.conf
2529 ?? SNs 0:00.03 /usr/sbin/cron -s
6839 ?? SN 0:00.03 smtp -t unix -u
7168 ?? IN 0:00.02 bounce -z -n defer -t unix -u
8601 ?? SN 0:00.70 /usr/local/bin/php -f /etc/rc.newipsecdns
9432 ?? Is 0:00.00 /usr/sbin/sshd
11306 ?? Ss 0:00.02 /usr/sbin/hostapd -B /var/etc/hostapd_ath0_wlan0.conf
16321 ?? Ss 0:00.04 /usr/local/sbin/miniupnpd -f /var/etc/miniupnpd.conf
19652 ?? I 0:00.02 rrdtool -
24038 ?? SNs 0:00.03 postscreen -l -n 127.0.0.1:25 -t inet -u -o user=post
24228 ?? IN 0:00.02 dnsblog -z -t unix -u
24342 ?? IN 0:00.02 tlsmgr -l -t unix -u
24428 ?? SN 0:00.06 smtpd -t pass -u -o stress=
24660 ?? SN 0:00.02 trivial-rewrite -n rewrite -t unix -u
25279 ?? Ss 0:00.20 /usr/local/sbin/openvpn --config /var/etc/openvpn/cli
27684 ?? SNs 0:00.10 /usr/local/libexec/postfix/master
27831 ?? Ss 0:00.02 /usr/local/sbin/openvpn --config /var/etc/openvpn/ser
29918 ?? S 0:29.49 /usr/local/freeswitch/bin/./freeswitch -nc
33505 ?? SNs 0:01.50 /usr/sbin/syslogd -s -c -c -l /var/dhcpd/var/run/log
33542 ?? Ss 0:00.29 /usr/local/sbin/apinger -c /var/etc/apinger.conf
42179 ?? SNs 0:00.36 /usr/local/libexec/nut/apcsmart -a gate1backups
43263 ?? SNs 0:00.06 /usr/local/sbin/upsd
43515 ?? INs 0:00.01 /usr/local/sbin/upsmon gate1backups@localhost
43566 ?? SN 0:00.07 /usr/local/sbin/upsmon gate1backups@localhost
47371 ?? S 0:15.92 /usr/local/sbin/lighttpd -f /var/etc/lighty-webConfig
47517 ?? Is 0:00.18 /usr/local/bin/php
48386 ?? Is 0:00.18 /usr/local/bin/php
52292 ?? I 0:00.42 /usr/local/bin/php
52328 ?? SN 0:00.02 cleanup -z -t unix -u
52404 ?? S 0:04.94 /usr/local/bin/php
52539 ?? SN 0:00.02 bounce -z -t unix -u
53363 ?? R 0:00.01 ps ax
54225 ?? IN 0:00.02 pickup -l -t fifo -u
54264 ?? SN 0:00.04 qmgr -l -t fifo -u
58353 ?? SN 0:00.02 anvil -l -t unix -u
63159 ?? Ss 0:00.27 /usr/local/sbin/dhcpd -user dhcpd -group _dhcp -chroo
25 v0 Is+ 0:00.04 sh /etc/rc autoboot
257 v0 I+ 1:37.98 /usr/local/bin/php -f /etc/rc.bootup
14085 v0 SN+ 0:00.97 /bin/sh /var/db/rrd/updaterrd.sh
20322 v0 I+ 0:00.01 /bin/sh ./+INSTALL postfix-2.8.7,1 POST-INSTALL
28607 v0 S+ 0:00.11 /usr/sbin/tcpdump -s 256 -v -S -l -n -e -ttt -i pflog
28821 v0 S+ 0:00.12 logger -t pf -p local0.info
35930 v0 I+ 0:00.15 /usr/sbin/pkg_add -fv /tmp/apkg_postfix-2.8.7,1.tbz
41620 v0 I+ 0:00.00 /bin/sh ./+INSTALL postfix-2.8.7,1 POST-INSTALL
52298 v0 SN+ 0:00.00 sleep 60

I can hold it here, and not reboot if there is any diagnostic info you'd like?

mschiek01

I have seen this before on the upgrade what other packages do you have installed?

hcoin

on the system I just got working (check the box fix): arping, cron, notes, nut, pfblocker, postfix forwarder. services running include those plus miniupnpd, dhcpd and dnsmasq and openvpn.

On the one still hung during upgrade:

cron The cron utility is used to manage commands on a schedule.
Running
[Restart Service] [Stop Service]
dhcpd DHCP Service
Running
[Restart Service] [Stop Service]
dnsmasq DNS Forwarder
Running
[Restart Service] [Stop Service]
miniupnpd UPnP Service
Running
[Restart Service] [Stop Service]
ntpd NTP clock sync
Running
[Restart Service] [Stop Service]
nut Network UPS Tools
Running
[Restart Service] [Stop Service]
openvpn OpenVPN client: Mama Bosso VPN Site-Site
Running
[Restart Service] [Stop Service]
openvpn OpenVPN server: QF Tunnel
Running
[Restart Service] [Stop Service]
snort Snort is the most widely deployed IDS/IPS technology worldwide.
Stopped
[Start Service]
tftp

and it's still waiting on the postfix install processes, they appear to be hung.

All packages install as normal except for postfix. The one system is still hung though I have access to the GUI. Any live diagnostic info you'd like before I reboot?

May 9 14:53:39 syslogd: kernel boot file is /boot/kernel/kernel
May 9 14:53:39 syslogd: exiting on signal 15
May 9 14:53:38 check_reload_status: Syncing firewall
May 9 13:39:30 SnortStartup[63836]: Snort START For netbs(12157_xl1)…
May 9 13:39:30 snort[63737]: FATAL ERROR: /usr/local/etc/snort/snort_12157_xl1/rules/snort.rules(571) Please enable the HTTP Inspect preprocessor before using the http content modifiers
May 9 13:39:30 snort[63737]: FATAL ERROR: /usr/local/etc/snort/snort_12157_xl1/rules/snort.rules(571) Please enable the HTTP Inspect preprocessor before using the http content modifiers
May 9 13:39:27 SnortStartup[62411]: Snort START For mediacom(22941_xl0)…
May 9 13:39:27 snort[62194]: FATAL ERROR: /usr/local/etc/snort/snort_22941_xl0/rules/snort.rules(571) Please enable the HTTP Inspect preprocessor before using the http content modifiers
May 9 13:39:27 snort[62194]: FATAL ERROR: /usr/local/etc/snort/snort_22941_xl0/rules/snort.rules(571) Please enable the HTTP Inspect preprocessor before using the http content modifiers
May 9 13:39:23 php: : The command '/usr/local/etc/rc.d/snort.sh stop' returned exit code '1', the output was ''
May 9 13:39:21 SnortStartup[52738]: Snort STOP For netbs(12157_xl1)…
May 9 13:39:19 SnortStartup[51918]: Snort STOP For mediacom(22941_xl0)…
May 9 13:39:08 php: : Checking for and disabling any rules dependent upon disabled preprocessors for NETBS...
May 9 13:38:45 kernel: s...
May 9 13:38:42 kernel: for package installation...
May 9 13:38:42 kernel: .
May 9 13:38:34 php: : Beginning package installation for Postfix Forwarder.
May 9 13:38:27 check_reload_status: Syncing firewall
May 9 13:38:18 php: : Checking for and disabling any rules dependent upon disabled preprocessors for MEDIACOM...
May 9 13:37:54 php: : Beginning package installation for TFTP.
May 9 13:37:50 check_reload_status: Syncing firewall
May 9 13:37:48 upsd[43263]: User monuser@127.0.0.1 logged into UPS [gate1backups]
May 9 13:37:46 upsmon[43515]: Startup successful
May 9 13:37:46 upsd[43263]: Startup successful
May 9 13:37:45 upsd[42451]: Connected to UPS [gate1backups]: apcsmart-gate1backups
May 9 13:37:45 upsd[42451]: listening on 127.0.0.1 port 3493
May 9 13:37:45 upsd[42451]: listening on ::1 port 3493
May 9 13:37:44 apcsmart[42179]: Startup successful
May 9 13:37:38 check_reload_status: Syncing firewall
May 9 13:37:34 php: : No pfBlocker action during boot process.
May 9 13:37:34 php: : No pfBlocker action during boot process.
May 9 13:37:32 kernel: package instructions…done.
May 9 13:37:31 kernel: Package XML... done.
May 9 13:37:31 kernel: >Cleaning up... Beginning package installation for arping...
May 9 13:37:30 kernel: .
May 9 13:37:30 kernel: .
May 9 13:37:30 kernel: structions...
May 9 13:37:25 php: : Beginning package installation for pfBlocker.
May 9 13:37:22 php: : No pfBlocker action during boot process.
May 9 13:37:19 check_reload_status: Syncing firewall
May 9 13:37:11 php: : Postfix setup completed
May 9 13:37:06 check_reload_status: Syncing firewall
May 9 13:37:04 kernel: done.
May 9 13:37:03 php: : Reloading/starting postfix
May 9 13:37:02 php: : Writing rc_file
May 9 13:37:00 php: : Beginning package installation for Notes.
May 9 13:37:00 php: : Writing out configuration
May 9 13:36:56 check_reload_status: Syncing firewall
May 9 13:36:42 syslogd: kernel boot file is /boot/kernel/kernel
May 9 13:36:39 syslogd: exiting on signal 15
May 9 13:36:39 php: : Beginning package installation for OpenVPN tap Bridging Fix.
May 9 13:36:31 check_reload_status: Syncing firewall
May 9 13:36:28 php: : XML error: Not well-formed (invalid token) at line 1 in /usr/local/pkg/
May 9 13:36:22 apinger: rrdtool respawning too fast, waiting 300s.
May 9 13:36:22 apinger: Error while feeding rrdtool: Broken pipe
May 9 13:36:21 php: : Message sent to room_qf_systems_status@quietfountain.com OK
May 9 13:36:20 php: : Postfix setup completed
May 9 13:36:20 postfix/postfix-script[11930]: fatal: the Postfix mail system is not running
May 9 13:36:18 php: : Message sent to room_qf_systems_status@quietfountain.com OK
May 9 13:36:17 php: : Could not send the message to room_qf_systems_status@quietfountain.com – Error: it was not possible to read line from the SMTP server: data access time out
May 9 13:36:16 check_reload_status: Syncing firewall
May 9 13:36:13 php: : Reloading/starting postfix
May 9 13:36:12 php: : Writing rc_file
May 9 13:36:10 php: : Writing out configuration
May 9 13:36:10 php: : The command '/usr/local/sbin/postfix reload' returned exit code '1', the output was ''
May 9 13:36:10 postfix/postfix-script[7778]: fatal: the Postfix mail system is not running
May 9 13:36:07 syslogd: kernel boot file is /boot/kernel/kernel
May 9 13:36:07 syslogd: exiting on signal 15
May 9 13:36:02 check_reload_status: Syncing firewall
May 9 13:35:48 miniupnpd[16321]: Listening for NAT-PMP traffic on port 5351
May 9 13:35:48 miniupnpd[16321]: Listening for NAT-PMP traffic on port 5351
May 9 13:35:48 miniupnpd[16321]: HTTP listening on port 2189
May 9 13:35:48 miniupnpd[16321]: HTTP listening on port 2189
May 9 13:35:48 php: : miniupnpd: Starting service on interface: opt3, opt4
May 9 13:35:48 php: : Creating rrd update script
May 9 13:35:44 check_reload_status: Restarting ipsec tunnels
May 9 13:35:42 php: : No pfBlocker action during boot process.
May 9 13:35:42 php: : No pfBlocker action during boot process.
May 9 13:35:42 php: : No pfBlocker action during boot process.
May 9 13:35:42 php: : No pfBlocker action during boot process.
May 9 13:35:41 php: : filter_generate_address: is not a valid source port.
May 9 13:35:41 php: : filter_generate_address: is not a valid source port.
May 9 13:35:38 php: : filter_generate_address: is not a valid source port.
May 9 13:35:38 php: : filter_generate_address: is not a valid source port.
May 9 13:35:34 php: : XML error: Not well-formed (invalid token) at line 1 in /usr/local/pkg/
May 9 13:35:34 php: : XML error: Not well-formed (invalid token) at line 1 in /usr/local/pkg/
May 9 13:35:33 php: : Message sent to room_qf_systems_status@quietfountain.com OK
May 9 13:35:32 php: : Restarting/Starting all packages.
May 9 13:35:31 php: : pfSense package system has detected an ip change -> 192.168.55.6 … Restarting packages.
May 9 13:35:31 ntpdate[60859]: step time server 216.171.120.36 offset 0.988073 sec
May 9 13:35:30 dnsmasq[159]: read /etc/hosts - 55 addresses
May 9 13:35:30 dnsmasq[159]: using nameserver 192.168.50.1#53 for domain XXXXXX.com
May 9 13:35:30 dnsmasq[159]: ignoring nameserver 127.0.0.1 - local interface
May 9 13:35:30 dnsmasq[159]: ignoring nameserver 127.0.0.1 - local interface
May 9 13:35:30 dnsmasq[159]: using nameserver XXXXX0#53
May 9 13:35:30 dnsmasq[159]: using nameserver xXXXXX3#53
May 9 13:35:30 dnsmasq[159]: using nameserver 8.8.8.8#53
May 9 13:35:30 dnsmasq[159]: using nameserver 8.8.4.4#53
May 9 13:35:30 dnsmasq[159]: reading /etc/resolv.conf
May 9 13:35:30 dnsmasq[159]: using nameserver 192.168.50.1#53 for domain mamabosso.com
May 9 13:35:30 dnsmasq[159]: compile time options: IPv6 GNU-getopt no-DBus i18n IDN DHCP DHCPv6 no-Lua TFTP no-conntrack
May 9 13:35:30 dnsmasq[159]: started, version 2.65 cachesize 10000
May 9 13:35:30 check_reload_status: Updating all dyndns
May 9 13:35:30 dhcpd: For info, please visit https://www.isc.org/software/dhcp/
May 9 13:35:30 dhcpd: All rights reserved.
May 9 13:35:30 dhcpd: Copyright 2004-2012 Internet Systems Consortium.
May 9 13:35:30 dhcpd: Internet Systems Consortium DHCP Server 4.2.4-P2
May 9 13:35:27 php: : rc.newwanip: on (IP address: 192.168.55.6) (interface: ) (real interface: ovpnc3).
May 9 13:35:27 php: : rc.newwanip: Informational is starting ovpnc3.
May 9 13:35:27 php: : Gateways status could not be determined, considering all as up/active.
May 9 13:35:26 check_reload_status: Starting packages
May 9 13:35:26 php: : pfSense package system has detected an ip change -> 192.168.24.1 … Restarting packages.
May 9 13:35:26 php: : ROUTING: setting default route to 97.64.213.193
May 9 13:35:23 check_reload_status: rc.newwanip starting ovpnc3
May 9 13:35:23 kernel: ovpnc3: link state changed to UP
May 9 13:35:22 check_reload_status: Reloading filter
May 9 13:35:22 apinger: Starting Alarm Pinger, apinger(33542)
May 9 13:35:22 php: : rc.newwanip: on (IP address: 192.168.24.1) (interface: ) (real interface: ovpns1).
May 9 13:35:22 php: : rc.newwanip: Informational is starting ovpns1.
May 9 13:35:21 php: : Removing static route for monitor 8.8.8.8 and adding a new route through 97.64.213.193
May 9 13:35:21 php: : filter_generate_address: is not a valid source port.
May 9 13:35:20 php: : filter_generate_address: is not a valid source port.
May 9 13:35:18 kernel: pflog0: promiscuous mode enabled
May 9 13:35:18 kernel: Trying to mount root from ufs:/dev/ad0s1a
....

mschiek01

Try this.

Go into package manager and uninstall:
nut, pfblocker, postfix forwarder.

Go to the command line and type pkg_info

Look at the installed packages and make sure none of them are showing installed also make sure none of them show older versions installed.

If any of them are type pkg_delete -f "package name"

Reboot the box

Then go into package manager and install.

postfix first and make sure that you check the check box to run postfix as well as save the configuration. It should still be there as it was before.

Reboot the box and make sure postfix starts.

Then install the other two packages and you should be good to go.

hcoin

Love to, but as 'the packages are reinstalling in the background' the package manager won't display them. When I navigate to the package manager, it tells me to wait until the re-installation, which will never finish, finishes.

If I reboot I think I can do as you suggest. Should I reboot then try?

mschiek01

Yes

hcoin

I removed as indicated. After removal, of interest pkg_info included:

postfix-current-2.9.20120102,4 A secure alternative to widely-used Sendmail

There were no references to pfblocker or nut. I removed the above, the package manager having already removed others noted.

I followed the directions indicated above, all appears to be working. What a ride!

What could I have done to have avoided this prize? What went wrong?

And, mostly, thanks! :D

mschiek01

This -> postfix-current-2.9.20120102 was your problem.

For some reason the old package did not completely uninstall. I have had this problem a few times.

On an upgrade I usually uninstall the packages and then do the upgrade and then manually reinstall the packages through the gui after the upgrade has finnished. Also I always check from the command line to make sure the package has unistalled properly.

hcoin

That's correct. On two different PF boxes running postfix, AFTER I removed postfix through the gui, the above reference to postfix remained in the pkg_info output. I did a pkg_delete -f … on it, rebooted, reinstalled postfix, enabled it, rebooted. postfix ran. I added nut and pfblocker back as well. Re-enabled pfblocker, started nut from the services screen. Rebooted, -- all up and running normally on both boxes.

mschiek01

See my previous post as I changed it.

Glad I could help.

hcoin

Talk about belt-and-suspenders. Makes me wish each package that was a vm guest that was its own iso/appliance. As hard as the open source world tries to deal with 'dependency hell' it just never seems to work out of the workbench environment.

marcelloc

@hcoin:

Talk about belt-and-suspenders. Makes me wish each package that was a vm guest that was its own iso/appliance. As hard as the open source world tries to deal with 'dependency hell' it just never seems to work out of the workbench environment.

On 2.1 pbi packages will be much easier…

I'm testing firmware upgrade on one of my 3 inbound smtp servers and I it's stuck on upgrade process.
I found a mtree process that is "indexing" /usr dir with 60bg of dcc log from mailscanner package.
For next 2 boxes upgrade I'll remove these folders before the update and remove all packages as well.