500 "too many non super user connections". Guilty parameter: "statement_timeout = 0"

Hello:

Warning: this both a ranting and an advice to novices
about stupid configuration parameter
"statement_timeout", which is by default set to "0",
rendering thus statements inmortal, and increasing up
the number of connections occupied by days-old unused
statements. If you think I am wrong, please correct me
after reading on.

Problems aroused after switching from postgres 6.2,
where everything worked fine, to postgres 7.3 (details
later). So I had no old postgresql.conf to relay on.

I lost the exact wording of the 500 error, but was
like this:

"too many non super user connections"

Now, this was an error rendered by our JSP server
(caucho.resin-3.0.3, which makes roughly same things
as Tomcat), but the source of the error is obviously
the database backend (postgresql-server-7.3.2-3 RedHat
RPM), as the JSP configuration has no parameter named
like that, and postgres does have one like that.

OS is RedHat 9.0 totally up to date running 24 hours
in a Pentium 2.4 GHz, 512 Mg RAM, 80 GB hard disk, so
it is not a perfomance problem. Server is standalone
JSP+Postgres.

JSP pages use these instructions to open and close the
database.

DRIVER = "org.postgresql.Driver";

STRING = "jdbc:postgresql://127.0.0.1:5432/aip";

// get driver and connection
Driver DriverPest =
(Driver)Class.forName(DRIVER).newInstance();

Connection ConnPest =
DriverManager.getConnection(STRING,USERNAME,PASSWORD);

//
// some statements, prepared statements, etc.
//

// politely close ResultSets and connections (NOT IN
// ALL FILES, SOME FILES "FORGET" TO CLOSE THE
// CONNECTION, surely the problem starts there)
rstPest.close();

ConnPest.close();

The 500 error appeared after five/six days in a row of
flawless working, so I interrogated the machine before
restarting the server, to guess the source problem.

Command "netstat -antp" gives me +150 lines the likes
of this:

tcp 0 0 127.0.0.1:5432
127.0.0.1:43741 ESTABLISHED 10033/postgres:
aip

tcp 0 0 127.0.0.1:43741
127.0.0.1:5432 ESTABLISHED 19181/java

...and another +150 lines saying CLOSE_WAIT instead of
ESTABLISHED, all in paired postgres/java ports. Really
slick.

This looks like the "java" process (the JSP server)
connecting to postgres, and the postgres connecting
back to the "java" process.

"aip" is a database name. There are only two databases
in the server, "aip" and "cel". Some connections have
"aip" name, others hace "cel" name, so I know it is
not database especific.

"ps aux" is very funny (look at the end of the
message). Postgres processes are inmortal, and more
processes keep happily popping up day after day until
they stop, in sunday. The 500 error was first noticed
in monday morning, and JSP server process was not
restarted until tuesday morning, after half an hour
collecting enough evidence to make a forensics
analysis. Once the JSP server was stopped, all extra
postgres processes and connections desappeared after a
few seconds. JSP server was restarted and worked
apparently normal.

Then I looked over the postgresql.conf file and found
the guilty line:

statement_timeout = 0 # 0 is disabled, in
milliseconds

Statements never time out! I changed it to:

statement_timeout = 600000 # 0 is disabled, in
milliseconds

Perhaps a bit too long timeout (10 minutes), but want
be on the sure side, and server is fast and new, so
what the heck. The JSP server gets only 1500-2000 hits
a day. That's 75 to 100 visits. With
max_connections=128, it should work fine.

Please understand: if all JSP pages closed connections
correctly, then *perhaps* this could not happen, but
these are legacy pages from long ago, and anyways I
can't make myself responsible for every clumsy
programmer mistake. The server has to work perfectly
*always*.

I must say that Apache+PHP+mysql (all latest RPMs from
RedHat) was running happily all that time in that
server with no problem at all. Oh, well.

Thanks for listening to my rant. Corrections welcome.

*************************
POSTGRESQL.CONF
**************************

#
# Connection Parameters
#
tcpip_socket = true
ssl = false

max_connections = 128
superuser_reserved_connections = 2

port = 5432
#hostname_lookup = false
#show_source_port = false

#unix_socket_directory = ''
#unix_socket_group = ''
#unix_socket_permissions = 0777 # octal

#virtual_host = ''

#krb_server_keyfile = ''

#
# Shared Memory Size
#
shared_buffers = 256 # min max_connections*2 or 16,
8KB each
max_fsm_relations = 2000 # min 10, fsm is free space
map, ~40 bytes
max_fsm_pages = 20000 # min 1000, fsm is free space
map, ~6 bytes
max_locks_per_transaction = 64 # min 10
wal_buffers = 32 # min 4, typically 8KB each

#
# Non-shared Memory Sizes
#
sort_mem = 1024 # min 64, size in KB
vacuum_mem = 8192 # min 1024, size in KB

#
# Write-ahead log (WAL)
#
#checkpoint_segments = 3 # in logfile segments, min 1,
16MB each
#checkpoint_timeout = 300 # range 30-3600, in seconds
#
#commit_delay = 0 # range 0-100000, in microseconds
#commit_siblings = 5 # range 1-1000
#
#fsync = true
#wal_sync_method = fsync # the default varies across
platforms:
# # fsync, fdatasync, open_sync, or open_datasync
#wal_debug = 0 # range 0-16

#
# Optimizer Parameters
#
#enable_seqscan = true
#enable_indexscan = true
#enable_tidscan = true
#enable_sort = true
#enable_nestloop = true
#enable_mergejoin = true
#enable_hashjoin = true

effective_cache_size = 2000 # typically 8KB each
#random_page_cost = 4 # units are one sequential page
fetch cost
#cpu_tuple_cost = 0.01 # (same)
#cpu_index_tuple_cost = 0.001 # (same)
#cpu_operator_cost = 0.0025 # (same)

#default_statistics_target = 10 # range 1-1000

#
# GEQO Optimizer Parameters
#
#geqo = true
#geqo_selection_bias = 2.0 # range 1.5-2.0
#geqo_threshold = 11
#geqo_pool_size = 0 # default based on tables in
statement,
# range 128-1024
#geqo_effort = 1
#geqo_generations = 0
#geqo_random_seed = -1 # auto-compute seed

#
# Message display
#
#server_min_messages = notice # Values, in order of
decreasing detail:
# debug5, debug4, debug3, debug2, debug1,
# info, notice, warning, error, log, fatal,
# panic
#client_min_messages = notice # Values, in order of
decreasing detail:
# debug5, debug4, debug3, debug2, debug1,
# log, info, notice, warning, error
#silent_mode = false

log_connections = true
#log_pid = false
#log_statement = false
log_duration = true
log_timestamp = true

log_min_error_statement = error # Values in order of
increasing severity:
# debug5, debug4, debug3, debug2, debug1,
# info, notice, warning, error, panic(off)

#debug_print_parse = false
#debug_print_rewritten = false
#debug_print_plan = false
#debug_pretty_print = false

#explain_pretty_print = true

# requires USE_ASSERT_CHECKING
#debug_assertions = true

#
# Syslog
#
syslog = 0 # range 0-2
#syslog_facility = 'LOCAL0'
syslog_ident = 'postgres'

#
# Statistics
#
#show_parser_stats = false
#show_planner_stats = false
#show_executor_stats = false
#show_statement_stats = false

# requires BTREE_BUILD_STATS
#show_btree_build_stats = false

#
# Access statistics collection
#
#stats_start_collector = true
#stats_reset_on_server_start = true
#stats_command_string = false
#stats_row_level = false
#stats_block_level = false

#
# Lock Tracing
#
#trace_notify = false

# requires LOCK_DEBUG
#trace_locks = false
#trace_userlocks = false
#trace_lwlocks = false
#debug_deadlocks = false
#trace_lock_oidmin = 16384
#trace_lock_table = 0

#
# Misc
#
#autocommit = true
#dynamic_library_path = '$libdir'
search_path = '$user,public'
#datestyle = 'iso, us'
#timezone = unknown # actually, defaults to TZ
environment setting
#australian_timezones = false
#client_encoding = sql_ascii # actually, defaults to
database encoding
#authentication_timeout = 60 # 1-600, in seconds
#deadlock_timeout = 1000 # in milliseconds
#default_transaction_isolation = 'read committed'
#max_expr_depth = 10000 # min 10
#max_files_per_process = 1000 # min 25
password_encryption = true
#sql_inheritance = true
#transform_null_equals = false
statement_timeout = 600000 # 0 is disabled, in
milliseconds
#db_user_namespace = false

#
# Locale settings
#
# (initialized by initdb -- may be changed)
LC_MESSAGES = 'ca_ES.UTF-8'
LC_MONETARY = 'ca_ES.UTF-8'
LC_NUMERIC = 'ca_ES.UTF-8'
LC_TIME = 'ca_ES.UTF-8'

******************************
NETSTAT -ATNP OUTPUT
*******************************

postgres 680 0.0 0.0 13940 0 ? SW
Nov06 0:00 postgres: aipo ai
postgres 4641 0.0 0.0 13924 0 ? SW
Nov07 0:00 postgres: aipo ai
postgres 4642 0.0 0.0 13924 0 ? SW
Nov07 0:00 postgres: aipo ai
postgres 6410 0.0 0.0 13924 0 ? SW
Nov07 0:00 postgres: aipo ai
postgres 6411 0.0 0.0 13924 0 ? SW
Nov07 0:00 postgres: aipo ai
postgres 6412 0.0 0.0 13940 0 ? SW
Nov07 0:00 postgres: aipo ai
postgres 6414 0.0 0.0 13940 0 ? SW
Nov07 0:00 postgres: aipo ai
postgres 6416 0.0 0.0 13940 0 ? SW
Nov07 0:00 postgres: aipo ai
postgres 6417 0.0 0.0 13924 0 ? SW
Nov07 0:00 postgres: aipo ai
postgres 6418 0.0 0.0 13924 0 ? SW
Nov07 0:00 postgres: aipo ai
postgres 7720 0.0 0.0 13940 0 ? SW
Nov07 0:00 postgres: aipo ai
postgres 8275 0.0 0.1 13908 604 ? S
Nov07 0:00 postgres: cel cel
postgres 8278 0.0 0.1 13908 592 ? S
Nov07 0:00 postgres: cel cel
postgres 8281 0.0 0.1 13908 548 ? S
Nov07 0:00 postgres: cel cel
postgres 8526 0.0 0.1 13940 668 ? S
Nov07 0:00 postgres: aipo ai
postgres 8585 0.0 0.1 13924 576 ? S
Nov07 0:00 postgres: aipo ai
postgres 8586 0.0 0.1 13924 672 ? S
Nov07 0:00 postgres: aipo ai
postgres 8587 0.0 0.0 13940 300 ? S
Nov07 0:00 postgres: aipo ai
postgres 9156 0.0 0.1 13924 532 ? S
Nov08 0:00 postgres: aipo ai
postgres 9157 0.0 0.1 13924 672 ? S
Nov08 0:00 postgres: aipo ai
postgres 10028 0.0 0.1 13932 608 ? S
Nov08 0:00 postgres: cel cel
postgres 10033 0.0 0.1 13924 556 ? S
Nov08 0:00 postgres: aipo ai
postgres 10034 0.0 0.1 13924 680 ? S
Nov08 0:00 postgres: aipo ai
postgres 10035 0.0 0.1 13940 676 ? S
Nov08 0:00 postgres: aipo ai
postgres 10159 0.0 0.1 13932 652 ? S
Nov08 0:00 postgres: cel cel
postgres 10233 0.0 0.0 13924 496 ? S
Nov08 0:00 postgres: aipo ai
postgres 10234 0.0 0.1 13924 680 ? S
Nov08 0:00 postgres: aipo ai
postgres 10235 0.0 0.1 13940 676 ? S
Nov08 0:00 postgres: aipo ai
postgres 11014 0.0 0.1 13924 608 ? S
Nov08 0:00 postgres: aipo ai
postgres 11015 0.0 0.1 13924 680 ? S
Nov08 0:00 postgres: aipo ai
postgres 11016 0.0 0.1 13940 676 ? S
Nov08 0:00 postgres: aipo ai
postgres 11163 0.0 0.1 13932 584 ? S
Nov08 0:00 postgres: cel cel
postgres 11479 0.0 0.1 13940 676 ? S
Nov08 0:00 postgres: aipo ai
postgres 11643 0.0 0.1 13924 636 ? S
Nov08 0:00 postgres: aipo ai
postgres 11644 0.0 0.1 13924 680 ? S
Nov08 0:00 postgres: aipo ai
postgres 11645 0.0 0.1 13940 676 ? S
Nov08 0:00 postgres: aipo ai
postgres 12114 0.0 0.0 13940 500 ? S
Nov08 0:00 postgres: cel cel
postgres 12124 0.0 0.1 13940 680 ? S
Nov08 0:00 postgres: aipo ai
postgres 12138 0.0 0.1 13924 672 ? S
Nov08 0:00 postgres: aipo ai
postgres 12139 0.0 0.1 13924 684 ? S
Nov08 0:00 postgres: aipo ai
postgres 12140 0.0 0.1 13940 680 ? S
Nov08 0:00 postgres: aipo ai
postgres 12277 0.0 0.1 13932 660 ? S
Nov08 0:00 postgres: cel cel
postgres 12282 0.0 0.1 13940 684 ? S
Nov08 0:00 postgres: aipo ai
postgres 12312 0.0 0.1 13940 684 ? S
Nov08 0:00 postgres: aipo ai
postgres 12314 0.0 0.1 13924 624 ? S
Nov08 0:00 postgres: aipo ai
postgres 12315 0.0 0.1 13924 688 ? S
Nov08 0:00 postgres: aipo ai
postgres 12316 0.0 0.1 13940 684 ? S
Nov08 0:00 postgres: aipo ai
postgres 12318 0.0 0.1 13932 520 ? S
Nov08 0:00 postgres: cel cel
postgres 12471 0.0 0.1 13924 556 ? S
Nov08 0:00 postgres: aipo ai
postgres 12472 0.0 0.1 13924 692 ? S
Nov08 0:00 postgres: aipo ai
postgres 12473 0.0 0.1 13940 684 ? S
Nov08 0:00 postgres: aipo ai
postgres 12517 0.0 0.1 13924 604 ? S
Nov08 0:00 postgres: aipo ai
postgres 12518 0.0 0.1 13924 696 ? S
Nov08 0:00 postgres: aipo ai
postgres 12519 0.0 0.1 13940 688 ? S
Nov08 0:00 postgres: aipo ai
postgres 12625 0.0 0.1 13940 632 ? S
Nov08 0:00 postgres: aipo ai
postgres 12642 0.0 0.1 13940 692 ? S
Nov08 0:00 postgres: aipo ai
postgres 12657 0.0 0.1 13940 576 ? S
Nov08 0:00 postgres: aipo ai
postgres 12816 0.0 0.1 13932 676 ? S
Nov08 0:00 postgres: cel cel
postgres 12824 0.0 0.0 13932 284 ? S
Nov08 0:00 postgres: cel cel
postgres 12828 0.0 0.0 13924 432 ? S
Nov08 0:00 postgres: aipo ai
postgres 12829 0.0 0.1 13924 668 ? S
Nov08 0:00 postgres: aipo ai
postgres 12830 0.0 0.1 13940 696 ? S
Nov08 0:00 postgres: aipo ai
postgres 12832 0.0 0.1 13940 696 ? S
Nov08 0:00 postgres: aipo ai
postgres 12839 0.0 0.1 13944 540 ? S
Nov08 0:00 postgres: aipo ai
postgres 12842 0.0 0.1 13940 696 ? S
Nov08 0:00 postgres: aipo ai
postgres 12984 0.0 0.1 13924 572 ? S
Nov08 0:00 postgres: aipo ai
postgres 12985 0.0 0.1 13924 700 ? S
Nov08 0:00 postgres: aipo ai
postgres 12986 0.0 0.1 13940 660 ? S
Nov08 0:00 postgres: aipo ai
postgres 12993 0.0 0.1 13924 696 ? S
Nov08 0:00 postgres: aipo ai
postgres 12994 0.0 0.1 13924 700 ? S
Nov08 0:00 postgres: aipo ai
postgres 12995 0.0 0.1 13944 692 ? S
Nov08 0:00 postgres: aipo ai
postgres 12996 0.0 0.1 13928 584 ? S
Nov08 0:00 postgres: aipo ai
postgres 12997 0.0 0.1 13928 692 ? S
Nov08 0:00 postgres: aipo ai
postgres 12998 0.0 0.1 13944 688 ? S
Nov08 0:00 postgres: aipo ai
postgres 12999 0.0 0.1 13928 552 ? S
Nov08 0:00 postgres: aipo ai
postgres 13000 0.0 0.1 13928 692 ? S
Nov08 0:00 postgres: aipo ai
postgres 13001 0.0 0.1 13944 688 ? S
Nov08 0:00 postgres: aipo ai
postgres 13007 0.0 0.1 13928 564 ? S
Nov08 0:00 postgres: aipo ai
postgres 13008 0.0 0.1 13928 692 ? S
Nov08 0:00 postgres: aipo ai
postgres 13009 0.0 0.1 13944 688 ? S
Nov08 0:00 postgres: aipo ai
postgres 13017 0.0 0.1 13928 684 ? S
Nov08 0:00 postgres: aipo ai
postgres 13018 0.0 0.1 13928 692 ? S
Nov08 0:00 postgres: aipo ai
postgres 13019 0.0 0.1 13944 692 ? S
Nov08 0:00 postgres: aipo ai
postgres 13319 0.0 0.1 13944 692 ? S
Nov09 0:00 postgres: aipo ai
postgres 13321 0.0 0.1 13936 560 ? S
Nov09 0:00 postgres: cel cel
postgres 13340 0.0 0.1 13944 696 ? S
Nov09 0:00 postgres: aipo ai
postgres 13496 0.0 0.1 13928 688 ? S
Nov09 0:00 postgres: aipo ai
postgres 13497 0.0 0.1 13928 700 ? S
Nov09 0:00 postgres: aipo ai
postgres 13498 0.0 0.1 13944 696 ? S
Nov09 0:00 postgres: aipo ai
postgres 13500 0.0 0.1 13928 532 ? S
Nov09 0:00 postgres: aipo ai
postgres 13501 0.0 0.1 13928 696 ? S
Nov09 0:00 postgres: aipo ai
postgres 13502 0.0 0.1 13944 692 ? S
Nov09 0:00 postgres: aipo ai
postgres 13503 0.0 0.1 13928 688 ? S
Nov09 0:00 postgres: aipo ai
postgres 13504 0.0 0.1 13928 696 ? S
Nov09 0:00 postgres: aipo ai
postgres 13505 0.0 0.1 13944 608 ? S
Nov09 0:00 postgres: aipo ai
postgres 13509 0.0 0.0 13928 460 ? S
Nov09 0:00 postgres: aipo ai
postgres 13510 0.0 0.1 13928 684 ? S
Nov09 0:00 postgres: aipo ai
postgres 13511 0.0 0.1 13944 680 ? S
Nov09 0:00 postgres: aipo ai
postgres 14274 0.0 0.1 13936 568 ? S
Nov09 0:00 postgres: cel cel
postgres 14284 0.0 0.1 13928 600 ? S
Nov09 0:00 postgres: aipo ai
postgres 14285 0.0 0.1 13928 688 ? S
Nov09 0:00 postgres: aipo ai
postgres 14286 0.0 0.1 13944 684 ? S
Nov09 0:00 postgres: aipo ai
postgres 21700 0.0 0.1 13944 684 ? S
Nov09 0:00 postgres: aipo ai
postgres 21990 0.0 0.0 13928 508 ? S
Nov09 0:00 postgres: aipo ai
postgres 21991 0.0 0.1 13928 688 ? S
Nov09 0:00 postgres: aipo ai
postgres 21992 0.0 0.1 13944 632 ? S
Nov09 0:00 postgres: aipo ai
postgres 21993 0.0 0.0 13928 388 ? S
Nov09 0:00 postgres: aipo ai
postgres 21994 0.0 0.1 13928 688 ? S
Nov09 0:00 postgres: aipo ai
postgres 21995 0.0 0.1 13944 684 ? S
Nov09 0:00 postgres: aipo ai
postgres 22003 0.0 0.1 13912 648 ? S
Nov09 0:00 postgres: aipo ai
postgres 22004 0.0 0.1 13912 628 ? S
Nov09 0:00 postgres: aipo ai
postgres 22010 0.0 0.1 13928 564 ? S
Nov09 0:00 postgres: aipo ai
postgres 22011 0.0 0.1 13928 688 ? S
Nov09 0:00 postgres: aipo ai
postgres 22012 0.0 0.1 13944 680 ? S
Nov09 0:00 postgres: aipo ai
postgres 22016 0.0 0.1 13944 684 ? S
Nov09 0:00 postgres: aipo ai
postgres 22019 0.0 0.1 13944 684 ? S
Nov09 0:00 postgres: aipo ai
postgres 22022 0.0 0.1 13944 684 ? S
Nov09 0:00 postgres: aipo ai
postgres 22025 0.0 0.1 13944 684 ? S
Nov09 0:00 postgres: aipo ai
postgres 22028 0.0 0.1 13944 684 ? S
Nov09 0:00 postgres: aipo ai
postgres 22030 0.0 0.1 13944 684 ? S
Nov09 0:00 postgres: aipo ai
postgres 22033 0.0 0.1 13944 684 ? S
Nov09 0:00 postgres: aipo ai
postgres 22034 0.0 0.0 13928 416 ? S
Nov09 0:00 postgres: aipo ai
postgres 22035 0.0 0.1 13928 688 ? S
Nov09 0:00 postgres: aipo ai
postgres 22036 0.0 0.1 13944 684 ? S
Nov09 0:00 postgres: aipo ai
postgres 22038 0.0 0.1 13928 644 ? S
Nov09 0:00 postgres: aipo ai
postgres 22039 0.0 0.1 13928 688 ? S
Nov09 0:00 postgres: aipo ai

=====
Enric Naval
Estudiante de Informtica de Gestin en la Udl (Lleida)

__________________________________
Do you Yahoo!?
Protect your identity with Yahoo! Mail AddressGuard
http://antispam.yahoo.com/whatsnewfree