PostgreSQL fails on boot, but works fine after logging in

Question

I'm not sure if my problem started after update. I'm running Debian Squeeze and postgresql-8.4(8.4.12-0squeeze1). On startup or after reboot, I noticed that my PostgreSQL database service fails. However, when I'll login with root, the service is already running, and I can execute /etc/init.d/postgresql restart in a conosle, and it works fine. What could cause this error message?

here is my log from /var/log/boot

...
Tue Jul 24 09:40:23 2012: + pg_ctlcluster 8.4 main start
Tue Jul 24 09:41:04 2012: + ERRMSG=The PostgreSQL server failed to start. Please check the log output:
Tue Jul 24 09:41:04 2012: + res=1
Tue Jul 24 09:41:04 2012: + set -e
Tue Jul 24 09:41:04 2012: + [ 1 -eq 0 ]
Tue Jul 24 09:41:04 2012: + [ 1 -eq 2 ]
Tue Jul 24 09:41:04 2012: + status=1
Tue Jul 24 09:41:04 2012: + [ 1 -ne 0 -a -n The PostgreSQL server failed to start. Please check the log output: ]
Tue Jul 24 09:41:04 2012: + log_failure_msg The PostgreSQL server failed to start. Please check the log output:
Tue Jul 24 09:41:04 2012: + [ -n The PostgreSQL server failed to start. Please check the log output: ]
Tue Jul 24 09:41:04 2012: + log_begin_msg The PostgreSQL server failed to start. Please check the log output: ...
Tue Jul 24 09:41:04 2012: + [ -z The ]
Tue Jul 24 09:41:04 2012: + echo -n The PostgreSQL server failed to start. Please check the log output: ...
Tue Jul 24 09:41:04 2012: The PostgreSQL server failed to start. Please check the log output: ...+ log_end_msg 1
Tue Jul 24 09:41:04 2012: + [ -z 1 ]
Tue Jul 24 09:41:04 2012: + retval=1
Tue Jul 24 09:41:04 2012: + log_end_msg_pre 1
Tue Jul 24 09:41:04 2012: + :
Tue Jul 24 09:41:04 2012: + log_use_fancy_output
Tue Jul 24 09:41:04 2012: + TPUT=/usr/bin/tput
Tue Jul 24 09:41:04 2012: + EXPR=/usr/bin/expr
Tue Jul 24 09:41:04 2012: + [ -t 1 ]
Tue Jul 24 09:41:04 2012: + [ xlinux != x ]
Tue Jul 24 09:41:04 2012: + [ xlinux != xdumb ]
Tue Jul 24 09:41:04 2012: + [ -x /usr/bin/tput ]
Tue Jul 24 09:41:04 2012: + [ -x /usr/bin/expr ]
Tue Jul 24 09:41:04 2012: + /usr/bin/tput hpa 60
Tue Jul 24 09:41:04 2012: + /usr/bin/tput setaf 1
Tue Jul 24 09:41:04 2012: + [ -z ]
Tue Jul 24 09:41:04 2012: + FANCYTTY=1
Tue Jul 24 09:41:04 2012: + true
Tue Jul 24 09:41:04 2012: + /usr/bin/tput setaf 1
Tue Jul 24 09:41:04 2012: + RED=^[[31m
Tue Jul 24 09:41:04 2012: + /usr/bin/tput setaf 3
Tue Jul 24 09:41:04 2012: + YELLOW=^[[33m
Tue Jul 24 09:41:04 2012: + /usr/bin/tput op
Tue Jul 24 09:41:04 2012: + NORMAL=^[[39;49m
Tue Jul 24 09:41:04 2012: + [ 1 -eq 0 ]
Tue Jul 24 09:41:04 2012: + [ 1 -eq 255 ]
Tue Jul 24 09:41:04 2012: + /bin/echo -e  ^[[31mfailed!^[[39;49m
Tue Jul 24 09:41:04 2012:  ^[[31mfailed!^[[39;49m
Tue Jul 24 09:41:04 2012: + log_end_msg_post 1
Tue Jul 24 09:41:04 2012: + :
Tue Jul 24 09:41:04 2012: + return 1
Tue Jul 24 09:41:04 2012: + true
Tue Jul 24 09:41:04 2012: + log_end_msg 1
Tue Jul 24 09:41:04 2012: + [ -z 1 ]
Tue Jul 24 09:41:04 2012: + retval=1
Tue Jul 24 09:41:04 2012: + log_end_msg_pre 1
Tue Jul 24 09:41:04 2012: + :
Tue Jul 24 09:41:04 2012: + log_use_fancy_output
Tue Jul 24 09:41:04 2012: + TPUT=/usr/bin/tput
Tue Jul 24 09:41:04 2012: + EXPR=/usr/bin/expr
Tue Jul 24 09:41:04 2012: + [ -t 1 ]
Tue Jul 24 09:41:04 2012: + [ xlinux != x ]
Tue Jul 24 09:41:04 2012: + [ xlinux != xdumb ]
Tue Jul 24 09:41:04 2012: + [ -x /usr/bin/tput ]
Tue Jul 24 09:41:04 2012: + [ -x /usr/bin/expr ]
Tue Jul 24 09:41:04 2012: + /usr/bin/tput hpa 60
Tue Jul 24 09:41:04 2012: + /usr/bin/tput setaf 1
Tue Jul 24 09:41:04 2012: + [ -z 1 ]
Tue Jul 24 09:41:04 2012: + true
Tue Jul 24 09:41:04 2012: + true
Tue Jul 24 09:41:04 2012: + /usr/bin/tput setaf 1
Tue Jul 24 09:41:04 2012: + RED=^[[31m
Tue Jul 24 09:41:04 2012: + /usr/bin/tput setaf 3
Tue Jul 24 09:41:04 2012: + YELLOW=^[[33m
Tue Jul 24 09:41:04 2012: + /usr/bin/tput op
Tue Jul 24 09:41:04 2012: + NORMAL=^[[39;49m
Tue Jul 24 09:41:04 2012: + [ 1 -eq 0 ]
Tue Jul 24 09:41:04 2012: + [ 1 -eq 255 ]
Tue Jul 24 09:41:04 2012: + /bin/echo -e  ^[[31mfailed!^[[39;49m
Tue Jul 24 09:41:04 2012:  ^[[31mfailed!^[[39;49m
Tue Jul 24 09:41:04 2012: + log_end_msg_post 1
Tue Jul 24 09:41:04 2012: + :
Tue Jul 24 09:41:04 2012: + return 1

here is log from /var/log/postgresql/postgresql-8.4-main.log

2012-07-25 10:40:41 CEST LOG:  could not receive data from client: Connection reset by peer
2012-07-25 10:40:41 CEST LOG:  unexpected EOF on client connection
2012-07-25 10:45:46 CEST LOG:  incomplete startup packet
2012-07-25 10:45:46 CEST LOG:  received fast shutdown request
2012-07-25 10:45:46 CEST LOG:  aborting any active transactions
2012-07-25 10:45:46 CEST LOG:  autovacuum launcher shutting down
2012-07-25 10:45:46 CEST LOG:  shutting down
2012-07-25 10:45:46 CEST LOG:  database system is shut down
2012-07-25 10:46:18 CEST LOG:  database system was shut down at 2012-07-25 10:45:46 CEST
2012-07-25 10:48:45 CEST LOG:  autovacuum launcher started
2012-07-25 10:48:45 CEST LOG:  database system is ready to accept connections

Answer 1

Based on the two log files (and the description at the top of your question that I missed when I read this last night :x), your startup script has a bug that causes it to think Postgres has failed to start when it is in fact up and running (database system is ready to accept connections).

If I had to guess I would say the bug is in pg_ctlcluster, which from your boot log above seems to be returning 1 ("Other failures") even though the DB server is running. Without seeing the pg_ctlcluster script I can't tell you what the problem is, but since that script is supplied by the Debian folks my answer would be the same: Report this as a bug to Debian so they can fix their script to correctly determine if Postgres was successfully started or not.

_{(Sorry my answer isn't more helpful, but pg_ctlcluster is a Debianism. Even if we look at the script, figure out what's wrong, and tell you how to fix it the package manager will overwrite it the next time Debian ships a Postgres upgrade and it will start reporting false failures again...)}