My biggest problem is the lack of any real error message on the server.
I don't see anything wrong in the system logs, and there's no core
file in the /var/postgresql directory.
Are you sure core files are enabled; i.e. the server is running with
'ulimit -c unlimited' ?
Yes:
$ whoami
_postgresql
$ ulimit -c
unlimited
I did a 'vacuumdb -afz' just as
a shot in the dark, without affect. Pretty much all I see in the logs
is this:
<USER%DB x.y.z.a(51478) 487>LOG: unexpected EOF on client connection
This means a client is dying or closing its connection prematurely,
and would seem to be a different problem. It shouldn't ever cause the
server to crash.
If the server is crashing - I have absolutely no info to suggest that,
except possibly this: at a later time I did a tcpdump of one of these
sessions, for lack of better ideas, and saw this near the end:
<snip lots of tcpdump output>
16:32:19.523842 clam.int.geekisp.com.15245 >
morningsun.int.geekisp.com.postgresql: P 17389:18036(647) ack 9323 win
16384 <nop,nop,timestamp 133396667 3702263885> (DF)
16:32:19.524289 morningsun.int.geekisp.com.postgresql >
clam.int.geekisp.com.15245: P 9323:9343(20) ack 18036 win 17376
<nop,nop,timestamp 3702263885 133396667> (DF)
16:32:19.562544 clam.int.geekisp.com.15245 >
morningsun.int.geekisp.com.postgresql: P 18036:18041(5) ack 9343 win
16384 <nop,nop,timestamp 133396667 3702263885> (DF)
******16:32:19.566662 morningsun.int.geekisp.com.postgresql >
clam.int.geekisp.com.15245: F 9343:9343(0) ack 18041 win 17376
<nop,nop,timestamp 3702263885 133396667> (DF)
16:32:19.567043 clam.int.geekisp.com.15245 >
morningsun.int.geekisp.com.postgresql: . ack 9344 win 16384
<nop,nop,timestamp 133396667 3702263885> (DF)
16:32:19.649445 clam.int.geekisp.com.15245 >
morningsun.int.geekisp.com.postgresql: P 18041:18851(810) ack 9344 win
16384 <nop,nop,timestamp 133396667 3702263885> (DF)
16:32:19.649468 morningsun.int.geekisp.com.postgresql >
clam.int.geekisp.com.15245: R 545360451:545360451(0) win 0 (DF)
16:32:19.649652 clam.int.geekisp.com.15245 >
morningsun.int.geekisp.com.postgresql: F 18851:18851(0) ack 9344 win
16384 <nop,nop,timestamp 133396667 3702263885> (DF)
16:32:19.649665 morningsun.int.geekisp.com.postgresql >
clam.int.geekisp.com.15245: R 545360451:545360451(0) win 0 (DF)
The '*****' above is my own, to highlight the interesting part.
Morningsun is the server, clam is the ruby client. Based on this, I
think the server *might* be dying first (hard to tell), since morningsun
is the one who sends the FIN packet and thereby closes the connection.
(Sorry for the horrible wrapping).
Again, having trouble making sure.
Googling turned up a few reports suggesting bad hardware, or corrupted
indexes, but I don't think that's the case here.
Any starting points or ideas would be greatly appreciated.
Make sure the server is able to dump a core file, and perhaps crank up
the logging level.
Just to verify that a core dump is possible for the postgresql user, I
wrote a tiny C program that just calls abort(). Sure enough, running it
gives me a core file.
I cranked the debug level up to 5 (man that's a lot), and here's what I
think is the relevent chunk:
<geekispv2%geekisp-v2-test 192.168.4.38(31992) 9155>STATEMENT: UPDATE
job_members SET "start_time" = NULL, "exit_code" = NULL, "create_time" =
'2006-01-07 17:10:31', "job_id" = 30, "command" = '---
!ruby/object:GeekISP::ShellCommand
args:
command: /bin/ls /tmp/
exit_code:
logger: !ruby/object:Logger
datetime_format:
level: 0
logdev: !ruby/object:Logger::LogDevice
dev: !ruby/object:File {}
filename:
/mnt/scratch/dave/control_panel/trunk/config/../log/test.log
shift_age: 0
shift_size: 1048576
progname:
run_as:
stderr:
stdin:
stdout: ', "finish_time" = NULL, "last_update_time" = NULL,
"host_id" = 4, "status" = 'in_progress', "output" = NULL WHERE
job_member_id = 105
<geekispv2%geekisp-v2-test 192.168.4.38(31992) 9155>DEBUG: name:
unnamed; blockState: STARTED; state: INPROGR, xid/subid/cid:
10290432/1/0, nestlvl: 1, children: <>
<geekispv2%geekisp-v2-test 192.168.4.38(31992) 9155>STATEMENT: UPDATE
job_members SET "start_time" = NULL, "exit_code" = NULL, "create_time" =
'2006-01-07 17:10:31', "job_id" = 30, "command" = '---
!ruby/object:GeekISP::ShellCommand
args:
command: /bin/ls /tmp/
exit_code:
logger: !ruby/object:Logger
datetime_format:
level: 0
logdev: !ruby/object:Logger::LogDevice
dev: !ruby/object:File {}
filename:
/mnt/scratch/dave/control_panel/trunk/config/../log/test.log
shift_age: 0
shift_size: 1048576
progname:
run_as:
stderr:
stdin:
stdout: ', "finish_time" = NULL, "last_update_time" = NULL,
"host_id" = 4, "status" = 'in_progress', "output" = NULL WHERE
job_member_id = 105
<geekispv2%geekisp-v2-test 192.168.4.38(31992) 9155>DEBUG: proc_exit(0)
<geekispv2%geekisp-v2-test 192.168.4.38(31992) 9155>DEBUG: shmem_exit(0)
<geekispv2%geekisp-v2-test 192.168.4.38(31992) 9155>LOG: disconnection:
session time: 0:00:00.84 user=geekispv2 database=geekisp-v2-test
host=192.168.4.38 port=31992
<geekispv2%geekisp-v2-test 192.168.4.38(31992) 9155>DEBUG: exit(0)
<% 7303>DEBUG: reaping dead processes
<% 7303>DEBUG: server process (PID 9155) exited with exit code 0
That looks to me like a clean and normal exit. This is pointing more
and more towards the client in the ruby case, isn't it?
Regards,
--
Dave Steinberg
http://www.geekisp.com/
http://www.steinbergcomputing.com/
