Restart after poweroutage

Today I had a power outage which upon reboot seems to have done
something to cause Postgresql to not restart properly. This has
happened to me before:
http://archives.postgresql.org/pgsql-general/2006-09/msg00938.php

...and during this previous discussion, Tom Lane pointed out that I may
have destroyed the evidence on what was causing this problem:
http://archives.postgresql.org/pgsql-general/2006-09/msg00944.php

So, today, I have taken care to *not* destroy any evidence (ie: I didn't
delete the postmaster.pid file and restart).

What can I do to help diagnose what is happening?

Thanks!
-Jon

[root(at)bilbo ~]# rpm -q postgresql
postgresql-8.1.8-1.fc6.x86_64
[root(at)bilbo ~]# cat /etc/issue
Fedora Core release 6 (Zod)
Kernel \r on an \m
[root(at)bilbo ~]# cat /var/lib/pgsql/data/postmaster.pid
2809
/var/lib/pgsql/data
5432001 32768
[root(at)bilbo ~]# ps -Al | grep 2809
[root(at)bilbo ~]# ps -Al | grep -i post
[root(at)bilbo ~]# chkconfig --list postgresql
postgresql 0:off 1:off 2:off 3:on 4:off 5:on 6:off
[root(at)bilbo ~]# service postgresql status
postmaster is stopped
[root(at)bilbo ~]# service postgresql start
Starting postgresql service: [FAILED]
[root(at)bilbo ~]# tail -2 /var/lib/pgsql/pgstartup.log
FATAL: pre-existing shared memory block (key 5432001, ID 32768) is
still in use
HINT: If you're sure there are no old server processes still running,
remove the shared memory block with the command "ipcclean", "ipcrm", or
just delete the file "postmaster.pid".

--
-**-*-*---*-*---*-*---*-----*-*-----*---*-*---*-----*-----*-*-----*---
Jon Lapham <lapham(at)jandr(dot)org> Rio de Janeiro, Brasil
Personal: http://www.jandr.org/
***-*--*----*-------*------------*--------------------*---------------

Jon Lapham <lapham(at)jandr(dot)org> writes:
> What can I do to help diagnose what is happening?

Let's see the output from
ps auxww | grep postgres
sudo ipcs -a

(or local equivalents)

regards, tom lane

Tom Lane wrote:
> Jon Lapham <lapham(at)jandr(dot)org> writes:
>> What can I do to help diagnose what is happening?
>
> Let's see the output from
> ps auxww | grep postgres
> sudo ipcs -a

[root(at)bilbo ~]# ps auxww | grep postgres
root 3969 0.0 0.0 60272 688 pts/1 R+ 15:47 0:00 grep
postgres
[root(at)bilbo ~]# ipcs -a

------ Shared Memory Segments --------
key shmid owner perms bytes nattch status

0x00000000 65536 root 777 172032 1

0x00000000 131073 lapham 600 393216 2 dest

0x00000000 163842 lapham 600 393216 2 dest

0x00000000 196611 lapham 600 393216 2 dest

0x00000000 229380 lapham 600 393216 2 dest

0x00000000 262149 lapham 600 393216 2 dest

0x00000000 294918 lapham 600 393216 2 dest

0x00000000 327687 lapham 600 393216 2 dest

0x00000000 360456 lapham 600 393216 2 dest

0x00000000 393225 lapham 600 393216 2 dest

0x00000000 425994 lapham 600 393216 2 dest

0x00000000 458763 lapham 600 393216 2 dest

0x00000000 491532 lapham 600 393216 2 dest

0x00000000 524301 lapham 600 393216 2 dest

0x00000000 557070 lapham 600 393216 2 dest

0x00000000 589839 lapham 600 393216 2 dest

0x00000000 819219 lapham 666 43200 1 dest

------ Semaphore Arrays --------
key semid owner perms nsems
0x00000000 65536 apache 600 1
0x00000000 32769 apache 600 1
0x00000000 98306 apache 600 1
0x00000000 131075 apache 600 1
0x00000000 163844 apache 600 1
0x00000000 196613 apache 600 1
0x00000000 229382 apache 600 1
0x00000000 262151 apache 600 1

------ Message Queues --------
key msqid owner perms used-bytes messages

--
-**-*-*---*-*---*-*---*-----*-*-----*---*-*---*-----*-----*-*-----*---
Jon Lapham <lapham(at)jandr(dot)org> Rio de Janeiro, Brasil
Personal: http://www.jandr.org/
***-*--*----*-------*------------*--------------------*---------------

Jon Lapham <lapham(at)jandr(dot)org> writes:
> Tom Lane wrote:
>> Let's see the output from
>> sudo ipcs -a

> [root(at)bilbo ~]# ipcs -a

[ no postgres-owned segments... ]

Well, that's dang interesting. Could you run the postmaster under
strace and send the output?

regards, tom lane

Tom Lane wrote:
> Jon Lapham <lapham(at)jandr(dot)org> writes:
>> Tom Lane wrote:
>>> Let's see the output from
>>> sudo ipcs -a
>
>> [root(at)bilbo ~]# ipcs -a
>
> [ no postgres-owned segments... ]
>
> Well, that's dang interesting. Could you run the postmaster under
> strace and send the output?

Let me know if this is correct. I made this change to the init script:

[root(at)bilbo ~]# diff /etc/init.d/postgresql /etc/init.d/postgresql_strace
190c190
< $SU -l postgres -c "$PGENGINE/postmaster -p '$PGPORT' -D
'$PGDATA' ${PGOPTS} &" >> "$PGLOG" 2>&1 < /dev/null
---
> $SU -l postgres -c "/usr/bin/strace $PGENGINE/postmaster -p
'$PGPORT' -D '$PGDATA' ${PGOPTS} &" >> "$PGLOG" 2>&1 < /dev/null

...which gives this output to the log file after running "service
postgresql start":

execve("/usr/bin/postmaster", ["/usr/bin/postmaster", "-p", "5432",
"-D", "/var/lib/pgsql/data"], [/* 25 vars */]) = 0
brk(0) = 0xaed000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0)
= 0x2aaaaaaab000
uname({sys="Linux", node="bilbo.localdomain", ...}) = 0
access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or
directory)
open("/etc/ld.so.cache", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=108345, ...}) = 0
mmap(NULL, 108345, PROT_READ, MAP_PRIVATE, 3, 0) = 0x2aaaaaaac000
close(3) = 0
open("/lib64/libpam.so.0", O_RDONLY) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\200$ 42"...,
832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=46872, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0)
= 0x2aaaaaac7000
mmap(0x3234200000, 2139976, PROT_READ|PROT_EXEC,
MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x3234200000
mprotect(0x323420a000, 2097152, PROT_NONE) = 0
mmap(0x323440a000, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0xa000) = 0x323440a000
close(3) = 0
open("/lib64/libssl.so.6", O_RDONLY) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\260\"a1"...,
832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=302552, ...}) = 0
mmap(0x3231600000, 2395424, PROT_READ|PROT_EXEC,
MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x3231600000
mprotect(0x3231643000, 2097152, PROT_NONE) = 0
mmap(0x3231843000, 24576, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x43000) = 0x3231843000
close(3) = 0
open("/lib64/libcrypto.so.6", O_RDONLY) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\0d%12\0"...,
832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=1326456, ...}) = 0
mmap(0x3231200000, 3434392, PROT_READ|PROT_EXEC,
MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x3231200000
mprotect(0x3231325000, 2093056, PROT_NONE) = 0
mmap(0x3231524000, 126976, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x124000) = 0x3231524000
mmap(0x3231543000, 14232, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x3231543000
close(3) = 0
open("/usr/lib64/libkrb5.so.3", O_RDONLY) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\0ra02\0"...,
832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=555512, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0)
= 0x2aaaaaac8000
mmap(0x3230600000, 2648352, PROT_READ|PROT_EXEC,
MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x3230600000
mprotect(0x3230683000, 2097152, PROT_NONE) = 0
mmap(0x3230883000, 16384, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x83000) = 0x3230883000
close(3) = 0
open("/usr/lib64/libz.so.1", O_RDONLY) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\320\37\300"...,
832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=85928, ...}) = 0
mmap(0x3227c00000, 2178920, PROT_READ|PROT_EXEC,
MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x3227c00000
mprotect(0x3227c14000, 2093056, PROT_NONE) = 0
mmap(0x3227e13000, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x13000) = 0x3227e13000
close(3) = 0
open("/usr/lib64/libreadline.so.5", O_RDONLY) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\300:\1)"...,
832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=247160, ...}) = 0
mmap(0x3229000000, 2345024, PROT_READ|PROT_EXEC,
MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x3229000000
mprotect(0x3229035000, 2093056, PROT_NONE) = 0
mmap(0x3229234000, 32768, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x34000) = 0x3229234000
mmap(0x322923c000, 2112, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x322923c000
close(3) = 0
open("/lib64/libtermcap.so.2", O_RDONLY) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0`\20@)2\0"...,
832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=15840, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0)
= 0x2aaaaaac9000
mmap(0x3229400000, 2108944, PROT_READ|PROT_EXEC,
MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x3229400000
mprotect(0x3229403000, 2093056, PROT_NONE) = 0
mmap(0x3229602000, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2000) = 0x3229602000
close(3) = 0
open("/lib64/libcrypt.so.1", O_RDONLY) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\240\n\340"...,
832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=30920, ...}) = 0
mmap(0x3237e00000, 2306464, PROT_READ|PROT_EXEC,
MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x3237e00000
mprotect(0x3237e05000, 2093056, PROT_NONE) = 0
mmap(0x3238004000, 8192, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x4000) = 0x3238004000
mmap(0x3238006000, 184736, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x3238006000
close(3) = 0
open("/lib64/libresolv.so.2", O_RDONLY) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\3603\240"...,
832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=92728, ...}) = 0
mmap(0x322fa00000, 2181864, PROT_READ|PROT_EXEC,
MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x322fa00000
mprotect(0x322fa11000, 2097152, PROT_NONE) = 0
mmap(0x322fc11000, 8192, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x11000) = 0x322fc11000
mmap(0x322fc13000, 6888, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x322fc13000
close(3) = 0
open("/lib64/libnsl.so.1", O_RDONLY) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\300(at)\240"...,
832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=109824, ...}) = 0
mmap(0x322ea00000, 2189680, PROT_READ|PROT_EXEC,
MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x322ea00000
mprotect(0x322ea14000, 2093056, PROT_NONE) = 0
mmap(0x322ec13000, 8192, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x13000) = 0x322ec13000
mmap(0x322ec15000, 6512, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x322ec15000
close(3) = 0
open("/lib64/libdl.so.2", O_RDONLY) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0`\17\200"...,
832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=23520, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0)
= 0x2aaaaaaca000
mmap(0x3227800000, 2109728, PROT_READ|PROT_EXEC,
MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x3227800000
mprotect(0x3227803000, 2093056, PROT_NONE) = 0
mmap(0x3227a02000, 8192, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2000) = 0x3227a02000
close(3) = 0
open("/lib64/libm.so.6", O_RDONLY) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\260?(at)\'"...,
832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=615136, ...}) = 0
mmap(0x3227400000, 2629848, PROT_READ|PROT_EXEC,
MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x3227400000
mprotect(0x3227482000, 2093056, PROT_NONE) = 0
mmap(0x3227681000, 8192, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x81000) = 0x3227681000
close(3) = 0
open("/lib64/libc.so.6", O_RDONLY) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0(at)\333\1\'"...,
832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=1678512, ...}) = 0
mmap(0x3227000000, 3461304, PROT_READ|PROT_EXEC,
MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x3227000000
mprotect(0x3227144000, 2097152, PROT_NONE) = 0
mmap(0x3227344000, 20480, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x144000) = 0x3227344000
mmap(0x3227349000, 16568, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x3227349000
close(3) = 0
open("/lib64/libcom_err.so.2", O_RDONLY) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\20\f\340"...,
832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=10264, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0)
= 0x2aaaaaacb000
mmap(0x322fe00000, 2103320, PROT_READ|PROT_EXEC,
MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x322fe00000
mprotect(0x322fe02000, 2093056, PROT_NONE) = 0
mmap(0x3230001000, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1000) = 0x3230001000
close(3) = 0
open("/lib64/libaudit.so.0", O_RDONLY) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\300#\240"...,
832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=78504, ...}) = 0
mmap(0x3232a00000, 2171456, PROT_READ|PROT_EXEC,
MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x3232a00000
mprotect(0x3232a12000, 2093056, PROT_NONE) = 0
mmap(0x3232c11000, 8192, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x11000) = 0x3232c11000
close(3) = 0
open("/usr/lib64/libgssapi_krb5.so.2", O_RDONLY) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\20_\240"...,
832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=174040, ...}) = 0
mmap(0x3230a00000, 2267056, PROT_READ|PROT_EXEC,
MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x3230a00000
mprotect(0x3230a29000, 2093056, PROT_NONE) = 0
mmap(0x3230c28000, 8192, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x28000) = 0x3230c28000
close(3) = 0
open("/usr/lib64/libk5crypto.so.3", O_RDONLY) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0 T 02\0\0"...,
832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=153008, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0)
= 0x2aaaaaacc000
mmap(0x3230200000, 2246920, PROT_READ|PROT_EXEC,
MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x3230200000
mprotect(0x3230223000, 2097152, PROT_NONE) = 0
mmap(0x3230423000, 8192, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x23000) = 0x3230423000
close(3) = 0
open("/usr/lib64/libkrb5support.so.0", O_RDONLY) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\300\33\340"...,
832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=32200, ...}) = 0
mmap(0x3230e00000, 2125104, PROT_READ|PROT_EXEC,
MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x3230e00000
mprotect(0x3230e07000, 2093056, PROT_NONE) = 0
mmap(0x3231006000, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x6000) = 0x3231006000
close(3) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0)
= 0x2aaaaaacd000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0)
= 0x2aaaaaace000
arch_prctl(ARCH_SET_FS, 0x2aaaaaace440) = 0
mprotect(0x3238004000, 4096, PROT_READ) = 0
mprotect(0x322fc11000, 4096, PROT_READ) = 0
mprotect(0x322ec13000, 4096, PROT_READ) = 0
mprotect(0x3227a02000, 4096, PROT_READ) = 0
mprotect(0x3227681000, 4096, PROT_READ) = 0
mprotect(0x3227344000, 16384, PROT_READ) = 0
mprotect(0x3226e19000, 4096, PROT_READ) = 0
munmap(0x2aaaaaaac000, 108345) = 0
brk(0) = 0xaed000
brk(0xb0e000) = 0xb0e000
getcwd("/var/lib/pgsql", 1024) = 15
stat("/usr/bin/postmaster", {st_mode=S_IFREG|0755, st_size=3068296,
...}) = 0
geteuid() = 26
socket(PF_FILE, SOCK_STREAM, 0) = 3
fcntl(3, F_GETFL) = 0x2 (flags O_RDWR)
fcntl(3, F_SETFL, O_RDWR|O_NONBLOCK) = 0
connect(3, {sa_family=AF_FILE, path="/var/run/nscd/socket"}, 110) = -1
ENOENT (No such file or directory)
close(3) = 0
socket(PF_FILE, SOCK_STREAM, 0) = 3
fcntl(3, F_GETFL) = 0x2 (flags O_RDWR)
fcntl(3, F_SETFL, O_RDWR|O_NONBLOCK) = 0
connect(3, {sa_family=AF_FILE, path="/var/run/nscd/socket"}, 110) = -1
ENOENT (No such file or directory)
close(3) = 0
open("/etc/nsswitch.conf", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=1696, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0)
= 0x2aaaaaaac000
read(3, "#\n# /etc/nsswitch.conf\n#\n# An ex"..., 4096) = 1696
read(3, "", 4096) = 0
close(3) = 0
munmap(0x2aaaaaaac000, 4096) = 0
open("/etc/ld.so.cache", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=108345, ...}) = 0
mmap(NULL, 108345, PROT_READ, MAP_PRIVATE, 3, 0) = 0x2aaaaaaac000
close(3) = 0
open("/lib64/libnss_files.so.2", O_RDONLY) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0000!\0\0"...,
832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=53880, ...}) = 0
mmap(NULL, 2139432, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3,
0) = 0x2aaaaaacf000
mprotect(0x2aaaaaad9000, 2093056, PROT_NONE) = 0
mmap(0x2aaaaacd8000, 8192, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x9000) = 0x2aaaaacd8000
close(3) = 0
mprotect(0x2aaaaacd8000, 4096, PROT_READ) = 0
munmap(0x2aaaaaaac000, 108345) = 0
open("/etc/passwd", O_RDONLY) = 3
fcntl(3, F_GETFD) = 0
fcntl(3, F_SETFD, FD_CLOEXEC) = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=2744, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0)
= 0x2aaaaaaac000
read(3, "root:x:0:0:root:/root:/bin/bash\n"..., 4096) = 2744
close(3) = 0
munmap(0x2aaaaaaac000, 4096) = 0
socket(PF_FILE, SOCK_STREAM, 0) = 3
fcntl(3, F_GETFL) = 0x2 (flags O_RDWR)
fcntl(3, F_SETFL, O_RDWR|O_NONBLOCK) = 0
connect(3, {sa_family=AF_FILE, path="/var/run/nscd/socket"}, 110) = -1
ENOENT (No such file or directory)
close(3) = 0
socket(PF_FILE, SOCK_STREAM, 0) = 3
fcntl(3, F_GETFL) = 0x2 (flags O_RDWR)
fcntl(3, F_SETFL, O_RDWR|O_NONBLOCK) = 0
connect(3, {sa_family=AF_FILE, path="/var/run/nscd/socket"}, 110) = -1
ENOENT (No such file or directory)
close(3) = 0
open("/etc/group", O_RDONLY) = 3
fcntl(3, F_GETFD) = 0
fcntl(3, F_SETFD, FD_CLOEXEC) = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=1096, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0)
= 0x2aaaaaaac000
read(3, "root:x:0:root\nbin:x:1:root,bin,d"..., 4096) = 1096
close(3) = 0
munmap(0x2aaaaaaac000, 4096) = 0
getcwd("/var/lib/pgsql", 1024) = 15
chdir("/usr/bin") = 0
lstat("postmaster", {st_mode=S_IFLNK|0777, st_size=8, ...}) = 0
readlink("postmaster", "postgres", 1024) = 8
lstat("postgres", {st_mode=S_IFREG|0755, st_size=3068296, ...}) = 0
getcwd("/usr/bin", 1024) = 9
chdir("/var/lib/pgsql") = 0
open("/usr/lib/locale/locale-archive", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=55565824, ...}) = 0
mmap(NULL, 55565824, PROT_READ, MAP_PRIVATE, 3, 0) = 0x2aaaaacda000
close(3) = 0
geteuid() = 26
getuid() = 26
geteuid() = 26
getpid() = 4151
umask(077) = 022
getcwd("/var/lib/pgsql", 1024) = 15
stat("/usr/bin/postmaster", {st_mode=S_IFREG|0755, st_size=3068296,
...}) = 0
geteuid() = 26
open("/etc/passwd", O_RDONLY) = 3
fcntl(3, F_GETFD) = 0
fcntl(3, F_SETFD, FD_CLOEXEC) = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=2744, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0)
= 0x2aaaae1d8000
read(3, "root:x:0:0:root:/root:/bin/bash\n"..., 4096) = 2744
close(3) = 0
munmap(0x2aaaae1d8000, 4096) = 0
open("/etc/group", O_RDONLY) = 3
fcntl(3, F_GETFD) = 0
fcntl(3, F_SETFD, FD_CLOEXEC) = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=1096, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0)
= 0x2aaaae1d8000
read(3, "root:x:0:root\nbin:x:1:root,bin,d"..., 4096) = 1096
close(3) = 0
munmap(0x2aaaae1d8000, 4096) = 0
getcwd("/var/lib/pgsql", 1024) = 15
chdir("/usr/bin") = 0
lstat("postmaster", {st_mode=S_IFLNK|0777, st_size=8, ...}) = 0
readlink("postmaster", "postgres", 1024) = 8
lstat("postgres", {st_mode=S_IFREG|0755, st_size=3068296, ...}) = 0
getcwd("/usr/bin", 1024) = 9
chdir("/var/lib/pgsql") = 0
open("/proc/meminfo", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0)
= 0x2aaaae1d8000
read(3, "MemTotal: 1024332 kB\nMemFre"..., 1024) = 725
close(3) = 0
munmap(0x2aaaae1d8000, 4096) = 0
stat("/var/lib/pgsql/data/postgresql.conf", {st_mode=S_IFREG|0600,
st_size=13694, ...}) = 0
open("/var/lib/pgsql/data/postgresql.conf", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0600, st_size=13694, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0)
= 0x2aaaae1d8000
read(3, "# -----------------------------\n"..., 8192) = 8192
read(3, "nt_min_messages = notice\t\t# Valu"..., 8192) = 5502
read(3, "", 4096) = 0
read(3, "", 8192) = 0
close(3) = 0
munmap(0x2aaaae1d8000, 4096) = 0
stat("/var/lib/pgsql/data", {st_mode=S_IFDIR|0700, st_size=4096, ...}) = 0
geteuid() = 26
open("/var/lib/pgsql/data/PG_VERSION", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0600, st_size=4, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0)
= 0x2aaaae1d8000
read(3, "8.1\n", 4096) = 4
close(3) = 0
munmap(0x2aaaae1d8000, 4096) = 0
open("/var/lib/pgsql/data/global/pg_control", O_RDONLY) = 3
close(3) = 0
chdir("/var/lib/pgsql/data") = 0
open("postmaster.pid", O_RDWR|O_CREAT|O_EXCL, 0600) = -1 EEXIST (File
exists)
open("postmaster.pid", O_RDONLY) = 3
read(3, "2809\n/var/lib/pgsql/data\n 54320"..., 1123) = 45
close(3) = 0
getppid() = 4150
kill(2809, SIG_0) = -1 ESRCH (No such process)
shmctl(32768, IPC_STAT, 0x7fffd6144e00) = -1 EIDRM (Identifier removed)
open("/usr/share/locale/locale.alias", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=2528, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0)
= 0x2aaaae1d8000
read(3, "# Locale name alias data base.\n#"..., 4096) = 2528
read(3, "", 4096) = 0
close(3) = 0
munmap(0x2aaaae1d8000, 4096) = 0
open("/usr/share/locale/en_US.UTF-8/LC_MESSAGES/postgres.mo", O_RDONLY)
= -1 ENOENT (No such file or directory)
open("/usr/share/locale/en_US.utf8/LC_MESSAGES/postgres.mo", O_RDONLY) =
-1 ENOENT (No such file or directory)
open("/usr/share/locale/en_US/LC_MESSAGES/postgres.mo", O_RDONLY) = -1
ENOENT (No such file or directory)
open("/usr/share/locale/en.UTF-8/LC_MESSAGES/postgres.mo", O_RDONLY) =
-1 ENOENT (No such file or directory)
open("/usr/share/locale/en.utf8/LC_MESSAGES/postgres.mo", O_RDONLY) = -1
ENOENT (No such file or directory)
open("/usr/share/locale/en/LC_MESSAGES/postgres.mo", O_RDONLY) = -1
ENOENT (No such file or directory)
write(2, "FATAL: pre-existing shared memo"..., 263FATAL: pre-existing
shared memory block (key 5432001, ID 32768) is still in use
HINT: If you're sure there are no old server processes still running,
remove the shared memory block with the command "ipcclean", "ipcrm", or
just delete the file "postmaster.pid".
) = 263
exit_group(1) = ?
Process 4151 detached

--
-**-*-*---*-*---*-*---*-----*-*-----*---*-*---*-----*-----*-*-----*---
Jon Lapham <lapham(at)jandr(dot)org> Rio de Janeiro, Brasil
Personal: http://www.jandr.org/
***-*--*----*-------*------------*--------------------*---------------

Jon Lapham <lapham(at)jandr(dot)org> writes:
> chdir("/var/lib/pgsql/data") = 0
> open("postmaster.pid", O_RDWR|O_CREAT|O_EXCL, 0600) = -1 EEXIST (File
> exists)
> open("postmaster.pid", O_RDONLY) = 3
> read(3, "2809\n/var/lib/pgsql/data\n 54320"..., 1123) = 45
> close(3) = 0
> getppid() = 4150
> kill(2809, SIG_0) = -1 ESRCH (No such process)
> shmctl(32768, IPC_STAT, 0x7fffd6144e00) = -1 EIDRM (Identifier removed)

Oh, that's interesting. The code is barfing on this because

/*
* Otherwise, we had better assume that the segment is in use. The
* only likely case is EIDRM, which implies that the segment has been
* IPC_RMID'd but there are still processes attached to it.
*/

It would seem that maybe your kernel has a different idea of what EIDRM
means than we do. You say this persists across a reboot?

regards, tom lane

Tom Lane wrote:
> Oh, that's interesting. The code is barfing on this because
>
> /*
> * Otherwise, we had better assume that the segment is in use. The
> * only likely case is EIDRM, which implies that the segment has been
> * IPC_RMID'd but there are still processes attached to it.
> */
>
> It would seem that maybe your kernel has a different idea of what EIDRM
> means than we do. You say this persists across a reboot?

I probably should have asked before doing this... but I just rebooted
and postgresql came up fine. I hope I didn't screw up the forensics.

So, on the second boot postgresql starts as it should (the first boot
being when I powered up after the power outage).

--
-**-*-*---*-*---*-*---*-----*-*-----*---*-*---*-----*-----*-*-----*---
Jon Lapham <lapham(at)jandr(dot)org> Rio de Janeiro, Brasil
Personal: http://www.jandr.org/
***-*--*----*-------*------------*--------------------*---------------

Jon Lapham <lapham(at)jandr(dot)org> writes:
> Tom Lane wrote:
>> It would seem that maybe your kernel has a different idea of what EIDRM
>> means than we do. You say this persists across a reboot?

> I probably should have asked before doing this... but I just rebooted
> and postgresql came up fine. I hope I didn't screw up the forensics.

Well, we have a clue now anyway: it's got something to do with the
kernel unexpectedly returning EIDRM.

Just for completeness, could we see the output of "ipcs -a" now?

regards, tom lane

Tom Lane wrote:
> Jon Lapham <lapham(at)jandr(dot)org> writes:
>> Tom Lane wrote:
>>> It would seem that maybe your kernel has a different idea of what EIDRM
>>> means than we do. You say this persists across a reboot?
>
>> I probably should have asked before doing this... but I just rebooted
>> and postgresql came up fine. I hope I didn't screw up the forensics.
>
> Well, we have a clue now anyway: it's got something to do with the
> kernel unexpectedly returning EIDRM.
>
> Just for completeness, could we see the output of "ipcs -a" now?

[root(at)bilbo ~]# ipcs -a

------ Shared Memory Segments --------
key shmid owner perms bytes nattch status

0x0052e2c1 32768 postgres 600 11083776 2

0x00000000 65537 root 777 172032 1

0x00000000 131074 lapham 600 393216 2 dest

0x00000000 163843 lapham 600 393216 2 dest

0x00000000 196612 lapham 600 393216 2 dest

0x00000000 229381 lapham 600 393216 2 dest

0x00000000 262150 lapham 600 393216 2 dest

0x00000000 294919 lapham 600 393216 2 dest

0x00000000 327688 lapham 600 393216 2 dest

0x00000000 360457 lapham 600 393216 2 dest

0x00000000 393226 lapham 600 393216 2 dest

0x00000000 425995 lapham 600 393216 2 dest

0x00000000 458764 lapham 600 393216 2 dest

0x00000000 491533 lapham 600 393216 2 dest

0x00000000 524302 lapham 600 393216 2 dest

0x00000000 557071 lapham 600 393216 2 dest

0x00000000 589840 lapham 600 393216 2 dest

------ Semaphore Arrays --------
key semid owner perms nsems
0x0052e2c1 0 postgres 600 17
0x0052e2c2 32769 postgres 600 17
0x0052e2c3 65538 postgres 600 17
0x0052e2c4 98307 postgres 600 17
0x0052e2c5 131076 postgres 600 17
0x0052e2c6 163845 postgres 600 17
0x0052e2c7 196614 postgres 600 17
0x00000000 294919 apache 600 1
0x00000000 262152 apache 600 1
0x00000000 327689 apache 600 1
0x00000000 360458 apache 600 1
0x00000000 393227 apache 600 1
0x00000000 425996 apache 600 1
0x00000000 458765 apache 600 1
0x00000000 491534 apache 600 1

------ Message Queues --------
key msqid owner perms used-bytes messages

--
-**-*-*---*-*---*-*---*-----*-*-----*---*-*---*-----*-----*-*-----*---
Jon Lapham <lapham(at)jandr(dot)org> Rio de Janeiro, Brasil
Personal: http://www.jandr.org/
***-*--*----*-------*------------*--------------------*---------------

Jon Lapham <lapham(at)jandr(dot)org> writes:
> Tom Lane wrote:
>> Just for completeness, could we see the output of "ipcs -a" now?
> [root(at)bilbo ~]# ipcs -a

Thanks. The postgres segment looks pretty standard here. I'm a bit
curious what all the lapham-owned destroyed segments are --- any idea?
Although it seems that they can't possibly be relevant.

I'm kind of leaning to the idea that we're seeing the results of some
corner-case kernel bug here. Anyone familiar with what part of the
Linux kernel implements shmctl()? I've never dug into it ...

regards, tom lane

BTW, you said you were on FC6, but what kernel version exactly?
(uname -a is good)

regards, tom lane

Tom Lane wrote:
> BTW, you said you were on FC6, but what kernel version exactly?
> (uname -a is good)

lapham(at)bilbo > uname -a
Linux bilbo.localdomain 2.6.19-1.2911.6.5.fc6 #1 SMP Sun Mar 4 16:05:34
EST 2007 x86_64 x86_64 x86_64 GNU/Linux
lapham(at)bilbo > cat /proc/cpuinfo
processor : 0
vendor_id : AuthenticAMD
cpu family : 15
model : 44
model name : AMD Athlon(tm) 64 Processor 3200+

FWIW: The kernel says SMP, but it is a single core processor.

--
-**-*-*---*-*---*-*---*-----*-*-----*---*-*---*-----*-----*-*-----*---
Jon Lapham <lapham(at)jandr(dot)org> Rio de Janeiro, Brasil
Personal: http://www.jandr.org/
***-*--*----*-------*------------*--------------------*---------------

Some time ago, Jon Lapham <lapham(at)jandr(dot)org> wrote:
> Today I had a power outage which upon reboot seems to have done
> something to cause Postgresql to not restart properly. This has
> happened to me before:
> http://archives.postgresql.org/pgsql-general/2006-09/msg00938.php

We finally tracked down the cause of this, and it is indeed a Linux
kernel bug: it's simply returning the wrong error code. There'll be
a workaround in the next set of Postgres releases.

regards, tom lane

Tom Lane wrote:
> Some time ago, Jon Lapham <lapham(at)jandr(dot)org> wrote:
>> Today I had a power outage which upon reboot seems to have done
>> something to cause Postgresql to not restart properly. This has
>> happened to me before:
>> http://archives.postgresql.org/pgsql-general/2006-09/msg00938.php
>
> We finally tracked down the cause of this, and it is indeed a Linux
> kernel bug: it's simply returning the wrong error code. There'll be
> a workaround in the next set of Postgres releases.

Thanks for the diligence!

--
-**-*-*---*-*---*-*---*-----*-*-----*---*-*---*-----*-----*-*-----*---
Jon Lapham <lapham(at)jandr(dot)org> Rio de Janeiro, Brasil
Personal: http://www.jandr.org/
***-*--*----*-------*------------*--------------------*---------------